X-Git-Url: https://gerrit.fd.io/r/gitweb?a=blobdiff_plain;f=src%2Fvppinfra%2Felog.c;h=caddf6f37571369bd38b811ccc1fdfa5540ff6bb;hb=88cecfad98d2e8b32e68b90538c2c4cb906eb204;hp=e9f06d0948cac97df5360565f1dbfeef14339d96;hpb=7cd468a3d7dee7d6c92f69a0bb7061ae208ec727;p=vpp.git

diff --git a/src/vppinfra/elog.c b/src/vppinfra/elog.c
index e9f06d0948c..caddf6f3757 100644
--- a/src/vppinfra/elog.c
+++ b/src/vppinfra/elog.c
@@ -41,13 +41,14 @@
 #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,8 +56,7 @@ elog_unlock (elog_main_t * em)
 {
   if (PREDICT_FALSE (em->lock != 0))
     {
-      CLIB_MEMORY_BARRIER ();
-      *em->lock = 0;
+      clib_atomic_release (em->lock);
     }
 }
 
@@ -77,6 +77,7 @@ new_event_type (elog_main_t * em, uword i)
     em->event_type_by_format =
       hash_create_vec ( /* size */ 0, sizeof (u8), sizeof (uword));
 
+  t->type_index_plus_one = i + 1;
   hash_set_mem (em->event_type_by_format, t->format, i);
 }
 
@@ -107,6 +108,13 @@ elog_event_type_register (elog_main_t * em, elog_event_type_t * t)
 
   elog_lock (em);
 
+  /* Multiple simultaneous registration attempts, */
+  if (t->type_index_plus_one > 0)
+    {
+      elog_unlock (em);
+      return t->type_index_plus_one - 1;
+    }
+
   l = vec_len (em->event_types);
 
   t->type_index_plus_one = 1 + l;
@@ -388,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 *);
@@ -396,18 +404,46 @@ 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)
 {
   u64 cpu_time_now, os_time_now_nsec;
+  struct timespec ts;
 
 #ifdef CLIB_UNIX
   {
 #include <sys/syscall.h>
-    struct timespec ts;
+#ifdef __APPLE__
+    clock_gettime (CLOCK_REALTIME, &ts);
+#else
     syscall (SYS_clock_gettime, CLOCK_REALTIME, &ts);
+#endif
     cpu_time_now = clib_cpu_time_now ();
-    os_time_now_nsec = 1e9 * ts.tv_sec + ts.tv_nsec;
+    /* Subtract 3/30/2017's worth of seconds to retain precision */
+    os_time_now_nsec = 1e9 * (ts.tv_sec - 1490885108) + ts.tv_nsec;
   }
 #else
   cpu_time_now = clib_cpu_time_now ();
@@ -456,7 +492,7 @@ elog_alloc (elog_main_t * em, u32 n_events)
 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;
 
@@ -472,6 +508,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. */
@@ -525,16 +562,42 @@ 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;
 }
@@ -600,11 +663,21 @@ elog_cmp (void *a1, void *a2)
   elog_event_t *e1 = a1;
   elog_event_t *e2 = a2;
 
-  return e1->time - e2->time;
+  if (e1->time < e2->time)
+    return -1;
+
+  if (e1->time > e2->time)
+    return 1;
+
+  return 0;
 }
 
+/*
+ * merge two event logs. Complicated and cranky.
+ */
 void
-elog_merge (elog_main_t * dst, u8 * dst_tag, elog_main_t * src, u8 * src_tag)
+elog_merge (elog_main_t * dst, u8 * dst_tag, elog_main_t * src, u8 * src_tag,
+	    f64 align_tweak)
 {
   elog_event_t *e;
   uword l;
@@ -613,8 +686,9 @@ 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);
   elog_get_events (dst);
 
@@ -622,7 +696,7 @@ elog_merge (elog_main_t * dst, u8 * dst_tag, elog_main_t * src, u8 * src_tag)
   vec_append (dst->string_table, src->string_table);
 
   l = vec_len (dst->events);
-  vec_add (dst->events, src->events, vec_len (src->events));
+  vec_append (dst->events, src->events);
 
   /* Prepend the supplied tag (if any) to all dst track names */
   if (dst_tag)
@@ -638,6 +712,9 @@ elog_merge (elog_main_t * dst, u8 * dst_tag, elog_main_t * src, u8 * src_tag)
 	}
     }
 
