src/vppinfra/elog.c

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