# HG changeset patch # User Sebastien Decugis # Date 1354232650 -3600 # Node ID fbf77629cb7bd3134adfb8ca06f311ec323f045b # Parent 43fb27a9037fad04a350a97ea58c0ec94714a1fb Added received and sent timestamps in the messages; added logs on emission and reception diff -r 43fb27a9037f -r fbf77629cb7b include/freeDiameter/libfdproto.h --- 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: diff -r 43fb27a9037f -r fbf77629cb7b libfdcore/p_out.c --- 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: diff -r 43fb27a9037f -r fbf77629cb7b libfdcore/p_psm.c --- 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) { diff -r 43fb27a9037f -r fbf77629cb7b libfdproto/messages.c --- 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) { diff -r 43fb27a9037f -r fbf77629cb7b libfdproto/msg_log.c --- 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)) {