Mercurial > hg > freeDiameter

changeset 895:fbf77629cb7b

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
Added received and sent timestamps in the messages; added logs on emission and reception
author Sebastien Decugis <sdecugis@freediameter.net>
date Fri, 30 Nov 2012 00:44:10 +0100
parents 43fb27a9037f
children b13359ace625
files include/freeDiameter/libfdproto.h libfdcore/p_out.c libfdcore/p_psm.c libfdproto/messages.c libfdproto/msg_log.c
diffstat 5 files changed, 149 insertions(+), 11 deletions(-) [+]
line wrap: on
line diff
--- a/include/freeDiameter/libfdproto.h	Thu Nov 29 22:51:49 2012 +0100
+++ b/include/freeDiameter/libfdproto.h	Fri Nov 30 00:44:10 2012 +0100
@@ -203,8 +203,6 @@
 #define FCTS 6  /* Display entry parameters of most functions */
 #define CALL 9  /* Display calls to most functions (with CHECK macros) */
 
-#define TIMING INFO /* Display the message handing time information with this level */
-
 /* Increment the debug level for a file at compilation time by defining -DTRACE_LEVEL=FULL for example. */
 #ifndef TRACE_LEVEL 
 #define TRACE_LEVEL NONE
@@ -595,6 +593,17 @@
 	(    ((ts1)->tv_sec  < (ts2)->tv_sec ) 	\
 	  || (((ts1)->tv_sec  == (ts2)->tv_sec ) && ((ts1)->tv_nsec < (ts2)->tv_nsec) ))
 
+/* Compute diff between two timespecs (pointers) */
+#define TS_DIFFERENCE( tsdiff, tsstart, tsend )	{					\
+	if ((tsend)->tv_nsec < (tsstart)->tv_nsec ) {					\
+		(tsdiff)->tv_sec = (tsend)->tv_sec - (tsstart)->tv_sec - 1;		\
+		(tsdiff)->tv_nsec = (tsend)->tv_nsec + 1000000000 - (tsstart)->tv_nsec;	\
+	} else {									\
+		(tsdiff)->tv_sec  = (tsend)->tv_sec  - (tsstart)->tv_sec;		\
+		(tsdiff)->tv_nsec = (tsend)->tv_nsec - (tsstart)->tv_nsec;		\
+	}}
+		
+
 /* This gives a good size for buffered reads */
 #ifndef BUFSIZ
 #define BUFSIZ 96
@@ -2220,9 +2229,10 @@
 	FD_MSG_LOG_DROPPED = 0,  /* message has been dropped by the framework */ 
 	FD_MSG_LOG_RECEIVED,     /* message received from the network */ 
 	FD_MSG_LOG_SENT,         /* message sent to another peer */ 
-	FD_MSG_LOG_NODELIVER     /* message could not be delivered to any peer */ 
+	FD_MSG_LOG_NODELIVER,    /* message could not be delivered to any peer */
+	FD_MSG_LOG_TIMING	 /* profiling messages */
 };
-#define FD_MSG_LOG_MAX FD_MSG_LOG_NODELIVER
+#define FD_MSG_LOG_MAX FD_MSG_LOG_TIMING
 void fd_msg_log( enum fd_msg_log_cause cause, struct msg * msg, const char * prefix_format, ... );
 
 /* configure the msg_log facility */
