Changeset 895:fbf77629cb7b in freeDiameter for libfdcore

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

Location:

libfdcore

Files:

• p_out.c (modified) (2 diffs)
• p_psm.c (modified) (3 diffs)

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