FD.io VPP  v19.08-23-g4b943d6
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 #include <vppinfra/lock.h>
45 
46 static inline void
48 {
49  if (PREDICT_FALSE (em->lock != 0))
50  while (clib_atomic_test_and_set (em->lock))
51  CLIB_PAUSE ();
52 }
53 
54 static inline void
56 {
57  if (PREDICT_FALSE (em->lock != 0))
58  {
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  /* String table entries MUST be NULL terminated */
576  len = vec_len (em->string_table_tmp);
577  ASSERT (len > 0);
578  if (em->string_table_tmp[len - 1] != 0)
579  vec_add1 (em->string_table_tmp, 0);
580 
581  /* See if we already have this string in the string table */
583 
584  /* We already have the string, so give the caller its offset */
585  if (p)
586  {
587  elog_unlock (em);
588  return (p[0]);
589  }
590 
591  /* We don't, so add it. */
592 
593  offset = vec_len (em->string_table);
595 
597 
598  /* We gave the key to the string table hash, so we can't reuse it! */
599  em->string_table_tmp = 0;
600  elog_unlock (em);
601 
602  return offset;
603 }
604 
605 elog_event_t *
607 {
608  if (!em->events)
609  em->events = elog_peek_events (em);
610  return em->events;
611 }
612 
613 static void
616 {
617  void *d = (u8 *) e->data;
618  char *a;
619 
620  if (offset == 0)
621  return;
622 
623  a = t->format_args;
624 
625  while (1)
626  {
627  uword n_bytes = 0, n_digits;
628 
629  if (a[0] == 0)
630  break;
631 
632  /* Don't go past end of event data. */
633  ASSERT (d < (void *) (e->data + sizeof (e->data)));
634 
635  n_digits = parse_2digit_decimal (a + 1, &n_bytes);
636  switch (a[0])
637  {
638  case 'T':
639  ASSERT (n_bytes == 4);
640  clib_mem_unaligned (d, u32) += offset;
641  break;
642 
643  case 'i':
644  case 't':
645  case 'f':
646  case 's':
647  break;
648 
649  default:
650  ASSERT (0);
651  break;
652  }
653 
654  ASSERT (n_digits > 0 && n_digits <= 2);
655  a += 1 + n_digits;
656  d += n_bytes;
657  }
658 }
659 
660 static int
661 elog_cmp (void *a1, void *a2)
662 {
663  elog_event_t *e1 = a1;
664  elog_event_t *e2 = a2;
665 
666  if (e1->time < e2->time)
667  return -1;
668 
669  if (e1->time > e2->time)
670  return 1;
671 
672  return 0;
673 }
674 
675 /*
676  * merge two event logs. Complicated and cranky.
677  */
678 void
679 elog_merge (elog_main_t * dst, u8 * dst_tag, elog_main_t * src, u8 * src_tag,
680  f64 align_tweak)
681 {
682  elog_event_t *e;
683  uword l;
684  u32 string_table_offset_for_src_events;
685  u32 track_offset_for_src_tracks;
686  elog_track_t newt;
687  int i;
688 
689  clib_memset (&newt, 0, sizeof (newt));
690 
691  /* Acquire src and dst events */
692  elog_get_events (src);
693  elog_get_events (dst);
694 
695  string_table_offset_for_src_events = vec_len (dst->string_table);
696  vec_append (dst->string_table, src->string_table);
697 
698  l = vec_len (dst->events);
699  vec_append (dst->events, src->events);
700 
701  /* Prepend the supplied tag (if any) to all dst track names */
702  if (dst_tag)
703  {
704  for (i = 0; i < vec_len (dst->tracks); i++)
705  {
706  elog_track_t *t = vec_elt_at_index (dst->tracks, i);
707  char *new_name;
708 
709  new_name = (char *) format (0, "%s:%s%c", dst_tag, t->name, 0);
710  vec_free (t->name);
711  t->name = new_name;
712  }
713  }
714 
715  /*
716  * Remember where we started allocating new tracks while merging
717  */
718  track_offset_for_src_tracks = vec_len (dst->tracks);
719 
720  /* Copy / tag source tracks */
721  for (i = 0; i < vec_len (src->tracks); i++)
722  {
723  elog_track_t *t = vec_elt_at_index (src->tracks, i);
724  if (src_tag)
725  newt.name = (char *) format (0, "%s:%s%c", src_tag, t->name, 0);
726  else
727  newt.name = (char *) format (0, "%s%c", t->name, 0);
728  (void) elog_track_register (dst, &newt);
729  vec_free (newt.name);
730  }
731 
732  /* Across all (copied) src events... */
733  for (e = dst->events + l; e < vec_end (dst->events); e++)
734  {
736 
737  /* Remap type from src -> dst. */
738  e->type = find_or_create_type (dst, t);
739 
740  /* Remap string table offsets for 'T' format args */
742  string_table_offset_for_src_events);
743 
744  /* Remap track */
745  e->track += track_offset_for_src_tracks;
746  }
747 
748  /* Adjust event times for relative starting times of event streams. */
749  {
750  f64 dt_event, dt_os_nsec, dt_clock_nsec;
751 
752  /* Set clock parameters if dst was not generated by unserialize. */
753  if (dst->serialize_time.cpu == 0)
754  {
755  dst->init_time = src->init_time;
756  dst->serialize_time = src->serialize_time;
758  }
759 
760  dt_os_nsec =
762 
763  dt_event = dt_os_nsec;
764  dt_clock_nsec =
765  (elog_time_stamp_diff_cpu (&src->init_time, &dst->init_time) * .5 *
766  (dst->nsec_per_cpu_clock + src->nsec_per_cpu_clock));
767 
768  /*
769  * Heuristic to see if src/dst came from same time source.
770  * If frequencies are "the same" and os clock and cpu clock agree
771  * to within 100e-9 secs about time difference between src/dst
772  * init_time, then we use cpu clock. Otherwise we use OS clock.
773  *
774  * When merging event logs from different systems, time paradoxes
775  * at the O(1ms) level are to be expected. Hence, the "align_tweak"
776  * parameter. If two events logged on different processors are known
777  * to occur in a specific order - and with a reasonably-estimated
778  * interval - supply a non-zero "align_tweak" parameter
779  */
780  if (fabs (src->nsec_per_cpu_clock - dst->nsec_per_cpu_clock) < 1e-2
781  && fabs (dt_os_nsec - dt_clock_nsec) < 100)
782  dt_event = dt_clock_nsec;
783 
784  /* Convert to seconds. */
785  dt_event *= 1e-9;
786 
787  /*
788  * Move the earlier set of events later, to avoid creating
789  * events which precede the Big Bang (aka have negative timestamps).
790  *
791  * Not to any scale, we have something like the following picture:
792  *
793  * DST capture start point
794  * ^
795  * +--- dt_event --+
796  * v
797  * SRC capture start point
798  *
799  * In this case dt_event is positive, src started after dst,
800  * to put src events onto a common timebase we have to move them
801  * forward in time. Naturally, the opposite case is
802  * possible, too: dt_event will be negative, and so we have to
803  * move dst events forward in time by the |dt_event|.
804  * In both cases, we add align_tweak.
805  */
806  if (dt_event > 0)
807  {
808  /* Src started after dst. */
809  for (e = dst->events + l; e < vec_end (dst->events); e++)
810  e->time += dt_event + align_tweak;
811  }
812  else
813  {
814  /* Dst started after src. */
815  dt_event = -dt_event;
816  for (e = dst->events + 0; e < dst->events + l; e++)
817  e->time += dt_event + align_tweak;
818  }
819  }
820 
821  /* Sort events by increasing time. */
823 
824  dst->n_total_events = vec_len (dst->events);
825 
826  /* Recreate the event ring or the results won't serialize */
827  {
828  int i;
829 
831 
832  elog_alloc (dst, vec_len (dst->events));
833  for (i = 0; i < vec_len (dst->events); i++)
834  {
835  elog_event_t *es, *ed;
836 
837  es = dst->events + i;
838  ed = dst->event_ring + i;
839 
840  ed[0] = es[0];
841  }
842  }
843 }
844 
845 static void
847 {
848  elog_main_t *em = va_arg (*va, elog_main_t *);
849  elog_event_t *e = va_arg (*va, elog_event_t *);
851  u8 *d = e->data;
852  u8 *p = (u8 *) t->format_args;
853 
854  serialize_integer (m, e->type, sizeof (e->type));
855  serialize_integer (m, e->track, sizeof (e->track));
856  serialize (m, serialize_f64, e->time);
857 
858  while (*p)
859  {
860  uword n_digits, n_bytes = 0;
861 
862  n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
863 
864  switch (p[0])
865  {
866  case 'i':
867  case 't':
868  case 'T':
869  if (n_bytes == 1)
870  serialize_integer (m, d[0], sizeof (u8));
871  else if (n_bytes == 2)
872  serialize_integer (m, clib_mem_unaligned (d, u16), sizeof (u16));
873  else if (n_bytes == 4)
874  serialize_integer (m, clib_mem_unaligned (d, u32), sizeof (u32));
875  else if (n_bytes == 8)
877  else
878  ASSERT (0);
879  break;
880 
881  case 's':
882  serialize_cstring (m, (char *) d);
883  if (n_bytes == 0)
884  n_bytes = strlen ((char *) d) + 1;
885  break;
886 
887  case 'f':
888  if (n_bytes == 4)
890  else if (n_bytes == 8)
892  else
893  ASSERT (0);
894  break;
895 
896  default:
897  ASSERT (0);
898  break;
899  }
900 
901  p += 1 + n_digits;
902  d += n_bytes;
903  }
904 }
905 
906 static void
908 {
909  elog_main_t *em = va_arg (*va, elog_main_t *);
910  elog_event_t *e = va_arg (*va, elog_event_t *);
912  u8 *p, *d;
913 
914  {
915  u16 tmp[2];
916 
917  unserialize_integer (m, &tmp[0], sizeof (e->type));
918  unserialize_integer (m, &tmp[1], sizeof (e->track));
919 
920  e->type = tmp[0];
921  e->track = tmp[1];
922 
923  /* Make sure it fits. */
924  ASSERT (e->type == tmp[0]);
925  ASSERT (e->track == tmp[1]);
926  }
927 
928  t = vec_elt_at_index (em->event_types, e->type);
929 
930  unserialize (m, unserialize_f64, &e->time);
931 
932  d = e->data;
933  p = (u8 *) t->format_args;
934 
935  while (p && *p)
936  {
937  uword n_digits, n_bytes = 0;
938  u32 tmp;
939 
940  n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
941 
942  switch (p[0])
943  {
944  case 'i':
945  case 't':
946  case 'T':
947  if (n_bytes == 1)
948  {
949  unserialize_integer (m, &tmp, sizeof (u8));
950  d[0] = tmp;
951  }
952  else if (n_bytes == 2)
953  {
954  unserialize_integer (m, &tmp, sizeof (u16));
955  clib_mem_unaligned (d, u16) = tmp;
956  }
957  else if (n_bytes == 4)
958  {
959  unserialize_integer (m, &tmp, sizeof (u32));
960  clib_mem_unaligned (d, u32) = tmp;
961  }
962  else if (n_bytes == 8)
963  {
964  u64 x;
965  unserialize (m, unserialize_64, &x);
966  clib_mem_unaligned (d, u64) = x;
967  }
968  else
969  ASSERT (0);
970  break;
971 
972  case 's':
973  {
974  char *t;
975  unserialize_cstring (m, &t);
976  if (n_bytes == 0)
977  n_bytes = strlen (t) + 1;
978  clib_memcpy (d, t, clib_min (n_bytes, vec_len (t)));
979  vec_free (t);
980  break;
981  }
982 
983  case 'f':
984  if (n_bytes == 4)
985  {
986  f32 x;
987  unserialize (m, unserialize_f32, &x);
988  clib_mem_unaligned (d, f32) = x;
989  }
990  else if (n_bytes == 8)
991  {
992  f64 x;
993  unserialize (m, unserialize_f64, &x);
994  clib_mem_unaligned (d, f64) = x;
995  }
996  else
997  ASSERT (0);
998  break;
999 
1000  default:
1001  ASSERT (0);
1002  break;
1003  }
1004 
1005  p += 1 + n_digits;
1006  d += n_bytes;
1007  }
1008 }
1009 
1010 static void
1012 {
1013  elog_event_type_t *t = va_arg (*va, elog_event_type_t *);
1014  int n = va_arg (*va, int);
1015  int i, j;
1016  for (i = 0; i < n; i++)
1017  {
1018  serialize_cstring (m, t[i].format);
1019  serialize_cstring (m, t[i].format_args);
1020  serialize_integer (m, t[i].type_index_plus_one,
1021  sizeof (t->type_index_plus_one));
1022  serialize_integer (m, t[i].n_enum_strings,
1023  sizeof (t[i].n_enum_strings));
1024  for (j = 0; j < t[i].n_enum_strings; j++)
1025  serialize_cstring (m, t[i].enum_strings_vector[j]);
1026  }
1027 }
1028 
1029 static void
1031 {
1032  elog_event_type_t *t = va_arg (*va, elog_event_type_t *);
1033  int n = va_arg (*va, int);
1034  int i, j;
1035  for (i = 0; i < n; i++)
1036  {
1037  unserialize_cstring (m, &t[i].format);
1038  unserialize_cstring (m, &t[i].format_args);
1039  unserialize_integer (m, &t[i].type_index_plus_one,
1040  sizeof (t->type_index_plus_one));
1041  unserialize_integer (m, &t[i].n_enum_strings,
1042  sizeof (t[i].n_enum_strings));
1043  vec_resize (t[i].enum_strings_vector, t[i].n_enum_strings);
1044  for (j = 0; j < t[i].n_enum_strings; j++)
1045  unserialize_cstring (m, &t[i].enum_strings_vector[j]);
1046  }
1047 }
1048 
1049 static void
1051 {
1052  elog_track_t *t = va_arg (*va, elog_track_t *);
1053  int n = va_arg (*va, int);
1054  int i;
1055  for (i = 0; i < n; i++)
1056  {
1057  serialize_cstring (m, t[i].name);
1058  }
1059 }
1060 
1061 static void
1063 {
1064  elog_track_t *t = va_arg (*va, elog_track_t *);
1065  int n = va_arg (*va, int);
1066  int i;
1067  for (i = 0; i < n; i++)
1068  {
1069  unserialize_cstring (m, &t[i].name);
1070  }
1071 }
1072 
1073 static void
1075 {
1076  elog_time_stamp_t *st = va_arg (*va, elog_time_stamp_t *);
1077  serialize (m, serialize_64, st->os_nsec);
1078  serialize (m, serialize_64, st->cpu);
1079 }
1080 
1081 static void
1083 {
1084  elog_time_stamp_t *st = va_arg (*va, elog_time_stamp_t *);
1085  unserialize (m, unserialize_64, &st->os_nsec);
1086  unserialize (m, unserialize_64, &st->cpu);
1087 }
1088 
1089 static char *elog_serialize_magic = "elog v0";
1090 
1091 void
1093 {
1094  elog_main_t *em = va_arg (*va, elog_main_t *);
1095  int flush_ring = va_arg (*va, int);
1096  elog_event_t *e;
1097 
1099 
1100  serialize_integer (m, em->event_ring_size, sizeof (u32));
1101 
1105 
1109 
1110  /* Free old events (cached) in case they have changed. */
1111  if (flush_ring)
1112  {
1113  vec_free (em->events);
1114  elog_get_events (em);
1115  }
1116 
1117  serialize_integer (m, vec_len (em->events), sizeof (u32));
1118 
1119  /* SMP logs can easily have local time paradoxes... */
1121 
1122  vec_foreach (e, em->events) serialize (m, serialize_elog_event, em, e);
1123 }
1124 
1125 void
1127 {
1128  elog_main_t *em = va_arg (*va, elog_main_t *);
1129  uword i;
1130  u32 rs;
1131 
1133  strlen (elog_serialize_magic));
1134 
1135  unserialize_integer (m, &rs, sizeof (u32));
1136  em->event_ring_size = rs;
1137  elog_init (em, em->event_ring_size);
1138 
1142 
1144  for (i = 0; i < vec_len (em->event_types); i++)
1145  new_event_type (em, i);
1146 
1149 
1150  {
1151  u32 ne;
1152  elog_event_t *e;
1153 
1154  unserialize_integer (m, &ne, sizeof (u32));
1155  vec_resize (em->events, ne);
1156  vec_foreach (e, em->events)
1157  unserialize (m, unserialize_elog_event, em, e);
1158  }
1159 }
1160 
1161 /*
1162  * fd.io coding-style-patch-verification: ON
1163  *
1164  * Local Variables:
1165  * eval: (c-set-style "gnu")
1166  * End:
1167  */
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
#define CLIB_PAUSE()
Definition: lock.h:23
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:606
static void maybe_fix_string_table_offset(elog_event_t *e, elog_event_type_t *t, u32 offset)
Definition: elog.c:614
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
#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
vl_api_address_t src
Definition: gre.api:51
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
clib_memset(h->entries, 0, sizeof(h->entries[0])*entries)
static void elog_lock(elog_main_t *em)
Definition: elog.c:47
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:1092
u8 * format_elog_event(u8 *s, va_list *va)
Definition: elog.c:296
char * format
Format string.
Definition: elog.h:92
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:1074
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:1030
#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:1126
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:907
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:129
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:1082
#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:42
#define hash_create_string(elts, value_bytes)
Definition: hash.h:690
static int elog_cmp(void *a1, void *a2)
Definition: elog.c:661
vl_api_fib_path_type_t type
Definition: fib_types.api:123
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
#define clib_atomic_release(a)
Definition: atomics.h:43
lo
static char * elog_serialize_magic
Definition: elog.c:1089
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:1011
#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_address_t dst
Definition: gre.api:52
static void unserialize_elog_track(serialize_main_t *m, va_list *va)
Definition: elog.c:1062
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:55
u8 len
Definition: ip_types.api:90
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:846
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:1050
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.
elog_track_t default_track
Default track.
Definition: elog.h:166
void elog_merge(elog_main_t *dst, u8 *dst_tag, elog_main_t *src, u8 *src_tag, f64 align_tweak)
Definition: elog.c:679
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