@@ -2385,6 +2395,28 @@
 int fd_msg_source_get( struct msg * msg, DiamId_t *diamid, size_t * diamidlen );
 
 /*
+ * FUNCTION:	fd_msg_ts_*
+ *
+ * PARAMETERS:
+ *  msg		: A msg object.
+ *  ts		: A struct timespec pointer, indexed on CLOCK_REALTIME
+ *
+ * DESCRIPTION: 
+ *   Associate or retrieve timestamps meaningful for the message.
+ *  A timestamp with a value of { 0, 0 } means: not set.
+ *
+ * RETURN VALUE:
+ *  0      	: Operation complete.
+ *  !0      	: an error occurred.
+ */
+/* when msg was received from network */
+int fd_msg_ts_set_recv( struct msg * msg, struct timespec * ts );
+int fd_msg_ts_get_recv( struct msg * msg, struct timespec * ts );
+int fd_msg_ts_set_sent( struct msg * msg, struct timespec * ts );
+int fd_msg_ts_get_sent( struct msg * msg, struct timespec * ts );
+
+
+/*
  * FUNCTION:	fd_msg_eteid_get
  *
  * PARAMETERS:
--- a/libfdcore/p_out.c	Thu Nov 29 22:51:49 2012 +0100
+++ b/libfdcore/p_out.c	Fri Nov 30 00:44:10 2012 +0100
@@ -44,6 +44,8 @@
 	size_t sz;
 	int ret;
 	uint32_t bkp_hbh = 0;
+	struct timespec senton;
+	struct msg * cpy_for_logs_only;
 	
 	TRACE_ENTRY("%p %x %p %p %p", msg, flags, cnx, hbh, srl);
 	
@@ -63,14 +65,39 @@
 	CHECK_FCT(fd_msg_bufferize( *msg, &buf, &sz ));
 	pthread_cleanup_push( free, buf );
 	
-	/* Log the message */
-	fd_msg_log( FD_MSG_LOG_SENT, *msg, "Sent to '%s'", fd_cnx_getid(cnx));
+	cpy_for_logs_only = *msg;
 	
 	/* Save a request before sending so that there is no race condition with the answer */
 	if (msg_is_a_req) {
 		CHECK_FCT_DO( ret = fd_p_sr_store(srl, msg, &hdr->msg_hbhid, bkp_hbh), goto out );
 	}
 	
+	CHECK_SYS_DO( clock_gettime(CLOCK_REALTIME, &senton), /* ... */ );
+	CHECK_FCT_DO( fd_msg_ts_set_sent(cpy_for_logs_only, &senton), /* ... */ );
+	
+	/* Log the message */
+	fd_msg_log( FD_MSG_LOG_SENT, cpy_for_logs_only, "Sent to '%s'", fd_cnx_getid(cnx));
+	
+	{
+		struct timespec rcvon, delay;
+		
+		(void) fd_msg_ts_get_recv(cpy_for_logs_only, &rcvon);
+		if (rcvon.tv_sec != 0 || rcvon.tv_nsec != 0) {
+			TS_DIFFERENCE( &delay, &rcvon, &senton);
+			fd_msg_log( FD_MSG_LOG_TIMING, cpy_for_logs_only, "Forwarded in %d.%06.6d sec", delay.tv_sec, delay.tv_nsec/1000);
+		} else { /* We log the answer time only for answers generated locally */
+			if (!msg_is_a_req) {
+				/* get the matching request */
+				struct msg * req;
+				struct timespec reqrcvon;
+				(void) fd_msg_answ_getq(cpy_for_logs_only, &req);
+				(void) fd_msg_ts_get_recv(req, &reqrcvon);
+				TS_DIFFERENCE( &delay, &reqrcvon, &senton);
+				fd_msg_log( FD_MSG_LOG_TIMING, cpy_for_logs_only, "Answered in %d.%06.6d sec", delay.tv_sec, delay.tv_nsec/1000);
+			}
+		}
+	}
+	
 	/* Send the message */
 	CHECK_FCT_DO( ret = fd_cnx_send(cnx, buf, sz, flags), );
 out:
--- a/libfdcore/p_psm.c	Thu Nov 29 22:51:49 2012 +0100
+++ b/libfdcore/p_psm.c	Fri Nov 30 00:44:10 2012 +0100
@@ -477,6 +477,10 @@
 	if (event == FDEVP_CNX_MSG_RECV) {
 		struct msg * msg = NULL;
 		struct msg_hdr * hdr;
+		struct timespec rcvon;
+		
+		/* Retrieve the piggytailed timestamp */
+		memcpy(&rcvon, ev_data+ev_sz, sizeof(struct timespec));
 		
 		/* Parse the received buffer */
 		CHECK_FCT_DO( fd_msg_parse_buffer( (void *)&ev_data, ev_sz, &msg), 
@@ -486,6 +490,8 @@
 				CHECK_FCT_DO( fd_event_send(peer->p_events, FDEVP_CNX_ERROR, 0, NULL), goto psm_reset );
 				goto psm_loop;
 			} );
