Mercurial > hg > freeDiameter

changeset 1060:13fc3fc9c789

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
New feature in fd_fifo to get timing statistics
author Sebastien Decugis <sdecugis@freediameter.net>
date Mon, 29 Apr 2013 17:15:34 +0800
parents 1c6c8fa622ff
children be24c7453aa6
files extensions/dbg_interactive/queues.i include/freeDiameter/libfdproto.h libfdproto/fifo.c tests/testfifo.c
diffstat 4 files changed, 127 insertions(+), 23 deletions(-) [+]
line wrap: on
line diff
--- a/extensions/dbg_interactive/queues.i	Mon Apr 29 12:43:41 2013 +0800
+++ b/extensions/dbg_interactive/queues.i	Mon Apr 29 17:15:34 2013 +0800
@@ -66,7 +66,7 @@
 	/* Get the length of the queue (nb elements) */
 	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);
 		}
--- a/include/freeDiameter/libfdproto.h	Mon Apr 29 12:43:41 2013 +0800
+++ b/include/freeDiameter/libfdproto.h	Mon Apr 29 17:15:34 2013 +0800
@@ -3036,6 +3036,7 @@
  * PARAMETERS:
  *  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: 
  *  Retrieve the number of elements in a queue.
@@ -3044,10 +3045,29 @@
  *  0		: The length of the queue has been written.
  *  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);
+
+
+/*
  * FUNCTION:	fd_fifo_setthrhd
  *
  * PARAMETERS:
--- a/libfdproto/fifo.c	Mon Apr 29 12:43:41 2013 +0800
+++ b/libfdproto/fifo.c	Mon Apr 29 17:15:34 2013 +0800
@@ -69,6 +69,16 @@
 	void		(*l_cb)(struct fifo *, void **);
 	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;
 };
 
 /* The eye catcher value */
@@ -129,13 +139,19 @@
 			queue->high, queue->low, queue->highest, 
 			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) {
 		struct fd_list * li;
 		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);
 		}
 	}
 	CHECK_POSIX_DO(  pthread_mutex_unlock( &queue->mtx ), /* continue */  );
@@ -250,9 +266,9 @@
 }
 
 /* Get the length of the queue */
-int fd_fifo_length ( struct fifo * queue, int * length )
+int fd_fifo_length ( struct fifo * queue, int * length, int * max )
 {
-	TRACE_ENTRY( "%p %p", queue, length );
+	TRACE_ENTRY( "%p %p %p", queue, length, max );
 	
 	/* Check the parameters */
 	CHECK_PARAMS( CHECK_FIFO( queue ) && length );
@@ -263,6 +279,9 @@
 	/* Retrieve the count */
 	*length = queue->count;
 	
+	if (max)
+		*max = queue->max;
+	
 	/* Unlock */
 	CHECK_POSIX(  pthread_mutex_unlock( &queue->mtx )  );
 	
@@ -270,6 +289,34 @@
 	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 */
 int fd_fifo_length_noerr ( struct fifo * queue )
 {
@@ -325,14 +372,18 @@
 /* Post a new item in the queue */
 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 );
 	
 	/* 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 */
 	CHECK_POSIX(  pthread_mutex_lock( &queue->mtx )  );
 	
@@ -352,15 +403,15 @@
 	}
 	
 	/* 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)
 		queue->highest_ever = queue->count;
@@ -369,6 +420,20 @@
 		queue->highest = queue->count;
 	}
 	
+	/* 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) {
 		CHECK_POSIX(  pthread_cond_signal(&queue->cond_pull)  );
@@ -393,14 +458,31 @@
 static void * mq_pop(struct fifo * queue)
 {
 	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) {
 		CHECK_POSIX_DO( pthread_cond_signal( &queue->cond_push ), );
--- a/tests/testfifo.c	Mon Apr 29 12:43:41 2013 +0800
+++ b/tests/testfifo.c	Mon Apr 29 17:15:34 2013 +0800
@@ -216,15 +216,16 @@
 	/* Basic operation */
 	{
 		struct fifo * queue = NULL;
-		int count;
+		int count, max;
 		struct msg * msg  = NULL;
 		
 		/* Create the queue */
 		CHECK( 0, fd_fifo_new(&queue, 0) );
 		
 		/* 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 */
 		msg = msg1;
@@ -235,13 +236,14 @@
 		CHECK( 0, fd_fifo_post(queue, &msg) );
 		
 		/* 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);
 		
 		/* Retrieve the second message using fd_fifo_timedget */
@@ -249,18 +251,18 @@
 		ts.tv_sec += 1; /* Set the timeout to 1 second */
 		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);
 		
 		/* Retrieve the third message using meq_tryget */
 		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);
 		
 		/* Check the timedget actually timesout */
@@ -271,7 +273,7 @@
 			ts.tv_sec += 1;
 		}
 		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);
 		
 		/* We're done for basic tests */
@@ -360,7 +362,7 @@
 		}
 		
 		/* 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);
 		
 		/* Destroy this queue and the messages */
"Welcome to our mercurial repository"