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