#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
{
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)
{
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);
}
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;
return l;
}
-word
+__clib_export word
elog_track_register (elog_main_t * em, elog_track_t * t)
{
word l;
return s;
}
-u8 *
+__clib_export u8 *
format_elog_event (u8 * s, va_list * va)
{
elog_main_t *em = va_arg (*va, elog_main_t *);
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;
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 *);
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)
{
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 ();
&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;
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. */
}
}
-elog_event_t *
+__clib_export elog_event_t *
elog_peek_events (elog_main_t * em)
{
elog_event_t *e, *f, *es = 0;
}
/* 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;
}
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;
}
-void
-elog_merge (elog_main_t * dst, u8 * dst_tag, elog_main_t * src, u8 * src_tag)
+/*
+ * merge two event logs. Complicated and cranky.
+ */
+__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;
uword l;
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);
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)
}
}
+ /*
+ * Remember where we started allocating new tracks while merging
+ */
track_offset_for_src_tracks = vec_len (dst->tracks);
/* Copy / tag source tracks */
/* 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,
(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;
/* 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;
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);
}
}
{
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);
{
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);
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 *);
+ int flush_ring = va_arg (*va, int);
elog_event_t *e;
serialize_magic (m, elog_serialize_magic, strlen (elog_serialize_magic));
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));
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;
}
}
+#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
*
Code Review / vpp.git / blobdiff