FD.io VPP  v21.06-1-gbb7418cf9
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 __clib_export 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 __clib_export 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
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 __clib_export 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 
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 __clib_export 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 __clib_export 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,
424  e->time + dt, format_elog_event, em, e);
425  }
426  vec_free (es);
427  return s;
428 }
429 
430 __clib_export char *
431 format_one_elog_event (void *em_arg, void *ep_arg)
432 {
433  elog_main_t *em = (elog_main_t *) em_arg;
434  elog_event_t *ep = (elog_event_t *) ep_arg;
435 
436  return (char *) format (0, "%U", format_elog_event, em, ep);
437 }
438 
439 void
441 {
442  u64 cpu_time_now, os_time_now_nsec;
443  struct timespec ts;
444 
445 #ifdef CLIB_UNIX
446  {
447 #include <sys/syscall.h>
448 #ifdef __APPLE__
449  clock_gettime (CLOCK_REALTIME, &ts);
450 #else
451  syscall (SYS_clock_gettime, CLOCK_REALTIME, &ts);
452 #endif
453  cpu_time_now = clib_cpu_time_now ();
454  /* Subtract 3/30/2017's worth of seconds to retain precision */
455  os_time_now_nsec = 1e9 * (ts.tv_sec - 1490885108) + ts.tv_nsec;
456  }
457 #else
458  cpu_time_now = clib_cpu_time_now ();
459  os_time_now_nsec = 0;
460 #endif
461 
462  et->cpu = cpu_time_now;
463  et->os_nsec = os_time_now_nsec;
464 }
465 
468 {
469  return (i64) t1->os_nsec - (i64) t2->os_nsec;
470 }
471 
474 {
475  return (i64) t1->cpu - (i64) t2->cpu;
476 }
477 
480 {
482  &em->init_time)
484  &em->init_time));
485 }
486 
487 static void
488 elog_alloc_internal (elog_main_t * em, u32 n_events, int free_ring)
489 {
490  if (free_ring && em->event_ring)
491  vec_free (em->event_ring);
492 
493  /* Ring size must be a power of 2. */
494  em->event_ring_size = n_events = max_pow2 (n_events);
495 
497  _vec_len (em->event_ring) = n_events;
498 }
499 
500 __clib_export void
501 elog_alloc (elog_main_t * em, u32 n_events)
502 {
503  elog_alloc_internal (em, n_events, 1 /* free ring */ );
504 }
505 
506 __clib_export void
507 elog_resize (elog_main_t * em, u32 n_events)
508 {
509  elog_alloc_internal (em, n_events, 0 /* do not free ring */ );
510 }
511 
512 __clib_export void
513 elog_init (elog_main_t * em, u32 n_events)
514 {
515  clib_memset (em, 0, sizeof (em[0]));
516 
517  em->lock = 0;
518 
519  if (n_events > 0)
520  elog_alloc (em, n_events);
521 
522  clib_time_init (&em->cpu_timer);
523 
525 
526  /* Make track 0. */
527  em->default_track.name = "default";
529 
530  elog_time_now (&em->init_time);
531  em->string_table_hash = hash_create_string (0, sizeof (uword));
532 }
533 
534 /* Returns number of events in ring and start index. */
535 static uword
537 {
538  uword l = em->event_ring_size;
539  u64 i = em->n_total_events;
540 
541  /* Ring never wrapped? */
542  if (i <= (u64) l)
543  {
544  if (lo)
545  *lo = 0;
546  return i;
547  }
548  else
549  {
550  if (lo)
551  *lo = i & (l - 1);
552  return l;
553  }
554 }
555 
556 __clib_export elog_event_t *
558 {
559  elog_event_t *e, *f, *es = 0;
560  uword i, j, n;
561 
562  n = elog_event_range (em, &j);
563  for (i = 0; i < n; i++)
564  {
565  vec_add2 (es, e, 1);
566  f = vec_elt_at_index (em->event_ring, j);
567  e[0] = f[0];
568 
569  /* Convert absolute time from cycles to seconds from start. */
570  e->time =
571  (e->time_cycles -
573 
574  j = (j + 1) & (em->event_ring_size - 1);
575  }
576 
577  return es;
578 }
579 
580 /* Add a formatted string to the string table. */
581 __clib_export u32
582 elog_string (elog_main_t * em, char *fmt, ...)
583 {
584  u32 offset;
585  uword *p;
586  uword len;
587  va_list va;
588 
589  elog_lock (em);
591  va_start (va, fmt);
592  em->string_table_tmp = va_format (em->string_table_tmp, fmt, &va);
593  va_end (va);
594 
595  /* String table entries MUST be NULL terminated */
596  len = vec_len (em->string_table_tmp);
597  ASSERT (len > 0);
598  if (em->string_table_tmp[len - 1] != 0)
599  vec_add1 (em->string_table_tmp, 0);
600 
601  /* See if we already have this string in the string table */
603 
604  /* We already have the string, so give the caller its offset */
605  if (p)
606  {
607  elog_unlock (em);
608  return (p[0]);
609  }
610 
611  /* We don't, so add it. */
612 
613  offset = vec_len (em->string_table);
615 
617 
618  /* We gave the key to the string table hash, so we can't reuse it! */
619  em->string_table_tmp = 0;
620  elog_unlock (em);
621 
622  return offset;
623 }
624 
625 __clib_export elog_event_t *
627 {
628  vec_free (em->events);
629  em->events = elog_peek_events (em);
630  return em->events;
631 }
632 
633 static void
636 {
637  void *d = (u8 *) e->data;
638  char *a;
639 
640  if (offset == 0)
641  return;
642 
643  a = t->format_args;
644 
645  while (1)
646  {
647  uword n_bytes = 0, n_digits;
648 
649  if (a[0] == 0)
650  break;
651 
652  /* Don't go past end of event data. */
653  ASSERT (d < (void *) (e->data + sizeof (e->data)));
654 
655  n_digits = parse_2digit_decimal (a + 1, &n_bytes);
656  switch (a[0])
657  {
658  case 'T':
659  ASSERT (n_bytes == 4);
660  clib_mem_unaligned (d, u32) += offset;
661  break;
662 
663  case 'i':
664  case 't':
665  case 'f':
666  case 's':
667  break;
668 
669  default:
670  ASSERT (0);
671  break;
672  }
673 
674  ASSERT (n_digits > 0 && n_digits <= 2);
675  a += 1 + n_digits;
676  d += n_bytes;
677  }
678 }
679 
680 static int
681 elog_cmp (void *a1, void *a2)
682 {
683  elog_event_t *e1 = a1;
684  elog_event_t *e2 = a2;
685 
686  if (e1->time < e2->time)
687  return -1;
688 
689  if (e1->time > e2->time)
690  return 1;
691 
692  return 0;
693 }
694 
695 /*
696  * merge two event logs. Complicated and cranky.
697  */
698 __clib_export void
699 elog_merge (elog_main_t *dst, u8 *dst_tag, elog_main_t *src, u8 *src_tag,
700  f64 align_tweak)
701 {
702  elog_event_t *e;
703  uword l;
704  u32 string_table_offset_for_src_events;
705  u32 track_offset_for_src_tracks;
706  elog_track_t newt;
707  int i;
708 
709  clib_memset (&newt, 0, sizeof (newt));
710 
711  /* Acquire src and dst events */
712  elog_get_events (src);
713  elog_get_events (dst);
714 
715  string_table_offset_for_src_events = vec_len (dst->string_table);
716  vec_append (dst->string_table, src->string_table);
717 
718  l = vec_len (dst->events);
719  vec_append (dst->events, src->events);
720 
721  /* Prepend the supplied tag (if any) to all dst track names */
722  if (dst_tag)
723  {
724  for (i = 0; i < vec_len (dst->tracks); i++)
725  {
726  elog_track_t *t = vec_elt_at_index (dst->tracks, i);
727  char *new_name;
728 
729  new_name = (char *) format (0, "%s:%s%c", dst_tag, t->name, 0);
730  vec_free (t->name);
731  t->name = new_name;
732  }
733  }
734 
735  /*
736  * Remember where we started allocating new tracks while merging
737  */
738  track_offset_for_src_tracks = vec_len (dst->tracks);
739 
740  /* Copy / tag source tracks */
741  for (i = 0; i < vec_len (src->tracks); i++)
742  {
743  elog_track_t *t = vec_elt_at_index (src->tracks, i);
744  if (src_tag)
745  newt.name = (char *) format (0, "%s:%s%c", src_tag, t->name, 0);
746  else
747  newt.name = (char *) format (0, "%s%c", t->name, 0);
748  (void) elog_track_register (dst, &newt);
749  vec_free (newt.name);
750  }
751 
752  /* Across all (copied) src events... */
753  for (e = dst->events + l; e < vec_end (dst->events); e++)
754  {
755  elog_event_type_t *t =
757 
758  /* Remap type from src -> dst. */
759  e->event_type = find_or_create_type (dst, t);
760 
761  /* Remap string table offsets for 'T' format args */
763  string_table_offset_for_src_events);
764 
765  /* Remap track */
766  e->track += track_offset_for_src_tracks;
767  }
768 
769  /* Adjust event times for relative starting times of event streams. */
770  {
771  f64 dt_event, dt_os_nsec, dt_clock_nsec;
772 
773  /* Set clock parameters if dst was not generated by unserialize. */
774  if (dst->serialize_time.cpu == 0)
775  {
776  dst->init_time = src->init_time;
777  dst->serialize_time = src->serialize_time;
779  }
780 
781  dt_os_nsec =
783 
784  dt_event = dt_os_nsec;
785  dt_clock_nsec =
786  (elog_time_stamp_diff_cpu (&src->init_time, &dst->init_time) * .5 *
787  (dst->nsec_per_cpu_clock + src->nsec_per_cpu_clock));
788 
789  /*
790  * Heuristic to see if src/dst came from same time source.
791  * If frequencies are "the same" and os clock and cpu clock agree
792  * to within 100e-9 secs about time difference between src/dst
793  * init_time, then we use cpu clock. Otherwise we use OS clock.
794  *
795  * When merging event logs from different systems, time paradoxes
796  * at the O(1ms) level are to be expected. Hence, the "align_tweak"
797  * parameter. If two events logged on different processors are known
798  * to occur in a specific order - and with a reasonably-estimated
799  * interval - supply a non-zero "align_tweak" parameter
800  */
801  if (fabs (src->nsec_per_cpu_clock - dst->nsec_per_cpu_clock) < 1e-2
802  && fabs (dt_os_nsec - dt_clock_nsec) < 100)
803  dt_event = dt_clock_nsec;
804 
805  /* Convert to seconds. */
806  dt_event *= 1e-9;
807 
808  /*
809  * Move the earlier set of events later, to avoid creating
810  * events which precede the Big Bang (aka have negative timestamps).
811  *
812  * Not to any scale, we have something like the following picture:
813  *
814  * DST capture start point
815  * ^
816  * +--- dt_event --+
817  * v
818  * SRC capture start point
819  *
820  * In this case dt_event is positive, src started after dst,
821  * to put src events onto a common timebase we have to move them
822  * forward in time. Naturally, the opposite case is
823  * possible, too: dt_event will be negative, and so we have to
824  * move dst events forward in time by the |dt_event|.
825  * In both cases, we add align_tweak.
826  */
827  if (dt_event > 0)
828  {
829  /* Src started after dst. */
830  for (e = dst->events + l; e < vec_end (dst->events); e++)
831  e->time += dt_event + align_tweak;
832  }
833  else
834  {
835  /* Dst started after src. */
836  dt_event = -dt_event;
837  for (e = dst->events + 0; e < dst->events + l; e++)
838  e->time += dt_event + align_tweak;
839  }
840  }
841 
842  /* Sort events by increasing time. */
844 
845  dst->n_total_events = vec_len (dst->events);
846 
847  /* Recreate the event ring or the results won't serialize */
848  {
849  int i;
850 
852 
853  elog_alloc (dst, vec_len (dst->events));
854  for (i = 0; i < vec_len (dst->events); i++)
855  {
856  elog_event_t *es, *ed;
857 
858  es = dst->events + i;
859  ed = dst->event_ring + i;
860 
861  ed[0] = es[0];
862  }
863  }
864 }
865 
866 static void
868 {
869  elog_main_t *em = va_arg (*va, elog_main_t *);
870  elog_event_t *e = va_arg (*va, elog_event_t *);
872  u8 *d = e->data;
873  u8 *p = (u8 *) t->format_args;
874 
875  serialize_integer (m, e->event_type, sizeof (e->event_type));
876  serialize_integer (m, e->track, sizeof (e->track));
877  serialize (m, serialize_f64, e->time);
878 
879  while (*p)
880  {
881  uword n_digits, n_bytes = 0;
882 
883  n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
884 
885  switch (p[0])
886  {
887  case 'i':
888  case 't':
889  case 'T':
890  if (n_bytes == 1)
891  serialize_integer (m, d[0], sizeof (u8));
892  else if (n_bytes == 2)
893  serialize_integer (m, clib_mem_unaligned (d, u16), sizeof (u16));
894  else if (n_bytes == 4)
895  serialize_integer (m, clib_mem_unaligned (d, u32), sizeof (u32));
896  else if (n_bytes == 8)
898  else
899  ASSERT (0);
900  break;
901 
902  case 's':
903  serialize_cstring (m, (char *) d);
904  if (n_bytes == 0)
905  n_bytes = strlen ((char *) d) + 1;
906  break;
907 
908  case 'f':
909  if (n_bytes == 4)
911  else if (n_bytes == 8)
913  else
914  ASSERT (0);
915  break;
916 
917  default:
918  ASSERT (0);
919  break;
920  }
921 
922  p += 1 + n_digits;
923  d += n_bytes;
924  }
925 }
926 
927 static void
929 {
930  elog_main_t *em = va_arg (*va, elog_main_t *);
931  elog_event_t *e = va_arg (*va, elog_event_t *);
933  u8 *p, *d;
934 
935  {
936  u16 tmp[2];
937 
938  unserialize_integer (m, &tmp[0], sizeof (e->event_type));
939  unserialize_integer (m, &tmp[1], sizeof (e->track));
940 
941  e->event_type = tmp[0];
942  e->track = tmp[1];
943 
944  /* Make sure it fits. */
945  ASSERT (e->event_type == tmp[0]);
946  ASSERT (e->track == tmp[1]);
947  }
948 
950 
951  unserialize (m, unserialize_f64, &e->time);
952 
953  d = e->data;
954  p = (u8 *) t->format_args;
955 
956  while (p && *p)
957  {
958  uword n_digits, n_bytes = 0;
959  u32 tmp;
960 
961  n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
962 
963  switch (p[0])
964  {
965  case 'i':
966  case 't':
967  case 'T':
968  if (n_bytes == 1)
969  {
970  unserialize_integer (m, &tmp, sizeof (u8));
971  d[0] = tmp;
972  }
973  else if (n_bytes == 2)
974  {
975  unserialize_integer (m, &tmp, sizeof (u16));
976  clib_mem_unaligned (d, u16) = tmp;
977  }
978  else if (n_bytes == 4)
979  {
980  unserialize_integer (m, &tmp, sizeof (u32));
981  clib_mem_unaligned (d, u32) = tmp;
982  }
983  else if (n_bytes == 8)
984  {
985  u64 x;
986  unserialize (m, unserialize_64, &x);
987  clib_mem_unaligned (d, u64) = x;
988  }
989  else
990  ASSERT (0);
991  break;
992 
993  case 's':
994  {
995  char *t;
996  unserialize_cstring (m, &t);
997  if (n_bytes == 0)
998  n_bytes = strlen (t) + 1;
999  clib_memcpy (d, t, clib_min (n_bytes, vec_len (t)));
1000  vec_free (t);
1001  break;
1002  }
1003 
1004  case 'f':
1005  if (n_bytes == 4)
1006  {
1007  f32 x;
1008  unserialize (m, unserialize_f32, &x);
1009  clib_mem_unaligned (d, f32) = x;
1010  }
1011  else if (n_bytes == 8)
1012  {
1013  f64 x;
1014  unserialize (m, unserialize_f64, &x);
1015  clib_mem_unaligned (d, f64) = x;
1016  }
1017  else
1018  ASSERT (0);
1019  break;
1020 
1021  default:
1022  ASSERT (0);
1023  break;
1024  }
1025 
1026  p += 1 + n_digits;
1027  d += n_bytes;
1028  }
1029 }
1030 
1031 static void
1033 {
1034  elog_event_type_t *t = va_arg (*va, elog_event_type_t *);
1035  int n = va_arg (*va, int);
1036  int i, j;
1037  for (i = 0; i < n; i++)
1038  {
1039  serialize_cstring (m, t[i].format);
1040  serialize_cstring (m, t[i].format_args);
1041  serialize_integer (m, t[i].type_index_plus_one,
1042  sizeof (t->type_index_plus_one));
1043  serialize_integer (m, t[i].n_enum_strings,
1044  sizeof (t[i].n_enum_strings));
1045  for (j = 0; j < t[i].n_enum_strings; j++)
1046  serialize_cstring (m, t[i].enum_strings_vector[j]);
1047  }
1048 }
1049 
1050 static void
1052 {
1053  elog_event_type_t *t = va_arg (*va, elog_event_type_t *);
1054  int n = va_arg (*va, int);
1055  int i, j;
1056  for (i = 0; i < n; i++)
1057  {
1058  unserialize_cstring (m, &t[i].format);
1059  unserialize_cstring (m, &t[i].format_args);
1060  unserialize_integer (m, &t[i].type_index_plus_one,
1061  sizeof (t->type_index_plus_one));
1062  unserialize_integer (m, &t[i].n_enum_strings,
1063  sizeof (t[i].n_enum_strings));
1064  vec_resize (t[i].enum_strings_vector, t[i].n_enum_strings);
1065  for (j = 0; j < t[i].n_enum_strings; j++)
1066  unserialize_cstring (m, &t[i].enum_strings_vector[j]);
1067  }
1068 }
1069 
1070 static void
1072 {
1073  elog_track_t *t = va_arg (*va, elog_track_t *);
1074  int n = va_arg (*va, int);
1075  int i;
1076  for (i = 0; i < n; i++)
1077  {
1078  serialize_cstring (m, t[i].name);
1079  }
1080 }
1081 
1082 static void
1084 {
1085  elog_track_t *t = va_arg (*va, elog_track_t *);
1086  int n = va_arg (*va, int);
1087  int i;
1088  for (i = 0; i < n; i++)
1089  {
1090  unserialize_cstring (m, &t[i].name);
1091  }
1092 }
1093 
1094 static void
1096 {
1097  elog_time_stamp_t *st = va_arg (*va, elog_time_stamp_t *);
1098  serialize (m, serialize_64, st->os_nsec);
1099  serialize (m, serialize_64, st->cpu);
1100 }
1101 
1102 static void
1104 {
1105  elog_time_stamp_t *st = va_arg (*va, elog_time_stamp_t *);
1106  unserialize (m, unserialize_64, &st->os_nsec);
1107  unserialize (m, unserialize_64, &st->cpu);
1108 }
1109 
1110 static char *elog_serialize_magic = "elog v0";
1111 
1112 __clib_export void
1114 {
1115  elog_main_t *em = va_arg (*va, elog_main_t *);
1116  int flush_ring = va_arg (*va, int);
1117  elog_event_t *e;
1118 
1120 
1121  serialize_integer (m, em->event_ring_size, sizeof (u32));
1122 
1126 
1130 
1131  /* Free old events (cached) in case they have changed. */
1132  if (flush_ring)
1133  {
1134  vec_free (em->events);
1135  elog_get_events (em);
1136  }
1137 
1138  serialize_integer (m, vec_len (em->events), sizeof (u32));
1139 
1140  /* SMP logs can easily have local time paradoxes... */
1142 
1143  vec_foreach (e, em->events) serialize (m, serialize_elog_event, em, e);
1144 }
1145 
1146 __clib_export void
1148 {
1149  elog_main_t *em = va_arg (*va, elog_main_t *);
1150  uword i;
1151  u32 rs;
1152 
1154  strlen (elog_serialize_magic));
1155 
1156  unserialize_integer (m, &rs, sizeof (u32));
1157  em->event_ring_size = rs;
1158  elog_init (em, em->event_ring_size);
1159 
1163 
1165  for (i = 0; i < vec_len (em->event_types); i++)
1166  new_event_type (em, i);
1167 
1170 
1171  {
1172  u32 ne;
1173  elog_event_t *e;
1174 
1175  unserialize_integer (m, &ne, sizeof (u32));
1176  vec_resize (em->events, ne);
1177  vec_foreach (e, em->events)
1178  unserialize (m, unserialize_elog_event, em, e);
1179  }
1180 }
1181 
1182 #ifdef CLIB_UNIX
1183 clib_error_t *
1184 elog_write_file_not_inline (elog_main_t * em, char *clib_file, int flush_ring)
1185 {
1186  serialize_main_t m;
1188 
1189  error = serialize_open_clib_file (&m, clib_file);
1190  if (error)
1191  return error;
1192  error = serialize (&m, serialize_elog_main, em, flush_ring);
1193  if (!error)
1194  serialize_close (&m);
1195  return error;
1196 }
1197 
1198 __clib_export clib_error_t *
1200 {
1201  serialize_main_t m;
1203 
1204  error = unserialize_open_clib_file (&m, clib_file);
1205  if (error)
1206  return error;
1207  error = unserialize (&m, unserialize_elog_main, em);
1208  if (!error)
1209  unserialize_close (&m);
1210  return error;
1211 }
1212 #endif /* CLIB_UNIX */
1213 
1214 
1215 /*
1216  * fd.io coding-style-patch-verification: ON
1217  *
1218  * Local Variables:
1219  * eval: (c-set-style "gnu")
1220  * End:
1221  */
static uword elog_event_range(elog_main_t *em, uword *lo)
Definition: elog.c:536
static void unserialize_elog_track(serialize_main_t *m, va_list *va)
Definition: elog.c:1083
__clib_export u8 * va_format(u8 *s, const char *fmt, va_list *va)
Definition: format.c:391
uword * string_table_hash
Definition: elog.h:159
__clib_export clib_error_t * elog_read_file_not_inline(elog_main_t *em, char *clib_file)
Definition: elog.c:1199
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:342
void unserialize_check_magic(serialize_main_t *m, void *magic, u32 magic_bytes)
Definition: serialize.c:634
a
Definition: bitmap.h:544
u16 event_type
Event type index.
Definition: elog.h:71
#define vec_serialize(m, v, f)
Definition: serialize.h:371
__clib_export void unserialize_elog_main(serialize_main_t *m, va_list *va)
Definition: elog.c:1147
u32 n_bytes
unsigned long u64
Definition: types.h:89
elog_time_stamp_t init_time
Timestamps.
Definition: elog.h:172
clib_memset(h->entries, 0, sizeof(h->entries[0]) *entries)
#define vec_unserialize(m, v, f)
Definition: serialize.h:374
serialize_function_t unserialize_64
Definition: serialize.h:354
u64 time_cycles
Absolute time stamp in CPU clock cycles.
Definition: elog.h:64
#define vec_add1(V, E)
Add 1 element to end of vector (unspecified alignment).
Definition: vec.h:607
static u64 clib_cpu_time_now(void)
Definition: time.h:81
vl_api_address_t src
Definition: gre.api:54
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:645
static u32 format_get_indent(u8 *s)
Definition: format.h:72
#define hash_set_mem(h, key, value)
Definition: hash.h:275
string name[64]
Definition: fib.api:25
__clib_export void elog_resize(elog_main_t *em, u32 n_events)
Definition: elog.c:507
char * format
Format string.
Definition: elog.h:92
static void serialize_elog_event_type(serialize_main_t *m, va_list *va)
Definition: elog.c:1032
#define vec_validate_aligned(V, I, A)
Make sure vector is long enough for given index (no header, specified alignment)
Definition: vec.h:535
__clib_export u8 * format_elog_track_name(u8 *s, va_list *va)
Definition: elog.c:399
__clib_export void elog_merge(elog_main_t *dst, u8 *dst_tag, elog_main_t *src, u8 *src_tag, f64 align_tweak)
Definition: elog.c:699
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
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
unsigned int u32
Definition: types.h:88
#define clib_memcpy(d, s, n)
Definition: string.h:197
#define vec_add(V, E, N)
Add N elements to end of vector V (no header, unspecified alignment)
Definition: vec.h:689
vlib_frame_t * f
u32 n_enum_strings
Number of elements in string enum table.
Definition: elog.h:107
static char * elog_serialize_magic
Definition: elog.c:1110
serialize_function_t unserialize_f32
Definition: serialize.h:359
if(node->flags &VLIB_NODE_FLAG_TRACE) vnet_interface_output_trace(vm
i64 word
Definition: types.h:111
__clib_export void elog_init(elog_main_t *em, u32 n_events)
Definition: elog.c:513
__clib_export void serialize_elog_main(serialize_main_t *m, va_list *va)
Definition: elog.c:1113
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
description fragment has unexpected format
Definition: map.api:433
const char *const const double number
Definition: cJSON.h:268
__clib_export void serialize_close(serialize_main_t *m)
Definition: serialize.c:870
static void unserialize_elog_time_stamp(serialize_main_t *m, va_list *va)
Definition: elog.c:1103
#define vec_elt_at_index(v, i)
Get vector value at index i checking that i is in bounds.
__clib_export void elog_alloc(elog_main_t *em, u32 n_events)
Definition: elog.c:501
uword * lock
SMP lock, non-zero means locking required.
Definition: elog.h:175
char * format_args
Specifies how arguments to format are parsed from event data.
Definition: elog.h:101
static perfmon_event_t events[]
Definition: core.c:21
#define vec_resize(V, N)
Resize a vector (no header, unspecified alignment) Add N elements to end of given vector V...
Definition: vec.h:296
__clib_export void serialize_cstring(serialize_main_t *m, char *s)
Definition: serialize.c:164
#define vec_end(v)
End (last data address) of vector.
static void serialize_elog_event(serialize_main_t *m, va_list *va)
Definition: elog.c:867
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:45
static f64 elog_nsec_per_clock(elog_main_t *em)
Definition: elog.c:479
#define hash_create_string(elts, value_bytes)
Definition: hash.h:690
__clib_export u8 * format_elog_track(u8 *s, va_list *args)
Definition: elog.c:408
__clib_export 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:626
static uword find_or_create_type(elog_main_t *em, elog_event_type_t *t)
Definition: elog.c:85
while(n_left_from > 0)
vl_api_fib_path_type_t type
Definition: fib_types.api:123
Definition: cJSON.c:88
elog_event_type_t * event_types
Vector of event types.
Definition: elog.h:152
#define clib_atomic_release(a)
Definition: atomics.h:46
lo
__clib_export u8 * format_elog_event(u8 *s, va_list *va)
Definition: elog.c:296
__clib_export 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:557
clib_error_t * elog_write_file_not_inline(elog_main_t *em, char *clib_file, int flush_ring)
Definition: elog.c:1184
unsigned short u16
Definition: types.h:57
signed long i64
Definition: types.h:78
char * name
Track name vector.
Definition: elog.h:116
static void elog_alloc_internal(elog_main_t *em, u32 n_events, int free_ring)
Definition: elog.c:488
static void elog_lock(elog_main_t *em)
Definition: elog.c:47
u32 * tmp
elog_event_t * event_ring
Vector of events (circular buffer).
Definition: elog.h:149
#define PREDICT_FALSE(x)
Definition: clib.h:124
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:58
word elog_event_type_register(elog_main_t *em, elog_event_type_t *t)
register an event type
Definition: elog.c:104
serialize_function_t unserialize_f64
Definition: serialize.h:358
__clib_export void * elog_event_data(elog_main_t *em, elog_event_type_t *type, elog_track_t *track, u64 cpu_time)
Definition: elog.c:65
int cJSON_bool fmt
Definition: cJSON.h:160
__clib_export word elog_track_register(elog_main_t *em, elog_track_t *t)
register an event track
Definition: elog.c:198
static void unserialize_elog_event_type(serialize_main_t *m, va_list *va)
Definition: elog.c:1051
u8 len
Definition: ip_types.api:103
static void unserialize_elog_event(serialize_main_t *m, va_list *va)
Definition: elog.c:928
The fine-grained event logger allows lightweight, thread-safe event logging at minimum cost...
__clib_export void unserialize_close(serialize_main_t *m)
Definition: serialize.c:877
sll srl srl sll sra u16x4 i
Definition: vector_sse42.h:261
#define vec_free(V)
Free vector&#39;s memory (no header).
Definition: vec.h:395
__clib_export clib_error_t * serialize(serialize_main_t *m,...)
Definition: serialize.c:672
static f64 fabs(f64 x)
Definition: math.h:50
__clib_export clib_error_t * unserialize_open_clib_file(serialize_main_t *m, char *file)
Definition: serialize.c:1242
void elog_time_now(elog_time_stamp_t *et)
Definition: elog.c:440
static uword max_pow2(uword x)
Definition: clib.h:258
static void maybe_fix_string_table_offset(elog_event_t *e, elog_event_type_t *t, u32 offset)
Definition: elog.c:634
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 u8 * fixed_format(u8 *s, char *fmt, char *result, uword *result_len)
Definition: elog.c:249
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
#define always_inline
Definition: rdma_mlx5dv.h:23
__clib_export void clib_time_init(clib_time_t *c)
Definition: time.c:207
u64 cpu
CPU cycle counter.
Definition: elog.h:126
static i64 elog_time_stamp_diff_cpu(elog_time_stamp_t *t1, elog_time_stamp_t *t2)
Definition: elog.c:473
#define vec_append(v1, v2)
Append v2 after v1.
Definition: vec.h:912
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
#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 SYS_clock_gettime
#define hash_create_vec(elts, key_bytes, value_bytes)
Definition: hash.h:668
serialize_function_t serialize_vec_8
Definition: serialize.h:362
static i64 elog_time_stamp_diff_os_nsec(elog_time_stamp_t *t1, elog_time_stamp_t *t2)
Definition: elog.c:467
static void new_event_type(elog_main_t *em, uword i)
Definition: elog.c:72
#define vec_len(v)
Number of elements in vector (rvalue-only, NULL tolerant)
__clib_export char * format_one_elog_event(void *em_arg, void *ep_arg)
Definition: elog.c:431
static uword parse_2digit_decimal(char *p, uword *number)
Definition: elog.c:222
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:1098
__clib_export void unserialize_cstring(serialize_main_t *m, char **s)
Definition: serialize.c:178
u8 * string_table_tmp
Definition: elog.h:160
static void elog_unlock(elog_main_t *em)
Definition: elog.c:55
elog_track_t * tracks
Vector of tracks.
Definition: elog.h:163
static void serialize_elog_time_stamp(serialize_main_t *m, va_list *va)
Definition: elog.c:1095
#define hash_get_mem(h, key)
Definition: hash.h:269
struct clib_bihash_value offset
template key/value backing page structure
static void serialize_elog_track(serialize_main_t *m, va_list *va)
Definition: elog.c:1071
char * string_table
Events may refer to strings in string table.
Definition: elog.h:158
vl_api_ip4_address_t dst
Definition: pnat.api:41
#define vec_foreach(var, vec)
Vector iterator.
elog_track_t default_track
Default track.
Definition: elog.h:166
Definition: file.h:51
u32 n_total_events
Total number of events in buffer.
Definition: elog.h:135
#define CLIB_CACHE_LINE_BYTES
Definition: cache.h:59
__clib_export clib_error_t * unserialize(serialize_main_t *m,...)
Definition: serialize.c:684
__clib_export u32 elog_string(elog_main_t *em, char *fmt,...)
add a string to the event-log string table
Definition: elog.c:582
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
__clib_export clib_error_t * serialize_open_clib_file(serialize_main_t *m, char *file)
Definition: serialize.c:1236
serialize_function_t serialize_f64
Definition: serialize.h:358
static int elog_cmp(void *a1, void *a2)
Definition: elog.c:681