From 377120083031eda4cf06cde5b5fb203e680c2a5b Mon Sep 17 00:00:00 2001 From: Nathan Skrzypczak Date: Tue, 9 Jul 2019 18:04:00 +0200 Subject: quic: Improve timing interface for quic_echo Type: feature Change-Id: I7a99b72276878625017c73dff8402f3e7fa7c33f Signed-off-by: Nathan Skrzypczak --- src/plugins/hs_apps/sapi/quic_echo.c | 302 +++++++++++++++++++++++------------ 1 file changed, 202 insertions(+), 100 deletions(-) (limited to 'src') diff --git a/src/plugins/hs_apps/sapi/quic_echo.c b/src/plugins/hs_apps/sapi/quic_echo.c index 3be513afa89..13308b50458 100644 --- a/src/plugins/hs_apps/sapi/quic_echo.c +++ b/src/plugins/hs_apps/sapi/quic_echo.c @@ -41,11 +41,6 @@ #define SESSION_INVALID_INDEX ((u32)~0) #define SESSION_INVALID_HANDLE ((u64)~0) -#define QUIC_ECHO_DBG 0 -#define DBG(_fmt, _args...) \ - if (QUIC_ECHO_DBG) \ - clib_warning (_fmt, ##_args) - #define CHECK(expected, result, _fmt, _args...) \ if (expected != result) \ ECHO_FAIL ("expected %d, got %d : " _fmt, expected, result, ##_args); @@ -55,7 +50,15 @@ echo_main_t *em = &echo_main; \ em->has_failed = 1; \ em->time_to_stop = 1; \ - clib_warning ("ECHO-ERROR: "_fmt, ##_args); \ + if (em->log_lvl > 1) \ + clib_warning ("ECHO-ERROR: "_fmt, ##_args); \ + } + +#define ECHO_LOG(lvl, _fmt,_args...) \ + { \ + echo_main_t *em = &echo_main; \ + if (em->log_lvl > lvl) \ + clib_warning (_fmt, ##_args); \ } typedef struct @@ -205,6 +208,8 @@ typedef struct data_source_t data_source; u8 send_quic_disconnects; /* actively send disconnect */ u8 send_stream_disconnects; /* actively send disconnect */ + u8 output_json; + u8 log_lvl; u8 *appns_id; u64 appns_flags; @@ -222,7 +227,7 @@ typedef struct u64 rx_total; /* Event based timing : start & end depend on CLI specified events */ - u8 first_sconnect_sent; /* Sent the first Stream session connect ? */ + u8 events_sent; f64 start_time; f64 end_time; u8 timing_start_event; @@ -616,7 +621,7 @@ echo_disconnect_session (echo_main_t * em, echo_session_t * s) dmp->_vl_msg_id = ntohs (VL_API_DISCONNECT_SESSION); dmp->client_index = em->my_client_index; dmp->handle = s->vpp_session_handle; - DBG ("Disconnect session 0x%lx", dmp->handle); + ECHO_LOG (1, "Disconnect session 0x%lx", dmp->handle); vl_msg_api_send_shmem (em->vl_input_queue, (u8 *) & dmp); } @@ -633,7 +638,7 @@ wait_for_segment_allocation (u64 segment_handle) f64 timeout; timeout = clib_time_now (&em->clib_time) + TIMEOUT; uword *segment_present; - DBG ("Waiting for segment 0x%lx...", segment_handle); + ECHO_LOG (1, "Waiting for segment 0x%lx...", segment_handle); while (clib_time_now (&em->clib_time) < timeout) { clib_spinlock_lock (&em->segment_handles_lock); @@ -644,17 +649,20 @@ wait_for_segment_allocation (u64 segment_handle) if (em->time_to_stop == 1) return 0; } - DBG ("timeout wait_for_segment_allocation (0x%lx)", segment_handle); + ECHO_LOG (1, "timeout wait_for_segment_allocation (0x%lx)", segment_handle); return -1; } static void quic_echo_notify_event (echo_main_t * em, echo_test_evt_t e) { + if (em->events_sent & e) + return; if (em->timing_start_event == e) em->start_time = clib_time_now (&em->clib_time); else if (em->timing_end_event == e) em->end_time = clib_time_now (&em->clib_time); + em->events_sent |= e; } static void @@ -755,27 +763,62 @@ static void session_print_stats (echo_main_t * em, echo_session_t * session) { f64 deltat = clib_time_now (&em->clib_time) - session->start; - fformat (stdout, "Session 0x%x done in %.6fs RX[%.4f] TX[%.4f] Gbit/s\n", - session->vpp_session_handle, deltat, - (session->bytes_received * 8.0) / deltat / 1e9, - (session->bytes_sent * 8.0) / deltat / 1e9); + ECHO_LOG (0, "Session 0x%x done in %.6fs RX[%.4f] TX[%.4f] Gbit/s\n", + session->vpp_session_handle, deltat, + (session->bytes_received * 8.0) / deltat / 1e9, + (session->bytes_sent * 8.0) / deltat / 1e9); +} + +static void +echo_event_didnt_happen (u8 e) +{ + echo_main_t *em = &echo_main; + u8 *s = format (0, "%U", echo_format_timing_event, e); + ECHO_LOG (0, "Expected event %s to happend, which did not", s); + em->has_failed = 1; +} + +static void +print_global_json_stats (echo_main_t * em) +{ + if (!(em->events_sent & em->timing_start_event)) + return echo_event_didnt_happen (em->timing_start_event); + if (!(em->events_sent & em->timing_end_event)) + return echo_event_didnt_happen (em->timing_end_event); + f64 deltat = em->end_time - em->start_time; + u8 *start_evt = + format (0, "%U", echo_format_timing_event, em->timing_start_event); + u8 *end_evt = + format (0, "%U", echo_format_timing_event, em->timing_end_event); + fformat (stdout, "{\n"); + fformat (stdout, "\"time\": \"%.9f\",\n", deltat); + fformat (stdout, "\"start_evt\": \"%s\",\n", start_evt); + fformat (stdout, "\"end_evt\": \"%s\",\n", end_evt); + fformat (stdout, "\"rx_data\": %lld,\n", em->rx_total); + fformat (stdout, "\"tx_rx\": %lld,\n", em->tx_total); + fformat (stdout, "}\n"); } static void print_global_stats (echo_main_t * em) { + u8 *s; + if (!(em->events_sent & em->timing_start_event)) + return echo_event_didnt_happen (em->timing_start_event); + if (!(em->events_sent & em->timing_end_event)) + return echo_event_didnt_happen (em->timing_end_event); f64 deltat = em->end_time - em->start_time; - u8 *s = format (0, "%U:%U", - echo_format_timing_event, em->timing_start_event, - echo_format_timing_event, em->timing_end_event); + s = format (0, "%U:%U", + echo_format_timing_event, em->timing_start_event, + echo_format_timing_event, em->timing_end_event); fformat (stdout, "Timing %s\n", s); fformat (stdout, "-------- TX --------\n"); - fformat (stdout, "%lld bytes (%lld mbytes, %lld gbytes) in %.2f seconds\n", + fformat (stdout, "%lld bytes (%lld mbytes, %lld gbytes) in %.6f seconds\n", em->tx_total, em->tx_total / (1ULL << 20), em->tx_total / (1ULL << 30), deltat); fformat (stdout, "%.4f Gbit/second\n", (em->tx_total * 8.0) / deltat / 1e9); fformat (stdout, "-------- RX --------\n"); - fformat (stdout, "%lld bytes (%lld mbytes, %lld gbytes) in %.2f seconds\n", + fformat (stdout, "%lld bytes (%lld mbytes, %lld gbytes) in %.6f seconds\n", em->rx_total, em->rx_total / (1ULL << 20), em->rx_total / (1ULL << 30), deltat); fformat (stdout, "%.4f Gbit/second\n", (em->rx_total * 8.0) / deltat / 1e9); @@ -800,7 +843,7 @@ echo_free_sessions (echo_main_t * em) { /* Free session */ s = pool_elt_at_index (em->sessions, *session_index); - DBG ("Freeing session 0x%lx", s->vpp_session_handle); + ECHO_LOG (1, "Freeing session 0x%lx", s->vpp_session_handle); pool_put (em->sessions, s); clib_memset (s, 0xfe, sizeof (*s)); } @@ -828,8 +871,8 @@ echo_cleanup_session (echo_main_t * em, echo_session_t * s) else if (s->session_type == QUIC_SESSION_TYPE_STREAM) clib_atomic_sub_fetch (&em->n_clients_connected, 1); - DBG ("Cleanup sessions (still %uQ %uS)", em->n_quic_clients_connected, - em->n_clients_connected); + ECHO_LOG (1, "Cleanup sessions (still %uQ %uS)", + em->n_quic_clients_connected, em->n_clients_connected); hash_unset (em->session_index_by_vpp_handles, s->vpp_session_handle); s->session_state = QUIC_SESSION_STATE_CLOSED; } @@ -848,6 +891,28 @@ echo_initiate_session_close (echo_main_t * em, echo_session_t * s, u8 active) echo_cleanup_session (em, s); /* We can clean Q/Lsessions right away */ } +static void +echo_initiate_qsession_close_no_stream (echo_main_t * em) +{ + ECHO_LOG (1, "Closing Qsessions"); + /* Close Quic session without streams */ + echo_session_t *s; + + /* *INDENT-OFF* */ + pool_foreach (s, em->sessions, + ({ + if (s->session_type == QUIC_SESSION_TYPE_QUIC && s->accepted_session_count == 0) + { + ECHO_LOG (1,"ACTIVE close 0x%lx", s->vpp_session_handle); + if (em->send_quic_disconnects == ECHO_CLOSE_F_ACTIVE) + echo_disconnect_session (em, s); + else if (em->send_quic_disconnects == ECHO_CLOSE_F_NONE) + echo_cleanup_session (em, s); + } + })); + /* *INDENT-ON* */ +} + static void test_recv_bytes (echo_main_t * em, echo_session_t * s, u8 * rx_buf, u32 n_read) @@ -859,12 +924,12 @@ test_recv_bytes (echo_main_t * em, echo_session_t * s, u8 * rx_buf, expected = (s->bytes_received + i) & 0xff; if (rx_buf[i] == expected || em->max_test_msg > 0) continue; - clib_warning ("Session 0x%lx byte %lld was 0x%x expected 0x%x", - s->vpp_session_handle, s->bytes_received + i, rx_buf[i], - expected); + ECHO_LOG (0, "Session 0x%lx byte %lld was 0x%x expected 0x%x", + s->vpp_session_handle, s->bytes_received + i, rx_buf[i], + expected); em->max_test_msg--; if (em->max_test_msg == 0) - clib_warning ("Too many errors, hiding next ones"); + ECHO_LOG (0, "Too many errors, hiding next ones"); if (em->test_return_packets == RETURN_PACKETS_ASSERT) ECHO_FAIL ("test-bytes errored"); } @@ -946,16 +1011,20 @@ echo_thread_handle_data (echo_main_t * em, echo_session_t * s, u8 * rx_buf) return; } - /* check idle clients */ - if (n_sent || n_read) - s->idle_cycles = 0; - else if (s->idle_cycles++ == 1e7) + if (em->log_lvl > 1) { - s->idle_cycles = 0; - DBG ("Idle client TX:%dB RX:%dB", s->bytes_to_send, - s->bytes_to_receive); - DBG ("Idle FIFOs TX:%dB RX:%dB", svm_fifo_max_dequeue (s->tx_fifo), - svm_fifo_max_dequeue (s->rx_fifo)); + /* check idle clients */ + if (n_sent || n_read) + s->idle_cycles = 0; + else if (s->idle_cycles++ == 1e7) + { + s->idle_cycles = 0; + ECHO_LOG (1, "Idle client TX:%dB RX:%dB", s->bytes_to_send, + s->bytes_to_receive); + ECHO_LOG (1, "Idle FIFOs TX:%dB RX:%dB", + svm_fifo_max_dequeue (s->tx_fifo), + svm_fifo_max_dequeue (s->rx_fifo)); + } } } @@ -963,9 +1032,10 @@ static void echo_thread_handle_closing (echo_main_t * em, echo_session_t * s) { - DBG ("[%lu/%lu] -> S(%x) -> [%lu/%lu]", - s->bytes_received, s->bytes_received + s->bytes_to_receive, - s->session_index, s->bytes_sent, s->bytes_sent + s->bytes_to_send); + ECHO_LOG (1, "[%lu/%lu] -> S(%x) -> [%lu/%lu]", + s->bytes_received, s->bytes_received + s->bytes_to_receive, + s->session_index, s->bytes_sent, + s->bytes_sent + s->bytes_to_send); clib_atomic_fetch_add (&em->tx_total, s->bytes_sent); clib_atomic_fetch_add (&em->rx_total, s->bytes_received); @@ -1032,8 +1102,8 @@ echo_start_rx_thread (u32 session_index) { first_idx = n * (nc / n); thread_sessions = (nc + 1) % n == 0 ? n : (nc + 1) % n; - DBG ("Start thread %u [%u -> %u]", nc / n, first_idx, - first_idx + thread_sessions - 1); + ECHO_LOG (1, "Start thread %u [%u -> %u]", nc / n, first_idx, + first_idx + thread_sessions - 1); return pthread_create (&em->client_thread_handles[nc / n], NULL /*attr */ , echo_thread_fn, (void *) ((u64) first_idx << 32 | (u64) @@ -1054,10 +1124,9 @@ session_bound_handler (session_bound_msg_t * mp) clib_net_to_host_u32 (mp->retval)); return; } - - clib_warning ("listening on %U:%u", format_ip46_address, mp->lcl_ip, - mp->lcl_is_ip4 ? IP46_TYPE_IP4 : IP46_TYPE_IP6, - clib_net_to_host_u16 (mp->lcl_port)); + ECHO_LOG (0, "listening on %U:%u", format_ip46_address, mp->lcl_ip, + mp->lcl_is_ip4 ? IP46_TYPE_IP4 : IP46_TYPE_IP6, + clib_net_to_host_u16 (mp->lcl_port)); /* Allocate local session and set it up */ listen_session = echo_session_alloc (em); @@ -1111,7 +1180,8 @@ session_accepted_handler (session_accepted_msg_t * mp) clib_atomic_fetch_add (&listen_session->accepted_session_count, 1); /* Add it to lookup table */ - DBG ("Accepted session 0x%lx -> 0x%lx", mp->handle, mp->listener_handle); + ECHO_LOG (1, "Accepted session 0x%lx -> 0x%lx", mp->handle, + mp->listener_handle); hash_set (em->session_index_by_vpp_handles, mp->handle, session->session_index); @@ -1124,6 +1194,7 @@ session_accepted_handler (session_accepted_msg_t * mp) if (listen_session->session_type == QUIC_SESSION_TYPE_LISTEN) { + quic_echo_notify_event (em, ECHO_EVT_FIRST_QCONNECT); session->session_type = QUIC_SESSION_TYPE_QUIC; if (em->cb_vft.quic_accepted_cb) em->cb_vft.quic_accepted_cb (mp, session->session_index); @@ -1132,6 +1203,7 @@ session_accepted_handler (session_accepted_msg_t * mp) else if (em->i_am_master) { session->session_type = QUIC_SESSION_TYPE_STREAM; + quic_echo_notify_event (em, ECHO_EVT_FIRST_SCONNECT); if (em->cb_vft.server_stream_accepted_cb) em->cb_vft.server_stream_accepted_cb (mp, session->session_index); clib_atomic_fetch_add (&em->n_clients_connected, 1); @@ -1139,19 +1211,28 @@ session_accepted_handler (session_accepted_msg_t * mp) else { session->session_type = QUIC_SESSION_TYPE_STREAM; + quic_echo_notify_event (em, ECHO_EVT_FIRST_SCONNECT); if (em->cb_vft.client_stream_accepted_cb) em->cb_vft.client_stream_accepted_cb (mp, session->session_index); clib_atomic_fetch_add (&em->n_clients_connected, 1); } - if (em->n_clients_connected == em->n_clients * em->n_stream_clients) + if (em->n_clients_connected == em->n_clients * em->n_stream_clients + && em->n_clients_connected != 0) { - DBG ("App is ready"); + ECHO_LOG (1, "App is ready"); em->state = STATE_READY; quic_echo_notify_event (em, ECHO_EVT_LAST_SCONNECTED); } if (em->n_quic_clients_connected == em->n_clients) - quic_echo_notify_event (em, ECHO_EVT_LAST_QCONNECTED); + { + quic_echo_notify_event (em, ECHO_EVT_LAST_QCONNECTED); + if (em->n_stream_clients == 0) + { + em->state = STATE_READY; + echo_initiate_qsession_close_no_stream (em); + } + } } static void @@ -1196,10 +1277,10 @@ session_connected_handler (session_connected_msg_t * mp) session->listener_index = listen_session->session_index; } - DBG ("Connected session 0x%lx -> 0x%lx", mp->handle, - listener_index != - SESSION_INVALID_INDEX ? listen_session->vpp_session_handle : (u64) ~ - 0); + ECHO_LOG (1, "Connected session 0x%lx -> 0x%lx", mp->handle, + listener_index != + SESSION_INVALID_INDEX ? listen_session->vpp_session_handle : (u64) + ~ 0); hash_set (em->session_index_by_vpp_handles, mp->handle, session->session_index); @@ -1225,14 +1306,22 @@ session_connected_handler (session_connected_msg_t * mp) clib_atomic_fetch_add (&em->n_clients_connected, 1); } - if (em->n_clients_connected == em->n_clients * em->n_stream_clients) + if (em->n_clients_connected == em->n_clients * em->n_stream_clients + && em->n_clients_connected != 0) { - DBG ("App is ready"); + ECHO_LOG (1, "App is ready"); em->state = STATE_READY; quic_echo_notify_event (em, ECHO_EVT_LAST_SCONNECTED); } if (em->n_quic_clients_connected == em->n_clients) - quic_echo_notify_event (em, ECHO_EVT_LAST_QCONNECTED); + { + quic_echo_notify_event (em, ECHO_EVT_LAST_QCONNECTED); + if (em->n_stream_clients == 0) + { + em->state = STATE_READY; + echo_initiate_qsession_close_no_stream (em); + } + } } /* @@ -1249,17 +1338,13 @@ echo_on_connected_connect (session_connected_msg_t * mp, u32 session_index) u8 *uri = format (0, "QUIC://session/%lu", mp->handle); u64 i; - if (!em->first_sconnect_sent) - { - em->first_sconnect_sent = 1; - quic_echo_notify_event (em, ECHO_EVT_FIRST_SCONNECT); - } + quic_echo_notify_event (em, ECHO_EVT_FIRST_SCONNECT); for (i = 0; i < em->n_stream_clients; i++) echo_send_connect (em, uri, session_index); - clib_warning ("Qsession 0x%llx connected to %U:%d", - mp->handle, format_ip46_address, &mp->lcl.ip, - mp->lcl.is_ip4, clib_net_to_host_u16 (mp->lcl.port)); + ECHO_LOG (0, "Qsession 0x%llx connected to %U:%d", + mp->handle, format_ip46_address, &mp->lcl.ip, + mp->lcl.is_ip4, clib_net_to_host_u16 (mp->lcl.port)); } static void @@ -1309,15 +1394,11 @@ static void echo_on_accept_connect (session_accepted_msg_t * mp, u32 session_index) { echo_main_t *em = &echo_main; - DBG ("Accept on QSession 0x%lx %u", mp->handle); + ECHO_LOG (1, "Accept on QSession 0x%lx %u", mp->handle); u8 *uri = format (0, "QUIC://session/%lu", mp->handle); u32 i; - if (!em->first_sconnect_sent) - { - em->first_sconnect_sent = 1; - quic_echo_notify_event (em, ECHO_EVT_FIRST_SCONNECT); - } + quic_echo_notify_event (em, ECHO_EVT_FIRST_SCONNECT); for (i = 0; i < em->n_stream_clients; i++) echo_send_connect (em, uri, session_index); } @@ -1334,8 +1415,8 @@ echo_on_accept_log_ip (session_accepted_msg_t * mp, u32 session_index) { u8 *ip_str; ip_str = format (0, "%U", format_ip46_address, &mp->rmt.ip, mp->rmt.is_ip4); - clib_warning ("Accepted session from: %s:%d", ip_str, - clib_net_to_host_u16 (mp->rmt.port)); + ECHO_LOG (0, "Accepted session from: %s:%d", ip_str, + clib_net_to_host_u16 (mp->rmt.port)); } @@ -1391,7 +1472,7 @@ session_disconnected_handler (session_disconnected_msg_t * mp) echo_session_t *s; uword *p; int rv = 0; - DBG ("passive close session 0x%lx", mp->handle); + ECHO_LOG (1, "passive close session 0x%lx", mp->handle); p = hash_get (em->session_index_by_vpp_handles, mp->handle); if (!p) { @@ -1423,7 +1504,7 @@ session_reset_handler (session_reset_msg_t * mp) uword *p; int rv = 0; - DBG ("Reset session 0x%lx", mp->handle); + ECHO_LOG (1, "Reset session 0x%lx", mp->handle); p = hash_get (em->session_index_by_vpp_handles, mp->handle); if (!p) @@ -1466,7 +1547,7 @@ handle_mq_event (session_event_t * e) case SESSION_IO_EVT_RX: break; default: - clib_warning ("unhandled event %u", e->event_type); + ECHO_LOG (0, "unhandled event %u", e->event_type); } } @@ -1493,7 +1574,7 @@ wait_for_state_change (echo_main_t * em, connection_state_t state, handle_mq_event (e); svm_msg_q_free_msg (em->our_event_queue, &msg); } - DBG ("timeout waiting for %U", format_quic_echo_state, state); + ECHO_LOG (1, "timeout waiting for %U", format_quic_echo_state, state); return -1; } @@ -1503,7 +1584,7 @@ echo_event_loop (echo_main_t * em) svm_msg_q_msg_t msg; session_event_t *e; - DBG ("Waiting for data on %u clients", em->n_clients_connected); + ECHO_LOG (1, "Waiting for data on %u clients", em->n_clients_connected); while (em->n_clients_connected | em->n_quic_clients_connected) { int rc = svm_msg_q_sub (em->our_event_queue, &msg, SVM_Q_TIMEDWAIT, 1); @@ -1570,7 +1651,7 @@ vl_api_application_attach_reply_t_handler (vl_api_application_attach_reply_t * u32 n_fds = 0; u64 segment_handle; segment_handle = clib_net_to_host_u64 (mp->segment_handle); - DBG ("Attached returned app %u", htons (mp->app_index)); + ECHO_LOG (1, "Attached returned app %u", htons (mp->app_index)); if (mp->retval) { @@ -1627,7 +1708,7 @@ vl_api_application_attach_reply_t_handler (vl_api_application_attach_reply_t * clib_spinlock_lock (&em->segment_handles_lock); hash_set (em->shared_segment_handles, segment_handle, 1); clib_spinlock_unlock (&em->segment_handles_lock); - DBG ("Mapped segment 0x%lx", segment_handle); + ECHO_LOG (1, "Mapped segment 0x%lx", segment_handle); em->state = STATE_ATTACHED; } @@ -1654,7 +1735,7 @@ vl_api_unmap_segment_t_handler (vl_api_unmap_segment_t * mp) clib_spinlock_lock (&em->segment_handles_lock); hash_unset (em->shared_segment_handles, segment_handle); clib_spinlock_unlock (&em->segment_handles_lock); - DBG ("Unmaped segment 0x%lx", segment_handle); + ECHO_LOG (1, "Unmaped segment 0x%lx", segment_handle); } static void @@ -1694,7 +1775,7 @@ vl_api_map_another_segment_t_handler (vl_api_map_another_segment_t * mp) clib_spinlock_lock (&em->segment_handles_lock); hash_set (em->shared_segment_handles, segment_handle, 1); clib_spinlock_unlock (&em->segment_handles_lock); - DBG ("Mapped segment 0x%lx", segment_handle); + ECHO_LOG (1, "Mapped segment 0x%lx", segment_handle); } static void @@ -1740,7 +1821,7 @@ vl_api_disconnect_session_reply_t_handler (vl_api_disconnect_session_reply_t * return; } - DBG ("Got disonnected reply for session 0x%lx", mp->handle); + ECHO_LOG (1, "Got disonnected reply for session 0x%lx", mp->handle); p = hash_get (em->session_index_by_vpp_handles, mp->handle); if (!p) { @@ -1779,14 +1860,14 @@ vl_api_connect_uri_reply_t_handler (vl_api_connect_uri_reply_t * mp) /* retry connect */ if (mp->context == SESSION_INVALID_INDEX) { - DBG ("Retrying connect %s", em->uri); + ECHO_LOG (1, "Retrying connect %s", em->uri); echo_send_connect (em, em->uri, SESSION_INVALID_INDEX); } else { session = pool_elt_at_index (em->sessions, mp->context); uri = format (0, "QUIC://session/%lu", session->vpp_session_handle); - DBG ("Retrying connect %s", uri); + ECHO_LOG (1, "Retrying connect %s", uri); echo_send_connect (em, uri, mp->context); } } @@ -1827,7 +1908,8 @@ static void print_usage_and_exit (void) { fprintf (stderr, - "quic_echo [socket-name SOCKET] [client|server] [uri URI] [OPTIONS]\n" + "Usage: quic_echo [socket-name SOCKET] [client|server] [uri URI] [OPTIONS]\n" + "Generates traffic and assert correct teardown of the QUIC hoststack\n" "\n" " socket-name PATH Specify the binary socket path to connect to VPP\n" " use-svm-api Use SVM API to connect to VPP\n" @@ -1841,19 +1923,32 @@ print_usage_and_exit (void) " global-scope global-scope option\n" " secret SECRET set namespace secret\n" " chroot prefix PATH Use PATH as memory root path\n" - " quic-setup OPT OPT=serverstream : Client open N connections. On each one server opens M streams\n" - " by default : Client open N connections. On each one client opens M streams\n" - " sclose=[Y|N|W] When a stream is done (RX & TX), send close[Y] wait for close[W] or pass[N]\n" - " qclose=[Y|N|W] When a connection is done (RX & TX), send close[Y] wait for close[W] or pass[N]\n" + " quic-setup OPT OPT=serverstream : Client open N connections. \n" + " On each one server opens M streams\n" + " OPT=default : Client open N connections.\n" + " On each one client opens M streams\n" + " sclose=[Y|N|W] When a stream is done, pass[N] send[Y] or wait[W] for close\n" + " qclose=[Y|N|W] When a connection is done pass[N] send[Y] or wait[W] for close\n" "\n" - " nclients N[/M] Open N QUIC connections, each one with M streams (M defaults to 1)\n" - " nthreads N Use N busy loop threads for data [in addition to main & msg queue]\n" - " TX=1337[Kb|Mb|GB] Send 1337 [K|M|G]bytes, use TX=RX to reflect the data\n" - " RX=1337[Kb|Mb|GB] Expect 1337 [K|M|G]bytes\n" + " time START:END Time between evts START & END, events being :\n" + " start - Start of the app\n" + " qconnect - first Connection connect sent\n" + " qconnected - last Connection connected\n" + " sconnect - first Stream connect sent\n" + " sconnected - last Stream got connected\n" + " lastbyte - Last expected byte received\n" + " exit - Exiting of the app\n" + " json Output global stats in json\n" + " log=N Set the log level to [0: no output, 1:errors, 2:log]\n" "\n" - "Default config is :\n" - "server nclients 1/1 RX=64Kb TX=RX\n" - "client nclients 1/1 RX=64Kb TX=64Kb\n"); + " nclients N[/M] Open N QUIC connections, each one with M streams (M defaults to 1)\n" + " nthreads N Use N busy loop threads for data [in addition to main & msg queue]\n" + " TX=1337[Kb|Mb|GB] Send 1337 [K|M|G]bytes, use TX=RX to reflect the data\n" + " RX=1337[Kb|Mb|GB] Expect 1337 [K|M|G]bytes\n" + "\n" + "Default configuration is :\n" + " server nclients 1/1 RX=64Kb TX=RX\n" + " client nclients 1/1 RX=64Kb TX=64Kb\n"); exit (1); } @@ -1922,6 +2017,10 @@ quic_echo_process_opts (int argc, char **argv) ; else if (unformat (a, "RX=%U", unformat_data, &em->bytes_to_receive)) ; + else if (unformat (a, "json")) + em->output_json = 1; + else if (unformat (a, "log=%d", &em->log_lvl)) + ; else if (unformat (a, "sclose=%U", unformat_close, &em->send_stream_disconnects)) @@ -2021,7 +2120,7 @@ main (int argc, char **argv) if (connect_to_vpp (app_name) < 0) { svm_region_exit (); - fformat (stderr, "ECHO-ERROR: Couldn't connect to vpe, exiting...\n"); + ECHO_FAIL ("ECHO-ERROR: Couldn't connect to vpe, exiting...\n"); exit (1); } @@ -2030,7 +2129,7 @@ main (int argc, char **argv) application_send_attach (em); if (wait_for_state_change (em, STATE_ATTACHED, TIMEOUT)) { - fformat (stderr, "ECHO-ERROR: Couldn't attach to vpp, exiting...\n"); + ECHO_FAIL ("ECHO-ERROR: Couldn't attach to vpp, exiting...\n"); exit (1); } if (em->i_am_master) @@ -2038,20 +2137,23 @@ main (int argc, char **argv) else clients_run (em); quic_echo_notify_event (em, ECHO_EVT_EXIT); - print_global_stats (em); + if (em->output_json) + print_global_json_stats (em); + else + print_global_stats (em); echo_free_sessions (em); echo_assert_test_suceeded (em); application_detach (em); if (wait_for_state_change (em, STATE_DETACHED, TIMEOUT)) { - fformat (stderr, "ECHO-ERROR: Couldn't detach from vpp, exiting...\n"); + ECHO_FAIL ("ECHO-ERROR: Couldn't detach from vpp, exiting...\n"); exit (1); } if (em->use_sock_api) vl_socket_client_disconnect (); else vl_client_disconnect_from_vlib (); - fformat (stdout, "Test complete !\n"); + ECHO_LOG (0, "Test complete !\n"); exit (em->has_failed); } -- cgit 1.2.3-korg