2 *------------------------------------------------------------------
3 * Copyright (c) 2008-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.
18 * Search for O(N**2) functions bracketed by before/after
19 * events. The "before" event's datum is used as a tag, e.g. which function
20 * did we call that's strongly O(N).
25 #include <netinet/in.h>
27 #include <sys/types.h>
33 #include <vppinfra/clib.h>
34 #include <vppinfra/vec.h>
35 #include <vppinfra/hash.h>
44 typedef unsigned long long ulonglong;
46 void process_traces (void);
47 void record_instance (ulong tag, ulonglong time);
48 void report_actors (void);
49 void scatterplot_data(void);
50 int entry_event, exit_event;
52 char *version = "cpelinreg 2.0";
56 ulonglong first_start_time;
57 ulonglong last_end_time;
62 typedef struct bound_track_ {
69 u64 time_thread_on_cpu;
72 bound_track_t *bound_tracks;
73 uword *the_trackdef_hash;
78 typedef struct instance_ {
79 struct instance_ *next;
83 typedef struct actor_ {
86 struct instance_ *first;
87 struct instance_ *last;
99 actor_t *hash[NBUCKETS];
101 actor_t *find_or_create_actor (ulong key)
107 bucket = key % NBUCKETS;
112 /* Ensure 8-byte alignment to avoid (double) alignment faults */
113 mem = malloc(sizeof(*ap) + 4);
114 if (((uword)(mem)) & 0x7)
119 fprintf (stderr, "out of memory...\n");
138 mem = malloc(sizeof(*ap)+4);
139 if (((uword)(mem) & 0x7))
144 fprintf (stderr, "out of memory...\n");
153 ap->next = hash[bucket];
159 void record_instance (ulong key, ulonglong time)
167 ap = find_or_create_actor (key);
169 ip = (instance_t *)malloc(sizeof(*ip));
171 fprintf (stderr, "out of memory...\n");
177 if (ap->first == 0) {
188 #define NINSTANCE 200000
193 int actor_compare (const void *arg1, const void *arg2)
196 actor_t **a1 = (actor_t **)arg1;
197 actor_t **a2 = (actor_t **)arg2;
198 double ninst1, ninst2;
200 ninst1 = ((double)((*a1)->ninst));
201 ninst2 = ((double)((*a2)->ninst));
203 e10k1 = ninst1 * ((*a1)->mean);
204 e10k2 = ninst2 * ((*a2)->mean);
208 else if (e10k1 == e10k2)
214 void report_actors (void)
221 actor_t **actor_vector;
223 extern void linreg (double *x, double *y, int nitems, double *a, double *b,
224 double *minp, double *maxp, double *meanp, double *r);
226 for (i = 0; i < NBUCKETS; i++) {
237 if (ninstance < NINSTANCE) {
238 x[ninstance] = ninstance;
239 y[ninstance] = ((double)ip->time);
248 for (j = 0; j < ninstance; j++) {
249 printf("x[%d] = %10.2f, y[%d] = %10.2f\n",
254 linreg (x, y, ninstance, &ap->a, &ap->b, &ap->min,
255 &ap->max, &ap->mean, &ap->r);
265 actor_vector = (actor_t **)malloc (nactors*sizeof(*actor_vector));
268 for (i = 0; i < NBUCKETS; i++) {
273 if ((ap->a != 0.00) || (ap->b != 0.00)) {
274 actor_vector[nactors++] = ap;
280 qsort (actor_vector, nactors, sizeof (actor_t *), actor_compare);
283 printf("NInst Offset Slope T(Ninst) Min Max Avg %%InstTime R Key");
285 printf("NInst Offset Slope T(Ninst) Key");
287 for (i = 0; i < model_index; i++) {
288 printf ("T @ %-8d ", model_these[i]);
293 for (i = 0; i < nactors; i++) {
297 ap = actor_vector[i];
300 e10k = ninst * (ap->a + ap->b*((ninst-1.0)/2.0));
304 pcttot = (e10k / ((double)total_time)) * 100.0;
305 printf ("%6ld %11.2f %11.2f %11.2f %11.2f %11.2f %11.2f %11.2f %11.2f 0x%08lx ",
306 ap->ninst, ap->a, ap->b, e10k, ap->min,
307 ap->max, ap->mean, pcttot, ap->r, ap->key);
310 printf ("%6ld %11.2f %11.2f %11.2f 0x%08lx ",
311 ap->ninst, ap->a, ap->b, e10k, ap->key);
313 for (j = 0; j < model_index; j++) {
314 ninst = model_these[j];
315 e10k = ninst * (ap->a + ap->b*((ninst-1.0)/2.0));
316 printf ("%10.2f ", e10k);
323 void scatterplot_data(void)
331 for (i = 0; i < NBUCKETS; i++) {
336 if (ap->key == scatterkey){
339 time = ((double)ip->time);
340 printf ("%d\t%.0f\n", count++, time);
353 fprintf(stderr, "%s", s);
354 fprintf(stderr, "\n");
363 int (*pass1)(cpel_section_header_t *, int, FILE *);
364 } section_processor_t;
366 int bad_section(cpel_section_header_t *sh, int verbose, FILE *ofp)
368 fprintf(ofp, "Bad (type 0) section, skipped...\n");
372 int noop_pass(cpel_section_header_t *sh, int verbose, FILE *ofp)
377 int unsupported_pass (cpel_section_header_t *sh, int verbose, FILE *ofp)
380 fprintf(ofp, "Unsupported type %d section\n",
381 ntohl(sh->section_type));
386 int trackdef_pass(cpel_section_header_t *sh, int verbose, FILE *ofp)
389 track_definition_section_header_t *tdh;
390 track_definition_t *tp;
395 tdh = (track_definition_section_header_t *)(sh+1);
396 nevents = ntohl(tdh->number_of_track_definitions);
399 fprintf(stderr, "Track Definition Section: %d definitions\n",
403 tp = (track_definition_t *)(tdh+1);
405 for (i = 0; i < nevents; i++) {
406 track_code = ntohl(tp->track);
407 p = hash_get(the_trackdef_hash, track_code);
409 fprintf(ofp, "track %d redefined, retain first definition\n",
413 vec_add2(bound_tracks, btp, 1);
414 btp->track_code = track_code;
415 hash_set(the_trackdef_hash, track_code, btp - bound_tracks);
422 int event_pass (cpel_section_header_t *sh, int verbose, FILE *ofp)
424 event_section_header_t *eh;
429 ulonglong end_time = 0;
436 u32 last_track_code = 0xdeafb00b;
438 u32 event_code, event_datum;
439 bound_track_t *tp = 0;
445 eh = (event_section_header_t *)(sh+1);
446 nevents = ntohl(eh->number_of_events);
447 ticks_per_us = ((double)ntohl(eh->clock_ticks_per_second))/1e6;
450 fprintf(ofp, "%.3f ticks_per_us\n", ticks_per_us);
453 ep = (event_entry_t *)(eh+1);
455 time0 = ntohl (ep->time[0]);
456 time1 = ntohl (ep->time[1]);
458 now = (((u64) time0)<<32) | time1;
461 first_start_time = d;
463 for (i = 0; i < nevents; i++) {
464 time0 = ntohl (ep->time[0]);
465 time1 = ntohl (ep->time[1]);
467 now = (((u64) time0)<<32) | time1;
469 /* Convert from bus ticks to usec */
475 track_code = ntohl(ep->track);
476 event_code = ntohl(ep->event_code);
477 event_datum = ntohl(ep->event_datum);
479 if (track_code != last_track_code) {
481 tp->thread_timestamp += now - tp->time_thread_on_cpu;
482 tp->time_thread_on_cpu = 0;
484 p = hash_get(the_trackdef_hash, track_code);
486 /* synthesize a new track */
487 vec_add2(bound_tracks, tp, 1);
488 tp->track_code = track_code;
489 hash_set(the_trackdef_hash, track_code, tp - bound_tracks);
491 tp = bound_tracks + p[0];
493 last_track_code = track_code;
494 tp->time_thread_on_cpu = now;
497 if (event_code != entry_event &&
498 event_code != exit_event) {
505 case 0: /* not in state */
506 /* Another exit event? Stack pop */
507 if (event_code == exit_event) {
508 /* Only if we have something on the stack */
509 if (vec_len(tp->start_datum) > 0) {
514 "End event before start event, key 0x%x.",
515 ntohl(ep->event_datum));
516 fprintf (stderr, " Interpret results carefully...\n");
521 if (vec_len(tp->start_datum) >= MAXSTACK) {
524 fprintf (stderr, "stack overflow..\n");
525 for (j = vec_len(tp->start_datum)-1; j >= 0; j--) {
526 fprintf(stderr, "stack[%d]: datum 0x%x\n",
527 j, tp->start_datum[j]);
530 "Stack overflow... This occurs when "
531 "(start, datum)...(end, datum) events\n"
532 "are not properly paired.\n\n"
533 "A typical scenario looks like this:\n\n"
535 " ELOG(..., START_EVENT, datum);\n"
537 " return; /*oops, forgot the end event*/\n"
538 " ELOG(..., END_EVENT, datum);\n"
540 "The datum stack dump (above) should make it clear\n"
541 "where to start looking for a sneak path...\n");
545 vec_add1(tp->start_datum, event_datum);
546 vec_add1(tp->start_time, (tp->thread_timestamp + (now - tp->time_thread_on_cpu)));
547 #ifdef HAVING_TROUBLE
548 printf ("sp %lld key 0x%x start time %llu\n",
549 (long long) vec_len(tp->start_time)-1, event_datum,
551 tp->start_time [vec_len(tp->start_time)-1]);
552 printf ("timestamp %llu, now %llu, thread on cpu %llu\n",
553 (unsigned long long) tp->thread_timestamp,
554 (unsigned long long) now,
555 (unsigned long long) tp->time_thread_on_cpu);
561 * Multiple identical enter events? If the user knows that
562 * gcc is producing bogus events due to inline functions,
563 * trash the duplicate.
566 && vec_len (tp->start_datum) > 1
567 && tp->start_datum [vec_len(tp->start_datum)-1] ==
568 tp->start_datum [vec_len(tp->start_datum)-2]) {
569 vec_add1 (tp->dup_event, 1);
571 vec_add1 (tp->dup_event, 0);
578 case 1: /* in state */
579 /* Another entry event? Stack push*/
580 if (event_code == entry_event) {
585 if (vec_len(tp->start_datum) == 0) {
586 fprintf (stderr, "Stack underflow...\n");
590 sp = vec_len(tp->start_time)-1;
592 end_time = tp->thread_timestamp + (now - tp->time_thread_on_cpu);
594 if (!tp->dup_event[sp]) {
595 #ifdef HAVING_TROUBLE
596 printf ("sp %d key 0x%x charged %llu\n", sp,
597 tp->start_datum[sp], end_time - tp->start_time[sp]);
598 printf (" start %llu, end %llu\n", (unsigned long long) tp->start_time[sp],
599 (unsigned long long) end_time);
602 record_instance (tp->start_datum[sp], (end_time -
603 tp->start_time[sp]));
605 /* Factor out our time from surrounding services, if any */
606 for (ancestor = sp-1; ancestor >= 0; ancestor--) {
607 #ifdef HAVING_TROUBLE
608 printf ("Factor out %lld from key 0x%08x\n",
609 (end_time - tp->start_time[sp]), tp->start_datum[ancestor]);
611 tp->start_time[ancestor] += (end_time - tp->start_time[sp]);
614 total_time += (end_time - tp->start_time[sp]);
619 vec_set_len (tp->start_datum, sp);
620 vec_set_len (tp->start_time, sp);
621 vec_set_len (tp->dup_event, sp);
634 t = (double)total_time;
635 printf ("%ld instances of state, %.2f microseconds average\n",
636 output_count, t / output_count);
638 printf ("Total instrumented runtime: %.2f microseconds\n",
639 ((double)total_time));
640 printf ("Total runtime: %lld microseconds\n",
641 last_end_time - first_start_time);
643 t /= (double)(last_end_time - first_start_time);
647 printf ("Suppressed %ld duplicate state entry events\n",
650 printf ("Instrumented code accounts for %.2f%% of total time.\n\n",
654 printf ("No instances of state...\n");
661 * Note: If necessary, add passes / columns to this table to
662 * handle section order dependencies.
665 section_processor_t processors[CPEL_NUM_SECTION_TYPES+1] =
667 {unsupported_pass}, /* type 0 -- f**ked */
668 {noop_pass}, /* type 1 -- STRTAB */
669 {noop_pass}, /* type 2 -- SYMTAB */
670 {noop_pass}, /* type 3 -- EVTDEF */
671 {trackdef_pass}, /* type 4 -- TRACKDEF */
672 {event_pass}, /* type 5 -- EVENTS */
675 int process_section(cpel_section_header_t *sh, int verbose, FILE *ofp,
679 type = ntohl(sh->section_type);
681 int (*fp)(cpel_section_header_t *, int, FILE *);
683 if (type > CPEL_NUM_SECTION_TYPES) {
684 fprintf(stderr, "Unknown section type %d\n", type);
689 fp = processors[type].pass1;
693 fprintf(stderr, "Unknown pass %d\n", pass);
697 rv = (*fp)(sh, verbose, ofp);
702 char *mapfile (char *file)
709 maphfile = open (file, O_RDONLY);
713 fprintf (stderr, "Couldn't read %s, skipping it...\n", file);
717 if (fstat (maphfile, &statb) < 0)
719 fprintf (stderr, "Couldn't get size of %s, skipping it...\n", file);
723 /* Don't try to mmap directories, FIFOs, semaphores, etc. */
724 if (! (statb.st_mode & S_IFREG)) {
725 fprintf (stderr, "%s is not a regular file, skipping it...\n", file);
729 mapfsize = statb.st_size;
733 fprintf (stderr, "%s zero-length, skipping it...\n", file);
738 rv = mmap (0, mapfsize, PROT_READ, MAP_SHARED, maphfile, 0);
742 fprintf (stderr, "%s problem mapping, I quit...\n", file);
749 int process_file (u8 *cpel, int verbose)
751 cpel_file_header_t *fh;
752 cpel_section_header_t *sh;
758 /* First, the file header */
759 fh = (cpel_file_header_t *)cpel;
760 if (fh->endian_version != CPEL_FILE_VERSION) {
761 if (fh->endian_version & CPEL_FILE_LITTLE_ENDIAN) {
762 fprintf(stderr, "Little endian data format not supported\n");
765 fprintf(stderr, "Unsupported file version 0x%x\n",
769 nsections = ntohs(fh->nsections);
772 * Take a passe through the file.
774 sh = (cpel_section_header_t *)(fh+1);
775 for (i = 0; i < nsections; i++) {
776 section_size = ntohl(sh->data_length);
779 fprintf(ofp, "Section type %d, size %d\n",
780 ntohl(sh->section_type),
784 if(process_section(sh, verbose, ofp, PASS1))
788 sh = (cpel_section_header_t *)(((u8 *)sh)+section_size);
794 /****************************************************************************
796 ****************************************************************************/
798 int main (int argc, char **argv)
806 fprintf (stderr, "usage: cpelinreg -i <file>\n");
807 fprintf (stderr, " -s start-event --e end-event [-nokey]\n");
808 fprintf (stderr, " [-m <ninst-to-model>][-xtra-stats]\n");
809 fprintf (stderr, " [-keyscatterplot <hex-key>]\n\n");
810 fprintf (stderr, "%s\n", version);
814 while (curarg < argc) {
815 if (!strncmp (argv[curarg], "-ifile", 2)) {
817 g_ifile = argv[curarg++];
820 if (!strncmp (argv[curarg], "-start", 2)) {
822 entry_event = atol (argv [curarg++]);
825 if (!strncmp (argv[curarg], "-end", 2)) {
827 exit_event = atol (argv [curarg++]);
831 if (!strncmp(argv[curarg], "-badinlines", 2)) {
837 if (!strncmp (argv[curarg], "-x", 2)) {
842 if (!strncmp (argv[curarg], "-nokey", 2)) {
847 if (!strncmp (argv[curarg], "-keyscatterplot", 2)) {
849 sscanf (argv[curarg], "%lx", &scatterkey);
854 if (!strncmp (argv[curarg], "-model", 2)) {
855 if (model_index >= sizeof(model_these) / sizeof(int)) {
856 fprintf (stderr, "Too many model requests\n");
860 model_these[model_index++] = atol (argv [curarg++]);
863 if (!strncmp (argv[curarg], "-verbose", 2)) {
869 fprintf (stderr, "unknown switch '%s'\n", argv[curarg]);
873 cpel = (u8 *)mapfile(g_ifile);
877 fprintf (stderr, "Couldn't open %s\n", g_ifile);
881 printf ("Extracting state info from %s\nentry_event %d, exit_event %d\n",
882 g_ifile, entry_event, exit_event);
884 printf ("All state instances mapped to a single actor chain\n");
887 the_trackdef_hash = hash_create (0, sizeof (uword));
889 process_file(cpel, verbose);