blob: e28217cd590bd171fbf2382612fb4723fa9dd031 [file] [log] [blame]
Ed Warnickecb9cada2015-12-08 15:45:58 -07001/*
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#include <vppinfra/elog.h>
39#include <vppinfra/cache.h>
40#include <vppinfra/error.h>
41#include <vppinfra/format.h>
42#include <vppinfra/hash.h>
43#include <vppinfra/math.h>
44
Dave Barachc3799992016-08-15 11:12:27 -040045static inline void
46elog_lock (elog_main_t * em)
Ed Warnickecb9cada2015-12-08 15:45:58 -070047{
Dave Barachc3799992016-08-15 11:12:27 -040048 if (PREDICT_FALSE (em->lock != 0))
Sirshak Das2f6d7bb2018-10-03 22:53:51 +000049 while (clib_atomic_test_and_set (em->lock))
Dave Barachc3799992016-08-15 11:12:27 -040050 ;
Ed Warnickecb9cada2015-12-08 15:45:58 -070051}
52
Dave Barachc3799992016-08-15 11:12:27 -040053static inline void
54elog_unlock (elog_main_t * em)
Ed Warnickecb9cada2015-12-08 15:45:58 -070055{
Dave Barachc3799992016-08-15 11:12:27 -040056 if (PREDICT_FALSE (em->lock != 0))
Dave Barachfb6e59d2016-03-26 18:45:42 -040057 {
Dave Barachc3799992016-08-15 11:12:27 -040058 CLIB_MEMORY_BARRIER ();
Dave Barachfb6e59d2016-03-26 18:45:42 -040059 *em->lock = 0;
60 }
Ed Warnickecb9cada2015-12-08 15:45:58 -070061}
62
63/* Non-inline version. */
64void *
65elog_event_data (elog_main_t * em,
Dave Barachc3799992016-08-15 11:12:27 -040066 elog_event_type_t * type, elog_track_t * track, u64 cpu_time)
Ed Warnickecb9cada2015-12-08 15:45:58 -070067{
Dave Barachc3799992016-08-15 11:12:27 -040068 return elog_event_data_inline (em, type, track, cpu_time);
69}
Ed Warnickecb9cada2015-12-08 15:45:58 -070070
Dave Barachc3799992016-08-15 11:12:27 -040071static void
72new_event_type (elog_main_t * em, uword i)
73{
74 elog_event_type_t *t = vec_elt_at_index (em->event_types, i);
75
76 if (!em->event_type_by_format)
77 em->event_type_by_format =
78 hash_create_vec ( /* size */ 0, sizeof (u8), sizeof (uword));
Ed Warnickecb9cada2015-12-08 15:45:58 -070079
Dave Barach903fd512017-04-01 11:07:40 -040080 t->type_index_plus_one = i + 1;
Ed Warnickecb9cada2015-12-08 15:45:58 -070081 hash_set_mem (em->event_type_by_format, t->format, i);
82}
83
84static uword
85find_or_create_type (elog_main_t * em, elog_event_type_t * t)
86{
Dave Barachc3799992016-08-15 11:12:27 -040087 uword *p = hash_get_mem (em->event_type_by_format, t->format);
Ed Warnickecb9cada2015-12-08 15:45:58 -070088 uword i;
89
90 if (p)
91 i = p[0];
92 else
93 {
94 i = vec_len (em->event_types);
95 vec_add1 (em->event_types, t[0]);
96 new_event_type (em, i);
97 }
98
99 return i;
100}
101
102/* External function to register types. */
Dave Barachc3799992016-08-15 11:12:27 -0400103word
104elog_event_type_register (elog_main_t * em, elog_event_type_t * t)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700105{
Dave Barachc3799992016-08-15 11:12:27 -0400106 elog_event_type_t *static_type = t;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700107 word l;
108
109 elog_lock (em);
110
Dave Barach12c6fdc2017-06-30 08:46:24 -0400111 /* Multiple simultaneous registration attempts, */
112 if (t->type_index_plus_one > 0)
113 {
114 elog_unlock (em);
115 return t->type_index_plus_one - 1;
116 }
117
Ed Warnickecb9cada2015-12-08 15:45:58 -0700118 l = vec_len (em->event_types);
119
120 t->type_index_plus_one = 1 + l;
121
122 ASSERT (t->format);
123
124 /* If format args are not specified try to be smart about providing defaults
125 so most of the time user does not have to specify them. */
Dave Barachc3799992016-08-15 11:12:27 -0400126 if (!t->format_args)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700127 {
128 uword i, l;
Dave Barachc3799992016-08-15 11:12:27 -0400129 char *this_arg;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700130
131 l = strlen (t->format);
132 for (i = 0; i < l; i++)
133 {
134 if (t->format[i] != '%')
135 continue;
136 if (i + 1 >= l)
137 continue;
Dave Barachc3799992016-08-15 11:12:27 -0400138 if (t->format[i + 1] == '%') /* %% */
Ed Warnickecb9cada2015-12-08 15:45:58 -0700139 continue;
140
Dave Barachc3799992016-08-15 11:12:27 -0400141 switch (t->format[i + 1])
142 {
143 default:
144 case 'd':
145 case 'x':
146 case 'u':
147 this_arg = "i4"; /* size of u32 */
148 break;
149 case 'f':
150 this_arg = "f8"; /* defaults to f64 */
151 break;
152 case 's':
153 this_arg = "s0"; /* defaults to null terminated string. */
154 break;
155 }
Ed Warnickecb9cada2015-12-08 15:45:58 -0700156
Dave Barachc3799992016-08-15 11:12:27 -0400157 t->format_args =
158 (char *) format ((u8 *) t->format_args, "%s", this_arg);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700159 }
160
161 /* Null terminate. */
162 vec_add1 (t->format_args, 0);
Dave Barachc3799992016-08-15 11:12:27 -0400163 }
Ed Warnickecb9cada2015-12-08 15:45:58 -0700164
165 vec_add1 (em->event_types, t[0]);
166
167 t = em->event_types + l;
168
169 /* Make copies of strings for hashing etc. */
170 if (t->function)
171 t->format = (char *) format (0, "%s %s%c", t->function, t->format, 0);
172 else
173 t->format = (char *) format (0, "%s%c", t->format, 0);
174
175 t->format_args = (char *) format (0, "%s%c", t->format_args, 0);
176
177 /* Construct string table. */
178 {
179 uword i;
180 t->n_enum_strings = static_type->n_enum_strings;
181 for (i = 0; i < t->n_enum_strings; i++)
182 {
Dave Barachc3799992016-08-15 11:12:27 -0400183 if (!static_type->enum_strings[i])
Ed Warnickecb9cada2015-12-08 15:45:58 -0700184 static_type->enum_strings[i] = "MISSING";
Dave Barachc3799992016-08-15 11:12:27 -0400185 vec_add1 (t->enum_strings_vector,
186 (char *) format (0, "%s%c", static_type->enum_strings[i],
187 0));
Ed Warnickecb9cada2015-12-08 15:45:58 -0700188 }
189 }
190
191 new_event_type (em, l);
Dave Barachc3799992016-08-15 11:12:27 -0400192 elog_unlock (em);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700193
194 return l;
195}
196
Dave Barachc3799992016-08-15 11:12:27 -0400197word
198elog_track_register (elog_main_t * em, elog_track_t * t)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700199{
200 word l;
201
202 elog_lock (em);
203
204 l = vec_len (em->tracks);
205
206 t->track_index_plus_one = 1 + l;
207
208 ASSERT (t->name);
209
210 vec_add1 (em->tracks, t[0]);
211
212 t = em->tracks + l;
213
214 t->name = (char *) format (0, "%s%c", t->name, 0);
215
216 elog_unlock (em);
217
218 return l;
219}
220
Dave Barachc3799992016-08-15 11:12:27 -0400221static uword
222parse_2digit_decimal (char *p, uword * number)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700223{
224 uword i = 0;
225 u8 digits[2];
226
227 digits[0] = digits[1] = 0;
228 while (p[i] >= '0' && p[i] <= '9')
229 {
230 if (i >= 2)
231 break;
232 digits[i] = p[i] - '0';
233 i++;
234 }
235
236 if (i >= 1 && i <= 2)
237 {
238 if (i == 1)
239 *number = digits[0];
240 else
241 *number = 10 * digits[0] + digits[1];
242 return i;
243 }
244 else
245 return 0;
246}
247
Dave Barachc3799992016-08-15 11:12:27 -0400248static u8 *
249fixed_format (u8 * s, char *fmt, char *result, uword * result_len)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700250{
Dave Barachc3799992016-08-15 11:12:27 -0400251 char *f = fmt;
252 char *percent;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700253 uword l = 0;
254
255 while (1)
256 {
257 if (f[0] == 0)
258 break;
259 if (f[0] == '%' && f[1] != '%')
260 break;
261 f++;
262 }
263 if (f > fmt)
264 vec_add (s, fmt, f - fmt);
265
266 if (f[0] != '%')
267 goto done;
268
269 /* Skip percent. */
270 percent = f++;
271
272 /* Skip possible +-= justification. */
273 f += f[0] == '+' || f[0] == '-' || f[0] == '=';
274
275 /* Skip possible X.Y width. */
276 while ((f[0] >= '0' && f[0] <= '9') || f[0] == '.')
277 f++;
278
279 /* Skip wlL as in e.g. %Ld. */
280 f += f[0] == 'w' || f[0] == 'l' || f[0] == 'L';
281
282 /* Finally skip format letter. */
283 f += f[0] != 0;
284
285 ASSERT (*result_len > f - percent);
286 l = clib_min (f - percent, *result_len - 1);
Damjan Marionf1213b82016-03-13 02:22:06 +0100287 clib_memcpy (result, percent, l);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700288 result[l] = 0;
289
Dave Barachc3799992016-08-15 11:12:27 -0400290done:
Ed Warnickecb9cada2015-12-08 15:45:58 -0700291 *result_len = f - fmt;
292 return s;
293}
294
Dave Barachc3799992016-08-15 11:12:27 -0400295u8 *
296format_elog_event (u8 * s, va_list * va)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700297{
Dave Barachc3799992016-08-15 11:12:27 -0400298 elog_main_t *em = va_arg (*va, elog_main_t *);
299 elog_event_t *e = va_arg (*va, elog_event_t *);
300 elog_event_type_t *t;
301 char *a, *f;
302 void *d = (u8 *) e->data;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700303 char arg_format[64];
304
305 t = vec_elt_at_index (em->event_types, e->type);
306
307 f = t->format;
308 a = t->format_args;
309 while (1)
310 {
311 uword n_bytes = 0, n_digits, f_bytes = 0;
312
313 f_bytes = sizeof (arg_format);
314 s = fixed_format (s, f, arg_format, &f_bytes);
315 f += f_bytes;
316
317 if (a == 0 || a[0] == 0)
318 {
319 /* Format must also be at end. */
320 ASSERT (f[0] == 0);
321 break;
322 }
323
324 /* Don't go past end of event data. */
325 ASSERT (d < (void *) (e->data + sizeof (e->data)));
326
327 n_digits = parse_2digit_decimal (a + 1, &n_bytes);
328 switch (a[0])
329 {
330 case 'i':
331 case 't':
332 case 'T':
333 {
334 u32 i = 0;
335 u64 l = 0;
336
337 if (n_bytes == 1)
338 i = ((u8 *) d)[0];
339 else if (n_bytes == 2)
340 i = clib_mem_unaligned (d, u16);
341 else if (n_bytes == 4)
342 i = clib_mem_unaligned (d, u32);
343 else if (n_bytes == 8)
344 l = clib_mem_unaligned (d, u64);
345 else
346 ASSERT (0);
347 if (a[0] == 't')
348 {
Dave Barachc3799992016-08-15 11:12:27 -0400349 char *e =
350 vec_elt (t->enum_strings_vector, n_bytes == 8 ? l : i);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700351 s = format (s, arg_format, e);
352 }
353 else if (a[0] == 'T')
354 {
Dave Barachc3799992016-08-15 11:12:27 -0400355 char *e =
356 vec_elt_at_index (em->string_table, n_bytes == 8 ? l : i);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700357 s = format (s, arg_format, e);
358 }
359 else if (n_bytes == 8)
360 s = format (s, arg_format, l);
361 else
362 s = format (s, arg_format, i);
363 }
364 break;
365
366 case 'f':
367 {
368 f64 x = 0;
369 if (n_bytes == 4)
370 x = clib_mem_unaligned (d, f32);
371 else if (n_bytes == 8)
372 x = clib_mem_unaligned (d, f64);
373 else
374 ASSERT (0);
375 s = format (s, arg_format, x);
376 }
377 break;
378
379 case 's':
380 s = format (s, arg_format, d);
381 if (n_bytes == 0)
382 n_bytes = strlen (d) + 1;
383 break;
384
385 default:
386 ASSERT (0);
387 break;
388 }
389
390 ASSERT (n_digits > 0 && n_digits <= 2);
391 a += 1 + n_digits;
392 d += n_bytes;
393 }
394
395 return s;
396}
397
Dave Barachc3799992016-08-15 11:12:27 -0400398u8 *
Florin Corasaefbede2018-12-19 13:07:49 -0800399format_elog_track_name (u8 * s, va_list * va)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700400{
Dave Barachc3799992016-08-15 11:12:27 -0400401 elog_main_t *em = va_arg (*va, elog_main_t *);
402 elog_event_t *e = va_arg (*va, elog_event_t *);
403 elog_track_t *t = vec_elt_at_index (em->tracks, e->track);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700404 return format (s, "%s", t->name);
405}
406
Florin Corasaefbede2018-12-19 13:07:49 -0800407u8 *
408format_elog_track (u8 * s, va_list * args)
409{
410 elog_main_t *em = va_arg (*args, elog_main_t *);
411 f64 dt = va_arg (*args, f64);
412 int track_index = va_arg (*args, int);
413 elog_event_t *e, *es;
414 u8 indent;
415
416 indent = format_get_indent (s) + 1;
417
418 es = elog_peek_events (em);
419 vec_foreach (e, es)
420 {
421 if (e->track != track_index)
422 continue;
423 s = format (s, "%U%18.9f: %U\n", format_white_space, indent, e->time + dt,
424 format_elog_event, em, e);
425 }
426 vec_free (es);
427 return s;
428}
429
Dave Barachc3799992016-08-15 11:12:27 -0400430void
431elog_time_now (elog_time_stamp_t * et)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700432{
433 u64 cpu_time_now, os_time_now_nsec;
Dave Barach903fd512017-04-01 11:07:40 -0400434 struct timespec ts;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700435
436#ifdef CLIB_UNIX
437 {
438#include <sys/syscall.h>
Damjan Marion4dffd1c2018-09-03 12:30:36 +0200439#ifdef __APPLE__
440 clock_gettime (CLOCK_REALTIME, &ts);
441#else
Ed Warnickecb9cada2015-12-08 15:45:58 -0700442 syscall (SYS_clock_gettime, CLOCK_REALTIME, &ts);
Damjan Marion4dffd1c2018-09-03 12:30:36 +0200443#endif
Ed Warnickecb9cada2015-12-08 15:45:58 -0700444 cpu_time_now = clib_cpu_time_now ();
Dave Barach903fd512017-04-01 11:07:40 -0400445 /* Subtract 3/30/2017's worth of seconds to retain precision */
446 os_time_now_nsec = 1e9 * (ts.tv_sec - 1490885108) + ts.tv_nsec;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700447 }
448#else
449 cpu_time_now = clib_cpu_time_now ();
450 os_time_now_nsec = 0;
451#endif
452
453 et->cpu = cpu_time_now;
454 et->os_nsec = os_time_now_nsec;
455}
456
457always_inline i64
Dave Barachc3799992016-08-15 11:12:27 -0400458elog_time_stamp_diff_os_nsec (elog_time_stamp_t * t1, elog_time_stamp_t * t2)
459{
460 return (i64) t1->os_nsec - (i64) t2->os_nsec;
461}
Ed Warnickecb9cada2015-12-08 15:45:58 -0700462
463always_inline i64
Dave Barachc3799992016-08-15 11:12:27 -0400464elog_time_stamp_diff_cpu (elog_time_stamp_t * t1, elog_time_stamp_t * t2)
465{
466 return (i64) t1->cpu - (i64) t2->cpu;
467}
Ed Warnickecb9cada2015-12-08 15:45:58 -0700468
469always_inline f64
470elog_nsec_per_clock (elog_main_t * em)
471{
472 return ((f64) elog_time_stamp_diff_os_nsec (&em->serialize_time,
473 &em->init_time)
474 / (f64) elog_time_stamp_diff_cpu (&em->serialize_time,
475 &em->init_time));
476}
477
Dave Barachc3799992016-08-15 11:12:27 -0400478void
479elog_alloc (elog_main_t * em, u32 n_events)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700480{
481 if (em->event_ring)
482 vec_free (em->event_ring);
Dave Barachc3799992016-08-15 11:12:27 -0400483
Ed Warnickecb9cada2015-12-08 15:45:58 -0700484 /* Ring size must be a power of 2. */
485 em->event_ring_size = n_events = max_pow2 (n_events);
486
487 /* Leave an empty ievent at end so we can always speculatively write
488 and event there (possibly a long form event). */
489 vec_resize_aligned (em->event_ring, n_events, CLIB_CACHE_LINE_BYTES);
490}
491
Dave Barachc3799992016-08-15 11:12:27 -0400492void
493elog_init (elog_main_t * em, u32 n_events)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700494{
Dave Barachb7b92992018-10-17 10:38:51 -0400495 clib_memset (em, 0, sizeof (em[0]));
Ed Warnickecb9cada2015-12-08 15:45:58 -0700496
497 em->lock = 0;
498
499 if (n_events > 0)
500 elog_alloc (em, n_events);
501
502 clib_time_init (&em->cpu_timer);
503
504 em->n_total_events_disable_limit = ~0;
505
506 /* Make track 0. */
507 em->default_track.name = "default";
508 elog_track_register (em, &em->default_track);
509
510 elog_time_now (&em->init_time);
511}
512
513/* Returns number of events in ring and start index. */
Dave Barachc3799992016-08-15 11:12:27 -0400514static uword
515elog_event_range (elog_main_t * em, uword * lo)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700516{
517 uword l = em->event_ring_size;
518 u64 i = em->n_total_events;
519
520 /* Ring never wrapped? */
521 if (i <= (u64) l)
522 {
Dave Barachc3799992016-08-15 11:12:27 -0400523 if (lo)
524 *lo = 0;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700525 return i;
526 }
527 else
528 {
Dave Barachc3799992016-08-15 11:12:27 -0400529 if (lo)
530 *lo = i & (l - 1);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700531 return l;
532 }
533}
534
Dave Barachc3799992016-08-15 11:12:27 -0400535elog_event_t *
536elog_peek_events (elog_main_t * em)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700537{
Dave Barachc3799992016-08-15 11:12:27 -0400538 elog_event_t *e, *f, *es = 0;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700539 uword i, j, n;
540
541 n = elog_event_range (em, &j);
542 for (i = 0; i < n; i++)
543 {
544 vec_add2 (es, e, 1);
545 f = vec_elt_at_index (em->event_ring, j);
546 e[0] = f[0];
547
548 /* Convert absolute time from cycles to seconds from start. */
Dave Barachc3799992016-08-15 11:12:27 -0400549 e->time =
550 (e->time_cycles -
551 em->init_time.cpu) * em->cpu_timer.seconds_per_clock;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700552
553 j = (j + 1) & (em->event_ring_size - 1);
554 }
555
556 return es;
557}
558
559/* Add a formatted string to the string table. */
Dave Barachc3799992016-08-15 11:12:27 -0400560u32
561elog_string (elog_main_t * em, char *fmt, ...)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700562{
563 u32 offset;
564 va_list va;
565
Steven Luongd31a5982019-05-31 07:34:39 -0700566 elog_lock (em);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700567 va_start (va, fmt);
568 offset = vec_len (em->string_table);
569 em->string_table = (char *) va_format ((u8 *) em->string_table, fmt, &va);
570 va_end (va);
571
572 /* Null terminate string if it is not already. */
573 if (vec_end (em->string_table)[-1] != 0)
574 vec_add1 (em->string_table, 0);
Steven Luongd31a5982019-05-31 07:34:39 -0700575 elog_unlock (em);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700576
577 return offset;
578}
579
Dave Barachc3799992016-08-15 11:12:27 -0400580elog_event_t *
581elog_get_events (elog_main_t * em)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700582{
Dave Barachc3799992016-08-15 11:12:27 -0400583 if (!em->events)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700584 em->events = elog_peek_events (em);
585 return em->events;
586}
587
Dave Barachc3799992016-08-15 11:12:27 -0400588static void
589maybe_fix_string_table_offset (elog_event_t * e,
590 elog_event_type_t * t, u32 offset)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700591{
Dave Barachc3799992016-08-15 11:12:27 -0400592 void *d = (u8 *) e->data;
593 char *a;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700594
595 if (offset == 0)
596 return;
597
598 a = t->format_args;
599
600 while (1)
601 {
602 uword n_bytes = 0, n_digits;
603
604 if (a[0] == 0)
Dave Barachc3799992016-08-15 11:12:27 -0400605 break;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700606
607 /* Don't go past end of event data. */
608 ASSERT (d < (void *) (e->data + sizeof (e->data)));
609
610 n_digits = parse_2digit_decimal (a + 1, &n_bytes);
611 switch (a[0])
612 {
613 case 'T':
Dave Barachc3799992016-08-15 11:12:27 -0400614 ASSERT (n_bytes == 4);
615 clib_mem_unaligned (d, u32) += offset;
616 break;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700617
618 case 'i':
619 case 't':
620 case 'f':
621 case 's':
622 break;
623
624 default:
625 ASSERT (0);
626 break;
627 }
628
629 ASSERT (n_digits > 0 && n_digits <= 2);
630 a += 1 + n_digits;
631 d += n_bytes;
632 }
633}
634
Dave Barachc3799992016-08-15 11:12:27 -0400635static int
636elog_cmp (void *a1, void *a2)
Matus Fabiand2dc3df2015-12-14 10:31:33 -0500637{
Dave Barachc3799992016-08-15 11:12:27 -0400638 elog_event_t *e1 = a1;
639 elog_event_t *e2 = a2;
Matus Fabiand2dc3df2015-12-14 10:31:33 -0500640
Dave Barach903fd512017-04-01 11:07:40 -0400641 if (e1->time < e2->time)
642 return -1;
643
644 if (e1->time > e2->time)
645 return 1;
646
647 return 0;
Matus Fabiand2dc3df2015-12-14 10:31:33 -0500648}
649
Dave Barach903fd512017-04-01 11:07:40 -0400650/*
651 * merge two event logs. Complicated and cranky.
652 */
Dave Barachc3799992016-08-15 11:12:27 -0400653void
Dave Barach903fd512017-04-01 11:07:40 -0400654elog_merge (elog_main_t * dst, u8 * dst_tag, elog_main_t * src, u8 * src_tag,
655 f64 align_tweak)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700656{
Dave Barachc3799992016-08-15 11:12:27 -0400657 elog_event_t *e;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700658 uword l;
659 u32 string_table_offset_for_src_events;
660 u32 track_offset_for_src_tracks;
661 elog_track_t newt;
662 int i;
663
Dave Barachb7b92992018-10-17 10:38:51 -0400664 clib_memset (&newt, 0, sizeof (newt));
Dave Barachf9c231e2016-08-05 10:10:18 -0400665
Dave Barach903fd512017-04-01 11:07:40 -0400666 /* Acquire src and dst events */
Ed Warnickecb9cada2015-12-08 15:45:58 -0700667 elog_get_events (src);
668 elog_get_events (dst);
669
670 string_table_offset_for_src_events = vec_len (dst->string_table);
671 vec_append (dst->string_table, src->string_table);
672
673 l = vec_len (dst->events);
Dave Barach903fd512017-04-01 11:07:40 -0400674 vec_append (dst->events, src->events);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700675
676 /* Prepend the supplied tag (if any) to all dst track names */
677 if (dst_tag)
678 {
Dave Barachc3799992016-08-15 11:12:27 -0400679 for (i = 0; i < vec_len (dst->tracks); i++)
680 {
681 elog_track_t *t = vec_elt_at_index (dst->tracks, i);
682 char *new_name;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700683
Dave Barachc3799992016-08-15 11:12:27 -0400684 new_name = (char *) format (0, "%s:%s%c", dst_tag, t->name, 0);
685 vec_free (t->name);
686 t->name = new_name;
687 }
Ed Warnickecb9cada2015-12-08 15:45:58 -0700688 }
Dave Barachc3799992016-08-15 11:12:27 -0400689
Dave Barach903fd512017-04-01 11:07:40 -0400690 /*
691 * Remember where we started allocating new tracks while merging
692 */
Ed Warnickecb9cada2015-12-08 15:45:58 -0700693 track_offset_for_src_tracks = vec_len (dst->tracks);
Dave Barachc3799992016-08-15 11:12:27 -0400694
Ed Warnickecb9cada2015-12-08 15:45:58 -0700695 /* Copy / tag source tracks */
696 for (i = 0; i < vec_len (src->tracks); i++)
697 {
Dave Barachc3799992016-08-15 11:12:27 -0400698 elog_track_t *t = vec_elt_at_index (src->tracks, i);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700699 if (src_tag)
Dave Barachc3799992016-08-15 11:12:27 -0400700 newt.name = (char *) format (0, "%s:%s%c", src_tag, t->name, 0);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700701 else
Dave Barachc3799992016-08-15 11:12:27 -0400702 newt.name = (char *) format (0, "%s%c", t->name, 0);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700703 (void) elog_track_register (dst, &newt);
704 vec_free (newt.name);
705 }
Dave Barachc3799992016-08-15 11:12:27 -0400706
Ed Warnickecb9cada2015-12-08 15:45:58 -0700707 /* Across all (copied) src events... */
708 for (e = dst->events + l; e < vec_end (dst->events); e++)
709 {
Dave Barachc3799992016-08-15 11:12:27 -0400710 elog_event_type_t *t = vec_elt_at_index (src->event_types, e->type);
711
Ed Warnickecb9cada2015-12-08 15:45:58 -0700712 /* Remap type from src -> dst. */
713 e->type = find_or_create_type (dst, t);
714
715 /* Remap string table offsets for 'T' format args */
Dave Barachc3799992016-08-15 11:12:27 -0400716 maybe_fix_string_table_offset (e, t,
717 string_table_offset_for_src_events);
718
Ed Warnickecb9cada2015-12-08 15:45:58 -0700719 /* Remap track */
720 e->track += track_offset_for_src_tracks;
721 }
722
723 /* Adjust event times for relative starting times of event streams. */
724 {
725 f64 dt_event, dt_os_nsec, dt_clock_nsec;
726
727 /* Set clock parameters if dst was not generated by unserialize. */
728 if (dst->serialize_time.cpu == 0)
729 {
730 dst->init_time = src->init_time;
731 dst->serialize_time = src->serialize_time;
732 dst->nsec_per_cpu_clock = src->nsec_per_cpu_clock;
733 }
734
Dave Barachc3799992016-08-15 11:12:27 -0400735 dt_os_nsec =
736 elog_time_stamp_diff_os_nsec (&src->init_time, &dst->init_time);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700737
738 dt_event = dt_os_nsec;
Dave Barachc3799992016-08-15 11:12:27 -0400739 dt_clock_nsec =
740 (elog_time_stamp_diff_cpu (&src->init_time, &dst->init_time) * .5 *
741 (dst->nsec_per_cpu_clock + src->nsec_per_cpu_clock));
Ed Warnickecb9cada2015-12-08 15:45:58 -0700742
Dave Barach903fd512017-04-01 11:07:40 -0400743 /*
744 * Heuristic to see if src/dst came from same time source.
745 * If frequencies are "the same" and os clock and cpu clock agree
746 * to within 100e-9 secs about time difference between src/dst
747 * init_time, then we use cpu clock. Otherwise we use OS clock.
748 *
749 * When merging event logs from different systems, time paradoxes
750 * at the O(1ms) level are to be expected. Hence, the "align_tweak"
751 * parameter. If two events logged on different processors are known
752 * to occur in a specific order - and with a reasonably-estimated
753 * interval - supply a non-zero "align_tweak" parameter
754 */
Ed Warnickecb9cada2015-12-08 15:45:58 -0700755 if (fabs (src->nsec_per_cpu_clock - dst->nsec_per_cpu_clock) < 1e-2
756 && fabs (dt_os_nsec - dt_clock_nsec) < 100)
757 dt_event = dt_clock_nsec;
758
759 /* Convert to seconds. */
760 dt_event *= 1e-9;
761
Dave Barach903fd512017-04-01 11:07:40 -0400762 /*
763 * Move the earlier set of events later, to avoid creating
Paul Vinciguerraec11b132018-09-24 05:25:00 -0700764 * events which precede the Big Bang (aka have negative timestamps).
Dave Barach903fd512017-04-01 11:07:40 -0400765 *
766 * Not to any scale, we have something like the following picture:
767 *
768 * DST capture start point
769 * ^
770 * +--- dt_event --+
771 * v
772 * SRC capture start point
773 *
774 * In this case dt_event is positive, src started after dst,
775 * to put src events onto a common timebase we have to move them
776 * forward in time. Naturally, the opposite case is
777 * possible, too: dt_event will be negative, and so we have to
778 * move dst events forward in time by the |dt_event|.
779 * In both cases, we add align_tweak.
780 */
Ed Warnickecb9cada2015-12-08 15:45:58 -0700781 if (dt_event > 0)
782 {
783 /* Src started after dst. */
784 for (e = dst->events + l; e < vec_end (dst->events); e++)
Dave Barach903fd512017-04-01 11:07:40 -0400785 e->time += dt_event + align_tweak;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700786 }
787 else
788 {
789 /* Dst started after src. */
Dave Barach903fd512017-04-01 11:07:40 -0400790 dt_event = -dt_event;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700791 for (e = dst->events + 0; e < dst->events + l; e++)
Dave Barach903fd512017-04-01 11:07:40 -0400792 e->time += dt_event + align_tweak;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700793 }
794 }
795
796 /* Sort events by increasing time. */
Matus Fabiand2dc3df2015-12-14 10:31:33 -0500797 vec_sort_with_function (dst->events, elog_cmp);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700798
Dave Barach903fd512017-04-01 11:07:40 -0400799 dst->n_total_events = vec_len (dst->events);
800
Ed Warnickecb9cada2015-12-08 15:45:58 -0700801 /* Recreate the event ring or the results won't serialize */
802 {
803 int i;
804
805 ASSERT (dst->cpu_timer.seconds_per_clock);
806
807 elog_alloc (dst, vec_len (dst->events));
Dave Barachc3799992016-08-15 11:12:27 -0400808 for (i = 0; i < vec_len (dst->events); i++)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700809 {
Dave Barachc3799992016-08-15 11:12:27 -0400810 elog_event_t *es, *ed;
811
812 es = dst->events + i;
813 ed = dst->event_ring + i;
814
815 ed[0] = es[0];
Ed Warnickecb9cada2015-12-08 15:45:58 -0700816 }
Ed Warnickecb9cada2015-12-08 15:45:58 -0700817 }
818}
819
820static void
821serialize_elog_event (serialize_main_t * m, va_list * va)
822{
Dave Barachc3799992016-08-15 11:12:27 -0400823 elog_main_t *em = va_arg (*va, elog_main_t *);
824 elog_event_t *e = va_arg (*va, elog_event_t *);
825 elog_event_type_t *t = vec_elt_at_index (em->event_types, e->type);
826 u8 *d = e->data;
827 u8 *p = (u8 *) t->format_args;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700828
829 serialize_integer (m, e->type, sizeof (e->type));
830 serialize_integer (m, e->track, sizeof (e->track));
831 serialize (m, serialize_f64, e->time);
832
833 while (*p)
834 {
835 uword n_digits, n_bytes = 0;
836
837 n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
838
839 switch (p[0])
840 {
841 case 'i':
842 case 't':
843 case 'T':
844 if (n_bytes == 1)
845 serialize_integer (m, d[0], sizeof (u8));
846 else if (n_bytes == 2)
847 serialize_integer (m, clib_mem_unaligned (d, u16), sizeof (u16));
848 else if (n_bytes == 4)
849 serialize_integer (m, clib_mem_unaligned (d, u32), sizeof (u32));
850 else if (n_bytes == 8)
851 serialize (m, serialize_64, clib_mem_unaligned (d, u64));
852 else
853 ASSERT (0);
854 break;
855
856 case 's':
857 serialize_cstring (m, (char *) d);
858 if (n_bytes == 0)
859 n_bytes = strlen ((char *) d) + 1;
860 break;
861
862 case 'f':
863 if (n_bytes == 4)
864 serialize (m, serialize_f32, clib_mem_unaligned (d, f32));
865 else if (n_bytes == 8)
866 serialize (m, serialize_f64, clib_mem_unaligned (d, f64));
867 else
868 ASSERT (0);
869 break;
870
871 default:
872 ASSERT (0);
873 break;
874 }
875
876 p += 1 + n_digits;
877 d += n_bytes;
878 }
879}
880
881static void
882unserialize_elog_event (serialize_main_t * m, va_list * va)
883{
Dave Barachc3799992016-08-15 11:12:27 -0400884 elog_main_t *em = va_arg (*va, elog_main_t *);
885 elog_event_t *e = va_arg (*va, elog_event_t *);
886 elog_event_type_t *t;
887 u8 *p, *d;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700888
889 {
890 u16 tmp[2];
891
892 unserialize_integer (m, &tmp[0], sizeof (e->type));
893 unserialize_integer (m, &tmp[1], sizeof (e->track));
894
895 e->type = tmp[0];
896 e->track = tmp[1];
897
898 /* Make sure it fits. */
899 ASSERT (e->type == tmp[0]);
900 ASSERT (e->track == tmp[1]);
901 }
902
903 t = vec_elt_at_index (em->event_types, e->type);
904
905 unserialize (m, unserialize_f64, &e->time);
906
907 d = e->data;
908 p = (u8 *) t->format_args;
909
910 while (p && *p)
911 {
912 uword n_digits, n_bytes = 0;
913 u32 tmp;
914
915 n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
916
917 switch (p[0])
918 {
919 case 'i':
920 case 't':
921 case 'T':
922 if (n_bytes == 1)
923 {
924 unserialize_integer (m, &tmp, sizeof (u8));
925 d[0] = tmp;
926 }
927 else if (n_bytes == 2)
928 {
929 unserialize_integer (m, &tmp, sizeof (u16));
930 clib_mem_unaligned (d, u16) = tmp;
931 }
932 else if (n_bytes == 4)
933 {
934 unserialize_integer (m, &tmp, sizeof (u32));
935 clib_mem_unaligned (d, u32) = tmp;
936 }
937 else if (n_bytes == 8)
938 {
939 u64 x;
940 unserialize (m, unserialize_64, &x);
941 clib_mem_unaligned (d, u64) = x;
942 }
943 else
944 ASSERT (0);
945 break;
946
Dave Barachc3799992016-08-15 11:12:27 -0400947 case 's':
948 {
949 char *t;
950 unserialize_cstring (m, &t);
951 if (n_bytes == 0)
952 n_bytes = strlen (t) + 1;
953 clib_memcpy (d, t, clib_min (n_bytes, vec_len (t)));
954 vec_free (t);
955 break;
956 }
Ed Warnickecb9cada2015-12-08 15:45:58 -0700957
958 case 'f':
959 if (n_bytes == 4)
960 {
961 f32 x;
962 unserialize (m, unserialize_f32, &x);
963 clib_mem_unaligned (d, f32) = x;
964 }
965 else if (n_bytes == 8)
966 {
967 f64 x;
968 unserialize (m, unserialize_f64, &x);
969 clib_mem_unaligned (d, f64) = x;
970 }
971 else
972 ASSERT (0);
973 break;
974
975 default:
976 ASSERT (0);
977 break;
978 }
979
980 p += 1 + n_digits;
981 d += n_bytes;
982 }
983}
984
985static void
986serialize_elog_event_type (serialize_main_t * m, va_list * va)
987{
Dave Barachc3799992016-08-15 11:12:27 -0400988 elog_event_type_t *t = va_arg (*va, elog_event_type_t *);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700989 int n = va_arg (*va, int);
990 int i, j;
991 for (i = 0; i < n; i++)
992 {
993 serialize_cstring (m, t[i].format);
994 serialize_cstring (m, t[i].format_args);
Dave Barachc3799992016-08-15 11:12:27 -0400995 serialize_integer (m, t[i].type_index_plus_one,
996 sizeof (t->type_index_plus_one));
997 serialize_integer (m, t[i].n_enum_strings,
998 sizeof (t[i].n_enum_strings));
Ed Warnickecb9cada2015-12-08 15:45:58 -0700999 for (j = 0; j < t[i].n_enum_strings; j++)
1000 serialize_cstring (m, t[i].enum_strings_vector[j]);
1001 }
1002}
1003
1004static void
1005unserialize_elog_event_type (serialize_main_t * m, va_list * va)
1006{
Dave Barachc3799992016-08-15 11:12:27 -04001007 elog_event_type_t *t = va_arg (*va, elog_event_type_t *);
Ed Warnickecb9cada2015-12-08 15:45:58 -07001008 int n = va_arg (*va, int);
1009 int i, j;
1010 for (i = 0; i < n; i++)
1011 {
1012 unserialize_cstring (m, &t[i].format);
1013 unserialize_cstring (m, &t[i].format_args);
Dave Barachc3799992016-08-15 11:12:27 -04001014 unserialize_integer (m, &t[i].type_index_plus_one,
1015 sizeof (t->type_index_plus_one));
1016 unserialize_integer (m, &t[i].n_enum_strings,
1017 sizeof (t[i].n_enum_strings));
Ed Warnickecb9cada2015-12-08 15:45:58 -07001018 vec_resize (t[i].enum_strings_vector, t[i].n_enum_strings);
1019 for (j = 0; j < t[i].n_enum_strings; j++)
1020 unserialize_cstring (m, &t[i].enum_strings_vector[j]);
1021 }
1022}
1023
1024static void
1025serialize_elog_track (serialize_main_t * m, va_list * va)
1026{
Dave Barachc3799992016-08-15 11:12:27 -04001027 elog_track_t *t = va_arg (*va, elog_track_t *);
Ed Warnickecb9cada2015-12-08 15:45:58 -07001028 int n = va_arg (*va, int);
1029 int i;
1030 for (i = 0; i < n; i++)
1031 {
1032 serialize_cstring (m, t[i].name);
1033 }
1034}
1035
1036static void
1037unserialize_elog_track (serialize_main_t * m, va_list * va)
1038{
Dave Barachc3799992016-08-15 11:12:27 -04001039 elog_track_t *t = va_arg (*va, elog_track_t *);
Ed Warnickecb9cada2015-12-08 15:45:58 -07001040 int n = va_arg (*va, int);
1041 int i;
1042 for (i = 0; i < n; i++)
1043 {
1044 unserialize_cstring (m, &t[i].name);
1045 }
1046}
1047
1048static void
1049serialize_elog_time_stamp (serialize_main_t * m, va_list * va)
1050{
Dave Barachc3799992016-08-15 11:12:27 -04001051 elog_time_stamp_t *st = va_arg (*va, elog_time_stamp_t *);
Ed Warnickecb9cada2015-12-08 15:45:58 -07001052 serialize (m, serialize_64, st->os_nsec);
1053 serialize (m, serialize_64, st->cpu);
1054}
1055
1056static void
1057unserialize_elog_time_stamp (serialize_main_t * m, va_list * va)
1058{
Dave Barachc3799992016-08-15 11:12:27 -04001059 elog_time_stamp_t *st = va_arg (*va, elog_time_stamp_t *);
Ed Warnickecb9cada2015-12-08 15:45:58 -07001060 unserialize (m, unserialize_64, &st->os_nsec);
1061 unserialize (m, unserialize_64, &st->cpu);
1062}
1063
Dave Barachc3799992016-08-15 11:12:27 -04001064static char *elog_serialize_magic = "elog v0";
Ed Warnickecb9cada2015-12-08 15:45:58 -07001065
1066void
1067serialize_elog_main (serialize_main_t * m, va_list * va)
1068{
Dave Barachc3799992016-08-15 11:12:27 -04001069 elog_main_t *em = va_arg (*va, elog_main_t *);
Dave Barach903fd512017-04-01 11:07:40 -04001070 int flush_ring = va_arg (*va, int);
Dave Barachc3799992016-08-15 11:12:27 -04001071 elog_event_t *e;
Ed Warnickecb9cada2015-12-08 15:45:58 -07001072
1073 serialize_magic (m, elog_serialize_magic, strlen (elog_serialize_magic));
1074
1075 serialize_integer (m, em->event_ring_size, sizeof (u32));
1076
1077 elog_time_now (&em->serialize_time);
1078 serialize (m, serialize_elog_time_stamp, &em->serialize_time);
1079 serialize (m, serialize_elog_time_stamp, &em->init_time);
1080
1081 vec_serialize (m, em->event_types, serialize_elog_event_type);
1082 vec_serialize (m, em->tracks, serialize_elog_track);
1083 vec_serialize (m, em->string_table, serialize_vec_8);
1084
1085 /* Free old events (cached) in case they have changed. */
Dave Barach903fd512017-04-01 11:07:40 -04001086 if (flush_ring)
1087 {
1088 vec_free (em->events);
1089 elog_get_events (em);
1090 }
Ed Warnickecb9cada2015-12-08 15:45:58 -07001091
1092 serialize_integer (m, vec_len (em->events), sizeof (u32));
1093
1094 /* SMP logs can easily have local time paradoxes... */
Matus Fabiand2dc3df2015-12-14 10:31:33 -05001095 vec_sort_with_function (em->events, elog_cmp);
Ed Warnickecb9cada2015-12-08 15:45:58 -07001096
Dave Barachc3799992016-08-15 11:12:27 -04001097 vec_foreach (e, em->events) serialize (m, serialize_elog_event, em, e);
Ed Warnickecb9cada2015-12-08 15:45:58 -07001098}
1099
1100void
1101unserialize_elog_main (serialize_main_t * m, va_list * va)
1102{
Dave Barachc3799992016-08-15 11:12:27 -04001103 elog_main_t *em = va_arg (*va, elog_main_t *);
Ed Warnickecb9cada2015-12-08 15:45:58 -07001104 uword i;
1105 u32 rs;
1106
1107 unserialize_check_magic (m, elog_serialize_magic,
1108 strlen (elog_serialize_magic));
1109
1110 unserialize_integer (m, &rs, sizeof (u32));
1111 em->event_ring_size = rs;
1112 elog_init (em, em->event_ring_size);
1113
1114 unserialize (m, unserialize_elog_time_stamp, &em->serialize_time);
1115 unserialize (m, unserialize_elog_time_stamp, &em->init_time);
1116 em->nsec_per_cpu_clock = elog_nsec_per_clock (em);
1117
1118 vec_unserialize (m, &em->event_types, unserialize_elog_event_type);
1119 for (i = 0; i < vec_len (em->event_types); i++)
1120 new_event_type (em, i);
1121
1122 vec_unserialize (m, &em->tracks, unserialize_elog_track);
1123 vec_unserialize (m, &em->string_table, unserialize_vec_8);
1124
1125 {
1126 u32 ne;
Dave Barachc3799992016-08-15 11:12:27 -04001127 elog_event_t *e;
Ed Warnickecb9cada2015-12-08 15:45:58 -07001128
1129 unserialize_integer (m, &ne, sizeof (u32));
1130 vec_resize (em->events, ne);
1131 vec_foreach (e, em->events)
1132 unserialize (m, unserialize_elog_event, em, e);
1133 }
1134}
Dave Barachc3799992016-08-15 11:12:27 -04001135
1136/*
1137 * fd.io coding-style-patch-verification: ON
1138 *
1139 * Local Variables:
1140 * eval: (c-set-style "gnu")
1141 * End:
1142 */