FD.io VPP  v18.07.1-19-g511ce25
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 (__sync_lock_test_and_set (em->lock, 1))
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 (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 void
409 {
410  u64 cpu_time_now, os_time_now_nsec;
411  struct timespec ts;
412 
413 #ifdef CLIB_UNIX
414  {
415 #include <sys/syscall.h>
416  syscall (SYS_clock_gettime, CLOCK_REALTIME, &ts);
417  cpu_time_now = clib_cpu_time_now ();
418  /* Subtract 3/30/2017's worth of seconds to retain precision */
419  os_time_now_nsec = 1e9 * (ts.tv_sec - 1490885108) + ts.tv_nsec;
420  }
421 #else
422  cpu_time_now = clib_cpu_time_now ();
423  os_time_now_nsec = 0;
424 #endif
425 
426  et->cpu = cpu_time_now;
427  et->os_nsec = os_time_now_nsec;
428 }
429 
432 {
433  return (i64) t1->os_nsec - (i64) t2->os_nsec;
434 }
435 
438 {
439  return (i64) t1->cpu - (i64) t2->cpu;
440 }
441 
444 {
446  &em->init_time)
448  &em->init_time));
449 }
450 
451 void
452 elog_alloc (elog_main_t * em, u32 n_events)
453 {
454  if (em->event_ring)
455  vec_free (em->event_ring);
456 
457  /* Ring size must be a power of 2. */
458  em->event_ring_size = n_events = max_pow2 (n_events);
459 
460  /* Leave an empty ievent at end so we can always speculatively write
461  and event there (possibly a long form event). */
463 }
464 
465 void
466 elog_init (elog_main_t * em, u32 n_events)
467 {
468  memset (em, 0, sizeof (em[0]));
469 
470  em->lock = 0;
471 
472  if (n_events > 0)
473  elog_alloc (em, n_events);
474 
475  clib_time_init (&em->cpu_timer);
476 
478 
479  /* Make track 0. */
480  em->default_track.name = "default";
482 
483  elog_time_now (&em->init_time);
484 }
485 
486 /* Returns number of events in ring and start index. */
487 static uword
489 {
490  uword l = em->event_ring_size;
491  u64 i = em->n_total_events;
492 
493  /* Ring never wrapped? */
494  if (i <= (u64) l)
495  {
496  if (lo)
497  *lo = 0;
498  return i;
499  }
500  else
501  {
502  if (lo)
503  *lo = i & (l - 1);
504  return l;
505  }
506 }
507 
508 elog_event_t *
510 {
511  elog_event_t *e, *f, *es = 0;
512  uword i, j, n;
513 
514  n = elog_event_range (em, &j);
515  for (i = 0; i < n; i++)
516  {
517  vec_add2 (es, e, 1);
518  f = vec_elt_at_index (em->event_ring, j);
519  e[0] = f[0];
520 
521  /* Convert absolute time from cycles to seconds from start. */
522  e->time =
523  (e->time_cycles -
525 
526  j = (j + 1) & (em->event_ring_size - 1);
527  }
528 
529  return es;
530 }
531 
532 /* Add a formatted string to the string table. */
533 u32
534 elog_string (elog_main_t * em, char *fmt, ...)
535 {
536  u32 offset;
537  va_list va;
538 
539  va_start (va, fmt);
540  offset = vec_len (em->string_table);
541  em->string_table = (char *) va_format ((u8 *) em->string_table, fmt, &va);
542  va_end (va);
543 
544  /* Null terminate string if it is not already. */
545  if (vec_end (em->string_table)[-1] != 0)
546  vec_add1 (em->string_table, 0);
547 
548  return offset;
549 }
550 
551 elog_event_t *
553 {
554  if (!em->events)
555  em->events = elog_peek_events (em);
556  return em->events;
557 }
558 
559 static void
562 {
563  void *d = (u8 *) e->data;
564  char *a;
565 
566  if (offset == 0)
567  return;
568 
569  a = t->format_args;
570 
571  while (1)
572  {
573  uword n_bytes = 0, n_digits;
574 
575  if (a[0] == 0)
576  break;
577 
578  /* Don't go past end of event data. */
579  ASSERT (d < (void *) (e->data + sizeof (e->data)));
580 
581  n_digits = parse_2digit_decimal (a + 1, &n_bytes);
582  switch (a[0])
583  {
584  case 'T':
585  ASSERT (n_bytes == 4);
586  clib_mem_unaligned (d, u32) += offset;
587  break;
588 
589  case 'i':
590  case 't':
591  case 'f':
592  case 's':
593  break;
594 
595  default:
596  ASSERT (0);
597  break;
598  }
599 
600  ASSERT (n_digits > 0 && n_digits <= 2);
601  a += 1 + n_digits;
602  d += n_bytes;
603  }
604 }
605 
606 static int
607 elog_cmp (void *a1, void *a2)
608 {
609  elog_event_t *e1 = a1;
610  elog_event_t *e2 = a2;
611 
612  if (e1->time < e2->time)
613  return -1;
614 
615  if (e1->time > e2->time)
616  return 1;
617 
618  return 0;
619 }
620 
621 /*
622  * merge two event logs. Complicated and cranky.
623  */
624 void
625 elog_merge (elog_main_t * dst, u8 * dst_tag, elog_main_t * src, u8 * src_tag,
626  f64 align_tweak)
627 {
628  elog_event_t *e;
629  uword l;
630  u32 string_table_offset_for_src_events;
631  u32 track_offset_for_src_tracks;
632  elog_track_t newt;
633  int i;
634 
635  memset (&newt, 0, sizeof (newt));
636 
637  /* Acquire src and dst events */
638  elog_get_events (src);
639  elog_get_events (dst);
640 
641  string_table_offset_for_src_events = vec_len (dst->string_table);
642  vec_append (dst->string_table, src->string_table);
643 
644  l = vec_len (dst->events);
645  vec_append (dst->events, src->events);
646 
647  /* Prepend the supplied tag (if any) to all dst track names */
648  if (dst_tag)
649  {
650  for (i = 0; i < vec_len (dst->tracks); i++)
651  {
652  elog_track_t *t = vec_elt_at_index (dst->tracks, i);
653  char *new_name;
654 
655  new_name = (char *) format (0, "%s:%s%c", dst_tag, t->name, 0);
656  vec_free (t->name);
657  t->name = new_name;
658  }
659  }
660 
661  /*
662  * Remember where we started allocating new tracks while merging
663  */
664  track_offset_for_src_tracks = vec_len (dst->tracks);
665 
666  /* Copy / tag source tracks */
667  for (i = 0; i < vec_len (src->tracks); i++)
668  {
669  elog_track_t *t = vec_elt_at_index (src->tracks, i);
670  if (src_tag)
671  newt.name = (char *) format (0, "%s:%s%c", src_tag, t->name, 0);
672  else
673  newt.name = (char *) format (0, "%s%c", t->name, 0);
674  (void) elog_track_register (dst, &newt);
675  vec_free (newt.name);
676  }
677 
678  /* Across all (copied) src events... */
679  for (e = dst->events + l; e < vec_end (dst->events); e++)
680  {
682 
683  /* Remap type from src -> dst. */
684  e->type = find_or_create_type (dst, t);
685 
686  /* Remap string table offsets for 'T' format args */
688  string_table_offset_for_src_events);
689 
690  /* Remap track */
691  e->track += track_offset_for_src_tracks;
692  }
693 
694  /* Adjust event times for relative starting times of event streams. */
695  {
696  f64 dt_event, dt_os_nsec, dt_clock_nsec;
697 
698  /* Set clock parameters if dst was not generated by unserialize. */
699  if (dst->serialize_time.cpu == 0)
700  {
701  dst->init_time = src->init_time;
702  dst->serialize_time = src->serialize_time;
704  }
705 
706  dt_os_nsec =
708 
709  dt_event = dt_os_nsec;
710  dt_clock_nsec =
711  (elog_time_stamp_diff_cpu (&src->init_time, &dst->init_time) * .5 *
712  (dst->nsec_per_cpu_clock + src->nsec_per_cpu_clock));
713 
714  /*
715  * Heuristic to see if src/dst came from same time source.
716  * If frequencies are "the same" and os clock and cpu clock agree
717  * to within 100e-9 secs about time difference between src/dst
718  * init_time, then we use cpu clock. Otherwise we use OS clock.
719  *
720  * When merging event logs from different systems, time paradoxes
721  * at the O(1ms) level are to be expected. Hence, the "align_tweak"
722  * parameter. If two events logged on different processors are known
723  * to occur in a specific order - and with a reasonably-estimated
724  * interval - supply a non-zero "align_tweak" parameter
725  */
726  if (fabs (src->nsec_per_cpu_clock - dst->nsec_per_cpu_clock) < 1e-2
727  && fabs (dt_os_nsec - dt_clock_nsec) < 100)
728  dt_event = dt_clock_nsec;
729 
730  /* Convert to seconds. */
731  dt_event *= 1e-9;
732 
733  /*
734  * Move the earlier set of events later, to avoid creating
735  * events which preceed the Big Bang (aka have negative timestamps).
736  *
737  * Not to any scale, we have something like the following picture:
738  *
739  * DST capture start point
740  * ^
741  * +--- dt_event --+
742  * v
743  * SRC capture start point
744  *
745  * In this case dt_event is positive, src started after dst,
746  * to put src events onto a common timebase we have to move them
747  * forward in time. Naturally, the opposite case is
748  * possible, too: dt_event will be negative, and so we have to
749  * move dst events forward in time by the |dt_event|.
750  * In both cases, we add align_tweak.
751  */
752  if (dt_event > 0)
753  {
754  /* Src started after dst. */
755  for (e = dst->events + l; e < vec_end (dst->events); e++)
756  e->time += dt_event + align_tweak;
757  }
758  else
759  {
760  /* Dst started after src. */
761  dt_event = -dt_event;
762  for (e = dst->events + 0; e < dst->events + l; e++)
763  e->time += dt_event + align_tweak;
764  }
765  }
766 
767  /* Sort events by increasing time. */
769 
770  dst->n_total_events = vec_len (dst->events);
771 
772  /* Recreate the event ring or the results won't serialize */
773  {
774  int i;
775 
777 
778  elog_alloc (dst, vec_len (dst->events));
779  for (i = 0; i < vec_len (dst->events); i++)
780  {
781  elog_event_t *es, *ed;
782 
783  es = dst->events + i;
784  ed = dst->event_ring + i;
785 
786  ed[0] = es[0];
787  }
788  }
789 }
790 
791 static void
793 {
794  elog_main_t *em = va_arg (*va, elog_main_t *);
795  elog_event_t *e = va_arg (*va, elog_event_t *);
797  u8 *d = e->data;
798  u8 *p = (u8 *) t->format_args;
799 
800  serialize_integer (m, e->type, sizeof (e->type));
801  serialize_integer (m, e->track, sizeof (e->track));
802  serialize (m, serialize_f64, e->time);
803 
804  while (*p)
805  {
806  uword n_digits, n_bytes = 0;
807 
808  n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
809 
810  switch (p[0])
811  {
812  case 'i':
813  case 't':
814  case 'T':
815  if (n_bytes == 1)
816  serialize_integer (m, d[0], sizeof (u8));
817  else if (n_bytes == 2)
818  serialize_integer (m, clib_mem_unaligned (d, u16), sizeof (u16));
819  else if (n_bytes == 4)
820  serialize_integer (m, clib_mem_unaligned (d, u32), sizeof (u32));
821  else if (n_bytes == 8)
823  else
824  ASSERT (0);
825  break;
826 
827  case 's':
828  serialize_cstring (m, (char *) d);
829  if (n_bytes == 0)
830  n_bytes = strlen ((char *) d) + 1;
831  break;
832 
833  case 'f':
834  if (n_bytes == 4)
836  else if (n_bytes == 8)
838  else
839  ASSERT (0);
840  break;
841 
842  default:
843  ASSERT (0);
844  break;
845  }
846 
847  p += 1 + n_digits;
848  d += n_bytes;
849  }
850 }
851 
852 static void
854 {
855  elog_main_t *em = va_arg (*va, elog_main_t *);
856  elog_event_t *e = va_arg (*va, elog_event_t *);
858  u8 *p, *d;
859 
860  {
861  u16 tmp[2];
862 
863  unserialize_integer (m, &tmp[0], sizeof (e->type));
864  unserialize_integer (m, &tmp[1], sizeof (e->track));
865 
866  e->type = tmp[0];
867  e->track = tmp[1];
868 
869  /* Make sure it fits. */
870  ASSERT (e->type == tmp[0]);
871  ASSERT (e->track == tmp[1]);
872  }
873 
874  t = vec_elt_at_index (em->event_types, e->type);
875 
876  unserialize (m, unserialize_f64, &e->time);
877 
878  d = e->data;
879  p = (u8 *) t->format_args;
880 
881  while (p && *p)
882  {
883  uword n_digits, n_bytes = 0;
884  u32 tmp;
885 
886  n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
887 
888  switch (p[0])
889  {
890  case 'i':
891  case 't':
892  case 'T':
893  if (n_bytes == 1)
894  {
895  unserialize_integer (m, &tmp, sizeof (u8));
896  d[0] = tmp;
897  }
898  else if (n_bytes == 2)
899  {
900  unserialize_integer (m, &tmp, sizeof (u16));
901  clib_mem_unaligned (d, u16) = tmp;
902  }
903  else if (n_bytes == 4)
904  {
905  unserialize_integer (m, &tmp, sizeof (u32));
906  clib_mem_unaligned (d, u32) = tmp;
907  }
908  else if (n_bytes == 8)
909  {
910  u64 x;
911  unserialize (m, unserialize_64, &x);
912  clib_mem_unaligned (d, u64) = x;
913  }
914  else
915  ASSERT (0);
916  break;
917 
918  case 's':
919  {
920  char *t;
921  unserialize_cstring (m, &t);
922  if (n_bytes == 0)
923  n_bytes = strlen (t) + 1;
924  clib_memcpy (d, t, clib_min (n_bytes, vec_len (t)));
925  vec_free (t);
926  break;
927  }
928 
929  case 'f':
930  if (n_bytes == 4)
931  {
932  f32 x;
933  unserialize (m, unserialize_f32, &x);
934  clib_mem_unaligned (d, f32) = x;
935  }
936  else if (n_bytes == 8)
937  {
938  f64 x;
939  unserialize (m, unserialize_f64, &x);
940  clib_mem_unaligned (d, f64) = x;
941  }
942  else
943  ASSERT (0);
944  break;
945 
946  default:
947  ASSERT (0);
948  break;
949  }
950 
951  p += 1 + n_digits;
952  d += n_bytes;
953  }
954 }
955 
956 static void
958 {
959  elog_event_type_t *t = va_arg (*va, elog_event_type_t *);
960  int n = va_arg (*va, int);
961  int i, j;
962  for (i = 0; i < n; i++)
963  {
964  serialize_cstring (m, t[i].format);
965  serialize_cstring (m, t[i].format_args);
966  serialize_integer (m, t[i].type_index_plus_one,
967  sizeof (t->type_index_plus_one));
968  serialize_integer (m, t[i].n_enum_strings,
969  sizeof (t[i].n_enum_strings));
970  for (j = 0; j < t[i].n_enum_strings; j++)
971  serialize_cstring (m, t[i].enum_strings_vector[j]);
972  }
973 }
974 
975 static void
977 {
978  elog_event_type_t *t = va_arg (*va, elog_event_type_t *);
979  int n = va_arg (*va, int);
980  int i, j;
981  for (i = 0; i < n; i++)
982  {
983  unserialize_cstring (m, &t[i].format);
984  unserialize_cstring (m, &t[i].format_args);
985  unserialize_integer (m, &t[i].type_index_plus_one,
986  sizeof (t->type_index_plus_one));
987  unserialize_integer (m, &t[i].n_enum_strings,
988  sizeof (t[i].n_enum_strings));
989  vec_resize (t[i].enum_strings_vector, t[i].n_enum_strings);
990  for (j = 0; j < t[i].n_enum_strings; j++)
991  unserialize_cstring (m, &t[i].enum_strings_vector[j]);
992  }
993 }
994 
995 static void
997 {
998  elog_track_t *t = va_arg (*va, elog_track_t *);
999  int n = va_arg (*va, int);
1000  int i;
1001  for (i = 0; i < n; i++)
1002  {
1003  serialize_cstring (m, t[i].name);
1004  }
1005 }
1006 
1007 static void
1009 {
1010  elog_track_t *t = va_arg (*va, elog_track_t *);
1011  int n = va_arg (*va, int);
1012  int i;
1013  for (i = 0; i < n; i++)
1014  {
1015  unserialize_cstring (m, &t[i].name);
1016  }
1017 }
1018 
1019 static void
1021 {
1022  elog_time_stamp_t *st = va_arg (*va, elog_time_stamp_t *);
1023  serialize (m, serialize_64, st->os_nsec);
1024  serialize (m, serialize_64, st->cpu);
1025 }
1026 
1027 static void
1029 {
1030  elog_time_stamp_t *st = va_arg (*va, elog_time_stamp_t *);
1031  unserialize (m, unserialize_64, &st->os_nsec);
1032  unserialize (m, unserialize_64, &st->cpu);
1033 }
1034 
1035 static char *elog_serialize_magic = "elog v0";
1036 
1037 void
1039 {
1040  elog_main_t *em = va_arg (*va, elog_main_t *);
1041  int flush_ring = va_arg (*va, int);
1042  elog_event_t *e;
1043 
1045 
1046  serialize_integer (m, em->event_ring_size, sizeof (u32));
1047 
1051 
1055 
1056  /* Free old events (cached) in case they have changed. */
1057  if (flush_ring)
1058  {
1059  vec_free (em->events);
1060  elog_get_events (em);
1061  }
1062 
1063  serialize_integer (m, vec_len (em->events), sizeof (u32));
1064 
1065  /* SMP logs can easily have local time paradoxes... */
1067 
1068  vec_foreach (e, em->events) serialize (m, serialize_elog_event, em, e);
1069 }
1070 
1071 void
1073 {
1074  elog_main_t *em = va_arg (*va, elog_main_t *);
1075  uword i;
1076  u32 rs;
1077 
1079  strlen (elog_serialize_magic));
1080 
1081  unserialize_integer (m, &rs, sizeof (u32));
1082  em->event_ring_size = rs;
1083  elog_init (em, em->event_ring_size);
1084 
1088 
1090  for (i = 0; i < vec_len (em->event_types); i++)
1091  new_event_type (em, i);
1092 
1095 
1096  {
1097  u32 ne;
1098  elog_event_t *e;
1099 
1100  unserialize_integer (m, &ne, sizeof (u32));
1101  vec_resize (em->events, ne);
1102  vec_foreach (e, em->events)
1103  unserialize (m, unserialize_elog_event, em, e);
1104  }
1105 }
1106 
1107 /*
1108  * fd.io coding-style-patch-verification: ON
1109  *
1110  * Local Variables:
1111  * eval: (c-set-style "gnu")
1112  * End:
1113  */
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
#define clib_min(x, y)
Definition: clib.h:289
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:552
static void maybe_fix_string_table_offset(elog_event_t *e, elog_event_type_t *t, u32 offset)
Definition: elog.c:560
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:431
void elog_time_now(elog_time_stamp_t *et)
Definition: elog.c:408
#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:523
static u64 clib_cpu_time_now(void)
Definition: time.h:73
u8 * format_elog_track(u8 *s, va_list *va)
Definition: elog.c:399
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:562
int i
#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: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:1038
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:1020
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:976
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:600
void unserialize_elog_main(serialize_main_t *m, va_list *va)
Definition: elog.c:1072
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:853
i64 word
Definition: types.h:111
void elog_init(elog_main_t *em, u32 n_events)
Definition: elog.c:466
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:92
u32 type_index_plus_one
Type index plus one assigned to this type.
Definition: elog.h:85
static i64 elog_time_stamp_diff_cpu(elog_time_stamp_t *t1, elog_time_stamp_t *t2)
Definition: elog.c:437
static void unserialize_elog_time_stamp(serialize_main_t *m, va_list *va)
Definition: elog.c:1028
#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:488
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:240
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
static int elog_cmp(void *a1, void *a2)
Definition: elog.c:607
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:1035
unsigned short u16
Definition: types.h:57
signed long i64
Definition: types.h:82
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:957
#define PREDICT_FALSE(x)
Definition: clib.h:105
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:1008
void clib_time_init(clib_time_t *c)
Definition: time.c:178
void elog_alloc(elog_main_t *em, u32 n_events)
Definition: elog.c:452
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
#define vec_free(V)
Free vector&#39;s memory (no header).
Definition: vec.h:339
static f64 elog_nsec_per_clock(elog_main_t *em)
Definition: elog.c:443
static f64 fabs(f64 x)
Definition: math.h:50
#define clib_memcpy(a, b, c)
Definition: string.h:75
static void serialize_elog_event(serialize_main_t *m, va_list *va)
Definition: elog.c:792
static uword max_pow2(uword x)
Definition: clib.h:220
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:996
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:820
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:534
#define vec_len(v)
Number of elements in vector (rvalue-only, NULL tolerant)
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:982
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:109
void elog_merge(elog_main_t *dst, u8 *dst_tag, elog_main_t *src, u8 *src_tag, f64 align_tweak)
Definition: elog.c:625
u32 n_total_events
Total number of events in buffer.
Definition: elog.h:134
#define CLIB_CACHE_LINE_BYTES
Definition: cache.h:62
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:509
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:253