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_MEMORY_BARRIER ();
  60       *em->lock = 0;
  61     }
  62 }
  63
  64 /* Non-inline version. */
  65 void *
  66 elog_event_data (elog_main_t * em,
  67                  elog_event_type_t * type, elog_track_t * track, u64 cpu_time)
  68 {
  69   return elog_event_data_inline (em, type, track, cpu_time);
  70 }
  71
  72 static void
  73 new_event_type (elog_main_t * em, uword i)
  74 {
  75   elog_event_type_t *t = vec_elt_at_index (em->event_types, i);
  76
  77   if (!em->event_type_by_format)
  78     em->event_type_by_format =
  79       hash_create_vec ( /* size */ 0, sizeof (u8), sizeof (uword));
  80
  81   t->type_index_plus_one = i + 1;
  82   hash_set_mem (em->event_type_by_format, t->format, i);
  83 }
  84
  85 static uword
  86 find_or_create_type (elog_main_t * em, elog_event_type_t * t)
  87 {
  88   uword *p = hash_get_mem (em->event_type_by_format, t->format);
  89   uword i;
  90
  91   if (p)
  92     i = p[0];
  93   else
  94     {
  95       i = vec_len (em->event_types);
  96       vec_add1 (em->event_types, t[0]);
  97       new_event_type (em, i);
  98     }
  99
 100   return i;
 101 }
 102
 103 /* External function to register types. */
 104 word
 105 elog_event_type_register (elog_main_t * em, elog_event_type_t * t)
 106 {
 107   elog_event_type_t *static_type = t;
 108   word l;
 109
 110   elog_lock (em);
 111
 112   /* Multiple simultaneous registration attempts, */
 113   if (t->type_index_plus_one > 0)
 114     {
 115       elog_unlock (em);
 116       return t->type_index_plus_one - 1;
 117     }
 118
 119   l = vec_len (em->event_types);
 120
 121   t->type_index_plus_one = 1 + l;
 122
 123   ASSERT (t->format);
 124
 125   /* If format args are not specified try to be smart about providing defaults
 126      so most of the time user does not have to specify them. */
 127   if (!t->format_args)
 128     {
 129       uword i, l;
 130       char *this_arg;
 131
 132       l = strlen (t->format);
 133       for (i = 0; i < l; i++)
 134         {
 135           if (t->format[i] != '%')
 136             continue;
 137           if (i + 1 >= l)
 138             continue;
 139           if (t->format[i + 1] == '%')  /* %% */
 140             continue;
 141
 142           switch (t->format[i + 1])
 143             {
 144             default:
 145             case 'd':
 146             case 'x':
 147             case 'u':
 148               this_arg = "i4";  /* size of u32 */
 149               break;
 150             case 'f':
 151               this_arg = "f8";  /* defaults to f64 */
 152               break;
 153             case 's':
 154               this_arg = "s0";  /* defaults to null terminated string. */
 155               break;
 156             }
 157
 158           t->format_args =
 159             (char *) format ((u8 *) t->format_args, "%s", this_arg);
 160         }
 161
 162       /* Null terminate. */
 163       vec_add1 (t->format_args, 0);
 164     }
 165
 166   vec_add1 (em->event_types, t[0]);
 167
 168   t = em->event_types + l;
 169
 170   /* Make copies of strings for hashing etc. */
 171   if (t->function)
 172     t->format = (char *) format (0, "%s %s%c", t->function, t->format, 0);
 173   else
 174     t->format = (char *) format (0, "%s%c", t->format, 0);
 175
 176   t->format_args = (char *) format (0, "%s%c", t->format_args, 0);
 177
 178   /* Construct string table. */
 179   {
 180     uword i;
 181     t->n_enum_strings = static_type->n_enum_strings;
 182     for (i = 0; i < t->n_enum_strings; i++)
 183       {
 184         if (!static_type->enum_strings[i])
 185           static_type->enum_strings[i] = "MISSING";
 186         vec_add1 (t->enum_strings_vector,
 187                   (char *) format (0, "%s%c", static_type->enum_strings[i],
 188                                    0));
 189       }
 190   }
 191
 192   new_event_type (em, l);
 193   elog_unlock (em);
 194
 195   return l;
 196 }
 197
 198 word
 199 elog_track_register (elog_main_t * em, elog_track_t * t)
 200 {
 201   word l;
 202
 203   elog_lock (em);
 204
 205   l = vec_len (em->tracks);
 206
 207   t->track_index_plus_one = 1 + l;
 208
 209   ASSERT (t->name);
 210
 211   vec_add1 (em->tracks, t[0]);
 212
 213   t = em->tracks + l;
 214
 215   t->name = (char *) format (0, "%s%c", t->name, 0);
 216
 217   elog_unlock (em);
 218
 219   return l;
 220 }
 221
 222 static uword
 223 parse_2digit_decimal (char *p, uword * number)
 224 {
 225   uword i = 0;
 226   u8 digits[2];
 227
 228   digits[0] = digits[1] = 0;
 229   while (p[i] >= '0' && p[i] <= '9')
 230     {
 231       if (i >= 2)
 232         break;
 233       digits[i] = p[i] - '0';
 234       i++;
 235     }
 236
 237   if (i >= 1 && i <= 2)
 238     {
 239       if (i == 1)
 240         *number = digits[0];
 241       else
 242         *number = 10 * digits[0] + digits[1];
 243       return i;
 244     }
 245   else
 246     return 0;
 247 }
 248
 249 static u8 *
 250 fixed_format (u8 * s, char *fmt, char *result, uword * result_len)
 251 {
 252   char *f = fmt;
 253   char *percent;
 254   uword l = 0;
 255
 256   while (1)
 257     {
 258       if (f[0] == 0)
 259         break;
 260       if (f[0] == '%' && f[1] != '%')
 261         break;
 262       f++;
 263     }
 264   if (f > fmt)
 265     vec_add (s, fmt, f - fmt);
 266
 267   if (f[0] != '%')
 268     goto done;
 269
 270   /* Skip percent. */
 271   percent = f++;
 272
 273   /* Skip possible +-= justification. */
 274   f += f[0] == '+' || f[0] == '-' || f[0] == '=';
 275
 276   /* Skip possible X.Y width. */
 277   while ((f[0] >= '0' && f[0] <= '9') || f[0] == '.')
 278     f++;
 279
 280   /* Skip wlL as in e.g. %Ld. */
 281   f += f[0] == 'w' || f[0] == 'l' || f[0] == 'L';
 282
 283   /* Finally skip format letter. */
 284   f += f[0] != 0;
 285
 286   ASSERT (*result_len > f - percent);
 287   l = clib_min (f - percent, *result_len - 1);
 288   clib_memcpy (result, percent, l);
 289   result[l] = 0;
 290
 291 done:
 292   *result_len = f - fmt;
 293   return s;
 294 }
 295
 296 u8 *
 297 format_elog_event (u8 * s, va_list * va)
 298 {
 299   elog_main_t *em = va_arg (*va, elog_main_t *);
 300   elog_event_t *e = va_arg (*va, elog_event_t *);
 301   elog_event_type_t *t;
 302   char *a, *f;
 303   void *d = (u8 *) e->data;
 304   char arg_format[64];
 305
 306   t = vec_elt_at_index (em->event_types, e->type);
 307
 308   f = t->format;
 309   a = t->format_args;
 310   while (1)
 311     {
 312       uword n_bytes = 0, n_digits, f_bytes = 0;
 313
 314       f_bytes = sizeof (arg_format);
 315       s = fixed_format (s, f, arg_format, &f_bytes);
 316       f += f_bytes;
 317
 318       if (a == 0 || a[0] == 0)
 319         {
 320           /* Format must also be at end. */
 321           ASSERT (f[0] == 0);
 322           break;
 323         }
 324
 325       /* Don't go past end of event data. */
 326       ASSERT (d < (void *) (e->data + sizeof (e->data)));
 327
 328       n_digits = parse_2digit_decimal (a + 1, &n_bytes);
 329       switch (a[0])
 330         {
 331         case 'i':
 332         case 't':
 333         case 'T':
 334           {
 335             u32 i = 0;
 336             u64 l = 0;
 337
 338             if (n_bytes == 1)
 339               i = ((u8 *) d)[0];
 340             else if (n_bytes == 2)
 341               i = clib_mem_unaligned (d, u16);
 342             else if (n_bytes == 4)
 343               i = clib_mem_unaligned (d, u32);
 344             else if (n_bytes == 8)
 345               l = clib_mem_unaligned (d, u64);
 346             else
 347               ASSERT (0);
 348             if (a[0] == 't')
 349               {
 350                 char *e =
 351                   vec_elt (t->enum_strings_vector, n_bytes == 8 ? l : i);
 352                 s = format (s, arg_format, e);
 353               }
 354             else if (a[0] == 'T')
 355               {
 356                 char *e =
 357                   vec_elt_at_index (em->string_table, n_bytes == 8 ? l : i);
 358                 s = format (s, arg_format, e);
 359               }
 360             else if (n_bytes == 8)
 361               s = format (s, arg_format, l);
 362             else
 363               s = format (s, arg_format, i);
 364           }
 365           break;
 366
 367         case 'f':
 368           {
 369             f64 x = 0;
 370             if (n_bytes == 4)
 371               x = clib_mem_unaligned (d, f32);
 372             else if (n_bytes == 8)
 373               x = clib_mem_unaligned (d, f64);
 374             else
 375               ASSERT (0);
 376             s = format (s, arg_format, x);
 377           }
 378           break;
 379
 380         case 's':
 381           s = format (s, arg_format, d);
 382           if (n_bytes == 0)
 383             n_bytes = strlen (d) + 1;
 384           break;
 385
 386         default:
 387           ASSERT (0);
 388           break;
 389         }
 390
 391       ASSERT (n_digits > 0 && n_digits <= 2);
 392       a += 1 + n_digits;
 393       d += n_bytes;
 394     }
 395
 396   return s;
 397 }
 398
 399 u8 *
 400 format_elog_track_name (u8 * s, va_list * va)
 401 {
 402   elog_main_t *em = va_arg (*va, elog_main_t *);
 403   elog_event_t *e = va_arg (*va, elog_event_t *);
 404   elog_track_t *t = vec_elt_at_index (em->tracks, e->track);
 405   return format (s, "%s", t->name);
 406 }
 407
 408 u8 *
 409 format_elog_track (u8 * s, va_list * args)
 410 {
 411   elog_main_t *em = va_arg (*args, elog_main_t *);
 412   f64 dt = va_arg (*args, f64);
 413   int track_index = va_arg (*args, int);
 414   elog_event_t *e, *es;
 415   u8 indent;
 416
 417   indent = format_get_indent (s) + 1;
 418
 419   es = elog_peek_events (em);
 420   vec_foreach (e, es)
 421   {
 422     if (e->track != track_index)
 423       continue;
 424     s = format (s, "%U%18.9f: %U\n", format_white_space, indent, e->time + dt,
 425                 format_elog_event, em, e);
 426   }
 427   vec_free (es);
 428   return s;
 429 }
 430
 431 void
 432 elog_time_now (elog_time_stamp_t * et)
 433 {
 434   u64 cpu_time_now, os_time_now_nsec;
 435   struct timespec ts;
 436
 437 #ifdef CLIB_UNIX
 438   {
 439 #include <sys/syscall.h>
 440 #ifdef __APPLE__
 441     clock_gettime (CLOCK_REALTIME, &ts);
 442 #else
 443     syscall (SYS_clock_gettime, CLOCK_REALTIME, &ts);
 444 #endif
 445     cpu_time_now = clib_cpu_time_now ();
 446     /* Subtract 3/30/2017's worth of seconds to retain precision */
 447     os_time_now_nsec = 1e9 * (ts.tv_sec - 1490885108) + ts.tv_nsec;
 448   }
 449 #else
 450   cpu_time_now = clib_cpu_time_now ();
 451   os_time_now_nsec = 0;
 452 #endif
 453
 454   et->cpu = cpu_time_now;
 455   et->os_nsec = os_time_now_nsec;
 456 }
 457
 458 always_inline i64
 459 elog_time_stamp_diff_os_nsec (elog_time_stamp_t * t1, elog_time_stamp_t * t2)
 460 {
 461   return (i64) t1->os_nsec - (i64) t2->os_nsec;
 462 }
 463
 464 always_inline i64
 465 elog_time_stamp_diff_cpu (elog_time_stamp_t * t1, elog_time_stamp_t * t2)
 466 {
 467   return (i64) t1->cpu - (i64) t2->cpu;
 468 }
 469
 470 always_inline f64
 471 elog_nsec_per_clock (elog_main_t * em)
 472 {
 473   return ((f64) elog_time_stamp_diff_os_nsec (&em->serialize_time,
 474                                               &em->init_time)
 475           / (f64) elog_time_stamp_diff_cpu (&em->serialize_time,
 476                                             &em->init_time));
 477 }
 478
 479 void
 480 elog_alloc (elog_main_t * em, u32 n_events)
 481 {
 482   if (em->event_ring)
 483     vec_free (em->event_ring);
 484
 485   /* Ring size must be a power of 2. */
 486   em->event_ring_size = n_events = max_pow2 (n_events);
 487
 488   /* Leave an empty ievent at end so we can always speculatively write
 489      and event there (possibly a long form event). */
 490   vec_resize_aligned (em->event_ring, n_events, CLIB_CACHE_LINE_BYTES);
 491 }
 492
 493 void
 494 elog_init (elog_main_t * em, u32 n_events)
 495 {
 496   clib_memset (em, 0, sizeof (em[0]));
 497
 498   em->lock = 0;
 499
 500   if (n_events > 0)
 501     elog_alloc (em, n_events);
 502
 503   clib_time_init (&em->cpu_timer);
 504
 505   em->n_total_events_disable_limit = ~0;
 506
 507   /* Make track 0. */
 508   em->default_track.name = "default";
 509   elog_track_register (em, &em->default_track);
 510
 511   elog_time_now (&em->init_time);
 512   em->string_table_hash = hash_create_string (0, sizeof (uword));
 513 }
 514
 515 /* Returns number of events in ring and start index. */
 516 static uword
 517 elog_event_range (elog_main_t * em, uword * lo)
 518 {
 519   uword l = em->event_ring_size;
 520   u64 i = em->n_total_events;
 521
 522   /* Ring never wrapped? */
 523   if (i <= (u64) l)
 524     {
 525       if (lo)
 526         *lo = 0;
 527       return i;
 528     }
 529   else
 530     {
 531       if (lo)
 532         *lo = i & (l - 1);
 533       return l;
 534     }
 535 }
 536
 537 elog_event_t *
 538 elog_peek_events (elog_main_t * em)
 539 {
 540   elog_event_t *e, *f, *es = 0;
 541   uword i, j, n;
 542
 543   n = elog_event_range (em, &j);
 544   for (i = 0; i < n; i++)
 545     {
 546       vec_add2 (es, e, 1);
 547       f = vec_elt_at_index (em->event_ring, j);
 548       e[0] = f[0];
 549
 550       /* Convert absolute time from cycles to seconds from start. */
 551       e->time =
 552         (e->time_cycles -
 553          em->init_time.cpu) * em->cpu_timer.seconds_per_clock;
 554
 555       j = (j + 1) & (em->event_ring_size - 1);
 556     }
 557
 558   return es;
 559 }
 560
 561 /* Add a formatted string to the string table. */
 562 u32
 563 elog_string (elog_main_t * em, char *fmt, ...)
 564 {
 565   u32 offset;
 566   uword *p;
 567   uword len;
 568   va_list va;
 569
 570   elog_lock (em);
 571   vec_reset_length (em->string_table_tmp);
 572   va_start (va, fmt);
 573   em->string_table_tmp = va_format (em->string_table_tmp, fmt, &va);
 574   va_end (va);
 575
 576   /* String table entries MUST be NULL terminated */
 577   len = vec_len (em->string_table_tmp);
 578   ASSERT (len > 0);
 579   if (em->string_table_tmp[len - 1] != 0)
 580     vec_add1 (em->string_table_tmp, 0);
 581
 582   /* See if we already have this string in the string table */
 583   p = hash_get_mem (em->string_table_hash, em->string_table_tmp);
 584
 585   /* We already have the string, so give the caller its offset */
 586   if (p)
 587     {
 588       elog_unlock (em);
 589       return (p[0]);
 590     }
 591
 592   /* We don't, so add it. */
 593
 594   offset = vec_len (em->string_table);
 595   vec_append (em->string_table, em->string_table_tmp);
 596
 597   hash_set_mem (em->string_table_hash, em->string_table_tmp, offset);
 598
 599   /* We gave the key to the string table hash, so we can't reuse it! */
 600   em->string_table_tmp = 0;
 601   elog_unlock (em);
 602
 603   return offset;
 604 }
 605
 606 elog_event_t *
 607 elog_get_events (elog_main_t * em)
 608 {
 609   if (!em->events)
 610     em->events = elog_peek_events (em);
 611   return em->events;
 612 }
 613
 614 static void
 615 maybe_fix_string_table_offset (elog_event_t * e,
 616                                elog_event_type_t * t, u32 offset)
 617 {
 618   void *d = (u8 *) e->data;
 619   char *a;
 620
 621   if (offset == 0)
 622     return;
 623
 624   a = t->format_args;
 625
 626   while (1)
 627     {
 628       uword n_bytes = 0, n_digits;
 629
 630       if (a[0] == 0)
 631         break;
 632
 633       /* Don't go past end of event data. */
 634       ASSERT (d < (void *) (e->data + sizeof (e->data)));
 635
 636       n_digits = parse_2digit_decimal (a + 1, &n_bytes);
 637       switch (a[0])
 638         {
 639         case 'T':
 640           ASSERT (n_bytes == 4);
 641           clib_mem_unaligned (d, u32) += offset;
 642           break;
 643
 644         case 'i':
 645         case 't':
 646         case 'f':
 647         case 's':
 648           break;
 649
 650         default:
 651           ASSERT (0);
 652           break;
 653         }
 654
 655       ASSERT (n_digits > 0 && n_digits <= 2);
 656       a += 1 + n_digits;
 657       d += n_bytes;
 658     }
 659 }
 660
 661 static int
 662 elog_cmp (void *a1, void *a2)
 663 {
 664   elog_event_t *e1 = a1;
 665   elog_event_t *e2 = a2;
 666
 667   if (e1->time < e2->time)
 668     return -1;
 669
 670   if (e1->time > e2->time)
 671     return 1;
 672
 673   return 0;
 674 }
 675
 676 /*
 677  * merge two event logs. Complicated and cranky.
 678  */
 679 void
 680 elog_merge (elog_main_t * dst, u8 * dst_tag, elog_main_t * src, u8 * src_tag,
 681             f64 align_tweak)
 682 {
 683   elog_event_t *e;
 684   uword l;
 685   u32 string_table_offset_for_src_events;
 686   u32 track_offset_for_src_tracks;
 687   elog_track_t newt;
 688   int i;
 689
 690   clib_memset (&newt, 0, sizeof (newt));
 691
 692   /* Acquire src and dst events */
 693   elog_get_events (src);
 694   elog_get_events (dst);
 695
 696   string_table_offset_for_src_events = vec_len (dst->string_table);
 697   vec_append (dst->string_table, src->string_table);
 698
 699   l = vec_len (dst->events);
 700   vec_append (dst->events, src->events);
 701
 702   /* Prepend the supplied tag (if any) to all dst track names */
 703   if (dst_tag)
 704     {
 705       for (i = 0; i < vec_len (dst->tracks); i++)
 706         {
 707           elog_track_t *t = vec_elt_at_index (dst->tracks, i);
 708           char *new_name;
 709
 710           new_name = (char *) format (0, "%s:%s%c", dst_tag, t->name, 0);
 711           vec_free (t->name);
 712           t->name = new_name;
 713         }
 714     }
 715
 716   /*
 717    * Remember where we started allocating new tracks while merging
 718    */
 719   track_offset_for_src_tracks = vec_len (dst->tracks);
 720
 721   /* Copy / tag source tracks */
 722   for (i = 0; i < vec_len (src->tracks); i++)
 723     {
 724       elog_track_t *t = vec_elt_at_index (src->tracks, i);
 725       if (src_tag)
 726         newt.name = (char *) format (0, "%s:%s%c", src_tag, t->name, 0);
 727       else
 728         newt.name = (char *) format (0, "%s%c", t->name, 0);
 729       (void) elog_track_register (dst, &newt);
 730       vec_free (newt.name);
 731     }
 732
 733   /* Across all (copied) src events... */
 734   for (e = dst->events + l; e < vec_end (dst->events); e++)
 735     {
 736       elog_event_type_t *t = vec_elt_at_index (src->event_types, e->type);
 737
 738       /* Remap type from src -> dst. */
 739       e->type = find_or_create_type (dst, t);
 740
 741       /* Remap string table offsets for 'T' format args */
 742       maybe_fix_string_table_offset (e, t,
 743                                      string_table_offset_for_src_events);
 744
 745       /* Remap track */
 746       e->track += track_offset_for_src_tracks;
 747     }
 748
 749   /* Adjust event times for relative starting times of event streams. */
 750   {
 751     f64 dt_event, dt_os_nsec, dt_clock_nsec;
 752
 753     /* Set clock parameters if dst was not generated by unserialize. */
 754     if (dst->serialize_time.cpu == 0)
 755       {
 756         dst->init_time = src->init_time;
 757         dst->serialize_time = src->serialize_time;
 758         dst->nsec_per_cpu_clock = src->nsec_per_cpu_clock;
 759       }
 760
 761     dt_os_nsec =
 762       elog_time_stamp_diff_os_nsec (&src->init_time, &dst->init_time);
 763
 764     dt_event = dt_os_nsec;
 765     dt_clock_nsec =
 766       (elog_time_stamp_diff_cpu (&src->init_time, &dst->init_time) * .5 *
 767        (dst->nsec_per_cpu_clock + src->nsec_per_cpu_clock));
 768
 769     /*
 770      * Heuristic to see if src/dst came from same time source.
 771      * If frequencies are "the same" and os clock and cpu clock agree
 772      * to within 100e-9 secs about time difference between src/dst
 773      * init_time, then we use cpu clock.  Otherwise we use OS clock.
 774      *
 775      * When merging event logs from different systems, time paradoxes
 776      * at the O(1ms) level are to be expected. Hence, the "align_tweak"
 777      * parameter. If two events logged on different processors are known
 778      * to occur in a specific order - and with a reasonably-estimated
 779      * interval - supply a non-zero "align_tweak" parameter
 780      */
 781     if (fabs (src->nsec_per_cpu_clock - dst->nsec_per_cpu_clock) < 1e-2
 782         && fabs (dt_os_nsec - dt_clock_nsec) < 100)
 783       dt_event = dt_clock_nsec;
 784
 785     /* Convert to seconds. */
 786     dt_event *= 1e-9;
 787
 788     /*
 789      * Move the earlier set of events later, to avoid creating
 790      * events which precede the Big Bang (aka have negative timestamps).
 791      *
 792      * Not to any scale, we have something like the following picture:
 793      *
 794      * DST capture start point
 795      *       ^
 796      *       +--- dt_event --+
 797      *                       v
 798      *                 SRC capture start point
 799      *
 800      * In this case dt_event is positive, src started after dst,
 801      * to put src events onto a common timebase we have to move them
 802      * forward in time. Naturally, the opposite case is
 803      * possible, too: dt_event will be negative, and so we have to
 804      * move dst events forward in time by the |dt_event|.
 805      * In both cases, we add align_tweak.
 806      */
 807     if (dt_event > 0)
 808       {
 809         /* Src started after dst. */
 810         for (e = dst->events + l; e < vec_end (dst->events); e++)
 811           e->time += dt_event + align_tweak;
 812       }
 813     else
 814       {
 815         /* Dst started after src. */
 816         dt_event = -dt_event;
 817         for (e = dst->events + 0; e < dst->events + l; e++)
 818           e->time += dt_event + align_tweak;
 819       }
 820   }
 821
 822   /* Sort events by increasing time. */
 823   vec_sort_with_function (dst->events, elog_cmp);
 824
 825   dst->n_total_events = vec_len (dst->events);
 826
 827   /* Recreate the event ring or the results won't serialize */
 828   {
 829     int i;
 830
 831     ASSERT (dst->cpu_timer.seconds_per_clock);
 832
 833     elog_alloc (dst, vec_len (dst->events));
 834     for (i = 0; i < vec_len (dst->events); i++)
 835       {
 836         elog_event_t *es, *ed;
 837
 838         es = dst->events + i;
 839         ed = dst->event_ring + i;
 840
 841         ed[0] = es[0];
 842       }
 843   }
 844 }
 845
 846 static void
 847 serialize_elog_event (serialize_main_t * m, va_list * va)
 848 {
 849   elog_main_t *em = va_arg (*va, elog_main_t *);
 850   elog_event_t *e = va_arg (*va, elog_event_t *);
 851   elog_event_type_t *t = vec_elt_at_index (em->event_types, e->type);
 852   u8 *d = e->data;
 853   u8 *p = (u8 *) t->format_args;
 854
 855   serialize_integer (m, e->type, sizeof (e->type));
 856   serialize_integer (m, e->track, sizeof (e->track));
 857   serialize (m, serialize_f64, e->time);
 858
 859   while (*p)
 860     {
 861       uword n_digits, n_bytes = 0;
 862
 863       n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
 864
 865       switch (p[0])
 866         {
 867         case 'i':
 868         case 't':
 869         case 'T':
 870           if (n_bytes == 1)
 871             serialize_integer (m, d[0], sizeof (u8));
 872           else if (n_bytes == 2)
 873             serialize_integer (m, clib_mem_unaligned (d, u16), sizeof (u16));
 874           else if (n_bytes == 4)
 875             serialize_integer (m, clib_mem_unaligned (d, u32), sizeof (u32));
 876           else if (n_bytes == 8)
 877             serialize (m, serialize_64, clib_mem_unaligned (d, u64));
 878           else
 879             ASSERT (0);
 880           break;
 881
 882         case 's':
 883           serialize_cstring (m, (char *) d);
 884           if (n_bytes == 0)
 885             n_bytes = strlen ((char *) d) + 1;
 886           break;
 887
 888         case 'f':
 889           if (n_bytes == 4)
 890             serialize (m, serialize_f32, clib_mem_unaligned (d, f32));
 891           else if (n_bytes == 8)
 892             serialize (m, serialize_f64, clib_mem_unaligned (d, f64));
 893           else
 894             ASSERT (0);
 895           break;
 896
 897         default:
 898           ASSERT (0);
 899           break;
 900         }
 901
 902       p += 1 + n_digits;
 903       d += n_bytes;
 904     }
 905 }
 906
 907 static void
 908 unserialize_elog_event (serialize_main_t * m, va_list * va)
 909 {
 910   elog_main_t *em = va_arg (*va, elog_main_t *);
 911   elog_event_t *e = va_arg (*va, elog_event_t *);
 912   elog_event_type_t *t;
 913   u8 *p, *d;
 914
 915   {
 916     u16 tmp[2];
 917
 918     unserialize_integer (m, &tmp[0], sizeof (e->type));
 919     unserialize_integer (m, &tmp[1], sizeof (e->track));
 920
 921     e->type = tmp[0];
 922     e->track = tmp[1];
 923
 924     /* Make sure it fits. */
 925     ASSERT (e->type == tmp[0]);
 926     ASSERT (e->track == tmp[1]);
 927   }
 928
 929   t = vec_elt_at_index (em->event_types, e->type);
 930
 931   unserialize (m, unserialize_f64, &e->time);
 932
 933   d = e->data;
 934   p = (u8 *) t->format_args;
 935
 936   while (p && *p)
 937     {
 938       uword n_digits, n_bytes = 0;
 939       u32 tmp;
 940
 941       n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
 942
 943       switch (p[0])
 944         {
 945         case 'i':
 946         case 't':
 947         case 'T':
 948           if (n_bytes == 1)
 949             {
 950               unserialize_integer (m, &tmp, sizeof (u8));
 951               d[0] = tmp;
 952             }
 953           else if (n_bytes == 2)
 954             {
 955               unserialize_integer (m, &tmp, sizeof (u16));
 956               clib_mem_unaligned (d, u16) = tmp;
 957             }
 958           else if (n_bytes == 4)
 959             {
 960               unserialize_integer (m, &tmp, sizeof (u32));
 961               clib_mem_unaligned (d, u32) = tmp;
 962             }
 963           else if (n_bytes == 8)
 964             {
 965               u64 x;
 966               unserialize (m, unserialize_64, &x);
 967               clib_mem_unaligned (d, u64) = x;
 968             }
 969           else
 970             ASSERT (0);
 971           break;
 972
 973         case 's':
 974           {
 975             char *t;
 976             unserialize_cstring (m, &t);
 977             if (n_bytes == 0)
 978               n_bytes = strlen (t) + 1;
 979             clib_memcpy (d, t, clib_min (n_bytes, vec_len (t)));
 980             vec_free (t);
 981             break;
 982           }
 983
 984         case 'f':
 985           if (n_bytes == 4)
 986             {
 987               f32 x;
 988               unserialize (m, unserialize_f32, &x);
 989               clib_mem_unaligned (d, f32) = x;
 990             }
 991           else if (n_bytes == 8)
 992             {
 993               f64 x;
 994               unserialize (m, unserialize_f64, &x);
 995               clib_mem_unaligned (d, f64) = x;
 996             }
 997           else
 998             ASSERT (0);
 999           break;
1000
1001         default:
1002           ASSERT (0);
1003           break;
1004         }
1005
1006       p += 1 + n_digits;
1007       d += n_bytes;
1008     }
1009 }
1010
1011 static void
1012 serialize_elog_event_type (serialize_main_t * m, va_list * va)
1013 {
1014   elog_event_type_t *t = va_arg (*va, elog_event_type_t *);
1015   int n = va_arg (*va, int);
1016   int i, j;
1017   for (i = 0; i < n; i++)
1018     {
1019       serialize_cstring (m, t[i].format);
1020       serialize_cstring (m, t[i].format_args);
1021       serialize_integer (m, t[i].type_index_plus_one,
1022                          sizeof (t->type_index_plus_one));
1023       serialize_integer (m, t[i].n_enum_strings,
1024                          sizeof (t[i].n_enum_strings));
1025       for (j = 0; j < t[i].n_enum_strings; j++)
1026         serialize_cstring (m, t[i].enum_strings_vector[j]);
1027     }
1028 }
1029
1030 static void
1031 unserialize_elog_event_type (serialize_main_t * m, va_list * va)
1032 {
1033   elog_event_type_t *t = va_arg (*va, elog_event_type_t *);
1034   int n = va_arg (*va, int);
1035   int i, j;
1036   for (i = 0; i < n; i++)
1037     {
1038       unserialize_cstring (m, &t[i].format);
1039       unserialize_cstring (m, &t[i].format_args);
1040       unserialize_integer (m, &t[i].type_index_plus_one,
1041                            sizeof (t->type_index_plus_one));
1042       unserialize_integer (m, &t[i].n_enum_strings,
1043                            sizeof (t[i].n_enum_strings));
1044       vec_resize (t[i].enum_strings_vector, t[i].n_enum_strings);
1045       for (j = 0; j < t[i].n_enum_strings; j++)
1046         unserialize_cstring (m, &t[i].enum_strings_vector[j]);
1047     }
1048 }
1049
1050 static void
1051 serialize_elog_track (serialize_main_t * m, va_list * va)
1052 {
1053   elog_track_t *t = va_arg (*va, elog_track_t *);
1054   int n = va_arg (*va, int);
1055   int i;
1056   for (i = 0; i < n; i++)
1057     {
1058       serialize_cstring (m, t[i].name);
1059     }
1060 }
1061
1062 static void
1063 unserialize_elog_track (serialize_main_t * m, va_list * va)
1064 {
1065   elog_track_t *t = va_arg (*va, elog_track_t *);
1066   int n = va_arg (*va, int);
1067   int i;
1068   for (i = 0; i < n; i++)
1069     {
1070       unserialize_cstring (m, &t[i].name);
1071     }
1072 }
1073
1074 static void
1075 serialize_elog_time_stamp (serialize_main_t * m, va_list * va)
1076 {
1077   elog_time_stamp_t *st = va_arg (*va, elog_time_stamp_t *);
1078   serialize (m, serialize_64, st->os_nsec);
1079   serialize (m, serialize_64, st->cpu);
1080 }
1081
1082 static void
1083 unserialize_elog_time_stamp (serialize_main_t * m, va_list * va)
1084 {
1085   elog_time_stamp_t *st = va_arg (*va, elog_time_stamp_t *);
1086   unserialize (m, unserialize_64, &st->os_nsec);
1087   unserialize (m, unserialize_64, &st->cpu);
1088 }
1089
1090 static char *elog_serialize_magic = "elog v0";
1091
1092 void
1093 serialize_elog_main (serialize_main_t * m, va_list * va)
1094 {
1095   elog_main_t *em = va_arg (*va, elog_main_t *);
1096   int flush_ring = va_arg (*va, int);
1097   elog_event_t *e;
1098
1099   serialize_magic (m, elog_serialize_magic, strlen (elog_serialize_magic));
1100
1101   serialize_integer (m, em->event_ring_size, sizeof (u32));
1102
1103   elog_time_now (&em->serialize_time);
1104   serialize (m, serialize_elog_time_stamp, &em->serialize_time);
1105   serialize (m, serialize_elog_time_stamp, &em->init_time);
1106
1107   vec_serialize (m, em->event_types, serialize_elog_event_type);
1108   vec_serialize (m, em->tracks, serialize_elog_track);
1109   vec_serialize (m, em->string_table, serialize_vec_8);
1110
1111   /* Free old events (cached) in case they have changed. */
1112   if (flush_ring)
1113     {
1114       vec_free (em->events);
1115       elog_get_events (em);
1116     }
1117
1118   serialize_integer (m, vec_len (em->events), sizeof (u32));
1119
1120   /* SMP logs can easily have local time paradoxes... */
1121   vec_sort_with_function (em->events, elog_cmp);
1122
1123   vec_foreach (e, em->events) serialize (m, serialize_elog_event, em, e);
1124 }
1125
1126 void
1127 unserialize_elog_main (serialize_main_t * m, va_list * va)
1128 {
1129   elog_main_t *em = va_arg (*va, elog_main_t *);
1130   uword i;
1131   u32 rs;
1132
1133   unserialize_check_magic (m, elog_serialize_magic,
1134                            strlen (elog_serialize_magic));
1135
1136   unserialize_integer (m, &rs, sizeof (u32));
1137   em->event_ring_size = rs;
1138   elog_init (em, em->event_ring_size);
1139
1140   unserialize (m, unserialize_elog_time_stamp, &em->serialize_time);
1141   unserialize (m, unserialize_elog_time_stamp, &em->init_time);
1142   em->nsec_per_cpu_clock = elog_nsec_per_clock (em);
1143
1144   vec_unserialize (m, &em->event_types, unserialize_elog_event_type);
1145   for (i = 0; i < vec_len (em->event_types); i++)
1146     new_event_type (em, i);
1147
1148   vec_unserialize (m, &em->tracks, unserialize_elog_track);
1149   vec_unserialize (m, &em->string_table, unserialize_vec_8);
1150
1151   {
1152     u32 ne;
1153     elog_event_t *e;
1154
1155     unserialize_integer (m, &ne, sizeof (u32));
1156     vec_resize (em->events, ne);
1157     vec_foreach (e, em->events)
1158       unserialize (m, unserialize_elog_event, em, e);
1159   }
1160 }
1161
1162 /*
1163  * fd.io coding-style-patch-verification: ON
1164  *
1165  * Local Variables:
1166  * eval: (c-set-style "gnu")
1167  * End:
1168  */