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