session: add cli option to dump session elog

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

src/tools/perftool/c2cpel.c

@@ -105,7 +105,7 @@ void convert_clib_file(char *clib_file)
 
         ep->event_id = find_or_add_event(brief_event_name, "%s");
 
-        track_name = format (0, "%U%c", format_elog_track, em, e, 0);
+        track_name = format (0, "%U%c", format_elog_track_name, em, e, 0);
 
         ep->track_id = find_or_add_track (track_name);
 

src/tools/perftool/elog_merge.c

@@ -121,7 +121,8 @@ elog_merge_main (unformat_input_t * input)
       vec_foreach (e, es)
       {
 	clib_warning ("%18.9f: %12U %U\n", e->time,
-		      format_elog_track, em, e, format_elog_event, em, e);
+		      format_elog_track_name, em, e, format_elog_event, em,
+		      e);
       }
     }
 

src/vnet/session/session_cli.c

@@ -204,10 +204,11 @@ static clib_error_t *
 show_session_command_fn (vlib_main_t * vm, unformat_input_t * input,
 			 vlib_cli_command_t * cmd)
 {
+  u8 *str = 0, one_session = 0, do_listeners = 0, sst, do_elog = 1;
   session_manager_main_t *smm = &session_manager_main;
-  u8 *str = 0, one_session = 0, do_listeners = 0, sst;
+  u32 transport_proto = ~0, track_index;
   stream_session_t *pool, *s;
-  u32 transport_proto = ~0;
+  transport_connection_t *tc;
   app_worker_t *app_wrk;
   int verbose = 0, i;
   const u8 *app_name;
@@ -230,6 +231,8 @@ show_session_command_fn (vlib_main_t * vm, unformat_input_t * input,
 	{
 	  one_session = 1;
 	}
+      else if (unformat (input, "elog"))
+	do_elog = 1;
       else
 	return clib_error_return (0, "unknown input `%U'",
 				  format_unformat_error, input);
@@ -237,7 +240,21 @@ show_session_command_fn (vlib_main_t * vm, unformat_input_t * input,
 
   if (one_session)
     {
-      vlib_cli_output (vm, "%U", format_stream_session, s, 3);
+      str = format (0, "%U", format_stream_session, s, 3);
+      if (do_elog)
+	{
+	  elog_main_t *em = &vm->elog_main;
+	  f64 dt;
+
+	  tc = session_get_transport (s);
+	  track_index = transport_elog_track_index (tc);
+	  dt = (em->init_time.cpu - vm->clib_time.init_cpu_time)
+	    * vm->clib_time.seconds_per_clock;
+	  if (track_index != ~0)
+	    str = format (str, " session elog:\n%U", format_elog_track, em,
+			  dt, track_index);
+	}
+      vlib_cli_output (vm, "%v", str);
       return 0;
     }
 

src/vnet/session/transport_interface.h

@@ -103,6 +103,16 @@ transport_tx_fn_type_t transport_protocol_tx_fn_type (transport_proto_t tp);
 void transport_update_time (f64 time_now, u8 thread_index);
 void transport_enable_disable (vlib_main_t * vm, u8 is_en);
 
+always_inline u32
+transport_elog_track_index (transport_connection_t * tc)
+{
+#if TRANSPORT_DEBUG
+  return tc->elog_track.track_index_plus_one - 1;
+#else
+  return ~0;
+#endif
+}
+
 void transport_connection_tx_pacer_reset (transport_connection_t * tc,
 					  u32 rate_bytes_per_sec,
 					  u32 initial_bucket, u64 time_now);

src/vnet/tcp/tcp_input.c

@@ -2819,6 +2819,7 @@ tcp46_rcv_process_inline (vlib_main_t * vm, vlib_node_runtime_t * node,
 		  tcp_send_fin (tc0);
 		  tcp_connection_timers_reset (tc0);
 		  tc0->state = TCP_STATE_LAST_ACK;
+		  TCP_EVT_DBG (TCP_EVT_STATE_CHANGE, tc0);
 		  tcp_timer_update (tc0, TCP_TIMER_WAITCLOSE, TCP_2MSL_TIME);
 		}
 	    }

src/vppinfra/elog.c

@@ -396,7 +396,7 @@ format_elog_event (u8 * s, va_list * va)
 }
 
 u8 *
-format_elog_track (u8 * s, va_list * va)
+format_elog_track_name (u8 * s, va_list * va)
 {
   elog_main_t *em = va_arg (*va, elog_main_t *);
   elog_event_t *e = va_arg (*va, elog_event_t *);
@@ -404,6 +404,29 @@ format_elog_track (u8 * s, va_list * va)
   return format (s, "%s", t->name);
 }
 
+u8 *
+format_elog_track (u8 * s, va_list * args)
+{
+  elog_main_t *em = va_arg (*args, elog_main_t *);
+  f64 dt = va_arg (*args, f64);
+  int track_index = va_arg (*args, int);
+  elog_event_t *e, *es;
+  u8 indent;
+
+  indent = format_get_indent (s) + 1;
+
+  es = elog_peek_events (em);
+  vec_foreach (e, es)
+  {
+    if (e->track != track_index)
+      continue;
+    s = format (s, "%U%18.9f: %U\n", format_white_space, indent, e->time + dt,
+		format_elog_event, em, e);
+  }
+  vec_free (es);
+  return s;
+}
+
 void
 elog_time_now (elog_time_stamp_t * et)
 {

src/vppinfra/elog.h

@@ -515,7 +515,8 @@ void elog_merge (elog_main_t * dst, u8 * dst_tag,
 
 /* 2 arguments elog_main_t and elog_event_t to format event or track name. */
 u8 *format_elog_event (u8 * s, va_list * va);
-u8 *format_elog_track (u8 * s, va_list * va);
+u8 *format_elog_track_name (u8 * s, va_list * va);
+u8 *format_elog_track (u8 * s, va_list * args);
 
 void serialize_elog_main (serialize_main_t * m, va_list * va);
 void unserialize_elog_main (serialize_main_t * m, va_list * va);

src/vppinfra/test_elog.c

@@ -244,7 +244,8 @@ test_elog_main (unformat_input_t * input)
       vec_foreach (e, es)
       {
 	clib_warning ("%18.9f: %12U %U\n", e->time,
-		      format_elog_track, em, e, format_elog_event, em, e);
+		      format_elog_track_name, em, e, format_elog_event, em,
+		      e);
       }
     }