+  /*
+   * Remember where we started allocating new tracks while merging
+   */
   track_offset_for_src_tracks = vec_len (dst->tracks);
 
   /* Copy / tag source tracks */
@@ -688,10 +765,18 @@ elog_merge (elog_main_t * dst, u8 * dst_tag, elog_main_t * src, u8 * src_tag)
       (elog_time_stamp_diff_cpu (&src->init_time, &dst->init_time) * .5 *
        (dst->nsec_per_cpu_clock + src->nsec_per_cpu_clock));
 
-    /* Heuristic to see if src/dst came from same time source.
-       If frequencies are "the same" and os clock and cpu clock agree
-       to within 100e-9 secs about time difference between src/dst
-       init_time, then we use cpu clock.  Otherwise we use OS clock. */
+    /*
+     * Heuristic to see if src/dst came from same time source.
+     * If frequencies are "the same" and os clock and cpu clock agree
+     * to within 100e-9 secs about time difference between src/dst
+     * init_time, then we use cpu clock.  Otherwise we use OS clock.
+     *
+     * When merging event logs from different systems, time paradoxes
+     * at the O(1ms) level are to be expected. Hence, the "align_tweak"
+     * parameter. If two events logged on different processors are known
+     * to occur in a specific order - and with a reasonably-estimated
+     * interval - supply a non-zero "align_tweak" parameter
+     */
     if (fabs (src->nsec_per_cpu_clock - dst->nsec_per_cpu_clock) < 1e-2
 	&& fabs (dt_os_nsec - dt_clock_nsec) < 100)
       dt_event = dt_clock_nsec;
@@ -699,23 +784,45 @@ elog_merge (elog_main_t * dst, u8 * dst_tag, elog_main_t * src, u8 * src_tag)
     /* Convert to seconds. */
     dt_event *= 1e-9;
 
+    /*
+     * Move the earlier set of events later, to avoid creating
+     * events which precede the Big Bang (aka have negative timestamps).
+     *
+     * Not to any scale, we have something like the following picture:
+     *
+     * DST capture start point
+     *       ^
+     *       +--- dt_event --+
+     *                       v
+     *                 SRC capture start point
+     *
+     * In this case dt_event is positive, src started after dst,
+     * to put src events onto a common timebase we have to move them
+     * forward in time. Naturally, the opposite case is
+     * possible, too: dt_event will be negative, and so we have to
+     * move dst events forward in time by the |dt_event|.
+     * In both cases, we add align_tweak.
+     */
     if (dt_event > 0)
       {
 	/* Src started after dst. */
 	for (e = dst->events + l; e < vec_end (dst->events); e++)
-	  e->time += dt_event;
+	  e->time += dt_event + align_tweak;
       }
     else
       {
 	/* Dst started after src. */
+	dt_event = -dt_event;
 	for (e = dst->events + 0; e < dst->events + l; e++)
-	  e->time += dt_event;
+	  e->time += dt_event + align_tweak;
       }
   }
 
   /* Sort events by increasing time. */
   vec_sort_with_function (dst->events, elog_cmp);
 
+  dst->n_total_events = vec_len (dst->events);
+
   /* Recreate the event ring or the results won't serialize */
   {
     int i;
@@ -731,12 +838,7 @@ elog_merge (elog_main_t * dst, u8 * dst_tag, elog_main_t * src, u8 * src_tag)
 	ed = dst->event_ring + i;
 
 	ed[0] = es[0];
-
-	/* Invert elog_peek_events calculation */
-	ed->time_cycles =
-	  (es->time / dst->cpu_timer.seconds_per_clock) + dst->init_time.cpu;
       }
-    dst->n_total_events = vec_len (dst->events);
   }
 }
 
@@ -990,6 +1092,7 @@ void
 serialize_elog_main (serialize_main_t * m, va_list * va)
 {
   elog_main_t *em = va_arg (*va, elog_main_t *);
+  int flush_ring = va_arg (*va, int);
   elog_event_t *e;
 
   serialize_magic (m, elog_serialize_magic, strlen (elog_serialize_magic));
@@ -1005,8 +1108,11 @@ serialize_elog_main (serialize_main_t * m, va_list * va)
   vec_serialize (m, em->string_table, serialize_vec_8);
 
   /* Free old events (cached) in case they have changed. */
-  vec_free (em->events);
-  elog_get_events (em);
+  if (flush_ring)
+    {
+      vec_free (em->events);
+      elog_get_events (em);
+    }
 
   serialize_integer (m, vec_len (em->events), sizeof (u32));