FD.io VPP  v19.04.4-rc0-5-ge88582fac
Vector Packet Processing
elog.c
Go to the documentation of this file.
1 /*
2  * Copyright (c) 2015 Cisco and/or its affiliates.
3  * Licensed under the Apache License, Version 2.0 (the "License");
4  * you may not use this file except in compliance with the License.
5  * You may obtain a copy of the License at:
6  *
7  * http://www.apache.org/licenses/LICENSE-2.0
8  *
9  * Unless required by applicable law or agreed to in writing, software
10  * distributed under the License is distributed on an "AS IS" BASIS,
11  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12  * See the License for the specific language governing permissions and
13  * limitations under the License.
14  */
15 /*
16  Copyright (c) 2005,2009 Eliot Dresselhaus
17 
18  Permission is hereby granted, free of charge, to any person obtaining
19  a copy of this software and associated documentation files (the
20  "Software"), to deal in the Software without restriction, including
21  without limitation the rights to use, copy, modify, merge, publish,
22  distribute, sublicense, and/or sell copies of the Software, and to
23  permit persons to whom the Software is furnished to do so, subject to
24  the following conditions:
25 
26  The above copyright notice and this permission notice shall be
27  included in all copies or substantial portions of the Software.
28 
29  THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
30  EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
31  MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND
32  NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE
33  LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION
34  OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION
35  WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
36 */
37 
38 #include <vppinfra/elog.h>
39 #include <vppinfra/cache.h>
40 #include <vppinfra/error.h>
41 #include <vppinfra/format.h>
42 #include <vppinfra/hash.h>
43 #include <vppinfra/math.h>
44 
45 static inline void
47 {
48  if (PREDICT_FALSE (em->lock != 0))
49  while (clib_atomic_test_and_set (em->lock))
50  ;
51 }
52 
53 static inline void
55 {
56  if (PREDICT_FALSE (em->lock != 0))
57  {
59  *em->lock = 0;
60  }
61 }
62 
63 /* Non-inline version. */
64 void *
66  elog_event_type_t * type, elog_track_t * track, u64 cpu_time)
67 {
68  return elog_event_data_inline (em, type, track, cpu_time);
69 }
70 
71 static void
73 {
75 
76  if (!em->event_type_by_format)
78  hash_create_vec ( /* size */ 0, sizeof (u8), sizeof (uword));
79 
80  t->type_index_plus_one = i + 1;
82 }
83 
84 static uword
86 {
88  uword i;
89 
90  if (p)
91  i = p[0];
92  else
93  {
94  i = vec_len (em->event_types);
95  vec_add1 (em->event_types, t[0]);
96  new_event_type (em, i);
97  }
98 
99  return i;
100 }
101 
102 /* External function to register types. */
103 word
105 {
106  elog_event_type_t *static_type = t;
107  word l;
108 
109  elog_lock (em);
110 
111  /* Multiple simultaneous registration attempts, */
112  if (t->type_index_plus_one > 0)
113  {
114  elog_unlock (em);
115  return t->type_index_plus_one - 1;
116  }
117 
118  l = vec_len (em->event_types);
119 
120  t->type_index_plus_one = 1 + l;
121 
122  ASSERT (t->format);
123 
124  /* If format args are not specified try to be smart about providing defaults
125  so most of the time user does not have to specify them. */
126  if (!t->format_args)
127  {
128  uword i, l;
129  char *this_arg;
130 
131  l = strlen (t->format);
132  for (i = 0; i < l; i++)
133  {
134  if (t->format[i] != '%')
135  continue;
136  if (i + 1 >= l)
137  continue;
138  if (t->format[i + 1] == '%') /* %% */
139  continue;
140 
141  switch (t->format[i + 1])
142  {
143  default:
144  case 'd':
145  case 'x':
146  case 'u':
147  this_arg = "i4"; /* size of u32 */
148  break;
149  case 'f':
150  this_arg = "f8"; /* defaults to f64 */
151  break;
152  case 's':
153  this_arg = "s0"; /* defaults to null terminated string. */
154  break;
155  }
156 
157  t->format_args =
158  (char *) format ((u8 *) t->format_args, "%s", this_arg);
159  }
160 
161  /* Null terminate. */
162  vec_add1 (t->format_args, 0);
163  }
164 
165  vec_add1 (em->event_types, t[0]);
166 
167  t = em->event_types + l;
168 
169  /* Make copies of strings for hashing etc. */
170  if (t->function)
171  t->format = (char *) format (0, "%s %s%c", t->function, t->format, 0);
172  else
173  t->format = (char *) format (0, "%s%c", t->format, 0);
174 
175  t->format_args = (char *) format (0, "%s%c", t->format_args, 0);
176 
177  /* Construct string table. */
178  {
179  uword i;
180  t->n_enum_strings = static_type->n_enum_strings;
181  for (i = 0; i < t->n_enum_strings; i++)
182  {
183  if (!static_type->enum_strings[i])
184  static_type->enum_strings[i] = "MISSING";
186  (char *) format (0, "%s%c", static_type->enum_strings[i],
187  0));
188  }
189  }
190 
191  new_event_type (em, l);
192  elog_unlock (em);
193 
194  return l;
195 }
196 
197 word
199 {
200  word l;
201 
202  elog_lock (em);
203 
204  l = vec_len (em->tracks);
205 
206  t->track_index_plus_one = 1 + l;
207 
208  ASSERT (t->name);
209 
210  vec_add1 (em->tracks, t[0]);
211 
212  t = em->tracks + l;
213 
214  t->name = (char *) format (0, "%s%c", t->name, 0);
215 
216  elog_unlock (em);
217 
218  return l;
219 }
220 
221 static uword
222 parse_2digit_decimal (char *p, uword * number)
223 {
224  uword i = 0;
225  u8 digits[2];
226 
227  digits[0] = digits[1] = 0;
228  while (p[i] >= '0' && p[i] <= '9')
229  {
230  if (i >= 2)
231  break;
232  digits[i] = p[i] - '0';
233  i++;
234  }
235 
236  if (i >= 1 && i <= 2)
237  {
238  if (i == 1)
239  *number = digits[0];
240  else
241  *number = 10 * digits[0] + digits[1];
242  return i;
243  }
244  else
245  return 0;
246 }
247 
248 static u8 *
249 fixed_format (u8 * s, char *fmt, char *result, uword * result_len)
250 {
251  char *f = fmt;
252  char *percent;
253  uword l = 0;
254 
255  while (1)
256  {
257  if (f[0] == 0)
258  break;
259  if (f[0] == '%' && f[1] != '%')
260  break;
261  f++;
262  }
263  if (f > fmt)
264  vec_add (s, fmt, f - fmt);
265 
266  if (f[0] != '%')
267  goto done;
268 
269  /* Skip percent. */
270  percent = f++;
271 
272  /* Skip possible +-= justification. */
273  f += f[0] == '+' || f[0] == '-' || f[0] == '=';
274 
275  /* Skip possible X.Y width. */
276  while ((f[0] >= '0' && f[0] <= '9') || f[0] == '.')
277  f++;
278 
279  /* Skip wlL as in e.g. %Ld. */
280  f += f[0] == 'w' || f[0] == 'l' || f[0] == 'L';
281 
282  /* Finally skip format letter. */
283  f += f[0] != 0;
284 
285  ASSERT (*result_len > f - percent);
286  l = clib_min (f - percent, *result_len - 1);
287  clib_memcpy (result, percent, l);
288  result[l] = 0;
289 
290 done:
291  *result_len = f - fmt;
292  return s;
293 }
294 
295 u8 *
296 format_elog_event (u8 * s, va_list * va)
297 {
298  elog_main_t *em = va_arg (*va, elog_main_t *);
299  elog_event_t *e = va_arg (*va, elog_event_t *);
301  char *a, *f;
302  void *d = (u8 *) e->data;
303  char arg_format[64];
304 
305  t = vec_elt_at_index (em->event_types, e->type);
306 
307  f = t->format;
308  a = t->format_args;
309  while (1)
310  {
311  uword n_bytes = 0, n_digits, f_bytes = 0;
312 
313  f_bytes = sizeof (arg_format);
314  s = fixed_format (s, f, arg_format, &f_bytes);
315  f += f_bytes;
316 
317  if (a == 0 || a[0] == 0)
318  {
319  /* Format must also be at end. */
320  ASSERT (f[0] == 0);
321  break;
322  }
323 
324  /* Don't go past end of event data. */
325  ASSERT (d < (void *) (e->data + sizeof (e->data)));
326 
327  n_digits = parse_2digit_decimal (a + 1, &n_bytes);
328  switch (a[0])
329  {
330  case 'i':
331  case 't':
332  case 'T':
333  {
334  u32 i = 0;
335  u64 l = 0;
336 
337  if (n_bytes == 1)
338  i = ((u8 *) d)[0];
339  else if (n_bytes == 2)
340  i = clib_mem_unaligned (d, u16);
341  else if (n_bytes == 4)
342  i = clib_mem_unaligned (d, u32);
343  else if (n_bytes == 8)
344  l = clib_mem_unaligned (d, u64);
345  else
346  ASSERT (0);
347  if (a[0] == 't')
348  {
349  char *e =
350  vec_elt (t->enum_strings_vector, n_bytes == 8 ? l : i);
351  s = format (s, arg_format, e);
352  }
353  else if (a[0] == 'T')
354  {
355  char *e =
356  vec_elt_at_index (em->string_table, n_bytes == 8 ? l : i);
357  s = format (s, arg_format, e);
358  }
359  else if (n_bytes == 8)
360  s = format (s, arg_format, l);
361  else
362  s = format (s, arg_format, i);
363  }
364  break;
365 
366  case 'f':
367  {
368  f64 x = 0;
369  if (n_bytes == 4)
370  x = clib_mem_unaligned (d, f32);
371  else if (n_bytes == 8)
372  x = clib_mem_unaligned (d, f64);
373  else
374  ASSERT (0);
375  s = format (s, arg_format, x);
376  }
377  break;
378 
379  case 's':
380  s = format (s, arg_format, d);
381  if (n_bytes == 0)
382  n_bytes = strlen (d) + 1;
383  break;
384 
385  default:
386  ASSERT (0);
387  break;
388  }
389 
390  ASSERT (n_digits > 0 && n_digits <= 2);
391  a += 1 + n_digits;
392  d += n_bytes;
393  }
394 
395  return s;
396 }
397 
398 u8 *
399 format_elog_track_name (u8 * s, va_list * va)
400 {
401  elog_main_t *em = va_arg (*va, elog_main_t *);
402  elog_event_t *e = va_arg (*va, elog_event_t *);
403  elog_track_t *t = vec_elt_at_index (em->tracks, e->track);
404  return format (s, "%s", t->name);
405 }
406 
407 u8 *
408 format_elog_track (u8 * s, va_list * args)
409 {
410  elog_main_t *em = va_arg (*args, elog_main_t *);
411  f64 dt = va_arg (*args, f64);
412  int track_index = va_arg (*args, int);
413  elog_event_t *e, *es;
414  u8 indent;
415 
416  indent = format_get_indent (s) + 1;
417 
418  es = elog_peek_events (em);
419  vec_foreach (e, es)
420  {
421  if (e->track != track_index)
422  continue;
423  s = format (s, "%U%18.9f: %U\n", format_white_space, indent, e->time + dt,
424  format_elog_event, em, e);
425  }
426  vec_free (es);
427  return s;
428 }
429 
430 void
432 {
433  u64 cpu_time_now, os_time_now_nsec;
434  struct timespec ts;
435 
436 #ifdef CLIB_UNIX
437  {
438 #include <sys/syscall.h>
439 #ifdef __APPLE__
440  clock_gettime (CLOCK_REALTIME, &ts);
441 #else
442  syscall (SYS_clock_gettime, CLOCK_REALTIME, &ts);
443 #endif
444  cpu_time_now = clib_cpu_time_now ();
445  /* Subtract 3/30/2017's worth of seconds to retain precision */
446  os_time_now_nsec = 1e9 * (ts.tv_sec - 1490885108) + ts.tv_nsec;
447  }
448 #else
449  cpu_time_now = clib_cpu_time_now ();
450  os_time_now_nsec = 0;
451 #endif
452 
453  et->cpu = cpu_time_now;
454  et->os_nsec = os_time_now_nsec;
455 }
456 
459 {
460  return (i64) t1->os_nsec - (i64) t2->os_nsec;
461 }
462 
465 {
466  return (i64) t1->cpu - (i64) t2->cpu;
467 }
468 
471 {
473  &em->init_time)
475  &em->init_time));
476 }
477 
478 void
479 elog_alloc (elog_main_t * em, u32 n_events)
480 {
481  if (em->event_ring)
482  vec_free (em->event_ring);
483 
484  /* Ring size must be a power of 2. */
485  em->event_ring_size = n_events = max_pow2 (n_events);
486 
487  /* Leave an empty ievent at end so we can always speculatively write
488  and event there (possibly a long form event). */
490 }
491 
492 void
493 elog_init (elog_main_t * em, u32 n_events)
494 {
495  clib_memset (em, 0, sizeof (em[0]));
496 
497  em->lock = 0;
498 
499  if (n_events > 0)
500  elog_alloc (em, n_events);
501 
502  clib_time_init (&em->cpu_timer);
503 
505 
506  /* Make track 0. */
507  em->default_track.name = "default";
509 
510  elog_time_now (&em->init_time);
511  em->string_table_hash = hash_create_string (0, sizeof (uword));
512 }
513 
514 /* Returns number of events in ring and start index. */
515 static uword
517 {
518  uword l = em->event_ring_size;
519  u64 i = em->n_total_events;
520 
521  /* Ring never wrapped? */
522  if (i <= (u64) l)
523  {
524  if (lo)
525  *lo = 0;
526  return i;
527  }
528  else
529  {
530  if (lo)
531  *lo = i & (l - 1);
532  return l;
533  }
534 }
535 
536 elog_event_t *
538 {
539  elog_event_t *e, *f, *es = 0;
540  uword i, j, n;
541 
542  n = elog_event_range (em, &j);
543  for (i = 0; i < n; i++)
544  {
545  vec_add2 (es, e, 1);
546  f = vec_elt_at_index (em->event_ring, j);
547  e[0] = f[0];
548 
549  /* Convert absolute time from cycles to seconds from start. */
550  e->time =
551  (e->time_cycles -
553 
554  j = (j + 1) & (em->event_ring_size - 1);
555  }
556 
557  return es;
558 }
559 
560 /* Add a formatted string to the string table. */
561 u32
562 elog_string (elog_main_t * em, char *fmt, ...)
563 {
564  u32 offset;
565  uword *p;
566  uword len;
567  va_list va;
568 
569  elog_lock (em);
571  va_start (va, fmt);
572  em->string_table_tmp = va_format (em->string_table_tmp, fmt, &va);
573  va_end (va);
574 
575  /* See if we already have this string in the string table */
577 
578  /* We already have the string, so give the caller its offset */
579  if (p)
580  {
581  elog_unlock (em);
582  return (p[0]);
583  }
584 
585  /* We don't, so add it. String table entries MUST be NULL terminated */
586  len = vec_len (em->string_table_tmp);
587  ASSERT (len > 0);
588  if (em->string_table_tmp[len - 1] != 0)
589  vec_add1 (em->string_table_tmp, 0);
590 
591  offset = vec_len (em->string_table);
593 
595 
596  /* We gave the key to the string table hash, so we can't reuse it! */
597  em->string_table_tmp = 0;
598  elog_unlock (em);
599 
600  return offset;
601 }
602 
603 elog_event_t *
605 {
606  if (!em->events)
607  em->events = elog_peek_events (em);
608  return em->events;
609 }
610 
611 static void
614 {
615  void *d = (u8 *) e->data;
616  char *a;
617 
618  if (offset == 0)
619  return;
620 
621  a = t->format_args;
622 
623  while (1)
624  {
625  uword n_bytes = 0, n_digits;
626 
627  if (a[0] == 0)
628  break;
629 
630  /* Don't go past end of event data. */
631  ASSERT (d < (void *) (e->data + sizeof (e->data)));
632 
633  n_digits = parse_2digit_decimal (a + 1, &n_bytes);
634  switch (a[0])
635  {
636  case 'T':
637  ASSERT (n_bytes == 4);
638  clib_mem_unaligned (d, u32) += offset;
639  break;
640 
641  case 'i':
642  case 't':
643  case 'f':
644  case 's':
645  break;
646 
647  default:
648  ASSERT (0);
649  break;
650  }
651 
652  ASSERT (n_digits > 0 && n_digits <= 2);
653  a += 1 + n_digits;
654  d += n_bytes;
655  }
656 }
657 
658 static int
659 elog_cmp (void *a1, void *a2)
660 {
661  elog_event_t *e1 = a1;
662  elog_event_t *e2 = a2;
663 
664  if (e1->time < e2->time)
665  return -1;
666 
667  if (e1->time > e2->time)
668  return 1;
669 
670  return 0;
671 }
672 
673 /*
674  * merge two event logs. Complicated and cranky.
675  */
676 void
677 elog_merge (elog_main_t * dst, u8 * dst_tag, elog_main_t * src, u8 * src_tag,
678  f64 align_tweak)
679 {
680  elog_event_t *e;
681  uword l;
682  u32 string_table_offset_for_src_events;
683  u32 track_offset_for_src_tracks;
684  elog_track_t newt;
685  int i;
686 
687  clib_memset (&newt, 0, sizeof (newt));
688 
689  /* Acquire src and dst events */
690  elog_get_events (src);
691  elog_get_events (dst);
692 
693  string_table_offset_for_src_events = vec_len (dst->string_table);
694  vec_append (dst->string_table, src->string_table);
695 
696  l = vec_len (dst->events);
697  vec_append (dst->events, src->events);
698 
699  /* Prepend the supplied tag (if any) to all dst track names */
700  if (dst_tag)
701  {
702  for (i = 0; i < vec_len (dst->tracks); i++)
703  {
704  elog_track_t *t = vec_elt_at_index (dst->tracks, i);
705  char *new_name;
706 
707  new_name = (char *) format (0, "%s:%s%c", dst_tag, t->name, 0);
708  vec_free (t->name);
709  t->name = new_name;
710  }
711  }
712 
713  /*
714  * Remember where we started allocating new tracks while merging
715  */
716  track_offset_for_src_tracks = vec_len (dst->tracks);
717 
718  /* Copy / tag source tracks */
719  for (i = 0; i < vec_len (src->tracks); i++)
720  {
721  elog_track_t *t = vec_elt_at_index (src->tracks, i);
722  if (src_tag)
723  newt.name = (char *) format (0, "%s:%s%c", src_tag, t->name, 0);
724  else
725  newt.name = (char *) format (0, "%s%c", t->name, 0);
726  (void) elog_track_register (dst, &newt);
727  vec_free (newt.name);
728  }
729 
730  /* Across all (copied) src events... */
731  for (e = dst->events + l; e < vec_end (dst->events); e++)
732  {
734 
735  /* Remap type from src -> dst. */
736  e->type = find_or_create_type (dst, t);
737 
738  /* Remap string table offsets for 'T' format args */
740  string_table_offset_for_src_events);
741 
742  /* Remap track */
743  e->track += track_offset_for_src_tracks;
744  }
745 
746  /* Adjust event times for relative starting times of event streams. */
747  {
748  f64 dt_event, dt_os_nsec, dt_clock_nsec;
749 
750  /* Set clock parameters if dst was not generated by unserialize. */
751  if (dst->serialize_time.cpu == 0)
752  {
753  dst->init_time = src->init_time;
754  dst->serialize_time = src->serialize_time;
756  }
757 
758  dt_os_nsec =
760 
761  dt_event = dt_os_nsec;
762  dt_clock_nsec =
763  (elog_time_stamp_diff_cpu (&src->init_time, &dst->init_time) * .5 *
764  (dst->nsec_per_cpu_clock + src->nsec_per_cpu_clock));
765 
766  /*
767  * Heuristic to see if src/dst came from same time source.
768  * If frequencies are "the same" and os clock and cpu clock agree
769  * to within 100e-9 secs about time difference between src/dst
770  * init_time, then we use cpu clock. Otherwise we use OS clock.
771  *
772  * When merging event logs from different systems, time paradoxes
773  * at the O(1ms) level are to be expected. Hence, the "align_tweak"
774  * parameter. If two events logged on different processors are known
775  * to occur in a specific order - and with a reasonably-estimated
776  * interval - supply a non-zero "align_tweak" parameter
777  */
778  if (fabs (src->nsec_per_cpu_clock - dst->nsec_per_cpu_clock) < 1e-2
779  && fabs (dt_os_nsec - dt_clock_nsec) < 100)
780  dt_event = dt_clock_nsec;
781 
782  /* Convert to seconds. */
783  dt_event *= 1e-9;
784 
785  /*
786  * Move the earlier set of events later, to avoid creating
787  * events which precede the Big Bang (aka have negative timestamps).
788  *
789  * Not to any scale, we have something like the following picture:
790  *
791  * DST capture start point
792  * ^
793  * +--- dt_event --+
794  * v
795  * SRC capture start point
796  *
797  * In this case dt_event is positive, src started after dst,
798  * to put src events onto a common timebase we have to move them
799  * forward in time. Naturally, the opposite case is
800  * possible, too: dt_event will be negative, and so we have to
801  * move dst events forward in time by the |dt_event|.
802  * In both cases, we add align_tweak.
803  */
804  if (dt_event > 0)
805  {
806  /* Src started after dst. */
807  for (e = dst->events + l; e < vec_end (dst->events); e++)
808  e->time += dt_event + align_tweak;
809  }
810  else
811  {
812  /* Dst started after src. */
813  dt_event = -dt_event;
814  for (e = dst->events + 0; e < dst->events + l; e++)
815  e->time += dt_event + align_tweak;
816  }
817  }
818 
819  /* Sort events by increasing time. */
821 
822  dst->n_total_events = vec_len (dst->events);
823 
824  /* Recreate the event ring or the results won't serialize */
825  {
826  int i;
827 
829 
830  elog_alloc (dst, vec_len (dst->events));
831  for (i = 0; i < vec_len (dst->events); i++)
832  {
833  elog_event_t *es, *ed;
834 
835  es = dst->events + i;
836  ed = dst->event_ring + i;
837 
838  ed[0] = es[0];
839  }
840  }
841 }
842 
843 static void
845 {
846  elog_main_t *em = va_arg (*va, elog_main_t *);
847  elog_event_t *e = va_arg (*va, elog_event_t *);
849  u8 *d = e->data;
850  u8 *p = (u8 *) t->format_args;
851 
852  serialize_integer (m, e->type, sizeof (e->type));
853  serialize_integer (m, e->track, sizeof (e->track));
854  serialize (m, serialize_f64, e->time);
855 
856  while (*p)
857  {
858  uword n_digits, n_bytes = 0;
859 
860  n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
861 
862  switch (p[0])
863  {
864  case 'i':
865  case 't':
866  case 'T':
867  if (n_bytes == 1)
868  serialize_integer (m, d[0], sizeof (u8));
869  else if (n_bytes == 2)
870  serialize_integer (m, clib_mem_unaligned (d, u16), sizeof (u16));
871  else if (n_bytes == 4)
872  serialize_integer (m, clib_mem_unaligned (d, u32), sizeof (u32));
873  else if (n_bytes == 8)
875  else
876  ASSERT (0);
877  break;
878 
879  case 's':
880  serialize_cstring (m, (char *) d);
881  if (n_bytes == 0)
882  n_bytes = strlen ((char *) d) + 1;
883  break;
884 
885  case 'f':
886  if (n_bytes == 4)
888  else if (n_bytes == 8)
890  else
891  ASSERT (0);
892  break;
893 
894  default:
895  ASSERT (0);
896  break;
897  }
898 
899  p += 1 + n_digits;
900  d += n_bytes;
901  }
902 }
903 
904 static void
906 {
907  elog_main_t *em = va_arg (*va, elog_main_t *);
908  elog_event_t *e = va_arg (*va, elog_event_t *);
910  u8 *p, *d;
911 
912  {
913  u16 tmp[2];
914 
915  unserialize_integer (m, &tmp[0], sizeof (e->type));
916  unserialize_integer (m, &tmp[1], sizeof (e->track));
917 
918  e->type = tmp[0];
919  e->track = tmp[1];
920 
921  /* Make sure it fits. */
922  ASSERT (e->type == tmp[0]);
923  ASSERT (e->track == tmp[1]);
924  }
925 
926  t = vec_elt_at_index (em->event_types, e->type);
927 
928  unserialize (m, unserialize_f64, &e->time);
929 
930  d = e->data;
931  p = (u8 *) t->format_args;
932 
933  while (p && *p)
934  {
935  uword n_digits, n_bytes = 0;
936  u32 tmp;
937 
938  n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
939 
940  switch (p[0])
941  {
942  case 'i':
943  case 't':
944  case 'T':
945  if (n_bytes == 1)
946  {
947  unserialize_integer (m, &tmp, sizeof (u8));
948  d[0] = tmp;
949  }
950  else if (n_bytes == 2)
951  {
952  unserialize_integer (m, &tmp, sizeof (u16));
953  clib_mem_unaligned (d, u16) = tmp;
954  }
955  else if (n_bytes == 4)
956  {
957  unserialize_integer (m, &tmp, sizeof (u32));
958  clib_mem_unaligned (d, u32) = tmp;
959  }
960  else if (n_bytes == 8)
961  {
962  u64 x;
963  unserialize (m, unserialize_64, &x);
964  clib_mem_unaligned (d, u64) = x;
965  }
966  else
967  ASSERT (0);
968  break;
969 
970  case 's':
971  {
972  char *t;
973  unserialize_cstring (m, &t);
974  if (n_bytes == 0)
975  n_bytes = strlen (t) + 1;
976  clib_memcpy (d, t, clib_min (n_bytes, vec_len (t)));
977  vec_free (t);
978  break;
979  }
980 
981  case 'f':
982  if (n_bytes == 4)
983  {
984  f32 x;
985  unserialize (m, unserialize_f32, &x);
986  clib_mem_unaligned (d, f32) = x;
987  }
988  else if (n_bytes == 8)
989  {
990  f64 x;
991  unserialize (m, unserialize_f64, &x);
992  clib_mem_unaligned (d, f64) = x;
993  }
994  else
995  ASSERT (0);
996  break;
997 
998  default:
999  ASSERT (0);
1000  break;
1001  }
1002 
1003  p += 1 + n_digits;
1004  d += n_bytes;
1005  }
1006 }
1007 
1008 static void
1010 {
1011  elog_event_type_t *t = va_arg (*va, elog_event_type_t *);
1012  int n = va_arg (*va, int);
1013  int i, j;
1014  for (i = 0; i < n; i++)
1015  {
1016  serialize_cstring (m, t[i].format);
1017  serialize_cstring (m, t[i].format_args);
1018  serialize_integer (m, t[i].type_index_plus_one,
1019  sizeof (t->type_index_plus_one));
1020  serialize_integer (m, t[i].n_enum_strings,
1021  sizeof (t[i].n_enum_strings));
1022  for (j = 0; j < t[i].n_enum_strings; j++)
1023  serialize_cstring (m, t[i].enum_strings_vector[j]);
1024  }
1025 }
1026 
1027 static void
1029 {
1030  elog_event_type_t *t = va_arg (*va, elog_event_type_t *);
1031  int n = va_arg (*va, int);
1032  int i, j;
1033  for (i = 0; i < n; i++)
1034  {
1035  unserialize_cstring (m, &t[i].format);
1036  unserialize_cstring (m, &t[i].format_args);
1037  unserialize_integer (m, &t[i].type_index_plus_one,
1038  sizeof (t->type_index_plus_one));
1039  unserialize_integer (m, &t[i].n_enum_strings,
1040  sizeof (t[i].n_enum_strings));
1041  vec_resize (t[i].enum_strings_vector, t[i].n_enum_strings);
1042  for (j = 0; j < t[i].n_enum_strings; j++)
1043  unserialize_cstring (m, &t[i].enum_strings_vector[j]);
1044  }
1045 }
1046 
1047 static void
1049 {
1050  elog_track_t *t = va_arg (*va, elog_track_t *);
1051  int n = va_arg (*va, int);
1052  int i;
1053  for (i = 0; i < n; i++)
1054  {
1055  serialize_cstring (m, t[i].name);
1056  }
1057 }
1058 
1059 static void
1061 {
1062  elog_track_t *t = va_arg (*va, elog_track_t *);
1063  int n = va_arg (*va, int);
1064  int i;
1065  for (i = 0; i < n; i++)
1066  {
1067  unserialize_cstring (m, &t[i].name);
1068  }
1069 }
1070 
1071 static void
1073 {
1074  elog_time_stamp_t *st = va_arg (*va, elog_time_stamp_t *);
1075  serialize (m, serialize_64, st->os_nsec);
1076  serialize (m, serialize_64, st->cpu);
1077 }
1078 
1079 static void
1081 {
1082  elog_time_stamp_t *st = va_arg (*va, elog_time_stamp_t *);
1083  unserialize (m, unserialize_64, &st->os_nsec);
1084  unserialize (m, unserialize_64, &st->cpu);
1085 }
1086 
1087 static char *elog_serialize_magic = "elog v0";
1088 
1089 void
1091 {
1092  elog_main_t *em = va_arg (*va, elog_main_t *);
1093  int flush_ring = va_arg (*va, int);
1094  elog_event_t *e;
1095 
1097 
1098  serialize_integer (m, em->event_ring_size, sizeof (u32));
1099 
1103 
1107 
1108  /* Free old events (cached) in case they have changed. */
1109  if (flush_ring)
1110  {
1111  vec_free (em->events);
1112  elog_get_events (em);
1113  }
1114 
1115  serialize_integer (m, vec_len (em->events), sizeof (u32));
1116 
1117  /* SMP logs can easily have local time paradoxes... */
1119 
1120  vec_foreach (e, em->events) serialize (m, serialize_elog_event, em, e);
1121 }
1122 
1123 void
1125 {
1126  elog_main_t *em = va_arg (*va, elog_main_t *);
1127  uword i;
1128  u32 rs;
1129 
1131  strlen (elog_serialize_magic));
1132 
1133  unserialize_integer (m, &rs, sizeof (u32));
1134  em->event_ring_size = rs;
1135  elog_init (em, em->event_ring_size);
1136 
1140 
1142  for (i = 0; i < vec_len (em->event_types); i++)
1143  new_event_type (em, i);
1144 
1147 
1148  {
1149  u32 ne;
1150  elog_event_t *e;
1151 
1152  unserialize_integer (m, &ne, sizeof (u32));
1153  vec_resize (em->events, ne);
1154  vec_foreach (e, em->events)
1155  unserialize (m, unserialize_elog_event, em, e);
1156  }
1157 }
1158 
1159 /*
1160  * fd.io coding-style-patch-verification: ON
1161  *
1162  * Local Variables:
1163  * eval: (c-set-style "gnu")
1164  * End:
1165  */
uword * string_table_hash
Definition: elog.h:159
char ** enum_strings_vector
String table as a vector constructed when type is registered.
Definition: elog.h:89
f64 time
Absolute time as floating point number in seconds.
Definition: elog.h:67
elog_time_stamp_t serialize_time
Definition: elog.h:172
#define clib_min(x, y)
Definition: clib.h:295
void unserialize_check_magic(serialize_main_t *m, void *magic, u32 magic_bytes)
Definition: serialize.c:634
elog_event_t * elog_get_events(elog_main_t *em)
convert event ring events to events, and return them as a vector.
Definition: elog.c:604
static void maybe_fix_string_table_offset(elog_event_t *e, elog_event_type_t *t, u32 offset)
Definition: elog.c:612
a
Definition: bitmap.h:538
static i64 elog_time_stamp_diff_os_nsec(elog_time_stamp_t *t1, elog_time_stamp_t *t2)
Definition: elog.c:458
void elog_time_now(elog_time_stamp_t *et)
Definition: elog.c:431
#define vec_serialize(m, v, f)
Definition: serialize.h:371
word elog_track_register(elog_main_t *em, elog_track_t *t)
register an event track
Definition: elog.c:198
unsigned long u64
Definition: types.h:89
elog_time_stamp_t init_time
Timestamps.
Definition: elog.h:172
clib_memset(h->entries, 0, sizeof(h->entries[0]) *entries)
#define vec_unserialize(m, v, f)
Definition: serialize.h:374
serialize_function_t unserialize_64
Definition: serialize.h:354
u64 time_cycles
Absolute time stamp in CPU clock cycles.
Definition: elog.h:64
#define vec_add1(V, E)
Add 1 element to end of vector (unspecified alignment).
Definition: vec.h:522
static u64 clib_cpu_time_now(void)
Definition: time.h:75
char * function
Function name generating event.
Definition: elog.h:104
#define vec_add2(V, P, N)
Add N elements to end of vector V, return pointer to new elements in P.
Definition: vec.h:560
int i
static u32 format_get_indent(u8 *s)
Definition: format.h:72
#define hash_set_mem(h, key, value)
Definition: hash.h:275
static void elog_lock(elog_main_t *em)
Definition: elog.c:46
u8 * format(u8 *s, const char *fmt,...)
Definition: format.c:424
u8 * va_format(u8 *s, const char *fmt, va_list *va)
Definition: format.c:387
void serialize_elog_main(serialize_main_t *m, va_list *va)
Definition: elog.c:1090
u8 * format_elog_event(u8 *s, va_list *va)
Definition: elog.c:296
char * format
Format string.
Definition: elog.h:92
vl_api_ip4_address_t dst
Definition: ipsec_gre.api:39
static uword find_or_create_type(elog_main_t *em, elog_event_type_t *t)
Definition: elog.c:85
serialize_function_t serialize_64
Definition: serialize.h:354
unsigned char u8
Definition: types.h:56
u8 data[20]
20-bytes of data follows, pads to 32 bytes.
Definition: elog.h:79
static void serialize_elog_time_stamp(serialize_main_t *m, va_list *va)
Definition: elog.c:1072
char * enum_strings[]
String table for enum/number to string formatting.
Definition: elog.h:110
#define vec_reset_length(v)
Reset vector length to zero NULL-pointer tolerant.
double f64
Definition: types.h:142
static void unserialize_elog_event_type(serialize_main_t *m, va_list *va)
Definition: elog.c:1028
#define clib_memcpy(d, s, n)
Definition: string.h:180
static void new_event_type(elog_main_t *em, uword i)
Definition: elog.c:72
#define vec_add(V, E, N)
Add N elements to end of vector V (no header, unspecified alignment)
Definition: vec.h:598
void unserialize_elog_main(serialize_main_t *m, va_list *va)
Definition: elog.c:1124
u32 n_enum_strings
Number of elements in string enum table.
Definition: elog.h:107
serialize_function_t unserialize_f32
Definition: serialize.h:359
static void unserialize_elog_event(serialize_main_t *m, va_list *va)
Definition: elog.c:905
i64 word
Definition: types.h:111
void elog_init(elog_main_t *em, u32 n_events)
Definition: elog.c:493
word elog_event_type_register(elog_main_t *em, elog_event_type_t *t)
register an event type
Definition: elog.c:104
#define always_inline
Definition: clib.h:98
u8 * format_white_space(u8 *s, va_list *va)
Definition: std-formats.c:113
u32 type_index_plus_one
Type index plus one assigned to this type.
Definition: elog.h:86
u8 * format_elog_track_name(u8 *s, va_list *va)
Definition: elog.c:399
static i64 elog_time_stamp_diff_cpu(elog_time_stamp_t *t1, elog_time_stamp_t *t2)
Definition: elog.c:464
static void unserialize_elog_time_stamp(serialize_main_t *m, va_list *va)
Definition: elog.c:1080
#define vec_elt_at_index(v, i)
Get vector value at index i checking that i is in bounds.
uword * lock
SMP lock, non-zero means locking required.
Definition: elog.h:175
static uword elog_event_range(elog_main_t *em, uword *lo)
Definition: elog.c:516
char * format_args
Specifies how arguments to format are parsed from event data.
Definition: elog.h:101
#define vec_resize(V, N)
Resize a vector (no header, unspecified alignment) Add N elements to end of given vector V...
Definition: vec.h:242
unsigned int u32
Definition: types.h:88
#define vec_end(v)
End (last data address) of vector.
uword * event_type_by_format
Hash table mapping type format to type index.
Definition: elog.h:155
#define clib_atomic_test_and_set(a)
Definition: atomics.h:40
#define hash_create_string(elts, value_bytes)
Definition: hash.h:690
static int elog_cmp(void *a1, void *a2)
Definition: elog.c:659
elog_event_type_t * event_types
Vector of event types.
Definition: elog.h:152
static uword parse_2digit_decimal(char *p, uword *number)
Definition: elog.c:222
lo
static char * elog_serialize_magic
Definition: elog.c:1087
unsigned short u16
Definition: types.h:57
signed long i64
Definition: types.h:78
char * name
Track name vector.
Definition: elog.h:116
elog_event_t * event_ring
Vector of events (circular buffer).
Definition: elog.h:149
static void serialize_elog_event_type(serialize_main_t *m, va_list *va)
Definition: elog.c:1009
#define PREDICT_FALSE(x)
Definition: clib.h:111
f64 nsec_per_cpu_clock
Use serialize_time and init_time to give estimate for cpu clock frequency.
Definition: elog.h:179
f64 seconds_per_clock
Definition: time.h:57
vl_api_ip4_address_t src
Definition: ipsec_gre.api:38
static void unserialize_elog_track(serialize_main_t *m, va_list *va)
Definition: elog.c:1060
void clib_time_init(clib_time_t *c)
Definition: time.c:178
u8 name[64]
Definition: memclnt.api:152
void elog_alloc(elog_main_t *em, u32 n_events)
Definition: elog.c:479
serialize_function_t unserialize_f64
Definition: serialize.h:358
void unserialize_cstring(serialize_main_t *m, char **s)
Definition: serialize.c:178
static void elog_unlock(elog_main_t *em)
Definition: elog.c:54
u8 len
Definition: ip_types.api:49
The fine-grained event logger allows lightweight, thread-safe event logging at minimum cost...
clib_error_t * serialize(serialize_main_t *m,...)
Definition: serialize.c:672
#define vec_free(V)
Free vector&#39;s memory (no header).
Definition: vec.h:341
static f64 elog_nsec_per_clock(elog_main_t *em)
Definition: elog.c:470
static f64 fabs(f64 x)
Definition: math.h:50
static void serialize_elog_event(serialize_main_t *m, va_list *va)
Definition: elog.c:844
static uword max_pow2(uword x)
Definition: clib.h:226
u32 track_index_plus_one
Set to one when track has been added to main structure.
Definition: elog.h:120
static void unserialize_integer(serialize_main_t *m, void *x, u32 n_bytes)
Definition: serialize.h:201
static void serialize_integer(serialize_main_t *m, u64 x, u32 n_bytes)
Definition: serialize.h:185
u32 n_total_events_disable_limit
When count reaches limit logging is disabled.
Definition: elog.h:139
static void serialize_elog_track(serialize_main_t *m, va_list *va)
Definition: elog.c:1048
u64 os_nsec
OS timer in nano secs since epoch 3/30/2017, see elog_time_now()
Definition: elog.h:129
serialize_function_t unserialize_vec_8
Definition: serialize.h:362
void serialize_magic(serialize_main_t *m, void *magic, u32 magic_bytes)
Definition: serialize.c:625
#define ASSERT(truth)
uword event_ring_size
Power of 2 number of elements in ring.
Definition: elog.h:145
u64 cpu
CPU cycle counter.
Definition: elog.h:126
clib_error_t * unserialize(serialize_main_t *m,...)
Definition: serialize.c:684
#define vec_append(v1, v2)
Append v2 after v1.
Definition: vec.h:818
u16 track
Track for this event.
Definition: elog.h:76
#define clib_mem_unaligned(pointer, type)
Definition: types.h:155
clib_time_t cpu_timer
Place holder for CPU clock frequency.
Definition: elog.h:169
serialize_function_t serialize_f32
Definition: serialize.h:359
float f32
Definition: types.h:143
void serialize_cstring(serialize_main_t *m, char *s)
Definition: serialize.c:164
#define vec_elt(v, i)
Get vector value at index i.
elog_event_t * events
Vector of events converted to generic form after collection.
Definition: elog.h:182
template key/value backing page structure
Definition: bihash_doc.h:44
#define hash_create_vec(elts, key_bytes, value_bytes)
Definition: hash.h:668
serialize_function_t serialize_vec_8
Definition: serialize.h:362
u32 elog_string(elog_main_t *em, char *fmt,...)
add a string to the event-log string table
Definition: elog.c:562
#define vec_len(v)
Number of elements in vector (rvalue-only, NULL tolerant)
u8 * format_elog_track(u8 *s, va_list *args)
Definition: elog.c:408
u16 type
Event type index.
Definition: elog.h:71
u64 uword
Definition: types.h:112
#define vec_sort_with_function(vec, f)
Sort a vector using the supplied element comparison function.
Definition: vec.h:980
void * elog_event_data(elog_main_t *em, elog_event_type_t *type, elog_track_t *track, u64 cpu_time)
Definition: elog.c:65
u8 * string_table_tmp
Definition: elog.h:160
elog_track_t * tracks
Vector of tracks.
Definition: elog.h:163
#define hash_get_mem(h, key)
Definition: hash.h:269
struct clib_bihash_value offset
template key/value backing page structure
static u8 * fixed_format(u8 *s, char *fmt, char *result, uword *result_len)
Definition: elog.c:249
char * string_table
Events may refer to strings in string table.
Definition: elog.h:158
#define vec_foreach(var, vec)
Vector iterator.
#define SYS_clock_gettime
elog_track_t default_track
Default track.
Definition: elog.h:166
#define CLIB_MEMORY_BARRIER()
Definition: clib.h:115
void elog_merge(elog_main_t *dst, u8 *dst_tag, elog_main_t *src, u8 *src_tag, f64 align_tweak)
Definition: elog.c:677
u32 n_total_events
Total number of events in buffer.
Definition: elog.h:135
#define CLIB_CACHE_LINE_BYTES
Definition: cache.h:59
static void * elog_event_data_inline(elog_main_t *em, elog_event_type_t *type, elog_track_t *track, u64 cpu_time)
Allocate an event to be filled in by the caller.
Definition: elog.h:293
elog_event_t * elog_peek_events(elog_main_t *em)
convert event ring events to events, and return them as a vector.
Definition: elog.c:537
serialize_function_t serialize_f64
Definition: serialize.h:358
#define vec_resize_aligned(V, N, A)
Resize a vector (no header, alignment specified).
Definition: vec.h:255