Add timestamps to debug latencies

packet-exchange/src/client.c

@@ -39,6 +39,7 @@ enum TSNTask {SEND_PACKET_TASK, RTT_TASK};
 typedef struct thread_stat {
   int nb_cycles;
   uint64_t rtt;
+  struct packet_timestamps packet_ts;
 } thread_stat_t;
 
 typedef struct thread_param {
@@ -152,6 +153,12 @@ int main(int argc, char *argv[]) {
     if(param.tsn_task == RTT_TASK) {
       printf("RTT: %" PRIu64 " (%d)\n", param.stats.rtt, param.stats.nb_cycles);
     }
+    else if (param.enable_timestamps) {
+      printf("(%d)\n", param.stats.nb_cycles);
+      printf("      Enter send_udp_packet timestamp: %" PRIu64 "\n", param.stats.packet_ts.user_enter_send);
+      printf("      Call sendmsg timestamp         : %" PRIu64 "\n", param.stats.packet_ts.user_call_sendmsg);
+      printf("      Leave kernel timestamp         : %" PRIu64 "\n", param.stats.packet_ts.kernel_leave);
+    }
 
     if (param.max_cycles)
       if (param.max_cycles == param.stats.nb_cycles) break;
@@ -164,7 +171,7 @@ static void do_tsn_task(struct thread_param * param, uint64_t next_txtime) {
     struct timespec t1, t2;
 
     if(param->tsn_task == SEND_PACKET_TASK) {
-      send_udp_packet(param->enable_etf, param->enable_timestamps, next_txtime, param->ip_address);
+      param->stats.packet_ts = send_udp_packet(param->enable_etf, param->enable_timestamps, next_txtime, param->ip_address);
     }
     else if(param->tsn_task == RTT_TASK) {
 

packet-exchange/src/send_packet.c

@@ -7,8 +7,8 @@
  *
  */
 
-#include "send_packet.h"
 
+#define _GNU_SOURCE
 #include <arpa/inet.h>
 #include <errno.h>
 #include <error.h>
@@ -37,16 +37,16 @@
 #include <unistd.h>
 
 #include "utilities.h"
+#include "send_packet.h"
 
 #define MESSAGE ((uint32_t)0x00FACADE)
 
-static void print_timestamps(struct msghdr *msg, uint64_t txtime);
-static void process_timestamps(uint64_t txtime);
+static void process_timestamps(struct packet_timestamps *packet_ts);
 static void init_tx_buffer(size_t _tx_buffer_len);
 
 static int so_priority = 3;
 static struct sock_txtime sk_txtime;
-static unsigned char * tx_buffer;
+static unsigned char *tx_buffer;
 static size_t tx_buffer_len;
 static int fd;
 
@@ -69,8 +69,7 @@ static int set_if(char *network_if) {
 }
 
 static void init_tx_buffer(size_t _tx_buffer_len) {
-
-  if( _tx_buffer_len < 1) {
+  if (_tx_buffer_len < 1) {
     fprintf(stderr, "tx buffer length should be greater than 1\n");
     exit(EXIT_FAILURE);
   }
@@ -78,8 +77,8 @@ static void init_tx_buffer(size_t _tx_buffer_len) {
   tx_buffer_len = _tx_buffer_len;
   tx_buffer = malloc(tx_buffer_len);
 
-  for(int i = 0; i < ( ((int)tx_buffer_len) - 1); i++) {
-    tx_buffer[i] = (unsigned char) i;
+  for (int i = 0; i < (((int)tx_buffer_len) - 1); i++) {
+    tx_buffer[i] = (unsigned char)i;
   }
 
   tx_buffer[tx_buffer_len - 1] = '\0';
@@ -99,7 +98,8 @@ void init_udp_send(int use_etf, int use_timestamps, int packet_priority,
 
   clock_gettime(CLOCK_MONOTONIC, &ts_mon);
   clock_gettime(CLOCK_TAI, &ts_tai);
-  tai_offset = (ts_mon.tv_sec - ts_tai.tv_sec) * NSEC_PER_SEC + (ts_mon.tv_nsec - ts_tai.tv_nsec);
+  tai_offset = (ts_mon.tv_sec - ts_tai.tv_sec) * NSEC_PER_SEC +
+               (ts_mon.tv_nsec - ts_tai.tv_nsec);
 
   so_priority = packet_priority;
 
@@ -144,9 +144,10 @@ uint64_t get_txtime() {
 }
 
 /*
- * Sends udp packets using the ETF qdisc
+ * Sends udp packets
  */
-void send_udp_packet(int use_etf, int use_timestamps, uint64_t txtime,
+struct packet_timestamps send_udp_packet(int use_etf, int use_timestamps,
+                                         uint64_t txtime,
                                          const char *server_ip) {
   char control[CMSG_SPACE(sizeof(txtime))] = {};
   struct sockaddr_in sin;
@@ -157,6 +158,14 @@ void send_udp_packet(int use_etf, int use_timestamps, uint64_t txtime,
   int res;
   struct pollfd poll_fd = {fd, POLLPRI, 0};
 
+  struct packet_timestamps packet_ts;
+  struct timespec ts;
+
+  if (use_timestamps) {
+    clock_gettime(CLOCK_MONOTONIC, &ts);
+    packet_ts.user_enter_send = ts_to_uint(ts);
+  }
+
   memset(&sin, 0, sizeof(sin));
   sin.sin_family = AF_INET;
   sin.sin_addr.s_addr = inet_addr(server_ip);
@@ -184,6 +193,11 @@ void send_udp_packet(int use_etf, int use_timestamps, uint64_t txtime,
     msg.msg_controllen = cmsg->cmsg_len;
   }
 
+  if (use_timestamps) {
+    clock_gettime(CLOCK_MONOTONIC, &ts);
+    packet_ts.user_call_sendmsg = ts_to_uint(ts);
+  }
+
   sendmsgerr = sendmsg(fd, &msg, 0);
   if (sendmsgerr < 0)
     error(EXIT_FAILURE, errno, "sendmsg failed, ret value: %d\n", sendmsgerr);
@@ -191,13 +205,15 @@ void send_udp_packet(int use_etf, int use_timestamps, uint64_t txtime,
   if (use_timestamps) {
     res = poll(&poll_fd, 1, 0);
     if (res > 0)
-      process_timestamps(txtime);
+      process_timestamps(&packet_ts);
     else
       fprintf(stderr, "select failed\n");
   }
+
+  return packet_ts;
 }
 
-static void process_timestamps(uint64_t txtime) {
+static void process_timestamps(struct packet_timestamps *packet_ts) {
   char data[256];
   struct msghdr msg;
   struct iovec entry;
@@ -206,6 +222,7 @@ static void process_timestamps(uint64_t txtime) {
     struct cmsghdr cm;
     char control[512];
   } control;
+  struct cmsghdr *cmsg;
 
   memset(&msg, 0, sizeof(msg));
   msg.msg_iov = &entry;
@@ -219,42 +236,17 @@ static void process_timestamps(uint64_t txtime) {
 
   if (recvmsg(fd, &msg, MSG_ERRQUEUE | MSG_DONTWAIT) == -1) {
     fprintf(stderr, "recvmsg failed\n");
-  } else {
-    print_timestamps(&msg, txtime);
+    return;
   }
-}
-
-static void print_timestamps(struct msghdr *msg, uint64_t txtime) {
-  struct cmsghdr *cmsg;
 
-  for (cmsg = CMSG_FIRSTHDR(msg); cmsg; cmsg = CMSG_NXTHDR(msg, cmsg)) {
-    switch (cmsg->cmsg_level) {
-      case SOL_SOCKET:
-        printf("SOL_SOCKET ");
-        switch (cmsg->cmsg_type) {
-          case SO_TIMESTAMPING: {
+  for (cmsg = CMSG_FIRSTHDR(&msg); cmsg; cmsg = CMSG_NXTHDR(&msg, cmsg)) {
+    if (cmsg->cmsg_level == SOL_SOCKET && cmsg->cmsg_type == SO_TIMESTAMPING) {
       struct timespec *stamp = (struct timespec *)CMSG_DATA(cmsg);
-            uint64_t timestamp_ns =
-                stamp->tv_sec * NSEC_PER_SEC + stamp->tv_nsec;
-            printf("SO_TIMESTAMPING ");
-            printf("SW %" PRIu64 " - %" PRIu64 " (%" PRIi64 ") ", timestamp_ns,
-                   txtime, ((int64_t)timestamp_ns) - txtime - tai_offset);
-            break;
-          }
-          default:
-#ifdef DEBUG
-            printf("type %d", cmsg->cmsg_type);
-#endif
-            break;
-        }
-        break;
-      default:
-#ifdef DEBUG
-        printf("level %d type %d", cmsg->cmsg_level, cmsg->cmsg_type);
-#endif
-        break;
+      packet_ts->kernel_leave = ts_to_uint(*stamp);
+    } else {
+      fprintf(stderr, "process_timestamps: level %d type %d", cmsg->cmsg_level,
+              cmsg->cmsg_type);
     }
-    printf("\n");
   }
 }
 

packet-exchange/src/send_packet.h

@@ -4,7 +4,13 @@
 #include <stdint.h>
 #include <stdio.h>
 
+struct packet_timestamps {
+  uint64_t user_enter_send;
+  uint64_t user_call_sendmsg;
+  uint64_t kernel_leave;
+};
+
 void init_udp_send(int use_etf, int use_timestamps, int so_priority, char * network_if, size_t tx_buffer_len);
-void send_udp_packet(int use_etf, int use_timestamps, uint64_t txtime, const char *server_ip);
+struct packet_timestamps send_udp_packet(int use_etf, int use_timestamps, uint64_t txtime, const char *server_ip);
 
 #endif

packet-exchange/src/utilities.c

@@ -6,6 +6,10 @@
 
 #include "utilities.h"
 
+uint64_t ts_to_uint(struct timespec t) {
+  return t.tv_nsec * NSEC_PER_SEC + t.tv_sec;
+}
+
 void add_ns(struct timespec *t, uint64_t ns) {
   t->tv_nsec += ns;
 

packet-exchange/src/utilities.h

@@ -11,6 +11,7 @@
 #define SERVER_PORT "50000"
 #define SERVER_PORT_INT 50000
 
+uint64_t ts_to_uint(struct timespec t);
 void add_ns(struct timespec *t, uint64_t ns);
 uint64_t calcdiff_ns(struct timespec t1, struct timespec t2);
 uint64_t max(uint64_t a, uint64_t b);