src/vppinfra/elog.c

   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
  47 elog_lock (elog_main_t * em)
  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
  55 elog_unlock (elog_main_t * em)
  56 {
  57   if (PREDICT_FALSE (em->lock != 0))
  58     {
  59       clib_atomic_release (em->lock);
  60     }
  61 }
  62
  63 /* Non-inline version. */
  64 void *
  65 elog_event_data (elog_main_t * em,
  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
  72 new_event_type (elog_main_t * em, uword i)
  73 {
  74   elog_event_type_t *t = vec_elt_at_index (em->event_types, i);
  75
  76   if (!em->event_type_by_format)
  77     em->event_type_by_format =
  78       hash_create_vec ( /* size */ 0, sizeof (u8), sizeof (uword));
  79
  80   t->type_index_plus_one = i + 1;
  81   hash_set_mem (em->event_type_by_format, t->format, i);
  82 }
  83
  84 static uword
  85 find_or_create_type (elog_main_t * em, elog_event_type_t * t)
  86 {
  87   uword *p = hash_get_mem (em->event_type_by_format, t->format);
  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
 104 elog_event_type_register (elog_main_t * em, elog_event_type_t * t)
 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";
 185         vec_add1 (t->enum_strings_vector,
 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
 198 elog_track_register (elog_main_t * em, elog_track_t * t)
 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 *);
 300   elog_event_type_t *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->event_type);
 306
 307   f = t->format;
 308   a = t->format_args;
 309   while (1)
 310     {
 311       uword n_bytes = 0, n_digits, f_bytes = 0;
 312
 313       f_bytes = sizeof (arg_format);
 314       s = fixed_format (s, f, arg_format, &f_bytes);
 315       f += f_bytes;
 316
 317       if (a == 0 || a[0] == 0)
 318         {
 319           /* Format must also be at end. */
 320           ASSERT (f[0] == 0);
 321           break;
 322         }
 323
 324       /* Don't go past end of event data. */
 325       ASSERT (d < (void *) (e->data + sizeof (e->data)));
 326
 327       n_digits = parse_2digit_decimal (a + 1, &n_bytes);
 328       switch (a[0])
 329         {
 330         case 'i':
 331         case 't':
 332         case 'T':
 333           {
 334             u32 i = 0;
 335             u64 l = 0;
 336
 337             if (n_bytes == 1)
 338               i = ((u8 *) d)[0];
 339             else if (n_bytes == 2)
 340               i = clib_mem_unaligned (d, u16);
 341             else if (n_bytes == 4)
 342               i = clib_mem_unaligned (d, u32);
 343             else if (n_bytes == 8)
 344               l = clib_mem_unaligned (d, u64);
 345             else
 346               ASSERT (0);
 347             if (a[0] == 't')
 348               {
 349                 char *e =
 350                   vec_elt (t->enum_strings_vector, n_bytes == 8 ? l : i);
 351                 s = format (s, arg_format, e);
 352               }
 353             else if (a[0] == 'T')
 354               {
 355                 char *e =
 356                   vec_elt_at_index (em->string_table, n_bytes == 8 ? l : i);
 357                 s = format (s, arg_format, e);
 358               }
 359             else if (n_bytes == 8)
 360               s = format (s, arg_format, l);
 361             else
 362               s = format (s, arg_format, i);
 363           }
 364           break;
 365
 366         case 'f':
 367           {
 368             f64 x = 0;
 369             if (n_bytes == 4)
 370               x = clib_mem_unaligned (d, f32);
 371             else if (n_bytes == 8)
 372               x = clib_mem_unaligned (d, f64);
 373             else
 374               ASSERT (0);
 375             s = format (s, arg_format, x);
 376           }
 377           break;
 378
 379         case 's':
 380           s = format (s, arg_format, d);
 381           if (n_bytes == 0)
 382             n_bytes = strlen (d) + 1;
 383           break;
 384
 385         default:
 386           ASSERT (0);
 387           break;
 388         }
 389
 390       ASSERT (n_digits > 0 && n_digits <= 2);
 391       a += 1 + n_digits;
 392       d += n_bytes;
 393     }
 394
 395   return s;
 396 }
 397
 398 u8 *
 399 format_elog_track_name (u8 * s, va_list * va)
 400 {
 401   elog_main_t *em = va_arg (*va, elog_main_t *);
 402   elog_event_t *e = va_arg (*va, elog_event_t *);
 403   elog_track_t *t = vec_elt_at_index (em->tracks, e->track);
 404   return format (s, "%s", t->name);
 405 }
 406
 407 u8 *
 408 format_elog_track (u8 * s, va_list * args)
 409 {
 410   elog_main_t *em = va_arg (*args, elog_main_t *);
 411   f64 dt = va_arg (*args, f64);
 412   int track_index = va_arg (*args, int);
 413   elog_event_t *e, *es;
 414   u8 indent;
 415
 416   indent = format_get_indent (s) + 1;
 417
 418   es = elog_peek_events (em);
 419   vec_foreach (e, es)
 420   {
 421     if (e->track != track_index)
 422       continue;
 423     s = format (s, "%U%18.9f: %U\n", format_white_space, indent,
 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
 440 elog_time_now (elog_time_stamp_t * et)
 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
 466 always_inline i64
 467 elog_time_stamp_diff_os_nsec (elog_time_stamp_t * t1, elog_time_stamp_t * t2)
 468 {
 469   return (i64) t1->os_nsec - (i64) t2->os_nsec;
 470 }
 471
 472 always_inline i64
 473 elog_time_stamp_diff_cpu (elog_time_stamp_t * t1, elog_time_stamp_t * t2)
 474 {
 475   return (i64) t1->cpu - (i64) t2->cpu;
 476 }
 477
 478 always_inline f64
 479 elog_nsec_per_clock (elog_main_t * em)
 480 {
 481   return ((f64) elog_time_stamp_diff_os_nsec (&em->serialize_time,
 482                                               &em->init_time)
 483           / (f64) elog_time_stamp_diff_cpu (&em->serialize_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). */
 498   vec_resize_aligned (em->event_ring, n_events, CLIB_CACHE_LINE_BYTES);
 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
 513   em->n_total_events_disable_limit = ~0;
 514
 515   /* Make track 0. */
 516   em->default_track.name = "default";
 517   elog_track_register (em, &em->default_track);
 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
 525 elog_event_range (elog_main_t * em, uword * lo)
 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 *
 546 elog_peek_events (elog_main_t * em)
 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 -
 561          em->init_time.cpu) * em->cpu_timer.seconds_per_clock;
 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);
 579   vec_reset_length (em->string_table_tmp);
 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 */
 591   p = hash_get_mem (em->string_table_hash, em->string_table_tmp);
 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);
 603   vec_append (em->string_table, em->string_table_tmp);
 604
 605   hash_set_mem (em->string_table_hash, em->string_table_tmp, offset);
 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 *
 615 elog_get_events (elog_main_t * em)
 616 {
 617   vec_reset_length (em->events);
 618   em->events = elog_peek_events (em);
 619   return em->events;
 620 }
 621
 622 static void
 623 maybe_fix_string_table_offset (elog_event_t * e,
 624                                elog_event_type_t * t, u32 offset)
 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 =
 745         vec_elt_at_index (src->event_types, e->event_type);
 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 */
 751       maybe_fix_string_table_offset (e, t,
 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;
 767         dst->nsec_per_cpu_clock = src->nsec_per_cpu_clock;
 768       }
 769
 770     dt_os_nsec =
 771       elog_time_stamp_diff_os_nsec (&src->init_time, &dst->init_time);
 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. */
 832   vec_sort_with_function (dst->events, elog_cmp);
 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
 840     ASSERT (dst->cpu_timer.seconds_per_clock);
 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
 856 serialize_elog_event (serialize_main_t * m, va_list * va)
 857 {
 858   elog_main_t *em = va_arg (*va, elog_main_t *);
 859   elog_event_t *e = va_arg (*va, elog_event_t *);
 860   elog_event_type_t *t = vec_elt_at_index (em->event_types, e->event_type);
 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)
 886             serialize (m, serialize_64, clib_mem_unaligned (d, u64));
 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)
 899             serialize (m, serialize_f32, clib_mem_unaligned (d, f32));
 900           else if (n_bytes == 8)
 901             serialize (m, serialize_f64, clib_mem_unaligned (d, f64));
 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
 917 unserialize_elog_event (serialize_main_t * m, va_list * va)
 918 {
 919   elog_main_t *em = va_arg (*va, elog_main_t *);
 920   elog_event_t *e = va_arg (*va, elog_event_t *);
 921   elog_event_type_t *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
 938   t = vec_elt_at_index (em->event_types, e->event_type);
 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
1021 serialize_elog_event_type (serialize_main_t * m, va_list * va)
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
1040 unserialize_elog_event_type (serialize_main_t * m, va_list * va)
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
1060 serialize_elog_track (serialize_main_t * m, va_list * va)
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
1072 unserialize_elog_track (serialize_main_t * m, va_list * va)
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
1084 serialize_elog_time_stamp (serialize_main_t * m, va_list * va)
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
1092 unserialize_elog_time_stamp (serialize_main_t * m, va_list * va)
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
1102 serialize_elog_main (serialize_main_t * m, va_list * va)
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
1108   serialize_magic (m, elog_serialize_magic, strlen (elog_serialize_magic));
1109
1110   serialize_integer (m, em->event_ring_size, sizeof (u32));
1111
1112   elog_time_now (&em->serialize_time);
1113   serialize (m, serialize_elog_time_stamp, &em->serialize_time);
1114   serialize (m, serialize_elog_time_stamp, &em->init_time);
1115
1116   vec_serialize (m, em->event_types, serialize_elog_event_type);
1117   vec_serialize (m, em->tracks, serialize_elog_track);
1118   vec_serialize (m, em->string_table, serialize_vec_8);
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... */
1130   vec_sort_with_function (em->events, elog_cmp);
1131
1132   vec_foreach (e, em->events) serialize (m, serialize_elog_event, em, e);
1133 }
1134
1135 void
1136 unserialize_elog_main (serialize_main_t * m, va_list * va)
1137 {
1138   elog_main_t *em = va_arg (*va, elog_main_t *);
1139   uword i;
1140   u32 rs;
1141
1142   unserialize_check_magic (m, elog_serialize_magic,
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
1149   unserialize (m, unserialize_elog_time_stamp, &em->serialize_time);
1150   unserialize (m, unserialize_elog_time_stamp, &em->init_time);
1151   em->nsec_per_cpu_clock = elog_nsec_per_clock (em);
1152
1153   vec_unserialize (m, &em->event_types, unserialize_elog_event_type);
1154   for (i = 0; i < vec_len (em->event_types); i++)
1155     new_event_type (em, i);
1156
1157   vec_unserialize (m, &em->tracks, unserialize_elog_track);
1158   vec_unserialize (m, &em->string_table, unserialize_vec_8);
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 *
1188 elog_read_file_not_inline (elog_main_t * em, char *clib_file)
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  */