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