src/vppinfra/elog.h

   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 /* High speed event logger */
  39
  40 /** \file
  41     The fine-grained event logger allows lightweight, thread-safe
  42     event logging at minimum cost. In typical operation, logging
  43     a single event costs around 80ns on x86_64. It's appropriate
  44     for at-least per-frame event-logging in vector packet processing.
  45
  46     See https://wiki.fd.io/view/VPP/elog for more information.
  47 */
  48
  49 #ifndef included_clib_elog_h
  50 #define included_clib_elog_h
  51
  52 #include <vppinfra/cache.h>
  53 #include <vppinfra/error.h>     /* for ASSERT */
  54 #include <vppinfra/serialize.h>
  55 #include <vppinfra/time.h>      /* for clib_cpu_time_now */
  56 #include <vppinfra/hash.h>
  57 #include <vppinfra/mhash.h>
  58
  59 typedef struct
  60 {
  61   union
  62   {
  63     /** Absolute time stamp in CPU clock cycles. */
  64     u64 time_cycles;
  65
  66     /** Absolute time as floating point number in seconds. */
  67     f64 time;
  68   };
  69
  70   /** Event type index. */
  71   u16 event_type;
  72
  73   /** Track for this event.  Tracks allow events to be sorted and
  74      displayed by track.  Think of 2 dimensional display with time and
  75      track being the x and y axes. */
  76   u16 track;
  77
  78   /** 20-bytes of data follows, pads to 32 bytes. */
  79   u8 data[20];
  80 } elog_event_t;
  81
  82 typedef struct
  83 {
  84   /** Type index plus one assigned to this type.
  85      This is used to mark type as seen. */
  86   u32 type_index_plus_one;
  87
  88   /** String table as a vector constructed when type is registered. */
  89   char **enum_strings_vector;
  90
  91   /** Format string. (example: "my-event (%d,%d)"). */
  92   char *format;
  93
  94   /** Specifies how arguments to format are parsed from event data.
  95      String of characters '0' '1' or '2' '3' to specify log2 size of data
  96      (e.g. for u8, u16, u32 or u64),
  97      's' means a null-terminated C string
  98      't' means argument is an index into enum string table for this type.
  99      'e' is a float,
 100      'f' is a double. */
 101   char *format_args;
 102
 103   /** Function name generating event. */
 104   char *function;
 105
 106   /** Number of elements in string enum table. */
 107   u32 n_enum_strings;
 108
 109   /** String table for enum/number to string formatting. */
 110   char *enum_strings[];
 111 } elog_event_type_t;
 112
 113 typedef struct
 114 {
 115   /** Track name vector. */
 116   char *name;
 117
 118   /** Set to one when track has been added to
 119      main structure. */
 120   u32 track_index_plus_one;
 121 } elog_track_t;
 122
 123 typedef struct
 124 {
 125   /** CPU cycle counter. */
 126   u64 cpu;
 127
 128   /** OS timer in nano secs since epoch 3/30/2017, see elog_time_now() */
 129   u64 os_nsec;
 130 } elog_time_stamp_t;
 131
 132 typedef struct
 133 {
 134   /** Total number of events in buffer. */
 135   u32 n_total_events;
 136
 137   /** When count reaches limit logging is disabled.  This is
 138      used for event triggers. */
 139   u32 n_total_events_disable_limit;
 140
 141   /** Dummy event to use when logger is disabled. */
 142   elog_event_t placeholder_event;
 143
 144   /** Power of 2 number of elements in ring. */
 145   uword event_ring_size;
 146
 147   /** Vector of events (circular buffer).  Power of 2 size.
 148       Used when events are being collected. */
 149   elog_event_t *event_ring;
 150
 151   /** Vector of event types. */
 152   elog_event_type_t *event_types;
 153
 154   /** Hash table mapping type format to type index. */
 155   uword *event_type_by_format;
 156
 157   /** Events may refer to strings in string table. */
 158   char *string_table;
 159   uword *string_table_hash;
 160   u8 *string_table_tmp;
 161
 162   /** Vector of tracks. */
 163   elog_track_t *tracks;
 164
 165   /** Default track. */
 166   elog_track_t default_track;
 167
 168   /** Place holder for CPU clock frequency. */
 169   clib_time_t cpu_timer;
 170
 171   /** Timestamps */
 172   elog_time_stamp_t init_time, serialize_time;
 173
 174   /** SMP lock, non-zero means locking required */
 175   uword *lock;
 176
 177   /** Use serialize_time and init_time to give estimate for
 178       cpu clock frequency. */
 179   f64 nsec_per_cpu_clock;
 180
 181   /** Vector of events converted to generic form after collection. */
 182   elog_event_t *events;
 183 } elog_main_t;
 184
 185 /** @brief Return number of events in the event-log buffer
 186     @param em elog_main_t *
 187     @return number of events in the buffer
 188 */
 189
 190 always_inline uword
 191 elog_n_events_in_buffer (elog_main_t * em)
 192 {
 193   return clib_min (em->n_total_events, em->event_ring_size);
 194 }
 195
 196 /** @brief Return number of events which can fit in the event buffer
 197     @param em elog_main_t *
 198     @return number of events which can fit in the buffer
 199 */
 200 always_inline uword
 201 elog_buffer_capacity (elog_main_t * em)
 202 {
 203   return em->event_ring_size;
 204 }
 205
 206 /** @brief Reset the event buffer
 207     @param em elog_main_t *
 208 */
 209 always_inline void
 210 elog_reset_buffer (elog_main_t * em)
 211 {
 212   em->n_total_events = 0;
 213   em->n_total_events_disable_limit = ~0;
 214 }
 215
 216 /** @brief Enable or disable event logging
 217     @param em elog_main_t *
 218 */
 219 always_inline void
 220 elog_enable_disable (elog_main_t * em, int is_enabled)
 221 {
 222   em->n_total_events = 0;
 223   em->n_total_events_disable_limit = is_enabled ? ~0 : 0;
 224 }
 225
 226 /** @brief disable logging after specified number of ievents have been logged.
 227
 228    This is used as a "debug trigger" when a certain event has occurred.
 229    Events will be logged both before and after the "event" but the
 230    event will not be lost as long as N < RING_SIZE.
 231
 232    @param em elog_main_t *
 233    @param n uword number of events before disabling event logging
 234 */
 235 always_inline void
 236 elog_disable_after_events (elog_main_t * em, uword n)
 237 {
 238   em->n_total_events_disable_limit = em->n_total_events + n;
 239 }
 240
 241 /* @brief mid-buffer logic-analyzer trigger
 242
 243    Currently, only midpoint triggering is supported, but it's pretty obvious
 244    how to generalize the scheme.
 245    @param em elog_main_t *
 246 */
 247 always_inline void
 248 elog_disable_trigger (elog_main_t * em)
 249 {
 250   em->n_total_events_disable_limit =
 251     em->n_total_events + vec_len (em->event_ring) / 2;
 252 }
 253
 254 /** @brief register an event type
 255     @param em elog_main_t *
 256     @param t elog_event_type_t * event to register
 257     @return type index
 258     @warning Typically not called directly
 259 */
 260
 261 word elog_event_type_register (elog_main_t * em, elog_event_type_t * t);
 262
 263 /** @brief register an event track
 264     @param em elog_main_t *
 265     @param t elog_track_t * track to register
 266     @return track index
 267     @note this function is often called directly
 268 */
 269 word elog_track_register (elog_main_t * em, elog_track_t * t);
 270
 271 /** @brief event logging enabled predicate
 272     @param em elog_main_t *
 273     @return 1 if enabled, 0 if not enabled
 274 */
 275 always_inline uword
 276 elog_is_enabled (elog_main_t * em)
 277 {
 278   return em->n_total_events < em->n_total_events_disable_limit;
 279 }
 280
 281 /** @brief Allocate an event to be filled in by the caller
 282
 283     Not normally called directly; this function underlies the
 284     ELOG_DATA and ELOG_TRACK_DATA macros
 285
 286     @param em elog_main_t *
 287     @param type elog_event_type_t * type
 288     @param track elog_track_t * track
 289     @param cpu_time u64 current cpu tick value
 290     @returns event to be filled in
 291 */
 292 always_inline void *
 293 elog_event_data_inline (elog_main_t * em,
 294                         elog_event_type_t * type,
 295                         elog_track_t * track, u64 cpu_time)
 296 {
 297   elog_event_t *e;
 298   uword ei;
 299   word type_index, track_index;
 300
 301   /* Return the user placeholder memory to scribble data into. */
 302   if (PREDICT_FALSE (!elog_is_enabled (em)))
 303     return em->placeholder_event.data;
 304
 305   type_index = (word) type->type_index_plus_one - 1;
 306   track_index = (word) track->track_index_plus_one - 1;
 307   if (PREDICT_FALSE ((type_index | track_index) < 0))
 308     {
 309       if (type_index < 0)
 310         type_index = elog_event_type_register (em, type);
 311       if (track_index < 0)
 312         track_index = elog_track_register (em, track);
 313     }
 314
 315   ASSERT (track_index < vec_len (em->tracks));
 316   ASSERT (is_pow2 (vec_len (em->event_ring)));
 317
 318   if (em->lock)
 319     ei = clib_atomic_fetch_add (&em->n_total_events, 1);
 320   else
 321     ei = em->n_total_events++;
 322
 323   ei &= em->event_ring_size - 1;
 324   e = vec_elt_at_index (em->event_ring, ei);
 325
 326   e->time_cycles = cpu_time;
 327   e->event_type = type_index;
 328   e->track = track_index;
 329
 330   /* Return user data for caller to fill in. */
 331   return e->data;
 332 }
 333
 334 /* External version of inline. */
 335 void *elog_event_data (elog_main_t * em,
 336                        elog_event_type_t * type,
 337                        elog_track_t * track, u64 cpu_time);
 338
 339 /** @brief Allocate an event to be filled in by the caller, non-inline
 340
 341     Not normally called directly; this function underlies the
 342     ELOG_DATA and ELOG_TRACK_DATA macros
 343
 344     @param em elog_main_t *
 345     @param type elog_event_type_t * type
 346     @param track elog_track_t * track
 347     @param cpu_time u64 current cpu tick value
 348     @returns event to be filled in
 349 */
 350 always_inline void *
 351 elog_event_data_not_inline (elog_main_t * em,
 352                             elog_event_type_t * type,
 353                             elog_track_t * track, u64 cpu_time)
 354 {
 355   /* Return the user placeholder memory to scribble data into. */
 356   if (PREDICT_FALSE (!elog_is_enabled (em)))
 357     return em->placeholder_event.data;
 358   return elog_event_data (em, type, track, cpu_time);
 359 }
 360
 361 /** @brief Log a single-datum event
 362     @param em elog_main_t *
 363     @param type elog_event_type_t * type
 364     @param data u32 single datum to capture
 365 */
 366 always_inline void
 367 elog (elog_main_t * em, elog_event_type_t * type, u32 data)
 368 {
 369   u32 *d = elog_event_data_not_inline (em,
 370                                        type,
 371                                        &em->default_track,
 372                                        clib_cpu_time_now ());
 373   d[0] = data;
 374 }
 375
 376 /** @brief Log a single-datum event, inline version
 377     @param em elog_main_t *
 378     @param type elog_event_type_t * type
 379     @param data u32 single datum to capture
 380 */
 381 always_inline void
 382 elog_inline (elog_main_t * em, elog_event_type_t * type, u32 data)
 383 {
 384   u32 *d = elog_event_data_inline (em,
 385                                    type,
 386                                    &em->default_track,
 387                                    clib_cpu_time_now ());
 388   d[0] = data;
 389 }
 390
 391 /** @brief Log a single-datum event to a specific track, non-inline version
 392     @param em elog_main_t *
 393     @param type elog_event_type_t * type
 394     @param type elog_event_track_t * track
 395     @param data u32 single datum to capture
 396 */
 397 always_inline void
 398 elog_track (elog_main_t * em, elog_event_type_t * type, elog_track_t * track,
 399             u32 data)
 400 {
 401   u32 *d = elog_event_data_not_inline (em,
 402                                        type,
 403                                        track,
 404                                        clib_cpu_time_now ());
 405   d[0] = data;
 406 }
 407
 408 /** @brief Log a single-datum event to a specific track
 409     @param em elog_main_t *
 410     @param type elog_event_type_t * type
 411     @param type elog_event_track_t * track
 412     @param data u32 single datum to capture
 413 */
 414 always_inline void
 415 elog_track_inline (elog_main_t * em, elog_event_type_t * type,
 416                    elog_track_t * track, u32 data)
 417 {
 418   u32 *d = elog_event_data_inline (em,
 419                                    type,
 420                                    track,
 421                                    clib_cpu_time_now ());
 422   d[0] = data;
 423 }
 424
 425 always_inline void *
 426 elog_data (elog_main_t * em, elog_event_type_t * type, elog_track_t * track)
 427 {
 428   return elog_event_data_not_inline (em, type, track, clib_cpu_time_now ());
 429 }
 430
 431 always_inline void *
 432 elog_data_inline (elog_main_t * em, elog_event_type_t * type,
 433                   elog_track_t * track)
 434 {
 435   return elog_event_data_inline (em, type, track, clib_cpu_time_now ());
 436 }
 437
 438 /* Macro shorthands for generating/declaring events. */
 439 #define __ELOG_TYPE_VAR(f) f
 440 #define __ELOG_TRACK_VAR(f) f
 441
 442 #define ELOG_TYPE_DECLARE(f) static elog_event_type_t __ELOG_TYPE_VAR(f)
 443
 444 #define ELOG_TYPE_INIT_FORMAT_AND_FUNCTION(fmt,func) \
 445   { .format = fmt, .function = func, }
 446
 447 #define ELOG_TYPE_INIT(fmt) \
 448   ELOG_TYPE_INIT_FORMAT_AND_FUNCTION(fmt,(char *) __FUNCTION__)
 449
 450 #define ELOG_TYPE_DECLARE_HELPER(f,fmt,func)            \
 451   static elog_event_type_t __ELOG_TYPE_VAR(f) =         \
 452     ELOG_TYPE_INIT_FORMAT_AND_FUNCTION (fmt, func)
 453
 454 #define ELOG_TYPE_DECLARE_FORMAT_AND_FUNCTION(f,fmt)            \
 455   ELOG_TYPE_DECLARE_HELPER (f, fmt, (char *) __FUNCTION__)
 456
 457 #define ELOG_TYPE_DECLARE_FORMAT(f,fmt)         \
 458   ELOG_TYPE_DECLARE_HELPER (f, fmt, 0)
 459
 460 /* Shorthands with and without __FUNCTION__.
 461    D for decimal; X for hex.  F for __FUNCTION__. */
 462 #define ELOG_TYPE(f,fmt) ELOG_TYPE_DECLARE_FORMAT_AND_FUNCTION(f,fmt)
 463 #define ELOG_TYPE_D(f)  ELOG_TYPE_DECLARE_FORMAT (f, #f " %d")
 464 #define ELOG_TYPE_X(f)  ELOG_TYPE_DECLARE_FORMAT (f, #f " 0x%x")
 465 #define ELOG_TYPE_DF(f) ELOG_TYPE_DECLARE_FORMAT_AND_FUNCTION (f, #f " %d")
 466 #define ELOG_TYPE_XF(f) ELOG_TYPE_DECLARE_FORMAT_AND_FUNCTION (f, #f " 0x%x")
 467 #define ELOG_TYPE_FD(f) ELOG_TYPE_DECLARE_FORMAT_AND_FUNCTION (f, #f " %d")
 468 #define ELOG_TYPE_FX(f) ELOG_TYPE_DECLARE_FORMAT_AND_FUNCTION (f, #f " 0x%x")
 469
 470 #define ELOG_TRACK_DECLARE(f) static elog_track_t __ELOG_TRACK_VAR(f)
 471 #define ELOG_TRACK(f) ELOG_TRACK_DECLARE(f) = { .name = #f, }
 472
 473 /* Log 32 bits of data. */
 474 #define ELOG(em,f,data) elog ((em), &__ELOG_TYPE_VAR(f), data)
 475 #define ELOG_INLINE(em,f,data) elog_inline ((em), &__ELOG_TYPE_VAR(f), data)
 476
 477 /* Return data pointer to fill in. */
 478 #define ELOG_TRACK_DATA(em,f,track) \
 479   elog_data ((em), &__ELOG_TYPE_VAR(f), &__ELOG_TRACK_VAR(track))
 480 #define ELOG_TRACK_DATA_INLINE(em,f,track) \
 481   elog_data_inline ((em), &__ELOG_TYPE_VAR(f), &__ELOG_TRACK_VAR(track))
 482
 483 /* Shorthand with default track. */
 484 #define ELOG_DATA(em,f) elog_data ((em), &__ELOG_TYPE_VAR (f), &(em)->default_track)
 485 #define ELOG_DATA_INLINE(em,f) elog_data_inline ((em), &__ELOG_TYPE_VAR (f), &(em)->default_track)
 486
 487 /** @brief add a string to the event-log string table
 488
 489     Often combined with hashing and the T4 elog format specifier to
 490     display complex strings in offline tooling
 491
 492     @param em elog_main_t *
 493     @param format char *
 494     @param VARARGS
 495     @return u32 index to add to event log
 496 */
 497 u32 elog_string (elog_main_t * em, char *format, ...);
 498
 499 void elog_time_now (elog_time_stamp_t * et);
 500
 501 /** @brief convert event ring events to events, and return them as a vector.
 502     @param em elog_main_t *
 503     @return event vector with timestamps in f64 seconds
 504     @note sets em->events to resulting vector.
 505 */
 506 elog_event_t *elog_get_events (elog_main_t * em);
 507
 508 /** @brief convert event ring events to events, and return them as a vector.
 509     @param em elog_main_t *
 510     @return event vector with timestamps in f64 seconds
 511     @note no side effects
 512 */
 513 elog_event_t *elog_peek_events (elog_main_t * em);
 514
 515 /* Merge two logs, add supplied track tags. */
 516 void elog_merge (elog_main_t * dst, u8 * dst_tag,
 517                  elog_main_t * src, u8 * src_tag, f64 align_tweak);
 518
 519 /* 2 arguments elog_main_t and elog_event_t to format event or track name. */
 520 u8 *format_elog_event (u8 * s, va_list * va);
 521 u8 *format_elog_track_name (u8 * s, va_list * va);
 522 u8 *format_elog_track (u8 * s, va_list * args);
 523
 524 void serialize_elog_main (serialize_main_t * m, va_list * va);
 525 void unserialize_elog_main (serialize_main_t * m, va_list * va);
 526
 527 void elog_init (elog_main_t * em, u32 n_events);
 528 void elog_alloc (elog_main_t * em, u32 n_events);
 529 void elog_resize (elog_main_t * em, u32 n_events);
 530
 531 #ifdef CLIB_UNIX
 532 always_inline clib_error_t *
 533 elog_write_file (elog_main_t * em, char *clib_file, int flush_ring)
 534 {
 535   serialize_main_t m;
 536   clib_error_t *error;
 537
 538   error = serialize_open_clib_file (&m, clib_file);
 539   if (error)
 540     return error;
 541   error = serialize (&m, serialize_elog_main, em, flush_ring);
 542   if (!error)
 543     serialize_close (&m);
 544   return error;
 545 }
 546
 547 clib_error_t *elog_write_file_not_inline (elog_main_t * em, char *clib_file,
 548                                           int flush_ring);
 549
 550 always_inline clib_error_t *
 551 elog_read_file (elog_main_t * em, char *clib_file)
 552 {
 553   serialize_main_t m;
 554   clib_error_t *error;
 555
 556   error = unserialize_open_clib_file (&m, clib_file);
 557   if (error)
 558     return error;
 559   error = unserialize (&m, unserialize_elog_main, em);
 560   if (!error)
 561     unserialize_close (&m);
 562   return error;
 563 }
 564
 565 clib_error_t *elog_read_file_not_inline (elog_main_t * em, char *clib_file);
 566 char *format_one_elog_event (void *em_arg, void *ep_arg);
 567
 568 #endif /* CLIB_UNIX */
 569
 570 #endif /* included_clib_elog_h */
 571
 572 /*
 573  * fd.io coding-style-patch-verification: ON
 574  *
 575  * Local Variables:
 576  * eval: (c-set-style "gnu")
 577  * End:
 578  */