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>
45 static inline void elog_lock (elog_main_t * em)
47 if (PREDICT_FALSE(em->lock != 0))
48 while (__sync_lock_test_and_set (em->lock, 1))
52 static inline void elog_unlock (elog_main_t * em)
54 if (PREDICT_FALSE(em->lock != 0))
58 /* Non-inline version. */
60 elog_event_data (elog_main_t * em,
61 elog_event_type_t * type,
64 { return elog_event_data_inline (em, type, track, cpu_time); }
66 static void new_event_type (elog_main_t * em, uword i)
68 elog_event_type_t * t = vec_elt_at_index (em->event_types, i);
70 if (! em->event_type_by_format)
71 em->event_type_by_format = hash_create_vec (/* size */ 0, sizeof (u8), sizeof (uword));
73 hash_set_mem (em->event_type_by_format, t->format, i);
77 find_or_create_type (elog_main_t * em, elog_event_type_t * t)
79 uword * p = hash_get_mem (em->event_type_by_format, t->format);
86 i = vec_len (em->event_types);
87 vec_add1 (em->event_types, t[0]);
88 new_event_type (em, i);
94 /* External function to register types. */
95 word elog_event_type_register (elog_main_t * em, elog_event_type_t * t)
97 elog_event_type_t * static_type = t;
102 l = vec_len (em->event_types);
104 t->type_index_plus_one = 1 + l;
108 /* If format args are not specified try to be smart about providing defaults
109 so most of the time user does not have to specify them. */
110 if (! t->format_args)
115 l = strlen (t->format);
116 for (i = 0; i < l; i++)
118 if (t->format[i] != '%')
122 if (t->format[i+1] == '%') /* %% */
125 switch (t->format[i+1]) {
127 case 'd': case 'x': case 'u':
128 this_arg = "i4"; /* size of u32 */
131 this_arg = "f8"; /* defaults to f64 */
134 this_arg = "s0"; /* defaults to null terminated string. */
138 t->format_args = (char *) format ((u8 *) t->format_args, "%s", this_arg);
141 /* Null terminate. */
142 vec_add1 (t->format_args, 0);
145 vec_add1 (em->event_types, t[0]);
147 t = em->event_types + l;
149 /* Make copies of strings for hashing etc. */
151 t->format = (char *) format (0, "%s %s%c", t->function, t->format, 0);
153 t->format = (char *) format (0, "%s%c", t->format, 0);
155 t->format_args = (char *) format (0, "%s%c", t->format_args, 0);
157 /* Construct string table. */
160 t->n_enum_strings = static_type->n_enum_strings;
161 for (i = 0; i < t->n_enum_strings; i++)
163 if (! static_type->enum_strings[i])
164 static_type->enum_strings[i] = "MISSING";
165 vec_add1 (t->enum_strings_vector,
166 (char *) format (0, "%s%c", static_type->enum_strings[i], 0));
170 new_event_type (em, l);
177 word elog_track_register (elog_main_t * em, elog_track_t * t)
183 l = vec_len (em->tracks);
185 t->track_index_plus_one = 1 + l;
189 vec_add1 (em->tracks, t[0]);
193 t->name = (char *) format (0, "%s%c", t->name, 0);
200 static uword parse_2digit_decimal (char * p, uword * number)
205 digits[0] = digits[1] = 0;
206 while (p[i] >= '0' && p[i] <= '9')
210 digits[i] = p[i] - '0';
214 if (i >= 1 && i <= 2)
219 *number = 10 * digits[0] + digits[1];
226 static u8 * fixed_format (u8 * s, char * fmt, char * result, uword * result_len)
236 if (f[0] == '%' && f[1] != '%')
241 vec_add (s, fmt, f - fmt);
249 /* Skip possible +-= justification. */
250 f += f[0] == '+' || f[0] == '-' || f[0] == '=';
252 /* Skip possible X.Y width. */
253 while ((f[0] >= '0' && f[0] <= '9') || f[0] == '.')
256 /* Skip wlL as in e.g. %Ld. */
257 f += f[0] == 'w' || f[0] == 'l' || f[0] == 'L';
259 /* Finally skip format letter. */
262 ASSERT (*result_len > f - percent);
263 l = clib_min (f - percent, *result_len - 1);
264 memcpy (result, percent, l);
268 *result_len = f - fmt;
272 u8 * format_elog_event (u8 * s, va_list * va)
274 elog_main_t * em = va_arg (*va, elog_main_t *);
275 elog_event_t * e = va_arg (*va, elog_event_t *);
276 elog_event_type_t * t;
278 void * d = (u8 *) e->data;
281 t = vec_elt_at_index (em->event_types, e->type);
287 uword n_bytes = 0, n_digits, f_bytes = 0;
289 f_bytes = sizeof (arg_format);
290 s = fixed_format (s, f, arg_format, &f_bytes);
293 if (a == 0 || a[0] == 0)
295 /* Format must also be at end. */
300 /* Don't go past end of event data. */
301 ASSERT (d < (void *) (e->data + sizeof (e->data)));
303 n_digits = parse_2digit_decimal (a + 1, &n_bytes);
315 else if (n_bytes == 2)
316 i = clib_mem_unaligned (d, u16);
317 else if (n_bytes == 4)
318 i = clib_mem_unaligned (d, u32);
319 else if (n_bytes == 8)
320 l = clib_mem_unaligned (d, u64);
325 char * e = vec_elt (t->enum_strings_vector, n_bytes == 8 ? l : i);
326 s = format (s, arg_format, e);
328 else if (a[0] == 'T')
330 char * e = vec_elt_at_index (em->string_table, n_bytes == 8 ? l : i);
331 s = format (s, arg_format, e);
333 else if (n_bytes == 8)
334 s = format (s, arg_format, l);
336 s = format (s, arg_format, i);
344 x = clib_mem_unaligned (d, f32);
345 else if (n_bytes == 8)
346 x = clib_mem_unaligned (d, f64);
349 s = format (s, arg_format, x);
354 s = format (s, arg_format, d);
356 n_bytes = strlen (d) + 1;
364 ASSERT (n_digits > 0 && n_digits <= 2);
372 u8 * format_elog_track (u8 * s, va_list * va)
374 elog_main_t * em = va_arg (*va, elog_main_t *);
375 elog_event_t * e = va_arg (*va, elog_event_t *);
376 elog_track_t * t = vec_elt_at_index (em->tracks, e->track);
377 return format (s, "%s", t->name);
380 void elog_time_now (elog_time_stamp_t * et)
382 u64 cpu_time_now, os_time_now_nsec;
386 #include <sys/syscall.h>
388 syscall (SYS_clock_gettime, CLOCK_REALTIME, &ts);
389 cpu_time_now = clib_cpu_time_now ();
390 os_time_now_nsec = 1e9 * ts.tv_sec + ts.tv_nsec;
393 cpu_time_now = clib_cpu_time_now ();
394 os_time_now_nsec = 0;
397 et->cpu = cpu_time_now;
398 et->os_nsec = os_time_now_nsec;
402 elog_time_stamp_diff_os_nsec (elog_time_stamp_t * t1,
403 elog_time_stamp_t * t2)
404 { return (i64) t1->os_nsec - (i64) t2->os_nsec; }
407 elog_time_stamp_diff_cpu (elog_time_stamp_t * t1,
408 elog_time_stamp_t * t2)
409 { return (i64) t1->cpu - (i64) t2->cpu; }
412 elog_nsec_per_clock (elog_main_t * em)
414 return ((f64) elog_time_stamp_diff_os_nsec (&em->serialize_time,
416 / (f64) elog_time_stamp_diff_cpu (&em->serialize_time,
420 static void elog_alloc (elog_main_t * em, u32 n_events)
423 vec_free (em->event_ring);
425 /* Ring size must be a power of 2. */
426 em->event_ring_size = n_events = max_pow2 (n_events);
428 /* Leave an empty ievent at end so we can always speculatively write
429 and event there (possibly a long form event). */
430 vec_resize_aligned (em->event_ring, n_events, CLIB_CACHE_LINE_BYTES);
433 void elog_init (elog_main_t * em, u32 n_events)
435 memset (em, 0, sizeof (em[0]));
440 elog_alloc (em, n_events);
442 clib_time_init (&em->cpu_timer);
444 em->n_total_events_disable_limit = ~0;
447 em->default_track.name = "default";
448 elog_track_register (em, &em->default_track);
450 elog_time_now (&em->init_time);
453 /* Returns number of events in ring and start index. */
454 static uword elog_event_range (elog_main_t * em, uword * lo)
456 uword l = em->event_ring_size;
457 u64 i = em->n_total_events;
459 /* Ring never wrapped? */
467 if (lo) *lo = i & (l - 1);
472 elog_event_t * elog_peek_events (elog_main_t * em)
474 elog_event_t * e, * f, * es = 0;
477 n = elog_event_range (em, &j);
478 for (i = 0; i < n; i++)
481 f = vec_elt_at_index (em->event_ring, j);
484 /* Convert absolute time from cycles to seconds from start. */
485 e->time = (e->time_cycles - em->init_time.cpu) * em->cpu_timer.seconds_per_clock;
487 j = (j + 1) & (em->event_ring_size - 1);
493 /* Add a formatted string to the string table. */
494 u32 elog_string (elog_main_t * em, char * fmt, ...)
500 offset = vec_len (em->string_table);
501 em->string_table = (char *) va_format ((u8 *) em->string_table, fmt, &va);
504 /* Null terminate string if it is not already. */
505 if (vec_end (em->string_table)[-1] != 0)
506 vec_add1 (em->string_table, 0);
511 elog_event_t * elog_get_events (elog_main_t * em)
514 em->events = elog_peek_events (em);
518 static void maybe_fix_string_table_offset (elog_event_t * e,
519 elog_event_type_t * t,
522 void * d = (u8 *) e->data;
532 uword n_bytes = 0, n_digits;
537 /* Don't go past end of event data. */
538 ASSERT (d < (void *) (e->data + sizeof (e->data)));
540 n_digits = parse_2digit_decimal (a + 1, &n_bytes);
544 ASSERT (n_bytes == 4);
545 clib_mem_unaligned (d, u32) += offset;
559 ASSERT (n_digits > 0 && n_digits <= 2);
565 static int elog_cmp (void * a1, void * a2)
567 elog_event_t * e1 = a1;
568 elog_event_t * e2 = a2;
570 return e1->time - e2->time;
573 void elog_merge (elog_main_t * dst, u8 * dst_tag,
574 elog_main_t * src, u8 * src_tag)
578 u32 string_table_offset_for_src_events;
579 u32 track_offset_for_src_tracks;
583 elog_get_events (src);
584 elog_get_events (dst);
586 string_table_offset_for_src_events = vec_len (dst->string_table);
587 vec_append (dst->string_table, src->string_table);
589 l = vec_len (dst->events);
590 vec_add (dst->events, src->events, vec_len (src->events));
592 /* Prepend the supplied tag (if any) to all dst track names */
595 for (i = 0; i < vec_len(dst->tracks); i++)
597 elog_track_t * t = vec_elt_at_index (dst->tracks, i);
600 new_name = (char *) format (0, "%s:%s%c", dst_tag, t->name, 0);
606 track_offset_for_src_tracks = vec_len (dst->tracks);
608 /* Copy / tag source tracks */
609 for (i = 0; i < vec_len (src->tracks); i++)
611 elog_track_t * t = vec_elt_at_index (src->tracks, i);
613 newt.name = (char *) format (0, "%s:%s%c", src_tag, t->name, 0);
615 newt.name = (char *) format (0, "%s%c", t->name, 0);
616 (void) elog_track_register (dst, &newt);
617 vec_free (newt.name);
620 /* Across all (copied) src events... */
621 for (e = dst->events + l; e < vec_end (dst->events); e++)
623 elog_event_type_t * t = vec_elt_at_index (src->event_types, e->type);
625 /* Remap type from src -> dst. */
626 e->type = find_or_create_type (dst, t);
628 /* Remap string table offsets for 'T' format args */
629 maybe_fix_string_table_offset (e, t, string_table_offset_for_src_events);
632 e->track += track_offset_for_src_tracks;
635 /* Adjust event times for relative starting times of event streams. */
637 f64 dt_event, dt_os_nsec, dt_clock_nsec;
639 /* Set clock parameters if dst was not generated by unserialize. */
640 if (dst->serialize_time.cpu == 0)
642 dst->init_time = src->init_time;
643 dst->serialize_time = src->serialize_time;
644 dst->nsec_per_cpu_clock = src->nsec_per_cpu_clock;
647 dt_os_nsec = elog_time_stamp_diff_os_nsec (&src->init_time, &dst->init_time);
649 dt_event = dt_os_nsec;
650 dt_clock_nsec = (elog_time_stamp_diff_cpu (&src->init_time, &dst->init_time)
651 * .5*(dst->nsec_per_cpu_clock + src->nsec_per_cpu_clock));
653 /* Heuristic to see if src/dst came from same time source.
654 If frequencies are "the same" and os clock and cpu clock agree
655 to within 100e-9 secs about time difference between src/dst
656 init_time, then we use cpu clock. Otherwise we use OS clock. */
657 if (fabs (src->nsec_per_cpu_clock - dst->nsec_per_cpu_clock) < 1e-2
658 && fabs (dt_os_nsec - dt_clock_nsec) < 100)
659 dt_event = dt_clock_nsec;
661 /* Convert to seconds. */
666 /* Src started after dst. */
667 for (e = dst->events + l; e < vec_end (dst->events); e++)
672 /* Dst started after src. */
673 for (e = dst->events + 0; e < dst->events + l; e++)
678 /* Sort events by increasing time. */
679 vec_sort_with_function (dst->events, elog_cmp);
681 /* Recreate the event ring or the results won't serialize */
685 ASSERT (dst->cpu_timer.seconds_per_clock);
687 elog_alloc (dst, vec_len (dst->events));
688 for (i = 0; i < vec_len(dst->events); i++)
690 elog_event_t *es, *ed;
692 es = dst->events + i;
693 ed = dst->event_ring + i;
697 /* Invert elog_peek_events calculation */
699 (es->time/dst->cpu_timer.seconds_per_clock) + dst->init_time.cpu;
701 dst->n_total_events = vec_len (dst->events);
706 serialize_elog_event (serialize_main_t * m, va_list * va)
708 elog_main_t * em = va_arg (*va, elog_main_t *);
709 elog_event_t * e = va_arg (*va, elog_event_t *);
710 elog_event_type_t * t = vec_elt_at_index (em->event_types, e->type);
712 u8 * p = (u8 *) t->format_args;
714 serialize_integer (m, e->type, sizeof (e->type));
715 serialize_integer (m, e->track, sizeof (e->track));
716 serialize (m, serialize_f64, e->time);
720 uword n_digits, n_bytes = 0;
722 n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
730 serialize_integer (m, d[0], sizeof (u8));
731 else if (n_bytes == 2)
732 serialize_integer (m, clib_mem_unaligned (d, u16), sizeof (u16));
733 else if (n_bytes == 4)
734 serialize_integer (m, clib_mem_unaligned (d, u32), sizeof (u32));
735 else if (n_bytes == 8)
736 serialize (m, serialize_64, clib_mem_unaligned (d, u64));
742 serialize_cstring (m, (char *) d);
744 n_bytes = strlen ((char *) d) + 1;
749 serialize (m, serialize_f32, clib_mem_unaligned (d, f32));
750 else if (n_bytes == 8)
751 serialize (m, serialize_f64, clib_mem_unaligned (d, f64));
767 unserialize_elog_event (serialize_main_t * m, va_list * va)
769 elog_main_t * em = va_arg (*va, elog_main_t *);
770 elog_event_t * e = va_arg (*va, elog_event_t *);
771 elog_event_type_t * t;
777 unserialize_integer (m, &tmp[0], sizeof (e->type));
778 unserialize_integer (m, &tmp[1], sizeof (e->track));
783 /* Make sure it fits. */
784 ASSERT (e->type == tmp[0]);
785 ASSERT (e->track == tmp[1]);
788 t = vec_elt_at_index (em->event_types, e->type);
790 unserialize (m, unserialize_f64, &e->time);
793 p = (u8 *) t->format_args;
797 uword n_digits, n_bytes = 0;
800 n_digits = parse_2digit_decimal ((char *) p + 1, &n_bytes);
809 unserialize_integer (m, &tmp, sizeof (u8));
812 else if (n_bytes == 2)
814 unserialize_integer (m, &tmp, sizeof (u16));
815 clib_mem_unaligned (d, u16) = tmp;
817 else if (n_bytes == 4)
819 unserialize_integer (m, &tmp, sizeof (u32));
820 clib_mem_unaligned (d, u32) = tmp;
822 else if (n_bytes == 8)
825 unserialize (m, unserialize_64, &x);
826 clib_mem_unaligned (d, u64) = x;
834 unserialize_cstring (m, &t);
836 n_bytes = strlen (t) + 1;
837 memcpy (d, t, clib_min (n_bytes, vec_len (t)));
846 unserialize (m, unserialize_f32, &x);
847 clib_mem_unaligned (d, f32) = x;
849 else if (n_bytes == 8)
852 unserialize (m, unserialize_f64, &x);
853 clib_mem_unaligned (d, f64) = x;
870 serialize_elog_event_type (serialize_main_t * m, va_list * va)
872 elog_event_type_t * t = va_arg (*va, elog_event_type_t *);
873 int n = va_arg (*va, int);
875 for (i = 0; i < n; i++)
877 serialize_cstring (m, t[i].format);
878 serialize_cstring (m, t[i].format_args);
879 serialize_integer (m, t[i].type_index_plus_one, sizeof (t->type_index_plus_one));
880 serialize_integer (m, t[i].n_enum_strings, sizeof (t[i].n_enum_strings));
881 for (j = 0; j < t[i].n_enum_strings; j++)
882 serialize_cstring (m, t[i].enum_strings_vector[j]);
887 unserialize_elog_event_type (serialize_main_t * m, va_list * va)
889 elog_event_type_t * t = va_arg (*va, elog_event_type_t *);
890 int n = va_arg (*va, int);
892 for (i = 0; i < n; i++)
894 unserialize_cstring (m, &t[i].format);
895 unserialize_cstring (m, &t[i].format_args);
896 unserialize_integer (m, &t[i].type_index_plus_one, sizeof (t->type_index_plus_one));
897 unserialize_integer (m, &t[i].n_enum_strings, sizeof (t[i].n_enum_strings));
898 vec_resize (t[i].enum_strings_vector, t[i].n_enum_strings);
899 for (j = 0; j < t[i].n_enum_strings; j++)
900 unserialize_cstring (m, &t[i].enum_strings_vector[j]);
905 serialize_elog_track (serialize_main_t * m, va_list * va)
907 elog_track_t * t = va_arg (*va, elog_track_t *);
908 int n = va_arg (*va, int);
910 for (i = 0; i < n; i++)
912 serialize_cstring (m, t[i].name);
917 unserialize_elog_track (serialize_main_t * m, va_list * va)
919 elog_track_t * t = va_arg (*va, elog_track_t *);
920 int n = va_arg (*va, int);
922 for (i = 0; i < n; i++)
924 unserialize_cstring (m, &t[i].name);
929 serialize_elog_time_stamp (serialize_main_t * m, va_list * va)
931 elog_time_stamp_t * st = va_arg (*va, elog_time_stamp_t *);
932 serialize (m, serialize_64, st->os_nsec);
933 serialize (m, serialize_64, st->cpu);
937 unserialize_elog_time_stamp (serialize_main_t * m, va_list * va)
939 elog_time_stamp_t * st = va_arg (*va, elog_time_stamp_t *);
940 unserialize (m, unserialize_64, &st->os_nsec);
941 unserialize (m, unserialize_64, &st->cpu);
944 static char * elog_serialize_magic = "elog v0";
947 serialize_elog_main (serialize_main_t * m, va_list * va)
949 elog_main_t * em = va_arg (*va, elog_main_t *);
952 serialize_magic (m, elog_serialize_magic, strlen (elog_serialize_magic));
954 serialize_integer (m, em->event_ring_size, sizeof (u32));
956 elog_time_now (&em->serialize_time);
957 serialize (m, serialize_elog_time_stamp, &em->serialize_time);
958 serialize (m, serialize_elog_time_stamp, &em->init_time);
960 vec_serialize (m, em->event_types, serialize_elog_event_type);
961 vec_serialize (m, em->tracks, serialize_elog_track);
962 vec_serialize (m, em->string_table, serialize_vec_8);
964 /* Free old events (cached) in case they have changed. */
965 vec_free (em->events);
966 elog_get_events (em);
968 serialize_integer (m, vec_len (em->events), sizeof (u32));
970 /* SMP logs can easily have local time paradoxes... */
971 vec_sort_with_function (em->events, elog_cmp);
973 vec_foreach (e, em->events)
974 serialize (m, serialize_elog_event, em, e);
978 unserialize_elog_main (serialize_main_t * m, va_list * va)
980 elog_main_t * em = va_arg (*va, elog_main_t *);
984 unserialize_check_magic (m, elog_serialize_magic,
985 strlen (elog_serialize_magic));
987 unserialize_integer (m, &rs, sizeof (u32));
988 em->event_ring_size = rs;
989 elog_init (em, em->event_ring_size);
991 unserialize (m, unserialize_elog_time_stamp, &em->serialize_time);
992 unserialize (m, unserialize_elog_time_stamp, &em->init_time);
993 em->nsec_per_cpu_clock = elog_nsec_per_clock (em);
995 vec_unserialize (m, &em->event_types, unserialize_elog_event_type);
996 for (i = 0; i < vec_len (em->event_types); i++)
997 new_event_type (em, i);
999 vec_unserialize (m, &em->tracks, unserialize_elog_track);
1000 vec_unserialize (m, &em->string_table, unserialize_vec_8);
1006 unserialize_integer (m, &ne, sizeof (u32));
1007 vec_resize (em->events, ne);
1008 vec_foreach (e, em->events)
1009 unserialize (m, unserialize_elog_event, em, e);