Changeset 1060:13fc3fc9c789 in freeDiameter

Timestamp:

Apr 29, 2013, 6:15:34 PM (11 years ago)

Author:

Sebastien Decugis <sdecugis@freediameter.net>

Branch:

default

Phase:

public

Message:

New feature in fd_fifo to get timing statistics

Files:

• extensions/dbg_interactive/queues.i (modified) (1 diff)
• include/freeDiameter/libfdproto.h (modified) (2 diffs)
• libfdproto/fifo.c (modified) (11 diffs)
• tests/testfifo.c (modified) (7 diffs)

extensions/dbg_interactive/queues.i

@@ -67 +67 @@
         int length() {
                 int l;
-                int ret = fd_fifo_length ( $self, &l );
+                int ret = fd_fifo_length ( $self, &l, NULL );
                 if (ret != 0) {
                         DI_ERROR(ret, NULL, NULL);

include/freeDiameter/libfdproto.h

@@ -3037 +3037 @@
  *  queue       : The queue from which to retrieve the number of elements.
  *  length      : Upon success, the current number of elements in the queue is stored here.
+ *  max         : the maximum number of elements as specified during creation. Can be NULL.
  *
  * DESCRIPTION: 
@@ -3045 +3046 @@
  *  EINVAL      : A parameter is invalid.
  */
-int fd_fifo_length ( struct fifo * queue, int * length );
+int fd_fifo_length ( struct fifo * queue, int * length, int * max);
 int fd_fifo_length_noerr ( struct fifo * queue ); /* no error checking version */
+
+/*
+ * FUNCTION:    fd_fifo_getstats
+ *
+ * PARAMETERS:
+ *  queue       : The queue from which to retrieve the timings information.
+ *  total       : Cumulated time all items spent in this queue, including blocking time (always growing, use deltas for monitoring)
+ *  blocking    : Cumulated time threads trying to post new items were blocked (queue full).
+ *  last        : For the last element retrieved from the queue, how long it take between posting (including blocking) and poping
+ *  
+ * DESCRIPTION: 
+ *  Retrieve the timing information associated with a queue, for monitoring purpose.
+ *
+ * RETURN VALUE:
+ *  0           : The statistics have been updated.
+ *  EINVAL      : A parameter is invalid.
+ */
+int fd_fifo_getstats( struct fifo * queue, struct timespec * total, struct timespec * blocking, struct timespec * last);
+
 
 /*

libfdproto/fifo.c

@@ -70 +70 @@
         int             highest;/* The highest count value for which h_cb has been called */
         int             highest_ever; /* The max count value this queue has reached (for tweaking) */
+        
+        struct timespec total_time;    /* Cumulated time all items spent in this queue, including blocking time (always growing, use deltas for monitoring) */
+        struct timespec blocking_time; /* Cumulated time threads trying to post new items were blocked (queue full). */
+        struct timespec last_time;     /* For the last element retrieved from the queue, how long it take between posting (including blocking) and poping */
+        
+};
+
+struct fifo_item {
+        struct fd_list   item;
+        struct timespec  posted_on;
 };
 
@@ -130 +140 @@
                         queue->h_cb, queue->l_cb, queue->data,
                         queue->highest_ever);
+        fd_log_debug("   timings: total:%ld.%06ld, blocking:%ld.%06ld, last:%ld.%06ld",
+                        (long)queue->total_time.tv_sec,(long)(queue->total_time.tv_nsec/1000),
+                        (long)queue->blocking_time.tv_sec,(long)(queue->blocking_time.tv_nsec/1000),
+                        (long)queue->last_time.tv_sec,(long)(queue->last_time.tv_nsec/1000) );
         
         if (dump_item) {
@@ -135 +149 @@
                 int i = 0;
                 for (li = queue->list.next; li != &queue->list; li = li->next) {
-                        fd_log_debug("  [%i] item %p in fifo %p:", i++, li->o, queue);
-                        (*dump_item)(level, li->o);
+                        struct fifo_item * fi = (struct fifo_item *)li;
+                        fd_log_debug("  [%i] item %p in fifo %p, posted:ld.%06ld", 
+                                i++, fi->item.o, queue, (long)fi->posted_on.tv_sec,(long)(fi->posted_on.tv_nsec/1000));
+                        (*dump_item)(level, fi->item.o);
                 }
         }
