FD.io VPP  v16.12-rc0-308-g931be3a
Vector Packet Processing
elog.h
Go to the documentation of this file.
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. */
55 
56  /* Absolute time as floating point number in seconds. */
58  };
59 
60  /* Event type index. */
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. */
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. */
77 
78  /* String table as a vector constructed when type is registered. */
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. */
98 
99  /* String table for enum/number to string formatting. */
100  char *enum_strings[];
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. */
111 } elog_track_t;
112 
113 typedef struct
114 {
115  /* CPU cycle counter. */
117 
118  /* OS timer in nano secs since epoch Jan 1 1970. */
121 
122 typedef struct
123 {
124  /* Total number of events in buffer. */
126 
127  /* When count reaches limit logging is disabled. This is
128  used for event triggers. */
130 
131  /* Dummy event to use when logger is disabled. */
133 
134  /* Power of 2 number of elements in ring. */
136 
137  /* Vector of events (circular buffer). Power of 2 size.
138  Used when events are being collected. */
140 
141  /* Vector of event types. */
143 
144  /* Hash table mapping type format to type index. */
146 
147  /* Events may refer to strings in string table. */
149 
150  /* Vector of tracks. */
152 
153  /* Default track. */
155 
156  /* Place holder for CPU clock frequency. */
158 
160 
161  /* SMP lock, non-zero means locking required */
163 
164  /* Use serialize_time and init_time to give estimate for
165  cpu clock frequency. */
167 
168  /* Vector of events converted to generic form after collection. */
170 } elog_main_t;
171 
174 {
175  return clib_min (em->n_total_events, em->event_ring_size);
176 }
177 
180 {
181  return em->event_ring_size;
182 }
183 
184 always_inline void
186 {
187  em->n_total_events = 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
204 {
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
212 {
214  em->n_total_events + vec_len (em->event_ring) / 2;
215 }
216 
217 /* External function to register types/tracks. */
220 
223 {
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 *
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 *
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 {
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
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
313  u32 data)
314 {
316  type,
317  track,
318  clib_cpu_time_now ());
319  d[0] = data;
320 }
321 
322 always_inline void
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 *
335 {
336  return elog_event_data_not_inline (em, type, track, clib_cpu_time_now ());
337 }
338 
339 always_inline void *
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. */
401 
402 /* Convert ievents to events and return them as a vector with no side effects. */
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
422 {
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 
437 {
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  */
static void elog_enable_disable(elog_main_t *em, int is_enabled)
Definition: elog.h:192
char ** enum_strings_vector
Definition: elog.h:79
f64 time
Definition: elog.h:57
elog_time_stamp_t serialize_time
Definition: elog.h:159
static void * elog_data_inline(elog_main_t *em, elog_event_type_t *type, elog_track_t *track)
Definition: elog.h:340
u32 elog_string(elog_main_t *em, char *format,...)
Definition: elog.c:525
#define clib_min(x, y)
Definition: clib.h:326
u64 time_cycles
Definition: elog.h:54
void serialize_elog_main(serialize_main_t *m, va_list *va)
Definition: elog.c:990
u8 * format_elog_event(u8 *s, va_list *va)
Definition: elog.c:288
static u64 clib_cpu_time_now(void)
Definition: time.h:73
word elog_event_type_register(elog_main_t *em, elog_event_type_t *t)
Definition: elog.c:103
elog_event_t dummy_event
Definition: elog.h:132
char * format
Definition: elog.h:82
void unserialize_elog_main(serialize_main_t *m, va_list *va)
Definition: elog.c:1020
u8 data[20]
Definition: elog.h:69
u32 n_enum_strings
Definition: elog.h:97
static void * elog_event_data_not_inline(elog_main_t *em, elog_event_type_t *type, elog_track_t *track, u64 cpu_time)
Definition: elog.h:279
#define clib_smp_atomic_add(addr, increment)
Definition: smp.h:46
clib_error_t * serialize_open_unix_file(serialize_main_t *m, char *file)
Definition: serialize.c:1235
clib_error_t * unserialize_open_unix_file(serialize_main_t *m, char *file)
Definition: serialize.c:1241
#define always_inline
Definition: clib.h:84
static void elog_disable_after_events(elog_main_t *em, uword n)
Definition: elog.h:203
u32 type_index_plus_one
Definition: elog.h:76
#define vec_elt_at_index(v, i)
Get vector value at index i checking that i is in bounds.
static clib_error_t * elog_write_file(elog_main_t *em, char *unix_file)
Definition: elog.h:421
uword * lock
Definition: elog.h:162
unsigned long u64
Definition: types.h:89
char * format_args
Definition: elog.h:91
uword * event_type_by_format
Definition: elog.h:145
elog_event_type_t * event_types
Definition: elog.h:142
void elog_init(elog_main_t *em, u32 n_events)
Definition: elog.c:457
static void elog_inline(elog_main_t *em, elog_event_type_t *type, u32 data)
Definition: elog.h:302
char * name
Definition: elog.h:106
void elog_alloc(elog_main_t *em, u32 n_events)
Definition: elog.c:443
elog_event_t * event_ring
Definition: elog.h:139
#define PREDICT_FALSE(x)
Definition: clib.h:97
f64 nsec_per_cpu_clock
Definition: elog.h:166
static void elog(elog_main_t *em, elog_event_type_t *type, u32 data)
Definition: elog.h:291
word elog_track_register(elog_main_t *em, elog_track_t *t)
Definition: elog.c:190
clib_error_t * serialize(serialize_main_t *m,...)
Definition: serialize.c:671
static uword elog_n_events_in_buffer(elog_main_t *em)
Definition: elog.h:173
u32 track_index_plus_one
Definition: elog.h:110
u32 n_total_events_disable_limit
Definition: elog.h:129
void unserialize_close(serialize_main_t *m)
Definition: serialize.c:876
void elog_time_now(elog_time_stamp_t *et)
Definition: elog.c:400
#define ASSERT(truth)
unsigned int u32
Definition: types.h:88
static void elog_reset_buffer(elog_main_t *em)
Definition: elog.h:185
uword event_ring_size
Definition: elog.h:135
void serialize_close(serialize_main_t *m)
Definition: serialize.c:869
clib_error_t * unserialize(serialize_main_t *m,...)
Definition: serialize.c:683
u16 track
Definition: elog.h:66
clib_time_t cpu_timer
Definition: elog.h:157
static uword is_pow2(uword x)
Definition: clib.h:266
u8 * format_elog_track(u8 *s, va_list *va)
Definition: elog.c:391
u64 uword
Definition: types.h:112
elog_event_t * events
Definition: elog.h:169
unsigned short u16
Definition: types.h:57
i64 word
Definition: types.h:111
#define vec_len(v)
Number of elements in vector (rvalue-only, NULL tolerant)
double f64
Definition: types.h:142
unsigned char u8
Definition: types.h:56
u16 type
Definition: elog.h:61
static uword elog_is_enabled(elog_main_t *em)
Definition: elog.h:222
Definition: unix.h:49
elog_track_t * tracks
Definition: elog.h:151
static void elog_track(elog_main_t *em, elog_event_type_t *type, elog_track_t *track, u32 data)
Definition: elog.h:312
static void * elog_data(elog_main_t *em, elog_event_type_t *type, elog_track_t *track)
Definition: elog.h:334
static clib_error_t * elog_read_file(elog_main_t *em, char *unix_file)
Definition: elog.h:436
char * string_table
Definition: elog.h:148
u8 * format(u8 *s, const char *fmt,...)
Definition: format.c:418
elog_track_t default_track
Definition: elog.h:154
u32 n_total_events
Definition: elog.h:125
elog_event_t * elog_get_events(elog_main_t *em)
Definition: elog.c:543
elog_event_t * elog_peek_events(elog_main_t *em)
Definition: elog.c:500
static void elog_track_inline(elog_main_t *em, elog_event_type_t *type, elog_track_t *track, u32 data)
Definition: elog.h:323
void elog_merge(elog_main_t *dst, u8 *dst_tag, elog_main_t *src, u8 *src_tag)
Definition: elog.c:607
void * elog_event_data(elog_main_t *em, elog_event_type_t *type, elog_track_t *track, u64 cpu_time)
Definition: elog.c:65
static void * elog_event_data_inline(elog_main_t *em, elog_event_type_t *type, elog_track_t *track, u64 cpu_time)
Definition: elog.h:230
static uword elog_buffer_capacity(elog_main_t *em)
Definition: elog.h:179
static void elog_disable_trigger(elog_main_t *em)
Definition: elog.h:211