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