api: API trace improvements
[vpp.git] / src / vppinfra / elog.c
index 182ca12..8ae752e 100644 (file)
 #include <vppinfra/format.h>
 #include <vppinfra/hash.h>
 #include <vppinfra/math.h>
+#include <vppinfra/lock.h>
 
 static inline void
 elog_lock (elog_main_t * em)
 {
   if (PREDICT_FALSE (em->lock != 0))
-    while (__sync_lock_test_and_set (em->lock, 1))
-      ;
+    while (clib_atomic_test_and_set (em->lock))
+      CLIB_PAUSE ();
 }
 
 static inline void
@@ -55,13 +56,12 @@ elog_unlock (elog_main_t * em)
 {
   if (PREDICT_FALSE (em->lock != 0))
     {
-      CLIB_MEMORY_BARRIER ();
-      *em->lock = 0;
+      clib_atomic_release (em->lock);
     }
 }
 
 /* Non-inline version. */
-void *
+__clib_export void *
 elog_event_data (elog_main_t * em,
                 elog_event_type_t * type, elog_track_t * track, u64 cpu_time)
 {
@@ -194,7 +194,7 @@ elog_event_type_register (elog_main_t * em, elog_event_type_t * t)
   return l;
 }
 
-word
+__clib_export word
 elog_track_register (elog_main_t * em, elog_track_t * t)
 {
   word l;
@@ -292,7 +292,7 @@ done:
   return s;
 }
 
-u8 *
+__clib_export u8 *
 format_elog_event (u8 * s, va_list * va)
 {
   elog_main_t *em = va_arg (*va, elog_main_t *);
@@ -302,7 +302,7 @@ format_elog_event (u8 * s, va_list * va)
   void *d = (u8 *) e->data;
   char arg_format[64];
 
-  t = vec_elt_at_index (em->event_types, e->type);
+  t = vec_elt_at_index (em->event_types, e->event_type);
 
   f = t->format;
   a = t->format_args;
@@ -395,8 +395,8 @@ format_elog_event (u8 * s, va_list * va)
   return s;
 }
 
-u8 *
-format_elog_track (u8 * s, va_list * va)
+__clib_export u8 *
+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,38 @@ format_elog_track (u8 * s, va_list * va)
   return format (s, "%s", t->name);
 }
 
+__clib_export 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;
+}
+
+__clib_export char *
+format_one_elog_event (void *em_arg, void *ep_arg)
+{
+  elog_main_t *em = (elog_main_t *) em_arg;
+  elog_event_t *ep = (elog_event_t *) ep_arg;
+
+  return (char *) format (0, "%U", format_elog_event, em, ep);
+}
+
 void
 elog_time_now (elog_time_stamp_t * et)
 {
@@ -413,7 +445,11 @@ elog_time_now (elog_time_stamp_t * et)
 #ifdef CLIB_UNIX
   {
 #include <sys/syscall.h>
+#ifdef __APPLE__
+    clock_gettime (CLOCK_REALTIME, &ts);
+#else
     syscall (SYS_clock_gettime, CLOCK_REALTIME, &ts);
+#endif
     cpu_time_now = clib_cpu_time_now ();
     /* Subtract 3/30/2017's worth of seconds to retain precision */
     os_time_now_nsec = 1e9 * (ts.tv_sec - 1490885108) + ts.tv_nsec;
@@ -448,24 +484,35 @@ elog_nsec_per_clock (elog_main_t * em)
                                            &em->init_time));
 }
 
-void
-elog_alloc (elog_main_t * em, u32 n_events)
+static void
+elog_alloc_internal (elog_main_t * em, u32 n_events, int free_ring)
 {
-  if (em->event_ring)
+  if (free_ring && em->event_ring)
     vec_free (em->event_ring);
 
   /* Ring size must be a power of 2. */
   em->event_ring_size = n_events = max_pow2 (n_events);
 
-  /* Leave an empty ievent at end so we can always speculatively write
-     and event there (possibly a long form event). */
-  vec_resize_aligned (em->event_ring, n_events, CLIB_CACHE_LINE_BYTES);
+  vec_validate_aligned (em->event_ring, n_events, CLIB_CACHE_LINE_BYTES);
+  _vec_len (em->event_ring) = n_events;
 }
 
