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