/* *------------------------------------------------------------------ * Copyright (c) 2006-2016 Cisco and/or its affiliates. * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at: * * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. */ #include <stdio.h> #include <stdlib.h> #include <netinet/in.h> #include <string.h> #include <sys/types.h> #include <sys/stat.h> #include <fcntl.h> #include <sys/fcntl.h> #include <sys/mman.h> #include <unistd.h> #include <ctype.h> #include <vppinfra/clib.h> #include <vppinfra/vec.h> #include <vppinfra/hash.h> #include <pwd.h> #include <stdarg.h> #include <time.h> #include "cpel.h" #include <math.h> char *time_format = "%.03d:%.02d:%.02d:%.03d:%.03d "; static char version[] = "cpelstate 2.0h"; #define USEC_PER_MS 1000LL #define USEC_PER_SECOND (1000*USEC_PER_MS) #define USEC_PER_MINUTE (60*USEC_PER_SECOND) #define USEC_PER_HOUR (60*USEC_PER_MINUTE) uword *the_strtab_hash; /* (name, base-VA) hash of all string tables */ uword *the_evtdef_hash; /* (event-id, event-definition) hash */ uword *the_trackdef_hash; /* (track-id, track-definition) hash */ f64 ticks_per_us; u32 state_event_code = 1; /* default: XR thread-on-cpu */ int exclude_kernel_from_summary_stats=1; int summary_stats_only; int scatterplot; u8 *name_filter; typedef enum { SORT_MAX_TIME=1, SORT_MAX_OCCURRENCES, SORT_NAME, } sort_t; sort_t sort_type = SORT_MAX_TIME; int widest_name_format=5; int widest_track_format=5; typedef struct bound_event_ { u32 event_code; u8 *event_str; u8 *datum_str; u32 is_strtab_ref; } bound_event_t; bound_event_t *bound_events; typedef struct bound_track_ { u32 track; u8 *track_str; u64 *ticks_in_state; /* vector of state occurrences */ f64 mean_ticks_in_state; f64 variance_ticks_in_state; f64 total_ticks_in_state; } bound_track_t; bound_track_t *bound_tracks; void fatal(char *s) { fprintf(stderr, "%s", s); exit(1); } typedef enum { PASS1=1, PASS2=2, } pass_t; typedef struct { int (*pass1)(cpel_section_header_t *, int, FILE *); int (*pass2)(cpel_section_header_t *, int, FILE *); } section_processor_t; int bad_section(cpel_section_header_t *sh, int verbose, FILE *ofp) { fprintf(ofp, "Bad (type 0) section, skipped...\n"); return(0); } int noop_pass(cpel_section_header_t *sh, int verbose, FILE *ofp) { return(0); } int strtab_pass1(cpel_section_header_t *sh, int verbose, FILE *ofp) { uword *p; u8 *strtab_data_area = (u8 *)(sh+1); /* Multiple string tables with the same name are Bad... */ p = hash_get_mem(the_strtab_hash, strtab_data_area); if (p) { fprintf(ofp, "Duplicate string table name %s", strtab_data_area); } /* * Looks funny, but we really do want key = first string in the * table, value = address(first string in the table) */ hash_set_mem(the_strtab_hash, strtab_data_area, strtab_data_area); if (verbose) { fprintf(ofp, "String Table %s\n", strtab_data_area); } return(0); } int evtdef_pass1(cpel_section_header_t *sh, int verbose, FILE *ofp) { int i, nevents; event_definition_section_header_t *edh; event_definition_t *ep; u8 *this_strtab; u32 event_code; uword *p; bound_event_t *bp; int thislen; edh = (event_definition_section_header_t *)(sh+1); nevents = ntohl(edh->number_of_event_definitions); if (verbose) { fprintf(ofp, "Event Definition Section: %d definitions\n", nevents); } p = hash_get_mem(the_strtab_hash, edh->string_table_name); if (!p) { fprintf(ofp, "Fatal: couldn't find string table\n"); return(1); } this_strtab = (u8 *)p[0]; ep = (event_definition_t *)(edh+1); for (i = 0; i < nevents; i++) { event_code = ntohl(ep->event); p = hash_get(the_evtdef_hash, event_code); if (p) { fprintf(ofp, "Event %d redefined, retain first definition\n", event_code); continue; } vec_add2(bound_events, bp, 1); bp->event_code = event_code; bp->event_str = this_strtab + ntohl(ep->event_format); bp->datum_str = this_strtab + ntohl(ep->datum_format); bp->is_strtab_ref = 0; /* Decide if the datum format is a %s format => strtab reference */ { int j; int seen_percent=0; for (j = 0; j < strlen((char *)(bp->datum_str)); j++) { if (bp->datum_str[j] == '%'){ seen_percent=1; continue; } if (seen_percent && bp->datum_str[j] == 's') { bp->is_strtab_ref = 1; } } } hash_set(the_evtdef_hash, event_code, bp - bound_events); thislen = strlen((char *)bp->event_str); if (thislen > widest_name_format) widest_name_format = thislen; ep++; } return (0); } int trackdef_pass1(cpel_section_header_t *sh, int verbose, FILE *ofp) { int i, nevents; track_definition_section_header_t *tdh; track_definition_t *tp; u8 *this_strtab; u32 track_code; uword *p; bound_track_t *btp; int thislen; tdh = (track_definition_section_header_t *)(sh+1); nevents = ntohl(tdh->number_of_track_definitions); if (verbose) { fprintf(ofp, "Track Definition Section: %d definitions\n", nevents); } p = hash_get_mem(the_strtab_hash, tdh->string_table_name); if (!p) { fprintf(ofp, "Fatal: couldn't find string table\n"); return(1); } this_strtab = (u8 *)p[0]; tp = (track_definition_t *)(tdh+1); for (i = 0; i < nevents; i++) { track_code = ntohl(tp->track); p = hash_get(the_trackdef_hash, track_code); if (p) { fprintf(ofp, "track %d redefined, retain first definition\n", track_code); continue; } vec_add2(bound_tracks, btp, 1); btp->track = track_code; btp->track_str = this_strtab + ntohl(tp->track_format); hash_set(the_trackdef_hash, track_code, btp - bound_tracks); thislen = strlen((char *)(btp->track_str)); if (thislen > widest_track_format) widest_track_format = thislen; tp++; } return (0); } int unsupported_pass (cpel_section_header_t *sh, int verbose, FILE *ofp) { if (verbose) { fprintf(ofp, "Unsupported type %d section\n", ntohl(sh->section_type)); } return(0); } int event_pass2(cpel_section_header_t *sh, int verbose, FILE *ofp) { event_section_header_t *eh; u32 track_code; int nevents; int i; uword *p; event_entry_t *ep; u64 now; u32 time0, time1; bound_track_t generic_track; u32 last_track_code; u64 state_start_ticks=0; u64 ticks_in_state; bound_track_t *state_track=0; int in_state=0; generic_track.track_str = (u8 *) "%d"; last_track_code = 0xdeafbeef; eh = (event_section_header_t *)(sh+1); nevents = ntohl(eh->number_of_events); ticks_per_us = ((double)ntohl(eh->clock_ticks_per_second))/1e6; if (verbose) { fprintf(ofp, "%.3f ticks_per_us\n", ticks_per_us); } ep = (event_entry_t *)(eh+1); p = hash_get_mem(the_strtab_hash, eh->string_table_name); if (!p) { fprintf(ofp, "Fatal: couldn't find string table\n"); return(1); } for (i = 0; i < nevents; i++) { time0 = ntohl (ep->time[0]); time1 = ntohl (ep->time[1]); now = (((u64) time0)<<32) | time1; /* Found the state-change event ? */ if (ntohl(ep->event_code) == state_event_code) { /* * Add a ticks-in-state record, unless * this is the "prime mover" event instance */ if (in_state) { ticks_in_state = now - state_start_ticks; vec_add1(state_track->ticks_in_state, ticks_in_state); } /* switch to now-current track */ state_start_ticks = now; track_code = ntohl(ep->track); if (track_code != last_track_code) { p = hash_get(the_trackdef_hash, track_code); if (p) { state_track = &bound_tracks[p[0]]; } else { state_track = &generic_track; } last_track_code = track_code; } in_state = 1; } ep++; } return(0); } /* * Note: If necessary, add passes / columns to this table to * handle section order dependencies. */ section_processor_t processors[CPEL_NUM_SECTION_TYPES+1] = { {bad_section, noop_pass}, /* type 0 -- f**ked */ {strtab_pass1, noop_pass}, /* type 1 -- STRTAB */ {unsupported_pass, noop_pass}, /* type 2 -- SYMTAB */ {evtdef_pass1, noop_pass}, /* type 3 -- EVTDEF */ {trackdef_pass1, noop_pass}, /* type 4 -- TRACKDEF */ {noop_pass, event_pass2}, /* type 5 -- EVENTS */ }; int process_section(cpel_section_header_t *sh, int verbose, FILE *ofp, pass_t pass) { u32 type; type = ntohl(sh->section_type); int rv; int (*fp)(cpel_section_header_t *, int, FILE *); if (type > CPEL_NUM_SECTION_TYPES) { fprintf(stderr, "Unknown section type %d\n", type); return(1); } switch(pass) { case PASS1: fp = processors[type].pass1; break; case PASS2: fp = processors[type].pass2; break; default: fprintf(stderr, "Unknown pass %d\n", pass); return(1); } rv = (*fp)(sh, verbose, ofp); return(rv); } int cpel_dump_file_header(cpel_file_header_t *fh, int verbose, FILE *ofp) { time_t file_time; if (verbose) { fprintf(ofp, "CPEL file: %s-endian, version %d\n", ((fh->endian_version & CPEL_FILE_LITTLE_ENDIAN) ? "little" : "big"), fh->endian_version & CPEL_FILE_VERSION_MASK); file_time = ntohl(fh->file_date); fprintf(ofp, "File created %s", ctime(&file_time)); fprintf(ofp, "File has %d sections\n", ntohs(fh->nsections)); } return(0); } int cpel_dump(u8 *cpel, int verbose, FILE *ofp) { cpel_file_header_t *fh; cpel_section_header_t *sh; u16 nsections; u32 section_size; int i; /* First, the file header */ fh = (cpel_file_header_t *)cpel; if (fh->endian_version != CPEL_FILE_VERSION) { if (fh->endian_version & CPEL_FILE_LITTLE_ENDIAN) { fprintf(stderr, "Little endian data format not supported\n"); return(1); } fprintf(stderr, "Unsupported file version 0x%x\n", fh->endian_version); return(1); } cpel_dump_file_header(fh, verbose, ofp); nsections = ntohs(fh->nsections); /* * Take two passes through the file. PASS1 builds * data structures, PASS2 actually dumps the file. * Just in case the sections are in an unobvious order. */ sh = (cpel_section_header_t *)(fh+1); for (i = 0; i < nsections; i++) { section_size = ntohl(sh->data_length); if(verbose) { fprintf(ofp, "Section type %d, size %d\n", ntohl(sh->section_type), section_size); } if(process_section(sh, verbose, ofp, PASS1)) return(1); sh++; sh = (cpel_section_header_t *)(((u8 *)sh)+section_size); } sh = (cpel_section_header_t *)(fh+1); for (i = 0; i < nsections; i++) { if(process_section(sh, verbose, ofp, PASS2)) return(1); section_size = ntohl(sh->data_length); sh++; sh = (cpel_section_header_t *)(((u8 *)sh)+section_size); } return(0); } void compute_state_statistics(int verbose, FILE *ofp) { int i, j; bound_track_t *bp; f64 fticks; /* Across the bound tracks */ for (i = 0; i < vec_len(bound_tracks); i++) { bp = &bound_tracks[i]; bp->mean_ticks_in_state = 0.0; bp->variance_ticks_in_state = 0.0; bp->total_ticks_in_state = 0.0; for (j = 0; j < vec_len(bp->ticks_in_state); j++) { bp->total_ticks_in_state += (f64) bp->ticks_in_state[j]; } /* Compute mean */ if (vec_len(bp->ticks_in_state)) { bp->mean_ticks_in_state = bp->total_ticks_in_state / ((f64) vec_len(bp->ticks_in_state)); } /* Accumulate sum: (Xi-Xbar)**2 */ for (j = 0; j < vec_len(bp->ticks_in_state); j++) { fticks = bp->ticks_in_state[j]; bp->variance_ticks_in_state += (fticks - bp->mean_ticks_in_state)* (fticks - bp->mean_ticks_in_state); } /* Compute s**2, the unbiased estimator of sigma**2 */ if (vec_len(bp->ticks_in_state) > 1) { bp->variance_ticks_in_state /= (f64) (vec_len(bp->ticks_in_state)-1); } } } int track_compare_max (const void *arg1, const void *arg2) { bound_track_t *a1 = (bound_track_t *)arg1; bound_track_t *a2 = (bound_track_t *)arg2; f64 v1, v2; v1 = a1->total_ticks_in_state; v2 = a2->total_ticks_in_state; if (v1 < v2) return (1); else if (v1 == v2) return (0); else return (-1); } int track_compare_occurrences (const void *arg1, const void *arg2) { bound_track_t *a1 = (bound_track_t *)arg1; bound_track_t *a2 = (bound_track_t *)arg2; f64 v1, v2; v1 = (f64) vec_len(a1->ticks_in_state); v2 = (f64) vec_len(a2->ticks_in_state); if (v1 < v2) return (1); else if (v1 == v2) return (0); else return (-1); } int track_compare_name (const void *arg1, const void *arg2) { bound_track_t *a1 = (bound_track_t *)arg1; bound_track_t *a2 = (bound_track_t *)arg2; return (strcmp((char *)(a1->track_str), (char *)(a2->track_str))); } void sort_state_statistics(sort_t type, FILE *ofp) { int (*compare)(const void *, const void *)=0; if (summary_stats_only) return; switch(type) { case SORT_MAX_TIME: fprintf(ofp, "Results sorted by max time in state.\n"); compare = track_compare_max; break; case SORT_MAX_OCCURRENCES: fprintf(ofp, "Results sorted by max occurrences of state.\n"); compare = track_compare_occurrences; break; case SORT_NAME: compare = track_compare_name; fprintf(ofp, "Results sorted by process-id/name/thread ID\n"); break; default: fatal("sort type not set?"); } qsort (bound_tracks, vec_len(bound_tracks), sizeof (bound_track_t), compare); } void print_state_statistics(int verbose, FILE *ofp) { int i,j; u8 *trackpad; bound_track_t *bp; f64 total_time = 0.0; f64 total_switches = 0.0; trackpad = format(0, "%%-%ds ", widest_track_format); vec_add1(trackpad, 0); if (!summary_stats_only) { fprintf(ofp, (char *)trackpad, "ProcThread"); fprintf(ofp, " Mean(us) Stdev(us) Total(us) N\n"); } for (i = 0; i < vec_len(bound_tracks); i++) { bp = &bound_tracks[i]; if (bp->mean_ticks_in_state == 0.0) continue; if (name_filter && strncmp((char *)(bp->track_str), (char *)name_filter, strlen((char *)name_filter))) continue; /* * Exclude kernel threads (e.g. idle thread) from * state statistics */ if (exclude_kernel_from_summary_stats && !strncmp((char *)(bp->track_str), "kernel ", 7)) continue; total_switches += (f64) vec_len(bp->ticks_in_state); if (!summary_stats_only) { fprintf(ofp, (char *) trackpad, bp->track_str); fprintf(ofp, "%10.3f +- %10.3f", bp->mean_ticks_in_state / ticks_per_us, sqrt(bp->variance_ticks_in_state) / (f64) ticks_per_us); fprintf(ofp, "%12.3f", bp->total_ticks_in_state / ticks_per_us); fprintf(ofp, "%8d\n", (int)vec_len(bp->ticks_in_state)); } if (scatterplot) { for (j = 0; j < vec_len(bp->ticks_in_state); j++) { fprintf(ofp, "%.3f\n", (f64)bp->ticks_in_state[j] / ticks_per_us); } } total_time += bp->total_ticks_in_state; } if (!summary_stats_only) fprintf(ofp, "\n"); fprintf(ofp, "Note: the following statistics %s kernel-thread activity.\n", exclude_kernel_from_summary_stats ? "exclude" : "include"); if (name_filter) fprintf(ofp, "Note: only pid/proc/threads matching '%s' are included.\n", name_filter); fprintf(ofp, "Total runtime: %10.3f (us), Total state switches: %.0f\n", total_time / ticks_per_us, total_switches); fprintf(ofp, "Average time in state: %10.3f (us)\n", (total_time / total_switches) / ticks_per_us); } char *mapfile (char *file) { struct stat statb; char *rv; int maphfile; size_t mapfsize; maphfile = open (file, O_RDONLY); if (maphfile < 0) { fprintf (stderr, "Couldn't read %s, skipping it...\n", file); return (NULL); } if (fstat (maphfile, &statb) < 0) { fprintf (stderr, "Couldn't get size of %s, skipping it...\n", file); return (NULL); } /* Don't try to mmap directories, FIFOs, semaphores, etc. */ if (! (statb.st_mode & S_IFREG)) { fprintf (stderr, "%s is not a regular file, skipping it...\n", file); return (NULL); } mapfsize = statb.st_size; if (mapfsize < 3) { fprintf (stderr, "%s zero-length, skipping it...\n", file); close (maphfile); return (NULL); } rv = mmap (0, mapfsize, PROT_READ, MAP_SHARED, maphfile, 0); if (rv == 0) { fprintf (stderr, "%s problem mapping, I quit...\n", file); exit (-1); } close (maphfile); return (rv); } /* * main */ int main (int argc, char **argv) { char *cpel_file = 0; char *outputfile = 0; FILE *ofp; char *cpel; int verbose=0; int curarg=1; while (curarg < argc) { if (!strncmp(argv[curarg], "--input-file", 3)) { curarg++; if (curarg < argc) { cpel_file = argv[curarg]; curarg++; continue; } fatal("Missing filename after --input-file\n"); } if (!strncmp(argv[curarg], "--output-file", 3)) { curarg ++; if (curarg < argc) { outputfile = argv[curarg]; curarg ++; continue; } fatal("Missing filename after --output-file\n"); } if (!strncmp(argv[curarg], "--verbose", 3)) { curarg++; verbose++; continue; } if (!strncmp(argv[curarg], "--scatterplot", 4)) { curarg++; scatterplot=1; continue; } if (!strncmp(argv[curarg], "--state-event", 4)) { curarg++; if (curarg < argc) { state_event_code = atol(argv[curarg]); curarg ++; continue; } fatal("Missing integer after --state-event\n"); } if (!strncmp(argv[curarg], "--max-time-sort", 7)) { sort_type = SORT_MAX_TIME; curarg++; continue; } if (!strncmp(argv[curarg], "--max-occurrence-sort", 7)) { sort_type = SORT_MAX_OCCURRENCES; curarg++; continue; } if (!strncmp(argv[curarg], "--name-sort", 3)) { sort_type = SORT_NAME; curarg++; continue; } if (!strncmp(argv[curarg], "--kernel-included", 3)) { exclude_kernel_from_summary_stats = 0; curarg++; continue; } if (!strncmp(argv[curarg], "--summary", 3)) { summary_stats_only=1; curarg++; continue; } if (!strncmp(argv[curarg], "--filter", 3)) { curarg ++; if (curarg < argc) { name_filter = (u8 *)argv[curarg]; curarg ++; continue; } fatal("Missing filter string after --filter\n"); } usage: fprintf(stderr, "cpelstate --input-file <filename> [--output-file <filename>]\n"); fprintf(stderr, " [--state-event <decimal>] [--verbose]\n"); fprintf(stderr, " [--max-time-sort(default) | --max-occurrence-sort |\n"); fprintf(stderr, " --name-sort-sort] [--kernel-included]\n"); fprintf(stderr, " [--summary-stats-only] [--scatterplot]\n"); fprintf(stderr, "%s\n", version); exit(1); } if (cpel_file == 0) goto usage; cpel = mapfile(cpel_file); if (cpel == 0) { fprintf(stderr, "Couldn't map %s...\n", cpel_file); exit(1); } if (!outputfile) { ofp = fdopen(1, "w"); if (ofp == NULL) { fprintf(stderr, "Couldn't fdopen(1)?\n"); exit(1); } } else { ofp = fopen(outputfile, "w"); if (ofp == NULL) { fprintf(stderr, "Couldn't create %s...\n", outputfile); exit(1); } } the_strtab_hash = hash_create_string (0, sizeof (uword)); the_evtdef_hash = hash_create (0, sizeof (uword)); the_trackdef_hash = hash_create (0, sizeof (uword)); if (cpel_dump((u8 *) cpel, verbose, ofp)) { if (outputfile) unlink(outputfile); } compute_state_statistics(verbose, ofp); sort_state_statistics(sort_type, ofp); print_state_statistics(verbose, ofp); fclose(ofp); return(0); }