-void
+__clib_export void
+elog_alloc (elog_main_t * em, u32 n_events)
+{
+  elog_alloc_internal (em, n_events, 1 /* free ring */ );
+}
+
+__clib_export void
+elog_resize (elog_main_t * em, u32 n_events)
+{
+  elog_alloc_internal (em, n_events, 0 /* do not free ring */ );
+}
+
+__clib_export void
 elog_init (elog_main_t * em, u32 n_events)
 {
-  memset (em, 0, sizeof (em[0]));
+  clib_memset (em, 0, sizeof (em[0]));
 
   em->lock = 0;
 
@@ -481,6 +528,7 @@ elog_init (elog_main_t * em, u32 n_events)
   elog_track_register (em, &em->default_track);
 
   elog_time_now (&em->init_time);
+  em->string_table_hash = hash_create_string (0, sizeof (uword));
 }
 
 /* Returns number of events in ring and start index. */
@@ -505,7 +553,7 @@ elog_event_range (elog_main_t * em, uword * lo)
     }
 }
 
-elog_event_t *
+__clib_export elog_event_t *
 elog_peek_events (elog_main_t * em)
 {
   elog_event_t *e, *f, *es = 0;
@@ -530,29 +578,55 @@ elog_peek_events (elog_main_t * em)
 }
 
 /* Add a formatted string to the string table. */
-u32
+__clib_export u32
 elog_string (elog_main_t * em, char *fmt, ...)
 {
   u32 offset;
+  uword *p;
+  uword len;
   va_list va;
 
+  elog_lock (em);
+  vec_reset_length (em->string_table_tmp);
   va_start (va, fmt);
-  offset = vec_len (em->string_table);
-  em->string_table = (char *) va_format ((u8 *) em->string_table, fmt, &va);
+  em->string_table_tmp = va_format (em->string_table_tmp, fmt, &va);
   va_end (va);
 
-  /* Null terminate string if it is not already. */
-  if (vec_end (em->string_table)[-1] != 0)
-    vec_add1 (em->string_table, 0);
+  /* String table entries MUST be NULL terminated */
+  len = vec_len (em->string_table_tmp);
+  ASSERT (len > 0);
+  if (em->string_table_tmp[len - 1] != 0)
+    vec_add1 (em->string_table_tmp, 0);
+
+  /* See if we already have this string in the string table */
+  p = hash_get_mem (em->string_table_hash, em->string_table_tmp);
+
+  /* We already have the string, so give the caller its offset */
+  if (p)
+    {
+      elog_unlock (em);
+      return (p[0]);
+    }
+
+  /* We don't, so add it. */
+
+  offset = vec_len (em->string_table);
+  vec_append (em->string_table, em->string_table_tmp);
+
+  hash_set_mem (em->string_table_hash, em->string_table_tmp, offset);
+
+  /* We gave the key to the string table hash, so we can't reuse it! */
+  em->string_table_tmp = 0;
+  elog_unlock (em);
 
   return offset;
 }
 
-elog_event_t *
+__clib_export elog_event_t *
 elog_get_events (elog_main_t * em)
 {
-  if (!em->events)
-    em->events = elog_peek_events (em);
+  vec_free (em->events);
+  em->events = elog_peek_events (em);
   return em->events;
 }
 
@@ -621,8 +695,8 @@ elog_cmp (void *a1, void *a2)
 /*
  * merge two event logs. Complicated and cranky.
  */
