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:
7 * http://www.apache.org/licenses/LICENSE-2.0
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.
16 Copyright (c) 2005,2009 Eliot Dresselhaus
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:
26 The above copyright notice and this permission notice shall be
27 included in all copies or substantial portions of the Software.
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.
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>
46 elog_lock (elog_main_t * em)
48 if (PREDICT_FALSE (em->lock != 0))
49 while (__sync_lock_test_and_set (em->lock, 1))
54 elog_unlock (elog_main_t * em)
56 if (PREDICT_FALSE (em->lock != 0))
58 CLIB_MEMORY_BARRIER ();
63 /* Non-inline version. */
65 elog_event_data (elog_main_t * em,
66 elog_event_type_t * type, elog_track_t * track, u64 cpu_time)
68 return elog_event_data_inline (em, type, track, cpu_time);
72 new_event_type (elog_main_t * em, uword i)
74 elog_event_type_t *t = vec_elt_at_index (em->event_types, i);
76 if (!em->event_type_by_format)
77 em->event_type_by_format =
78 hash_create_vec ( /* size */ 0, sizeof (u8), sizeof (uword));
80 hash_set_mem (em->event_type_by_format, t->format, i);
84 find_or_create_type (elog_main_t * em, elog_event_type_t * t)
86 uword *p = hash_get_mem (em->event_type_by_format, t->format);
93 i = vec_len (em->event_types);
94 vec_add1 (em->event_types, t[0]);
95 new_event_type (em, i);
101 /* External function to register types. */
103 elog_event_type_register (elog_main_t * em, elog_event_type_t * t)
105 elog_event_type_t *static_type = t;
110 l = vec_len (em->event_types);
112 t->type_index_plus_one = 1 + l;
116 /* If format args are not specified try to be smart about providing defaults
117 so most of the time user does not have to specify them. */
123 l = strlen (t->format);
124 for (i = 0; i < l; i++)
126 if (t->format[i] != '%')
130 if (t->format[i + 1] == '%') /* %% */
133 switch (t->format[i + 1])
139 this_arg = "i4"; /* size of u32 */
142 this_arg = "f8"; /* defaults to f64 */
145 this_arg = "s0"; /* defaults to null terminated string. */
150 (char *) format ((u8 *) t->format_args, "%s", this_arg);
153 /* Null terminate. */
154 vec_add1 (t->format_args, 0);
157 vec_add1 (em->event_types, t[0]);
159 t = em->event_types + l;
161 /* Make copies of strings for hashing etc. */
163 t->format = (char *) format (0, "%s %s%c", t->function, t->format, 0);
165 t->format = (char *) format (0, "%s%c", t->format, 0);
167 t->format_args = (char *) format (0, "%s%c", t->format_args, 0);
169 /* Construct string table. */
172 t->n_enum_strings = static_type->n_enum_strings;
173 for (i = 0; i < t->n_enum_strings; i++)
175 if (!static_type->enum_strings[i])
176 static_type->enum_strings[i] = "MISSING";
177 vec_add1 (t->enum_strings_vector,
178 (char *) format (0, "%s%c", static_type->enum_strings[i],
183 new_event_type (em, l);
190 elog_track_register (elog_main_t * em, elog_track_t * t)
196 l = vec_len (em->tracks);
198 t->track_index_plus_one = 1 + l;
202 vec_add1 (em->tracks, t[0]);
206 t->name = (char *) format (0, "%s%c", t->name, 0);
214 parse_2digit_decimal (char *p, uword * number)
219 digits[0] = digits[1] = 0;
220 while (p[i] >= '0' && p[i] <= '9')
224 digits[i] = p[i] - '0';
228 if (i >= 1 && i <= 2)
233 *number = 10 * digits[0] + digits[1];
241 fixed_format (u8 * s, char *fmt, char *result, uword * result_len)
251 if (f[0] == '%' && f[1] != '%')
256 vec_add (s, fmt, f - fmt);
264 /* Skip possible +-= justification. */
265 f += f[0] == '+' || f[0] == '-' || f[0] == '=';
267 /* Skip possible X.Y width. */
268 while ((f[0] >= '0' && f[0] <= '9') || f[0] == '.')
271 /* Skip wlL as in e.g. %Ld. */
272 f += f[0] == 'w' || f[0] == 'l' || f[0] == 'L';
274 /* Finally skip format letter. */
277 ASSERT (*result_len > f - percent);
278 l = clib_min (f - percent, *result_len - 1);
279 clib_memcpy (result, percent, l);
283 *result_len = f - fmt;
288 format_elog_event (u8 * s, va_list * va)
290 elog_main_t *em = va_arg (*va, elog_main_t *);
291 elog_event_t *e = va_arg (*va, elog_event_t *);
292 elog_event_type_t *t;
294 void *d = (u8 *) e->data;
297 t = vec_elt_at_index (em->event_types, e->type);
303 uword n_bytes = 0, n_digits, f_bytes = 0;
305 f_bytes = sizeof (arg_format);
306 s = fixed_format (s, f, arg_format, &f_bytes);
309 if (a == 0 || a[0] == 0)
311 /* Format must also be at end. */
316 /* Don't go past end of event data. */
317 ASSERT (d < (void *) (e->data + sizeof (e->data)));
319 n_digits = parse_2digit_decimal (a + 1, &n_bytes);
331 else if (n_bytes == 2)
332 i = clib_mem_unaligned (d, u16);
333 else if (n_bytes == 4)
334 i = clib_mem_unaligned (d, u32);
335 else if (n_bytes == 8)
336 l = clib_mem_unaligned (d, u64);
342 vec_elt (t->enum_strings_vector, n_bytes == 8 ? l : i);
343 s = format (s, arg_format, e);
345 else if (a[0] == 'T')
348 vec_elt_at_index (em->string_table, n_bytes == 8 ? l : i);
349 s = format (s, arg_format, e);
351 else if (n_bytes == 8)
352 s = format (s, arg_format, l);
354 s = format (s, arg_format, i);
362 x = clib_mem_unaligned (d, f32);
363 else if (n_bytes == 8)
364 x = clib_mem_unaligned (d, f64);
367 s = format (s, arg_format, x);
372 s = format (s, arg_format, d);
374 n_bytes = strlen (d) + 1;
382 ASSERT (n_digits > 0 && n_digits <= 2);
391 format_elog_track (u8 * s, va_list * va)
393 elog_main_t *em = va_arg (*va, elog_main_t *);
394 elog_event_t *e = va_arg (*va, elog_event_t *);
395 elog_track_t *t = vec_elt_at_index (em->tracks, e->track);
396 return format (s, "%s", t->name);
400 elog_time_now (elog_time_stamp_t * et)
402 u64 cpu_time_now, os_time_now_nsec;
406 #include <sys/syscall.h>
408 syscall (SYS_clock_gettime, CLOCK_REALTIME, &ts);
409 cpu_time_now = clib_cpu_time_now ();
410 os_time_now_nsec = 1e9 * ts.tv_sec + ts.tv_nsec;
413 cpu_time_now = clib_cpu_time_now ();
414 os_time_now_nsec = 0;
417 et->cpu = cpu_time_now;
418 et->os_nsec = os_time_now_nsec;
422 elog_time_stamp_diff_os_nsec (elog_time_stamp_t * t1, elog_time_stamp_t * t2)
424 return (i64) t1->os_nsec - (i64) t2->os_nsec;
428 elog_time_stamp_diff_cpu (elog_time_stamp_t * t1, elog_time_stamp_t * t2)
430 return (i64) t1->cpu - (i64) t2->cpu;
434 elog_nsec_per_clock (elog_main_t * em)
436 return ((f64) elog_time_stamp_diff_os_nsec (&em->serialize_time,
438 / (f64) elog_time_stamp_diff_cpu (&em->serialize_time,
443 elog_alloc (elog_main_t * em, u32 n_events)
446 vec_free (em->event_ring);
448 /* Ring size must be a power of 2. */
449 em->event_ring_size = n_events = max_pow2 (n_events);
451 /* Leave an empty ievent at end so we can always speculatively write
452 and event there (possibly a long form event). */
453 vec_resize_aligned (em->event_ring, n_events, CLIB_CACHE_LINE_BYTES);
457 elog_init (elog_main_t * em, u32 n_events)
459 memset (em, 0, sizeof (em[0]));
464 elog_alloc (em, n_events);
466 clib_time_init (&em->cpu_timer);
468 em->n_total_events_disable_limit = ~0;
471 em->default_track.name = "default";
472 elog_track_register (em, &em->default_track);
474 elog_time_now (&em->init_time);
477 /* Returns number of events in ring and start index. */
479 elog_event_range (elog_main_t * em, uword * lo)
481 uword l = em->event_ring_size;
482 u64 i = em->n_total_events;
484 /* Ring never wrapped? */
500 elog_peek_events (elog_main_t * em)
502 elog_event_t *e, *f, *es = 0;
505 n = elog_event_range (em, &j);
506 for (i = 0; i < n; i++)
509 f = vec_elt_at_index (em->event_ring, j);
512 /* Convert absolute time from cycles to seconds from start. */
515 em->init_time.cpu) * em->cpu_timer.seconds_per_clock;
517 j = (j + 1) & (em->event_ring_size - 1);
523 /* Add a formatted string to the string table. */
525 elog_string (elog_main_t * em, char *fmt, ...)
531 offset = vec_len (em->string_table);
532 em->string_table = (char *) va_format ((u8 *) em->string_table, fmt, &va);
535 /* Null terminate string if it is not already. */
536 if (vec_end (em->string_table)[-1] != 0)
537 vec_add1 (em->string_table, 0);
543 elog_get_events (elog_main_t * em)
546 em->events = elog_peek_events (em);
551 maybe_fix_string_table_offset (elog_event_t * e,
552 elog_event_type_t * t, u32 offset)
554 void *d = (u8 *) e->data;
564 uword n_bytes = 0, n_digits;
569 /* Don't go past end of event data. */
570 ASSERT (d < (void *) (e->data + sizeof (e->data)));
572 n_digits = parse_2digit_decimal (a + 1, &n_bytes);
576 ASSERT (n_bytes == 4);
577 clib_mem_unaligned (d, u32) += offset;
591 ASSERT (n_digits > 0 && n_digits <= 2);
598 elog_cmp (void *a1, void *a2)
600 elog_event_t *e1 = a1;
601 elog_event_t *e2 = a2;
603 return e1->time - e2->time;
607 elog_merge (elog_main_t * dst, u8 * dst_tag, elog_main_t * src, u8 * src_tag)
611 u32 string_table_offset_for_src_events;
612 u32 track_offset_for_src_tracks;
616 memset (&newt, 0, sizeof (newt));
618 elog_get_events (src);
619 elog_get_events (dst);
621 string_table_offset_for_src_events = vec_len (dst->string_table);
622 vec_append (dst->string_table, src->string_table);
624 l = vec_len (dst->events);
625 vec_add (dst->events, src->events, vec_len (src->events));
627 /* Prepend the supplied tag (if any) to all dst track names */
630 for (i = 0; i < vec_len (dst->tracks); i++)
632 elog_track_t *t = vec_elt_at_index (dst->tracks, i);
635 new_name = (char *) format (0, "%s:%s%c", dst_tag, t->name, 0);
641 track_offset_for_src_tracks = vec_len (dst->tracks);
643 /* Copy / tag source tracks */
644 for (i = 0; i < vec_len (src->tracks); i++)
646 elog_track_t *t = vec_elt_at_index (src->tracks, i);
648 newt.name = (char *) format (0, "%s:%s%c", src_tag, t->name, 0);
650 newt.name = (char *) format (0, "%s%c", t->name, 0);
651 (void) elog_track_register (dst, &newt);
652 vec_free (newt.name);
655 /* Across all (copied) src events... */
656 for (e = dst->events + l; e < vec_end (dst->events); e++)
658 elog_event_type_t *t = vec_elt_at_index (src->event_types, e->type);
660 /* Remap type from src -> dst. */
661 e->type = find_or_create_type (dst, t);
663 /* Remap string table offsets for 'T' format args */
664 maybe_fix_string_table_offset (e, t,
665 string_table_offset_for_src_events);
668 e->track += track_offset_for_src_tracks;
671 /* Adjust event times for relative starting times of event streams. */
673 f64 dt_event, dt_os_nsec, dt_clock_nsec;
675 /* Set clock parameters if dst was not generated by unserialize. */
676 if (dst->serialize_time.cpu == 0)
678 dst->init_time = src->init_time;
679 dst->serialize_time = src->serialize_time;
680 dst->nsec_per_cpu_clock = src->nsec_per_cpu_clock;
684 elog_time_stamp_diff_os_nsec (&src->init_time, &dst->init_time);
686 dt_event = dt_os_nsec;
688 (elog_time_stamp_diff_cpu (&src->init_time, &dst->init_time) * .5 *
689 (dst->nsec_per_cpu_clock + src->nsec_per_cpu_clock));
691 /* Heuristic to see if src/dst came from same time source.
692 If frequencies are "the same" and os clock and cpu clock agree
693 to within 100e-9 secs about time difference between src/dst
694 init_time, then we use cpu clock. Otherwise we use OS clock. */
695 if (fabs (src->nsec_per_cpu_clock - dst->nsec_per_cpu_clock) < 1e-2
696 && fabs (dt_os_nsec - dt_clock_nsec) < 100)
697 dt_event = dt_clock_nsec;
699 /* Convert to seconds. */
704 /* Src started after dst. */
705 for (e = dst->events + l; e < vec_end (dst->events); e++)
710 /* Dst started after src. */
711 for (e = dst->events + 0; e < dst->events + l; e++)
716 /* Sort events by increasing time. */
717 vec_sort_with_function (dst->events, elog_cmp);
719 /* Recreate the event ring or the results won't serialize */
723 ASSERT (dst->cpu_timer.seconds_per_clock);
725 elog_alloc (dst, vec_len (dst->events));
726 for (i = 0; i < vec_len (dst->events); i++)
728 elog_event_t *es, *ed;
730 es = dst->events + i;
731 ed = dst->event_ring + i;
735 /* Invert elog_peek_events calculation */
737 (es->time / dst->cpu_timer.seconds_per_clock) + dst->init_time.cpu;
739 dst->n_total_events = vec_len (dst->events);
744 serialize_elog_event (serialize_main_t * m, va_list * va)
746 elog_main_t *em = va_arg (*va, elog_main_t *);
747 elog_event_t *e = va_arg (*va, elog_event_t *);
748 elog_event_type_t *t = vec_elt_at_index (em->event_types, e->type);
750 u8 *p = (u8 *) t->format_args;
752 serialize_integer (m, e->type, sizeof (e->type));
753 serialize_integer (m, e->track, sizeof (e->track));
754 serialize (m, serialize_f64, e->time);
758 uword n_digits, n_bytes = 0;
760 n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
768 serialize_integer (m, d[0], sizeof (u8));
769 else if (n_bytes == 2)
770 serialize_integer (m, clib_mem_unaligned (d, u16), sizeof (u16));
771 else if (n_bytes == 4)
772 serialize_integer (m, clib_mem_unaligned (d, u32), sizeof (u32));
773 else if (n_bytes == 8)
774 serialize (m, serialize_64, clib_mem_unaligned (d, u64));
780 serialize_cstring (m, (char *) d);
782 n_bytes = strlen ((char *) d) + 1;
787 serialize (m, serialize_f32, clib_mem_unaligned (d, f32));
788 else if (n_bytes == 8)
789 serialize (m, serialize_f64, clib_mem_unaligned (d, f64));
805 unserialize_elog_event (serialize_main_t * m, va_list * va)
807 elog_main_t *em = va_arg (*va, elog_main_t *);
808 elog_event_t *e = va_arg (*va, elog_event_t *);
809 elog_event_type_t *t;
815 unserialize_integer (m, &tmp[0], sizeof (e->type));
816 unserialize_integer (m, &tmp[1], sizeof (e->track));
821 /* Make sure it fits. */
822 ASSERT (e->type == tmp[0]);
823 ASSERT (e->track == tmp[1]);
826 t = vec_elt_at_index (em->event_types, e->type);
828 unserialize (m, unserialize_f64, &e->time);
831 p = (u8 *) t->format_args;
835 uword n_digits, n_bytes = 0;
838 n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
847 unserialize_integer (m, &tmp, sizeof (u8));
850 else if (n_bytes == 2)
852 unserialize_integer (m, &tmp, sizeof (u16));
853 clib_mem_unaligned (d, u16) = tmp;
855 else if (n_bytes == 4)
857 unserialize_integer (m, &tmp, sizeof (u32));
858 clib_mem_unaligned (d, u32) = tmp;
860 else if (n_bytes == 8)
863 unserialize (m, unserialize_64, &x);
864 clib_mem_unaligned (d, u64) = x;
873 unserialize_cstring (m, &t);
875 n_bytes = strlen (t) + 1;
876 clib_memcpy (d, t, clib_min (n_bytes, vec_len (t)));
885 unserialize (m, unserialize_f32, &x);
886 clib_mem_unaligned (d, f32) = x;
888 else if (n_bytes == 8)
891 unserialize (m, unserialize_f64, &x);
892 clib_mem_unaligned (d, f64) = x;
909 serialize_elog_event_type (serialize_main_t * m, va_list * va)
911 elog_event_type_t *t = va_arg (*va, elog_event_type_t *);
912 int n = va_arg (*va, int);
914 for (i = 0; i < n; i++)
916 serialize_cstring (m, t[i].format);
917 serialize_cstring (m, t[i].format_args);
918 serialize_integer (m, t[i].type_index_plus_one,
919 sizeof (t->type_index_plus_one));
920 serialize_integer (m, t[i].n_enum_strings,
921 sizeof (t[i].n_enum_strings));
922 for (j = 0; j < t[i].n_enum_strings; j++)
923 serialize_cstring (m, t[i].enum_strings_vector[j]);
928 unserialize_elog_event_type (serialize_main_t * m, va_list * va)
930 elog_event_type_t *t = va_arg (*va, elog_event_type_t *);
931 int n = va_arg (*va, int);
933 for (i = 0; i < n; i++)
935 unserialize_cstring (m, &t[i].format);
936 unserialize_cstring (m, &t[i].format_args);
937 unserialize_integer (m, &t[i].type_index_plus_one,
938 sizeof (t->type_index_plus_one));
939 unserialize_integer (m, &t[i].n_enum_strings,
940 sizeof (t[i].n_enum_strings));
941 vec_resize (t[i].enum_strings_vector, t[i].n_enum_strings);
942 for (j = 0; j < t[i].n_enum_strings; j++)
943 unserialize_cstring (m, &t[i].enum_strings_vector[j]);
948 serialize_elog_track (serialize_main_t * m, va_list * va)
950 elog_track_t *t = va_arg (*va, elog_track_t *);
951 int n = va_arg (*va, int);
953 for (i = 0; i < n; i++)
955 serialize_cstring (m, t[i].name);
960 unserialize_elog_track (serialize_main_t * m, va_list * va)
962 elog_track_t *t = va_arg (*va, elog_track_t *);
963 int n = va_arg (*va, int);
965 for (i = 0; i < n; i++)
967 unserialize_cstring (m, &t[i].name);
972 serialize_elog_time_stamp (serialize_main_t * m, va_list * va)
974 elog_time_stamp_t *st = va_arg (*va, elog_time_stamp_t *);
975 serialize (m, serialize_64, st->os_nsec);
976 serialize (m, serialize_64, st->cpu);
980 unserialize_elog_time_stamp (serialize_main_t * m, va_list * va)
982 elog_time_stamp_t *st = va_arg (*va, elog_time_stamp_t *);
983 unserialize (m, unserialize_64, &st->os_nsec);
984 unserialize (m, unserialize_64, &st->cpu);
987 static char *elog_serialize_magic = "elog v0";
990 serialize_elog_main (serialize_main_t * m, va_list * va)
992 elog_main_t *em = va_arg (*va, elog_main_t *);
995 serialize_magic (m, elog_serialize_magic, strlen (elog_serialize_magic));
997 serialize_integer (m, em->event_ring_size, sizeof (u32));
999 elog_time_now (&em->serialize_time);
1000 serialize (m, serialize_elog_time_stamp, &em->serialize_time);
1001 serialize (m, serialize_elog_time_stamp, &em->init_time);
1003 vec_serialize (m, em->event_types, serialize_elog_event_type);
1004 vec_serialize (m, em->tracks, serialize_elog_track);
1005 vec_serialize (m, em->string_table, serialize_vec_8);
1007 /* Free old events (cached) in case they have changed. */
1008 vec_free (em->events);
1009 elog_get_events (em);
1011 serialize_integer (m, vec_len (em->events), sizeof (u32));
1013 /* SMP logs can easily have local time paradoxes... */
1014 vec_sort_with_function (em->events, elog_cmp);
1016 vec_foreach (e, em->events) serialize (m, serialize_elog_event, em, e);
1020 unserialize_elog_main (serialize_main_t * m, va_list * va)
1022 elog_main_t *em = va_arg (*va, elog_main_t *);
1026 unserialize_check_magic (m, elog_serialize_magic,
1027 strlen (elog_serialize_magic));
1029 unserialize_integer (m, &rs, sizeof (u32));
1030 em->event_ring_size = rs;
1031 elog_init (em, em->event_ring_size);
1033 unserialize (m, unserialize_elog_time_stamp, &em->serialize_time);
1034 unserialize (m, unserialize_elog_time_stamp, &em->init_time);
1035 em->nsec_per_cpu_clock = elog_nsec_per_clock (em);
1037 vec_unserialize (m, &em->event_types, unserialize_elog_event_type);
1038 for (i = 0; i < vec_len (em->event_types); i++)
1039 new_event_type (em, i);
1041 vec_unserialize (m, &em->tracks, unserialize_elog_track);
1042 vec_unserialize (m, &em->string_table, unserialize_vec_8);
1048 unserialize_integer (m, &ne, sizeof (u32));
1049 vec_resize (em->events, ne);
1050 vec_foreach (e, em->events)
1051 unserialize (m, unserialize_elog_event, em, e);
1056 * fd.io coding-style-patch-verification: ON
1059 * eval: (c-set-style "gnu")