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