-void
-elog_merge (elog_main_t * dst, u8 * dst_tag, elog_main_t * src, u8 * src_tag,
+__clib_export void
+elog_merge (elog_main_t *dst, u8 *dst_tag, elog_main_t *src, u8 *src_tag,
            f64 align_tweak)
 {
   elog_event_t *e;
@@ -632,7 +706,7 @@ elog_merge (elog_main_t * dst, u8 * dst_tag, elog_main_t * src, u8 * src_tag,
   elog_track_t newt;
   int i;
 
-  memset (&newt, 0, sizeof (newt));
+  clib_memset (&newt, 0, sizeof (newt));
 
   /* Acquire src and dst events */
   elog_get_events (src);
@@ -678,10 +752,11 @@ elog_merge (elog_main_t * dst, u8 * dst_tag, elog_main_t * src, u8 * src_tag,
   /* Across all (copied) src events... */
   for (e = dst->events + l; e < vec_end (dst->events); e++)
     {
-      elog_event_type_t *t = vec_elt_at_index (src->event_types, e->type);
+      elog_event_type_t *t =
+       vec_elt_at_index (src->event_types, e->event_type);
 
       /* Remap type from src -> dst. */
-      e->type = find_or_create_type (dst, t);
+      e->event_type = find_or_create_type (dst, t);
 
       /* Remap string table offsets for 'T' format args */
       maybe_fix_string_table_offset (e, t,
@@ -732,7 +807,7 @@ elog_merge (elog_main_t * dst, u8 * dst_tag, elog_main_t * src, u8 * src_tag,
 
     /*
      * Move the earlier set of events later, to avoid creating
-     * events which preceed the Big Bang (aka have negative timestamps).
+     * events which precede the Big Bang (aka have negative timestamps).
      *
      * Not to any scale, we have something like the following picture:
      *
@@ -793,11 +868,11 @@ serialize_elog_event (serialize_main_t * m, va_list * va)
 {
   elog_main_t *em = va_arg (*va, elog_main_t *);
   elog_event_t *e = va_arg (*va, elog_event_t *);
-  elog_event_type_t *t = vec_elt_at_index (em->event_types, e->type);
+  elog_event_type_t *t = vec_elt_at_index (em->event_types, e->event_type);
   u8 *d = e->data;
   u8 *p = (u8 *) t->format_args;
 
-  serialize_integer (m, e->type, sizeof (e->type));
+  serialize_integer (m, e->event_type, sizeof (e->event_type));
   serialize_integer (m, e->track, sizeof (e->track));
   serialize (m, serialize_f64, e->time);
 
@@ -860,18 +935,18 @@ unserialize_elog_event (serialize_main_t * m, va_list * va)
   {
     u16 tmp[2];
 
-    unserialize_integer (m, &tmp[0], sizeof (e->type));
+    unserialize_integer (m, &tmp[0], sizeof (e->event_type));
     unserialize_integer (m, &tmp[1], sizeof (e->track));
 
-    e->type = tmp[0];
+    e->event_type = tmp[0];
     e->track = tmp[1];
 
     /* Make sure it fits. */
-    ASSERT (e->type == tmp[0]);
+    ASSERT (e->event_type == tmp[0]);
     ASSERT (e->track == tmp[1]);
   }
 
-  t = vec_elt_at_index (em->event_types, e->type);
+  t = vec_elt_at_index (em->event_types, e->event_type);
 
   unserialize (m, unserialize_f64, &e->time);
 
@@ -1034,7 +1109,7 @@ unserialize_elog_time_stamp (serialize_main_t * m, va_list * va)
 
 static char *elog_serialize_magic = "elog v0";
 
-void
+__clib_export void
 serialize_elog_main (serialize_main_t * m, va_list * va)
 {
   elog_main_t *em = va_arg (*va, elog_main_t *);
@@ -1068,8 +1143,8 @@ serialize_elog_main (serialize_main_t * m, va_list * va)
   vec_foreach (e, em->events) serialize (m, serialize_elog_event, em, e);
 }
 
-void
-unserialize_elog_main (serialize_main_t * m, va_list * va)
+__clib_export void
+unserialize_elog_main (serialize_main_t *m, va_list *va)
 {
   elog_main_t *em = va_arg (*va, elog_main_t *);
   uword i;
@@ -1104,6 +1179,39 @@ unserialize_elog_main (serialize_main_t * m, va_list * va)
   }
 }
 
+#ifdef CLIB_UNIX
+clib_error_t *
+elog_write_file_not_inline (elog_main_t * em, char *clib_file, int flush_ring)
+{
+  serialize_main_t m;
+  clib_error_t *error;
+
+  error = serialize_open_clib_file (&m, clib_file);
+  if (error)
+    return error;
+  error = serialize (&m, serialize_elog_main, em, flush_ring);
+  if (!error)
+    serialize_close (&m);
+  return error;
+}
+
+__clib_export clib_error_t *
+elog_read_file_not_inline (elog_main_t * em, char *clib_file)
+{
+  serialize_main_t m;
+  clib_error_t *error;
+
+  error = unserialize_open_clib_file (&m, clib_file);
+  if (error)
+    return error;
+  error = unserialize (&m, unserialize_elog_main, em);
+  if (!error)
+    unserialize_close (&m);
+  return error;
+}
+#endif /* CLIB_UNIX */
+
+
 /*
  * fd.io coding-style-patch-verification: ON
  *