From 08f26641fa920d5a9629140430660adcf736a1c7 Mon Sep 17 00:00:00 2001 From: Nathan Skrzypczak Date: Tue, 3 Dec 2019 17:13:09 +0100 Subject: [PATCH] hsa: Less verbose logging for many sessions Type: feature ECHO_LOG has the following levels 0 -> global progression (many connections) 1 -> Connection global evts (some conn, much data) 2 -> More connection events 3 -> Data related logging Change-Id: I69eeaa0dd02a4b8ebcfefa1c7a218ef57f217d2b Signed-off-by: Nathan Skrzypczak --- src/plugins/hs_apps/sapi/vpp_echo.c | 61 +++++++++++++++----------- src/plugins/hs_apps/sapi/vpp_echo_bapi.c | 8 ++-- src/plugins/hs_apps/sapi/vpp_echo_common.c | 14 +++--- src/plugins/hs_apps/sapi/vpp_echo_common.h | 3 ++ src/plugins/hs_apps/sapi/vpp_echo_proto_quic.c | 45 ++++++++++++++----- src/plugins/hs_apps/sapi/vpp_echo_proto_tcp.c | 2 +- 6 files changed, 83 insertions(+), 50 deletions(-) diff --git a/src/plugins/hs_apps/sapi/vpp_echo.c b/src/plugins/hs_apps/sapi/vpp_echo.c index cfe1a3d37be..18a0280e6b2 100644 --- a/src/plugins/hs_apps/sapi/vpp_echo.c +++ b/src/plugins/hs_apps/sapi/vpp_echo.c @@ -160,6 +160,10 @@ print_global_json_stats (echo_main_t * em) em->stats.active_count.q, em->stats.active_count.s); fformat (stdout, " \"clean\": { \"q\": %d, \"s\": %d }\n", em->stats.clean_count.q, em->stats.clean_count.s); + fformat (stdout, " \"accepted\": { \"q\": %d, \"s\": %d }\n", + em->stats.accepted_count.q, em->stats.accepted_count.s); + fformat (stdout, " \"connected\": { \"q\": %d, \"s\": %d }\n", + em->stats.connected_count.q, em->stats.connected_count.s); fformat (stdout, " }\n"); fformat (stdout, " \"results\": {\n"); fformat (stdout, " \"has_failed\": \"%d\"\n", em->has_failed); @@ -220,6 +224,11 @@ print_global_stats (echo_main_t * em) em->stats.active_count.s, em->stats.active_count.q); fformat (stdout, "Discarded %d streams (and %d Quic conn)\n", em->stats.clean_count.s, em->stats.clean_count.q); + fformat (stdout, "--------------------\n"); + fformat (stdout, "Got accept on %d streams (and %d Quic conn)\n", + em->stats.accepted_count.s, em->stats.accepted_count.q); + fformat (stdout, "Got connected on %d streams (and %d Quic conn)\n", + em->stats.connected_count.s, em->stats.connected_count.q); if (em->has_failed) fformat (stdout, "\nFailure Return Status: %d\n%v", em->has_failed, em->fail_descr); @@ -231,7 +240,7 @@ void echo_update_count_on_session_close (echo_main_t * em, echo_session_t * s) { - ECHO_LOG (1, "[%lu/%lu] -> %U -> [%lu/%lu]", + ECHO_LOG (2, "[%lu/%lu] -> %U -> [%lu/%lu]", s->bytes_received, s->bytes_received + s->bytes_to_receive, echo_format_session, s, s->bytes_sent, s->bytes_sent + s->bytes_to_send); @@ -278,12 +287,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; - ECHO_LOG (0, "Session 0x%lx byte %lld was 0x%x expected 0x%x", + ECHO_LOG (1, "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) - ECHO_LOG (0, "Too many errors, hiding next ones"); + ECHO_LOG (1, "Too many errors, hiding next ones"); if (em->test_return_packets == RETURN_PACKETS_ASSERT) ECHO_FAIL (ECHO_FAIL_TEST_BYTES_ERR, "test-bytes errored"); } @@ -339,7 +348,7 @@ echo_check_closed_listener (echo_main_t * em, echo_session_t * s) /* if parent has died, terminate gracefully */ if (s->listener_index == SESSION_INVALID_INDEX) { - ECHO_LOG (2, "%U: listener_index == SESSION_INVALID_INDEX", + ECHO_LOG (3, "%U: listener_index == SESSION_INVALID_INDEX", echo_format_session, s); return; } @@ -353,7 +362,7 @@ echo_check_closed_listener (echo_main_t * em, echo_session_t * s) return; } - ECHO_LOG (2, "%U died, close child %U", echo_format_session, ls, + ECHO_LOG (3, "%U died, close child %U", echo_format_session, ls, echo_format_session, s); echo_update_count_on_session_close (em, s); em->proto_cb_vft->cleanup_cb (s, 1 /* parent_died */ ); @@ -394,7 +403,7 @@ echo_handle_data (echo_main_t * em, echo_session_t * s, u8 * rx_buf) clib_atomic_fetch_add (&em->stats.clean_count.s, 1); } } - ECHO_LOG (2, "%U: %U", echo_format_session, s, + ECHO_LOG (3, "%U: %U", echo_format_session, s, echo_format_session_state, s->session_state); return; } @@ -407,12 +416,12 @@ echo_handle_data (echo_main_t * em, echo_session_t * s, u8 * rx_buf) else if (s->idle_cycles++ == 1e7) { s->idle_cycles = 0; - ECHO_LOG (1, "Idle client TX:%dB RX:%dB", s->bytes_to_send, + ECHO_LOG (2, "Idle client TX:%dB RX:%dB", s->bytes_to_send, s->bytes_to_receive); - ECHO_LOG (1, "Idle FIFOs TX:%dB RX:%dB", + ECHO_LOG (2, "Idle FIFOs TX:%dB RX:%dB", svm_fifo_max_dequeue (s->tx_fifo), svm_fifo_max_dequeue (s->rx_fifo)); - ECHO_LOG (1, "Session 0x%lx state %U", s->vpp_session_handle, + ECHO_LOG (2, "Session 0x%lx state %U", s->vpp_session_handle, echo_format_session_state, s->session_state); } } @@ -428,7 +437,7 @@ echo_data_thread_fn (void *arg) u32 idx = (u64) arg; if (n * idx >= N) { - ECHO_LOG (1, "Thread %u exiting, no sessions to care for", idx); + ECHO_LOG (2, "Thread %u exiting, no sessions to care for", idx); pthread_exit (0); } u32 thread_n_sessions = clib_min (n, N - n * idx); @@ -460,13 +469,13 @@ echo_data_thread_fn (void *arg) echo_check_closed_listener (em, s); break; case ECHO_SESSION_STATE_CLOSING: - ECHO_LOG (2, "%U: %U", echo_format_session, s, + ECHO_LOG (3, "%U: %U", echo_format_session, s, echo_format_session_state, s->session_state); echo_update_count_on_session_close (em, s); em->proto_cb_vft->cleanup_cb (s, 0 /* parent_died */ ); break; case ECHO_SESSION_STATE_CLOSED: - ECHO_LOG (2, "%U: %U", echo_format_session, s, + ECHO_LOG (3, "%U: %U", echo_format_session, s, echo_format_session_state, s->session_state); n_closed_sessions++; break; @@ -474,7 +483,7 @@ echo_data_thread_fn (void *arg) if (n_closed_sessions == thread_n_sessions) break; } - ECHO_LOG (1, "Mission accomplished!"); + ECHO_LOG (2, "Mission accomplished!"); pthread_exit (0); } @@ -500,7 +509,7 @@ session_bound_handler (session_bound_msg_t * mp) clib_net_to_host_u32 (mp->retval)); return; } - ECHO_LOG (0, "listening on %U:%u", format_ip46_address, mp->lcl_ip, + ECHO_LOG (1, "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)); @@ -565,7 +574,7 @@ session_accepted_handler (session_accepted_msg_t * mp) session->listener_index = ls->session_index; /* Add it to lookup table */ - ECHO_LOG (1, "Accepted session 0x%lx S[%u] -> 0x%lx S[%u]", + ECHO_LOG (2, "Accepted session 0x%lx S[%u] -> 0x%lx S[%u]", mp->handle, session->session_index, mp->listener_handle, session->listener_index); echo_session_handle_add_del (em, mp->handle, session->session_index); @@ -647,17 +656,17 @@ session_disconnected_handler (session_disconnected_msg_t * mp) echo_session_t *s; if (!(s = echo_get_session_from_handle (em, mp->handle))) { - ECHO_LOG (0, "Invalid vpp_session_handle: 0x%lx", mp->handle); + ECHO_LOG (1, "Invalid vpp_session_handle: 0x%lx", mp->handle); return; } if (s->session_state == ECHO_SESSION_STATE_CLOSED) { - ECHO_LOG (1, "%U: already in ECHO_SESSION_STATE_CLOSED", + ECHO_LOG (2, "%U: already in ECHO_SESSION_STATE_CLOSED", echo_format_session, s); } else { - ECHO_LOG (1, "%U: passive close", echo_format_session, s); + ECHO_LOG (2, "%U: passive close", echo_format_session, s); em->proto_cb_vft->disconnected_cb (mp, s); } app_alloc_ctrl_evt_to_vpp (s->vpp_evt_q, app_evt, @@ -678,10 +687,10 @@ session_reset_handler (session_reset_msg_t * mp) echo_session_t *s = 0; if (!(s = echo_get_session_from_handle (em, mp->handle))) { - ECHO_LOG (0, "Invalid vpp_session_handle: 0x%lx", mp->handle); + ECHO_LOG (1, "Invalid vpp_session_handle: 0x%lx", mp->handle); return; } - ECHO_LOG (1, "%U: session reset", echo_format_session, s); + ECHO_LOG (2, "%U: session reset", echo_format_session, s); em->proto_cb_vft->reset_cb (mp, s); app_alloc_ctrl_evt_to_vpp (s->vpp_evt_q, app_evt, @@ -713,7 +722,7 @@ handle_mq_event (session_event_t * e) case SESSION_IO_EVT_RX: break; default: - ECHO_LOG (0, "unhandled event %u", e->event_type); + ECHO_LOG (1, "unhandled event %u", e->event_type); } } @@ -797,7 +806,7 @@ clients_run (echo_main_t * em) for (i = 0; i < em->n_connects; i++) echo_send_connect (SESSION_INVALID_HANDLE, SESSION_INVALID_INDEX); wait_for_state_change (em, STATE_READY, 0); - ECHO_LOG (1, "App is ready"); + ECHO_LOG (2, "App is ready"); echo_process_rpcs (em); } @@ -807,10 +816,10 @@ server_run (echo_main_t * em) echo_session_t *ls; echo_send_listen (em); wait_for_state_change (em, STATE_READY, 0); - ECHO_LOG (1, "App is ready"); + ECHO_LOG (2, "App is ready"); echo_process_rpcs (em); /* Cleanup */ - ECHO_LOG (1, "Unbind listen port"); + ECHO_LOG (2, "Unbind listen port"); ls = pool_elt_at_index (em->sessions, em->listen_session_index); echo_send_unbind (em, ls); if (wait_for_state_change (em, STATE_DISCONNECTED, TIMEOUT)) @@ -1183,7 +1192,7 @@ main (int argc, char **argv) em->state = STATE_ATTACHED; else { - ECHO_LOG (1, "Adding crypto context %U", echo_format_crypto_engine, + ECHO_LOG (2, "Adding crypto context %U", echo_format_crypto_engine, em->crypto_engine); echo_send_add_cert_key (em); if (wait_for_state_change (em, STATE_ATTACHED, TIMEOUT)) @@ -1241,7 +1250,7 @@ main (int argc, char **argv) vl_client_disconnect_from_vlib (); echo_assert_test_suceeded (em); exit_on_error: - ECHO_LOG (0, "Test complete !\n"); + ECHO_LOG (1, "Test complete !\n"); if (em->output_json) print_global_json_stats (em); else diff --git a/src/plugins/hs_apps/sapi/vpp_echo_bapi.c b/src/plugins/hs_apps/sapi/vpp_echo_bapi.c index 2bba9fc0fe2..f343ad12865 100644 --- a/src/plugins/hs_apps/sapi/vpp_echo_bapi.c +++ b/src/plugins/hs_apps/sapi/vpp_echo_bapi.c @@ -278,7 +278,7 @@ vl_api_app_attach_reply_t_handler (vl_api_app_attach_reply_t * mp) u32 n_fds = 0; u64 segment_handle; segment_handle = clib_net_to_host_u64 (mp->segment_handle); - ECHO_LOG (1, "Attached returned app %u", htons (mp->app_index)); + ECHO_LOG (2, "Attached returned app %u", htons (mp->app_index)); if (mp->retval) { @@ -346,7 +346,7 @@ vl_api_app_attach_reply_t_handler (vl_api_app_attach_reply_t * mp) } } echo_segment_handle_add_del (em, segment_handle, 1 /* add */ ); - ECHO_LOG (1, "Mapped segment 0x%lx", segment_handle); + ECHO_LOG (2, "Mapped segment 0x%lx", segment_handle); em->state = STATE_ATTACHED_NO_CERT; return; @@ -375,7 +375,7 @@ vl_api_unmap_segment_t_handler (vl_api_unmap_segment_t * mp) echo_main_t *em = &echo_main; u64 segment_handle = clib_net_to_host_u64 (mp->segment_handle); echo_segment_handle_add_del (em, segment_handle, 0 /* add */ ); - ECHO_LOG (1, "Unmaped segment 0x%lx", segment_handle); + ECHO_LOG (2, "Unmaped segment 0x%lx", segment_handle); } static void @@ -421,7 +421,7 @@ vl_api_map_another_segment_t_handler (vl_api_map_another_segment_t * mp) } } echo_segment_handle_add_del (em, segment_handle, 1 /* add */ ); - ECHO_LOG (1, "Mapped segment 0x%lx", segment_handle); + ECHO_LOG (2, "Mapped segment 0x%lx", segment_handle); return; failed: diff --git a/src/plugins/hs_apps/sapi/vpp_echo_common.c b/src/plugins/hs_apps/sapi/vpp_echo_common.c index b91203a7bb3..a5bdeb4f27b 100644 --- a/src/plugins/hs_apps/sapi/vpp_echo_common.c +++ b/src/plugins/hs_apps/sapi/vpp_echo_common.c @@ -503,12 +503,12 @@ echo_session_handle_add_del (echo_main_t * em, u64 handle, u32 sid) clib_spinlock_lock (&em->sid_vpp_handles_lock); if (sid == SESSION_INVALID_INDEX) { - ECHO_LOG (2, "hash_unset(0x%lx)", handle); + ECHO_LOG (3, "hash_unset(0x%lx)", handle); hash_unset (em->session_index_by_vpp_handles, handle); } else { - ECHO_LOG (2, "hash_set(0x%lx) S[%d]", handle, sid); + ECHO_LOG (3, "hash_set(0x%lx) S[%d]", handle, sid); hash_set (em->session_index_by_vpp_handles, handle, sid); } clib_spinlock_unlock (&em->sid_vpp_handles_lock); @@ -558,7 +558,7 @@ echo_get_session_from_handle (echo_main_t * em, u64 handle) clib_spinlock_unlock (&em->sid_vpp_handles_lock); if (!p) { - ECHO_LOG (1, "unknown handle 0x%lx", handle); + ECHO_LOG (2, "unknown handle 0x%lx", handle); return 0; } return pool_elt_at_index (em->sessions, p[0]); @@ -571,7 +571,7 @@ wait_for_segment_allocation (u64 segment_handle) f64 timeout; timeout = clib_time_now (&em->clib_time) + TIMEOUT; uword *segment_present; - ECHO_LOG (1, "Waiting for segment 0x%lx...", segment_handle); + ECHO_LOG (3, "Waiting for segment 0x%lx...", segment_handle); while (clib_time_now (&em->clib_time) < timeout) { clib_spinlock_lock (&em->segment_handles_lock); @@ -582,7 +582,7 @@ wait_for_segment_allocation (u64 segment_handle) if (em->time_to_stop == 1) return 0; } - ECHO_LOG (1, "timeout wait_for_segment_allocation (0x%lx)", segment_handle); + ECHO_LOG (2, "timeout wait_for_segment_allocation (0x%lx)", segment_handle); return -1; } @@ -598,7 +598,7 @@ wait_for_state_change (echo_main_t * em, connection_state_t state, if (em->time_to_stop) return 1; } - ECHO_LOG (1, "timeout waiting for %U", echo_format_app_state, state); + ECHO_LOG (2, "timeout waiting for %U", echo_format_app_state, state); return -1; } @@ -618,7 +618,7 @@ void echo_session_print_stats (echo_main_t * em, echo_session_t * session) { f64 deltat = clib_time_now (&em->clib_time) - session->start; - ECHO_LOG (0, "Session 0x%x done in %.6fs RX[%.4f] TX[%.4f] Gbit/s\n", + ECHO_LOG (1, "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); diff --git a/src/plugins/hs_apps/sapi/vpp_echo_common.h b/src/plugins/hs_apps/sapi/vpp_echo_common.h index 7d134d9a2c2..00d54f83070 100644 --- a/src/plugins/hs_apps/sapi/vpp_echo_common.h +++ b/src/plugins/hs_apps/sapi/vpp_echo_common.h @@ -36,6 +36,7 @@ #undef vl_printfun #define TIMEOUT 10.0 +#define LOGGING_BATCH (100) #define foreach_echo_fail_code \ _(ECHO_FAIL_NONE, "ECHO_FAIL_NONE") \ @@ -345,6 +346,8 @@ typedef struct teardown_stat_t close_count; /* received close from vpp */ teardown_stat_t active_count; /* sent close to vpp */ teardown_stat_t clean_count; /* cleaned up stale session */ + teardown_stat_t connected_count; /* connected sessions count */ + teardown_stat_t accepted_count; /* connected sessions count */ } stats; struct /* Event based timing : start & end depend on CLI specified events */ diff --git a/src/plugins/hs_apps/sapi/vpp_echo_proto_quic.c b/src/plugins/hs_apps/sapi/vpp_echo_proto_quic.c index d20bacb2a5d..18b70dd2257 100644 --- a/src/plugins/hs_apps/sapi/vpp_echo_proto_quic.c +++ b/src/plugins/hs_apps/sapi/vpp_echo_proto_quic.c @@ -60,7 +60,7 @@ quic_echo_on_connected_connect (session_connected_msg_t * mp, for (i = 0; i < eqm->n_stream_clients; i++) echo_send_rpc (em, echo_send_connect, (void *) mp->handle, session_index); - ECHO_LOG (0, "Qsession 0x%llx S[%d] connected to %U:%d", + ECHO_LOG (1, "Qsession 0x%llx S[%d] connected to %U:%d", mp->handle, session_index, format_ip46_address, &mp->lcl.ip, mp->lcl.is_ip4, clib_net_to_host_u16 (mp->lcl.port)); } @@ -106,7 +106,7 @@ quic_echo_on_accept_connect (session_accepted_msg_t * mp, u32 session_index) { echo_main_t *em = &echo_main; quic_echo_proto_main_t *eqm = &quic_echo_proto_main; - ECHO_LOG (1, "Accept on QSession 0x%lx S[%u]", mp->handle, session_index); + ECHO_LOG (2, "Accept on QSession 0x%lx S[%u]", mp->handle, session_index); u32 i; echo_notify_event (em, ECHO_EVT_FIRST_SCONNECT); @@ -127,7 +127,7 @@ quic_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); - ECHO_LOG (0, "Accepted session from: %s:%d", ip_str, + ECHO_LOG (1, "Accepted session from: %s:%d", ip_str, clib_net_to_host_u16 (mp->rmt.port)); } @@ -166,7 +166,7 @@ quic_echo_cleanup_listener (u32 listener_index, echo_main_t * em, ls = pool_elt_at_index (em->sessions, listener_index); if (ls->session_type != ECHO_SESSION_TYPE_QUIC) { - ECHO_LOG (1, "%U: Invalid listener session type", + ECHO_LOG (2, "%U: Invalid listener session type", echo_format_session, ls); return; } @@ -194,7 +194,7 @@ quic_echo_cleanup_cb (echo_session_t * s, u8 parent_died) if ((em->state == STATE_DATA_DONE) || !(s->session_state < ECHO_SESSION_STATE_CLOSED)) return; - ECHO_LOG (2, "%U cleanup (parent_died %d)", echo_format_session, s, + ECHO_LOG (3, "%U cleanup (parent_died %d)", echo_format_session, s, parent_died); s->session_state = ECHO_SESSION_STATE_CLOSED; if (s->session_type == ECHO_SESSION_TYPE_QUIC) @@ -214,7 +214,7 @@ quic_echo_cleanup_cb (echo_session_t * s, u8 parent_died) } if (!em->n_clients_connected && !eqm->n_quic_clients_connected) em->state = STATE_DATA_DONE; - ECHO_LOG (1, "Cleanup sessions (still %uQ %uS): app %U", + ECHO_LOG (2, "Cleanup sessions (still %uQ %uS): app %U", eqm->n_quic_clients_connected, em->n_clients_connected, echo_format_app_state, em->state); } @@ -223,7 +223,7 @@ static void quic_echo_initiate_qsession_close_no_stream (echo_main_t * em) { quic_echo_proto_main_t *eqm = &quic_echo_proto_main; - ECHO_LOG (1, "Closing Qsessions"); + ECHO_LOG (2, "Closing Qsessions"); /* Close Quic session without streams */ echo_session_t *s; @@ -234,19 +234,19 @@ quic_echo_initiate_qsession_close_no_stream (echo_main_t * em) { if (eqm->send_quic_disconnects == ECHO_CLOSE_F_ACTIVE) { - ECHO_LOG (1,"%U: ACTIVE close", echo_format_session, s); + ECHO_LOG (2,"%U: ACTIVE close", echo_format_session, s); echo_send_rpc (em, echo_send_disconnect_session, (void *) s->vpp_session_handle, 0); clib_atomic_fetch_add (&em->stats.active_count.q, 1); } else if (eqm->send_quic_disconnects == ECHO_CLOSE_F_NONE) { - ECHO_LOG (1,"%U: CLEAN close", echo_format_session, s); + ECHO_LOG (2,"%U: CLEAN close", echo_format_session, s); quic_echo_cleanup_cb (s, 0 /* parent_died */); clib_atomic_fetch_add (&em->stats.clean_count.q, 1); } else - ECHO_LOG (1,"%U: PASSIVE close", echo_format_session, s); + ECHO_LOG (2,"%U: PASSIVE close", echo_format_session, s); } })); /* *INDENT-ON* */ @@ -262,28 +262,39 @@ quic_echo_on_connected (session_connected_msg_t * mp, u32 session_index) if (session->listener_index == SESSION_INVALID_INDEX) { + clib_atomic_fetch_add (&em->stats.connected_count.q, 1); session->session_type = ECHO_SESSION_TYPE_QUIC; - ECHO_LOG (1, "Connected %U -> URI", echo_format_session, session); + ECHO_LOG (2, "Connected %U -> URI", echo_format_session, session); session->accepted_session_count = 0; if (eqm->cb_vft.quic_connected_cb) eqm->cb_vft.quic_connected_cb (mp, session->session_index); clib_atomic_fetch_add (&eqm->n_quic_clients_connected, 1); + + if (em->stats.connected_count.q % LOGGING_BATCH == 0) + ECHO_LOG (0, "Connected Q %d / %d", em->stats.connected_count.q, + em->n_connects); } else { + clib_atomic_fetch_add (&em->stats.connected_count.s, 1); listen_session = pool_elt_at_index (em->sessions, session->listener_index); session->session_type = ECHO_SESSION_TYPE_STREAM; clib_atomic_fetch_add (&listen_session->accepted_session_count, 1); - ECHO_LOG (1, "Connected %U -> %U", echo_format_session, session, + ECHO_LOG (2, "Connected %U -> %U", echo_format_session, session, echo_format_session, listen_session); if (em->i_am_master && eqm->cb_vft.server_stream_connected_cb) eqm->cb_vft.server_stream_connected_cb (mp, session->session_index); if (!em->i_am_master && eqm->cb_vft.client_stream_connected_cb) eqm->cb_vft.client_stream_connected_cb (mp, session->session_index); clib_atomic_fetch_add (&em->n_clients_connected, 1); + + if (em->stats.connected_count.s % LOGGING_BATCH == 0) + ECHO_LOG (0, "Connected S %d / %d", em->stats.connected_count.s, + em->n_clients); } + if (em->n_clients_connected == em->n_clients && em->n_clients_connected != 0) echo_notify_event (em, ECHO_EVT_LAST_SCONNECTED); @@ -320,15 +331,21 @@ quic_echo_accepted_cb (session_accepted_msg_t * mp, echo_session_t * session) ls = pool_elt_at_index (em->sessions, session->listener_index); if (ls->session_type == ECHO_SESSION_TYPE_LISTEN) { + clib_atomic_fetch_add (&em->stats.accepted_count.q, 1); echo_notify_event (em, ECHO_EVT_FIRST_QCONNECT); session->session_type = ECHO_SESSION_TYPE_QUIC; session->accepted_session_count = 0; if (eqm->cb_vft.quic_accepted_cb) eqm->cb_vft.quic_accepted_cb (mp, session->session_index); clib_atomic_fetch_add (&eqm->n_quic_clients_connected, 1); + + if (em->stats.accepted_count.q % LOGGING_BATCH == 0) + ECHO_LOG (0, "Accepted Q %d / %d", em->stats.accepted_count.q, + em->n_connects); } else { + clib_atomic_fetch_add (&em->stats.accepted_count.s, 1); session->session_type = ECHO_SESSION_TYPE_STREAM; echo_notify_event (em, ECHO_EVT_FIRST_SCONNECT); clib_atomic_fetch_add (&ls->accepted_session_count, 1); @@ -337,6 +354,10 @@ quic_echo_accepted_cb (session_accepted_msg_t * mp, echo_session_t * session) if (!em->i_am_master && eqm->cb_vft.client_stream_accepted_cb) eqm->cb_vft.client_stream_accepted_cb (mp, session->session_index); clib_atomic_fetch_add (&em->n_clients_connected, 1); + + if (em->stats.accepted_count.s % LOGGING_BATCH == 0) + ECHO_LOG (0, "Accepted S %d / %d", em->stats.accepted_count.s, + em->n_clients); } if (em->n_clients_connected == em->n_clients diff --git a/src/plugins/hs_apps/sapi/vpp_echo_proto_tcp.c b/src/plugins/hs_apps/sapi/vpp_echo_proto_tcp.c index 5b6d74b429c..0a4a0bdbc1f 100644 --- a/src/plugins/hs_apps/sapi/vpp_echo_proto_tcp.c +++ b/src/plugins/hs_apps/sapi/vpp_echo_proto_tcp.c @@ -53,7 +53,7 @@ tcp_echo_connected_cb (session_connected_bundled_msg_t * mp, return; /* Dont handle bapi connect errors for now */ } - ECHO_LOG (1, "Connected session 0x%lx -> URI", + ECHO_LOG (2, "Connected session 0x%lx -> URI", ((session_connected_msg_t *) mp)->handle); session->session_type = ECHO_SESSION_TYPE_STREAM; session->accepted_session_count = 0; -- 2.16.6