hsa: include rtt & jitter measurements in echo client periodic reports

Periodic reports in echo client now include RTT measurements by default
in TCP & UDP echo-bytes runs. They can be swapped for basic jitter
measurements with report-jitter.

Type: improvement

Change-Id: I8ee0b17b49ed24799adb95ac7a3bbad383e339e1
Signed-off-by: Semir Sionek <[email protected]>

diff --git a/src/plugins/hs_apps/echo_client.c b/src/plugins/hs_apps/echo_client.c
index 93e7296..7064f2f 100644 (file)
--- a/src/plugins/hs_apps/echo_client.c
+++ b/src/plugins/hs_apps/echo_client.c
@@ -90,6 +90,7 @@ update_rtt_stats (f64 session_rtt)
 {
   ec_main_t *ecm = &ec_main;
   clib_spinlock_lock (&ecm->rtt_stats.w_lock);
+  ecm->rtt_stats.last_rtt = session_rtt;
   ecm->rtt_stats.sum_rtt += session_rtt;
   ecm->rtt_stats.n_sum++;
   if (session_rtt < ecm->rtt_stats.min_rtt)
@@ -99,6 +100,24 @@ update_rtt_stats (f64 session_rtt)
   clib_spinlock_unlock (&ecm->rtt_stats.w_lock);
 }
 
