Improve session debugging

Also improves builtin client code.

Change-Id: I8bca1aa632028f95c373726efb0abf2ee0eff414
Signed-off-by: Florin Coras <fcoras@cisco.com>

7 files changed, 171 insertions, 85 deletions

diff --git a/src/vnet/session/session_cli.c b/src/vnet/session/session_cli.c
index f5990c81..509eedbb 100755
--- a/src/vnet/session/session_cli.c
+++ b/src/vnet/session/session_cli.c
@@ -30,33 +30,35 @@ format_stream_session (u8 * s, va_list * args)
   int verbose = va_arg (*args, int);
   transport_proto_vft_t *tp_vft;
   u8 *str = 0;
-
   tp_vft = session_get_transport_vft (ss->session_type);
 
-  if (verbose)
-    str = format (0, "%-20llp%-20llp%-15lld", ss->server_rx_fifo,
-		  ss->server_tx_fifo, stream_session_get_index (ss));
+  if (verbose == 1)
+    str = format (0, "%-10u%-10u%-10lld",
+		  svm_fifo_max_dequeue (ss->server_rx_fifo),
+		  svm_fifo_max_enqueue (ss->server_tx_fifo),
+		  stream_session_get_index (ss));
 
   if (ss->session_state == SESSION_STATE_READY)
     {
-      s = format (s, "%-40U%v", tp_vft->format_connection,
-		  ss->connection_index, ss->thread_index, str);
+      s = format (s, "%U", tp_vft->format_connection, ss->connection_index,
+		  ss->thread_index, verbose);
+      if (verbose == 1)
+	s = format (s, "%v", str);
     }
   else if (ss->session_state == SESSION_STATE_LISTENING)
     {
       s = format (s, "%-40U%v", tp_vft->format_listener, ss->connection_index,
 		  str);
     }
