vppinfra/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 logging with much thanks to Dave Barach. */
  39
  40 #ifndef included_clib_elog_h
  41 #define included_clib_elog_h
  42
  43 #include <vppinfra/cache.h>
  44 #include <vppinfra/error.h>     /* for ASSERT */
  45 #include <vppinfra/serialize.h>
  46 #include <vppinfra/time.h>      /* for clib_cpu_time_now */
  47 #include <vppinfra/mhash.h>
  48
  49 typedef struct
  50 {
  51   union
  52   {
  53     /* Absolute time stamp in CPU clock cycles. */
  54     u64 time_cycles;
  55
  56     /* Absolute time as floating point number in seconds. */
  57     f64 time;
  58   };
  59
  60   /* Event type index. */
  61   u16 type;
  62
  63   /* Track for this event.  Tracks allow events to be sorted and
  64      displayed by track.  Think of 2 dimensional display with time and
  65      track being the x and y axes. */
  66   u16 track;
  67
  68   /* 20-bytes of data follows and pads to 32 bytes. */
  69   u8 data[20];
  70 } elog_event_t;
  71
  72 typedef struct
  73 {
  74   /* Type index plus one assigned to this type.
  75      This is used to mark type as seen. */
  76   u32 type_index_plus_one;
  77
  78   /* String table as a vector constructed when type is registered. */
  79   char **enum_strings_vector;
  80
  81   /* Format string. (example: "my-event (%d,%d)"). */
  82   char *format;
  83
  84   /* Specifies how arguments to format are parsed from event data.
  85      String of characters '0' '1' or '2' '3' to specify log2 size of data
  86      (e.g. for u8, u16, u32 or u64),
  87      's' means a null-terminated C string
  88      't' means argument is an index into enum string table for this type.
  89      'e' is a float,
  90      'f' is a double. */
  91   char *format_args;
  92
  93   /* Function name generating event. */
  94   char *function;
  95
  96   /* Number of elements in string enum table. */
  97   u32 n_enum_strings;
  98
  99   /* String table for enum/number to string formatting. */
 100   char *enum_strings[];
 101 } elog_event_type_t;
 102
 103 typedef struct
 104 {
 105   /* Track name vector. */
 106   char *name;
 107
 108   /* Set to one when track has been added to
 109      main structure. */
 110   u32 track_index_plus_one;
 111 } elog_track_t;
 112
 113 typedef struct
 114 {
 115   /* CPU cycle counter. */
 116   u64 cpu;
 117
 118   /* OS timer in nano secs since epoch Jan 1 1970. */
 119   u64 os_nsec;
 120 } elog_time_stamp_t;
 121
 122 typedef struct
 123 {
 124   /* Total number of events in buffer. */
 125   u32 n_total_events;
 126
 127   /* When count reaches limit logging is disabled.  This is
 128      used for event triggers. */
 129   u32 n_total_events_disable_limit;
 130
 131   /* Dummy event to use when logger is disabled. */
 132   elog_event_t dummy_event;
 133
 134   /* Power of 2 number of elements in ring. */
 135   uword event_ring_size;
 136
 137   /* Vector of events (circular buffer).  Power of 2 size.
 138      Used when events are being collected. */
 139   elog_event_t *event_ring;
 140
 141   /* Vector of event types. */
 142   elog_event_type_t *event_types;
 143
 144   /* Hash table mapping type format to type index. */
 145   uword *event_type_by_format;
 146
 147   /* Events may refer to strings in string table. */
 148   char *string_table;
 149
 150   /* Vector of tracks. */
 151   elog_track_t *tracks;
 152
 153   /* Default track. */
 154   elog_track_t default_track;
 155
 156   /* Place holder for CPU clock frequency. */
 157   clib_time_t cpu_timer;
 158
 159   elog_time_stamp_t init_time, serialize_time;
 160
 161   /* SMP lock, non-zero means locking required */
 162   uword *lock;
 163
 164   /* Use serialize_time and init_time to give estimate for
 165      cpu clock frequency. */
 166   f64 nsec_per_cpu_clock;
 167
 168   /* Vector of events converted to generic form after collection. */
 169   elog_event_t *events;
 170 } elog_main_t;
 171
 172 always_inline uword
 173 elog_n_events_in_buffer (elog_main_t * em)
 174 {
 175   return clib_min (em->n_total_events, em->event_ring_size);
 176 }
 177
 178 always_inline uword
 179 elog_buffer_capacity (elog_main_t * em)
 180 {
 181   return em->event_ring_size;
 182 }
 183
 184 always_inline void
 185 elog_reset_buffer (elog_main_t * em)
 186 {
 187   em->n_total_events = 0;
 188   em->n_total_events_disable_limit = ~0;
 189 }
 190
 191 always_inline void
 192 elog_enable_disable (elog_main_t * em, int is_enabled)
 193 {
 194   em->n_total_events = 0;
 195   em->n_total_events_disable_limit = is_enabled ? ~0 : 0;
 196 }
 197
 198 /* Disable logging after specified number of ievents have been logged.
 199    This is used as a "debug trigger" when a certain event has occurred.
 200    Events will be logged both before and after the "event" but the
 201    event will not be lost as long as N < RING_SIZE. */
 202 always_inline void
 203 elog_disable_after_events (elog_main_t * em, uword n)
 204 {
 205   em->n_total_events_disable_limit = em->n_total_events + n;
 206 }
 207
 208 /* Signal a trigger.  We do this when we encounter an event that we want to save
 209    context around (before and after). */
 210 always_inline void
 211 elog_disable_trigger (elog_main_t * em)
 212 {
 213   em->n_total_events_disable_limit =
 214     em->n_total_events + vec_len (em->event_ring) / 2;
 215 }
 216
 217 /* External function to register types/tracks. */
 218 word elog_event_type_register (elog_main_t * em, elog_event_type_t * t);
 219 word elog_track_register (elog_main_t * em, elog_track_t * t);
 220
 221 always_inline uword
 222 elog_is_enabled (elog_main_t * em)
 223 {
 224   return em->n_total_events < em->n_total_events_disable_limit;
 225 }
 226
 227 /* Add an event to the log.  Returns a pointer to the
 228    data for caller to write into. */
 229 always_inline void *
 230 elog_event_data_inline (elog_main_t * em,
 231                         elog_event_type_t * type,
 232                         elog_track_t * track, u64 cpu_time)
 233 {
 234   elog_event_t *e;
 235   uword ei;
 236   word type_index, track_index;
 237
 238   /* Return the user dummy memory to scribble data into. */
 239   if (PREDICT_FALSE (!elog_is_enabled (em)))
 240     return em->dummy_event.data;
 241
 242   type_index = (word) type->type_index_plus_one - 1;
 243   track_index = (word) track->track_index_plus_one - 1;
 244   if (PREDICT_FALSE ((type_index | track_index) < 0))
 245     {
 246       if (type_index < 0)
 247         type_index = elog_event_type_register (em, type);
 248       if (track_index < 0)
 249         track_index = elog_track_register (em, track);
 250     }
 251
 252   ASSERT (type_index < vec_len (em->event_types));
 253   ASSERT (track_index < vec_len (em->tracks));
 254   ASSERT (is_pow2 (vec_len (em->event_ring)));
 255
 256   if (em->lock)
 257     ei = clib_smp_atomic_add (&em->n_total_events, 1);
 258   else
 259     ei = em->n_total_events++;
 260
 261   ei &= em->event_ring_size - 1;
 262   e = vec_elt_at_index (em->event_ring, ei);
 263
 264   e->time_cycles = cpu_time;
 265   e->type = type_index;
 266   e->track = track_index;
 267
 268   /* Return user data for caller to fill in. */
 269   return e->data;
 270 }
 271
 272 /* External version of inline. */
 273 void *elog_event_data (elog_main_t * em,
 274                        elog_event_type_t * type,
 275                        elog_track_t * track, u64 cpu_time);
 276
 277 /* Non-inline version. */
 278 always_inline void *
 279 elog_event_data_not_inline (elog_main_t * em,
 280                             elog_event_type_t * type,
 281                             elog_track_t * track, u64 cpu_time)
 282 {
 283   /* Return the user dummy memory to scribble data into. */
 284   if (PREDICT_FALSE (!elog_is_enabled (em)))
 285     return em->dummy_event.data;
 286   return elog_event_data (em, type, track, cpu_time);
 287 }
 288
 289 /* Most common forms: log a single 32 bit datum, w / w-out track */
 290 always_inline void
 291 elog (elog_main_t * em, elog_event_type_t * type, u32 data)
 292 {
 293   u32 *d = elog_event_data_not_inline (em,
 294                                        type,
 295                                        &em->default_track,
 296                                        clib_cpu_time_now ());
 297   d[0] = data;
 298 }
 299
 300 /* Inline version of above. */
 301 always_inline void
 302 elog_inline (elog_main_t * em, elog_event_type_t * type, u32 data)
 303 {
 304   u32 *d = elog_event_data_inline (em,
 305                                    type,
 306                                    &em->default_track,
 307                                    clib_cpu_time_now ());
 308   d[0] = data;
 309 }
 310
 311 always_inline void
 312 elog_track (elog_main_t * em, elog_event_type_t * type, elog_track_t * track,
 313             u32 data)
 314 {
 315   u32 *d = elog_event_data_not_inline (em,
 316                                        type,
 317                                        track,
 318                                        clib_cpu_time_now ());
 319   d[0] = data;
 320 }
 321
 322 always_inline void
 323 elog_track_inline (elog_main_t * em, elog_event_type_t * type,
 324                    elog_track_t * track, u32 data)
 325 {
 326   u32 *d = elog_event_data_inline (em,
 327                                    type,
 328                                    track,
 329                                    clib_cpu_time_now ());
 330   d[0] = data;
 331 }
 332
 333 always_inline void *
 334 elog_data (elog_main_t * em, elog_event_type_t * type, elog_track_t * track)
 335 {
 336   return elog_event_data_not_inline (em, type, track, clib_cpu_time_now ());
 337 }
 338
 339 always_inline void *
 340 elog_data_inline (elog_main_t * em, elog_event_type_t * type,
 341                   elog_track_t * track)
 342 {
 343   return elog_event_data_inline (em, type, track, clib_cpu_time_now ());
 344 }
 345
 346 /* Macro shorthands for generating/declaring events. */
 347 #define __ELOG_TYPE_VAR(f) f
 348 #define __ELOG_TRACK_VAR(f) f
 349
 350 #define ELOG_TYPE_DECLARE(f) static elog_event_type_t __ELOG_TYPE_VAR(f)
 351
 352 #define ELOG_TYPE_INIT_FORMAT_AND_FUNCTION(fmt,func) \
 353   { .format = fmt, .function = func, }
 354
 355 #define ELOG_TYPE_INIT(fmt) \
 356   ELOG_TYPE_INIT_FORMAT_AND_FUNCTION(fmt,(char *) __FUNCTION__)
 357
 358 #define ELOG_TYPE_DECLARE_HELPER(f,fmt,func)            \
 359   static elog_event_type_t __ELOG_TYPE_VAR(f) =         \
 360     ELOG_TYPE_INIT_FORMAT_AND_FUNCTION (fmt, func)
 361
 362 #define ELOG_TYPE_DECLARE_FORMAT_AND_FUNCTION(f,fmt)            \
 363   ELOG_TYPE_DECLARE_HELPER (f, fmt, (char *) __FUNCTION__)
 364
 365 #define ELOG_TYPE_DECLARE_FORMAT(f,fmt)         \
 366   ELOG_TYPE_DECLARE_HELPER (f, fmt, 0)
 367
 368 /* Shorthands with and without __FUNCTION__.
 369    D for decimal; X for hex.  F for __FUNCTION__. */
 370 #define ELOG_TYPE(f,fmt) ELOG_TYPE_DECLARE_FORMAT_AND_FUNCTION(f,fmt)
 371 #define ELOG_TYPE_D(f)  ELOG_TYPE_DECLARE_FORMAT (f, #f " %d")
 372 #define ELOG_TYPE_X(f)  ELOG_TYPE_DECLARE_FORMAT (f, #f " 0x%x")
 373 #define ELOG_TYPE_DF(f) ELOG_TYPE_DECLARE_FORMAT_AND_FUNCTION (f, #f " %d")
 374 #define ELOG_TYPE_XF(f) ELOG_TYPE_DECLARE_FORMAT_AND_FUNCTION (f, #f " 0x%x")
 375 #define ELOG_TYPE_FD(f) ELOG_TYPE_DECLARE_FORMAT_AND_FUNCTION (f, #f " %d")
 376 #define ELOG_TYPE_FX(f) ELOG_TYPE_DECLARE_FORMAT_AND_FUNCTION (f, #f " 0x%x")
 377
 378 #define ELOG_TRACK_DECLARE(f) static elog_track_t __ELOG_TRACK_VAR(f)
 379 #define ELOG_TRACK(f) ELOG_TRACK_DECLARE(f) = { .name = #f, }
 380
 381 /* Log 32 bits of data. */
 382 #define ELOG(em,f,data) elog ((em), &__ELOG_TYPE_VAR(f), data)
 383 #define ELOG_INLINE(em,f,data) elog_inline ((em), &__ELOG_TYPE_VAR(f), data)
 384
 385 /* Return data pointer to fill in. */
 386 #define ELOG_TRACK_DATA(em,f,track) \
 387   elog_data ((em), &__ELOG_TYPE_VAR(f), &__ELOG_TRACK_VAR(track))
 388 #define ELOG_TRACK_DATA_INLINE(em,f,track) \
 389   elog_data_inline ((em), &__ELOG_TYPE_VAR(f), &__ELOG_TRACK_VAR(track))
 390
 391 /* Shorthand with default track. */
 392 #define ELOG_DATA(em,f) elog_data ((em), &__ELOG_TYPE_VAR (f), &(em)->default_track)
 393 #define ELOG_DATA_INLINE(em,f) elog_data_inline ((em), &__ELOG_TYPE_VAR (f), &(em)->default_track)
 394
 395 u32 elog_string (elog_main_t * em, char *format, ...);
 396 void elog_time_now (elog_time_stamp_t * et);
 397
 398 /* Convert ievents to events and return them as a vector.
 399    Sets em->events to resulting vector. */
 400 elog_event_t *elog_get_events (elog_main_t * em);
 401
 402 /* Convert ievents to events and return them as a vector with no side effects. */
 403 elog_event_t *elog_peek_events (elog_main_t * em);
 404
 405 /* Merge two logs, add supplied track tags. */
 406 void elog_merge (elog_main_t * dst, u8 * dst_tag,
 407                  elog_main_t * src, u8 * src_tag);
 408
 409 /* 2 arguments elog_main_t and elog_event_t to format event or track name. */
 410 u8 *format_elog_event (u8 * s, va_list * va);
 411 u8 *format_elog_track (u8 * s, va_list * va);
 412
 413 void serialize_elog_main (serialize_main_t * m, va_list * va);
 414 void unserialize_elog_main (serialize_main_t * m, va_list * va);
 415
 416 void elog_init (elog_main_t * em, u32 n_events);
 417 void elog_alloc (elog_main_t * em, u32 n_events);
 418
 419 #ifdef CLIB_UNIX
 420 always_inline clib_error_t *
 421 elog_write_file (elog_main_t * em, char *unix_file)
 422 {
 423   serialize_main_t m;
 424   clib_error_t *error;
 425
 426   error = serialize_open_unix_file (&m, unix_file);
 427   if (error)
 428     return error;
 429   error = serialize (&m, serialize_elog_main, em);
 430   if (!error)
 431     serialize_close (&m);
 432   return error;
 433 }
 434
 435 always_inline clib_error_t *
 436 elog_read_file (elog_main_t * em, char *unix_file)
 437 {
 438   serialize_main_t m;
 439   clib_error_t *error;
 440
 441   error = unserialize_open_unix_file (&m, unix_file);
 442   if (error)
 443     return error;
 444   error = unserialize (&m, unserialize_elog_main, em);
 445   if (!error)
 446     unserialize_close (&m);
 447   return error;
 448 }
 449
 450 #endif /* CLIB_UNIX */
 451
 452 #endif /* included_clib_elog_h */
 453
 454 /*
 455  * fd.io coding-style-patch-verification: ON
 456  *
 457  * Local Variables:
 458  * eval: (c-set-style "gnu")
 459  * End:
 460  */