Changeset 895:fbf77629cb7b in freeDiameter

Timestamp:

Nov 30, 2012, 8:44:10 AM (11 years ago)

Author:

Sebastien Decugis <sdecugis@freediameter.net>

Branch:

default

Phase:

public

Message:

Added received and sent timestamps in the messages; added logs on emission and reception

Files:

• include/freeDiameter/libfdproto.h (modified) (4 diffs)
• libfdcore/p_out.c (modified) (2 diffs)
• libfdcore/p_psm.c (modified) (3 diffs)
• libfdproto/messages.c (modified) (7 diffs)
• libfdproto/msg_log.c (modified) (2 diffs)

include/freeDiameter/libfdproto.h

@@ -203 +203 @@
 #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 +594 @@
           || (((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 +2230 @@
         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 +2394 @@
 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 );
+
 
 /*

libfdcore/p_out.c

@@ -45 +45 @@
         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 +66 @@
         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);
+                        }
+                }
         }
         

libfdcore/p_psm.c

@@ -478 +478 @@
                 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 +491 @@
                                 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 +521 @@
                         /* 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 );
+                        }
                 }
                 

libfdproto/messages.c

@@ -128 +128 @@
         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 +679 @@
 {
         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 +688 @@
                 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 +749 @@
         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 +841 @@
         
         /* 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 +853 @@
                                 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 +1167 @@
         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 */

libfdproto/msg_log.c

@@ -166 +166 @@
         (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 +174 @@
         (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 */