blob: 036dce98f325ba3672ca50126b243ac450a52d55 [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))
49 while (__sync_lock_test_and_set (em->lock, 1))
50 ;
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 *
399format_elog_track (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
Dave Barachc3799992016-08-15 11:12:27 -0400407void
408elog_time_now (elog_time_stamp_t * et)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700409{
410 u64 cpu_time_now, os_time_now_nsec;
Dave Barach903fd512017-04-01 11:07:40 -0400411 struct timespec ts;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700412
413#ifdef CLIB_UNIX
414 {
415#include <sys/syscall.h>
Damjan Marion4dffd1c2018-09-03 12:30:36 +0200416#ifdef __APPLE__
417 clock_gettime (CLOCK_REALTIME, &ts);
418#else
Ed Warnickecb9cada2015-12-08 15:45:58 -0700419 syscall (SYS_clock_gettime, CLOCK_REALTIME, &ts);
Damjan Marion4dffd1c2018-09-03 12:30:36 +0200420#endif
Ed Warnickecb9cada2015-12-08 15:45:58 -0700421 cpu_time_now = clib_cpu_time_now ();
Dave Barach903fd512017-04-01 11:07:40 -0400422 /* Subtract 3/30/2017's worth of seconds to retain precision */
423 os_time_now_nsec = 1e9 * (ts.tv_sec - 1490885108) + ts.tv_nsec;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700424 }
425#else
426 cpu_time_now = clib_cpu_time_now ();
427 os_time_now_nsec = 0;
428#endif
429
430 et->cpu = cpu_time_now;
431 et->os_nsec = os_time_now_nsec;
432}
433
434always_inline i64
Dave Barachc3799992016-08-15 11:12:27 -0400435elog_time_stamp_diff_os_nsec (elog_time_stamp_t * t1, elog_time_stamp_t * t2)
436{
437 return (i64) t1->os_nsec - (i64) t2->os_nsec;
438}
Ed Warnickecb9cada2015-12-08 15:45:58 -0700439
440always_inline i64
Dave Barachc3799992016-08-15 11:12:27 -0400441elog_time_stamp_diff_cpu (elog_time_stamp_t * t1, elog_time_stamp_t * t2)
442{
443 return (i64) t1->cpu - (i64) t2->cpu;
444}
Ed Warnickecb9cada2015-12-08 15:45:58 -0700445
446always_inline f64
447elog_nsec_per_clock (elog_main_t * em)
448{
449 return ((f64) elog_time_stamp_diff_os_nsec (&em->serialize_time,
450 &em->init_time)
451 / (f64) elog_time_stamp_diff_cpu (&em->serialize_time,
452 &em->init_time));
453}
454
Dave Barachc3799992016-08-15 11:12:27 -0400455void
456elog_alloc (elog_main_t * em, u32 n_events)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700457{
458 if (em->event_ring)
459 vec_free (em->event_ring);
Dave Barachc3799992016-08-15 11:12:27 -0400460
Ed Warnickecb9cada2015-12-08 15:45:58 -0700461 /* Ring size must be a power of 2. */
462 em->event_ring_size = n_events = max_pow2 (n_events);
463
464 /* Leave an empty ievent at end so we can always speculatively write
465 and event there (possibly a long form event). */
466 vec_resize_aligned (em->event_ring, n_events, CLIB_CACHE_LINE_BYTES);
467}
468
Dave Barachc3799992016-08-15 11:12:27 -0400469void
470elog_init (elog_main_t * em, u32 n_events)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700471{
472 memset (em, 0, sizeof (em[0]));
473
474 em->lock = 0;
475
476 if (n_events > 0)
477 elog_alloc (em, n_events);
478
479 clib_time_init (&em->cpu_timer);
480
481 em->n_total_events_disable_limit = ~0;
482
483 /* Make track 0. */
484 em->default_track.name = "default";
485 elog_track_register (em, &em->default_track);
486
487 elog_time_now (&em->init_time);
488}
489
490/* Returns number of events in ring and start index. */
Dave Barachc3799992016-08-15 11:12:27 -0400491static uword
492elog_event_range (elog_main_t * em, uword * lo)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700493{
494 uword l = em->event_ring_size;
495 u64 i = em->n_total_events;
496
497 /* Ring never wrapped? */
498 if (i <= (u64) l)
499 {
Dave Barachc3799992016-08-15 11:12:27 -0400500 if (lo)
501 *lo = 0;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700502 return i;
503 }
504 else
505 {
Dave Barachc3799992016-08-15 11:12:27 -0400506 if (lo)
507 *lo = i & (l - 1);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700508 return l;
509 }
510}
511
Dave Barachc3799992016-08-15 11:12:27 -0400512elog_event_t *
513elog_peek_events (elog_main_t * em)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700514{
Dave Barachc3799992016-08-15 11:12:27 -0400515 elog_event_t *e, *f, *es = 0;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700516 uword i, j, n;
517
518 n = elog_event_range (em, &j);
519 for (i = 0; i < n; i++)
520 {
521 vec_add2 (es, e, 1);
522 f = vec_elt_at_index (em->event_ring, j);
523 e[0] = f[0];
524
525 /* Convert absolute time from cycles to seconds from start. */
Dave Barachc3799992016-08-15 11:12:27 -0400526 e->time =
527 (e->time_cycles -
528 em->init_time.cpu) * em->cpu_timer.seconds_per_clock;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700529
530 j = (j + 1) & (em->event_ring_size - 1);
531 }
532
533 return es;
534}
535
536/* Add a formatted string to the string table. */
Dave Barachc3799992016-08-15 11:12:27 -0400537u32
538elog_string (elog_main_t * em, char *fmt, ...)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700539{
540 u32 offset;
541 va_list va;
542
543 va_start (va, fmt);
544 offset = vec_len (em->string_table);
545 em->string_table = (char *) va_format ((u8 *) em->string_table, fmt, &va);
546 va_end (va);
547
548 /* Null terminate string if it is not already. */
549 if (vec_end (em->string_table)[-1] != 0)
550 vec_add1 (em->string_table, 0);
551
552 return offset;
553}
554
Dave Barachc3799992016-08-15 11:12:27 -0400555elog_event_t *
556elog_get_events (elog_main_t * em)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700557{
Dave Barachc3799992016-08-15 11:12:27 -0400558 if (!em->events)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700559 em->events = elog_peek_events (em);
560 return em->events;
561}
562
Dave Barachc3799992016-08-15 11:12:27 -0400563static void
564maybe_fix_string_table_offset (elog_event_t * e,
565 elog_event_type_t * t, u32 offset)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700566{
Dave Barachc3799992016-08-15 11:12:27 -0400567 void *d = (u8 *) e->data;
568 char *a;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700569
570 if (offset == 0)
571 return;
572
573 a = t->format_args;
574
575 while (1)
576 {
577 uword n_bytes = 0, n_digits;
578
579 if (a[0] == 0)
Dave Barachc3799992016-08-15 11:12:27 -0400580 break;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700581
582 /* Don't go past end of event data. */
583 ASSERT (d < (void *) (e->data + sizeof (e->data)));
584
585 n_digits = parse_2digit_decimal (a + 1, &n_bytes);
586 switch (a[0])
587 {
588 case 'T':
Dave Barachc3799992016-08-15 11:12:27 -0400589 ASSERT (n_bytes == 4);
590 clib_mem_unaligned (d, u32) += offset;
591 break;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700592
593 case 'i':
594 case 't':
595 case 'f':
596 case 's':
597 break;
598
599 default:
600 ASSERT (0);
601 break;
602 }
603
604 ASSERT (n_digits > 0 && n_digits <= 2);
605 a += 1 + n_digits;
606 d += n_bytes;
607 }
608}
609
Dave Barachc3799992016-08-15 11:12:27 -0400610static int
611elog_cmp (void *a1, void *a2)
Matus Fabiand2dc3df2015-12-14 10:31:33 -0500612{
Dave Barachc3799992016-08-15 11:12:27 -0400613 elog_event_t *e1 = a1;
614 elog_event_t *e2 = a2;
Matus Fabiand2dc3df2015-12-14 10:31:33 -0500615
Dave Barach903fd512017-04-01 11:07:40 -0400616 if (e1->time < e2->time)
617 return -1;
618
619 if (e1->time > e2->time)
620 return 1;
621
622 return 0;
Matus Fabiand2dc3df2015-12-14 10:31:33 -0500623}
624
Dave Barach903fd512017-04-01 11:07:40 -0400625/*
626 * merge two event logs. Complicated and cranky.
627 */
Dave Barachc3799992016-08-15 11:12:27 -0400628void
Dave Barach903fd512017-04-01 11:07:40 -0400629elog_merge (elog_main_t * dst, u8 * dst_tag, elog_main_t * src, u8 * src_tag,
630 f64 align_tweak)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700631{
Dave Barachc3799992016-08-15 11:12:27 -0400632 elog_event_t *e;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700633 uword l;
634 u32 string_table_offset_for_src_events;
635 u32 track_offset_for_src_tracks;
636 elog_track_t newt;
637 int i;
638
Dave Barachc3799992016-08-15 11:12:27 -0400639 memset (&newt, 0, sizeof (newt));
Dave Barachf9c231e2016-08-05 10:10:18 -0400640
Dave Barach903fd512017-04-01 11:07:40 -0400641 /* Acquire src and dst events */
Ed Warnickecb9cada2015-12-08 15:45:58 -0700642 elog_get_events (src);
643 elog_get_events (dst);
644
645 string_table_offset_for_src_events = vec_len (dst->string_table);
646 vec_append (dst->string_table, src->string_table);
647
648 l = vec_len (dst->events);
Dave Barach903fd512017-04-01 11:07:40 -0400649 vec_append (dst->events, src->events);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700650
651 /* Prepend the supplied tag (if any) to all dst track names */
652 if (dst_tag)
653 {
Dave Barachc3799992016-08-15 11:12:27 -0400654 for (i = 0; i < vec_len (dst->tracks); i++)
655 {
656 elog_track_t *t = vec_elt_at_index (dst->tracks, i);
657 char *new_name;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700658
Dave Barachc3799992016-08-15 11:12:27 -0400659 new_name = (char *) format (0, "%s:%s%c", dst_tag, t->name, 0);
660 vec_free (t->name);
661 t->name = new_name;
662 }
Ed Warnickecb9cada2015-12-08 15:45:58 -0700663 }
Dave Barachc3799992016-08-15 11:12:27 -0400664
Dave Barach903fd512017-04-01 11:07:40 -0400665 /*
666 * Remember where we started allocating new tracks while merging
667 */
Ed Warnickecb9cada2015-12-08 15:45:58 -0700668 track_offset_for_src_tracks = vec_len (dst->tracks);
Dave Barachc3799992016-08-15 11:12:27 -0400669
Ed Warnickecb9cada2015-12-08 15:45:58 -0700670 /* Copy / tag source tracks */
671 for (i = 0; i < vec_len (src->tracks); i++)
672 {
Dave Barachc3799992016-08-15 11:12:27 -0400673 elog_track_t *t = vec_elt_at_index (src->tracks, i);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700674 if (src_tag)
Dave Barachc3799992016-08-15 11:12:27 -0400675 newt.name = (char *) format (0, "%s:%s%c", src_tag, t->name, 0);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700676 else
Dave Barachc3799992016-08-15 11:12:27 -0400677 newt.name = (char *) format (0, "%s%c", t->name, 0);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700678 (void) elog_track_register (dst, &newt);
679 vec_free (newt.name);
680 }
Dave Barachc3799992016-08-15 11:12:27 -0400681
Ed Warnickecb9cada2015-12-08 15:45:58 -0700682 /* Across all (copied) src events... */
683 for (e = dst->events + l; e < vec_end (dst->events); e++)
684 {
Dave Barachc3799992016-08-15 11:12:27 -0400685 elog_event_type_t *t = vec_elt_at_index (src->event_types, e->type);
686
Ed Warnickecb9cada2015-12-08 15:45:58 -0700687 /* Remap type from src -> dst. */
688 e->type = find_or_create_type (dst, t);
689
690 /* Remap string table offsets for 'T' format args */
Dave Barachc3799992016-08-15 11:12:27 -0400691 maybe_fix_string_table_offset (e, t,
692 string_table_offset_for_src_events);
693
Ed Warnickecb9cada2015-12-08 15:45:58 -0700694 /* Remap track */
695 e->track += track_offset_for_src_tracks;
696 }
697
698 /* Adjust event times for relative starting times of event streams. */
699 {
700 f64 dt_event, dt_os_nsec, dt_clock_nsec;
701
702 /* Set clock parameters if dst was not generated by unserialize. */
703 if (dst->serialize_time.cpu == 0)
704 {
705 dst->init_time = src->init_time;
706 dst->serialize_time = src->serialize_time;
707 dst->nsec_per_cpu_clock = src->nsec_per_cpu_clock;
708 }
709
Dave Barachc3799992016-08-15 11:12:27 -0400710 dt_os_nsec =
711 elog_time_stamp_diff_os_nsec (&src->init_time, &dst->init_time);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700712
713 dt_event = dt_os_nsec;
Dave Barachc3799992016-08-15 11:12:27 -0400714 dt_clock_nsec =
715 (elog_time_stamp_diff_cpu (&src->init_time, &dst->init_time) * .5 *
716 (dst->nsec_per_cpu_clock + src->nsec_per_cpu_clock));
Ed Warnickecb9cada2015-12-08 15:45:58 -0700717
Dave Barach903fd512017-04-01 11:07:40 -0400718 /*
719 * Heuristic to see if src/dst came from same time source.
720 * If frequencies are "the same" and os clock and cpu clock agree
721 * to within 100e-9 secs about time difference between src/dst
722 * init_time, then we use cpu clock. Otherwise we use OS clock.
723 *
724 * When merging event logs from different systems, time paradoxes
725 * at the O(1ms) level are to be expected. Hence, the "align_tweak"
726 * parameter. If two events logged on different processors are known
727 * to occur in a specific order - and with a reasonably-estimated
728 * interval - supply a non-zero "align_tweak" parameter
729 */
Ed Warnickecb9cada2015-12-08 15:45:58 -0700730 if (fabs (src->nsec_per_cpu_clock - dst->nsec_per_cpu_clock) < 1e-2
731 && fabs (dt_os_nsec - dt_clock_nsec) < 100)
732 dt_event = dt_clock_nsec;
733
734 /* Convert to seconds. */
735 dt_event *= 1e-9;
736
Dave Barach903fd512017-04-01 11:07:40 -0400737 /*
738 * Move the earlier set of events later, to avoid creating
739 * events which preceed the Big Bang (aka have negative timestamps).
740 *
741 * Not to any scale, we have something like the following picture:
742 *
743 * DST capture start point
744 * ^
745 * +--- dt_event --+
746 * v
747 * SRC capture start point
748 *
749 * In this case dt_event is positive, src started after dst,
750 * to put src events onto a common timebase we have to move them
751 * forward in time. Naturally, the opposite case is
752 * possible, too: dt_event will be negative, and so we have to
753 * move dst events forward in time by the |dt_event|.
754 * In both cases, we add align_tweak.
755 */
Ed Warnickecb9cada2015-12-08 15:45:58 -0700756 if (dt_event > 0)
757 {
758 /* Src started after dst. */
759 for (e = dst->events + l; e < vec_end (dst->events); e++)
Dave Barach903fd512017-04-01 11:07:40 -0400760 e->time += dt_event + align_tweak;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700761 }
762 else
763 {
764 /* Dst started after src. */
Dave Barach903fd512017-04-01 11:07:40 -0400765 dt_event = -dt_event;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700766 for (e = dst->events + 0; e < dst->events + l; e++)
Dave Barach903fd512017-04-01 11:07:40 -0400767 e->time += dt_event + align_tweak;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700768 }
769 }
770
771 /* Sort events by increasing time. */
Matus Fabiand2dc3df2015-12-14 10:31:33 -0500772 vec_sort_with_function (dst->events, elog_cmp);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700773
Dave Barach903fd512017-04-01 11:07:40 -0400774 dst->n_total_events = vec_len (dst->events);
775
Ed Warnickecb9cada2015-12-08 15:45:58 -0700776 /* Recreate the event ring or the results won't serialize */
777 {
778 int i;
779
780 ASSERT (dst->cpu_timer.seconds_per_clock);
781
782 elog_alloc (dst, vec_len (dst->events));
Dave Barachc3799992016-08-15 11:12:27 -0400783 for (i = 0; i < vec_len (dst->events); i++)
Ed Warnickecb9cada2015-12-08 15:45:58 -0700784 {
Dave Barachc3799992016-08-15 11:12:27 -0400785 elog_event_t *es, *ed;
786
787 es = dst->events + i;
788 ed = dst->event_ring + i;
789
790 ed[0] = es[0];
Ed Warnickecb9cada2015-12-08 15:45:58 -0700791 }
Ed Warnickecb9cada2015-12-08 15:45:58 -0700792 }
793}
794
795static void
796serialize_elog_event (serialize_main_t * m, va_list * va)
797{
Dave Barachc3799992016-08-15 11:12:27 -0400798 elog_main_t *em = va_arg (*va, elog_main_t *);
799 elog_event_t *e = va_arg (*va, elog_event_t *);
800 elog_event_type_t *t = vec_elt_at_index (em->event_types, e->type);
801 u8 *d = e->data;
802 u8 *p = (u8 *) t->format_args;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700803
804 serialize_integer (m, e->type, sizeof (e->type));
805 serialize_integer (m, e->track, sizeof (e->track));
806 serialize (m, serialize_f64, e->time);
807
808 while (*p)
809 {
810 uword n_digits, n_bytes = 0;
811
812 n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
813
814 switch (p[0])
815 {
816 case 'i':
817 case 't':
818 case 'T':
819 if (n_bytes == 1)
820 serialize_integer (m, d[0], sizeof (u8));
821 else if (n_bytes == 2)
822 serialize_integer (m, clib_mem_unaligned (d, u16), sizeof (u16));
823 else if (n_bytes == 4)
824 serialize_integer (m, clib_mem_unaligned (d, u32), sizeof (u32));
825 else if (n_bytes == 8)
826 serialize (m, serialize_64, clib_mem_unaligned (d, u64));
827 else
828 ASSERT (0);
829 break;
830
831 case 's':
832 serialize_cstring (m, (char *) d);
833 if (n_bytes == 0)
834 n_bytes = strlen ((char *) d) + 1;
835 break;
836
837 case 'f':
838 if (n_bytes == 4)
839 serialize (m, serialize_f32, clib_mem_unaligned (d, f32));
840 else if (n_bytes == 8)
841 serialize (m, serialize_f64, clib_mem_unaligned (d, f64));
842 else
843 ASSERT (0);
844 break;
845
846 default:
847 ASSERT (0);
848 break;
849 }
850
851 p += 1 + n_digits;
852 d += n_bytes;
853 }
854}
855
856static void
857unserialize_elog_event (serialize_main_t * m, va_list * va)
858{
Dave Barachc3799992016-08-15 11:12:27 -0400859 elog_main_t *em = va_arg (*va, elog_main_t *);
860 elog_event_t *e = va_arg (*va, elog_event_t *);
861 elog_event_type_t *t;
862 u8 *p, *d;
Ed Warnickecb9cada2015-12-08 15:45:58 -0700863
864 {
865 u16 tmp[2];
866
867 unserialize_integer (m, &tmp[0], sizeof (e->type));
868 unserialize_integer (m, &tmp[1], sizeof (e->track));
869
870 e->type = tmp[0];
871 e->track = tmp[1];
872
873 /* Make sure it fits. */
874 ASSERT (e->type == tmp[0]);
875 ASSERT (e->track == tmp[1]);
876 }
877
878 t = vec_elt_at_index (em->event_types, e->type);
879
880 unserialize (m, unserialize_f64, &e->time);
881
882 d = e->data;
883 p = (u8 *) t->format_args;
884
885 while (p && *p)
886 {
887 uword n_digits, n_bytes = 0;
888 u32 tmp;
889
890 n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
891
892 switch (p[0])
893 {
894 case 'i':
895 case 't':
896 case 'T':
897 if (n_bytes == 1)
898 {
899 unserialize_integer (m, &tmp, sizeof (u8));
900 d[0] = tmp;
901 }
902 else if (n_bytes == 2)
903 {
904 unserialize_integer (m, &tmp, sizeof (u16));
905 clib_mem_unaligned (d, u16) = tmp;
906 }
907 else if (n_bytes == 4)
908 {
909 unserialize_integer (m, &tmp, sizeof (u32));
910 clib_mem_unaligned (d, u32) = tmp;
911 }
912 else if (n_bytes == 8)
913 {
914 u64 x;
915 unserialize (m, unserialize_64, &x);
916 clib_mem_unaligned (d, u64) = x;
917 }
918 else
919 ASSERT (0);
920 break;
921
Dave Barachc3799992016-08-15 11:12:27 -0400922 case 's':
923 {
924 char *t;
925 unserialize_cstring (m, &t);
926 if (n_bytes == 0)
927 n_bytes = strlen (t) + 1;
928 clib_memcpy (d, t, clib_min (n_bytes, vec_len (t)));
929 vec_free (t);
930 break;
931 }
Ed Warnickecb9cada2015-12-08 15:45:58 -0700932
933 case 'f':
934 if (n_bytes == 4)
935 {
936 f32 x;
937 unserialize (m, unserialize_f32, &x);
938 clib_mem_unaligned (d, f32) = x;
939 }
940 else if (n_bytes == 8)
941 {
942 f64 x;
943 unserialize (m, unserialize_f64, &x);
944 clib_mem_unaligned (d, f64) = x;
945 }
946 else
947 ASSERT (0);
948 break;
949
950 default:
951 ASSERT (0);
952 break;
953 }
954
955 p += 1 + n_digits;
956 d += n_bytes;
957 }
958}
959
960static void
961serialize_elog_event_type (serialize_main_t * m, va_list * va)
962{
Dave Barachc3799992016-08-15 11:12:27 -0400963 elog_event_type_t *t = va_arg (*va, elog_event_type_t *);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700964 int n = va_arg (*va, int);
965 int i, j;
966 for (i = 0; i < n; i++)
967 {
968 serialize_cstring (m, t[i].format);
969 serialize_cstring (m, t[i].format_args);
Dave Barachc3799992016-08-15 11:12:27 -0400970 serialize_integer (m, t[i].type_index_plus_one,
971 sizeof (t->type_index_plus_one));
972 serialize_integer (m, t[i].n_enum_strings,
973 sizeof (t[i].n_enum_strings));
Ed Warnickecb9cada2015-12-08 15:45:58 -0700974 for (j = 0; j < t[i].n_enum_strings; j++)
975 serialize_cstring (m, t[i].enum_strings_vector[j]);
976 }
977}
978
979static void
980unserialize_elog_event_type (serialize_main_t * m, va_list * va)
981{
Dave Barachc3799992016-08-15 11:12:27 -0400982 elog_event_type_t *t = va_arg (*va, elog_event_type_t *);
Ed Warnickecb9cada2015-12-08 15:45:58 -0700983 int n = va_arg (*va, int);
984 int i, j;
985 for (i = 0; i < n; i++)
986 {
987 unserialize_cstring (m, &t[i].format);
988 unserialize_cstring (m, &t[i].format_args);
Dave Barachc3799992016-08-15 11:12:27 -0400989 unserialize_integer (m, &t[i].type_index_plus_one,
990 sizeof (t->type_index_plus_one));
991 unserialize_integer (m, &t[i].n_enum_strings,
992 sizeof (t[i].n_enum_strings));
Ed Warnickecb9cada2015-12-08 15:45:58 -0700993 vec_resize (t[i].enum_strings_vector, t[i].n_enum_strings);
994 for (j = 0; j < t[i].n_enum_strings; j++)
995 unserialize_cstring (m, &t[i].enum_strings_vector[j]);
996 }
997}
998
999static void
1000serialize_elog_track (serialize_main_t * m, va_list * va)
1001{
Dave Barachc3799992016-08-15 11:12:27 -04001002 elog_track_t *t = va_arg (*va, elog_track_t *);
Ed Warnickecb9cada2015-12-08 15:45:58 -07001003 int n = va_arg (*va, int);
1004 int i;
1005 for (i = 0; i < n; i++)
1006 {
1007 serialize_cstring (m, t[i].name);
1008 }
1009}
1010
1011static void
1012unserialize_elog_track (serialize_main_t * m, va_list * va)
1013{
Dave Barachc3799992016-08-15 11:12:27 -04001014 elog_track_t *t = va_arg (*va, elog_track_t *);
Ed Warnickecb9cada2015-12-08 15:45:58 -07001015 int n = va_arg (*va, int);
1016 int i;
1017 for (i = 0; i < n; i++)
1018 {
1019 unserialize_cstring (m, &t[i].name);
1020 }
1021}
1022
1023static void
1024serialize_elog_time_stamp (serialize_main_t * m, va_list * va)
1025{
Dave Barachc3799992016-08-15 11:12:27 -04001026 elog_time_stamp_t *st = va_arg (*va, elog_time_stamp_t *);
Ed Warnickecb9cada2015-12-08 15:45:58 -07001027 serialize (m, serialize_64, st->os_nsec);
1028 serialize (m, serialize_64, st->cpu);
1029}
1030
1031static void
1032unserialize_elog_time_stamp (serialize_main_t * m, va_list * va)
1033{
Dave Barachc3799992016-08-15 11:12:27 -04001034 elog_time_stamp_t *st = va_arg (*va, elog_time_stamp_t *);
Ed Warnickecb9cada2015-12-08 15:45:58 -07001035 unserialize (m, unserialize_64, &st->os_nsec);
1036 unserialize (m, unserialize_64, &st->cpu);
1037}
1038
Dave Barachc3799992016-08-15 11:12:27 -04001039static char *elog_serialize_magic = "elog v0";
Ed Warnickecb9cada2015-12-08 15:45:58 -07001040
1041void
1042serialize_elog_main (serialize_main_t * m, va_list * va)
1043{
Dave Barachc3799992016-08-15 11:12:27 -04001044 elog_main_t *em = va_arg (*va, elog_main_t *);
Dave Barach903fd512017-04-01 11:07:40 -04001045 int flush_ring = va_arg (*va, int);
Dave Barachc3799992016-08-15 11:12:27 -04001046 elog_event_t *e;
Ed Warnickecb9cada2015-12-08 15:45:58 -07001047
1048 serialize_magic (m, elog_serialize_magic, strlen (elog_serialize_magic));
1049
1050 serialize_integer (m, em->event_ring_size, sizeof (u32));
1051
1052 elog_time_now (&em->serialize_time);
1053 serialize (m, serialize_elog_time_stamp, &em->serialize_time);
1054 serialize (m, serialize_elog_time_stamp, &em->init_time);
1055
1056 vec_serialize (m, em->event_types, serialize_elog_event_type);
1057 vec_serialize (m, em->tracks, serialize_elog_track);
1058 vec_serialize (m, em->string_table, serialize_vec_8);
1059
1060 /* Free old events (cached) in case they have changed. */
Dave Barach903fd512017-04-01 11:07:40 -04001061 if (flush_ring)
1062 {
1063 vec_free (em->events);
1064 elog_get_events (em);
1065 }
Ed Warnickecb9cada2015-12-08 15:45:58 -07001066
1067 serialize_integer (m, vec_len (em->events), sizeof (u32));
1068
1069 /* SMP logs can easily have local time paradoxes... */
Matus Fabiand2dc3df2015-12-14 10:31:33 -05001070 vec_sort_with_function (em->events, elog_cmp);
Ed Warnickecb9cada2015-12-08 15:45:58 -07001071
Dave Barachc3799992016-08-15 11:12:27 -04001072 vec_foreach (e, em->events) serialize (m, serialize_elog_event, em, e);
Ed Warnickecb9cada2015-12-08 15:45:58 -07001073}
1074
1075void
1076unserialize_elog_main (serialize_main_t * m, va_list * va)
1077{
Dave Barachc3799992016-08-15 11:12:27 -04001078 elog_main_t *em = va_arg (*va, elog_main_t *);
Ed Warnickecb9cada2015-12-08 15:45:58 -07001079 uword i;
1080 u32 rs;
1081
1082 unserialize_check_magic (m, elog_serialize_magic,
1083 strlen (elog_serialize_magic));
1084
1085 unserialize_integer (m, &rs, sizeof (u32));
1086 em->event_ring_size = rs;
1087 elog_init (em, em->event_ring_size);
1088
1089 unserialize (m, unserialize_elog_time_stamp, &em->serialize_time);
1090 unserialize (m, unserialize_elog_time_stamp, &em->init_time);
1091 em->nsec_per_cpu_clock = elog_nsec_per_clock (em);
1092
1093 vec_unserialize (m, &em->event_types, unserialize_elog_event_type);
1094 for (i = 0; i < vec_len (em->event_types); i++)
1095 new_event_type (em, i);
1096
1097 vec_unserialize (m, &em->tracks, unserialize_elog_track);
1098 vec_unserialize (m, &em->string_table, unserialize_vec_8);
1099
1100 {
1101 u32 ne;
Dave Barachc3799992016-08-15 11:12:27 -04001102 elog_event_t *e;
Ed Warnickecb9cada2015-12-08 15:45:58 -07001103
1104 unserialize_integer (m, &ne, sizeof (u32));
1105 vec_resize (em->events, ne);
1106 vec_foreach (e, em->events)
1107 unserialize (m, unserialize_elog_event, em, e);
1108 }
1109}
Dave Barachc3799992016-08-15 11:12:27 -04001110
1111/*
1112 * fd.io coding-style-patch-verification: ON
1113 *
1114 * Local Variables:
1115 * eval: (c-set-style "gnu")
1116 * End:
1117 */