Line data Source code
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 0 : elog_n_events_in_buffer (elog_main_t * em)
192 : {
193 0 : 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 0 : elog_buffer_capacity (elog_main_t * em)
202 : {
203 0 : 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 20 : elog_reset_buffer (elog_main_t * em)
211 : {
212 20 : em->n_total_events = 0;
213 20 : em->n_total_events_disable_limit = ~0;
214 20 : }
215 :
216 : /** @brief Enable or disable event logging
217 : @param em elog_main_t *
218 : */
219 : always_inline void
220 575 : elog_enable_disable (elog_main_t * em, int is_enabled)
221 : {
222 575 : em->n_total_events = 0;
223 575 : em->n_total_events_disable_limit = is_enabled ? ~0 : 0;
224 575 : }
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 2021117 : elog_is_enabled (elog_main_t * em)
277 : {
278 2021117 : 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 1010560 : 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 1010560 : if (PREDICT_FALSE (!elog_is_enabled (em)))
303 0 : return em->placeholder_event.data;
304 :
305 1010560 : type_index = (word) type->type_index_plus_one - 1;
306 1010560 : track_index = (word) track->track_index_plus_one - 1;
307 1010560 : if (PREDICT_FALSE ((type_index | track_index) < 0))
308 : {
309 2454 : if (type_index < 0)
310 2454 : type_index = elog_event_type_register (em, type);
311 2454 : if (track_index < 0)
312 0 : track_index = elog_track_register (em, track);
313 : }
314 :
315 1010560 : ASSERT (track_index < vec_len (em->tracks));
316 1010560 : ASSERT (is_pow2 (vec_len (em->event_ring)));
317 :
318 1010560 : if (em->lock)
319 1010560 : ei = clib_atomic_fetch_add (&em->n_total_events, 1);
320 : else
321 0 : ei = em->n_total_events++;
322 :
323 1010560 : ei &= em->event_ring_size - 1;
324 1010560 : e = vec_elt_at_index (em->event_ring, ei);
325 :
326 1010560 : e->time_cycles = cpu_time;
327 1010560 : e->event_type = type_index;
328 1010560 : e->track = track_index;
329 :
330 : /* Return user data for caller to fill in. */
331 1010560 : 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 1010557 : 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 1010557 : if (PREDICT_FALSE (!elog_is_enabled (em)))
357 0 : return em->placeholder_event.data;
358 1010557 : 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 0 : elog (elog_main_t * em, elog_event_type_t * type, u32 data)
368 : {
369 0 : u32 *d = elog_event_data_not_inline (em,
370 : type,
371 : &em->default_track,
372 : clib_cpu_time_now ());
373 0 : d[0] = data;
374 0 : }
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 0 : elog_track (elog_main_t * em, elog_event_type_t * type, elog_track_t * track,
399 : u32 data)
400 : {
401 0 : u32 *d = elog_event_data_not_inline (em,
402 : type,
403 : track,
404 : clib_cpu_time_now ());
405 0 : d[0] = data;
406 0 : }
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 1010557 : elog_data (elog_main_t * em, elog_event_type_t * type, elog_track_t * track)
427 : {
428 1010557 : 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 0 : 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 0 : error = serialize_open_clib_file (&m, clib_file);
539 0 : if (error)
540 0 : return error;
541 0 : error = serialize (&m, serialize_elog_main, em, flush_ring);
542 0 : if (!error)
543 0 : serialize_close (&m);
544 0 : 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 : */
|
