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