-  else if (ss->session_state == SESSION_STATE_READY)
+  else if (ss->session_state == SESSION_STATE_CONNECTING)
     {
-      s =
-	format (s, "%-40U%v", tp_vft->format_half_open, ss->connection_index,
-		str);
+      s = format (s, "%-40U%v", tp_vft->format_half_open,
+		  ss->connection_index, str);
     }
   else if (ss->session_state == SESSION_STATE_CLOSED)
     {
       s = format (s, "[CL] %-40U%v", tp_vft->format_connection,
-		  ss->connection_index, ss->thread_index, str);
+		  ss->connection_index, ss->thread_index, verbose, str);
     }
   else
     {
@@ -85,7 +87,9 @@ show_session_command_fn (vlib_main_t * vm, unformat_input_t * input,
 
   while (unformat_check_input (input) != UNFORMAT_END_OF_INPUT)
     {
-      if (unformat (input, "verbose"))
+      if (unformat (input, "verbose %d", &verbose))
+	;
+      else if (unformat (input, "verbose"))
 	verbose = 1;
       else
 	break;
@@ -105,11 +109,11 @@ show_session_command_fn (vlib_main_t * vm, unformat_input_t * input,
 			   i, pool_elts (pool));
 	  if (verbose)
 	    {
-	      if (once_per_pool)
+	      if (once_per_pool && verbose == 1)
 		{
-		  str = format (str, "%-50s%-20s%-20s%-15s",
-				"Connection", "Rx fifo", "Tx fifo",
-				"Session Index");
+		  str =
+		    format (str, "%-50s%-15s%-10s%-10s%-10s", "Connection",
+			    "State", "Rx-f", "Tx-f", "S-idx");
 		  vlib_cli_output (vm, "%v", str);
 		  vec_reset_length (str);
 		  once_per_pool = 0;
@@ -118,7 +122,16 @@ show_session_command_fn (vlib_main_t * vm, unformat_input_t * input,
               /* *INDENT-OFF* */
               pool_foreach (s, pool,
               ({
-                vlib_cli_output (vm, "%U", format_stream_session, s, verbose);
+        	vec_reset_length (str);
+                str = format (str, "%U", format_stream_session, s, verbose);
+                if (verbose > 1)
+                  {
+                    str = format (str, " Rx fifo: %U", format_svm_fifo,
+				  s->server_rx_fifo, 1);
+                    str = format (str, " Tx fifo: %U", format_svm_fifo,
+				  s->server_tx_fifo, 1);
+                  }
+                vlib_cli_output (vm, "%v", str);
               }));
               /* *INDENT-ON* */
 	    }
diff --git a/src/vnet/tcp/builtin_client.c b/src/vnet/tcp/builtin_client.c
index d13fd446..aaefa7eb 100644
--- a/src/vnet/tcp/builtin_client.c
+++ b/src/vnet/tcp/builtin_client.c
@@ -187,6 +187,9 @@ tclient_thread_fn (void *arg)
 
   clib_per_cpu_mheaps[vlib_get_thread_index ()] = clib_per_cpu_mheaps[0];
 
+  vec_validate (session_indices, 0);
+  vec_reset_length (session_indices);
+
   while (1)
     {
       /* Wait until we're told to get busy */
@@ -201,14 +204,12 @@ tclient_thread_fn (void *arg)
       tm->run_test = 0;
       rx_total = 0;
 
-      clib_warning ("Run %d iterations", tm->n_iterations);
+      clib_warning ("Start test...");
 
       before = clib_time_now (&ttime);
 
-      for (i = 0; i < tm->n_iterations; i++)
+      do
 	{
-	  session_t *sp;
-
 	  do
 	    {
 	      try_tx = try_rx = 0;
@@ -229,24 +230,38 @@ tclient_thread_fn (void *arg)
                     receive_test_chunk (tm, sp);
                     try_rx = 1;
                   }
+                else
+                  {
+                    /* Session is complete */
+                    vec_add1 (session_indices, sp - tm->sessions);
+                  }
               }));
+              /* Terminate any completed sessions */
+              if (PREDICT_FALSE (_vec_len(session_indices) != 0))
+                {
+                  for (i = 0; i < _vec_len (session_indices); i++)
+                    {
+                      sp = pool_elt_at_index (tm->sessions, session_indices[i]);
+                      rx_total += sp->bytes_received;
+                      dmp = vl_msg_api_alloc_as_if_client (sizeof (*dmp));
+                      memset (dmp, 0, sizeof (*dmp));
+                      dmp->_vl_msg_id = ntohs (VL_API_DISCONNECT_SESSION);
+                      dmp->client_index = tm->my_client_index;
+                      dmp->handle = sp->vpp_session_handle;
+                      vl_msg_api_send_shmem (tm->vl_input_queue, (u8 *) & dmp);
+                      pool_put (tm->sessions, sp);
+                    }
+                  _vec_len(session_indices) = 0;
+                }
 	      /* *INDENT-ON* */
 	    }
 	  while (try_tx || try_rx);
-
-          /* *INDENT-OFF* */
-          pool_foreach (sp, tm->sessions,
-          ({
-            rx_total += sp->bytes_received;
-            sp->bytes_received = 0;
-            sp->bytes_to_send = tm->bytes_to_send;
-          }));
-          /* *INDENT-ON* */
 	}
+      while (0);
       after = clib_time_now (&ttime);
 
-      clib_warning ("Done %d iterations, %lld bytes in %.2f secs",
-		    tm->n_iterations, rx_total, (after - before));
+      clib_warning ("Test complete %lld bytes in %.2f secs",
+		    rx_total, (after - before));
       if ((after - before) != 0.0)
 	{
 	  clib_warning ("%.2f bytes/second full-duplex",
@@ -255,28 +270,11 @@ tclient_thread_fn (void *arg)
 			(((f64) rx_total * 8.0) / (after - before)) / 1e9);
 	}
 
-      /* Disconnect sessions... */
-      vec_reset_length (session_indices);
-
-      /* *INDENT-OFF* */
-      pool_foreach (sp, tm->sessions,
-      ({
-	vec_add1 (session_indices, sp - tm->sessions);
-      }));
-      /* *INDENT-ON* */
-
-      for (i = 0; i < vec_len (session_indices); i++)
-	{
-	  sp = pool_elt_at_index (tm->sessions, session_indices[i]);
-	  dmp = vl_msg_api_alloc_as_if_client (sizeof (*dmp));
-	  memset (dmp, 0, sizeof (*dmp));
-	  dmp->_vl_msg_id = ntohs (VL_API_DISCONNECT_SESSION);
-	  dmp->client_index = tm->my_client_index;
-	  dmp->handle = sp->vpp_session_handle;
-	  vl_msg_api_send_shmem (tm->vl_input_queue, (u8 *) & dmp);
-	  pool_put (tm->sessions, sp);
-	}
+      if (pool_elts (tm->sessions))
+	clib_warning ("BUG: %d active sessions remain...",
+		      pool_elts (tm->sessions));
     }
+  while (0);
   /* NOTREACHED */
 #if TCP_BUILTIN_CLIENT_PTHREAD
   return 0;
@@ -511,15 +509,12 @@ test_tcp_clients_command_fn (vlib_main_t * vm,
   u64 tmp;
 
   tm->bytes_to_send = 8192;
-  tm->n_iterations = 1;
   vec_free (tm->connect_uri);
 
   while (unformat_check_input (input) != UNFORMAT_END_OF_INPUT)
     {
       if (unformat (input, "nclients %d", &n_clients))
 	;
-      else if (unformat (input, "iterations %d", &tm->n_iterations))
-	;
       else if (unformat (input, "mbytes %lld", &tmp))
 	tm->bytes_to_send = tmp << 20;
       else if (unformat (input, "gbytes %lld", &tmp))
diff --git a/src/vnet/tcp/builtin_client.h b/src/vnet/tcp/builtin_client.h
index 756b3d18..57d112e6 100644
--- a/src/vnet/tcp/builtin_client.h
+++ b/src/vnet/tcp/builtin_client.h
@@ -93,9 +93,6 @@ typedef struct
   /* Signal variables */
   volatile int run_test;
 
-  /* Number of iterations */
-  int n_iterations;
-
   /* Bytes to send */
   u64 bytes_to_send;
 
diff --git a/src/vnet/tcp/tcp.c b/src/vnet/tcp/tcp.c
index 36d85e46..9b7b2f65 100644
--- a/src/vnet/tcp/tcp.c
+++ b/src/vnet/tcp/tcp.c
@@ -461,13 +461,12 @@ const char *tcp_fsm_states[] = {
 u8 *
 format_tcp_state (u8 * s, va_list * args)
 {
-  tcp_state_t *state = va_arg (*args, tcp_state_t *);
+  u32 state = va_arg (*args, u32);
 
-  if (*state < TCP_N_STATES)
-    s = format (s, "%s", tcp_fsm_states[*state]);
+  if (state < TCP_N_STATES)
+    s = format (s, "%s", tcp_fsm_states[state]);
   else
-    s = format (s, "UNKNOWN (%d (0x%x))", *state, *state);
-
+    s = format (s, "UNKNOWN (%d (0x%x))", state, state);
   return s;
 }
 
@@ -503,7 +502,51 @@ format_tcp_timers (u8 * s, va_list * args)
 }
 
 u8 *
-format_tcp_connection (u8 * s, va_list * args)
+format_tcp_congestion_status (u8 * s, va_list * args)
+{
+  tcp_connection_t *tc = va_arg (*args, tcp_connection_t *);
+  if (tcp_in_recovery (tc))
+    s = format (s, "recovery");
+  else if (tcp_in_fastrecovery (tc))
+    s = format (s, "fastrecovery");
+  else
+    s = format (s, "none");
+  return s;
+}
+
+u8 *
+format_tcp_vars (u8 * s, va_list * args)
+{
+  tcp_connection_t *tc = va_arg (*args, tcp_connection_t *);
+  s = format (s, " snd_una %u snd_nxt %u snd_una_max %u\n",
+	      tc->snd_una - tc->iss, tc->snd_nxt - tc->iss,
+	      tc->snd_una_max - tc->iss);
+  s = format (s, " rcv_nxt %u rcv_las %u\n",
+	      tc->rcv_nxt - tc->irs, tc->rcv_las - tc->irs);
+  s = format (s, " snd_wnd %u rcv_wnd %u snd_wl1 %u snd_wl2 %u\n",
+	      tc->snd_wnd, tc->rcv_wnd, tc->snd_wl1 - tc->irs,
+	      tc->snd_wl2 - tc->iss);
+  s = format (s, " flight size %u send space %u rcv_wnd available %d\n",
+	      tcp_flight_size (tc), tcp_snd_space (tc),
+	      tc->rcv_wnd - (tc->rcv_nxt - tc->rcv_las));
+  s = format (s, " cong %U ", format_tcp_congestion_status, tc);
+  s = format (s, "cwnd %u ssthresh %u rtx_bytes %u bytes_acked %u\n",
+	      tc->cwnd, tc->ssthresh, tc->rtx_bytes, tc->bytes_acked);
+  s = format (s, " prev_ssthresh %u snd_congestion %u\n", tc->prev_ssthresh,
+	      tc->snd_congestion - tc->iss);
+  s = format (s, " rto %u rto_boff %u srtt %u rttvar %u rtt_ts %u ", tc->rto,
+	      tc->rto_boff, tc->srtt, tc->rttvar, tc->rtt_ts);
+  s = format (s, "rtt_seq %u\n", tc->rtt_seq);
+  if (scoreboard_first_hole (&tc->sack_sb))
+    s = format (s, " scoreboard: %U\n", format_tcp_scoreboard, &tc->sack_sb);
+  if (vec_len (tc->snd_sacks))
+    s = format (s, " sacks tx: %U\n", format_tcp_sacks, tc);
+
+  return s;
+}
+
+u8 *
+format_tcp_connection_id (u8 * s, va_list * args)
 {
   tcp_connection_t *tc = va_arg (*args, tcp_connection_t *);
   if (!tc)
@@ -527,11 +570,18 @@ format_tcp_connection (u8 * s, va_list * args)
 }
 
 u8 *
-format_tcp_connection_verbose (u8 * s, va_list * args)
+format_tcp_connection (u8 * s, va_list * args)
 {
   tcp_connection_t *tc = va_arg (*args, tcp_connection_t *);
-  s = format (s, "%U %U %U", format_tcp_connection, tc, format_tcp_state,
-	      &tc->state, format_tcp_timers, tc);
+  u32 verbose = va_arg (*args, u32);
+
+  s = format (s, "%-50U", format_tcp_connection_id, tc);
+  if (verbose)
+    {
+      s = format (s, "%-15U", format_tcp_state, tc->state);
+      if (verbose > 1)
+	s = format (s, " %U\n%U", format_tcp_timers, tc, format_tcp_vars, tc);
+    }
   return s;
 }
 
@@ -540,11 +590,12 @@ format_tcp_session (u8 * s, va_list * args)
 {
   u32 tci = va_arg (*args, u32);
   u32 thread_index = va_arg (*args, u32);
+  u32 verbose = va_arg (*args, u32);
   tcp_connection_t *tc;
 
   tc = tcp_connection_get (tci, thread_index);
   if (tc)
-    return format (s, "%U", format_tcp_connection, tc);
+    return format (s, "%U", format_tcp_connection, tc, verbose);
   else
     return format (s, "empty");
 }
@@ -554,7 +605,7 @@ format_tcp_listener_session (u8 * s, va_list * args)
 {
   u32 tci = va_arg (*args, u32);
   tcp_connection_t *tc = tcp_listener_get (tci);
-  return format (s, "%U", format_tcp_connection, tc);
+  return format (s, "%U", format_tcp_connection_id, tc);
 }
 
 u8 *
@@ -562,7 +613,7 @@ format_tcp_half_open_session (u8 * s, va_list * args)
 {
   u32 tci = va_arg (*args, u32);
   tcp_connection_t *tc = tcp_half_open_connection_get (tci);
-  return format (s, "%U", format_tcp_connection, tc);
+  return format (s, "%U", format_tcp_connection_id, tc);
 }
 
 u8 *
@@ -659,12 +710,18 @@ tcp_round_snd_space (tcp_connection_t * tc, u32 snd_space)
 
 /**
  * Compute tx window session is allowed to fill.
+ *
+ * Takes into account available send space, snd_mss and the congestion
+ * state of the connection. If possible, the value returned is a multiple
+ * of snd_mss.
+ *
+ * @param tc tcp connection
+ * @return number of bytes session is allowed to write
  */
 u32
-tcp_session_send_space (transport_connection_t * trans_conn)
+tcp_snd_space (tcp_connection_t * tc)
 {
   int snd_space;
-  tcp_connection_t *tc = (tcp_connection_t *) trans_conn;
 
   /* If we haven't gotten dupacks or if we did and have gotten sacked bytes
    * then we can still send */
@@ -698,6 +755,13 @@ tcp_session_send_space (transport_connection_t * trans_conn)
 }
 
 u32
+tcp_session_send_space (transport_connection_t * trans_conn)
+{
+  tcp_connection_t *tc = (tcp_connection_t *) trans_conn;
+  return tcp_snd_space (tc);
+}
+
+u32
 tcp_session_tx_fifo_offset (transport_connection_t * trans_conn)
 {
   tcp_connection_t *tc = (tcp_connection_t *) trans_conn;
diff --git a/src/vnet/tcp/tcp.h b/src/vnet/tcp/tcp.h
index 8d24a70b..c3ebe22b 100644
--- a/src/vnet/tcp/tcp.h
+++ b/src/vnet/tcp/tcp.h
@@ -387,8 +387,8 @@ void tcp_connection_cleanup (tcp_connection_t * tc);
 void tcp_connection_del (tcp_connection_t * tc);
 void tcp_connection_reset (tcp_connection_t * tc);
 
+u8 *format_tcp_connection_id (u8 * s, va_list * args);
 u8 *format_tcp_connection (u8 * s, va_list * args);
-u8 *format_tcp_connection_verbose (u8 * s, va_list * args);
 u8 *format_tcp_scoreboard (u8 * s, va_list * args);
 
 always_inline tcp_connection_t *
@@ -481,6 +481,8 @@ tcp_available_snd_space (const tcp_connection_t * tc)
   return available_wnd - flight_size;
 }
 
+u32 tcp_rcv_wnd_available (tcp_connection_t * tc);
+u32 tcp_snd_space (tcp_connection_t * tc);
 void tcp_update_rcv_wnd (tcp_connection_t * tc);
 
 void tcp_retransmit_first_unacked (tcp_connection_t * tc);
diff --git a/src/vnet/tcp/tcp_input.c b/src/vnet/tcp/tcp_input.c
index 9d3f4cc3..35bc9094 100644
--- a/src/vnet/tcp/tcp_input.c
+++ b/src/vnet/tcp/tcp_input.c
@@ -722,9 +722,11 @@ tcp_update_snd_wnd (tcp_connection_t * tc, u32 seq, u32 ack, u32 snd_wnd)
       TCP_EVT_DBG (TCP_EVT_SND_WND, tc);
 
       /* Set probe timer if we just got 0 wnd */
-      if (tc->snd_wnd < tc->snd_mss
-	  && !tcp_timer_is_active (tc, TCP_TIMER_PERSIST))
-	tcp_persist_timer_set (tc);
+      if (tc->snd_wnd < tc->snd_mss)
+	{
+	  if (!tcp_timer_is_active (tc, TCP_TIMER_PERSIST))
+	    tcp_persist_timer_set (tc);
+	}
       else
 	tcp_persist_timer_reset (tc);
     }
@@ -763,6 +765,7 @@ static void
 tcp_cc_rcv_ack (tcp_connection_t * tc, vlib_buffer_t * b)
 {
   u8 partial_ack;
+  u32 bytes_advanced;
 
   if (tcp_in_fastrecovery (tc))
     {
@@ -804,10 +807,14 @@ tcp_cc_rcv_ack (tcp_connection_t * tc, vlib_buffer_t * b)
       tc->rcv_dupacks = 0;
       if (tcp_in_recovery (tc))
 	{
-	  tc->rtx_bytes -= clib_min (tc->bytes_acked, tc->rtx_bytes);
+	  bytes_advanced = tc->bytes_acked + tc->sack_sb.snd_una_adv;
+	  tc->rtx_bytes -= clib_min (bytes_advanced, tc->rtx_bytes);
 	  tc->rto = clib_min (tc->srtt + (tc->rttvar << 2), TCP_RTO_MAX);
 	  if (seq_geq (tc->snd_una, tc->snd_congestion))
-	    tcp_recovery_off (tc);
+	    {
+	      tc->rtx_bytes = 0;
+	      tcp_recovery_off (tc);
+	    }
 	}
     }
 }
@@ -1221,7 +1228,7 @@ format_tcp_rx_trace (u8 * s, va_list * args)
   s = format (s, "%U\n%U%U",
 	      format_tcp_header, &t->tcp_header, 128,
 	      format_white_space, indent,
-	      format_tcp_connection_verbose, &t->tcp_connection);
+	      format_tcp_connection, &t->tcp_connection, 1);
 
   return s;
 }