+			
+		CHECK_FCT_DO( fd_msg_ts_set_recv(msg, &rcvon), /* ... */ );
 		
 		/* If the current state does not allow receiving messages, just drop it */
 		if (cur_state == STATE_CLOSED) {
@@ -514,6 +520,14 @@
 			
 			/* Associate */
 			CHECK_FCT_DO( fd_msg_answ_associate( msg, req ), goto psm_end );
+			
+			/* Display the delay to receive the answer */
+			{
+				struct timespec reqsent, delay;
+				(void) fd_msg_ts_get_sent(req, &reqsent);
+				TS_DIFFERENCE( &delay, &reqsent, &rcvon );
+				fd_msg_log( FD_MSG_LOG_TIMING, msg, "Answer received in %d.%06.6d sec.", delay.tv_sec, delay.tv_nsec / 1000 );
+			}
 		}
 		
 		if (cur_state == STATE_OPEN_NEW) {
--- a/libfdproto/messages.c	Thu Nov 29 22:51:49 2012 +0100
+++ b/libfdproto/messages.c	Fri Nov 30 00:44:10 2012 +0100
@@ -127,7 +127,8 @@
 		}		 msg_cb;		/* Callback to be called when an answer is received, if not NULL */
 	DiamId_t		 msg_src_id;		/* Diameter Id of the peer this message was received from. This string is malloc'd and must be freed */
 	size_t			 msg_src_id_len;	/* cached length of this string */
-	struct timespec		 msg_ts;		/* Timestamp associated with the message */
+	struct timespec		 msg_ts_rcv;		/* Timestamp when this message was received from the network */
+	struct timespec		 msg_ts_sent;		/* Timestamp when this message was sent to the network */
 	
 };
 
@@ -677,6 +678,9 @@
 static int obj_dump_msg (struct msg * msg, int indent, char **outstr, size_t *offset, size_t *outlen )
 {
 	int ret = 0;
+	char buftime[256];
+	size_t tsoffset = 0;
+	struct tm tm;
 	
 	CHECK_FCT( dump_add_str(outstr, offset, outlen, "%*sMSG: %p\n", INOBJHDRVAL, msg) );
 	
@@ -685,6 +689,17 @@
 		return 0;
 	}
 	
+	if ((msg->msg_ts_rcv.tv_sec != 0) || (msg->msg_ts_rcv.tv_nsec != 0)) {
+		tsoffset += strftime(buftime + tsoffset, sizeof(buftime) - tsoffset, "%D,%T", localtime_r( &msg->msg_ts_rcv.tv_sec , &tm ));
+		tsoffset += snprintf(buftime + tsoffset, sizeof(buftime) - tsoffset, ".%6.6ld", msg->msg_ts_rcv.tv_nsec / 1000);
+		CHECK_FCT( dump_add_str(outstr, offset, outlen, INOBJHDR "Received: %s\n", INOBJHDRVAL, buftime) );
+	}
+	if ((msg->msg_ts_sent.tv_sec != 0) || (msg->msg_ts_sent.tv_nsec != 0)) {
+		tsoffset += strftime(buftime + tsoffset, sizeof(buftime) - tsoffset, "%D,%T", localtime_r( &msg->msg_ts_sent.tv_sec , &tm ));
+		tsoffset += snprintf(buftime + tsoffset, sizeof(buftime) - tsoffset, ".%6.6ld", msg->msg_ts_sent.tv_nsec / 1000);
+		CHECK_FCT( dump_add_str(outstr, offset, outlen, INOBJHDR "Sent    : %s\n", INOBJHDRVAL, buftime) );
+	}
+	
 	if (!msg->msg_model) {
 		
 		CHECK_FCT( dump_add_str(outstr, offset, outlen, INOBJHDR "(no model)\n", INOBJHDRVAL) );
@@ -733,7 +748,7 @@
 	
 	if (!avp->avp_model) {
 		
-		CHECK_FCT( dump_add_str(outstr, offset, outlen, INOBJHDR "(no model)\n", INOBJHDRVAL) );
+		CHECK_FCT( dump_add_str(outstr, offset, outlen, INOBJHDR "(no model resolved)\n", INOBJHDRVAL) );
 		
 	} else {
 		
@@ -825,7 +840,7 @@
 	} while (ref);
 	
 	/* now really output this in one shot, so it is not interrupted */
-	fd_log_debug_fstr(fstr, "%s", outstr);
+	fd_log_debug_fstr(fstr, "%s\n", outstr);
 	
 	free(outstr);
 }
