/* *------------------------------------------------------------------ * Copyright (c) 2008-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. */ /* * Search for O(N**2) functions bracketed by before/after * events. The "before" event's datum is used as a tag, e.g. which function * did we call that's strongly O(N). */ #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" FILE *g_ifp; char *g_ifile; typedef unsigned long long ulonglong; void process_traces (void); void record_instance (ulong tag, ulonglong time); void report_actors (void); void scatterplot_data(void); int entry_event, exit_event; int nokey; char *version = "cpelinreg 2.0"; int model_these[10]; int model_index; int summary_stats; ulonglong first_start_time; ulonglong last_end_time; ulonglong total_time; ulong scatterkey; int inline_mokus; typedef struct bound_track_ { u32 track_code; u32 *start_datum; u8 *dup_event; int state; u64 *start_time; u64 thread_timestamp; u64 time_thread_on_cpu; } bound_track_t; bound_track_t *bound_tracks; uword *the_trackdef_hash; #define MAXSTACK 128 typedef struct instance_ { struct instance_ *next; ulonglong time; }instance_t; typedef struct actor_ { struct actor_ *next; ulong key; struct instance_ *first; struct instance_ *last; double a; double b; double min; double max; double mean; double r; ulong ninst; } actor_t; #define NBUCKETS 1811 actor_t *hash[NBUCKETS]; actor_t *find_or_create_actor (ulong key) { ulong bucket; actor_t *ap; u8 *mem; bucket = key % NBUCKETS; ap = hash[bucket]; if (ap == NULL) { /* Ensure 8-byte alignment to avoid (double) alignment faults */ mem = malloc(sizeof(*ap) + 4); if (((uword)(mem)) & 0x7) mem += 4; ap = (actor_t *)mem; if (ap == NULL) { fprintf (stderr, "out of memory...\n"); exit (1); } ap->next = 0; ap->key = key; ap->first = 0; ap->last = 0; ap->a = 0.00; ap->b = 0.00; hash [bucket] = ap; return (ap); } while (ap) { if (ap->key == key) return (ap); ap = ap->next; } mem = malloc(sizeof(*ap)+4); if (((uword)(mem) & 0x7)) mem += 4; ap = (actor_t *)mem; if (ap == NULL) { fprintf (stderr, "out of memory...\n"); exit (1); } ap->key = key; ap->first = 0; ap->last = 0; ap->a = 0.00; ap->b = 0.00; ap->next = hash[bucket]; hash[bucket] = ap; return (ap); } void record_instance (ulong key, ulonglong time) { actor_t *ap; instance_t *ip; if (nokey) key = 0; ap = find_or_create_actor (key); ip = (instance_t *)malloc(sizeof(*ip)); if (ip == NULL) { fprintf (stderr, "out of memory...\n"); exit (1); } ip->time = time; ip->next = 0; if (ap->first == 0) { ap->first = ip; ap->last = ip; ap->ninst = 1; } else { ap->last->next = ip; ap->last = ip; ap->ninst++; } } #define NINSTANCE 200000 double x[NINSTANCE]; double y[NINSTANCE]; int actor_compare (const void *arg1, const void *arg2) { double e10k1, e10k2; actor_t **a1 = (actor_t **)arg1; actor_t **a2 = (actor_t **)arg2; double ninst1, ninst2; ninst1 = ((double)((*a1)->ninst)); ninst2 = ((double)((*a2)->ninst)); e10k1 = ninst1 * ((*a1)->mean); e10k2 = ninst2 * ((*a2)->mean); if (e10k1 < e10k2) return (1); else if (e10k1 == e10k2) return (0); else return (-1); } void report_actors (void) { int i; actor_t *ap; instance_t *ip; int nactors = 0; int ninstance; actor_t **actor_vector; double e10k; extern void linreg (double *x, double *y, int nitems, double *a, double *b, double *minp, double *maxp, double *meanp, double *r); for (i = 0; i < NBUCKETS; i++) { ap = hash[i]; if (ap == NULL) continue; while (ap) { nactors++; ninstance = 0; ip = ap->first; while (ip) { if (ninstance < NINSTANCE) { x[ninstance] = ninstance; y[ninstance] = ((double)ip->time); ninstance++; } ip = ip->next; } if (ninstance > 1) { #if DEBUG > 0 int j; for (j = 0; j < ninstance; j++) { printf("x[%d] = %10.2f, y[%d] = %10.2f\n", j, x[j], j, y[j]); } #endif linreg (x, y, ninstance, &ap->a, &ap->b, &ap->min, &ap->max, &ap->mean, &ap->r); } else { ap->a = 0.00; ap->b = 0.00; } ap = ap->next; } } actor_vector = (actor_t **)malloc (nactors*sizeof(*actor_vector)); nactors = 0; for (i = 0; i < NBUCKETS; i++) { ap = hash[i]; if (ap == NULL) continue; while (ap) { if ((ap->a != 0.00) || (ap->b != 0.00)) { actor_vector[nactors++] = ap; } ap = ap->next; } } qsort (actor_vector, nactors, sizeof (actor_t *), actor_compare); if (summary_stats) printf("NInst Offset Slope T(Ninst) Min Max Avg %%InstTime R Key"); else printf("NInst Offset Slope T(Ninst) Key"); for (i = 0; i < model_index; i++) { printf ("T @ %-8d ", model_these[i]); } printf ("\n"); for (i = 0; i < nactors; i++) { int j; double ninst; double pcttot; ap = actor_vector[i]; ninst = ap->ninst; e10k = ninst * (ap->a + ap->b*((ninst-1.0)/2.0)); if (ap->ninst) { if (summary_stats) { pcttot = (e10k / ((double)total_time)) * 100.0; printf ("%6ld %11.2f %11.2f %11.2f %11.2f %11.2f %11.2f %11.2f %11.2f 0x%08lx ", ap->ninst, ap->a, ap->b, e10k, ap->min, ap->max, ap->mean, pcttot, ap->r, ap->key); } else printf ("%6ld %11.2f %11.2f %11.2f 0x%08lx ", ap->ninst, ap->a, ap->b, e10k, ap->key); for (j = 0; j < model_index; j++) { ninst = model_these[j]; e10k = ninst * (ap->a + ap->b*((ninst-1.0)/2.0)); printf ("%10.2f ", e10k); } printf ("\n"); } } } void scatterplot_data(void) { actor_t *ap; int i; instance_t *ip; double time; int count=0; for (i = 0; i < NBUCKETS; i++) { ap = hash[i]; if (ap == NULL) continue; while (ap) { if (ap->key == scatterkey){ ip = ap->first; while (ip) { time = ((double)ip->time); printf ("%d\t%.0f\n", count++, time); ip = ip->next; } return; } ap = ap->next; } } } void fatal(char *s) { fprintf(stderr, "%s", s); fprintf(stderr, "\n"); exit(1); } typedef enum { PASS1=1, } pass_t; typedef struct { int (*pass1)(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 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 trackdef_pass(cpel_section_header_t *sh, int verbose, FILE *ofp) { int i, nevents; track_definition_section_header_t *tdh; track_definition_t *tp; u32 track_code; uword *p; bound_track_t *btp; tdh = (track_definition_section_header_t *)(sh+1); nevents = ntohl(tdh->number_of_track_definitions); if (verbose) { fprintf(stderr, "Track Definition Section: %d definitions\n", nevents); } 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_code = track_code; hash_set(the_trackdef_hash, track_code, btp - bound_tracks); tp++; } return (0); } int event_pass (cpel_section_header_t *sh, int verbose, FILE *ofp) { event_section_header_t *eh; event_entry_t *ep; f64 ticks_per_us; long output_count; long dup_events = 0; ulonglong end_time = 0; double t; int sp, ancestor; int nevents, i; u64 now; u64 time0, time1; double d; u32 last_track_code = 0xdeafb00b; u32 track_code; u32 event_code, event_datum; bound_track_t *tp = 0; uword *p; output_count = 0; total_time = 0; 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); time0 = ntohl (ep->time[0]); time1 = ntohl (ep->time[1]); now = (((u64) time0)<<32) | time1; d = now; d /= ticks_per_us; first_start_time = d; for (i = 0; i < nevents; i++) { time0 = ntohl (ep->time[0]); time1 = ntohl (ep->time[1]); now = (((u64) time0)<<32) | time1; /* Convert from bus ticks to usec */ d = now; d /= ticks_per_us; now = d; track_code = ntohl(ep->track); event_code = ntohl(ep->event_code); event_datum = ntohl(ep->event_datum); if (track_code != last_track_code) { if (tp) { tp->thread_timestamp += now - tp->time_thread_on_cpu; tp->time_thread_on_cpu = 0; } p = hash_get(the_trackdef_hash, track_code); if (!p) { /* synthesize a new track */ vec_add2(bound_tracks, tp, 1); tp->track_code = track_code; hash_set(the_trackdef_hash, track_code, tp - bound_tracks); } else { tp = bound_tracks + p[0]; } last_track_code = track_code; tp->time_thread_on_cpu = now; } if (event_code != entry_event && event_code != exit_event) { ep++; continue; } again: switch (tp->state) { case 0: /* not in state */ /* Another exit event? Stack pop */ if (event_code == exit_event) { /* Only if we have something on the stack */ if (vec_len(tp->start_datum) > 0) { tp->state = 1; goto again; } else { fprintf (stderr, "End event before start event, key 0x%x.", ntohl(ep->event_datum)); fprintf (stderr, " Interpret results carefully...\n"); } } tp->state = 1; if (vec_len(tp->start_datum) >= MAXSTACK) { int j; fprintf (stderr, "stack overflow..\n"); for (j = vec_len(tp->start_datum)-1; j >= 0; j--) { fprintf(stderr, "stack[%d]: datum 0x%x\n", j, tp->start_datum[j]); } fprintf (stderr, "Stack overflow... This occurs when " "(start, datum)...(end, datum) events\n" "are not properly paired.\n\n" "A typical scenario looks like this:\n\n" " ...\n" " ELOG(..., START_EVENT, datum);\n" " if (condition)\n" " return; /*oops, forgot the end event*/\n" " ELOG(..., END_EVENT, datum);\n" " ...\n\n" "The datum stack dump (above) should make it clear\n" "where to start looking for a sneak path...\n"); exit (1); } vec_add1(tp->start_datum, event_datum); vec_add1(tp->start_time, (tp->thread_timestamp + (now - tp->time_thread_on_cpu))); #ifdef HAVING_TROUBLE printf ("sp %lld key 0x%x start time %llu\n", (long long) vec_len(tp->start_time)-1, event_datum, (unsigned long long) tp->start_time [vec_len(tp->start_time)-1]); printf ("timestamp %llu, now %llu, thread on cpu %llu\n", (unsigned long long) tp->thread_timestamp, (unsigned long long) now, (unsigned long long) tp->time_thread_on_cpu); #endif /* * Multiple identical enter events? If the user knows that * gcc is producing bogus events due to inline functions, * trash the duplicate. */ if (inline_mokus && vec_len (tp->start_datum) > 1 && tp->start_datum [vec_len(tp->start_datum)-1] == tp->start_datum [vec_len(tp->start_datum)-2]) { vec_add1 (tp->dup_event, 1); } else { vec_add1 (tp->dup_event, 0); } ep++; continue; case 1: /* in state */ /* Another entry event? Stack push*/ if (event_code == entry_event) { tp->state = 0; goto again; } if (vec_len(tp->start_datum) == 0) { fprintf (stderr, "Stack underflow...\n"); exit (1); } sp = vec_len(tp->start_time)-1; end_time = tp->thread_timestamp + (now - tp->time_thread_on_cpu); if (!tp->dup_event[sp]) { #ifdef HAVING_TROUBLE printf ("sp %d key 0x%x charged %llu\n", sp, tp->start_datum[sp], end_time - tp->start_time[sp]); printf (" start %llu, end %llu\n", (unsigned long long) tp->start_time[sp], (unsigned long long) end_time); #endif record_instance (tp->start_datum[sp], (end_time - tp->start_time[sp])); /* Factor out our time from surrounding services, if any */ for (ancestor = sp-1; ancestor >= 0; ancestor--) { #ifdef HAVING_TROUBLE printf ("Factor out %lld from key 0x%08x\n", (end_time - tp->start_time[sp]), tp->start_datum[ancestor]); #endif tp->start_time[ancestor] += (end_time - tp->start_time[sp]); } output_count++; total_time += (end_time - tp->start_time[sp]); tp->state = 0; } else { dup_events++; } _vec_len(tp->start_datum) = sp; _vec_len(tp->start_time) = sp; _vec_len(tp->dup_event) = sp; } ep++; } last_end_time = now; if (scatterkey) { scatterplot_data(); exit (0); } if (output_count) { t = (double)total_time; printf ("%ld instances of state, %.2f microseconds average\n", output_count, t / output_count); printf ("Total instrumented runtime: %.2f microseconds\n", ((double)total_time)); printf ("Total runtime: %lld microseconds\n", last_end_time - first_start_time); t /= (double)(last_end_time - first_start_time); t *= 100.0; if (dup_events) { printf ("Suppressed %ld duplicate state entry events\n", dup_events); } printf ("Instrumented code accounts for %.2f%% of total time.\n\n", t); report_actors(); } else { printf ("No instances of state...\n"); } 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] = { {unsupported_pass}, /* type 0 -- f**ked */ {noop_pass}, /* type 1 -- STRTAB */ {noop_pass}, /* type 2 -- SYMTAB */ {noop_pass}, /* type 3 -- EVTDEF */ {trackdef_pass}, /* type 4 -- TRACKDEF */ {event_pass}, /* 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; default: fprintf(stderr, "Unknown pass %d\n", pass); return(1); } rv = (*fp)(sh, verbose, ofp); return(rv); } 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); } int process_file (u8 *cpel, int verbose) { cpel_file_header_t *fh; cpel_section_header_t *sh; u16 nsections; u32 section_size; int i; FILE *ofp = stderr; /* 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); } nsections = ntohs(fh->nsections); /* * Take a passe through the file. */ 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); } return(0); } /**************************************************************************** * main - ****************************************************************************/ int main (int argc, char **argv) { int curarg = 1; u8 *cpel = 0; int verbose = 0; if (argc < 6) { fprintf (stderr, "usage: cpelinreg -i <file>\n"); fprintf (stderr, " -s start-event --e end-event [-nokey]\n"); fprintf (stderr, " [-m <ninst-to-model>][-xtra-stats]\n"); fprintf (stderr, " [-keyscatterplot <hex-key>]\n\n"); fprintf (stderr, "%s\n", version); exit (1); } while (curarg < argc) { if (!strncmp (argv[curarg], "-ifile", 2)) { curarg++; g_ifile = argv[curarg++]; continue; } if (!strncmp (argv[curarg], "-start", 2)) { curarg++; entry_event = atol (argv [curarg++]); continue; } if (!strncmp (argv[curarg], "-end", 2)) { curarg++; exit_event = atol (argv [curarg++]); continue; } if (!strncmp(argv[curarg], "-badinlines", 2)) { curarg++; inline_mokus = 1; continue; } if (!strncmp (argv[curarg], "-x", 2)) { curarg++; summary_stats=1; continue; } if (!strncmp (argv[curarg], "-nokey", 2)) { curarg++; nokey = 1; continue; } if (!strncmp (argv[curarg], "-keyscatterplot", 2)) { curarg++; sscanf (argv[curarg], "%lx", &scatterkey); curarg++; continue; } if (!strncmp (argv[curarg], "-model", 2)) { if (model_index >= sizeof(model_these) / sizeof(int)) { fprintf (stderr, "Too many model requests\n"); exit (1); } curarg++; model_these[model_index++] = atol (argv [curarg++]); continue; } if (!strncmp (argv[curarg], "-verbose", 2)) { verbose++; curarg++; continue; } fprintf (stderr, "unknown switch '%s'\n", argv[curarg]); exit (1); } cpel = (u8 *)mapfile(g_ifile); if (cpel == NULL) { fprintf (stderr, "Couldn't open %s\n", g_ifile); exit (1); } printf ("Extracting state info from %s\nentry_event %d, exit_event %d\n", g_ifile, entry_event, exit_event); if (nokey) { printf ("All state instances mapped to a single actor chain\n"); } the_trackdef_hash = hash_create (0, sizeof (uword)); process_file(cpel, verbose); exit (0); }