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 <nathan.skrzypczak@gmail.com>

diff --git a/src/plugins/hs_apps/sapi/vpp_echo.c b/src/plugins/hs_apps/sapi/vpp_echo.c
index cfe1a3d..18a0280 100644 (file)
--- 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 2bba9fc..f343ad1 100644 (file)
--- 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 b91203a..a5bdeb4 100644 (file)
--- 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 7d134d9..00d54f8 100644 (file)
--- 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 d20bacb..18b70dd 100644 (file)
--- 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 5b6d74b..0a4a0bd 100644 (file)
--- 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;