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>
30 #include <sys/fcntl.h>
34 #include <vppinfra/clib.h>
35 #include <vppinfra/vec.h>
36 #include <vppinfra/hash.h>
45 typedef unsigned long long ulonglong;
47 void process_traces (void);
48 void record_instance (ulong tag, ulonglong time);
49 void report_actors (void);
50 void scatterplot_data(void);
51 int entry_event, exit_event;
53 char *version = "cpelinreg 2.0";
57 ulonglong first_start_time;
58 ulonglong last_end_time;
63 typedef struct bound_track_ {
70 u64 time_thread_on_cpu;
73 bound_track_t *bound_tracks;
74 uword *the_trackdef_hash;
79 typedef struct instance_ {
80 struct instance_ *next;
84 typedef struct actor_ {
87 struct instance_ *first;
88 struct instance_ *last;
100 actor_t *hash[NBUCKETS];
102 actor_t *find_or_create_actor (ulong key)
108 bucket = key % NBUCKETS;
113 /* Ensure 8-byte alignment to avoid (double) alignment faults */
114 mem = malloc(sizeof(*ap) + 4);
115 if (((uword)(mem)) & 0x7)
120 fprintf (stderr, "out of memory...\n");
139 mem = malloc(sizeof(*ap)+4);
140 if (((uword)(mem) & 0x7))
145 fprintf (stderr, "out of memory...\n");
154 ap->next = hash[bucket];
160 void record_instance (ulong key, ulonglong time)
168 ap = find_or_create_actor (key);
170 ip = (instance_t *)malloc(sizeof(*ip));
172 fprintf (stderr, "out of memory...\n");
178 if (ap->first == 0) {
189 #define NINSTANCE 200000
194 int actor_compare (const void *arg1, const void *arg2)
197 actor_t **a1 = (actor_t **)arg1;
198 actor_t **a2 = (actor_t **)arg2;
199 double ninst1, ninst2;
201 ninst1 = ((double)((*a1)->ninst));
202 ninst2 = ((double)((*a2)->ninst));
204 e10k1 = ninst1 * ((*a1)->mean);
205 e10k2 = ninst2 * ((*a2)->mean);
209 else if (e10k1 == e10k2)
215 void report_actors (void)
222 actor_t **actor_vector;
224 extern void linreg (double *x, double *y, int nitems, double *a, double *b,
225 double *minp, double *maxp, double *meanp, double *r);
227 for (i = 0; i < NBUCKETS; i++) {
238 if (ninstance < NINSTANCE) {
239 x[ninstance] = ninstance;
240 y[ninstance] = ((double)ip->time);
249 for (j = 0; j < ninstance; j++) {
250 printf("x[%d] = %10.2f, y[%d] = %10.2f\n",
255 linreg (x, y, ninstance, &ap->a, &ap->b, &ap->min,
256 &ap->max, &ap->mean, &ap->r);
266 actor_vector = (actor_t **)malloc (nactors*sizeof(*actor_vector));
269 for (i = 0; i < NBUCKETS; i++) {
274 if ((ap->a != 0.00) || (ap->b != 0.00)) {
275 actor_vector[nactors++] = ap;
281 qsort (actor_vector, nactors, sizeof (actor_t *), actor_compare);
284 printf("NInst Offset Slope T(Ninst) Min Max Avg %%InstTime R Key");
286 printf("NInst Offset Slope T(Ninst) Key");
288 for (i = 0; i < model_index; i++) {
289 printf ("T @ %-8d ", model_these[i]);
294 for (i = 0; i < nactors; i++) {
298 ap = actor_vector[i];
301 e10k = ninst * (ap->a + ap->b*((ninst-1.0)/2.0));
305 pcttot = (e10k / ((double)total_time)) * 100.0;
306 printf ("%6ld %11.2f %11.2f %11.2f %11.2f %11.2f %11.2f %11.2f %11.2f 0x%08lx ",
307 ap->ninst, ap->a, ap->b, e10k, ap->min,
308 ap->max, ap->mean, pcttot, ap->r, ap->key);
311 printf ("%6ld %11.2f %11.2f %11.2f 0x%08lx ",
312 ap->ninst, ap->a, ap->b, e10k, ap->key);
314 for (j = 0; j < model_index; j++) {
315 ninst = model_these[j];
316 e10k = ninst * (ap->a + ap->b*((ninst-1.0)/2.0));
317 printf ("%10.2f ", e10k);
324 void scatterplot_data(void)
332 for (i = 0; i < NBUCKETS; i++) {
337 if (ap->key == scatterkey){
340 time = ((double)ip->time);
341 printf ("%d\t%.0f\n", count++, time);
354 fprintf(stderr, "%s", s);
355 fprintf(stderr, "\n");
364 int (*pass1)(cpel_section_header_t *, int, FILE *);
365 } section_processor_t;
367 int bad_section(cpel_section_header_t *sh, int verbose, FILE *ofp)
369 fprintf(ofp, "Bad (type 0) section, skipped...\n");
373 int noop_pass(cpel_section_header_t *sh, int verbose, FILE *ofp)
378 int unsupported_pass (cpel_section_header_t *sh, int verbose, FILE *ofp)
381 fprintf(ofp, "Unsupported type %d section\n",
382 ntohl(sh->section_type));
387 int trackdef_pass(cpel_section_header_t *sh, int verbose, FILE *ofp)
390 track_definition_section_header_t *tdh;
391 track_definition_t *tp;
396 tdh = (track_definition_section_header_t *)(sh+1);
397 nevents = ntohl(tdh->number_of_track_definitions);
400 fprintf(stderr, "Track Definition Section: %d definitions\n",
404 tp = (track_definition_t *)(tdh+1);
406 for (i = 0; i < nevents; i++) {
407 track_code = ntohl(tp->track);
408 p = hash_get(the_trackdef_hash, track_code);
410 fprintf(ofp, "track %d redefined, retain first definition\n",
414 vec_add2(bound_tracks, btp, 1);
415 btp->track_code = track_code;
416 hash_set(the_trackdef_hash, track_code, btp - bound_tracks);
423 int event_pass (cpel_section_header_t *sh, int verbose, FILE *ofp)
425 event_section_header_t *eh;
430 ulonglong end_time = 0;
437 u32 last_track_code = 0xdeafb00b;
439 u32 event_code, event_datum;
440 bound_track_t *tp = 0;
446 eh = (event_section_header_t *)(sh+1);
447 nevents = ntohl(eh->number_of_events);
448 ticks_per_us = ((double)ntohl(eh->clock_ticks_per_second))/1e6;
451 fprintf(ofp, "%.3f ticks_per_us\n", ticks_per_us);
454 ep = (event_entry_t *)(eh+1);
456 time0 = ntohl (ep->time[0]);
457 time1 = ntohl (ep->time[1]);
459 now = (((u64) time0)<<32) | time1;
462 first_start_time = d;
464 for (i = 0; i < nevents; i++) {
465 time0 = ntohl (ep->time[0]);
466 time1 = ntohl (ep->time[1]);
468 now = (((u64) time0)<<32) | time1;
470 /* Convert from bus ticks to usec */
476 track_code = ntohl(ep->track);
477 event_code = ntohl(ep->event_code);
478 event_datum = ntohl(ep->event_datum);
480 if (track_code != last_track_code) {
482 tp->thread_timestamp += now - tp->time_thread_on_cpu;
483 tp->time_thread_on_cpu = 0;
485 p = hash_get(the_trackdef_hash, track_code);
487 /* synthesize a new track */
488 vec_add2(bound_tracks, tp, 1);
489 tp->track_code = track_code;
490 hash_set(the_trackdef_hash, track_code, tp - bound_tracks);
492 tp = bound_tracks + p[0];
494 last_track_code = track_code;
495 tp->time_thread_on_cpu = now;
498 if (event_code != entry_event &&
499 event_code != exit_event) {
506 case 0: /* not in state */
507 /* Another exit event? Stack pop */
508 if (event_code == exit_event) {
509 /* Only if we have something on the stack */
510 if (vec_len(tp->start_datum) > 0) {
515 "End event before start event, key 0x%x.",
516 ntohl(ep->event_datum));
517 fprintf (stderr, " Interpret results carefully...\n");
522 if (vec_len(tp->start_datum) >= MAXSTACK) {
525 fprintf (stderr, "stack overflow..\n");
526 for (j = vec_len(tp->start_datum)-1; j >= 0; j--) {
527 fprintf(stderr, "stack[%d]: datum 0x%x\n",
528 j, tp->start_datum[j]);
531 "Stack overflow... This occurs when "
532 "(start, datum)...(end, datum) events\n"
533 "are not properly paired.\n\n"
534 "A typical scenario looks like this:\n\n"
536 " ELOG(..., START_EVENT, datum);\n"
538 " return; /*oops, forgot the end event*/\n"
539 " ELOG(..., END_EVENT, datum);\n"
541 "The datum stack dump (above) should make it clear\n"
542 "where to start looking for a sneak path...\n");
546 vec_add1(tp->start_datum, event_datum);
547 vec_add1(tp->start_time, (tp->thread_timestamp + (now - tp->time_thread_on_cpu)));
548 #ifdef HAVING_TROUBLE
549 printf ("sp %lld key 0x%x start time %llu\n",
550 (long long) vec_len(tp->start_time)-1, event_datum,
552 tp->start_time [vec_len(tp->start_time)-1]);
553 printf ("timestamp %llu, now %llu, thread on cpu %llu\n",
554 (unsigned long long) tp->thread_timestamp,
555 (unsigned long long) now,
556 (unsigned long long) tp->time_thread_on_cpu);
562 * Multiple identical enter events? If the user knows that
563 * gcc is producing bogus events due to inline functions,
564 * trash the duplicate.
567 && vec_len (tp->start_datum) > 1
568 && tp->start_datum [vec_len(tp->start_datum)-1] ==
569 tp->start_datum [vec_len(tp->start_datum)-2]) {
570 vec_add1 (tp->dup_event, 1);
572 vec_add1 (tp->dup_event, 0);
579 case 1: /* in state */
580 /* Another entry event? Stack push*/
581 if (event_code == entry_event) {
586 if (vec_len(tp->start_datum) == 0) {
587 fprintf (stderr, "Stack underflow...\n");
591 sp = vec_len(tp->start_time)-1;
593 end_time = tp->thread_timestamp + (now - tp->time_thread_on_cpu);
595 if (!tp->dup_event[sp]) {
596 #ifdef HAVING_TROUBLE
597 printf ("sp %d key 0x%x charged %llu\n", sp,
598 tp->start_datum[sp], end_time - tp->start_time[sp]);
599 printf (" start %llu, end %llu\n", (unsigned long long) tp->start_time[sp],
600 (unsigned long long) end_time);
603 record_instance (tp->start_datum[sp], (end_time -
604 tp->start_time[sp]));
606 /* Factor out our time from surrounding services, if any */
607 for (ancestor = sp-1; ancestor >= 0; ancestor--) {
608 #ifdef HAVING_TROUBLE
609 printf ("Factor out %lld from key 0x%08x\n",
610 (end_time - tp->start_time[sp]), tp->start_datum[ancestor]);
612 tp->start_time[ancestor] += (end_time - tp->start_time[sp]);
615 total_time += (end_time - tp->start_time[sp]);
620 _vec_len(tp->start_datum) = sp;
621 _vec_len(tp->start_time) = sp;
622 _vec_len(tp->dup_event) = sp;
635 t = (double)total_time;
636 printf ("%ld instances of state, %.2f microseconds average\n",
637 output_count, t / output_count);
639 printf ("Total instrumented runtime: %.2f microseconds\n",
640 ((double)total_time));
641 printf ("Total runtime: %lld microseconds\n",
642 last_end_time - first_start_time);
644 t /= (double)(last_end_time - first_start_time);
648 printf ("Suppressed %ld duplicate state entry events\n",
651 printf ("Instrumented code accounts for %.2f%% of total time.\n\n",
655 printf ("No instances of state...\n");
662 * Note: If necessary, add passes / columns to this table to
663 * handle section order dependencies.
666 section_processor_t processors[CPEL_NUM_SECTION_TYPES+1] =
668 {unsupported_pass}, /* type 0 -- f**ked */
669 {noop_pass}, /* type 1 -- STRTAB */
670 {noop_pass}, /* type 2 -- SYMTAB */
671 {noop_pass}, /* type 3 -- EVTDEF */
672 {trackdef_pass}, /* type 4 -- TRACKDEF */
673 {event_pass}, /* type 5 -- EVENTS */
676 int process_section(cpel_section_header_t *sh, int verbose, FILE *ofp,
680 type = ntohl(sh->section_type);
682 int (*fp)(cpel_section_header_t *, int, FILE *);
684 if (type > CPEL_NUM_SECTION_TYPES) {
685 fprintf(stderr, "Unknown section type %d\n", type);
690 fp = processors[type].pass1;
694 fprintf(stderr, "Unknown pass %d\n", pass);
698 rv = (*fp)(sh, verbose, ofp);
703 char *mapfile (char *file)
710 maphfile = open (file, O_RDONLY);
714 fprintf (stderr, "Couldn't read %s, skipping it...\n", file);
718 if (fstat (maphfile, &statb) < 0)
720 fprintf (stderr, "Couldn't get size of %s, skipping it...\n", file);
724 /* Don't try to mmap directories, FIFOs, semaphores, etc. */
725 if (! (statb.st_mode & S_IFREG)) {
726 fprintf (stderr, "%s is not a regular file, skipping it...\n", file);
730 mapfsize = statb.st_size;
734 fprintf (stderr, "%s zero-length, skipping it...\n", file);
739 rv = mmap (0, mapfsize, PROT_READ, MAP_SHARED, maphfile, 0);
743 fprintf (stderr, "%s problem mapping, I quit...\n", file);
750 int process_file (u8 *cpel, int verbose)
752 cpel_file_header_t *fh;
753 cpel_section_header_t *sh;
759 /* First, the file header */
760 fh = (cpel_file_header_t *)cpel;
761 if (fh->endian_version != CPEL_FILE_VERSION) {
762 if (fh->endian_version & CPEL_FILE_LITTLE_ENDIAN) {
763 fprintf(stderr, "Little endian data format not supported\n");
766 fprintf(stderr, "Unsupported file version 0x%x\n",
770 nsections = ntohs(fh->nsections);
773 * Take a passe through the file.
775 sh = (cpel_section_header_t *)(fh+1);
776 for (i = 0; i < nsections; i++) {
777 section_size = ntohl(sh->data_length);
780 fprintf(ofp, "Section type %d, size %d\n",
781 ntohl(sh->section_type),
785 if(process_section(sh, verbose, ofp, PASS1))
789 sh = (cpel_section_header_t *)(((u8 *)sh)+section_size);
795 /****************************************************************************
797 ****************************************************************************/
799 int main (int argc, char **argv)
807 fprintf (stderr, "usage: cpelinreg -i <file>\n");
808 fprintf (stderr, " -s start-event --e end-event [-nokey]\n");
809 fprintf (stderr, " [-m <ninst-to-model>][-xtra-stats]\n");
810 fprintf (stderr, " [-keyscatterplot <hex-key>]\n\n");
811 fprintf (stderr, "%s\n", version);
815 while (curarg < argc) {
816 if (!strncmp (argv[curarg], "-ifile", 2)) {
818 g_ifile = argv[curarg++];
821 if (!strncmp (argv[curarg], "-start", 2)) {
823 entry_event = atol (argv [curarg++]);
826 if (!strncmp (argv[curarg], "-end", 2)) {
828 exit_event = atol (argv [curarg++]);
832 if (!strncmp(argv[curarg], "-badinlines", 2)) {
838 if (!strncmp (argv[curarg], "-x", 2)) {
843 if (!strncmp (argv[curarg], "-nokey", 2)) {
848 if (!strncmp (argv[curarg], "-keyscatterplot", 2)) {
850 sscanf (argv[curarg], "%lx", &scatterkey);
855 if (!strncmp (argv[curarg], "-model", 2)) {
856 if (model_index >= sizeof(model_these) / sizeof(int)) {
857 fprintf (stderr, "Too many model requests\n");
861 model_these[model_index++] = atol (argv [curarg++]);
864 if (!strncmp (argv[curarg], "-verbose", 2)) {
870 fprintf (stderr, "unknown switch '%s'\n", argv[curarg]);
874 cpel = (u8 *)mapfile(g_ifile);
878 fprintf (stderr, "Couldn't open %s\n", g_ifile);
882 printf ("Extracting state info from %s\nentry_event %d, exit_event %d\n",
883 g_ifile, entry_event, exit_event);
885 printf ("All state instances mapped to a single actor chain\n");
888 the_trackdef_hash = hash_create (0, sizeof (uword));
890 process_file(cpel, verbose);