From bb292f4d3fbecfc6b1bac695f833b0da78369116 Mon Sep 17 00:00:00 2001 From: Florin Coras Date: Fri, 19 May 2017 09:49:19 -0700 Subject: Improve session debugging Also improves builtin client code. Change-Id: I8bca1aa632028f95c373726efb0abf2ee0eff414 Signed-off-by: Florin Coras --- src/svm/svm_fifo.c | 9 +++-- src/vnet/session/session_cli.c | 47 +++++++++++++-------- src/vnet/tcp/builtin_client.c | 73 ++++++++++++++++----------------- src/vnet/tcp/builtin_client.h | 3 -- src/vnet/tcp/tcp.c | 92 +++++++++++++++++++++++++++++++++++------- src/vnet/tcp/tcp.h | 4 +- src/vnet/tcp/tcp_input.c | 25 +++++++----- src/vnet/tcp/tcp_output.c | 12 +++++- 8 files changed, 176 insertions(+), 89 deletions(-) diff --git a/src/svm/svm_fifo.c b/src/svm/svm_fifo.c index 9b09d0c20f4..f13f6feae1a 100644 --- a/src/svm/svm_fifo.c +++ b/src/svm/svm_fifo.c @@ -54,19 +54,20 @@ format_svm_fifo (u8 * s, va_list * args) s = format (s, "cursize %u nitems %u has_event %d\n", f->cursize, f->nitems, f->has_event); - s = format (s, "head %d tail %d\n", f->head, f->tail); + s = format (s, " head %d tail %d\n", f->head, f->tail); if (verbose > 1) s = format - (s, "server session %d thread %d client session %d thread %d\n", + (s, " server session %d thread %d client session %d thread %d\n", f->master_session_index, f->master_thread_index, f->client_session_index, f->client_thread_index); if (verbose) { - s = format (s, "ooo pool %d active elts\n", + s = format (s, " ooo pool %d active elts\n", pool_elts (f->ooo_segments)); - s = format (s, "%U", format_ooo_list, f); + if (svm_fifo_has_ooo_data (f)) + s = format (s, " %U", format_ooo_list, f); } return s; } diff --git a/src/vnet/session/session_cli.c b/src/vnet/session/session_cli.c index f5990c811b7..509eedbbe7b 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 d13fd446182..aaefa7ebb9a 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 756b3d18811..57d112e6572 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 36d85e46f0c..9b7b2f65c9d 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 */ @@ -697,6 +754,13 @@ tcp_session_send_space (transport_connection_t * trans_conn) return 0; } +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) { diff --git a/src/vnet/tcp/tcp.h b/src/vnet/tcp/tcp.h index 8d24a70b929..c3ebe22bde9 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 9d3f4cc39e9..35bc90943b4 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 a462d8dac3d..49fd6beffa3 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; } -- cgit 1.2.3-korg