+static void
+update_rtt_stats_tcp (ec_session_t *es)
+{
+  session_t *s = session_get_from_handle_if_valid (es->vpp_session_handle);
+  if (s)
+    {
+      transport_connection_t *tc;
+      tcp_connection_t *tcpc;
+      tc = transport_get_connection (TRANSPORT_PROTO_TCP, s->connection_index,
+                                    s->thread_index);
+      if (PREDICT_TRUE (tc != NULL))
+       {
+         tcpc = tcp_get_connection_from_transport (tc);
+         update_rtt_stats (tcpc->srtt * TCP_TICK);
+       }
+    }
+}
+
 static void
 send_data_chunk (ec_main_t *ecm, ec_session_t *es)
 {
@@ -169,7 +188,7 @@ send_data_chunk (ec_main_t *ecm, ec_session_t *es)
          bytes_this_chunk = clib_min (bytes_this_chunk, max_enqueue);
          if (!ecm->throughput)
            bytes_this_chunk = clib_min (bytes_this_chunk, 1460);
-         if (ecm->cfg.test_bytes)
+         if (ecm->include_buffer_offset)
            {
              /* Include buffer offset info to also be able to verify
               * out-of-order packets */
@@ -178,6 +197,13 @@ send_data_chunk (ec_main_t *ecm, ec_session_t *es)
                { (u8 *) &test_buf_offset, sizeof (u32) },
                { test_data + test_buf_offset, bytes_this_chunk }
              };
+             if (ecm->echo_bytes &&
+                 ((es->rtt_stat & EC_UDP_RTT_TX_FLAG) == 0))
+               {
+                 es->rtt_udp_buffer_offset = test_buf_offset;
+                 es->send_rtt = vlib_time_now (vlib_get_main ());
+                 es->rtt_stat |= EC_UDP_RTT_TX_FLAG;
+               }
              rv = app_send_dgram_segs ((app_session_t *) es, data_segs, 2,
                                        bytes_this_chunk + sizeof (u32), 0);
              if (rv)
@@ -236,7 +262,7 @@ receive_data_chunk (ec_worker_t *wrk, ec_session_t *es)
   u8 *rx_buf_start = wrk->rx_buf;
   u32 test_buf_offset = es->bytes_received;
 
-  if (ecm->cfg.test_bytes)
+  if (ecm->include_buffer_offset)
     {
       n_read =
        app_recv ((app_session_t *) es, wrk->rx_buf, vec_len (wrk->rx_buf));
@@ -275,8 +301,21 @@ receive_data_chunk (ec_worker_t *wrk, ec_session_t *es)
       if (ecm->transport_proto == TRANSPORT_PROTO_UDP && ecm->echo_bytes &&
          (es->rtt_stat & EC_UDP_RTT_RX_FLAG) == 0)
        {
-         es->rtt_stat |= EC_UDP_RTT_RX_FLAG;
-         update_rtt_stats (vlib_time_now (vlib_get_main ()) - es->send_rtt);
+         /* For periodic reports, verify that the buffer offset matches and we
+          * received the expected dgram, otherwise just match up the first
+          * received one */
+         if (((test_buf_offset == es->rtt_udp_buffer_offset) &&
+              ecm->report_interval) ||
+             !ecm->report_interval)
+           {
+             f64 rtt;
+             es->rtt_stat |= EC_UDP_RTT_RX_FLAG;
+             rtt = vlib_time_now (vlib_get_main ()) - es->send_rtt;
+             if (ecm->rtt_stats.last_rtt > 0)
+               es->jitter =
+                 clib_abs (rtt * 1000 - ecm->rtt_stats.last_rtt * 1000);
+             update_rtt_stats (rtt);
+           }
        }
       if (ecm->cfg.verbose)
        {
@@ -388,12 +427,6 @@ ec_node_fn (vlib_main_t *vm, vlib_node_runtime_t *node, vlib_frame_t *frame)
 
       if (es->bytes_to_send > 0)
        {
-         if (ecm->transport_proto == TRANSPORT_PROTO_UDP && ecm->echo_bytes &&
-             (es->rtt_stat & EC_UDP_RTT_TX_FLAG) == 0)
-           {
-             es->send_rtt = time_now;
-             es->rtt_stat |= EC_UDP_RTT_TX_FLAG;
-           }
          send_data_chunk (ecm, es);
          if (ecm->throughput)
            es->time_to_send += ecm->pacing_window_len;
@@ -416,17 +449,7 @@ ec_node_fn (vlib_main_t *vm, vlib_node_runtime_t *node, vlib_frame_t *frame)
          if (s)
            {
              if (ecm->transport_proto == TRANSPORT_PROTO_TCP)
-               {
-                 transport_connection_t *tc;
-                 tcp_connection_t *tcpc;
-                 tc = transport_get_connection (
-                   TRANSPORT_PROTO_TCP, s->connection_index, s->thread_index);
-                 if (PREDICT_TRUE (tc != NULL))
-                   {
-                     tcpc = tcp_get_connection_from_transport (tc);
-                     update_rtt_stats (tcpc->srtt * TCP_TICK);
-                   }
-               }
+               update_rtt_stats_tcp (es);
 
              vnet_disconnect_args_t _a, *a = &_a;
              a->handle = session_handle (s);
@@ -507,6 +530,8 @@ ec_reset_runtime_config (ec_main_t *ecm)
   ecm->last_total_rx_bytes = 0;
   ecm->last_total_rx_dgrams = 0;
   ecm->last_total_tx_dgrams = 0;
+  ecm->report_interval_jitter = 0;
+  ecm->include_buffer_offset = 0;
   clib_memset (&ecm->rtt_stats, 0, sizeof (ec_rttstat_t));
   ecm->rtt_stats.min_rtt = CLIB_F64_MAX;
   if (ecm->rtt_stats.w_lock == NULL)
@@ -1296,7 +1321,8 @@ static void
 ec_print_periodic_stats (vlib_main_t *vm, bool print_header, bool print_footer)
 {
   ec_main_t *ecm = &ec_main;
-  f64 time_now, print_delta, interval_start, interval_end;
+  f64 time_now, print_delta, interval_start, interval_end, rtt = 0.0,
+                                                          jitter = 0.0;
   u64 total_bytes,
     received_bytes = 0, sent_bytes = 0, dgrams_sent = 0, dgrams_received = 0,
     last_total_bytes = ecm->last_total_tx_bytes + ecm->last_total_rx_bytes;
@@ -1312,6 +1338,18 @@ ec_print_periodic_stats (vlib_main_t *vm, bool print_header, bool print_footer)
            {
              dgrams_received += sess->dgrams_received;
              dgrams_sent += sess->dgrams_sent;
+             sess->rtt_stat = 0;
+             jitter += sess->jitter;
+           }
+         else if (ecm->transport_proto == TRANSPORT_PROTO_TCP)
+           {
+             session_t *s =
+               session_get_from_handle_if_valid (sess->vpp_session_handle);
+             if (s)
+               {
+                 update_rtt_stats_tcp (sess);
+                 rtt += ecm->rtt_stats.last_rtt;
+               }
            }
        }
     }
@@ -1323,76 +1361,87 @@ ec_print_periodic_stats (vlib_main_t *vm, bool print_header, bool print_footer)
 
   if (ecm->transport_proto == TRANSPORT_PROTO_UDP)
     {
-      u8 *tput = 0;
+      jitter /= ecm->n_clients;
+      rtt = ecm->rtt_stats.last_rtt * 1000;
       if (print_header)
        {
          ec_cli ("-----------------------------------------------------------"
-                 "-------------");
+                 "-------------------------");
          if (ecm->report_interval_total)
-           ec_cli ("Run time (s)  Transmitted   Received   Throughput   "
-                   "Sent/received dgrams");
+           ec_cli (
+             "Run time (s)  Transmitted   Received   Throughput   "
+             "%sSent/received dgrams",
+             (ecm->report_interval_jitter ? "Jitter      " : "Roundtrip   "));
          else
-           ec_cli ("Interval (s)  Transmitted   Received   Throughput   "
-                   "Sent/received dgrams");
+           ec_cli (
+             "Interval (s)  Transmitted   Received   Throughput   "
+             "%sSent/received dgrams",
+             (ecm->report_interval_jitter ? "Jitter      " : "Roundtrip   "));
        }
       if (ecm->report_interval_total)
        {
-         tput =
-           format (tput, "%Ub/s", format_base10,
-                   flt_round_nearest ((f64) total_bytes /
-                                      (time_now - ecm->test_start_time)) *
-                     8);
-         ec_cli ("%-13.1f %-13U %-10U %-12s %llu/%llu", interval_end,
-                 format_base10, sent_bytes, format_base10, received_bytes,
-                 tput, dgrams_sent, dgrams_received);
+         ec_cli ("%-13.1f %-13U %-10U %+9Ub/s %+9.3fms %llu/%llu",
+                 interval_end, format_base10, sent_bytes, format_base10,
+                 received_bytes, format_base10,
+                 flt_round_nearest ((f64) (total_bytes - last_total_bytes) /
+                                    print_delta) *
+                   8,
+                 (ecm->report_interval_jitter ? jitter : rtt), dgrams_sent,
+                 dgrams_received);
        }
       else
        {
-         tput =
-           format (tput, "%Ub/s", format_base10,
-                   flt_round_nearest ((f64) (total_bytes - last_total_bytes) /
-                                      print_delta) *
-                     8);
-         ec_cli ("%.1f-%-9.1f %-13U %-10U %-12s %llu/%llu", interval_start,
-                 interval_end, format_base10,
+         rtt /= ecm->n_clients;
+         ec_cli ("%.1f-%-9.1f %-13U %-10U %+9Ub/s %+9.3fms %llu/%llu",
+                 interval_start, interval_end, format_base10,
                  sent_bytes - ecm->last_total_tx_bytes, format_base10,
-                 received_bytes - ecm->last_total_rx_bytes, tput,
+                 received_bytes - ecm->last_total_rx_bytes, format_base10,
+                 flt_round_nearest ((f64) (total_bytes - last_total_bytes) /
+                                    print_delta) *
+                   8,
+                 (ecm->report_interval_jitter ? jitter : rtt),
                  (dgrams_sent - ecm->last_total_tx_dgrams),
                  (dgrams_received - ecm->last_total_rx_dgrams));
        }
       if (print_footer)
        ec_cli ("-------------------------------------------------------------"
-               "-----------");
+               "-----------------------");
       ecm->last_total_tx_dgrams = dgrams_sent;
       ecm->last_total_rx_dgrams = dgrams_received;
-      vec_free (tput);
     }
   else
     {
       if (print_header)
        {
-         ec_cli ("-------------------------------------------------");
+         ec_cli (
+           "-------------------------------------------------------------");
          if (ecm->report_interval_total)
-           ec_cli ("Run time (s)  Transmitted   Received   Throughput");
+           ec_cli (
+             "Run time (s)  Transmitted   Received   Throughput   Roundtrip");
          else
-           ec_cli ("Interval (s)  Transmitted   Received   Throughput");
+           ec_cli (
+             "Interval (s)  Transmitted   Received   Throughput   Roundtrip");
        }
       if (ecm->report_interval_total)
-       ec_cli ("%-13.1f %-13U %-10U %Ub/s", interval_end, format_base10,
-               sent_bytes, format_base10, received_bytes, format_base10,
+       ec_cli ("%-13.1f %-13U %-10U %+9Ub/s %+7.3fms", interval_end,
+               format_base10, sent_bytes, format_base10, received_bytes,
+               format_base10,
                flt_round_nearest ((f64) total_bytes /
                                   (time_now - ecm->test_start_time)) *
-                 8);
+                 8,
+               rtt * 1000);
       else
-       ec_cli ("%.1f-%-9.1f %-13U %-10U %Ub/s", interval_start, interval_end,
-               format_base10, sent_bytes - ecm->last_total_tx_bytes,
-               format_base10, received_bytes - ecm->last_total_rx_bytes,
-               format_base10,
+       ec_cli ("%.1f-%-9.1f %-13U %-10U %+9Ub/s %+7.3fms", interval_start,
+               interval_end, format_base10,
+               sent_bytes - ecm->last_total_tx_bytes, format_base10,
+               received_bytes - ecm->last_total_rx_bytes, format_base10,
                flt_round_nearest (((f64) (total_bytes - last_total_bytes)) /
                                   print_delta) *
-                 8);
+                 8,
+               rtt * 1000);
       if (print_footer)
-       ec_cli ("-------------------------------------------------");
+       ec_cli (
+         "-------------------------------------------------------------");
     }
   ecm->last_print_time = time_now;
   ecm->last_total_tx_bytes = sent_bytes;
@@ -1440,7 +1489,7 @@ ec_print_final_stats (vlib_main_t *vm, f64 total_delta)
   ec_cli ("%u bytes/second %s",
          flt_round_nearest (((f64) total_bytes) / (total_delta)),
          transfer_type);
-  ec_cli ("%UBps %s", format_base10,
+  ec_cli ("%UB/s %s", format_base10,
          flt_round_nearest (((f64) total_bytes) / (total_delta)),
          transfer_type);
 }
@@ -1513,12 +1562,14 @@ ec_command_fn (vlib_main_t *vm, unformat_input_t *input,
       else if (unformat (line_input, "client-batch %d",
                         &ecm->connections_per_batch))
        ;
-      else if (unformat (line_input, "report-interval %u",
-                        &ecm->report_interval))
-       ;
+      else if (unformat (line_input, "report-jitter"))
+       ecm->report_interval_jitter = 1;
       else if (unformat (line_input, "report-interval-total %u",
                         &ecm->report_interval))
        ecm->report_interval_total = 1;
+      else if (unformat (line_input, "report-interval %u",
+                        &ecm->report_interval))
+       ;
       else if (unformat (line_input, "report-interval"))
        ecm->report_interval = 1;
       else if (unformat (line_input, "appns %_%v%_", &ecm->appns_id))
@@ -1584,6 +1635,10 @@ parse_config:
   else
     ecm->cfg.test = HS_TEST_TYPE_UNI;
 
+  if (ecm->cfg.test_bytes ||
+      (ecm->echo_bytes && ecm->transport_proto == TRANSPORT_PROTO_UDP))
+    ecm->include_buffer_offset = 1;
+
   ec_ctrl_connect ();
   ec_wait_for_signal (EC_CLI_CFG_SYNC);
 
@@ -1784,7 +1839,8 @@ VLIB_CLI_COMMAND (ec_command, static) = {
     "[run-time <time>][syn-timeout <time>][echo-bytes][fifo-size <size>]"
     "[private-segment-count <count>][private-segment-size <bytes>[m|g]]"
     "[preallocate-fifos][preallocate-sessions][client-batch <batch-size>]"
-    "[throughput <bytes>[m|g]][report-interval[-total] <time>][uri "
+    "[throughput <bytes>[m|g]][report-interval[-total] "
+    "<time>][report-jitter][[uri "
     "<tcp://ip/port>]"
     "[test-bytes][verbose]",
   .function = ec_command_fn,

diff --git a/src/plugins/hs_apps/echo_client.h b/src/plugins/hs_apps/echo_client.h
index 787ae7e..5131038 100644 (file)
--- a/src/plugins/hs_apps/echo_client.h
+++ b/src/plugins/hs_apps/echo_client.h
@@ -27,6 +27,7 @@ typedef struct ec_rttstat_
   f64 min_rtt;
   f64 max_rtt;
   f64 sum_rtt;
+  f64 last_rtt;
   u32 n_sum;
   clib_spinlock_t w_lock;
 } ec_rttstat_t;
@@ -49,6 +50,8 @@ typedef struct ec_session_
   u64 bytes_paced_current;
   f64 send_rtt;
   u8 rtt_stat;
+  u32 rtt_udp_buffer_offset;
+  f64 jitter;
   u64 dgrams_sent;
   u64 dgrams_received;
 } ec_session_t;
@@ -128,9 +131,10 @@ typedef struct
   f64 test_timeout;                    /**< Test timeout (s) */
   f64 run_time;                                /**< Length of a test (s) */
   u64 max_chunk_bytes;
-  u64 report_interval;     /**< Time between periodic raports (s) */
+  u64 report_interval;     /**< Time between periodic reports (s) */
   u8 report_interval_total; /**< Shown data are totals since the start of the
                               test */
+  u8 report_interval_jitter; /**< Report jitter in periodic reports */
 
   /*
    * Flags
@@ -145,6 +149,7 @@ typedef struct
   u8 test_failed;
   u8 transport_proto;
   u8 barrier_acq_needed;
+  u8 include_buffer_offset;
 
   vlib_main_t *vlib_main;
 } ec_main_t;

diff --git a/test-c/hs-test/echo_test.go b/test-c/hs-test/echo_test.go
index 6e26f87..a3a9590 100644 (file)
--- a/test-c/hs-test/echo_test.go
+++ b/test-c/hs-test/echo_test.go
@@ -8,7 +8,7 @@ import (
 )
 
 func init() {
-       RegisterVethTests(EchoBuiltinTest, EchoBuiltinBandwidthTest, EchoBuiltinEchobytesTest, EchoBuiltinRoundtripTest, EchoBuiltinTestbytesTest, EchoBuiltinPeriodicReportTest, EchoBuiltinPeriodicReportTotalTest, TlsSingleConnectionTest)
+       RegisterVethTests(EchoBuiltinTest, EchoBuiltinBandwidthTest, EchoBuiltinEchobytesTest, EchoBuiltinRoundtripTest, EchoBuiltinTestbytesTest, EchoBuiltinPeriodicReportTest, EchoBuiltinPeriodicReportTotalTest, TlsSingleConnectionTest, EchoBuiltinPeriodicReportUDPTest)
        RegisterVethMWTests(TcpWithLossTest)
        RegisterSoloVeth6Tests(TcpWithLoss6Test)
 }
@@ -58,7 +58,7 @@ func EchoBuiltinBandwidthTest(s *VethsSuite) {
 }
 
 func EchoBuiltinPeriodicReportTotalTest(s *VethsSuite) {
-       regex := regexp.MustCompile(`(\d?\.\d)\s+(\d+\.\d+)M\s+0\s+\d+\.\d+Mb/s`)
+       regex := regexp.MustCompile(`(\d?\.\d)\s+(\d+\.\d+)M\s+0\s+\d+\.\d+Mb/s\s+(\d?\.\d+)ms`)
        serverVpp := s.Containers.ServerVpp.VppInstance
 
        serverVpp.Vppctl("test echo server " +
@@ -79,6 +79,8 @@ func EchoBuiltinPeriodicReportTotalTest(s *VethsSuite) {
                for i := 0; i < 4; i++ {
                        mbytes, _ := strconv.ParseFloat(matches[i][2], 32)
                        s.AssertEqualWithinThreshold(mbytes, 2*(i+1), 0.1)
+                       rtt, _ := strconv.ParseFloat(matches[i][3], 32)
+                       s.AssertGreaterThan(rtt, 0.0)
                }
                // Verify reporting times
                s.AssertEqual(matches[0][1], "1.0")
@@ -90,8 +92,51 @@ func EchoBuiltinPeriodicReportTotalTest(s *VethsSuite) {
        }
 }
 
+func EchoBuiltinPeriodicReportUDPTest(s *VethsSuite) {
+       regex := regexp.MustCompile(`(\d?\.\d)-(\d?.\d)\s+(\d+\.\d+)M\s+\d?\.\d+M\s+\d+\.\d+Mb/s\s+(\d?\.\d+)ms\s+(\d+)/(\d+)`)
+       serverVpp := s.Containers.ServerVpp.VppInstance
+
+       serverVpp.Vppctl("test echo server " +
+               " uri udp://" + s.Interfaces.Server.Ip4AddressString() + "/" + s.Ports.Port1)
+
+       clientVpp := s.Containers.ClientVpp.VppInstance
+
+       o := clientVpp.Vppctl("test echo client bytes 6000k throughput 12m report-interval 1 echo-bytes" +
+               " uri udp://" + s.Interfaces.Server.Ip4AddressString() + "/" + s.Ports.Port1)
+       s.Log(o)
+       s.AssertContains(o, "Test started")
+       s.AssertContains(o, "Test finished")
+       if regex.MatchString(o) {
+               matches := regex.FindAllStringSubmatch(o, -1)
+               // Check we got a correct number of reports
+               s.AssertEqual(4, len(matches))
+               // Verify TX numbers
+               for i := 0; i < 4; i++ {
+                       mbytes, _ := strconv.ParseFloat(matches[i][3], 32)
+                       s.AssertEqualWithinThreshold(mbytes, 1.5, 0.1)
+                       rtt, _ := strconv.ParseFloat(matches[i][4], 32)
+                       s.AssertGreaterThan(rtt, 0.0)
+                       dgramsSent, _ := strconv.ParseUint(matches[i][5], 10, 32)
+                       s.AssertEqualWithinThreshold(dgramsSent, 2048, 20)
+                       dgramsReceived, _ := strconv.ParseUint(matches[i][6], 10, 32)
+                       s.AssertEqualWithinThreshold(dgramsReceived, 2048, 50)
+               }
+               // Verify time interval numbers
+               s.AssertEqual(matches[0][1], "0.0")
+               s.AssertEqual(matches[0][2], "1.0")
+               s.AssertEqual(matches[1][1], "1.0")
+               s.AssertEqual(matches[1][2], "2.0")
+               s.AssertEqual(matches[2][1], "2.0")
+               s.AssertEqual(matches[2][2], "3.0")
+               s.AssertEqual(matches[3][1], "3.0")
+               s.AssertEqual(matches[3][2], "4.0")
+       } else {
+               s.AssertEmpty("invalid echo test client output")
+       }
+}
+
 func EchoBuiltinPeriodicReportTest(s *VethsSuite) {
-       regex := regexp.MustCompile(`(\d?\.\d)-(\d?.\d)\s+(\d+\.\d+)M\s+0\s+\d+\.\d+Mb/s`)
+       regex := regexp.MustCompile(`(\d?\.\d)-(\d?.\d)\s+(\d+\.\d+)M\s+0\s+\d+\.\d+Mb/s\s+(\d?\.\d+)ms`)
        serverVpp := s.Containers.ServerVpp.VppInstance
 
        serverVpp.Vppctl("test echo server " +
@@ -112,6 +157,8 @@ func EchoBuiltinPeriodicReportTest(s *VethsSuite) {
                for i := 0; i < 4; i++ {
                        mbytes, _ := strconv.ParseFloat(matches[i][3], 32)
                        s.AssertEqualWithinThreshold(mbytes, 2, 0.1)
+                       rtt, _ := strconv.ParseFloat(matches[i][4], 32)
+                       s.AssertGreaterThan(rtt, 0.0)
                }
                // Verify time interval numbers
                s.AssertEqual(matches[0][1], "0.0")