FD.io VPP  v19.01.2-3-gf61a1a8
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 }
512 
513 /* Returns number of events in ring and start index. */
514 static uword
516 {
517  uword l = em->event_ring_size;
518  u64 i = em->n_total_events;
519 
520  /* Ring never wrapped? */
521  if (i <= (u64) l)
522  {
523  if (lo)
524  *lo = 0;
525  return i;
526  }
527  else
528  {
529  if (lo)
530  *lo = i & (l - 1);
531  return l;
532  }
533 }
534 
535 elog_event_t *
537 {
538  elog_event_t *e, *f, *es = 0;
539  uword i, j, n;
540 
541  n = elog_event_range (em, &j);
542  for (i = 0; i < n; i++)
543  {
544  vec_add2 (es, e, 1);
545  f = vec_elt_at_index (em->event_ring, j);
546  e[0] = f[0];
547 
548  /* Convert absolute time from cycles to seconds from start. */
549  e->time =
550  (e->time_cycles -
552 
553  j = (j + 1) & (em->event_ring_size - 1);
554  }
555 
556  return es;
557 }
558 
559 /* Add a formatted string to the string table. */
560 u32
561 elog_string (elog_main_t * em, char *fmt, ...)
562 {
563  u32 offset;
564  va_list va;
565 
566  va_start (va, fmt);
567  offset = vec_len (em->string_table);
568  em->string_table = (char *) va_format ((u8 *) em->string_table, fmt, &va);
569  va_end (va);
570 
571  /* Null terminate string if it is not already. */
572  if (vec_end (em->string_table)[-1] != 0)
573  vec_add1 (em->string_table, 0);
574 
575  return offset;
576 }
577 
578 elog_event_t *
580 {
581  if (!em->events)
582  em->events = elog_peek_events (em);
583  return em->events;
584 }
585 
586 static void
589 {
590  void *d = (u8 *) e->data;
591  char *a;
592 
593  if (offset == 0)
594  return;
595 
596  a = t->format_args;
597 
598  while (1)
599  {
600  uword n_bytes = 0, n_digits;
601 
602  if (a[0] == 0)
603  break;
604 
605  /* Don't go past end of event data. */
606  ASSERT (d < (void *) (e->data + sizeof (e->data)));
607 
608  n_digits = parse_2digit_decimal (a + 1, &n_bytes);
609  switch (a[0])
610  {
611  case 'T':
612  ASSERT (n_bytes == 4);
613  clib_mem_unaligned (d, u32) += offset;
614  break;
615 
616  case 'i':
617  case 't':
618  case 'f':
619  case 's':
620  break;
621 
622  default:
623  ASSERT (0);
624  break;
625  }
626 
627  ASSERT (n_digits > 0 && n_digits <= 2);
628  a += 1 + n_digits;
629  d += n_bytes;
630  }
631 }
632 
633 static int
634 elog_cmp (void *a1, void *a2)
635 {
636  elog_event_t *e1 = a1;
637  elog_event_t *e2 = a2;
638 
639  if (e1->time < e2->time)
640  return -1;
641 
642  if (e1->time > e2->time)
643  return 1;
644 
645  return 0;
646 }
647 
648 /*
649  * merge two event logs. Complicated and cranky.
650  */
651 void
652 elog_merge (elog_main_t * dst, u8 * dst_tag, elog_main_t * src, u8 * src_tag,
653  f64 align_tweak)
654 {
655  elog_event_t *e;
656  uword l;
657  u32 string_table_offset_for_src_events;
658  u32 track_offset_for_src_tracks;
659  elog_track_t newt;
660  int i;
661 
662  clib_memset (&newt, 0, sizeof (newt));
663 
664  /* Acquire src and dst events */
665  elog_get_events (src);
666  elog_get_events (dst);
667 
668  string_table_offset_for_src_events = vec_len (dst->string_table);
669  vec_append (dst->string_table, src->string_table);
670 
671  l = vec_len (dst->events);
672  vec_append (dst->events, src->events);
673 
674  /* Prepend the supplied tag (if any) to all dst track names */
675  if (dst_tag)
676  {
677  for (i = 0; i < vec_len (dst->tracks); i++)
678  {
679  elog_track_t *t = vec_elt_at_index (dst->tracks, i);
680  char *new_name;
681 
682  new_name = (char *) format (0, "%s:%s%c", dst_tag, t->name, 0);
683  vec_free (t->name);
684  t->name = new_name;
685  }
686  }
687 
688  /*
689  * Remember where we started allocating new tracks while merging
690  */
691  track_offset_for_src_tracks = vec_len (dst->tracks);
692 
693  /* Copy / tag source tracks */
694  for (i = 0; i < vec_len (src->tracks); i++)
695  {
696  elog_track_t *t = vec_elt_at_index (src->tracks, i);
697  if (src_tag)
698  newt.name = (char *) format (0, "%s:%s%c", src_tag, t->name, 0);
699  else
700  newt.name = (char *) format (0, "%s%c", t->name, 0);
701  (void) elog_track_register (dst, &newt);
702  vec_free (newt.name);
703  }
704 
705  /* Across all (copied) src events... */
706  for (e = dst->events + l; e < vec_end (dst->events); e++)
707  {
709 
710  /* Remap type from src -> dst. */
711  e->type = find_or_create_type (dst, t);
712 
713  /* Remap string table offsets for 'T' format args */
715  string_table_offset_for_src_events);
716 
717  /* Remap track */
718  e->track += track_offset_for_src_tracks;
719  }
720 
721  /* Adjust event times for relative starting times of event streams. */
722  {
723  f64 dt_event, dt_os_nsec, dt_clock_nsec;
724 
725  /* Set clock parameters if dst was not generated by unserialize. */
726  if (dst->serialize_time.cpu == 0)
727  {
728  dst->init_time = src->init_time;
729  dst->serialize_time = src->serialize_time;
731  }
732 
733  dt_os_nsec =
735 
736  dt_event = dt_os_nsec;
737  dt_clock_nsec =
738  (elog_time_stamp_diff_cpu (&src->init_time, &dst->init_time) * .5 *
739  (dst->nsec_per_cpu_clock + src->nsec_per_cpu_clock));
740 
741  /*
742  * Heuristic to see if src/dst came from same time source.
743  * If frequencies are "the same" and os clock and cpu clock agree
744  * to within 100e-9 secs about time difference between src/dst
745  * init_time, then we use cpu clock. Otherwise we use OS clock.
746  *
747  * When merging event logs from different systems, time paradoxes
748  * at the O(1ms) level are to be expected. Hence, the "align_tweak"
749  * parameter. If two events logged on different processors are known
750  * to occur in a specific order - and with a reasonably-estimated
751  * interval - supply a non-zero "align_tweak" parameter
752  */
753  if (fabs (src->nsec_per_cpu_clock - dst->nsec_per_cpu_clock) < 1e-2
754  && fabs (dt_os_nsec - dt_clock_nsec) < 100)
755  dt_event = dt_clock_nsec;
756 
757  /* Convert to seconds. */
758  dt_event *= 1e-9;
759 
760  /*
761  * Move the earlier set of events later, to avoid creating
762  * events which precede the Big Bang (aka have negative timestamps).
763  *
764  * Not to any scale, we have something like the following picture:
765  *
766  * DST capture start point
767  * ^
768  * +--- dt_event --+
769  * v
770  * SRC capture start point
771  *
772  * In this case dt_event is positive, src started after dst,
773  * to put src events onto a common timebase we have to move them
774  * forward in time. Naturally, the opposite case is
775  * possible, too: dt_event will be negative, and so we have to
776  * move dst events forward in time by the |dt_event|.
777  * In both cases, we add align_tweak.
778  */
779  if (dt_event > 0)
780  {
781  /* Src started after dst. */
782  for (e = dst->events + l; e < vec_end (dst->events); e++)
783  e->time += dt_event + align_tweak;
784  }
785  else
786  {
787  /* Dst started after src. */
788  dt_event = -dt_event;
789  for (e = dst->events + 0; e < dst->events + l; e++)
790  e->time += dt_event + align_tweak;
791  }
792  }
793 
794  /* Sort events by increasing time. */
796 
797  dst->n_total_events = vec_len (dst->events);
798 
799  /* Recreate the event ring or the results won't serialize */
800  {
801  int i;
802 
804 
805  elog_alloc (dst, vec_len (dst->events));
806  for (i = 0; i < vec_len (dst->events); i++)
807  {
808  elog_event_t *es, *ed;
809 
810  es = dst->events + i;
811  ed = dst->event_ring + i;
812 
813  ed[0] = es[0];
814  }
815  }
816 }
817 
818 static void
820 {
821  elog_main_t *em = va_arg (*va, elog_main_t *);
822  elog_event_t *e = va_arg (*va, elog_event_t *);
824  u8 *d = e->data;
825  u8 *p = (u8 *) t->format_args;
826 
827  serialize_integer (m, e->type, sizeof (e->type));
828  serialize_integer (m, e->track, sizeof (e->track));
829  serialize (m, serialize_f64, e->time);
830 
831  while (*p)
832  {
833  uword n_digits, n_bytes = 0;
834 
835  n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
836 
837  switch (p[0])
838  {
839  case 'i':
840  case 't':
841  case 'T':
842  if (n_bytes == 1)
843  serialize_integer (m, d[0], sizeof (u8));
844  else if (n_bytes == 2)
845  serialize_integer (m, clib_mem_unaligned (d, u16), sizeof (u16));
846  else if (n_bytes == 4)
847  serialize_integer (m, clib_mem_unaligned (d, u32), sizeof (u32));
848  else if (n_bytes == 8)
850  else
851  ASSERT (0);
852  break;
853 
854  case 's':
855  serialize_cstring (m, (char *) d);
856  if (n_bytes == 0)
857  n_bytes = strlen ((char *) d) + 1;
858  break;
859 
860  case 'f':
861  if (n_bytes == 4)
863  else if (n_bytes == 8)
865  else
866  ASSERT (0);
867  break;
868 
869  default:
870  ASSERT (0);
871  break;
872  }
873 
874  p += 1 + n_digits;
875  d += n_bytes;
876  }
877 }
878 
879 static void
881 {
882  elog_main_t *em = va_arg (*va, elog_main_t *);
883  elog_event_t *e = va_arg (*va, elog_event_t *);
885  u8 *p, *d;
886 
887  {
888  u16 tmp[2];
889 
890  unserialize_integer (m, &tmp[0], sizeof (e->type));
891  unserialize_integer (m, &tmp[1], sizeof (e->track));
892 
893  e->type = tmp[0];
894  e->track = tmp[1];
895 
896  /* Make sure it fits. */
897  ASSERT (e->type == tmp[0]);
898  ASSERT (e->track == tmp[1]);
899  }
900 
901  t = vec_elt_at_index (em->event_types, e->type);
902 
903  unserialize (m, unserialize_f64, &e->time);
904 
905  d = e->data;
906  p = (u8 *) t->format_args;
907 
908  while (p && *p)
909  {
910  uword n_digits, n_bytes = 0;
911  u32 tmp;
912 
913  n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
914 
915  switch (p[0])
916  {
917  case 'i':
918  case 't':
919  case 'T':
920  if (n_bytes == 1)
921  {
922  unserialize_integer (m, &tmp, sizeof (u8));
923  d[0] = tmp;
924  }
925  else if (n_bytes == 2)
926  {
927  unserialize_integer (m, &tmp, sizeof (u16));
928  clib_mem_unaligned (d, u16) = tmp;
929  }
930  else if (n_bytes == 4)
931  {
932  unserialize_integer (m, &tmp, sizeof (u32));
933  clib_mem_unaligned (d, u32) = tmp;
934  }
935  else if (n_bytes == 8)
936  {
937  u64 x;
938  unserialize (m, unserialize_64, &x);
939  clib_mem_unaligned (d, u64) = x;
940  }
941  else
942  ASSERT (0);
943  break;
944 
945  case 's':
946  {
947  char *t;
948  unserialize_cstring (m, &t);
949  if (n_bytes == 0)
950  n_bytes = strlen (t) + 1;
951  clib_memcpy (d, t, clib_min (n_bytes, vec_len (t)));
952  vec_free (t);
953  break;
954  }
955 
956  case 'f':
957  if (n_bytes == 4)
958  {
959  f32 x;
960  unserialize (m, unserialize_f32, &x);
961  clib_mem_unaligned (d, f32) = x;
962  }
963  else if (n_bytes == 8)
964  {
965  f64 x;
966  unserialize (m, unserialize_f64, &x);
967  clib_mem_unaligned (d, f64) = x;
968  }
969  else
970  ASSERT (0);
971  break;
972 
973  default:
974  ASSERT (0);
975  break;
976  }
977 
978  p += 1 + n_digits;
979  d += n_bytes;
980  }
981 }
982 
983 static void
985 {
986  elog_event_type_t *t = va_arg (*va, elog_event_type_t *);
987  int n = va_arg (*va, int);
988  int i, j;
989  for (i = 0; i < n; i++)
990  {
991  serialize_cstring (m, t[i].format);
992  serialize_cstring (m, t[i].format_args);
993  serialize_integer (m, t[i].type_index_plus_one,
994  sizeof (t->type_index_plus_one));
995  serialize_integer (m, t[i].n_enum_strings,
996  sizeof (t[i].n_enum_strings));
997  for (j = 0; j < t[i].n_enum_strings; j++)
998  serialize_cstring (m, t[i].enum_strings_vector[j]);
999  }
1000 }
1001 
1002 static void
1004 {
1005  elog_event_type_t *t = va_arg (*va, elog_event_type_t *);
1006  int n = va_arg (*va, int);
1007  int i, j;
1008  for (i = 0; i < n; i++)
1009  {
1010  unserialize_cstring (m, &t[i].format);
1011  unserialize_cstring (m, &t[i].format_args);
1012  unserialize_integer (m, &t[i].type_index_plus_one,
1013  sizeof (t->type_index_plus_one));
1014  unserialize_integer (m, &t[i].n_enum_strings,
1015  sizeof (t[i].n_enum_strings));
1016  vec_resize (t[i].enum_strings_vector, t[i].n_enum_strings);
1017  for (j = 0; j < t[i].n_enum_strings; j++)
1018  unserialize_cstring (m, &t[i].enum_strings_vector[j]);
1019  }
1020 }
1021 
1022 static void
1024 {
1025  elog_track_t *t = va_arg (*va, elog_track_t *);
1026  int n = va_arg (*va, int);
1027  int i;
1028  for (i = 0; i < n; i++)
1029  {
1030  serialize_cstring (m, t[i].name);
1031  }
1032 }
1033 
1034 static void
1036 {
1037  elog_track_t *t = va_arg (*va, elog_track_t *);
1038  int n = va_arg (*va, int);
1039  int i;
1040  for (i = 0; i < n; i++)
1041  {
1042  unserialize_cstring (m, &t[i].name);
1043  }
1044 }
1045 
1046 static void
1048 {
1049  elog_time_stamp_t *st = va_arg (*va, elog_time_stamp_t *);
1050  serialize (m, serialize_64, st->os_nsec);
1051  serialize (m, serialize_64, st->cpu);
1052 }
1053 
1054 static void
1056 {
1057  elog_time_stamp_t *st = va_arg (*va, elog_time_stamp_t *);
1058  unserialize (m, unserialize_64, &st->os_nsec);
1059  unserialize (m, unserialize_64, &st->cpu);
1060 }
1061 
1062 static char *elog_serialize_magic = "elog v0";
1063 
1064 void
1066 {
1067  elog_main_t *em = va_arg (*va, elog_main_t *);
1068  int flush_ring = va_arg (*va, int);
1069  elog_event_t *e;
1070 
1072 
1073  serialize_integer (m, em->event_ring_size, sizeof (u32));
1074 
1078 
1082 
1083  /* Free old events (cached) in case they have changed. */
1084  if (flush_ring)
1085  {
1086  vec_free (em->events);
1087  elog_get_events (em);
1088  }
1089 
1090  serialize_integer (m, vec_len (em->events), sizeof (u32));
1091 
1092  /* SMP logs can easily have local time paradoxes... */
1094 
1095  vec_foreach (e, em->events) serialize (m, serialize_elog_event, em, e);
1096 }
1097 
1098 void
1100 {
1101  elog_main_t *em = va_arg (*va, elog_main_t *);
1102  uword i;
1103  u32 rs;
1104 
1106  strlen (elog_serialize_magic));
1107 
1108  unserialize_integer (m, &rs, sizeof (u32));
1109  em->event_ring_size = rs;
1110  elog_init (em, em->event_ring_size);
1111 
1115 
1117  for (i = 0; i < vec_len (em->event_types); i++)
1118  new_event_type (em, i);
1119 
1122 
1123  {
1124  u32 ne;
1125  elog_event_t *e;
1126 
1127  unserialize_integer (m, &ne, sizeof (u32));
1128  vec_resize (em->events, ne);
1129  vec_foreach (e, em->events)
1130  unserialize (m, unserialize_elog_event, em, e);
1131  }
1132 }
1133 
1134 /*
1135  * fd.io coding-style-patch-verification: ON
1136  *
1137  * Local Variables:
1138  * eval: (c-set-style "gnu")
1139  * End:
1140  */
char ** enum_strings_vector
String table as a vector constructed when type is registered.
Definition: elog.h:88
f64 time
Absolute time as floating point number in seconds.
Definition: elog.h:66
elog_time_stamp_t serialize_time
Definition: elog.h:169
vl_api_address_t src
Definition: vxlan_gbp.api:32
#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:579
static void maybe_fix_string_table_offset(elog_event_t *e, elog_event_type_t *t, u32 offset)
Definition: elog.c:587
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:169
#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:63
#define vec_add1(V, E)
Add 1 element to end of vector (unspecified alignment).
Definition: vec.h:525
static u64 clib_cpu_time_now(void)
Definition: time.h:75
char * function
Function name generating event.
Definition: elog.h:103
#define vec_add2(V, P, N)
Add N elements to end of vector V, return pointer to new elements in P.
Definition: vec.h:564
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:46
u8 * format(u8 *s, const char *fmt,...)
Definition: format.c:419
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:1065
u8 * format_elog_event(u8 *s, va_list *va)
Definition: elog.c:296
char * format
Format string.
Definition: elog.h:91
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:78
static void serialize_elog_time_stamp(serialize_main_t *m, va_list *va)
Definition: elog.c:1047
char * enum_strings[]
String table for enum/number to string formatting.
Definition: elog.h:109
double f64
Definition: types.h:142
static void unserialize_elog_event_type(serialize_main_t *m, va_list *va)
Definition: elog.c:1003
#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:602
void unserialize_elog_main(serialize_main_t *m, va_list *va)
Definition: elog.c:1099
u32 n_enum_strings
Number of elements in string enum table.
Definition: elog.h:106
serialize_function_t unserialize_f32
Definition: serialize.h:359
static void unserialize_elog_event(serialize_main_t *m, va_list *va)
Definition: elog.c:880
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:85
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:1055
#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:172
static uword elog_event_range(elog_main_t *em, uword *lo)
Definition: elog.c:515
char * format_args
Specifies how arguments to format are parsed from event data.
Definition: elog.h:100
#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:154
#define clib_atomic_test_and_set(a)
Definition: atomics.h:40
static int elog_cmp(void *a1, void *a2)
Definition: elog.c:634
elog_event_type_t * event_types
Vector of event types.
Definition: elog.h:151
static uword parse_2digit_decimal(char *p, uword *number)
Definition: elog.c:222
lo
static char * elog_serialize_magic
Definition: elog.c:1062
unsigned short u16
Definition: types.h:57
signed long i64
Definition: types.h:78
char * name
Track name vector.
Definition: elog.h:115
elog_event_t * event_ring
Vector of events (circular buffer).
Definition: elog.h:148
static void serialize_elog_event_type(serialize_main_t *m, va_list *va)
Definition: elog.c:984
#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:176
f64 seconds_per_clock
Definition: time.h:57
static void unserialize_elog_track(serialize_main_t *m, va_list *va)
Definition: elog.c:1035
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
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
vl_api_address_t dst
Definition: vxlan_gbp.api:33
#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:819
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:119
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:138
static void serialize_elog_track(serialize_main_t *m, va_list *va)
Definition: elog.c:1023
u64 os_nsec
OS timer in nano secs since epoch 3/30/2017, see elog_time_now()
Definition: elog.h:128
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:144
u64 cpu
CPU cycle counter.
Definition: elog.h:125
clib_error_t * unserialize(serialize_main_t *m,...)
Definition: serialize.c:684
#define vec_append(v1, v2)
Append v2 after v1.
Definition: vec.h:822
u16 track
Track for this event.
Definition: elog.h:75
#define clib_mem_unaligned(pointer, type)
Definition: types.h:155
clib_time_t cpu_timer
Place holder for CPU clock frequency.
Definition: elog.h:166
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:179
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:561
#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:70
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:984
void * elog_event_data(elog_main_t *em, elog_event_type_t *type, elog_track_t *track, u64 cpu_time)
Definition: elog.c:65
elog_track_t * tracks
Vector of tracks.
Definition: elog.h:160
#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:157
#define vec_foreach(var, vec)
Vector iterator.
elog_track_t default_track
Default track.
Definition: elog.h:163
#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:652
u32 n_total_events
Total number of events in buffer.
Definition: elog.h:134
#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:290
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:536
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