@@ -1236,7 +1243,7 @@ format_tcp_rx_trace_short (u8 * s, va_list * args)
   s = format (s, "%d -> %d (%U)",
 	      clib_net_to_host_u16 (t->tcp_header.src_port),
 	      clib_net_to_host_u16 (t->tcp_header.dst_port), format_tcp_state,
-	      &t->tcp_connection.state);
+	      t->tcp_connection.state);
 
   return s;
 }
@@ -2165,6 +2172,7 @@ tcp46_listen_inline (vlib_main_t * vm, vlib_node_runtime_t * node,
 	  child0->c_rmt_port = th0->src_port;
 	  child0->c_is_ip4 = is_ip4;
 	  child0->c_thread_index = my_thread_index;
+	  child0->state = TCP_STATE_SYN_RCVD;
 
 	  if (is_ip4)
 	    {
@@ -2194,7 +2202,6 @@ tcp46_listen_inline (vlib_main_t * vm, vlib_node_runtime_t * node,
 	  child0->irs = vnet_buffer (b0)->tcp.seq_number;
 	  child0->rcv_nxt = vnet_buffer (b0)->tcp.seq_number + 1;
 	  child0->rcv_las = child0->rcv_nxt;
-	  child0->state = TCP_STATE_SYN_RCVD;
 
 	  /* RFC1323: TSval timestamps sent on {SYN} and {SYN,ACK}
 	   * segments are used to initialize PAWS. */
@@ -2450,7 +2457,7 @@ tcp46_input_inline (vlib_main_t * vm, vlib_node_runtime_t * node,
 
 		  if (error0 == TCP_ERROR_DISPATCH)
 		    clib_warning ("disp error state %U flags %U",
-				  format_tcp_state, &state0, format_tcp_flags,
+				  format_tcp_state, state0, format_tcp_flags,
 				  (int) flags0);
 		}
 	    }
diff --git a/src/vnet/tcp/tcp_output.c b/src/vnet/tcp/tcp_output.c
index a462d8da..49fd6bef 100644
--- a/src/vnet/tcp/tcp_output.c
+++ b/src/vnet/tcp/tcp_output.c
@@ -59,7 +59,7 @@ format_tcp_tx_trace (u8 * s, va_list * args)
   s = format (s, "%U\n%U%U",
 	      format_tcp_header, &t->tcp_header, 128,
 	      format_white_space, indent,
-	      format_tcp_connection_verbose, &t->tcp_connection);
+	      format_tcp_connection, &t->tcp_connection, 1);
 
   return s;
 }
@@ -1024,6 +1024,11 @@ tcp_prepare_retransmit_segment (tcp_connection_t * tc, vlib_buffer_t * b,
   ASSERT (n_bytes != 0);
   b->current_length = n_bytes;
   tcp_push_hdr_i (tc, b, tc->state, 0);
+
+  /* Don't count multiple retransmits of the same segment */
+  if (tc->rto_boff > 1)
+    goto done;
+
   tc->rtx_bytes += n_bytes;
 
 done:
@@ -1103,7 +1108,9 @@ tcp_timer_retransmit_handler_i (u32 index, u8 is_syn)
 
       if (n_bytes == 0)
 	{
-	  clib_warning ("could not retransmit");
+	  clib_warning ("could not retransmit anything");
+	  /* Try again eventually */
+	  tcp_retransmit_timer_set (tc);
 	  return;
 	}
     }
@@ -1203,6 +1210,7 @@ tcp_timer_persist_handler (u32 index)
   /* Nothing to send */
   if (n_bytes == 0)
     {
+      clib_warning ("persist found nothing to send");
       tcp_return_buffer (tm);
       return;
     }