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 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 =
 736         vec_elt_at_index (src->event_types, e->event_type);
 737
 738       /* Remap type from src -> dst. */
 739       e->event_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->event_type);
 852   u8 *d = e->data;
 853   u8 *p = (u8 *) t->format_args;
 854
 855   serialize_integer (m, e->event_type, sizeof (e->event_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->event_type));
 919     unserialize_integer (m, &tmp[1], sizeof (e->track));
 920
 921     e->event_type = tmp[0];
 922     e->track = tmp[1];
 923
 924     /* Make sure it fits. */
 925     ASSERT (e->event_type == tmp[0]);
 926     ASSERT (e->track == tmp[1]);
 927   }
 928
 929   t = vec_elt_at_index (em->event_types, e->event_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 #ifdef CLIB_UNIX
1163 clib_error_t *
1164 elog_write_file_not_inline (elog_main_t * em, char *clib_file, int flush_ring)
1165 {
1166   serialize_main_t m;
1167   clib_error_t *error;
1168
1169   error = serialize_open_clib_file (&m, clib_file);
1170   if (error)
1171     return error;
1172   error = serialize (&m, serialize_elog_main, em, flush_ring);
1173   if (!error)
1174     serialize_close (&m);
1175   return error;
1176 }
1177
1178 clib_error_t *
1179 elog_read_file_not_inline (elog_main_t * em, char *clib_file)
1180 {
1181   serialize_main_t m;
1182   clib_error_t *error;
1183
1184   error = unserialize_open_clib_file (&m, clib_file);
1185   if (error)
1186     return error;
1187   error = unserialize (&m, unserialize_elog_main, em);
1188   if (!error)
1189     unserialize_close (&m);
1190   return error;
1191 }
1192 #endif /* CLIB_UNIX */
1193
1194
1195 /*
1196  * fd.io coding-style-patch-verification: ON
1197  *
1198  * Local Variables:
1199  * eval: (c-set-style "gnu")
1200  * End:
1201  */