@@ -251 +267 @@
 
 /* Get the length of the queue */
-int fd_fifo_length ( struct fifo * queue, int * length )
-{
-        TRACE_ENTRY( "%p %p", queue, length );
+int fd_fifo_length ( struct fifo * queue, int * length, int * max )
+{
+        TRACE_ENTRY( "%p %p %p", queue, length, max );
         
         /* Check the parameters */
@@ -264 +280 @@
         *length = queue->count;
         
+        if (max)
+                *max = queue->max;
+        
         /* Unlock */
         CHECK_POSIX(  pthread_mutex_unlock( &queue->mtx )  );
@@ -270 +289 @@
         return 0;
 }
+
+/* Get the timings */
+int fd_fifo_getstats( struct fifo * queue, struct timespec * total, struct timespec * blocking, struct timespec * last)
+{
+        TRACE_ENTRY( "%p %p %p %p", queue, total, blocking, last);
+        
+        /* Check the parameters */
+        CHECK_PARAMS( CHECK_FIFO( queue ) );
+        
+        /* lock the queue */
+        CHECK_POSIX(  pthread_mutex_lock( &queue->mtx )  );
+        
+        if (total)
+                memcpy(total, &queue->total_time, sizeof(struct timespec));
+        
+        if (blocking)
+                memcpy(blocking, &queue->blocking_time, sizeof(struct timespec));
+        
+        if (last)
+                memcpy(last, &queue->last_time, sizeof(struct timespec));
+        
+        /* Unlock */
+        CHECK_POSIX(  pthread_mutex_unlock( &queue->mtx )  );
+        
+        /* Done */
+        return 0;
+}
+
 
 /* alternate version with no error checking */
@@ -326 +373 @@
 int fd_fifo_post_int ( struct fifo * queue, void ** item )
 {
-        struct fd_list * new;
+        struct fifo_item * new;
         int call_cb = 0;
+        struct timespec posted_on, queued_on;
         
         TRACE_ENTRY( "%p %p", queue, item );
@@ -333 +381 @@
         /* Check the parameters */
         CHECK_PARAMS( CHECK_FIFO( queue ) && item && *item );
+        
+        /* Get the timing of this call */
+        CHECK_SYS(  clock_gettime(CLOCK_REALTIME, &posted_on)  );
         
         /* lock the queue */
@@ -353 +404 @@
         
         /* Create a new list item */
-        CHECK_MALLOC_DO(  new = malloc (sizeof (struct fd_list)) , {
+        CHECK_MALLOC_DO(  new = malloc (sizeof (struct fifo_item)) , {
                         pthread_mutex_unlock( &queue->mtx );
                 } );
         
-        fd_list_init(new, *item);
+        fd_list_init(&new->item, *item);
         *item = NULL;
         
         /* Add the new item at the end */
-        fd_list_insert_before( &queue->list, new);
+        fd_list_insert_before( &queue->list, &new->item);
         queue->count++;
         if (queue->highest_ever < queue->count)
@@ -370 +421 @@
         }
         
+        /* store timing */
+        memcpy(&new->posted_on, &posted_on, sizeof(struct timespec));
+        
+        /* update queue timing info "blocking time" */
+        {
+                long long blocked_ns;
+                CHECK_SYS(  clock_gettime(CLOCK_REALTIME, &queued_on)  );
+                blocked_ns = (queued_on.tv_sec - posted_on.tv_sec) * 1000000000;
+                blocked_ns += (queued_on.tv_nsec - posted_on.tv_nsec);
+                blocked_ns += queue->blocking_time.tv_nsec;
+                queue->blocking_time.tv_sec += blocked_ns / 1000000000;
+                queue->blocking_time.tv_nsec = blocked_ns % 1000000000;
+        }
+        
         /* Signal if threads are asleep */
         if (queue->thrs > 0) {
@@ -394 +459 @@
 {
         void * ret = NULL;
-        struct fd_list * li;
+        struct fifo_item * fi;
+        struct timespec now;
         
         ASSERT( ! FD_IS_LIST_EMPTY(&queue->list) );
         
-        fd_list_unlink(li = queue->list.next);
+        fi = (struct fifo_item *)queue->list.next;
+        fd_list_unlink(&fi->item);
         queue->count--;
-        ret = li->o;
-        free(li);
+        ret = fi->item.o;
+        
+        /* Update the timings */
+        CHECK_SYS_DO(  clock_gettime(CLOCK_REALTIME, &now), goto skip_timing  );
+        {
+                long long elapsed = (now.tv_sec - fi->posted_on.tv_sec) * 1000000000;
+                elapsed += now.tv_nsec - fi->posted_on.tv_nsec;
+                
+                queue->last_time.tv_sec = elapsed / 1000000000;
+                queue->last_time.tv_nsec = elapsed % 1000000000;
+                
+                elapsed += queue->total_time.tv_nsec;
+                queue->total_time.tv_sec += elapsed / 1000000000;
+                queue->total_time.tv_nsec = elapsed % 1000000000;
+        }
+skip_timing:    
+        free(fi);
         
         if (queue->thrs_push) {

tests/testfifo.c

@@ -217 +217 @@
         {
                 struct fifo * queue = NULL;
-                int count;
+                int count, max;
                 struct msg * msg  = NULL;
                 
@@ -224 +224 @@
                 
                 /* Check the count is 0 */
-                CHECK( 0, fd_fifo_length(queue, &count) );
+                CHECK( 0, fd_fifo_length(queue, &count, &max) );
                 CHECK( 0, count);
+                CHECK( 0, max);
                 
                 /* Now enqueue */
@@ -236 +237 @@
                 
                 /* Check the count is 3 */
-                CHECK( 0, fd_fifo_length(queue, &count) );
+                CHECK( 0, fd_fifo_length(queue, &count, &max) );
                 CHECK( 3, count);
+                CHECK( 0, max);
                 
                 /* Retrieve the first message using fd_fifo_get */
                 CHECK( 0, fd_fifo_get(queue, &msg) );
                 CHECK( msg1, msg);
-                CHECK( 0, fd_fifo_length(queue, &count) );
+                CHECK( 0, fd_fifo_length(queue, &count, NULL) );
                 CHECK( 2, count);
                 
@@ -250 +252 @@
                 CHECK( 0, fd_fifo_timedget(queue, &msg, &ts) );
                 CHECK( msg2, msg);
-                CHECK( 0, fd_fifo_length(queue, &count) );
+                CHECK( 0, fd_fifo_length(queue, &count, NULL) );
                 CHECK( 1, count);
                 
@@ -256 +258 @@
                 CHECK( 0, fd_fifo_tryget(queue, &msg) );
                 CHECK( msg3, msg);
-                CHECK( 0, fd_fifo_length(queue, &count) );
+                CHECK( 0, fd_fifo_length(queue, &count, NULL) );
                 CHECK( 0, count);
                 
                 /* Check that another meq_tryget does not block */
                 CHECK( EWOULDBLOCK, fd_fifo_tryget(queue, &msg) );
-                CHECK( 0, fd_fifo_length(queue, &count) );
+                CHECK( 0, fd_fifo_length(queue, &count, NULL) );
                 CHECK( 0, count);
                 
@@ -272 +274 @@
                 }
                 CHECK( ETIMEDOUT, fd_fifo_timedget(queue, &msg, &ts) );
-                CHECK( 0, fd_fifo_length(queue, &count) );
+                CHECK( 0, fd_fifo_length(queue, &count, NULL) );
                 CHECK( 0, count);
                 
@@ -361 +363 @@
                 
                 /* Check the count of the queue is back to 0 */
-                CHECK( 0, fd_fifo_length(queue, &count) );
+                CHECK( 0, fd_fifo_length(queue, &count, NULL) );
                 CHECK( 0, count);