@@ -837,7 +852,7 @@
 	CHECK_FCT_DO(  msg_dump_intern ( NONE, msg, 2, &outstr, &offset, &outlen ),
 				fd_log_debug_fstr(fstr, "Error while dumping %p\n", msg) );
 	/* now really output this in one shot, so it is not interrupted */
-	fd_log_debug_fstr(fstr, "%s", outstr);
+	fd_log_debug_fstr(fstr, "%s\n", outstr);
 	
 	free(outstr);
 }
@@ -1152,6 +1167,55 @@
 	return 0;
 }
 
+int fd_msg_ts_set_recv( struct msg * msg, struct timespec * ts )
+{
+	TRACE_ENTRY("%p %p", msg, ts);
+	
+	/* Check we received valid parameters */
+	CHECK_PARAMS( CHECK_MSG(msg) );
+	CHECK_PARAMS( ts );
+	
+	memcpy(&msg->msg_ts_rcv, ts, sizeof(struct timespec));
+	return 0;
+}
+
+int fd_msg_ts_get_recv( struct msg * msg, struct timespec * ts )
+{
+	TRACE_ENTRY("%p %p", msg, ts);
+	
+	/* Check we received valid parameters */
+	CHECK_PARAMS( CHECK_MSG(msg) );
+	CHECK_PARAMS( ts );
+	
+	memcpy(ts, &msg->msg_ts_rcv, sizeof(struct timespec));
+	return 0;
+}
+
+int fd_msg_ts_set_sent( struct msg * msg, struct timespec * ts )
+{
+	TRACE_ENTRY("%p %p", msg, ts);
+	
+	/* Check we received valid parameters */
+	CHECK_PARAMS( CHECK_MSG(msg) );
+	CHECK_PARAMS( ts );
+	
+	memcpy(&msg->msg_ts_sent, ts, sizeof(struct timespec));
+	return 0;
+}
+
+int fd_msg_ts_get_sent( struct msg * msg, struct timespec * ts )
+{
+	TRACE_ENTRY("%p %p", msg, ts);
+	
+	/* Check we received valid parameters */
+	CHECK_PARAMS( CHECK_MSG(msg) );
+	CHECK_PARAMS( ts );
+	
+	memcpy(ts, &msg->msg_ts_sent, sizeof(struct timespec));
+	return 0;
+}
+
+
 /* Retrieve the session of the message */
 int fd_msg_sess_get(struct dictionary * dict, struct msg * msg, struct session ** session, int * new)
 {
--- a/libfdproto/msg_log.c	Thu Nov 29 22:51:49 2012 +0100
+++ b/libfdproto/msg_log.c	Fri Nov 30 00:44:10 2012 +0100
@@ -165,6 +165,7 @@
 	/* Then dump the prefix message to this stream, & to debug stream */
 	(void)pthread_mutex_lock(&fd_log_lock);
 	pthread_cleanup_push(fd_cleanup_mutex_silent, &fd_log_lock);
+	fprintf( fstr, "\n");
 	va_start(ap, prefix_format);
 	vfprintf( fstr, prefix_format, ap);
 	va_end(ap);
@@ -172,7 +173,7 @@
 	pthread_cleanup_pop(0);
 	(void)pthread_mutex_unlock(&fd_log_lock);
 	
-	fd_log_debug_fstr(fstr, "\nLogged: %s\n\n", buftime);
+	fd_log_debug_fstr(fstr, "\n Logged: %s\n", buftime);
 	
 	/* And now the message itself */
 	if ((meth == FD_MSG_LOGTO_DEBUGONLY) && (fd_g_debug_lvl <= INFO)) {
"Welcome to our mercurial repository"