Line data Source code
1 : /*
2 : * Copyright (c) 2015 Cisco and/or its affiliates.
3 : * Licensed under the Apache License, Version 2.0 (the "License");
4 : * you may not use this file except in compliance with the License.
5 : * You may obtain a copy of the License at:
6 : *
7 : * http://www.apache.org/licenses/LICENSE-2.0
8 : *
9 : * Unless required by applicable law or agreed to in writing, software
10 : * distributed under the License is distributed on an "AS IS" BASIS,
11 : * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12 : * See the License for the specific language governing permissions and
13 : * limitations under the License.
14 : */
15 : /*
16 : Copyright (c) 2005,2009 Eliot Dresselhaus
17 :
18 : Permission is hereby granted, free of charge, to any person obtaining
19 : a copy of this software and associated documentation files (the
20 : "Software"), to deal in the Software without restriction, including
21 : without limitation the rights to use, copy, modify, merge, publish,
22 : distribute, sublicense, and/or sell copies of the Software, and to
23 : permit persons to whom the Software is furnished to do so, subject to
24 : the following conditions:
25 :
26 : The above copyright notice and this permission notice shall be
27 : included in all copies or substantial portions of the Software.
28 :
29 : THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
30 : EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
31 : MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND
32 : NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE
33 : LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION
34 : OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION
35 : WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
36 : */
37 :
38 : #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 : #include <vppinfra/lock.h>
45 :
46 : static inline void
47 1430900 : elog_lock (elog_main_t * em)
48 : {
49 1430900 : if (PREDICT_FALSE (em->lock != 0))
50 1019060 : while (clib_atomic_test_and_set (em->lock))
51 488 : CLIB_PAUSE ();
52 1430900 : }
53 :
54 : static inline void
55 1430900 : elog_unlock (elog_main_t * em)
56 : {
57 1430900 : if (PREDICT_FALSE (em->lock != 0))
58 : {
59 1018580 : clib_atomic_release (em->lock);
60 : }
61 1430900 : }
62 :
63 : /* Non-inline version. */
64 : __clib_export void *
65 1010560 : elog_event_data (elog_main_t * em,
66 : elog_event_type_t * type, elog_track_t * track, u64 cpu_time)
67 : {
68 1010560 : return elog_event_data_inline (em, type, track, cpu_time);
69 : }
70 :
71 : static void
72 2454 : new_event_type (elog_main_t * em, uword i)
73 : {
74 2454 : elog_event_type_t *t = vec_elt_at_index (em->event_types, i);
75 :
76 2454 : if (!em->event_type_by_format)
77 575 : em->event_type_by_format =
78 575 : hash_create_vec ( /* size */ 0, sizeof (u8), sizeof (uword));
79 :
80 2454 : t->type_index_plus_one = i + 1;
81 4908 : hash_set_mem (em->event_type_by_format, t->format, i);
82 2454 : }
83 :
84 : static uword
85 0 : find_or_create_type (elog_main_t * em, elog_event_type_t * t)
86 : {
87 0 : uword *p = hash_get_mem (em->event_type_by_format, t->format);
88 : uword i;
89 :
90 0 : if (p)
91 0 : i = p[0];
92 : else
93 : {
94 0 : i = vec_len (em->event_types);
95 0 : vec_add1 (em->event_types, t[0]);
96 0 : new_event_type (em, i);
97 : }
98 :
99 0 : return i;
100 : }
101 :
102 : /* External function to register types. */
103 : word
104 2454 : elog_event_type_register (elog_main_t * em, elog_event_type_t * t)
105 : {
106 2454 : elog_event_type_t *static_type = t;
107 : word l;
108 :
109 2454 : elog_lock (em);
110 :
111 : /* Multiple simultaneous registration attempts, */
112 2454 : if (t->type_index_plus_one > 0)
113 : {
114 0 : elog_unlock (em);
115 0 : return t->type_index_plus_one - 1;
116 : }
117 :
118 2454 : l = vec_len (em->event_types);
119 :
120 2454 : t->type_index_plus_one = 1 + l;
121 :
122 2454 : 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. */
126 2454 : if (!t->format_args)
127 : {
128 : uword i, l;
129 : char *this_arg;
130 :
131 0 : l = strlen (t->format);
132 0 : for (i = 0; i < l; i++)
133 : {
134 0 : if (t->format[i] != '%')
135 0 : continue;
136 0 : if (i + 1 >= l)
137 0 : continue;
138 0 : if (t->format[i + 1] == '%') /* %% */
139 0 : continue;
140 :
141 0 : switch (t->format[i + 1])
142 : {
143 0 : default:
144 : case 'd':
145 : case 'x':
146 : case 'u':
147 0 : this_arg = "i4"; /* size of u32 */
148 0 : break;
149 0 : case 'f':
150 0 : this_arg = "f8"; /* defaults to f64 */
151 0 : break;
152 0 : case 's':
153 0 : this_arg = "s0"; /* defaults to null terminated string. */
154 0 : break;
155 : }
156 :
157 0 : t->format_args =
158 0 : (char *) format ((u8 *) t->format_args, "%s", this_arg);
159 : }
160 :
161 : /* Null terminate. */
162 0 : vec_add1 (t->format_args, 0);
163 : }
164 :
165 2454 : vec_add1 (em->event_types, t[0]);
166 :
167 2454 : t = em->event_types + l;
168 :
169 : /* Make copies of strings for hashing etc. */
170 2454 : if (t->function)
171 0 : t->format = (char *) format (0, "%s %s%c", t->function, t->format, 0);
172 : else
173 2454 : t->format = (char *) format (0, "%s%c", t->format, 0);
174 :
175 2454 : t->format_args = (char *) format (0, "%s%c", t->format_args, 0);
176 :
177 : /* Construct string table. */
178 : {
179 : uword i;
180 2454 : t->n_enum_strings = static_type->n_enum_strings;
181 4754 : for (i = 0; i < t->n_enum_strings; i++)
182 : {
183 2300 : if (!static_type->enum_strings[i])
184 0 : static_type->enum_strings[i] = "MISSING";
185 2300 : vec_add1 (t->enum_strings_vector,
186 : (char *) format (0, "%s%c", static_type->enum_strings[i],
187 : 0));
188 : }
189 : }
190 :
191 2454 : new_event_type (em, l);
192 2454 : elog_unlock (em);
193 :
194 2454 : return l;
195 : }
196 :
197 : __clib_export word
198 1205 : elog_track_register (elog_main_t * em, elog_track_t * t)
199 : {
200 : word l;
201 :
202 1205 : elog_lock (em);
203 :
204 1205 : l = vec_len (em->tracks);
205 :
206 1205 : t->track_index_plus_one = 1 + l;
207 :
208 1205 : ASSERT (t->name);
209 :
210 1205 : vec_add1 (em->tracks, t[0]);
211 :
212 1205 : t = em->tracks + l;
213 :
214 1205 : t->name = (char *) format (0, "%s%c", t->name, 0);
215 :
216 1205 : elog_unlock (em);
217 :
218 1205 : return l;
219 : }
220 :
221 : static uword
222 377 : parse_2digit_decimal (char *p, uword * number)
223 : {
224 377 : uword i = 0;
225 : u8 digits[2];
226 :
227 377 : digits[0] = digits[1] = 0;
228 754 : while (p[i] >= '0' && p[i] <= '9')
229 : {
230 377 : if (i >= 2)
231 0 : break;
232 377 : digits[i] = p[i] - '0';
233 377 : i++;
234 : }
235 :
236 377 : if (i >= 1 && i <= 2)
237 : {
238 377 : if (i == 1)
239 377 : *number = digits[0];
240 : else
241 0 : *number = 10 * digits[0] + digits[1];
242 377 : return i;
243 : }
244 : else
245 0 : return 0;
246 : }
247 :
248 : static u8 *
249 627 : fixed_format (u8 * s, char *fmt, char *result, uword * result_len)
250 : {
251 627 : char *f = fmt;
252 : char *percent;
253 627 : uword l = 0;
254 :
255 : while (1)
256 : {
257 3749 : if (f[0] == 0)
258 250 : break;
259 3499 : if (f[0] == '%' && f[1] != '%')
260 377 : break;
261 3122 : f++;
262 : }
263 627 : if (f > fmt)
264 377 : vec_add (s, fmt, f - fmt);
265 :
266 627 : if (f[0] != '%')
267 250 : goto done;
268 :
269 : /* Skip percent. */
270 377 : percent = f++;
271 :
272 : /* Skip possible +-= justification. */
273 377 : f += f[0] == '+' || f[0] == '-' || f[0] == '=';
274 :
275 : /* Skip possible X.Y width. */
276 377 : while ((f[0] >= '0' && f[0] <= '9') || f[0] == '.')
277 0 : f++;
278 :
279 : /* Skip wlL as in e.g. %Ld. */
280 377 : f += f[0] == 'w' || f[0] == 'l' || f[0] == 'L';
281 :
282 : /* Finally skip format letter. */
283 377 : f += f[0] != 0;
284 :
285 377 : ASSERT (*result_len > f - percent);
286 377 : l = clib_min (f - percent, *result_len - 1);
287 377 : clib_memcpy (result, percent, l);
288 377 : result[l] = 0;
289 :
290 627 : done:
291 627 : *result_len = f - fmt;
292 627 : return s;
293 : }
294 :
295 : __clib_export u8 *
296 250 : format_elog_event (u8 * s, va_list * va)
297 : {
298 250 : elog_main_t *em = va_arg (*va, elog_main_t *);
299 250 : elog_event_t *e = va_arg (*va, elog_event_t *);
300 : elog_event_type_t *t;
301 : char *a, *f;
302 250 : void *d = (u8 *) e->data;
303 : char arg_format[64];
304 :
305 250 : t = vec_elt_at_index (em->event_types, e->event_type);
306 :
307 250 : f = t->format;
308 250 : a = t->format_args;
309 : while (1)
310 377 : {
311 627 : uword n_bytes = 0, n_digits, f_bytes = 0;
312 :
313 627 : f_bytes = sizeof (arg_format);
314 627 : s = fixed_format (s, f, arg_format, &f_bytes);
315 627 : f += f_bytes;
316 :
317 627 : if (a == 0 || a[0] == 0)
318 : {
319 : /* Format must also be at end. */
320 250 : ASSERT (f[0] == 0);
321 250 : break;
322 : }
323 :
324 : /* Don't go past end of event data. */
325 377 : ASSERT (d < (void *) (e->data + sizeof (e->data)));
326 :
327 377 : n_digits = parse_2digit_decimal (a + 1, &n_bytes);
328 377 : switch (a[0])
329 : {
330 377 : case 'i':
331 : case 't':
332 : case 'T':
333 : {
334 377 : u32 i = 0;
335 377 : u64 l = 0;
336 :
337 377 : if (n_bytes == 1)
338 0 : i = ((u8 *) d)[0];
339 377 : else if (n_bytes == 2)
340 0 : i = clib_mem_unaligned (d, u16);
341 377 : else if (n_bytes == 4)
342 377 : i = clib_mem_unaligned (d, u32);
343 0 : else if (n_bytes == 8)
344 0 : l = clib_mem_unaligned (d, u64);
345 : else
346 0 : ASSERT (0);
347 377 : if (a[0] == 't')
348 : {
349 123 : char *e =
350 123 : vec_elt (t->enum_strings_vector, n_bytes == 8 ? l : i);
351 123 : s = format (s, arg_format, e);
352 : }
353 254 : else if (a[0] == 'T')
354 : {
355 249 : char *e =
356 249 : vec_elt_at_index (em->string_table, n_bytes == 8 ? l : i);
357 249 : s = format (s, arg_format, e);
358 : }
359 5 : else if (n_bytes == 8)
360 0 : s = format (s, arg_format, l);
361 : else
362 5 : s = format (s, arg_format, i);
363 : }
364 377 : break;
365 :
366 0 : case 'f':
367 : {
368 0 : f64 x = 0;
369 0 : if (n_bytes == 4)
370 0 : x = clib_mem_unaligned (d, f32);
371 0 : else if (n_bytes == 8)
372 0 : x = clib_mem_unaligned (d, f64);
373 : else
374 0 : ASSERT (0);
375 0 : s = format (s, arg_format, x);
376 : }
377 0 : break;
378 :
379 0 : case 's':
380 0 : s = format (s, arg_format, d);
381 0 : if (n_bytes == 0)
382 0 : n_bytes = strlen (d) + 1;
383 0 : break;
384 :
385 0 : default:
386 0 : ASSERT (0);
387 0 : break;
388 : }
389 :
390 377 : ASSERT (n_digits > 0 && n_digits <= 2);
391 377 : a += 1 + n_digits;
392 377 : d += n_bytes;
393 : }
394 :
395 250 : return s;
396 : }
397 :
398 : __clib_export u8 *
399 0 : format_elog_track_name (u8 *s, va_list *va)
400 : {
401 0 : elog_main_t *em = va_arg (*va, elog_main_t *);
402 0 : elog_event_t *e = va_arg (*va, elog_event_t *);
403 0 : elog_track_t *t = vec_elt_at_index (em->tracks, e->track);
404 0 : return format (s, "%s", t->name);
405 : }
406 :
407 : __clib_export u8 *
408 0 : format_elog_track (u8 * s, va_list * args)
409 : {
410 0 : elog_main_t *em = va_arg (*args, elog_main_t *);
411 0 : f64 dt = va_arg (*args, f64);
412 0 : int track_index = va_arg (*args, int);
413 : elog_event_t *e, *es;
414 : u8 indent;
415 :
416 0 : indent = format_get_indent (s) + 1;
417 :
418 0 : es = elog_peek_events (em);
419 0 : vec_foreach (e, es)
420 : {
421 0 : if (e->track != track_index)
422 0 : continue;
423 0 : s = format (s, "%U%18.9f: %U\n", format_white_space, indent,
424 0 : e->time + dt, format_elog_event, em, e);
425 : }
426 0 : vec_free (es);
427 0 : return s;
428 : }
429 :
430 : __clib_export char *
431 0 : format_one_elog_event (void *em_arg, void *ep_arg)
432 : {
433 0 : elog_main_t *em = (elog_main_t *) em_arg;
434 0 : elog_event_t *ep = (elog_event_t *) ep_arg;
435 :
436 0 : return (char *) format (0, "%U", format_elog_event, em, ep);
437 : }
438 :
439 : void
440 575 : elog_time_now (elog_time_stamp_t * et)
441 : {
442 : u64 cpu_time_now, os_time_now_nsec;
443 : struct timespec ts;
444 :
445 : #ifdef CLIB_UNIX
446 : {
447 : #include <sys/syscall.h>
448 : #ifdef __APPLE__
449 : clock_gettime (CLOCK_REALTIME, &ts);
450 : #else
451 575 : syscall (SYS_clock_gettime, CLOCK_REALTIME, &ts);
452 : #endif
453 575 : cpu_time_now = clib_cpu_time_now ();
454 : /* Subtract 3/30/2017's worth of seconds to retain precision */
455 575 : os_time_now_nsec = 1e9 * (ts.tv_sec - 1490885108) + ts.tv_nsec;
456 : }
457 : #else
458 : cpu_time_now = clib_cpu_time_now ();
459 : os_time_now_nsec = 0;
460 : #endif
461 :
462 575 : et->cpu = cpu_time_now;
463 575 : et->os_nsec = os_time_now_nsec;
464 575 : }
465 :
466 : always_inline i64
467 0 : elog_time_stamp_diff_os_nsec (elog_time_stamp_t * t1, elog_time_stamp_t * t2)
468 : {
469 0 : return (i64) t1->os_nsec - (i64) t2->os_nsec;
470 : }
471 :
472 : always_inline i64
473 0 : elog_time_stamp_diff_cpu (elog_time_stamp_t * t1, elog_time_stamp_t * t2)
474 : {
475 0 : return (i64) t1->cpu - (i64) t2->cpu;
476 : }
477 :
478 : always_inline f64
479 0 : elog_nsec_per_clock (elog_main_t * em)
480 : {
481 0 : return ((f64) elog_time_stamp_diff_os_nsec (&em->serialize_time,
482 : &em->init_time)
483 0 : / (f64) elog_time_stamp_diff_cpu (&em->serialize_time,
484 : &em->init_time));
485 : }
486 :
487 : static void
488 575 : elog_alloc_internal (elog_main_t * em, u32 n_events, int free_ring)
489 : {
490 575 : if (free_ring && em->event_ring)
491 0 : vec_free (em->event_ring);
492 :
493 : /* Ring size must be a power of 2. */
494 575 : em->event_ring_size = n_events = max_pow2 (n_events);
495 :
496 575 : vec_validate_aligned (em->event_ring, n_events, CLIB_CACHE_LINE_BYTES);
497 575 : vec_set_len (em->event_ring, n_events);
498 575 : }
499 :
500 : __clib_export void
501 575 : elog_alloc (elog_main_t * em, u32 n_events)
502 : {
503 575 : elog_alloc_internal (em, n_events, 1 /* free ring */ );
504 575 : }
505 :
506 : __clib_export void
507 0 : elog_resize (elog_main_t * em, u32 n_events)
508 : {
509 0 : elog_alloc_internal (em, n_events, 0 /* do not free ring */ );
510 0 : }
511 :
512 : __clib_export void
513 575 : elog_init (elog_main_t * em, u32 n_events)
514 : {
515 575 : clib_memset (em, 0, sizeof (em[0]));
516 :
517 575 : em->lock = 0;
518 :
519 575 : if (n_events > 0)
520 575 : elog_alloc (em, n_events);
521 :
522 575 : clib_time_init (&em->cpu_timer);
523 :
524 575 : em->n_total_events_disable_limit = ~0;
525 :
526 : /* Make track 0. */
527 575 : em->default_track.name = "default";
528 575 : elog_track_register (em, &em->default_track);
529 :
530 575 : elog_time_now (&em->init_time);
531 575 : em->string_table_hash = hash_create_string (0, sizeof (uword));
532 575 : }
533 :
534 : /* Returns number of events in ring and start index. */
535 : static uword
536 1 : elog_event_range (elog_main_t * em, uword * lo)
537 : {
538 1 : uword l = em->event_ring_size;
539 1 : u64 i = em->n_total_events;
540 :
541 : /* Ring never wrapped? */
542 1 : if (i <= (u64) l)
543 : {
544 1 : if (lo)
545 1 : *lo = 0;
546 1 : return i;
547 : }
548 : else
549 : {
550 0 : if (lo)
551 0 : *lo = i & (l - 1);
552 0 : return l;
553 : }
554 : }
555 :
556 : __clib_export elog_event_t *
557 1 : elog_peek_events (elog_main_t * em)
558 : {
559 1 : elog_event_t *e, *f, *es = 0;
560 : uword i, j, n;
561 :
562 1 : n = elog_event_range (em, &j);
563 276 : for (i = 0; i < n; i++)
564 : {
565 275 : vec_add2 (es, e, 1);
566 275 : f = vec_elt_at_index (em->event_ring, j);
567 275 : e[0] = f[0];
568 :
569 : /* Convert absolute time from cycles to seconds from start. */
570 275 : e->time =
571 275 : (e->time_cycles -
572 275 : em->init_time.cpu) * em->cpu_timer.seconds_per_clock;
573 :
574 275 : j = (j + 1) & (em->event_ring_size - 1);
575 : }
576 :
577 1 : return es;
578 : }
579 :
580 : /* Add a formatted string to the string table. */
581 : __clib_export u32
582 1427240 : elog_string (elog_main_t * em, char *fmt, ...)
583 : {
584 : u32 offset;
585 : uword *p;
586 : uword len;
587 : va_list va;
588 :
589 1427240 : elog_lock (em);
590 1427240 : vec_reset_length (em->string_table_tmp);
591 1427240 : va_start (va, fmt);
592 1427240 : em->string_table_tmp = va_format (em->string_table_tmp, fmt, &va);
593 1427240 : va_end (va);
594 :
595 : /* String table entries MUST be NULL terminated */
596 1427240 : len = vec_len (em->string_table_tmp);
597 1427240 : ASSERT (len > 0);
598 1427240 : if (em->string_table_tmp[len - 1] != 0)
599 1009680 : vec_add1 (em->string_table_tmp, 0);
600 :
601 : /* See if we already have this string in the string table */
602 2854480 : p = hash_get_mem (em->string_table_hash, em->string_table_tmp);
603 :
604 : /* We already have the string, so give the caller its offset */
605 1427240 : if (p)
606 : {
607 1003110 : elog_unlock (em);
608 1003110 : return (p[0]);
609 : }
610 :
611 : /* We don't, so add it. */
612 :
613 424132 : offset = vec_len (em->string_table);
614 424132 : vec_append (em->string_table, em->string_table_tmp);
615 :
616 848264 : hash_set_mem (em->string_table_hash, em->string_table_tmp, offset);
617 :
618 : /* We gave the key to the string table hash, so we can't reuse it! */
619 424132 : em->string_table_tmp = 0;
620 424132 : elog_unlock (em);
621 :
622 424132 : return offset;
623 : }
624 :
625 : __clib_export elog_event_t *
626 0 : elog_get_events (elog_main_t * em)
627 : {
628 0 : vec_free (em->events);
629 0 : em->events = elog_peek_events (em);
630 0 : return em->events;
631 : }
632 :
633 : static void
634 0 : maybe_fix_string_table_offset (elog_event_t * e,
635 : elog_event_type_t * t, u32 offset)
636 : {
637 0 : void *d = (u8 *) e->data;
638 : char *a;
639 :
640 0 : if (offset == 0)
641 0 : return;
642 :
643 0 : a = t->format_args;
644 :
645 : while (1)
646 0 : {
647 0 : uword n_bytes = 0, n_digits;
648 :
649 0 : if (a[0] == 0)
650 0 : break;
651 :
652 : /* Don't go past end of event data. */
653 0 : ASSERT (d < (void *) (e->data + sizeof (e->data)));
654 :
655 0 : n_digits = parse_2digit_decimal (a + 1, &n_bytes);
656 0 : switch (a[0])
657 : {
658 0 : case 'T':
659 0 : ASSERT (n_bytes == 4);
660 0 : clib_mem_unaligned (d, u32) += offset;
661 0 : break;
662 :
663 0 : case 'i':
664 : case 't':
665 : case 'f':
666 : case 's':
667 0 : break;
668 :
669 0 : default:
670 0 : ASSERT (0);
671 0 : break;
672 : }
673 :
674 0 : ASSERT (n_digits > 0 && n_digits <= 2);
675 0 : a += 1 + n_digits;
676 0 : d += n_bytes;
677 : }
678 : }
679 :
680 : static int
681 0 : elog_cmp (void *a1, void *a2)
682 : {
683 0 : elog_event_t *e1 = a1;
684 0 : elog_event_t *e2 = a2;
685 :
686 0 : if (e1->time < e2->time)
687 0 : return -1;
688 :
689 0 : if (e1->time > e2->time)
690 0 : return 1;
691 :
692 0 : return 0;
693 : }
694 :
695 : /*
696 : * merge two event logs. Complicated and cranky.
697 : */
698 : __clib_export void
699 0 : elog_merge (elog_main_t *dst, u8 *dst_tag, elog_main_t *src, u8 *src_tag,
700 : f64 align_tweak)
701 : {
702 : elog_event_t *e;
703 : uword l;
704 : u32 string_table_offset_for_src_events;
705 : u32 track_offset_for_src_tracks;
706 : elog_track_t newt;
707 : int i;
708 :
709 0 : clib_memset (&newt, 0, sizeof (newt));
710 :
711 : /* Acquire src and dst events */
712 0 : elog_get_events (src);
713 0 : elog_get_events (dst);
714 :
715 0 : string_table_offset_for_src_events = vec_len (dst->string_table);
716 0 : vec_append (dst->string_table, src->string_table);
717 :
718 0 : l = vec_len (dst->events);
719 0 : vec_append (dst->events, src->events);
720 :
721 : /* Prepend the supplied tag (if any) to all dst track names */
722 0 : if (dst_tag)
723 : {
724 0 : for (i = 0; i < vec_len (dst->tracks); i++)
725 : {
726 0 : elog_track_t *t = vec_elt_at_index (dst->tracks, i);
727 : char *new_name;
728 :
729 0 : new_name = (char *) format (0, "%s:%s%c", dst_tag, t->name, 0);
730 0 : vec_free (t->name);
731 0 : t->name = new_name;
732 : }
733 : }
734 :
735 : /*
736 : * Remember where we started allocating new tracks while merging
737 : */
738 0 : track_offset_for_src_tracks = vec_len (dst->tracks);
739 :
740 : /* Copy / tag source tracks */
741 0 : for (i = 0; i < vec_len (src->tracks); i++)
742 : {
743 0 : elog_track_t *t = vec_elt_at_index (src->tracks, i);
744 0 : if (src_tag)
745 0 : newt.name = (char *) format (0, "%s:%s%c", src_tag, t->name, 0);
746 : else
747 0 : newt.name = (char *) format (0, "%s%c", t->name, 0);
748 0 : (void) elog_track_register (dst, &newt);
749 0 : vec_free (newt.name);
750 : }
751 :
752 : /* Across all (copied) src events... */
753 0 : for (e = dst->events + l; e < vec_end (dst->events); e++)
754 : {
755 0 : elog_event_type_t *t =
756 0 : vec_elt_at_index (src->event_types, e->event_type);
757 :
758 : /* Remap type from src -> dst. */
759 0 : e->event_type = find_or_create_type (dst, t);
760 :
761 : /* Remap string table offsets for 'T' format args */
762 0 : maybe_fix_string_table_offset (e, t,
763 : string_table_offset_for_src_events);
764 :
765 : /* Remap track */
766 0 : e->track += track_offset_for_src_tracks;
767 : }
768 :
769 : /* Adjust event times for relative starting times of event streams. */
770 : {
771 : f64 dt_event, dt_os_nsec, dt_clock_nsec;
772 :
773 : /* Set clock parameters if dst was not generated by unserialize. */
774 0 : if (dst->serialize_time.cpu == 0)
775 : {
776 0 : dst->init_time = src->init_time;
777 0 : dst->serialize_time = src->serialize_time;
778 0 : dst->nsec_per_cpu_clock = src->nsec_per_cpu_clock;
779 : }
780 :
781 0 : dt_os_nsec =
782 0 : elog_time_stamp_diff_os_nsec (&src->init_time, &dst->init_time);
783 :
784 0 : dt_event = dt_os_nsec;
785 0 : dt_clock_nsec =
786 0 : (elog_time_stamp_diff_cpu (&src->init_time, &dst->init_time) * .5 *
787 0 : (dst->nsec_per_cpu_clock + src->nsec_per_cpu_clock));
788 :
789 : /*
790 : * Heuristic to see if src/dst came from same time source.
791 : * If frequencies are "the same" and os clock and cpu clock agree
792 : * to within 100e-9 secs about time difference between src/dst
793 : * init_time, then we use cpu clock. Otherwise we use OS clock.
794 : *
795 : * When merging event logs from different systems, time paradoxes
796 : * at the O(1ms) level are to be expected. Hence, the "align_tweak"
797 : * parameter. If two events logged on different processors are known
798 : * to occur in a specific order - and with a reasonably-estimated
799 : * interval - supply a non-zero "align_tweak" parameter
800 : */
801 0 : if (fabs (src->nsec_per_cpu_clock - dst->nsec_per_cpu_clock) < 1e-2
802 0 : && fabs (dt_os_nsec - dt_clock_nsec) < 100)
803 0 : dt_event = dt_clock_nsec;
804 :
805 : /* Convert to seconds. */
806 0 : dt_event *= 1e-9;
807 :
808 : /*
809 : * Move the earlier set of events later, to avoid creating
810 : * events which precede the Big Bang (aka have negative timestamps).
811 : *
812 : * Not to any scale, we have something like the following picture:
813 : *
814 : * DST capture start point
815 : * ^
816 : * +--- dt_event --+
817 : * v
818 : * SRC capture start point
819 : *
820 : * In this case dt_event is positive, src started after dst,
821 : * to put src events onto a common timebase we have to move them
822 : * forward in time. Naturally, the opposite case is
823 : * possible, too: dt_event will be negative, and so we have to
824 : * move dst events forward in time by the |dt_event|.
825 : * In both cases, we add align_tweak.
826 : */
827 0 : if (dt_event > 0)
828 : {
829 : /* Src started after dst. */
830 0 : for (e = dst->events + l; e < vec_end (dst->events); e++)
831 0 : e->time += dt_event + align_tweak;
832 : }
833 : else
834 : {
835 : /* Dst started after src. */
836 0 : dt_event = -dt_event;
837 0 : for (e = dst->events + 0; e < dst->events + l; e++)
838 0 : e->time += dt_event + align_tweak;
839 : }
840 : }
841 :
842 : /* Sort events by increasing time. */
843 0 : vec_sort_with_function (dst->events, elog_cmp);
844 :
845 0 : dst->n_total_events = vec_len (dst->events);
846 :
847 : /* Recreate the event ring or the results won't serialize */
848 : {
849 : int i;
850 :
851 0 : ASSERT (dst->cpu_timer.seconds_per_clock);
852 :
853 0 : elog_alloc (dst, vec_len (dst->events));
854 0 : for (i = 0; i < vec_len (dst->events); i++)
855 : {
856 : elog_event_t *es, *ed;
857 :
858 0 : es = dst->events + i;
859 0 : ed = dst->event_ring + i;
860 :
861 0 : ed[0] = es[0];
862 : }
863 : }
864 0 : }
865 :
866 : static void
867 0 : serialize_elog_event (serialize_main_t * m, va_list * va)
868 : {
869 0 : elog_main_t *em = va_arg (*va, elog_main_t *);
870 0 : elog_event_t *e = va_arg (*va, elog_event_t *);
871 0 : elog_event_type_t *t = vec_elt_at_index (em->event_types, e->event_type);
872 0 : u8 *d = e->data;
873 0 : u8 *p = (u8 *) t->format_args;
874 :
875 0 : serialize_integer (m, e->event_type, sizeof (e->event_type));
876 0 : serialize_integer (m, e->track, sizeof (e->track));
877 0 : serialize (m, serialize_f64, e->time);
878 :
879 0 : while (*p)
880 : {
881 0 : uword n_digits, n_bytes = 0;
882 :
883 0 : n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
884 :
885 0 : switch (p[0])
886 : {
887 0 : case 'i':
888 : case 't':
889 : case 'T':
890 0 : if (n_bytes == 1)
891 0 : serialize_integer (m, d[0], sizeof (u8));
892 0 : else if (n_bytes == 2)
893 0 : serialize_integer (m, clib_mem_unaligned (d, u16), sizeof (u16));
894 0 : else if (n_bytes == 4)
895 0 : serialize_integer (m, clib_mem_unaligned (d, u32), sizeof (u32));
896 0 : else if (n_bytes == 8)
897 0 : serialize (m, serialize_64, clib_mem_unaligned (d, u64));
898 : else
899 0 : ASSERT (0);
900 0 : break;
901 :
902 0 : case 's':
903 0 : serialize_cstring (m, (char *) d);
904 0 : if (n_bytes == 0)
905 0 : n_bytes = strlen ((char *) d) + 1;
906 0 : break;
907 :
908 0 : case 'f':
909 0 : if (n_bytes == 4)
910 0 : serialize (m, serialize_f32, clib_mem_unaligned (d, f32));
911 0 : else if (n_bytes == 8)
912 0 : serialize (m, serialize_f64, clib_mem_unaligned (d, f64));
913 : else
914 0 : ASSERT (0);
915 0 : break;
916 :
917 0 : default:
918 0 : ASSERT (0);
919 0 : break;
920 : }
921 :
922 0 : p += 1 + n_digits;
923 0 : d += n_bytes;
924 : }
925 0 : }
926 :
927 : static void
928 0 : unserialize_elog_event (serialize_main_t * m, va_list * va)
929 : {
930 0 : elog_main_t *em = va_arg (*va, elog_main_t *);
931 0 : elog_event_t *e = va_arg (*va, elog_event_t *);
932 : elog_event_type_t *t;
933 : u8 *p, *d;
934 :
935 : {
936 : u16 tmp[2];
937 :
938 0 : unserialize_integer (m, &tmp[0], sizeof (e->event_type));
939 0 : unserialize_integer (m, &tmp[1], sizeof (e->track));
940 :
941 0 : e->event_type = tmp[0];
942 0 : e->track = tmp[1];
943 :
944 : /* Make sure it fits. */
945 0 : ASSERT (e->event_type == tmp[0]);
946 0 : ASSERT (e->track == tmp[1]);
947 : }
948 :
949 0 : t = vec_elt_at_index (em->event_types, e->event_type);
950 :
951 0 : unserialize (m, unserialize_f64, &e->time);
952 :
953 0 : d = e->data;
954 0 : p = (u8 *) t->format_args;
955 :
956 0 : while (p && *p)
957 : {
958 0 : uword n_digits, n_bytes = 0;
959 : u32 tmp;
960 :
961 0 : n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
962 :
963 0 : switch (p[0])
964 : {
965 0 : case 'i':
966 : case 't':
967 : case 'T':
968 0 : if (n_bytes == 1)
969 : {
970 0 : unserialize_integer (m, &tmp, sizeof (u8));
971 0 : d[0] = tmp;
972 : }
973 0 : else if (n_bytes == 2)
974 : {
975 0 : unserialize_integer (m, &tmp, sizeof (u16));
976 0 : clib_mem_unaligned (d, u16) = tmp;
977 : }
978 0 : else if (n_bytes == 4)
979 : {
980 0 : unserialize_integer (m, &tmp, sizeof (u32));
981 0 : clib_mem_unaligned (d, u32) = tmp;
982 : }
983 0 : else if (n_bytes == 8)
984 : {
985 : u64 x;
986 0 : unserialize (m, unserialize_64, &x);
987 0 : clib_mem_unaligned (d, u64) = x;
988 : }
989 : else
990 0 : ASSERT (0);
991 0 : break;
992 :
993 0 : case 's':
994 : {
995 : char *t;
996 0 : unserialize_cstring (m, &t);
997 0 : if (n_bytes == 0)
998 0 : n_bytes = strlen (t) + 1;
999 0 : clib_memcpy (d, t, clib_min (n_bytes, vec_len (t)));
1000 0 : vec_free (t);
1001 0 : break;
1002 : }
1003 :
1004 0 : case 'f':
1005 0 : if (n_bytes == 4)
1006 : {
1007 : f32 x;
1008 0 : unserialize (m, unserialize_f32, &x);
1009 0 : clib_mem_unaligned (d, f32) = x;
1010 : }
1011 0 : else if (n_bytes == 8)
1012 : {
1013 : f64 x;
1014 0 : unserialize (m, unserialize_f64, &x);
1015 0 : clib_mem_unaligned (d, f64) = x;
1016 : }
1017 : else
1018 0 : ASSERT (0);
1019 0 : break;
1020 :
1021 0 : default:
1022 0 : ASSERT (0);
1023 0 : break;
1024 : }
1025 :
1026 0 : p += 1 + n_digits;
1027 0 : d += n_bytes;
1028 : }
1029 0 : }
1030 :
1031 : static void
1032 0 : serialize_elog_event_type (serialize_main_t * m, va_list * va)
1033 : {
1034 0 : elog_event_type_t *t = va_arg (*va, elog_event_type_t *);
1035 0 : int n = va_arg (*va, int);
1036 : int i, j;
1037 0 : for (i = 0; i < n; i++)
1038 : {
1039 0 : serialize_cstring (m, t[i].format);
1040 0 : serialize_cstring (m, t[i].format_args);
1041 0 : serialize_integer (m, t[i].type_index_plus_one,
1042 : sizeof (t->type_index_plus_one));
1043 0 : serialize_integer (m, t[i].n_enum_strings,
1044 : sizeof (t[i].n_enum_strings));
1045 0 : for (j = 0; j < t[i].n_enum_strings; j++)
1046 0 : serialize_cstring (m, t[i].enum_strings_vector[j]);
1047 : }
1048 0 : }
1049 :
1050 : static void
1051 0 : unserialize_elog_event_type (serialize_main_t * m, va_list * va)
1052 : {
1053 0 : elog_event_type_t *t = va_arg (*va, elog_event_type_t *);
1054 0 : int n = va_arg (*va, int);
1055 : int i, j;
1056 0 : for (i = 0; i < n; i++)
1057 : {
1058 0 : unserialize_cstring (m, &t[i].format);
1059 0 : unserialize_cstring (m, &t[i].format_args);
1060 0 : unserialize_integer (m, &t[i].type_index_plus_one,
1061 : sizeof (t->type_index_plus_one));
1062 0 : unserialize_integer (m, &t[i].n_enum_strings,
1063 : sizeof (t[i].n_enum_strings));
1064 0 : vec_resize (t[i].enum_strings_vector, t[i].n_enum_strings);
1065 0 : for (j = 0; j < t[i].n_enum_strings; j++)
1066 0 : unserialize_cstring (m, &t[i].enum_strings_vector[j]);
1067 : }
1068 0 : }
1069 :
1070 : static void
1071 0 : serialize_elog_track (serialize_main_t * m, va_list * va)
1072 : {
1073 0 : elog_track_t *t = va_arg (*va, elog_track_t *);
1074 0 : int n = va_arg (*va, int);
1075 : int i;
1076 0 : for (i = 0; i < n; i++)
1077 : {
1078 0 : serialize_cstring (m, t[i].name);
1079 : }
1080 0 : }
1081 :
1082 : static void
1083 0 : unserialize_elog_track (serialize_main_t * m, va_list * va)
1084 : {
1085 0 : elog_track_t *t = va_arg (*va, elog_track_t *);
1086 0 : int n = va_arg (*va, int);
1087 : int i;
1088 0 : for (i = 0; i < n; i++)
1089 : {
1090 0 : unserialize_cstring (m, &t[i].name);
1091 : }
1092 0 : }
1093 :
1094 : static void
1095 0 : serialize_elog_time_stamp (serialize_main_t * m, va_list * va)
1096 : {
1097 0 : elog_time_stamp_t *st = va_arg (*va, elog_time_stamp_t *);
1098 0 : serialize (m, serialize_64, st->os_nsec);
1099 0 : serialize (m, serialize_64, st->cpu);
1100 0 : }
1101 :
1102 : static void
1103 0 : unserialize_elog_time_stamp (serialize_main_t * m, va_list * va)
1104 : {
1105 0 : elog_time_stamp_t *st = va_arg (*va, elog_time_stamp_t *);
1106 0 : unserialize (m, unserialize_64, &st->os_nsec);
1107 0 : unserialize (m, unserialize_64, &st->cpu);
1108 0 : }
1109 :
1110 : static char *elog_serialize_magic = "elog v0";
1111 :
1112 : __clib_export void
1113 0 : serialize_elog_main (serialize_main_t * m, va_list * va)
1114 : {
1115 0 : elog_main_t *em = va_arg (*va, elog_main_t *);
1116 0 : int flush_ring = va_arg (*va, int);
1117 : elog_event_t *e;
1118 :
1119 0 : serialize_magic (m, elog_serialize_magic, strlen (elog_serialize_magic));
1120 :
1121 0 : serialize_integer (m, em->event_ring_size, sizeof (u32));
1122 :
1123 0 : elog_time_now (&em->serialize_time);
1124 0 : serialize (m, serialize_elog_time_stamp, &em->serialize_time);
1125 0 : serialize (m, serialize_elog_time_stamp, &em->init_time);
1126 :
1127 0 : vec_serialize (m, em->event_types, serialize_elog_event_type);
1128 0 : vec_serialize (m, em->tracks, serialize_elog_track);
1129 0 : vec_serialize (m, em->string_table, serialize_vec_8);
1130 :
1131 : /* Free old events (cached) in case they have changed. */
1132 0 : if (flush_ring)
1133 : {
1134 0 : vec_free (em->events);
1135 0 : elog_get_events (em);
1136 : }
1137 :
1138 0 : serialize_integer (m, vec_len (em->events), sizeof (u32));
1139 :
1140 : /* SMP logs can easily have local time paradoxes... */
1141 0 : vec_sort_with_function (em->events, elog_cmp);
1142 :
1143 0 : vec_foreach (e, em->events) serialize (m, serialize_elog_event, em, e);
1144 0 : }
1145 :
1146 : __clib_export void
1147 0 : unserialize_elog_main (serialize_main_t *m, va_list *va)
1148 : {
1149 0 : elog_main_t *em = va_arg (*va, elog_main_t *);
1150 : uword i;
1151 : u32 rs;
1152 :
1153 0 : unserialize_check_magic (m, elog_serialize_magic,
1154 0 : strlen (elog_serialize_magic));
1155 :
1156 0 : unserialize_integer (m, &rs, sizeof (u32));
1157 0 : em->event_ring_size = rs;
1158 0 : elog_init (em, em->event_ring_size);
1159 :
1160 0 : unserialize (m, unserialize_elog_time_stamp, &em->serialize_time);
1161 0 : unserialize (m, unserialize_elog_time_stamp, &em->init_time);
1162 0 : em->nsec_per_cpu_clock = elog_nsec_per_clock (em);
1163 :
1164 0 : vec_unserialize (m, &em->event_types, unserialize_elog_event_type);
1165 0 : for (i = 0; i < vec_len (em->event_types); i++)
1166 0 : new_event_type (em, i);
1167 :
1168 0 : vec_unserialize (m, &em->tracks, unserialize_elog_track);
1169 0 : vec_unserialize (m, &em->string_table, unserialize_vec_8);
1170 :
1171 : {
1172 : u32 ne;
1173 : elog_event_t *e;
1174 :
1175 0 : unserialize_integer (m, &ne, sizeof (u32));
1176 0 : vec_resize (em->events, ne);
1177 0 : vec_foreach (e, em->events)
1178 0 : unserialize (m, unserialize_elog_event, em, e);
1179 : }
1180 0 : }
1181 :
1182 : #ifdef CLIB_UNIX
1183 : clib_error_t *
1184 0 : elog_write_file_not_inline (elog_main_t * em, char *clib_file, int flush_ring)
1185 : {
1186 : serialize_main_t m;
1187 : clib_error_t *error;
1188 :
1189 0 : error = serialize_open_clib_file (&m, clib_file);
1190 0 : if (error)
1191 0 : return error;
1192 0 : error = serialize (&m, serialize_elog_main, em, flush_ring);
1193 0 : if (!error)
1194 0 : serialize_close (&m);
1195 0 : return error;
1196 : }
1197 :
1198 : __clib_export clib_error_t *
1199 0 : elog_read_file_not_inline (elog_main_t * em, char *clib_file)
1200 : {
1201 0 : serialize_main_t m = { 0 };
1202 : clib_error_t *error;
1203 :
1204 0 : error = unserialize_open_clib_file (&m, clib_file);
1205 0 : if (error)
1206 0 : return error;
1207 0 : error = unserialize (&m, unserialize_elog_main, em);
1208 0 : if (!error)
1209 0 : unserialize_close (&m);
1210 0 : return error;
1211 : }
1212 : #endif /* CLIB_UNIX */
1213 :
1214 :
1215 : /*
1216 : * fd.io coding-style-patch-verification: ON
1217 : *
1218 : * Local Variables:
1219 : * eval: (c-set-style "gnu")
1220 : * End:
1221 : */
|
