2 *------------------------------------------------------------------
3 * Copyright (c) 2006-2016 Cisco and/or its affiliates.
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at:
8 * http://www.apache.org/licenses/LICENSE-2.0
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
19 #include <netinet/in.h>
21 #include <sys/types.h>
24 #include <sys/fcntl.h>
28 #include <vppinfra/clib.h>
29 #include <vppinfra/vec.h>
30 #include <vppinfra/hash.h>
37 char *time_format = "%.03d:%.02d:%.02d:%.03d:%.03d ";
38 static char version[] = "cpelatency 2.0";
40 #define USEC_PER_MS 1000LL
41 #define USEC_PER_SECOND (1000*USEC_PER_MS)
42 #define USEC_PER_MINUTE (60*USEC_PER_SECOND)
43 #define USEC_PER_HOUR (60*USEC_PER_MINUTE)
45 uword *the_strtab_hash; /* (name, base-VA) hash of all string tables */
46 uword *the_evtdef_hash; /* (event-id, event-definition) hash */
47 uword *the_trackdef_hash; /* (track-id, track-definition) hash */
48 uword *the_pidtid_hash; /* ("pid:xxx tid:yy", track-definition) hash */
51 u32 start_event_code = 2; /* default: XR thread ready event */
52 u32 end_event_code = 1; /* default: XR thread running event */
53 int exclude_kernel_from_summary_stats=1;
54 int summary_stats_only;
65 sort_t sort_type = SORT_MAX_TIME;
67 int widest_name_format=5;
68 int widest_track_format=20;
70 typedef struct bound_event_ {
77 bound_event_t *bound_events;
79 typedef struct bound_track_ {
82 u64 state_start_ticks;
83 u64 *ticks_in_state; /* vector of state occurrences */
84 f64 mean_ticks_in_state;
85 f64 variance_ticks_in_state;
86 f64 total_ticks_in_state;
89 bound_track_t *bound_tracks;
93 fprintf(stderr, "%s", s);
103 int (*pass1)(cpel_section_header_t *, int, FILE *);
104 int (*pass2)(cpel_section_header_t *, int, FILE *);
105 } section_processor_t;
107 int bad_section(cpel_section_header_t *sh, int verbose, FILE *ofp)
109 fprintf(ofp, "Bad (type 0) section, skipped...\n");
113 int noop_pass(cpel_section_header_t *sh, int verbose, FILE *ofp)
118 int strtab_pass1(cpel_section_header_t *sh, int verbose, FILE *ofp)
121 u8 *strtab_data_area = (u8 *)(sh+1);
123 /* Multiple string tables with the same name are Bad... */
124 p = hash_get_mem(the_strtab_hash, strtab_data_area);
126 fprintf(ofp, "Duplicate string table name %s", strtab_data_area);
129 * Looks funny, but we really do want key = first string in the
130 * table, value = address(first string in the table)
132 hash_set_mem(the_strtab_hash, strtab_data_area, strtab_data_area);
134 fprintf(ofp, "String Table %s\n", strtab_data_area);
139 int evtdef_pass1(cpel_section_header_t *sh, int verbose, FILE *ofp)
142 event_definition_section_header_t *edh;
143 event_definition_t *ep;
150 edh = (event_definition_section_header_t *)(sh+1);
151 nevents = ntohl(edh->number_of_event_definitions);
154 fprintf(ofp, "Event Definition Section: %d definitions\n",
158 p = hash_get_mem(the_strtab_hash, edh->string_table_name);
160 fprintf(ofp, "Fatal: couldn't find string table\n");
163 this_strtab = (u8 *)p[0];
165 ep = (event_definition_t *)(edh+1);
167 for (i = 0; i < nevents; i++) {
168 event_code = ntohl(ep->event);
169 p = hash_get(the_evtdef_hash, event_code);
171 fprintf(ofp, "Event %d redefined, retain first definition\n",
175 vec_add2(bound_events, bp, 1);
176 bp->event_code = event_code;
177 bp->event_str = this_strtab + ntohl(ep->event_format);
178 bp->datum_str = this_strtab + ntohl(ep->datum_format);
179 bp->is_strtab_ref = 0;
180 /* Decide if the datum format is a %s format => strtab reference */
185 for (j = 0; j < strlen((char *) bp->datum_str); j++) {
186 if (bp->datum_str[j] == '%'){
190 if (seen_percent && bp->datum_str[j] == 's') {
191 bp->is_strtab_ref = 1;
196 hash_set(the_evtdef_hash, event_code, bp - bound_events);
198 thislen = strlen((char *) bp->event_str);
199 if (thislen > widest_name_format)
200 widest_name_format = thislen;
207 int trackdef_pass1(cpel_section_header_t *sh, int verbose, FILE *ofp)
210 track_definition_section_header_t *tdh;
211 track_definition_t *tp;
222 tdh = (track_definition_section_header_t *)(sh+1);
223 nevents = ntohl(tdh->number_of_track_definitions);
226 fprintf(ofp, "Track Definition Section: %d definitions\n",
230 p = hash_get_mem(the_strtab_hash, tdh->string_table_name);
232 fprintf(ofp, "Fatal: couldn't find string table\n");
235 this_strtab = (u8 *)p[0];
237 tp = (track_definition_t *)(tdh+1);
239 for (i = 0; i < nevents; i++) {
240 track_code = ntohl(tp->track);
241 p = hash_get(the_trackdef_hash, track_code);
243 fprintf(stderr, "track %d redefined, retain first definition\n",
247 vec_add2(bound_tracks, btp, 1);
248 btp->track = track_code;
249 btp->track_str = this_strtab + ntohl(tp->track_format);
250 hash_set(the_trackdef_hash, track_code, btp - bound_tracks);
253 fprintf(stderr, "adding track '%s'\n", btp->track_str);
256 thislen = strlen((char *) btp->track_str);
257 if (thislen > widest_track_format)
258 widest_track_format = thislen;
260 /* convert track_str "eth_server t11(20498)" to "pid:20498 tid:11" */
262 while (*cp && *cp != '(')
265 fprintf(stderr, "error canonicalizing '%s'\n", btp->track_str);
268 pidstr = cp+1; /* remember location of PID */
270 while (cp > btp->track_str && *cp != 't')
273 if (cp == btp->track_str) {
274 fprintf(stderr, "error canonicalizing '%s'\n", btp->track_str);
277 tid = atol((char *)(cp+1));
278 pid = atol((char *) pidstr);
279 pidtid_str = format(0, "pid:%d tid:%d", pid, tid);
280 vec_add1(pidtid_str, 0);
283 * Note: duplicates are possible due to thread create /
284 * thread destroy operations.
286 p = hash_get_mem(the_pidtid_hash, pidtid_str);
288 vec_free(pidtid_str);
291 hash_set_mem(the_pidtid_hash, pidtid_str, btp - bound_tracks);
300 int unsupported_pass (cpel_section_header_t *sh, int verbose, FILE *ofp)
303 fprintf(ofp, "Unsupported type %d section\n",
304 ntohl(sh->section_type));
309 int event_pass2(cpel_section_header_t *sh, int verbose, FILE *ofp)
311 event_section_header_t *eh;
322 bound_track_t *state_track=0;
328 eh = (event_section_header_t *)(sh+1);
329 nevents = ntohl(eh->number_of_events);
330 ticks_per_us = ((double)ntohl(eh->clock_ticks_per_second)) / 1e6;
333 fprintf(ofp, "%.3f ticks_per_us\n", ticks_per_us);
336 ep = (event_entry_t *)(eh+1);
338 p = hash_get_mem(the_strtab_hash, eh->string_table_name);
340 fprintf(ofp, "Fatal: couldn't find string table\n");
343 this_strtab = (u8 *)p[0];
346 * Some logger implementation that doesn't produce
347 * trackdef sections, synthesize the bound_tracks vector
349 if (!have_trackdefs) {
350 for (i = 0; i < nevents; i++) {
351 track_code = ntohl(ep->track);
352 pidtid_dup = format(0, "%d", track_code);
353 vec_add1(pidtid_dup, 0);
354 p = hash_get_mem(the_pidtid_hash, pidtid_dup);
356 vec_add2(bound_tracks, btp, 1);
357 btp->track = track_code;
358 btp->track_str = pidtid_dup;
359 hash_set(the_trackdef_hash, track_code, btp - bound_tracks);
360 hash_set_mem(the_pidtid_hash, pidtid_dup, btp - bound_tracks);
362 vec_free(pidtid_dup);
368 ep = (event_entry_t *)(eh+1);
370 for (i = 0; i < nevents; i++) {
371 time0 = ntohl (ep->time[0]);
372 time1 = ntohl (ep->time[1]);
374 now = (((u64) time0)<<32) | time1;
376 event_code = ntohl(ep->event_code);
378 /* Find the corresponding track via the pidtid hash table */
379 if (event_code == start_event_code || event_code == end_event_code) {
380 if (have_trackdefs) {
381 pidtid_str = this_strtab + ntohl(ep->event_datum);
382 pidtid_dup = format(0, (char *) pidtid_str);
383 vec_add1(pidtid_dup, 0);
384 ecp = &pidtid_dup[vec_len(pidtid_dup)-1];
385 while (*--ecp == ' ')
388 pidtid_dup = format(0, "%d", ntohl(ep->track));
389 vec_add1(pidtid_dup, 0);
392 p = hash_get_mem(the_pidtid_hash, pidtid_dup);
394 fprintf(stderr, "warning: couldn't find '%s'\n",
396 vec_free(pidtid_dup);
400 state_track = &bound_tracks[p[0]];
402 /* Found the start-event code ? */
403 if (event_code == start_event_code) {
404 state_track->state_start_ticks = now;
405 } else if (event_code == end_event_code) {
407 * Add a ticks-in-state record, unless
408 * e.g. the log started with the exit event
410 if (state_track->state_start_ticks) {
411 ticks_in_state = now - state_track->state_start_ticks;
412 vec_add1(state_track->ticks_in_state, ticks_in_state);
413 state_track->state_start_ticks = 0;
415 /* Otherwise, nothing */
423 * Note: If necessary, add passes / columns to this table to
424 * handle section order dependencies.
427 section_processor_t processors[CPEL_NUM_SECTION_TYPES+1] =
429 {bad_section, noop_pass}, /* type 0 -- f**ked */
430 {strtab_pass1, noop_pass}, /* type 1 -- STRTAB */
431 {unsupported_pass, noop_pass}, /* type 2 -- SYMTAB */
432 {evtdef_pass1, noop_pass}, /* type 3 -- EVTDEF */
433 {trackdef_pass1, noop_pass}, /* type 4 -- TRACKDEF */
434 {noop_pass, event_pass2}, /* type 5 -- EVENTS */
438 int process_section(cpel_section_header_t *sh, int verbose, FILE *ofp,
442 type = ntohl(sh->section_type);
444 int (*fp)(cpel_section_header_t *, int, FILE *);
446 if (type > CPEL_NUM_SECTION_TYPES) {
447 fprintf(stderr, "Unknown section type %d\n", type);
452 fp = processors[type].pass1;
456 fp = processors[type].pass2;
460 fprintf(stderr, "Unknown pass %d\n", pass);
464 rv = (*fp)(sh, verbose, ofp);
469 int cpel_dump_file_header(cpel_file_header_t *fh, int verbose, FILE *ofp)
474 fprintf(ofp, "CPEL file: %s-endian, version %d\n",
475 ((fh->endian_version & CPEL_FILE_LITTLE_ENDIAN) ?
477 fh->endian_version & CPEL_FILE_VERSION_MASK);
479 file_time = ntohl(fh->file_date);
481 fprintf(ofp, "File created %s", ctime(&file_time));
482 fprintf(ofp, "File has %d sections\n",
483 ntohs(fh->nsections));
490 int cpel_dump(u8 *cpel, int verbose, FILE *ofp)
492 cpel_file_header_t *fh;
493 cpel_section_header_t *sh;
498 /* First, the file header */
499 fh = (cpel_file_header_t *)cpel;
500 if (fh->endian_version != CPEL_FILE_VERSION) {
501 if (fh->endian_version & CPEL_FILE_LITTLE_ENDIAN) {
502 fprintf(stderr, "Little endian data format not supported\n");
505 fprintf(stderr, "Unsupported file version 0x%x\n",
509 cpel_dump_file_header(fh, verbose, ofp);
510 nsections = ntohs(fh->nsections);
513 * Take two passes through the file. PASS1 builds
514 * data structures, PASS2 actually dumps the file.
515 * Just in case the sections are in an unobvious order.
517 sh = (cpel_section_header_t *)(fh+1);
518 for (i = 0; i < nsections; i++) {
519 section_size = ntohl(sh->data_length);
522 fprintf(ofp, "Section type %d, size %d\n", ntohl(sh->section_type),
526 if(process_section(sh, verbose, ofp, PASS1))
530 sh = (cpel_section_header_t *)(((u8 *)sh)+section_size);
533 sh = (cpel_section_header_t *)(fh+1);
534 for (i = 0; i < nsections; i++) {
535 if(process_section(sh, verbose, ofp, PASS2))
537 section_size = ntohl(sh->data_length);
539 sh = (cpel_section_header_t *)(((u8 *)sh)+section_size);
544 void compute_state_statistics(int verbose, FILE *ofp)
550 /* Across the bound tracks */
551 for (i = 0; i < vec_len(bound_tracks); i++) {
552 bp = &bound_tracks[i];
553 bp->mean_ticks_in_state = 0.0;
554 bp->variance_ticks_in_state = 0.0;
555 bp->total_ticks_in_state = 0.0;
556 for (j = 0; j < vec_len(bp->ticks_in_state); j++) {
557 bp->total_ticks_in_state += (f64) bp->ticks_in_state[j];
560 if (vec_len(bp->ticks_in_state)) {
561 bp->mean_ticks_in_state = bp->total_ticks_in_state /
562 ((f64) vec_len(bp->ticks_in_state));
564 /* Accumulate sum: (Xi-Xbar)**2 */
565 for (j = 0; j < vec_len(bp->ticks_in_state); j++) {
566 fticks = bp->ticks_in_state[j];
567 bp->variance_ticks_in_state +=
568 (fticks - bp->mean_ticks_in_state)*
569 (fticks - bp->mean_ticks_in_state);
571 /* Compute s**2, the unbiased estimator of sigma**2 */
572 if (vec_len(bp->ticks_in_state) > 1) {
573 bp->variance_ticks_in_state /= (f64)
574 (vec_len(bp->ticks_in_state)-1);
579 int track_compare_max (const void *arg1, const void *arg2)
581 bound_track_t *a1 = (bound_track_t *)arg1;
582 bound_track_t *a2 = (bound_track_t *)arg2;
585 v1 = a1->total_ticks_in_state;
586 v2 = a2->total_ticks_in_state;
595 int track_compare_occurrences (const void *arg1, const void *arg2)
597 bound_track_t *a1 = (bound_track_t *)arg1;
598 bound_track_t *a2 = (bound_track_t *)arg2;
601 v1 = (f64) vec_len(a1->ticks_in_state);
602 v2 = (f64) vec_len(a2->ticks_in_state);
611 int track_compare_name (const void *arg1, const void *arg2)
613 bound_track_t *a1 = (bound_track_t *)arg1;
614 bound_track_t *a2 = (bound_track_t *)arg2;
616 return (strcmp((char *)(a1->track_str), (char *)(a2->track_str)));
619 void sort_state_statistics(sort_t type, FILE *ofp)
621 int (*compare)(const void *, const void *);
623 if (summary_stats_only)
628 fprintf(ofp, "Results sorted by max time in state.\n\n");
629 compare = track_compare_max;
632 case SORT_MAX_OCCURRENCES:
633 fprintf(ofp, "Results sorted by max occurrences of state.\n\n");
634 compare = track_compare_occurrences;
638 compare = track_compare_name;
639 fprintf(ofp, "Results sorted by process name, thread ID, PID\n\n");
643 fatal("sort type not set?");
646 qsort (bound_tracks, vec_len(bound_tracks),
647 sizeof (bound_track_t), compare);
650 void print_state_statistics(int verbose, FILE *ofp)
655 f64 total_time = 0.0;
656 f64 total_switches = 0.0;
658 trackpad = format(0, "%%-%ds ", widest_track_format);
659 vec_add1(trackpad, 0);
661 if (!summary_stats_only) {
662 fprintf(ofp, (char *)trackpad, "ProcName Thread(PID)");
663 fprintf(ofp, " Mean(us) Stdev(us) Total(us) N\n");
666 for (i = 0; i < vec_len(bound_tracks); i++) {
667 bp = &bound_tracks[i];
668 if (bp->mean_ticks_in_state == 0.0)
672 strncmp((char *)bp->track_str, (char *)name_filter,
673 strlen((char *)name_filter)))
677 * Exclude kernel threads (e.g. idle thread) from
680 if (exclude_kernel_from_summary_stats &&
681 !strncmp((char *) bp->track_str, "kernel ", 7))
684 total_switches += (f64) vec_len(bp->ticks_in_state);
686 if (!summary_stats_only) {
687 fprintf(ofp, (char *) trackpad, bp->track_str);
688 fprintf(ofp, "%10.3f +- %10.3f",
689 bp->mean_ticks_in_state / ticks_per_us,
690 sqrt(bp->variance_ticks_in_state)
692 fprintf(ofp, "%12.3f",
693 bp->total_ticks_in_state / ticks_per_us);
694 fprintf(ofp, "%8d\n", vec_len(bp->ticks_in_state));
698 for (j = 0; j < vec_len(bp->ticks_in_state); j++) {
699 fprintf(ofp, "%.3f\n",
700 (f64)bp->ticks_in_state[j] / ticks_per_us);
704 total_time += bp->total_ticks_in_state;
707 if (!summary_stats_only)
709 fprintf(ofp, "Note: the following statistics %s kernel-thread activity.\n",
710 exclude_kernel_from_summary_stats ? "exclude" : "include");
713 "Note: only pid/proc/threads matching '%s' are included.\n",
717 "Total time in state: %10.3f (us), Total state occurrences: %.0f\n",
718 total_time / ticks_per_us, total_switches);
719 fprintf(ofp, "Average time in state: %10.3f (us)\n",
720 (total_time / total_switches) / ticks_per_us);
721 fprintf(ofp, "State start event: %d, state end event: %d\n",
722 start_event_code, end_event_code);
725 char *mapfile (char *file)
732 maphfile = open (file, O_RDONLY);
736 fprintf (stderr, "Couldn't read %s, skipping it...\n", file);
740 if (fstat (maphfile, &statb) < 0)
742 fprintf (stderr, "Couldn't get size of %s, skipping it...\n", file);
746 /* Don't try to mmap directories, FIFOs, semaphores, etc. */
747 if (! (statb.st_mode & S_IFREG)) {
748 fprintf (stderr, "%s is not a regular file, skipping it...\n", file);
752 mapfsize = statb.st_size;
756 fprintf (stderr, "%s zero-length, skipping it...\n", file);
761 rv = mmap (0, mapfsize, PROT_READ, MAP_SHARED, maphfile, 0);
765 fprintf (stderr, "%s problem mapping, I quit...\n", file);
775 int main (int argc, char **argv)
778 char *outputfile = 0;
784 while (curarg < argc) {
785 if (!strncmp(argv[curarg], "--input-file", 3)) {
788 cpel_file = argv[curarg];
792 fatal("Missing filename after --input-file\n");
794 if (!strncmp(argv[curarg], "--output-file", 3)) {
797 outputfile = argv[curarg];
801 fatal("Missing filename after --output-file\n");
803 if (!strncmp(argv[curarg], "--verbose", 3)) {
808 if (!strncmp(argv[curarg], "--scatterplot", 4)) {
814 if (!strncmp(argv[curarg], "--start-event", 4)) {
817 start_event_code = atol(argv[curarg]);
821 fatal("Missing integer after --start-event\n");
823 if (!strncmp(argv[curarg], "--end-event", 4)) {
826 end_event_code = atol(argv[curarg]);
830 fatal("Missing integer after --end-event\n");
832 if (!strncmp(argv[curarg], "--max-time-sort", 7)) {
833 sort_type = SORT_MAX_TIME;
837 if (!strncmp(argv[curarg], "--max-occurrence-sort", 7)) {
838 sort_type = SORT_MAX_OCCURRENCES;
842 if (!strncmp(argv[curarg], "--name-sort", 3)) {
843 sort_type = SORT_NAME;
847 if (!strncmp(argv[curarg], "--kernel-included", 3)) {
848 exclude_kernel_from_summary_stats = 0;
852 if (!strncmp(argv[curarg], "--summary", 3)) {
853 summary_stats_only=1;
857 if (!strncmp(argv[curarg], "--filter", 3)) {
860 name_filter = (u8 *) argv[curarg];
864 fatal("Missing filter string after --filter\n");
870 "cpelatency --input-file <filename> [--output-file <filename>]\n");
872 " [--start-event <decimal>] [--verbose]\n");
874 " [--end-event <decimal>]\n");
876 " [--max-time-sort(default) | --max-occurrence-sort |\n");
879 " --name-sort-sort] [--kernel-included]\n");
882 " [--summary-stats-only] [--scatterplot]\n");
884 fprintf(stderr, "%s\n", version);
891 cpel = mapfile(cpel_file);
893 fprintf(stderr, "Couldn't map %s...\n", cpel_file);
898 ofp = fdopen(1, "w");
900 fprintf(stderr, "Couldn't fdopen(1)?\n");
904 ofp = fopen(outputfile, "w");
906 fprintf(stderr, "Couldn't create %s...\n", outputfile);
911 the_strtab_hash = hash_create_string (0, sizeof (uword));
912 the_evtdef_hash = hash_create (0, sizeof (uword));
913 the_trackdef_hash = hash_create (0, sizeof (uword));
914 the_pidtid_hash = hash_create_string (0, sizeof(uword));
916 if (cpel_dump((u8 *)cpel, verbose, ofp)) {
921 compute_state_statistics(verbose, ofp);
922 sort_state_statistics(sort_type, ofp);
923 print_state_statistics(verbose, ofp);