From: Semir Sionek Date: Wed, 20 Aug 2025 14:16:29 +0000 (+0000) Subject: hsa: add periodic reports to builtin echo client X-Git-Tag: v26.02-rc0~50 X-Git-Url: https://gerrit.fd.io/r/gitweb?a=commitdiff_plain;h=refs%2Fchanges%2F94%2F43594%2F17;p=vpp.git hsa: add periodic reports to builtin echo client report-interval now enables periodic reports, which display TX/RX stats, as well as throughput and sent/recv datagrams if running over UDP. It also features a -total variant, which displays same data, but as totals counted from test start time. Type: improvement Change-Id: I28dd1a0c8bfbcaf2882a102433ce4acf28b3d6ef Signed-off-by: Semir Sionek --- diff --git a/extras/hs-test/echo_test.go b/extras/hs-test/echo_test.go index 3dada0eda5d..070ab964b0b 100644 --- a/extras/hs-test/echo_test.go +++ b/extras/hs-test/echo_test.go @@ -8,7 +8,7 @@ import ( ) func init() { - RegisterVethTests(EchoBuiltinTest, EchoBuiltinBandwidthTest, EchoBuiltinEchobytesTest, EchoBuiltinRoundtripTest, EchoBuiltinTestbytesTest) + RegisterVethTests(EchoBuiltinTest, EchoBuiltinBandwidthTest, EchoBuiltinEchobytesTest, EchoBuiltinRoundtripTest, EchoBuiltinTestbytesTest, EchoBuiltinPeriodicReportTest, EchoBuiltinPeriodicReportTotalTest) RegisterVethMWTests(TcpWithLossTest) RegisterSoloVeth6Tests(TcpWithLoss6Test) } @@ -37,7 +37,7 @@ func EchoBuiltinBandwidthTest(s *VethsSuite) { clientVpp := s.Containers.ClientVpp.VppInstance - o := clientVpp.Vppctl("test echo client nclients 4 bytes 8m throughput 16m" + + o := clientVpp.Vppctl("test echo client nclients 4 bytes 2m throughput 32m" + " uri tcp://" + s.Interfaces.Server.Ip4AddressString() + "/" + s.Ports.Port1) s.Log(o) s.AssertContains(o, "Test started") @@ -46,9 +46,9 @@ func EchoBuiltinBandwidthTest(s *VethsSuite) { matches := regex.FindStringSubmatch(o) if len(matches) != 0 { seconds, _ := strconv.ParseFloat(matches[1], 32) - // Make sure that we are within 0.1 of the targeted + // Make sure that we are within 0.25 of the targeted // 2 seconds of runtime - s.AssertEqualWithinThreshold(seconds, 2, 0.1) + s.AssertEqualWithinThreshold(seconds, 2, 0.25) } else { s.AssertEmpty("invalid echo test client output") } @@ -57,6 +57,76 @@ func EchoBuiltinBandwidthTest(s *VethsSuite) { } } +func EchoBuiltinPeriodicReportTotalTest(s *VethsSuite) { + regex := regexp.MustCompile(`(\d?\.\d)\s+(\d+\.\d+)M\s+0\s+\d+\.\d+Mb/s`) + serverVpp := s.Containers.ServerVpp.VppInstance + + serverVpp.Vppctl("test echo server " + + " uri tcp://" + s.Interfaces.Server.Ip4AddressString() + "/" + s.Ports.Port1) + + clientVpp := s.Containers.ClientVpp.VppInstance + + o := clientVpp.Vppctl("test echo client bytes 7900k throughput 16m report-interval-total 1" + + " uri tcp://" + 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][2], 32) + s.AssertEqualWithinThreshold(mbytes, 2*(i+1), 0.1) + } + // Verify reporting times + s.AssertEqual(matches[0][1], "1.0") + s.AssertEqual(matches[1][1], "2.0") + s.AssertEqual(matches[2][1], "3.0") + s.AssertEqual(matches[3][1], "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`) + serverVpp := s.Containers.ServerVpp.VppInstance + + serverVpp.Vppctl("test echo server " + + " uri tcp://" + s.Interfaces.Server.Ip4AddressString() + "/" + s.Ports.Port1) + + clientVpp := s.Containers.ClientVpp.VppInstance + + o := clientVpp.Vppctl("test echo client bytes 7900k throughput 16m report-interval 1" + + " uri tcp://" + 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, 2, 0.1) + } + // 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 EchoBuiltinRoundtripTest(s *VethsSuite) { regex := regexp.MustCompile(`(\.\d+)ms roundtrip`) serverVpp := s.Containers.ServerVpp.VppInstance @@ -127,7 +197,7 @@ func tcpWithoutLoss(s *VethsSuite) string { clientVpp := s.Containers.ClientVpp.VppInstance // Do echo test from client-vpp container - output := clientVpp.Vppctl("test echo client uri tcp://%s/%s verbose echo-bytes run-time 10 test-timeout 20", + output := clientVpp.Vppctl("test echo client uri tcp://%s/%s verbose echo-bytes run-time 10", s.Interfaces.Server.Ip4AddressString(), s.Ports.Port1) s.Log(output) s.AssertNotEqual(len(output), 0) @@ -185,7 +255,7 @@ func tcpWithoutLoss6(s *Veths6Suite) string { clientVpp := s.Containers.ClientVpp.VppInstance // Do echo test from client-vpp container - output := clientVpp.Vppctl("test echo client uri tcp://%s/%s verbose echo-bytes run-time 10 test-timeout 20", + output := clientVpp.Vppctl("test echo client uri tcp://%s/%s verbose echo-bytes run-time 10", s.Interfaces.Server.Ip6AddressString(), s.Ports.Port1) s.Log(output) s.AssertNotEqual(len(output), 0) diff --git a/src/plugins/hs_apps/echo_client.c b/src/plugins/hs_apps/echo_client.c index d5896aecc7c..c4c64bad2d1 100644 --- a/src/plugins/hs_apps/echo_client.c +++ b/src/plugins/hs_apps/echo_client.c @@ -185,6 +185,8 @@ send_data_chunk (ec_main_t *ecm, ec_session_t *es) /* If we managed to enqueue data... */ if (rv > 0) { + if (es->is_dgram) + es->dgrams_sent++; /* Account for it... */ es->bytes_sent += rv; if (ecm->run_time) @@ -235,6 +237,7 @@ receive_data_chunk (ec_worker_t *wrk, ec_session_t *es) test_buf_offset = *(u32 *) wrk->rx_buf; rx_buf_start = wrk->rx_buf + sizeof (u32); n_read -= sizeof (u32); + es->dgrams_received++; } } else @@ -255,6 +258,7 @@ receive_data_chunk (ec_worker_t *wrk, ec_session_t *es) svm_fifo_dequeue_drop (rx_fifo, ph.data_length + SESSION_CONN_HDR_LEN); n_read = ph.data_length; + es->dgrams_received++; } } @@ -484,6 +488,11 @@ ec_reset_runtime_config (ec_main_t *ecm) ecm->throughput = 0; ecm->pacing_window_len = 1; ecm->max_chunk_bytes = 128 << 10; + ecm->report_interval = 0; + ecm->report_interval_total = 0; + ecm->last_print_time = 0; + ecm->last_total_tx_bytes = 0; + ecm->last_total_rx_bytes = 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) @@ -1249,20 +1258,180 @@ ec_ctrl_test_stop () goto cleanup; \ } +static void +ec_print_timeout_stats (vlib_main_t *vm) +{ + ec_main_t *ecm = &ec_main; + u64 received_bytes = 0, sent_bytes = 0; + ec_worker_t *wrk; + ec_session_t *sess; + vec_foreach (wrk, ecm->wrk) + { + pool_foreach (sess, wrk->sessions) + { + received_bytes += sess->bytes_received; + sent_bytes += sess->bytes_sent; + } + } + ec_cli ("Timeout at %.6f with %d sessions still active...", + vlib_time_now (vm), ecm->ready_connections); + if (ecm->transport_proto == TRANSPORT_PROTO_UDP) + { + ec_cli ("Received %llu bytes out of %llu sent (%llu target)", + received_bytes, sent_bytes, ecm->bytes_to_send * ecm->n_clients); + } +} + +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; + 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; + ec_worker_t *wrk; + ec_session_t *sess; + vec_foreach (wrk, ecm->wrk) + { + pool_foreach (sess, wrk->sessions) + { + received_bytes += sess->bytes_received; + sent_bytes += sess->bytes_sent; + if (ecm->transport_proto == TRANSPORT_PROTO_UDP) + { + dgrams_received += sess->dgrams_received; + dgrams_sent += sess->dgrams_sent; + } + } + } + time_now = vlib_time_now (vm); + interval_end = time_now - ecm->test_start_time; + interval_start = ecm->last_print_time - ecm->test_start_time; + total_bytes = received_bytes + sent_bytes; + print_delta = time_now - ecm->last_print_time; + + if (ecm->transport_proto == TRANSPORT_PROTO_UDP) + { + u8 *tput = 0; + if (print_header) + { + ec_cli ("-----------------------------------------------------------" + "-------------"); + if (ecm->report_interval_total) + ec_cli ("Run time (s) Transmitted Received Throughput " + "Sent/received dgrams"); + else + ec_cli ("Interval (s) Transmitted Received Throughput " + "Sent/received dgrams"); + } + 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); + } + 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, + sent_bytes - ecm->last_total_tx_bytes, format_base10, + received_bytes - ecm->last_total_rx_bytes, tput, + (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 ("-------------------------------------------------"); + if (ecm->report_interval_total) + ec_cli ("Run time (s) Transmitted Received Throughput"); + else + ec_cli ("Interval (s) Transmitted Received Throughput"); + } + 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, + flt_round_nearest ((f64) total_bytes / + (time_now - ecm->test_start_time)) * + 8); + 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, + flt_round_nearest (((f64) (total_bytes - last_total_bytes)) / + print_delta) * + 8); + if (print_footer) + ec_cli ("-------------------------------------------------"); + } + ecm->last_print_time = time_now; + ecm->last_total_tx_bytes = sent_bytes; + ecm->last_total_rx_bytes = received_bytes; +} + +static void +ec_print_final_stats (vlib_main_t *vm, f64 total_delta) +{ + ec_main_t *ecm = &ec_main; + u64 total_bytes; + char *transfer_type; + + if (ecm->transport_proto == TRANSPORT_PROTO_TCP || + (ecm->transport_proto == TRANSPORT_PROTO_UDP && ecm->echo_bytes)) + { + /* display rtt stats in milliseconds */ + if (ecm->rtt_stats.n_sum == 1) + ec_cli ("%.05fms roundtrip", ecm->rtt_stats.min_rtt * 1000); + else if (ecm->rtt_stats.n_sum > 1) + ec_cli ("%.05fms/%.05fms/%.05fms min/avg/max roundtrip", + ecm->rtt_stats.min_rtt * 1000, + ecm->rtt_stats.sum_rtt / ecm->rtt_stats.n_sum * 1000, + ecm->rtt_stats.max_rtt * 1000); + else + ec_cli ("error measuring roundtrip time"); + } + + total_bytes = (ecm->echo_bytes ? ecm->rx_total : ecm->tx_total); + transfer_type = ecm->echo_bytes ? "full-duplex" : "half-duplex"; + ec_cli ("%lld bytes (%lld mbytes, %lld gbytes) in %.2f seconds", total_bytes, + total_bytes / (1ULL << 20), total_bytes / (1ULL << 30), total_delta); + ec_cli ("%.2f bytes/second %s", ((f64) total_bytes) / (total_delta), + transfer_type); + ec_cli ("%.4f gbit/second %s", + (((f64) total_bytes * 8.0) / total_delta / 1e9), transfer_type); +} + static clib_error_t * ec_command_fn (vlib_main_t *vm, unformat_input_t *input, vlib_cli_command_t *cmd) { unformat_input_t _line_input, *line_input = &_line_input; - char *default_uri = "tcp://6.0.1.1/1234", *transfer_type; + char *default_uri = "tcp://6.0.1.1/1234"; ec_main_t *ecm = &ec_main; uword *event_data = 0, event_type; clib_error_t *error = 0; int rv, timed_run_conflict = 0, tput_conflict = 0, had_config = 1; - u64 total_bytes; - f64 delta; - ec_worker_t *wrk; - ec_session_t *sess; + f64 delta, wait_time = 0; if (ecm->test_client_attached) return clib_error_return (0, "failed: already running!"); @@ -1291,11 +1460,11 @@ ec_command_fn (vlib_main_t *vm, unformat_input_t *input, &ecm->bytes_to_send)) timed_run_conflict++; else if (unformat (line_input, "test-timeout %f", &ecm->test_timeout)) - ; + timed_run_conflict++; else if (unformat (line_input, "syn-timeout %f", &ecm->syn_timeout)) ; else if (unformat (line_input, "run-time %f", &ecm->run_time)) - ; + ecm->test_timeout = ecm->run_time; else if (unformat (line_input, "echo-bytes")) ecm->echo_bytes = 1; else if (unformat (line_input, "fifo-size %U", unformat_memory_size, @@ -1307,9 +1476,9 @@ ec_command_fn (vlib_main_t *vm, unformat_input_t *input, else if (unformat (line_input, "private-segment-size %U", unformat_memory_size, &ecm->private_segment_size)) ; - else if (unformat (line_input, "throughput %U", unformat_memory_size, + else if (unformat (line_input, "throughput %U", unformat_base10, &ecm->throughput)) - ; + ecm->throughput /= 8; else if (unformat (line_input, "max-tx-chunk %U", unformat_memory_size, &ecm->max_chunk_bytes)) tput_conflict = 1; @@ -1320,6 +1489,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-interval-total %u", + &ecm->report_interval)) + ecm->report_interval_total = 1; + else if (unformat (line_input, "report-interval")) + ecm->report_interval = 1; else if (unformat (line_input, "appns %_%v%_", &ecm->appns_id)) ; else if (unformat (line_input, "all-scope")) @@ -1437,75 +1614,76 @@ parse_config: } /* Testing officially starts now */ ecm->test_start_time = vlib_time_now (ecm->vlib_main); + if (ecm->report_interval) + ecm->last_print_time = ecm->test_start_time; ec_cli ("Test started at %.6f", ecm->test_start_time); /* - * If a timed run, wait and expire timer - */ - if (ecm->run_time) - { - vlib_process_suspend (vm, ecm->run_time); - ec_main.timer_expired = true; - } - - /* - * Wait for the sessions to finish or test_timeout seconds pass + * Wait for the sessions to finish or test_timeout (timeout or length + * of timed run) seconds pass. If providing periodic reports, wake up + * every now and then to print them and loop. */ - vlib_process_wait_for_event_or_clock (vm, ecm->test_timeout); - event_type = vlib_process_get_events (vm, &event_data); - switch (event_type) + u8 main_loop_done = false, print_header = true, report_timeout = false; + do { - case ~0: - ec_cli ("Timeout at %.6f with %d sessions still active...", - vlib_time_now (ecm->vlib_main), ecm->ready_connections); - if (ecm->transport_proto == TRANSPORT_PROTO_UDP) + if (ecm->report_interval) { - u64 received_bytes = 0; - u64 sent_bytes = 0; - vec_foreach (wrk, ecm->wrk) - pool_foreach (sess, wrk->sessions) - { - received_bytes += sess->bytes_received; - sent_bytes += sess->bytes_sent; - } - ec_cli ("Received %llu bytes out of %llu sent (%llu target)", - received_bytes, sent_bytes, - ecm->bytes_to_send * ecm->n_clients); + delta = vlib_time_now (vm) - ecm->test_start_time; + if (delta + (f64) ecm->report_interval > ecm->test_timeout) + { + report_timeout = true; + wait_time = ecm->test_timeout - delta; + } + else + wait_time = (f64) ecm->report_interval; } else - error = clib_error_return (0, "failed: timeout with %d sessions", - ecm->ready_connections); - goto stop_test; + { + report_timeout = true; + wait_time = (f64) ecm->test_timeout; + } - case EC_CLI_TEST_DONE: - ecm->test_end_time = vlib_time_now (vm); - ec_cli ("Test finished at %.6f", ecm->test_end_time); - break; + vlib_process_wait_for_event_or_clock (vm, wait_time); + event_type = vlib_process_get_events (vm, &event_data); + switch (event_type) + { + case ~0: + if (report_timeout) + { + if (ecm->run_time) + { + ecm->timer_expired = true; + ecm->test_timeout += 1; + break; + } + ec_print_timeout_stats (vm); + if (ecm->transport_proto != TRANSPORT_PROTO_UDP) + error = + clib_error_return (0, "failed: timeout with %d sessions", + ecm->ready_connections); + goto stop_test; + } + else + { + ec_print_periodic_stats (vm, print_header, false); + if (PREDICT_FALSE (print_header)) + print_header = false; + } + break; - default: - ec_cli ("unexpected event(3): %d", event_type); - error = - clib_error_return (0, "failed: unexpected event(3): %d", event_type); - goto stop_test; - } + case EC_CLI_TEST_DONE: + ecm->test_end_time = vlib_time_now (vm); + main_loop_done = true; + break; - /* - * Done. Compute stats - */ - if (ecm->transport_proto == TRANSPORT_PROTO_TCP || - (ecm->transport_proto == TRANSPORT_PROTO_UDP && ecm->echo_bytes)) - { - /* display rtt stats in milliseconds */ - if (ecm->rtt_stats.n_sum == 1) - ec_cli ("%.05fms roundtrip", ecm->rtt_stats.min_rtt * 1000); - else if (ecm->rtt_stats.n_sum > 1) - ec_cli ("%.05fms/%.05fms/%.05fms min/avg/max roundtrip", - ecm->rtt_stats.min_rtt * 1000, - ecm->rtt_stats.sum_rtt / ecm->rtt_stats.n_sum * 1000, - ecm->rtt_stats.max_rtt * 1000); - else - ec_cli ("error measuring roundtrip time"); + default: + ec_cli ("unexpected event(3): %d", event_type); + error = clib_error_return (0, "failed: unexpected event(3): %d", + event_type); + goto stop_test; + } } + while (!main_loop_done); delta = ecm->test_end_time - ecm->test_start_time; if (delta == 0.0) @@ -1514,15 +1692,12 @@ parse_config: error = clib_error_return (0, "failed: zero delta-t"); goto stop_test; } - - total_bytes = (ecm->echo_bytes ? ecm->rx_total : ecm->tx_total); - transfer_type = ecm->echo_bytes ? "full-duplex" : "half-duplex"; - ec_cli ("%lld bytes (%lld mbytes, %lld gbytes) in %.2f seconds", total_bytes, - total_bytes / (1ULL << 20), total_bytes / (1ULL << 30), delta); - ec_cli ("%.2f bytes/second %s", ((f64) total_bytes) / (delta), - transfer_type); - ec_cli ("%.4f gbit/second %s", (((f64) total_bytes * 8.0) / delta / 1e9), - transfer_type); + /* Print last interval */ + if (ecm->report_interval && + vlib_time_now (vm) - ecm->last_print_time >= 0.1f) + ec_print_periodic_stats (vm, print_header, true); + ec_cli ("Test finished at %.6f", ecm->test_end_time); + ec_print_final_stats (vm, delta); if (ecm->cfg.test_bytes && ecm->test_failed) error = clib_error_return (0, "failed: test bytes"); @@ -1578,7 +1753,9 @@ VLIB_CLI_COMMAND (ec_command, static) = { "[run-time