Index: include/freeDiameter/libfdproto.h
===================================================================
--- include/freeDiameter/libfdproto.h	(revision 894)
+++ include/freeDiameter/libfdproto.h	(revision 895)
@@ -203,6 +203,4 @@
 #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. */
@@ -596,4 +594,15 @@
 	  || (((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
@@ -2221,7 +2230,8 @@
 	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 */ 
-};
-#define FD_MSG_LOG_MAX FD_MSG_LOG_NODELIVER
+	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_TIMING
 void fd_msg_log( enum fd_msg_log_cause cause, struct msg * msg, const char * prefix_format, ... );
 
@@ -2384,4 +2394,26 @@
 int fd_msg_source_set( struct msg * msg, DiamId_t diamid, size_t diamidlen, int add_rr, struct dictionary * dict );
 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 );
+
 
 /*
Index: libfdcore/p_out.c
===================================================================
--- libfdcore/p_out.c	(revision 740)
+++ libfdcore/p_out.c	(revision 895)
@@ -45,4 +45,6 @@
 	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);
@@ -64,10 +66,35 @@
 	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);
+			}
+		}
 	}
 	
Index: libfdcore/p_psm.c
===================================================================
--- libfdcore/p_psm.c	(revision 767)
+++ libfdcore/p_psm.c	(revision 895)
@@ -478,4 +478,8 @@
 		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 */
@@ -487,4 +491,6 @@
 				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 */
@@ -515,4 +521,12 @@
 			/* 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 );
+			}
 		}
 		
Index: libfdproto/messages.c
===================================================================
--- libfdproto/messages.c	(revision 894)
+++ libfdproto/messages.c	(revision 895)
@@ -128,5 +128,6 @@
 	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 */
 	
 };
@@ -678,4 +679,7 @@
 {
 	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) );
@@ -684,4 +688,15 @@
 		CHECK_FCT( dump_add_str(outstr, offset, outlen, INOBJHDR "INVALID!\n", INOBJHDRVAL) );
 		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) );
 	}
 	
@@ -734,5 +749,5 @@
 	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 {
@@ -826,5 +841,5 @@
 	
 	/* 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);
@@ -838,5 +853,5 @@
 				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,4 +1167,53 @@
 	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 */
Index: libfdproto/msg_log.c
===================================================================
--- libfdproto/msg_log.c	(revision 765)
+++ libfdproto/msg_log.c	(revision 895)
@@ -166,4 +166,5 @@
 	(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);
@@ -173,5 +174,5 @@
 	(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 */
