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