1 /* //device/tools/dmtracedump/TraceDump.c 2 ** 3 ** Copyright 2006, The Android Open Source Project 4 ** 5 ** Licensed under the Apache License, Version 2.0 (the "License"); 6 ** you may not use this file except in compliance with the License. 7 ** You may obtain a copy of the License at 8 ** 9 ** http://www.apache.org/licenses/LICENSE-2.0 10 ** 11 ** Unless required by applicable law or agreed to in writing, software 12 ** distributed under the License is distributed on an "AS IS" BASIS, 13 ** WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 14 ** See the License for the specific language governing permissions and 15 ** limitations under the License. 16 */ 17 18 /* 19 * Process dmtrace output. 20 * 21 * This is the wrong way to go about it -- C is a clumsy language for 22 * shuffling data around. It'll do for a first pass. 23 */ 24 #define NOT_VM 25 #include "Profile.h" // from VM header 26 27 #include <stdio.h> 28 #include <stdlib.h> 29 #include <string.h> 30 #include <unistd.h> 31 #include <inttypes.h> 32 #include <time.h> 33 #include <errno.h> 34 #include <assert.h> 35 36 /* Version number in the key file. Version 1 uses one byte for the thread id. 37 * Version 2 uses two bytes for the thread ids. 38 */ 39 int versionNumber; 40 41 /* arbitrarily limit indentation */ 42 #define MAX_STACK_DEPTH 10000 43 44 /* thread list in key file is not reliable, so just max out */ 45 #define MAX_THREADS 32768 46 47 /* Size of temporary buffers for escaping html strings */ 48 #define HTML_BUFSIZE 10240 49 50 /* Size of methodId->method cache */ 51 #define METHOD_CACHE_SIZE 2048 52 #define METHOD_CACHE_SIZE_MASK (METHOD_CACHE_SIZE - 1) 53 54 /* Some filter constants */ 55 #define FILTER_TAG '*' 56 #define FILTER_FLAG_THREAD '+' 57 #define FILTER_TYPE_CLASS 0 58 #define FILTER_TYPE_METHOD 1 59 60 #define DEFAULT_ACTIVE_THREADS 8 61 62 char *htmlHeader = 63 "<html>\n<head>\n<script type=\"text/javascript\" src=\"%ssortable.js\"></script>\n" 64 "<script langugage=\"javascript\">\n" 65 "function toggle(item) {\n" 66 " obj=document.getElementById(item);\n" 67 " visible=(obj.style.display!=\"none\" && obj.style.display!=\"\");\n" 68 " key=document.getElementById(\"x\" + item);\n" 69 " if (visible) {\n" 70 " obj.style.display=\"none\";\n" 71 " key.innerHTML=\"+\";\n" 72 " } else {\n" 73 " obj.style.display=\"block\";\n" 74 " key.innerHTML=\"-\";\n" 75 " }\n" 76 "}\n" 77 "function onMouseOver(obj) {\n" 78 " obj.style.background=\"lightblue\";\n" 79 "}\n" 80 "function onMouseOut(obj) {\n" 81 " obj.style.background=\"white\";\n" 82 "}\n" 83 "</script>\n" 84 "<style type=\"text/css\">\n" 85 "div { font-family: courier; font-size: 13 }\n" 86 "div.parent { margin-left: 15; display: none }\n" 87 "div.leaf { margin-left: 10 }\n" 88 "div.header { margin-left: 10 }\n" 89 "div.link { margin-left: 10; cursor: move }\n" 90 "span.parent { padding-right: 10; }\n" 91 "span.leaf { padding-right: 10; }\n" 92 "a img { border: 0;}\n" 93 "table.sortable th { border-width: 0px 1px 1px 1px; background-color: #ccc;}\n" 94 "a { text-decoration: none; }\n" 95 "a:hover { text-decoration: underline; }\n" 96 "table.sortable th, table.sortable td { text-align: left;}" 97 "table.sortable tr.odd td { background-color: #ddd; }\n" 98 "table.sortable tr.even td { background-color: #fff; }\n" 99 "</style>\n" 100 "</head><body>\n\n"; 101 102 char *htmlFooter = "\n</body>\n</html>\n"; 103 char *profileSeparator = 104 "======================================================================"; 105 106 const char* tableHeader = 107 "<table class='sortable' id='%s'><tr>\n" 108 "<th>Method</th>\n" 109 "<th>Run 1 (us)</th>\n" 110 "<th>Run 2 (us)</th>\n" 111 "<th>Diff (us)</th>\n" 112 "<th>Diff (%%)</th>\n" 113 "<th>1: # calls</th>\n" 114 "<th>2: # calls</th>\n" 115 "</tr>\n"; 116 117 const char* tableHeaderMissing = 118 "<table class='sortable' id='%s'>\n" 119 "<th>Method</th>\n" 120 "<th>Exclusive</th>\n" 121 "<th>Inclusive</th>\n" 122 "<th># calls</th>\n"; 123 124 #define GRAPH_LABEL_VISITED 0x0001 125 #define GRAPH_NODE_VISITED 0x0002 126 127 /* 128 * Values from the header of the data file. 129 */ 130 typedef struct DataHeader { 131 unsigned int magic; 132 short version; 133 short offsetToData; 134 long long startWhen; 135 } DataHeader; 136 137 /* 138 * Entry from the thread list. 139 */ 140 typedef struct ThreadEntry { 141 int threadId; 142 const char* threadName; 143 uint64_t elapsedTime; 144 } ThreadEntry; 145 146 struct MethodEntry; 147 typedef struct TimedMethod { 148 struct TimedMethod *next; 149 uint64_t elapsedInclusive; 150 int numCalls; 151 struct MethodEntry *method; 152 } TimedMethod; 153 154 typedef struct ClassEntry { 155 const char *className; 156 uint64_t elapsedExclusive; 157 int numMethods; 158 struct MethodEntry **methods; /* list of methods in this class */ 159 int numCalls[2]; /* 0=normal, 1=recursive */ 160 } ClassEntry; 161 162 typedef struct UniqueMethodEntry { 163 uint64_t elapsedExclusive; 164 int numMethods; 165 struct MethodEntry **methods; /* list of methods with same name */ 166 int numCalls[2]; /* 0=normal, 1=recursive */ 167 } UniqueMethodEntry; 168 169 /* 170 * Entry from the method list. 171 */ 172 typedef struct MethodEntry { 173 unsigned int methodId; 174 const char* className; 175 const char* methodName; 176 const char* signature; 177 const char* fileName; 178 int lineNum; 179 uint64_t elapsedExclusive; 180 uint64_t elapsedInclusive; 181 uint64_t topExclusive; /* non-recursive exclusive time */ 182 uint64_t recursiveInclusive; 183 struct TimedMethod *parents[2]; /* 0=normal, 1=recursive */ 184 struct TimedMethod *children[2]; /* 0=normal, 1=recursive */ 185 int numCalls[2]; /* 0=normal, 1=recursive */ 186 int index; /* used after sorting to number methods */ 187 int recursiveEntries; /* number of entries on the stack */ 188 int graphState; /* used when graphing to see if this method has been visited before */ 189 } MethodEntry; 190 191 /* 192 * The parsed contents of the key file. 193 */ 194 typedef struct DataKeys { 195 char* fileData; /* contents of the entire file */ 196 long fileLen; 197 int numThreads; 198 ThreadEntry* threads; 199 int numMethods; 200 MethodEntry* methods; /* 2 extra methods: "toplevel" and "unknown" */ 201 int* methodCache; /* methodId->methodIndex mapping */ 202 // TODO change to map methodId->method itself 203 } DataKeys; 204 205 #define TOPLEVEL_INDEX 0 206 #define UNKNOWN_INDEX 1 207 208 typedef struct StackEntry { 209 MethodEntry *method; 210 uint64_t entryTime; 211 } StackEntry; 212 213 typedef struct CallStack { 214 int top; 215 StackEntry calls[MAX_STACK_DEPTH]; 216 uint64_t lastEventTime; 217 uint64_t threadStartTime; 218 uint64_t* remTimes; 219 // Note: remTimes keeps a sum of 'un-allocated' time for each thread, in case 220 // we need to allocate it to one (or many) filter later. This would happen when 221 // we see a method exit that maches a filter, but whose entry we hadn't seen. 222 // TODO: consider moving remTimes into FilterTimes and change logic appropriately 223 } CallStack; 224 225 typedef struct DiffEntry { 226 MethodEntry* method1; 227 MethodEntry* method2; 228 int64_t differenceExclusive; 229 int64_t differenceInclusive; 230 double differenceExclusivePercentage; 231 double differenceInclusivePercentage; 232 } DiffEntry; 233 234 // Global options 235 typedef struct Options { 236 const char* traceFileName; 237 const char* diffFileName; 238 const char* graphFileName; 239 const char* filterFileName; 240 int keepDotFile; 241 int dump; 242 int outputHtml; 243 const char* sortableUrl; 244 int threshold; 245 } Options; 246 247 typedef struct TraceData { 248 int numClasses; 249 ClassEntry *classes; 250 CallStack *stacks[MAX_THREADS]; 251 int depth[MAX_THREADS]; 252 int numUniqueMethods; 253 UniqueMethodEntry *uniqueMethods; 254 } TraceData; 255 256 typedef struct FilterKey { 257 int type[2]; /* 0=class, 1=method; 2 needed for start and end keys */ 258 uint32_t flags; /* 1st bit = include cross-thread time */ 259 char* keys[2]; /* 2 needed for start and end keys */ 260 } FilterKey; 261 262 typedef struct FilterTimes { 263 uint64_t totalWaitTime; 264 uint64_t* threadWaitTimes; 265 uint64_t* threadExecutionTimesWhileWaiting; 266 uint64_t* threadExecutionTimes; 267 } FilterTimes; 268 269 typedef struct Filter { 270 char* filterName; 271 FilterKey* filterKeys; 272 int numKeys; 273 int activeCount; 274 int* activeThreads; 275 int* activationKeys; 276 FilterTimes times; 277 } Filter; 278 279 int numFilters = 0; // global 280 281 static Options gOptions; 282 283 /* Escapes characters in the source string that are html special entities. 284 * The escaped string is written to "dest" which must be large enough to 285 * hold the result. A pointer to "dest" is returned. The characters and 286 * their corresponding escape sequences are: 287 * '<' < 288 * '>' > 289 * '&' & 290 */ 291 char *htmlEscape(const char *src, char *dest, int len) 292 { 293 char *destStart = dest; 294 295 if (src == NULL) 296 return NULL; 297 298 int nbytes = 0; 299 while (*src) { 300 if (*src == '<') { 301 nbytes += 4; 302 if (nbytes >= len) 303 break; 304 *dest++ = '&'; 305 *dest++ = 'l'; 306 *dest++ = 't'; 307 *dest++ = ';'; 308 } else if (*src == '>') { 309 nbytes += 4; 310 if (nbytes >= len) 311 break; 312 *dest++ = '&'; 313 *dest++ = 'g'; 314 *dest++ = 't'; 315 *dest++ = ';'; 316 } else if (*src == '&') { 317 nbytes += 5; 318 if (nbytes >= len) 319 break; 320 *dest++ = '&'; 321 *dest++ = 'a'; 322 *dest++ = 'm'; 323 *dest++ = 'p'; 324 *dest++ = ';'; 325 } else { 326 nbytes += 1; 327 if (nbytes >= len) 328 break; 329 *dest++ = *src; 330 } 331 src += 1; 332 } 333 if (nbytes >= len) { 334 fprintf(stderr, "htmlEscape(): buffer overflow\n"); 335 exit(1); 336 } 337 *dest = 0; 338 339 return destStart; 340 } 341 342 /* Initializes a MethodEntry 343 */ 344 void initMethodEntry(MethodEntry *method, unsigned int methodId, 345 const char *className, const char *methodName, 346 const char *signature, const char* fileName, 347 const char* lineNumStr) 348 { 349 method->methodId = methodId; 350 method->className = className; 351 method->methodName = methodName; 352 method->signature = signature; 353 method->fileName = fileName; 354 method->lineNum = (lineNumStr != NULL) ? atoi(lineNumStr) : -1; 355 method->elapsedExclusive = 0; 356 method->elapsedInclusive = 0; 357 method->topExclusive = 0; 358 method->recursiveInclusive = 0; 359 method->parents[0] = NULL; 360 method->parents[1] = NULL; 361 method->children[0] = NULL; 362 method->children[1] = NULL; 363 method->numCalls[0] = 0; 364 method->numCalls[1] = 0; 365 method->index = 0; 366 method->recursiveEntries = 0; 367 } 368 369 /* 370 * This comparison function is called from qsort() to sort 371 * methods into decreasing order of exclusive elapsed time. 372 */ 373 int compareElapsedExclusive(const void *a, const void *b) { 374 uint64_t elapsed1, elapsed2; 375 int result; 376 377 const MethodEntry *methodA = *(const MethodEntry**)a; 378 const MethodEntry *methodB = *(const MethodEntry**)b; 379 elapsed1 = methodA->elapsedExclusive; 380 elapsed2 = methodB->elapsedExclusive; 381 if (elapsed1 < elapsed2) 382 return 1; 383 if (elapsed1 > elapsed2) 384 return -1; 385 386 /* If the elapsed times of two methods are equal, then sort them 387 * into alphabetical order. 388 */ 389 result = strcmp(methodA->className, methodB->className); 390 if (result == 0) { 391 if (methodA->methodName == NULL || methodB->methodName == NULL) { 392 unsigned int idA = methodA->methodId; 393 unsigned int idB = methodB->methodId; 394 if (idA < idB) 395 return -1; 396 if (idA > idB) 397 return 1; 398 return 0; 399 } 400 result = strcmp(methodA->methodName, methodB->methodName); 401 if (result == 0) 402 result = strcmp(methodA->signature, methodB->signature); 403 } 404 return result; 405 } 406 407 /* 408 * This comparison function is called from qsort() to sort 409 * methods into decreasing order of inclusive elapsed time. 410 */ 411 int compareElapsedInclusive(const void *a, const void *b) { 412 const MethodEntry *methodA, *methodB; 413 uint64_t elapsed1, elapsed2; 414 int result; 415 416 methodA = *(MethodEntry const **)a; 417 methodB = *(MethodEntry const **)b; 418 elapsed1 = methodA->elapsedInclusive; 419 elapsed2 = methodB->elapsedInclusive; 420 if (elapsed1 < elapsed2) 421 return 1; 422 if (elapsed1 > elapsed2) 423 return -1; 424 425 /* If the elapsed times of two methods are equal, then sort them 426 * into alphabetical order. 427 */ 428 result = strcmp(methodA->className, methodB->className); 429 if (result == 0) { 430 if (methodA->methodName == NULL || methodB->methodName == NULL) { 431 unsigned int idA = methodA->methodId; 432 unsigned int idB = methodB->methodId; 433 if (idA < idB) 434 return -1; 435 if (idA > idB) 436 return 1; 437 return 0; 438 } 439 result = strcmp(methodA->methodName, methodB->methodName); 440 if (result == 0) 441 result = strcmp(methodA->signature, methodB->signature); 442 } 443 return result; 444 } 445 446 /* 447 * This comparison function is called from qsort() to sort 448 * threads into decreasing order of elapsed time. 449 */ 450 int compareElapsed(const void *a, const void *b) { 451 const ThreadEntry *threadA, *threadB; 452 uint64_t elapsed1, elapsed2; 453 int result = 0; 454 455 threadA = (ThreadEntry const *)a; 456 threadB = (ThreadEntry const *)b; 457 elapsed1 = threadA->elapsedTime; 458 elapsed2 = threadB->elapsedTime; 459 if (elapsed1 < elapsed2) 460 return 1; 461 if (elapsed1 > elapsed2) 462 return -1; 463 464 /* If the elapsed times of two threads are equal, then sort them 465 * by thread id. 466 */ 467 int idA = threadA->threadId; 468 int idB = threadB->threadId; 469 if (idA < idB) 470 result = -1; 471 if (idA > idB) 472 result = 1; 473 474 return result; 475 } 476 477 /* 478 * This comparison function is called from qsort() to sort 479 * TimedMethods into decreasing order of inclusive elapsed time. 480 */ 481 int compareTimedMethod(const void *a, const void *b) { 482 const TimedMethod *timedA, *timedB; 483 uint64_t elapsed1, elapsed2; 484 int result; 485 486 timedA = (TimedMethod const *)a; 487 timedB = (TimedMethod const *)b; 488 elapsed1 = timedA->elapsedInclusive; 489 elapsed2 = timedB->elapsedInclusive; 490 if (elapsed1 < elapsed2) 491 return 1; 492 if (elapsed1 > elapsed2) 493 return -1; 494 495 /* If the elapsed times of two methods are equal, then sort them 496 * into alphabetical order. 497 */ 498 MethodEntry *methodA = timedA->method; 499 MethodEntry *methodB = timedB->method; 500 result = strcmp(methodA->className, methodB->className); 501 if (result == 0) { 502 if (methodA->methodName == NULL || methodB->methodName == NULL) { 503 unsigned int idA = methodA->methodId; 504 unsigned int idB = methodB->methodId; 505 if (idA < idB) 506 return -1; 507 if (idA > idB) 508 return 1; 509 return 0; 510 } 511 result = strcmp(methodA->methodName, methodB->methodName); 512 if (result == 0) 513 result = strcmp(methodA->signature, methodB->signature); 514 } 515 return result; 516 } 517 518 /* 519 * This comparison function is called from qsort() to sort 520 * MethodEntry pointers into alphabetical order of class names. 521 */ 522 int compareClassNames(const void *a, const void *b) { 523 int result; 524 525 const MethodEntry *methodA = *(const MethodEntry**)a; 526 const MethodEntry *methodB = *(const MethodEntry**)b; 527 result = strcmp(methodA->className, methodB->className); 528 if (result == 0) { 529 unsigned int idA = methodA->methodId; 530 unsigned int idB = methodB->methodId; 531 if (idA < idB) 532 return -1; 533 if (idA > idB) 534 return 1; 535 return 0; 536 } 537 return result; 538 } 539 540 /* 541 * This comparison function is called from qsort() to sort 542 * classes into decreasing order of exclusive elapsed time. 543 */ 544 int compareClassExclusive(const void *a, const void *b) { 545 uint64_t elapsed1, elapsed2; 546 int result; 547 548 const ClassEntry *classA = *(const ClassEntry**)a; 549 const ClassEntry *classB = *(const ClassEntry**)b; 550 elapsed1 = classA->elapsedExclusive; 551 elapsed2 = classB->elapsedExclusive; 552 if (elapsed1 < elapsed2) 553 return 1; 554 if (elapsed1 > elapsed2) 555 return -1; 556 557 /* If the elapsed times of two classs are equal, then sort them 558 * into alphabetical order. 559 */ 560 result = strcmp(classA->className, classB->className); 561 if (result == 0) { 562 /* Break ties with the first method id. This is probably not 563 * needed. 564 */ 565 unsigned int idA = classA->methods[0]->methodId; 566 unsigned int idB = classB->methods[0]->methodId; 567 if (idA < idB) 568 return -1; 569 if (idA > idB) 570 return 1; 571 return 0; 572 } 573 return result; 574 } 575 576 /* 577 * This comparison function is called from qsort() to sort 578 * MethodEntry pointers into alphabetical order by method name, 579 * then by class name. 580 */ 581 int compareMethodNames(const void *a, const void *b) { 582 int result; 583 584 const MethodEntry *methodA = *(const MethodEntry**)a; 585 const MethodEntry *methodB = *(const MethodEntry**)b; 586 if (methodA->methodName == NULL || methodB->methodName == NULL) { 587 return compareClassNames(a, b); 588 } 589 result = strcmp(methodA->methodName, methodB->methodName); 590 if (result == 0) { 591 result = strcmp(methodA->className, methodB->className); 592 if (result == 0) { 593 unsigned int idA = methodA->methodId; 594 unsigned int idB = methodB->methodId; 595 if (idA < idB) 596 return -1; 597 if (idA > idB) 598 return 1; 599 return 0; 600 } 601 } 602 return result; 603 } 604 605 /* 606 * This comparison function is called from qsort() to sort 607 * unique methods into decreasing order of exclusive elapsed time. 608 */ 609 int compareUniqueExclusive(const void *a, const void *b) { 610 uint64_t elapsed1, elapsed2; 611 int result; 612 613 const UniqueMethodEntry *uniqueA = *(const UniqueMethodEntry**)a; 614 const UniqueMethodEntry *uniqueB = *(const UniqueMethodEntry**)b; 615 elapsed1 = uniqueA->elapsedExclusive; 616 elapsed2 = uniqueB->elapsedExclusive; 617 if (elapsed1 < elapsed2) 618 return 1; 619 if (elapsed1 > elapsed2) 620 return -1; 621 622 /* If the elapsed times of two methods are equal, then sort them 623 * into alphabetical order. 624 */ 625 result = strcmp(uniqueA->methods[0]->className, 626 uniqueB->methods[0]->className); 627 if (result == 0) { 628 unsigned int idA = uniqueA->methods[0]->methodId; 629 unsigned int idB = uniqueB->methods[0]->methodId; 630 if (idA < idB) 631 return -1; 632 if (idA > idB) 633 return 1; 634 return 0; 635 } 636 return result; 637 } 638 639 /* 640 * Free a DataKeys struct. 641 */ 642 void freeDataKeys(DataKeys* pKeys) 643 { 644 if (pKeys == NULL) 645 return; 646 647 free(pKeys->fileData); 648 free(pKeys->threads); 649 free(pKeys->methods); 650 free(pKeys->methodCache); 651 free(pKeys); 652 } 653 654 /* 655 * Find the offset to the next occurrence of the specified character. 656 * 657 * "data" should point somewhere within the current line. "len" is the 658 * number of bytes left in the buffer. 659 * 660 * Returns -1 if we hit the end of the buffer. 661 */ 662 int findNextChar(const char* data, int len, char lookFor) 663 { 664 const char* start = data; 665 666 while (len > 0) { 667 if (*data == lookFor) 668 return data - start; 669 670 data++; 671 len--; 672 } 673 674 return -1; 675 } 676 677 int countLinesToChar(const char* data, int len, const char toFind) 678 { 679 int count = 0; 680 int next; 681 682 while (*data != toFind) { 683 next = findNextChar(data, len, '\n'); 684 if (next < 0) 685 return count; 686 count++; 687 data += next+1; 688 len -= next+1; 689 } 690 691 return count; 692 } 693 694 /* 695 * Count the number of lines until the next token. 696 * 697 * Returns 0 if none found before EOF. 698 */ 699 int countLinesToToken(const char* data, int len) 700 { 701 return countLinesToChar(data, len, TOKEN_CHAR); 702 } 703 704 /* 705 * Make sure we're at the start of the right section. 706 * 707 * Returns the length of the token line, or -1 if something is wrong. 708 */ 709 int checkToken(const char* data, int len, const char* cmpStr) 710 { 711 int cmpLen = strlen(cmpStr); 712 int next; 713 714 if (*data != TOKEN_CHAR) { 715 fprintf(stderr, 716 "ERROR: not at start of %s (found '%.10s')\n", cmpStr, data); 717 return -1; 718 } 719 720 next = findNextChar(data, len, '\n'); 721 if (next < cmpLen+1) 722 return -1; 723 724 if (strncmp(data+1, cmpStr, cmpLen) != 0) { 725 fprintf(stderr, "ERROR: '%s' not found (got '%.7s')\n", cmpStr, data+1); 726 return -1; 727 } 728 729 return next+1; 730 } 731 732 /* 733 * Parse the "*version" section. 734 */ 735 long parseVersion(DataKeys* pKeys, long offset, int verbose) 736 { 737 char* data; 738 char* dataEnd; 739 int i, count, next; 740 741 if (offset < 0) 742 return -1; 743 744 data = pKeys->fileData + offset; 745 dataEnd = pKeys->fileData + pKeys->fileLen; 746 next = checkToken(data, dataEnd - data, "version"); 747 if (next <= 0) 748 return -1; 749 750 data += next; 751 752 /* 753 * Count the number of items in the "version" section. 754 */ 755 count = countLinesToToken(data, dataEnd - data); 756 if (count <= 0) { 757 fprintf(stderr, 758 "ERROR: failed while reading version (found %d)\n", count); 759 return -1; 760 } 761 762 /* find the end of the line */ 763 next = findNextChar(data, dataEnd - data, '\n'); 764 if (next < 0) 765 return -1; 766 767 data[next] = '\0'; 768 versionNumber = strtoul(data, NULL, 0); 769 if (verbose) 770 printf("VERSION: %d\n", versionNumber); 771 772 data += next+1; 773 774 /* skip over the rest of the stuff, which is "name=value" lines */ 775 for (i = 1; i < count; i++) { 776 next = findNextChar(data, dataEnd - data, '\n'); 777 if (next < 0) 778 return -1; 779 //data[next] = '\0'; 780 //printf("IGNORING: '%s'\n", data); 781 data += next+1; 782 } 783 784 return data - pKeys->fileData; 785 } 786 787 /* 788 * Parse the "*threads" section. 789 */ 790 long parseThreads(DataKeys* pKeys, long offset) 791 { 792 char* data; 793 char* dataEnd; 794 int i, next, tab, count; 795 796 if (offset < 0) 797 return -1; 798 799 data = pKeys->fileData + offset; 800 dataEnd = pKeys->fileData + pKeys->fileLen; 801 next = checkToken(data, dataEnd - data, "threads"); 802 803 data += next; 804 805 /* 806 * Count the number of thread entries (one per line). 807 */ 808 count = countLinesToToken(data, dataEnd - data); 809 if (count <= 0) { 810 fprintf(stderr, 811 "ERROR: failed while reading threads (found %d)\n", count); 812 return -1; 813 } 814 815 //printf("+++ found %d threads\n", count); 816 pKeys->threads = (ThreadEntry*) malloc(sizeof(ThreadEntry) * count); 817 if (pKeys->threads == NULL) 818 return -1; 819 820 /* 821 * Extract all entries. 822 */ 823 for (i = 0; i < count; i++) { 824 next = findNextChar(data, dataEnd - data, '\n'); 825 assert(next > 0); 826 data[next] = '\0'; 827 828 tab = findNextChar(data, next, '\t'); 829 data[tab] = '\0'; 830 831 pKeys->threads[i].threadId = atoi(data); 832 pKeys->threads[i].threadName = data + tab +1; 833 834 data += next+1; 835 } 836 837 pKeys->numThreads = count; 838 return data - pKeys->fileData; 839 } 840 841 /* 842 * Parse the "*methods" section. 843 */ 844 long parseMethods(DataKeys* pKeys, long offset) 845 { 846 char* data; 847 char* dataEnd; 848 int i, next, count; 849 850 if (offset < 0) 851 return -1; 852 853 data = pKeys->fileData + offset; 854 dataEnd = pKeys->fileData + pKeys->fileLen; 855 next = checkToken(data, dataEnd - data, "methods"); 856 if (next < 0) 857 return -1; 858 859 data += next; 860 861 /* 862 * Count the number of method entries (one per line). 863 */ 864 count = countLinesToToken(data, dataEnd - data); 865 if (count <= 0) { 866 fprintf(stderr, 867 "ERROR: failed while reading methods (found %d)\n", count); 868 return -1; 869 } 870 871 /* Reserve an extra method at location 0 for the "toplevel" method, 872 * and another extra method for all other "unknown" methods. 873 */ 874 count += 2; 875 pKeys->methods = (MethodEntry*) malloc(sizeof(MethodEntry) * count); 876 if (pKeys->methods == NULL) 877 return -1; 878 initMethodEntry(&pKeys->methods[TOPLEVEL_INDEX], 0, "(toplevel)", 879 NULL, NULL, NULL, NULL); 880 initMethodEntry(&pKeys->methods[UNKNOWN_INDEX], 0, "(unknown)", 881 NULL, NULL, NULL, NULL); 882 883 /* 884 * Extract all entries, starting with index 2. 885 */ 886 for (i = UNKNOWN_INDEX + 1; i < count; i++) { 887 int tab1, tab2, tab3, tab4, tab5; 888 unsigned int id; 889 char* endptr; 890 891 next = findNextChar(data, dataEnd - data, '\n'); 892 assert(next > 0); 893 data[next] = '\0'; 894 895 tab1 = findNextChar(data, next, '\t'); 896 tab2 = findNextChar(data+(tab1+1), next-(tab1+1), '\t'); 897 tab3 = findNextChar(data+(tab1+tab2+2), next-(tab1+tab2+2), '\t'); 898 tab4 = findNextChar(data+(tab1+tab2+tab3+3), 899 next-(tab1+tab2+tab3+3), '\t'); 900 tab5 = findNextChar(data+(tab1+tab2+tab3+tab4+4), 901 next-(tab1+tab2+tab3+tab4+4), '\t'); 902 if (tab1 < 0) { 903 fprintf(stderr, "ERROR: missing field on method line: '%s'\n", 904 data); 905 return -1; 906 } 907 assert(data[tab1] == '\t'); 908 data[tab1] = '\0'; 909 910 id = strtoul(data, &endptr, 0); 911 if (*endptr != '\0') { 912 fprintf(stderr, "ERROR: bad method ID '%s'\n", data); 913 return -1; 914 } 915 916 // Allow files that specify just a function name, instead of requiring 917 // "class \t method \t signature" 918 if (tab2 > 0 && tab3 > 0) { 919 tab2 += tab1+1; 920 tab3 += tab2+1; 921 assert(data[tab2] == '\t'); 922 assert(data[tab3] == '\t'); 923 data[tab2] = data[tab3] = '\0'; 924 925 // This is starting to get awkward. Allow filename and line #. 926 if (tab4 > 0 && tab5 > 0) { 927 tab4 += tab3+1; 928 tab5 += tab4+1; 929 930 assert(data[tab4] == '\t'); 931 assert(data[tab5] == '\t'); 932 data[tab4] = data[tab5] = '\0'; 933 934 initMethodEntry(&pKeys->methods[i], id, data + tab1 +1, 935 data + tab2 +1, data + tab3 +1, data + tab4 +1, 936 data + tab5 +1); 937 } else { 938 initMethodEntry(&pKeys->methods[i], id, data + tab1 +1, 939 data + tab2 +1, data + tab3 +1, NULL, NULL); 940 } 941 } else { 942 initMethodEntry(&pKeys->methods[i], id, data + tab1 +1, 943 NULL, NULL, NULL, NULL); 944 } 945 946 data += next+1; 947 } 948 949 pKeys->numMethods = count; 950 return data - pKeys->fileData; 951 } 952 953 /* 954 * Parse the "*end" section. 955 */ 956 long parseEnd(DataKeys* pKeys, long offset) 957 { 958 char* data; 959 char* dataEnd; 960 int next; 961 962 if (offset < 0) 963 return -1; 964 965 data = pKeys->fileData + offset; 966 dataEnd = pKeys->fileData + pKeys->fileLen; 967 next = checkToken(data, dataEnd - data, "end"); 968 if (next < 0) 969 return -1; 970 971 data += next; 972 973 return data - pKeys->fileData; 974 } 975 976 /* 977 * Sort the thread list entries. 978 */ 979 static int compareThreads(const void* thread1, const void* thread2) 980 { 981 return ((const ThreadEntry*) thread1)->threadId - 982 ((const ThreadEntry*) thread2)->threadId; 983 } 984 985 void sortThreadList(DataKeys* pKeys) 986 { 987 qsort(pKeys->threads, pKeys->numThreads, sizeof(pKeys->threads[0]), 988 compareThreads); 989 } 990 991 /* 992 * Sort the method list entries. 993 */ 994 static int compareMethods(const void* meth1, const void* meth2) 995 { 996 unsigned int id1, id2; 997 998 id1 = ((const MethodEntry*) meth1)->methodId; 999 id2 = ((const MethodEntry*) meth2)->methodId; 1000 if (id1 < id2) 1001 return -1; 1002 if (id1 > id2) 1003 return 1; 1004 return 0; 1005 } 1006 1007 void sortMethodList(DataKeys* pKeys) 1008 { 1009 qsort(pKeys->methods, pKeys->numMethods, sizeof(MethodEntry), 1010 compareMethods); 1011 } 1012 1013 /* 1014 * Parse the key section, and return a copy of the parsed contents. 1015 */ 1016 DataKeys* parseKeys(FILE *fp, int verbose) 1017 { 1018 DataKeys* pKeys = NULL; 1019 long offset; 1020 int i; 1021 1022 pKeys = (DataKeys*) calloc(1, sizeof(DataKeys)); 1023 if (pKeys == NULL) 1024 goto fail; 1025 1026 /* 1027 * We load the entire file into memory. We do this, rather than memory- 1028 * mapping it, because we want to change some whitespace to NULs. 1029 */ 1030 if (fseek(fp, 0L, SEEK_END) != 0) { 1031 perror("fseek"); 1032 goto fail; 1033 } 1034 pKeys->fileLen = ftell(fp); 1035 if (pKeys->fileLen == 0) { 1036 fprintf(stderr, "Key file is empty.\n"); 1037 goto fail; 1038 } 1039 rewind(fp); 1040 1041 pKeys->fileData = (char*) malloc(pKeys->fileLen); 1042 if (pKeys->fileData == NULL) { 1043 fprintf(stderr, "ERROR: unable to alloc %ld bytes\n", pKeys->fileLen); 1044 goto fail; 1045 } 1046 1047 if (fread(pKeys->fileData, 1, pKeys->fileLen, fp) != (size_t) pKeys->fileLen) 1048 { 1049 fprintf(stderr, "ERROR: unable to read %ld bytes from trace file\n", 1050 pKeys->fileLen); 1051 goto fail; 1052 } 1053 1054 offset = 0; 1055 1056 offset = parseVersion(pKeys, offset, verbose); 1057 offset = parseThreads(pKeys, offset); 1058 offset = parseMethods(pKeys, offset); 1059 offset = parseEnd(pKeys, offset); 1060 if (offset < 0) 1061 goto fail; 1062 1063 /* Leave fp pointing to the beginning of the data section. */ 1064 fseek(fp, offset, SEEK_SET); 1065 1066 sortThreadList(pKeys); 1067 sortMethodList(pKeys); 1068 1069 /* 1070 * Dump list of threads. 1071 */ 1072 if (verbose) { 1073 printf("Threads (%d):\n", pKeys->numThreads); 1074 for (i = 0; i < pKeys->numThreads; i++) { 1075 printf("%2d %s\n", 1076 pKeys->threads[i].threadId, pKeys->threads[i].threadName); 1077 } 1078 } 1079 1080 #if 0 1081 /* 1082 * Dump list of methods. 1083 */ 1084 if (verbose) { 1085 printf("Methods (%d):\n", pKeys->numMethods); 1086 for (i = 0; i < pKeys->numMethods; i++) { 1087 printf("0x%08x %s : %s : %s\n", 1088 pKeys->methods[i].methodId >> 2, pKeys->methods[i].className, 1089 pKeys->methods[i].methodName, pKeys->methods[i].signature); 1090 } 1091 } 1092 #endif 1093 1094 return pKeys; 1095 1096 fail: 1097 freeDataKeys(pKeys); 1098 return NULL; 1099 } 1100 1101 1102 /* 1103 * Read values from the binary data file. 1104 */ 1105 1106 /* Make the return value "unsigned int" instead of "unsigned short" so that 1107 * we can detect EOF. 1108 */ 1109 unsigned int read2LE(FILE* fp) 1110 { 1111 unsigned int val; 1112 1113 val = getc(fp); 1114 val |= getc(fp) << 8; 1115 return val; 1116 } 1117 unsigned int read4LE(FILE* fp) 1118 { 1119 unsigned int val; 1120 1121 val = getc(fp); 1122 val |= getc(fp) << 8; 1123 val |= getc(fp) << 16; 1124 val |= getc(fp) << 24; 1125 return val; 1126 } 1127 unsigned long long read8LE(FILE* fp) 1128 { 1129 unsigned long long val; 1130 1131 val = getc(fp); 1132 val |= (unsigned long long) getc(fp) << 8; 1133 val |= (unsigned long long) getc(fp) << 16; 1134 val |= (unsigned long long) getc(fp) << 24; 1135 val |= (unsigned long long) getc(fp) << 32; 1136 val |= (unsigned long long) getc(fp) << 40; 1137 val |= (unsigned long long) getc(fp) << 48; 1138 val |= (unsigned long long) getc(fp) << 56; 1139 return val; 1140 } 1141 1142 /* 1143 * Parse the header of the data section. 1144 * 1145 * Returns with the file positioned at the start of the record data. 1146 */ 1147 int parseDataHeader(FILE *fp, DataHeader* pHeader) 1148 { 1149 pHeader->magic = read4LE(fp); 1150 pHeader->version = read2LE(fp); 1151 pHeader->offsetToData = read2LE(fp); 1152 pHeader->startWhen = read8LE(fp); 1153 1154 if (fseek(fp, pHeader->offsetToData - 16, SEEK_CUR) != 0) { 1155 return -1; 1156 } 1157 1158 return 0; 1159 } 1160 1161 /* 1162 * Look up a method by its method ID (using binary search). 1163 * 1164 * Returns NULL if no matching method was found. 1165 */ 1166 MethodEntry* lookupMethod(DataKeys* pKeys, unsigned int methodId) 1167 { 1168 int hi, lo, mid; 1169 unsigned int id; 1170 int hashedId; 1171 1172 /* Create cache if it doesn't already exist */ 1173 if (pKeys->methodCache == NULL) { 1174 pKeys->methodCache = (int*) calloc(METHOD_CACHE_SIZE, sizeof(int)); 1175 } 1176 1177 // ids are multiples of 4, so shift 1178 hashedId = (methodId >> 2) & METHOD_CACHE_SIZE_MASK; 1179 if (pKeys->methodCache[hashedId]) /* cache hit */ 1180 if (pKeys->methods[pKeys->methodCache[hashedId]].methodId == methodId) 1181 return &pKeys->methods[pKeys->methodCache[hashedId]]; 1182 1183 lo = 0; 1184 hi = pKeys->numMethods - 1; 1185 1186 while (hi >= lo) { 1187 mid = (hi + lo) / 2; 1188 1189 id = pKeys->methods[mid].methodId; 1190 if (id == methodId) { /* match, put in cache */ 1191 hashedId = (methodId >> 2) & METHOD_CACHE_SIZE_MASK; 1192 pKeys->methodCache[hashedId] = mid; 1193 return &pKeys->methods[mid]; 1194 } else if (id < methodId) /* too low */ 1195 lo = mid + 1; 1196 else /* too high */ 1197 hi = mid - 1; 1198 } 1199 1200 return NULL; 1201 } 1202 1203 /* 1204 * Reads the next data record, and assigns the data values to threadId, 1205 * methodVal and elapsedTime. On end-of-file, the threadId, methodVal, 1206 * and elapsedTime are unchanged. Returns 1 on end-of-file, otherwise 1207 * returns 0. 1208 */ 1209 int readDataRecord(FILE *dataFp, int *threadId, unsigned int *methodVal, 1210 uint64_t *elapsedTime) 1211 { 1212 int id; 1213 1214 /* 1215 * TODO: 1216 * This SHOULD NOT be keyed off of the global version number! Use 1217 * a name=value setting in the version area instead! 1218 */ 1219 if (versionNumber == 1) { 1220 id = getc(dataFp); 1221 } else { 1222 id = read2LE(dataFp); 1223 } 1224 if (id == EOF) 1225 return 1; 1226 *threadId = id; 1227 1228 *methodVal = read4LE(dataFp); 1229 *elapsedTime = read4LE(dataFp); 1230 if (feof(dataFp)) { 1231 fprintf(stderr, "WARNING: hit EOF mid-record\n"); 1232 return 1; 1233 } 1234 return 0; 1235 } 1236 1237 /* 1238 * Read the key file and use it to produce formatted output from the 1239 * data file. 1240 */ 1241 void dumpTrace() 1242 { 1243 static const char* actionStr[] = { "ent", "xit", "unr", "???" }; 1244 MethodEntry bogusMethod = { 0, "???", "???", "???", "???", -1, 0, 0, 0, 0, 1245 {NULL, NULL}, {NULL, NULL}, {0, 0}, 0, 0, -1 }; 1246 char bogusBuf[80]; 1247 char spaces[MAX_STACK_DEPTH+1]; 1248 FILE* dataFp = NULL; 1249 DataHeader dataHeader; 1250 DataKeys* pKeys = NULL; 1251 int i; 1252 TraceData traceData; 1253 1254 //printf("Dumping '%s' '%s'\n", dataFileName, keyFileName); 1255 1256 memset(spaces, '.', MAX_STACK_DEPTH); 1257 spaces[MAX_STACK_DEPTH] = '\0'; 1258 1259 for (i = 0; i < MAX_THREADS; i++) 1260 traceData.depth[i] = 2; // adjust for return from start function 1261 1262 dataFp = fopen(gOptions.traceFileName, "r"); 1263 if (dataFp == NULL) 1264 goto bail; 1265 1266 if ((pKeys = parseKeys(dataFp, 1)) == NULL) 1267 goto bail; 1268 1269 if (parseDataHeader(dataFp, &dataHeader) < 0) 1270 goto bail; 1271 1272 printf("Trace (threadID action usecs class.method signature):\n"); 1273 1274 while (1) { 1275 MethodEntry* method; 1276 int threadId; 1277 unsigned int methodVal; 1278 uint64_t elapsedTime; 1279 int action, printDepth; 1280 unsigned int methodId, lastEnter = 0; 1281 int mismatch = 0; 1282 char depthNote; 1283 1284 /* 1285 * Extract values from file. 1286 */ 1287 if (readDataRecord(dataFp, &threadId, &methodVal, &elapsedTime)) 1288 break; 1289 1290 action = METHOD_ACTION(methodVal); 1291 methodId = METHOD_ID(methodVal); 1292 1293 /* 1294 * Generate a line of output. 1295 */ 1296 if (action == METHOD_TRACE_ENTER) { 1297 traceData.depth[threadId]++; 1298 lastEnter = methodId; 1299 } else { 1300 /* quick test for mismatched adjacent enter/exit */ 1301 if (lastEnter != 0 && lastEnter != methodId) 1302 mismatch = 1; 1303 } 1304 1305 printDepth = traceData.depth[threadId]; 1306 depthNote = ' '; 1307 if (printDepth < 0) { 1308 printDepth = 0; 1309 depthNote = '-'; 1310 } else if (printDepth > MAX_STACK_DEPTH) { 1311 printDepth = MAX_STACK_DEPTH; 1312 depthNote = '+'; 1313 } 1314 1315 method = lookupMethod(pKeys, methodId); 1316 if (method == NULL) { 1317 method = &bogusMethod; 1318 sprintf(bogusBuf, "methodId: 0x%x", methodId); 1319 method->signature = bogusBuf; 1320 } 1321 1322 if (method->methodName) { 1323 printf("%2d %s%c %8lld%c%s%s.%s %s\n", threadId, 1324 actionStr[action], mismatch ? '!' : ' ', 1325 elapsedTime, depthNote, 1326 spaces + (MAX_STACK_DEPTH - printDepth), 1327 method->className, method->methodName, method->signature); 1328 } else { 1329 printf("%2d %s%c %8lld%c%s%s\n", threadId, 1330 actionStr[action], mismatch ? '!' : ' ', 1331 elapsedTime, depthNote, 1332 spaces + (MAX_STACK_DEPTH - printDepth), 1333 method->className); 1334 } 1335 1336 if (action != METHOD_TRACE_ENTER) { 1337 traceData.depth[threadId]--; /* METHOD_TRACE_EXIT or METHOD_TRACE_UNROLL */ 1338 lastEnter = 0; 1339 } 1340 1341 mismatch = 0; 1342 } 1343 1344 bail: 1345 if (dataFp != NULL) 1346 fclose(dataFp); 1347 if (pKeys != NULL) 1348 freeDataKeys(pKeys); 1349 } 1350 1351 /* This routine adds the given time to the parent and child methods. 1352 * This is called when the child routine exits, after the child has 1353 * been popped from the stack. The elapsedTime parameter is the 1354 * duration of the child routine, including time spent in called routines. 1355 */ 1356 void addInclusiveTime(MethodEntry *parent, MethodEntry *child, 1357 uint64_t elapsedTime) 1358 { 1359 TimedMethod *pTimed; 1360 1361 #if 0 1362 bool verbose = false; 1363 if (strcmp(child->className, debugClassName) == 0) 1364 verbose = true; 1365 #endif 1366 1367 int childIsRecursive = (child->recursiveEntries > 0); 1368 int parentIsRecursive = (parent->recursiveEntries > 1); 1369 1370 if (child->recursiveEntries == 0) { 1371 child->elapsedInclusive += elapsedTime; 1372 } else if (child->recursiveEntries == 1) { 1373 child->recursiveInclusive += elapsedTime; 1374 } 1375 child->numCalls[childIsRecursive] += 1; 1376 1377 #if 0 1378 if (verbose) { 1379 fprintf(stderr, 1380 "%s %d elapsedTime: %lld eI: %lld, rI: %lld\n", 1381 child->className, child->recursiveEntries, 1382 elapsedTime, child->elapsedInclusive, 1383 child->recursiveInclusive); 1384 } 1385 #endif 1386 1387 /* Find the child method in the parent */ 1388 TimedMethod *children = parent->children[parentIsRecursive]; 1389 for (pTimed = children; pTimed; pTimed = pTimed->next) { 1390 if (pTimed->method == child) { 1391 pTimed->elapsedInclusive += elapsedTime; 1392 pTimed->numCalls += 1; 1393 break; 1394 } 1395 } 1396 if (pTimed == NULL) { 1397 /* Allocate a new TimedMethod */ 1398 pTimed = (TimedMethod *) malloc(sizeof(TimedMethod)); 1399 pTimed->elapsedInclusive = elapsedTime; 1400 pTimed->numCalls = 1; 1401 pTimed->method = child; 1402 1403 /* Add it to the front of the list */ 1404 pTimed->next = children; 1405 parent->children[parentIsRecursive] = pTimed; 1406 } 1407 1408 /* Find the parent method in the child */ 1409 TimedMethod *parents = child->parents[childIsRecursive]; 1410 for (pTimed = parents; pTimed; pTimed = pTimed->next) { 1411 if (pTimed->method == parent) { 1412 pTimed->elapsedInclusive += elapsedTime; 1413 pTimed->numCalls += 1; 1414 break; 1415 } 1416 } 1417 if (pTimed == NULL) { 1418 /* Allocate a new TimedMethod */ 1419 pTimed = (TimedMethod *) malloc(sizeof(TimedMethod)); 1420 pTimed->elapsedInclusive = elapsedTime; 1421 pTimed->numCalls = 1; 1422 pTimed->method = parent; 1423 1424 /* Add it to the front of the list */ 1425 pTimed->next = parents; 1426 child->parents[childIsRecursive] = pTimed; 1427 } 1428 1429 #if 0 1430 if (verbose) { 1431 fprintf(stderr, 1432 " %s %d eI: %lld\n", 1433 parent->className, parent->recursiveEntries, 1434 pTimed->elapsedInclusive); 1435 } 1436 #endif 1437 } 1438 1439 /* Sorts a linked list and returns a newly allocated array containing 1440 * the sorted entries. 1441 */ 1442 TimedMethod *sortTimedMethodList(TimedMethod *list, int *num) 1443 { 1444 int ii; 1445 TimedMethod *pTimed, *sorted; 1446 1447 /* Count the elements */ 1448 int num_entries = 0; 1449 for (pTimed = list; pTimed; pTimed = pTimed->next) 1450 num_entries += 1; 1451 *num = num_entries; 1452 if (num_entries == 0) 1453 return NULL; 1454 1455 /* Copy all the list elements to a new array and sort them */ 1456 sorted = (TimedMethod *) malloc(sizeof(TimedMethod) * num_entries); 1457 for (ii = 0, pTimed = list; pTimed; pTimed = pTimed->next, ++ii) 1458 memcpy(&sorted[ii], pTimed, sizeof(TimedMethod)); 1459 qsort(sorted, num_entries, sizeof(TimedMethod), compareTimedMethod); 1460 1461 /* Fix up the "next" pointers so that they work. */ 1462 for (ii = 0; ii < num_entries - 1; ++ii) 1463 sorted[ii].next = &sorted[ii + 1]; 1464 sorted[num_entries - 1].next = NULL; 1465 1466 return sorted; 1467 } 1468 1469 /* Define flag values for printInclusiveMethod() */ 1470 static const int kIsRecursive = 1; 1471 1472 /* This prints the inclusive stats for all the parents or children of a 1473 * method, depending on the list that is passed in. 1474 */ 1475 void printInclusiveMethod(MethodEntry *method, TimedMethod *list, int numCalls, 1476 int flags) 1477 { 1478 int num; 1479 TimedMethod *pTimed; 1480 char buf[80]; 1481 char *anchor_close; 1482 char *spaces = " "; /* 6 spaces */ 1483 int num_spaces = strlen(spaces); 1484 char *space_ptr = &spaces[num_spaces]; 1485 char *className, *methodName, *signature; 1486 char classBuf[HTML_BUFSIZE], methodBuf[HTML_BUFSIZE]; 1487 char signatureBuf[HTML_BUFSIZE]; 1488 1489 anchor_close = ""; 1490 if (gOptions.outputHtml) 1491 anchor_close = "</a>"; 1492 1493 TimedMethod *sorted = sortTimedMethodList(list, &num); 1494 double methodTotal = method->elapsedInclusive; 1495 for (pTimed = sorted; pTimed; pTimed = pTimed->next) { 1496 MethodEntry *relative = pTimed->method; 1497 className = (char*)(relative->className); 1498 methodName = (char*)(relative->methodName); 1499 signature = (char*)(relative->signature); 1500 double per = 100.0 * pTimed->elapsedInclusive / methodTotal; 1501 sprintf(buf, "[%d]", relative->index); 1502 if (gOptions.outputHtml) { 1503 int len = strlen(buf); 1504 if (len > num_spaces) 1505 len = num_spaces; 1506 sprintf(buf, "<a href=\"#m%d\">[%d]", 1507 relative->index, relative->index); 1508 space_ptr = &spaces[len]; 1509 className = htmlEscape(className, classBuf, HTML_BUFSIZE); 1510 methodName = htmlEscape(methodName, methodBuf, HTML_BUFSIZE); 1511 signature = htmlEscape(signature, signatureBuf, HTML_BUFSIZE); 1512 } 1513 int nCalls = numCalls; 1514 if (nCalls == 0) 1515 nCalls = relative->numCalls[0] + relative->numCalls[1]; 1516 if (relative->methodName) { 1517 if (flags & kIsRecursive) { 1518 // Don't display percentages for recursive functions 1519 printf("%6s %5s %6s %s%6s%s %6d/%-6d %9llu %s.%s %s\n", 1520 "", "", "", 1521 space_ptr, buf, anchor_close, 1522 pTimed->numCalls, nCalls, 1523 pTimed->elapsedInclusive, 1524 className, methodName, signature); 1525 } else { 1526 printf("%6s %5s %5.1f%% %s%6s%s %6d/%-6d %9llu %s.%s %s\n", 1527 "", "", per, 1528 space_ptr, buf, anchor_close, 1529 pTimed->numCalls, nCalls, 1530 pTimed->elapsedInclusive, 1531 className, methodName, signature); 1532 } 1533 } else { 1534 if (flags & kIsRecursive) { 1535 // Don't display percentages for recursive functions 1536 printf("%6s %5s %6s %s%6s%s %6d/%-6d %9llu %s\n", 1537 "", "", "", 1538 space_ptr, buf, anchor_close, 1539 pTimed->numCalls, nCalls, 1540 pTimed->elapsedInclusive, 1541 className); 1542 } else { 1543 printf("%6s %5s %5.1f%% %s%6s%s %6d/%-6d %9llu %s\n", 1544 "", "", per, 1545 space_ptr, buf, anchor_close, 1546 pTimed->numCalls, nCalls, 1547 pTimed->elapsedInclusive, 1548 className); 1549 } 1550 } 1551 } 1552 } 1553 1554 void countRecursiveEntries(CallStack *pStack, int top, MethodEntry *method) 1555 { 1556 int ii; 1557 1558 method->recursiveEntries = 0; 1559 for (ii = 0; ii < top; ++ii) { 1560 if (pStack->calls[ii].method == method) 1561 method->recursiveEntries += 1; 1562 } 1563 } 1564 1565 void stackDump(CallStack *pStack, int top) 1566 { 1567 int ii; 1568 1569 for (ii = 0; ii < top; ++ii) { 1570 MethodEntry *method = pStack->calls[ii].method; 1571 uint64_t entryTime = pStack->calls[ii].entryTime; 1572 if (method->methodName) { 1573 fprintf(stderr, " %2d: %8llu %s.%s %s\n", ii, entryTime, 1574 method->className, method->methodName, method->signature); 1575 } else { 1576 fprintf(stderr, " %2d: %8llu %s\n", ii, entryTime, method->className); 1577 } 1578 } 1579 } 1580 1581 void outputTableOfContents() 1582 { 1583 printf("<a name=\"contents\"></a>\n"); 1584 printf("<h2>Table of Contents</h2>\n"); 1585 printf("<ul>\n"); 1586 printf(" <li><a href=\"#exclusive\">Exclusive profile</a></li>\n"); 1587 printf(" <li><a href=\"#inclusive\">Inclusive profile</a></li>\n"); 1588 printf(" <li><a href=\"#thread\">Thread profile</a></li>\n"); 1589 printf(" <li><a href=\"#class\">Class/method profile</a></li>\n"); 1590 printf(" <li><a href=\"#method\">Method/class profile</a></li>\n"); 1591 printf("</ul>\n\n"); 1592 } 1593 1594 void outputNavigationBar() 1595 { 1596 printf("<a href=\"#contents\">[Top]</a>\n"); 1597 printf("<a href=\"#exclusive\">[Exclusive]</a>\n"); 1598 printf("<a href=\"#inclusive\">[Inclusive]</a>\n"); 1599 printf("<a href=\"#thread\">[Thread]</a>\n"); 1600 printf("<a href=\"#class\">[Class]</a>\n"); 1601 printf("<a href=\"#method\">[Method]</a>\n"); 1602 printf("<br><br>\n"); 1603 } 1604 1605 void printExclusiveProfile(MethodEntry **pMethods, int numMethods, 1606 uint64_t sumThreadTime) 1607 { 1608 int ii; 1609 MethodEntry* method; 1610 double total, sum, per, sum_per; 1611 char classBuf[HTML_BUFSIZE], methodBuf[HTML_BUFSIZE]; 1612 char signatureBuf[HTML_BUFSIZE]; 1613 char anchor_buf[80]; 1614 char *anchor_close = ""; 1615 1616 total = sumThreadTime; 1617 anchor_buf[0] = 0; 1618 if (gOptions.outputHtml) { 1619 anchor_close = "</a>"; 1620 printf("<a name=\"exclusive\"></a>\n"); 1621 printf("<hr>\n"); 1622 outputNavigationBar(); 1623 } else { 1624 printf("\n%s\n", profileSeparator); 1625 } 1626 1627 /* First, sort the methods into decreasing order of inclusive 1628 * elapsed time so that we can assign the method indices. 1629 */ 1630 qsort(pMethods, numMethods, sizeof(MethodEntry*), compareElapsedInclusive); 1631 1632 for (ii = 0; ii < numMethods; ++ii) 1633 pMethods[ii]->index = ii; 1634 1635 /* Sort the methods into decreasing order of exclusive elapsed time. 1636 */ 1637 qsort(pMethods, numMethods, sizeof(MethodEntry*), 1638 compareElapsedExclusive); 1639 1640 printf("Total cycles: %llu\n\n", sumThreadTime); 1641 if (gOptions.outputHtml) { 1642 printf("<br><br>\n"); 1643 } 1644 printf("Exclusive elapsed times for each method, not including time spent in\n"); 1645 printf("children, sorted by exclusive time.\n\n"); 1646 if (gOptions.outputHtml) { 1647 printf("<br><br>\n<pre>\n"); 1648 } 1649 1650 printf(" Usecs self %% sum %% Method\n"); 1651 sum = 0; 1652 1653 for (ii = 0; ii < numMethods; ++ii) { 1654 char *className, *methodName, *signature; 1655 1656 method = pMethods[ii]; 1657 /* Don't show methods with zero cycles */ 1658 if (method->elapsedExclusive == 0) 1659 break; 1660 className = (char*)(method->className); 1661 methodName = (char*)(method->methodName); 1662 signature = (char*)(method->signature); 1663 sum += method->elapsedExclusive; 1664 per = 100.0 * method->elapsedExclusive / total; 1665 sum_per = 100.0 * sum / total; 1666 if (gOptions.outputHtml) { 1667 sprintf(anchor_buf, "<a href=\"#m%d\">", method->index); 1668 className = htmlEscape(className, classBuf, HTML_BUFSIZE); 1669 methodName = htmlEscape(methodName, methodBuf, HTML_BUFSIZE); 1670 signature = htmlEscape(signature, signatureBuf, HTML_BUFSIZE); 1671 } 1672 if (method->methodName) { 1673 printf("%9llu %6.2f %6.2f %s[%d]%s %s.%s %s\n", 1674 method->elapsedExclusive, per, sum_per, 1675 anchor_buf, method->index, anchor_close, 1676 className, methodName, signature); 1677 } else { 1678 printf("%9llu %6.2f %6.2f %s[%d]%s %s\n", 1679 method->elapsedExclusive, per, sum_per, 1680 anchor_buf, method->index, anchor_close, 1681 className); 1682 } 1683 } 1684 if (gOptions.outputHtml) { 1685 printf("</pre>\n"); 1686 } 1687 } 1688 1689 /* check to make sure that the child method meets the threshold of the parent */ 1690 int checkThreshold(MethodEntry* parent, MethodEntry* child) 1691 { 1692 double parentTime = parent->elapsedInclusive; 1693 double childTime = child->elapsedInclusive; 1694 int64_t percentage = (childTime / parentTime) * 100.0; 1695 return (percentage < gOptions.threshold) ? 0 : 1; 1696 } 1697 1698 void createLabels(FILE* file, MethodEntry* method) 1699 { 1700 fprintf(file, "node%d[label = \"[%d] %s.%s (%llu, %llu, %d)\"]\n", 1701 method->index, method->index, method->className, method->methodName, 1702 method->elapsedInclusive / 1000, 1703 method->elapsedExclusive / 1000, 1704 method->numCalls[0]); 1705 1706 method->graphState = GRAPH_LABEL_VISITED; 1707 1708 TimedMethod* child; 1709 for (child = method->children[0] ; child ; child = child->next) { 1710 MethodEntry* childMethod = child->method; 1711 1712 if ((childMethod->graphState & GRAPH_LABEL_VISITED) == 0 && checkThreshold(method, childMethod)) { 1713 createLabels(file, child->method); 1714 } 1715 } 1716 } 1717 1718 void createLinks(FILE* file, MethodEntry* method) 1719 { 1720 method->graphState |= GRAPH_NODE_VISITED; 1721 1722 TimedMethod* child; 1723 for (child = method->children[0] ; child ; child = child->next) { 1724 MethodEntry* childMethod = child->method; 1725 if (checkThreshold(method, child->method)) { 1726 fprintf(file, "node%d -> node%d\n", method->index, child->method->index); 1727 // only visit children that haven't been visited before 1728 if ((childMethod->graphState & GRAPH_NODE_VISITED) == 0) { 1729 createLinks(file, child->method); 1730 } 1731 } 1732 } 1733 } 1734 1735 void createInclusiveProfileGraphNew(DataKeys* dataKeys) 1736 { 1737 // create a temporary file in /tmp 1738 char path[FILENAME_MAX]; 1739 if (gOptions.keepDotFile) { 1740 snprintf(path, FILENAME_MAX, "%s.dot", gOptions.graphFileName); 1741 } else { 1742 snprintf(path, FILENAME_MAX, "/tmp/dot-%d-%d.dot", (int)time(NULL), rand()); 1743 } 1744 1745 FILE* file = fopen(path, "w+"); 1746 1747 fprintf(file, "digraph g {\nnode [shape = record,height=.1];\n"); 1748 1749 createLabels(file, dataKeys->methods); 1750 createLinks(file, dataKeys->methods); 1751 1752 fprintf(file, "}"); 1753 fclose(file); 1754 1755 // now that we have the dot file generate the image 1756 char command[1024]; 1757 snprintf(command, 1024, "dot -Tpng -o '%s' '%s'", gOptions.graphFileName, path); 1758 1759 system(command); 1760 1761 if (! gOptions.keepDotFile) { 1762 remove(path); 1763 } 1764 } 1765 1766 void printInclusiveProfile(MethodEntry **pMethods, int numMethods, 1767 uint64_t sumThreadTime) 1768 { 1769 int ii; 1770 MethodEntry* method; 1771 double total, sum, per, sum_per; 1772 char classBuf[HTML_BUFSIZE], methodBuf[HTML_BUFSIZE]; 1773 char signatureBuf[HTML_BUFSIZE]; 1774 char anchor_buf[80]; 1775 1776 total = sumThreadTime; 1777 anchor_buf[0] = 0; 1778 if (gOptions.outputHtml) { 1779 printf("<a name=\"inclusive\"></a>\n"); 1780 printf("<hr>\n"); 1781 outputNavigationBar(); 1782 } else { 1783 printf("\n%s\n", profileSeparator); 1784 } 1785 1786 /* Sort the methods into decreasing order of inclusive elapsed time. */ 1787 qsort(pMethods, numMethods, sizeof(MethodEntry*), 1788 compareElapsedInclusive); 1789 1790 printf("\nInclusive elapsed times for each method and its parents and children,\n"); 1791 printf("sorted by inclusive time.\n\n"); 1792 1793 if (gOptions.outputHtml) { 1794 printf("<br><br>\n<pre>\n"); 1795 } 1796 1797 printf("index %%/total %%/self index calls usecs name\n"); 1798 for (ii = 0; ii < numMethods; ++ii) { 1799 int num; 1800 TimedMethod *pTimed; 1801 double excl_per; 1802 char buf[40]; 1803 char *className, *methodName, *signature; 1804 1805 method = pMethods[ii]; 1806 /* Don't show methods with zero cycles */ 1807 if (method->elapsedInclusive == 0) 1808 break; 1809 1810 className = (char*)(method->className); 1811 methodName = (char*)(method->methodName); 1812 signature = (char*)(method->signature); 1813 1814 if (gOptions.outputHtml) { 1815 printf("<a name=\"m%d\"></a>", method->index); 1816 className = htmlEscape(className, classBuf, HTML_BUFSIZE); 1817 methodName = htmlEscape(methodName, methodBuf, HTML_BUFSIZE); 1818 signature = htmlEscape(signature, signatureBuf, HTML_BUFSIZE); 1819 } 1820 printf("----------------------------------------------------\n"); 1821 1822 /* Sort and print the parents */ 1823 int numCalls = method->numCalls[0] + method->numCalls[1]; 1824 printInclusiveMethod(method, method->parents[0], numCalls, 0); 1825 if (method->parents[1]) { 1826 printf(" +++++++++++++++++++++++++\n"); 1827 printInclusiveMethod(method, method->parents[1], numCalls, 1828 kIsRecursive); 1829 } 1830 1831 per = 100.0 * method->elapsedInclusive / total; 1832 sprintf(buf, "[%d]", ii); 1833 if (method->methodName) { 1834 printf("%-6s %5.1f%% %5s %6s %6d+%-6d %9llu %s.%s %s\n", 1835 buf, 1836 per, "", "", method->numCalls[0], method->numCalls[1], 1837 method->elapsedInclusive, 1838 className, methodName, signature); 1839 } else { 1840 printf("%-6s %5.1f%% %5s %6s %6d+%-6d %9llu %s\n", 1841 buf, 1842 per, "", "", method->numCalls[0], method->numCalls[1], 1843 method->elapsedInclusive, 1844 className); 1845 } 1846 excl_per = 100.0 * method->topExclusive / method->elapsedInclusive; 1847 printf("%6s %5s %5.1f%% %6s %6s %6s %9llu\n", 1848 "", "", excl_per, "excl", "", "", method->topExclusive); 1849 1850 /* Sort and print the children */ 1851 printInclusiveMethod(method, method->children[0], 0, 0); 1852 if (method->children[1]) { 1853 printf(" +++++++++++++++++++++++++\n"); 1854 printInclusiveMethod(method, method->children[1], 0, 1855 kIsRecursive); 1856 } 1857 } 1858 if (gOptions.outputHtml) { 1859 printf("</pre>\n"); 1860 } 1861 } 1862 1863 void printThreadProfile(ThreadEntry *pThreads, int numThreads, uint64_t sumThreadTime, Filter** filters) 1864 { 1865 int ii, jj; 1866 ThreadEntry thread; 1867 double total, per, sum_per; 1868 uint64_t sum; 1869 char threadBuf[HTML_BUFSIZE]; 1870 char anchor_buf[80]; 1871 int drawTable; 1872 1873 total = sumThreadTime; 1874 anchor_buf[0] = 0; 1875 if (gOptions.outputHtml) { 1876 printf("<a name=\"thread\"></a>\n"); 1877 printf("<hr>\n"); 1878 outputNavigationBar(); 1879 } else { 1880 printf("\n%s\n", profileSeparator); 1881 } 1882 1883 /* Sort the threads into decreasing order of elapsed time. */ 1884 qsort(pThreads, numThreads, sizeof(ThreadEntry), compareElapsed); 1885 1886 printf("\nElapsed times for each thread, sorted by elapsed time.\n"); 1887 printf("Also includes percentage of time spent during the <i>execution</i> of any filters.\n\n"); 1888 1889 if (gOptions.outputHtml) { 1890 printf("<br><br>\n<pre>\n"); 1891 } 1892 1893 printf(" Usecs self %% sum %%"); 1894 for (ii = 0; ii < numFilters; ++ii) { 1895 printf(" %s %%", filters[ii]->filterName); 1896 } 1897 printf(" tid ThreadName\n"); 1898 sum = 0; 1899 1900 for (ii = 0; ii < numThreads; ++ii) { 1901 int threadId; 1902 char *threadName; 1903 uint64_t time; 1904 1905 thread = pThreads[ii]; 1906 1907 threadId = thread.threadId; 1908 threadName = (char*)(thread.threadName); 1909 time = thread.elapsedTime; 1910 1911 sum += time; 1912 per = 100.0 * time / total; 1913 sum_per = 100.0 * sum / total; 1914 1915 if (gOptions.outputHtml) { 1916 threadName = htmlEscape(threadName, threadBuf, HTML_BUFSIZE); 1917 } 1918 1919 printf("%9llu %6.2f %6.2f", time, per, sum_per); 1920 for (jj = 0; jj < numFilters; jj++) { 1921 printf(" %6.2f", 100.0 * filters[jj]->times.threadExecutionTimes[threadId] / time); 1922 } 1923 printf(" %3d %s\n", threadId, threadName); 1924 } 1925 1926 if (gOptions.outputHtml) 1927 printf("</pre><br />"); 1928 1929 printf("\n\nBreak-down of portion of time spent by each thread while waiting on a filter method.\n"); 1930 1931 for (ii = 0; ii < numFilters; ++ii) { 1932 // Draw a table for each filter that measures wait time 1933 drawTable = 0; 1934 for (jj = 0; jj < filters[ii]->numKeys; jj++) 1935 if (filters[ii]->filterKeys[jj].flags == 1) 1936 drawTable = 1; 1937 1938 if (drawTable) { 1939 1940 if (gOptions.outputHtml) 1941 printf("<br/><br/>\n<pre>\n"); 1942 printf("Filter: %s\n", filters[ii]->filterName); 1943 printf("Total waiting cycles: %llu (%6.2f%% of total)\n", 1944 filters[ii]->times.totalWaitTime, 1945 100.0 * filters[ii]->times.totalWaitTime / sum); 1946 1947 if (filters[ii]->times.totalWaitTime > 0) { 1948 1949 printf("Details: \n\n"); 1950 1951 printf(" Waiting cycles %% of total waiting time execution time while waiting thread name\n"); 1952 1953 for (jj = 0; jj < numThreads; jj++) { 1954 1955 thread = pThreads[jj]; 1956 1957 char *threadName; 1958 threadName = (char*) thread.threadName; 1959 if (gOptions.outputHtml) { 1960 threadName = htmlEscape(threadName, threadBuf, HTML_BUFSIZE); 1961 } 1962 1963 printf(" %9llu %6.2f %6.2f %s\n", 1964 filters[ii]->times.threadWaitTimes[thread.threadId], 1965 100.0 * filters[ii]->times.threadWaitTimes[thread.threadId] / filters[ii]->times.totalWaitTime, 1966 100.0 * filters[ii]->times.threadExecutionTimesWhileWaiting[thread.threadId] / filters[ii]->times.totalWaitTime, 1967 threadName); 1968 } 1969 } 1970 1971 if (gOptions.outputHtml) 1972 printf("</pre>\n"); 1973 1974 } 1975 } 1976 1977 } 1978 1979 void createClassList(TraceData* traceData, MethodEntry **pMethods, int numMethods) 1980 { 1981 int ii; 1982 1983 /* Sort the methods into alphabetical order to find the unique class 1984 * names. 1985 */ 1986 qsort(pMethods, numMethods, sizeof(MethodEntry*), compareClassNames); 1987 1988 /* Count the number of unique class names. */ 1989 const char *currentClassName = ""; 1990 const char *firstClassName = NULL; 1991 traceData->numClasses = 0; 1992 for (ii = 0; ii < numMethods; ++ii) { 1993 if (pMethods[ii]->methodName == NULL) { 1994 continue; 1995 } 1996 if (strcmp(pMethods[ii]->className, currentClassName) != 0) { 1997 // Remember the first one 1998 if (firstClassName == NULL) { 1999 firstClassName = pMethods[ii]->className; 2000 } 2001 traceData->numClasses += 1; 2002 currentClassName = pMethods[ii]->className; 2003 } 2004 } 2005 2006 if (traceData->numClasses == 0) { 2007 traceData->classes = NULL; 2008 return; 2009 } 2010 2011 /* Allocate space for all of the unique class names */ 2012 traceData->classes = (ClassEntry *) malloc(sizeof(ClassEntry) * traceData->numClasses); 2013 2014 /* Initialize the classes array */ 2015 memset(traceData->classes, 0, sizeof(ClassEntry) * traceData->numClasses); 2016 ClassEntry *pClass = traceData->classes; 2017 pClass->className = currentClassName = firstClassName; 2018 int prevNumMethods = 0; 2019 for (ii = 0; ii < numMethods; ++ii) { 2020 if (pMethods[ii]->methodName == NULL) { 2021 continue; 2022 } 2023 if (strcmp(pMethods[ii]->className, currentClassName) != 0) { 2024 pClass->numMethods = prevNumMethods; 2025 (++pClass)->className = currentClassName = pMethods[ii]->className; 2026 prevNumMethods = 0; 2027 } 2028 prevNumMethods += 1; 2029 } 2030 pClass->numMethods = prevNumMethods; 2031 2032 /* Create the array of MethodEntry pointers for each class */ 2033 pClass = NULL; 2034 currentClassName = ""; 2035 int nextMethod = 0; 2036 for (ii = 0; ii < numMethods; ++ii) { 2037 if (pMethods[ii]->methodName == NULL) { 2038 continue; 2039 } 2040 if (strcmp(pMethods[ii]->className, currentClassName) != 0) { 2041 currentClassName = pMethods[ii]->className; 2042 if (pClass == NULL) 2043 pClass = traceData->classes; 2044 else 2045 pClass++; 2046 /* Allocate space for the methods array */ 2047 int nbytes = sizeof(MethodEntry*) * pClass->numMethods; 2048 pClass->methods = (MethodEntry**) malloc(nbytes); 2049 nextMethod = 0; 2050 } 2051 pClass->methods[nextMethod++] = pMethods[ii]; 2052 } 2053 } 2054 2055 /* Prints a number of html non-breaking spaces according so that the length 2056 * of the string "buf" is at least "width" characters wide. If width is 2057 * negative, then trailing spaces are added instead of leading spaces. 2058 */ 2059 void printHtmlField(char *buf, int width) 2060 { 2061 int ii; 2062 2063 int leadingSpaces = 1; 2064 if (width < 0) { 2065 width = -width; 2066 leadingSpaces = 0; 2067 } 2068 int len = strlen(buf); 2069 int numSpaces = width - len; 2070 if (numSpaces <= 0) { 2071 printf("%s", buf); 2072 return; 2073 } 2074 if (leadingSpaces == 0) 2075 printf("%s", buf); 2076 for (ii = 0; ii < numSpaces; ++ii) 2077 printf(" "); 2078 if (leadingSpaces == 1) 2079 printf("%s", buf); 2080 } 2081 2082 void printClassProfiles(TraceData* traceData, uint64_t sumThreadTime) 2083 { 2084 int ii, jj; 2085 MethodEntry* method; 2086 double total, sum, per, sum_per; 2087 char classBuf[HTML_BUFSIZE], methodBuf[HTML_BUFSIZE]; 2088 char signatureBuf[HTML_BUFSIZE]; 2089 2090 total = sumThreadTime; 2091 if (gOptions.outputHtml) { 2092 printf("<a name=\"class\"></a>\n"); 2093 printf("<hr>\n"); 2094 outputNavigationBar(); 2095 } else { 2096 printf("\n%s\n", profileSeparator); 2097 } 2098 2099 if (traceData->numClasses == 0) { 2100 printf("\nNo classes.\n"); 2101 if (gOptions.outputHtml) { 2102 printf("<br><br>\n"); 2103 } 2104 return; 2105 } 2106 2107 printf("\nExclusive elapsed time for each class, summed over all the methods\n"); 2108 printf("in the class.\n\n"); 2109 if (gOptions.outputHtml) { 2110 printf("<br><br>\n"); 2111 } 2112 2113 /* For each class, sum the exclusive times in all of the methods 2114 * in that class. Also sum the number of method calls. Also 2115 * sort the methods so the most expensive appear at the top. 2116 */ 2117 ClassEntry *pClass = traceData->classes; 2118 for (ii = 0; ii < traceData->numClasses; ++ii, ++pClass) { 2119 //printf("%s %d methods\n", pClass->className, pClass->numMethods); 2120 int numMethods = pClass->numMethods; 2121 for (jj = 0; jj < numMethods; ++jj) { 2122 method = pClass->methods[jj]; 2123 pClass->elapsedExclusive += method->elapsedExclusive; 2124 pClass->numCalls[0] += method->numCalls[0]; 2125 pClass->numCalls[1] += method->numCalls[1]; 2126 } 2127 2128 /* Sort the methods into decreasing order of exclusive time */ 2129 qsort(pClass->methods, numMethods, sizeof(MethodEntry*), 2130 compareElapsedExclusive); 2131 } 2132 2133 /* Allocate an array of pointers to the classes for more efficient 2134 * sorting. 2135 */ 2136 ClassEntry **pClasses; 2137 pClasses = (ClassEntry**) malloc(sizeof(ClassEntry*) * traceData->numClasses); 2138 for (ii = 0; ii < traceData->numClasses; ++ii) 2139 pClasses[ii] = &traceData->classes[ii]; 2140 2141 /* Sort the classes into decreasing order of exclusive time */ 2142 qsort(pClasses, traceData->numClasses, sizeof(ClassEntry*), compareClassExclusive); 2143 2144 if (gOptions.outputHtml) { 2145 printf("<div class=\"header\"><span class=\"parent\"> </span> "); 2146 printf("Cycles %%/total Cumul.%% Calls+Recur Class</div>\n"); 2147 } else { 2148 printf(" Cycles %%/total Cumul.%% Calls+Recur Class\n"); 2149 } 2150 2151 sum = 0; 2152 for (ii = 0; ii < traceData->numClasses; ++ii) { 2153 char *className, *methodName, *signature; 2154 2155 /* Skip classes with zero cycles */ 2156 pClass = pClasses[ii]; 2157 if (pClass->elapsedExclusive == 0) 2158 break; 2159 2160 per = 100.0 * pClass->elapsedExclusive / total; 2161 sum += pClass->elapsedExclusive; 2162 sum_per = 100.0 * sum / total; 2163 className = (char*)(pClass->className); 2164 if (gOptions.outputHtml) { 2165 char buf[80]; 2166 2167 className = htmlEscape(className, classBuf, HTML_BUFSIZE); 2168 printf("<div class=\"link\" onClick=\"javascript:toggle('d%d')\" onMouseOver=\"javascript:onMouseOver(this)\" onMouseOut=\"javascript:onMouseOut(this)\"><span class=\"parent\" id=\"xd%d\">+</span>", ii, ii); 2169 sprintf(buf, "%llu", pClass->elapsedExclusive); 2170 printHtmlField(buf, 9); 2171 printf(" "); 2172 sprintf(buf, "%.1f", per); 2173 printHtmlField(buf, 7); 2174 printf(" "); 2175 sprintf(buf, "%.1f", sum_per); 2176 printHtmlField(buf, 7); 2177 printf(" "); 2178 sprintf(buf, "%d", pClass->numCalls[0]); 2179 printHtmlField(buf, 6); 2180 printf("+"); 2181 sprintf(buf, "%d", pClass->numCalls[1]); 2182 printHtmlField(buf, -6); 2183 printf(" "); 2184 printf("%s", className); 2185 printf("</div>\n"); 2186 printf("<div class=\"parent\" id=\"d%d\">\n", ii); 2187 } else { 2188 printf("---------------------------------------------\n"); 2189 printf("%9llu %7.1f %7.1f %6d+%-6d %s\n", 2190 pClass->elapsedExclusive, per, sum_per, 2191 pClass->numCalls[0], pClass->numCalls[1], 2192 className); 2193 } 2194 2195 int numMethods = pClass->numMethods; 2196 double classExclusive = pClass->elapsedExclusive; 2197 double sumMethods = 0; 2198 for (jj = 0; jj < numMethods; ++jj) { 2199 method = pClass->methods[jj]; 2200 methodName = (char*)(method->methodName); 2201 signature = (char*)(method->signature); 2202 per = 100.0 * method->elapsedExclusive / classExclusive; 2203 sumMethods += method->elapsedExclusive; 2204 sum_per = 100.0 * sumMethods / classExclusive; 2205 if (gOptions.outputHtml) { 2206 char buf[80]; 2207 2208 methodName = htmlEscape(methodName, methodBuf, HTML_BUFSIZE); 2209 signature = htmlEscape(signature, signatureBuf, HTML_BUFSIZE); 2210 printf("<div class=\"leaf\"><span class=\"leaf\"> </span>"); 2211 sprintf(buf, "%llu", method->elapsedExclusive); 2212 printHtmlField(buf, 9); 2213 printf(" "); 2214 sprintf(buf, "%llu", method->elapsedInclusive); 2215 printHtmlField(buf, 9); 2216 printf(" "); 2217 sprintf(buf, "%.1f", per); 2218 printHtmlField(buf, 7); 2219 printf(" "); 2220 sprintf(buf, "%.1f", sum_per); 2221 printHtmlField(buf, 7); 2222 printf(" "); 2223 sprintf(buf, "%d", method->numCalls[0]); 2224 printHtmlField(buf, 6); 2225 printf("+"); 2226 sprintf(buf, "%d", method->numCalls[1]); 2227 printHtmlField(buf, -6); 2228 printf(" "); 2229 printf("<a href=\"#m%d\">[%d]</a> %s %s", 2230 method->index, method->index, methodName, signature); 2231 printf("</div>\n"); 2232 } else { 2233 printf("%9llu %9llu %7.1f %7.1f %6d+%-6d [%d] %s %s\n", 2234 method->elapsedExclusive, 2235 method->elapsedInclusive, 2236 per, sum_per, 2237 method->numCalls[0], method->numCalls[1], 2238 method->index, methodName, signature); 2239 } 2240 } 2241 if (gOptions.outputHtml) { 2242 printf("</div>\n"); 2243 } 2244 } 2245 } 2246 2247 void createUniqueMethodList(TraceData* traceData, MethodEntry **pMethods, int numMethods) 2248 { 2249 int ii; 2250 2251 /* Sort the methods into alphabetical order of method names 2252 * to find the unique method names. 2253 */ 2254 qsort(pMethods, numMethods, sizeof(MethodEntry*), compareMethodNames); 2255 2256 /* Count the number of unique method names, ignoring class and 2257 * signature. 2258 */ 2259 const char *currentMethodName = ""; 2260 traceData->numUniqueMethods = 0; 2261 for (ii = 0; ii < numMethods; ++ii) { 2262 if (pMethods[ii]->methodName == NULL) 2263 continue; 2264 if (strcmp(pMethods[ii]->methodName, currentMethodName) != 0) { 2265 traceData->numUniqueMethods += 1; 2266 currentMethodName = pMethods[ii]->methodName; 2267 } 2268 } 2269 if (traceData->numUniqueMethods == 0) 2270 return; 2271 2272 /* Allocate space for pointers to all of the unique methods */ 2273 int nbytes = sizeof(UniqueMethodEntry) * traceData->numUniqueMethods; 2274 traceData->uniqueMethods = (UniqueMethodEntry *) malloc(nbytes); 2275 2276 /* Initialize the uniqueMethods array */ 2277 memset(traceData->uniqueMethods, 0, nbytes); 2278 UniqueMethodEntry *pUnique = traceData->uniqueMethods; 2279 currentMethodName = NULL; 2280 int prevNumMethods = 0; 2281 for (ii = 0; ii < numMethods; ++ii) { 2282 if (pMethods[ii]->methodName == NULL) 2283 continue; 2284 if (currentMethodName == NULL) 2285 currentMethodName = pMethods[ii]->methodName; 2286 if (strcmp(pMethods[ii]->methodName, currentMethodName) != 0) { 2287 currentMethodName = pMethods[ii]->methodName; 2288 pUnique->numMethods = prevNumMethods; 2289 pUnique++; 2290 prevNumMethods = 0; 2291 } 2292 prevNumMethods += 1; 2293 } 2294 pUnique->numMethods = prevNumMethods; 2295 2296 /* Create the array of MethodEntry pointers for each unique method */ 2297 pUnique = NULL; 2298 currentMethodName = ""; 2299 int nextMethod = 0; 2300 for (ii = 0; ii < numMethods; ++ii) { 2301 if (pMethods[ii]->methodName == NULL) 2302 continue; 2303 if (strcmp(pMethods[ii]->methodName, currentMethodName) != 0) { 2304 currentMethodName = pMethods[ii]->methodName; 2305 if (pUnique == NULL) 2306 pUnique = traceData->uniqueMethods; 2307 else 2308 pUnique++; 2309 /* Allocate space for the methods array */ 2310 int nbytes = sizeof(MethodEntry*) * pUnique->numMethods; 2311 pUnique->methods = (MethodEntry**) malloc(nbytes); 2312 nextMethod = 0; 2313 } 2314 pUnique->methods[nextMethod++] = pMethods[ii]; 2315 } 2316 } 2317 2318 void printMethodProfiles(TraceData* traceData, uint64_t sumThreadTime) 2319 { 2320 int ii, jj; 2321 MethodEntry* method; 2322 double total, sum, per, sum_per; 2323 char classBuf[HTML_BUFSIZE], methodBuf[HTML_BUFSIZE]; 2324 char signatureBuf[HTML_BUFSIZE]; 2325 2326 if (traceData->numUniqueMethods == 0) 2327 return; 2328 2329 total = sumThreadTime; 2330 if (gOptions.outputHtml) { 2331 printf("<a name=\"method\"></a>\n"); 2332 printf("<hr>\n"); 2333 outputNavigationBar(); 2334 } else { 2335 printf("\n%s\n", profileSeparator); 2336 } 2337 2338 printf("\nExclusive elapsed time for each method, summed over all the classes\n"); 2339 printf("that contain a method with the same name.\n\n"); 2340 if (gOptions.outputHtml) { 2341 printf("<br><br>\n"); 2342 } 2343 2344 /* For each unique method, sum the exclusive times in all of the methods 2345 * with the same name. Also sum the number of method calls. Also 2346 * sort the methods so the most expensive appear at the top. 2347 */ 2348 UniqueMethodEntry *pUnique = traceData->uniqueMethods; 2349 for (ii = 0; ii < traceData->numUniqueMethods; ++ii, ++pUnique) { 2350 int numMethods = pUnique->numMethods; 2351 for (jj = 0; jj < numMethods; ++jj) { 2352 method = pUnique->methods[jj]; 2353 pUnique->elapsedExclusive += method->elapsedExclusive; 2354 pUnique->numCalls[0] += method->numCalls[0]; 2355 pUnique->numCalls[1] += method->numCalls[1]; 2356 } 2357 2358 /* Sort the methods into decreasing order of exclusive time */ 2359 qsort(pUnique->methods, numMethods, sizeof(MethodEntry*), 2360 compareElapsedExclusive); 2361 } 2362 2363 /* Allocate an array of pointers to the methods for more efficient 2364 * sorting. 2365 */ 2366 UniqueMethodEntry **pUniqueMethods; 2367 int nbytes = sizeof(UniqueMethodEntry*) * traceData->numUniqueMethods; 2368 pUniqueMethods = (UniqueMethodEntry**) malloc(nbytes); 2369 for (ii = 0; ii < traceData->numUniqueMethods; ++ii) 2370 pUniqueMethods[ii] = &traceData->uniqueMethods[ii]; 2371 2372 /* Sort the methods into decreasing order of exclusive time */ 2373 qsort(pUniqueMethods, traceData->numUniqueMethods, sizeof(UniqueMethodEntry*), 2374 compareUniqueExclusive); 2375 2376 if (gOptions.outputHtml) { 2377 printf("<div class=\"header\"><span class=\"parent\"> </span> "); 2378 printf("Cycles %%/total Cumul.%% Calls+Recur Method</div>\n"); 2379 } else { 2380 printf(" Cycles %%/total Cumul.%% Calls+Recur Method\n"); 2381 } 2382 2383 sum = 0; 2384 for (ii = 0; ii < traceData->numUniqueMethods; ++ii) { 2385 char *className, *methodName, *signature; 2386 2387 /* Skip methods with zero cycles */ 2388 pUnique = pUniqueMethods[ii]; 2389 if (pUnique->elapsedExclusive == 0) 2390 break; 2391 2392 per = 100.0 * pUnique->elapsedExclusive / total; 2393 sum += pUnique->elapsedExclusive; 2394 sum_per = 100.0 * sum / total; 2395 methodName = (char*)(pUnique->methods[0]->methodName); 2396 if (gOptions.outputHtml) { 2397 char buf[80]; 2398 2399 methodName = htmlEscape(methodName, methodBuf, HTML_BUFSIZE); 2400 printf("<div class=\"link\" onClick=\"javascript:toggle('e%d')\" onMouseOver=\"javascript:onMouseOver(this)\" onMouseOut=\"javascript:onMouseOut(this)\"><span class=\"parent\" id=\"xe%d\">+</span>", ii, ii); 2401 sprintf(buf, "%llu", pUnique->elapsedExclusive); 2402 printHtmlField(buf, 9); 2403 printf(" "); 2404 sprintf(buf, "%.1f", per); 2405 printHtmlField(buf, 7); 2406 printf(" "); 2407 sprintf(buf, "%.1f", sum_per); 2408 printHtmlField(buf, 7); 2409 printf(" "); 2410 sprintf(buf, "%d", pUnique->numCalls[0]); 2411 printHtmlField(buf, 6); 2412 printf("+"); 2413 sprintf(buf, "%d", pUnique->numCalls[1]); 2414 printHtmlField(buf, -6); 2415 printf(" "); 2416 printf("%s", methodName); 2417 printf("</div>\n"); 2418 printf("<div class=\"parent\" id=\"e%d\">\n", ii); 2419 } else { 2420 printf("---------------------------------------------\n"); 2421 printf("%9llu %7.1f %7.1f %6d+%-6d %s\n", 2422 pUnique->elapsedExclusive, per, sum_per, 2423 pUnique->numCalls[0], pUnique->numCalls[1], 2424 methodName); 2425 } 2426 int numMethods = pUnique->numMethods; 2427 double methodExclusive = pUnique->elapsedExclusive; 2428 double sumMethods = 0; 2429 for (jj = 0; jj < numMethods; ++jj) { 2430 method = pUnique->methods[jj]; 2431 className = (char*)(method->className); 2432 signature = (char*)(method->signature); 2433 per = 100.0 * method->elapsedExclusive / methodExclusive; 2434 sumMethods += method->elapsedExclusive; 2435 sum_per = 100.0 * sumMethods / methodExclusive; 2436 if (gOptions.outputHtml) { 2437 char buf[80]; 2438 2439 className = htmlEscape(className, classBuf, HTML_BUFSIZE); 2440 signature = htmlEscape(signature, signatureBuf, HTML_BUFSIZE); 2441 printf("<div class=\"leaf\"><span class=\"leaf\"> </span>"); 2442 sprintf(buf, "%llu", method->elapsedExclusive); 2443 printHtmlField(buf, 9); 2444 printf(" "); 2445 sprintf(buf, "%llu", method->elapsedInclusive); 2446 printHtmlField(buf, 9); 2447 printf(" "); 2448 sprintf(buf, "%.1f", per); 2449 printHtmlField(buf, 7); 2450 printf(" "); 2451 sprintf(buf, "%.1f", sum_per); 2452 printHtmlField(buf, 7); 2453 printf(" "); 2454 sprintf(buf, "%d", method->numCalls[0]); 2455 printHtmlField(buf, 6); 2456 printf("+"); 2457 sprintf(buf, "%d", method->numCalls[1]); 2458 printHtmlField(buf, -6); 2459 printf(" "); 2460 printf("<a href=\"#m%d\">[%d]</a> %s.%s %s", 2461 method->index, method->index, 2462 className, methodName, signature); 2463 printf("</div>\n"); 2464 } else { 2465 printf("%9llu %9llu %7.1f %7.1f %6d+%-6d [%d] %s.%s %s\n", 2466 method->elapsedExclusive, 2467 method->elapsedInclusive, 2468 per, sum_per, 2469 method->numCalls[0], method->numCalls[1], 2470 method->index, className, methodName, signature); 2471 } 2472 } 2473 if (gOptions.outputHtml) { 2474 printf("</div>\n"); 2475 } 2476 } 2477 } 2478 2479 /* 2480 * Determines whether the given FilterKey matches the method. The FilterKey's 2481 * key that is used to match against the method is determined by index. 2482 */ 2483 int keyMatchesMethod(FilterKey filterKey, MethodEntry* method, int index) 2484 { 2485 if (filterKey.type[index] == 0) { // Class 2486 #if 0 2487 fprintf(stderr, " class is %s; filter key is %s\n", method->className, filterKey.keys[index]); 2488 #endif 2489 if (strcmp(method->className, filterKey.keys[index]) == 0) { 2490 return 1; 2491 } 2492 } else { // Method 2493 if (method->methodName != NULL) { 2494 // Get fully-qualified name 2495 // TODO: parse class name and method name an put them in structure to avoid 2496 // allocating memory here 2497 char* str = malloc ((strlen(method->className) + strlen(method->methodName) + 2) * sizeof(char)); 2498 strcpy(str, method->className); 2499 strcat(str, "."); 2500 strcat(str, method->methodName); 2501 #if 0 2502 fprintf(stderr, " method is %s; filter key is %s\n", str, filterKey.keys[index]); 2503 #endif 2504 if (strcmp(str, filterKey.keys[index]) == 0) { 2505 free(str); 2506 return 1; 2507 } 2508 free(str); 2509 } 2510 } 2511 return 0; 2512 } 2513 2514 /* 2515 * Adds the appropriate times to the given filter based on the given method. Activates and 2516 * de-activates filters as necessary. 2517 * 2518 * A filter is activated when the given method matches the 'entry' key of one of its FilterKeys. 2519 * It is de-activated when the method matches the 'exit' key of the same FilterKey that activated it 2520 * in the first place. Thus, a filter may be active more than once on the same thread (activated by 2521 * different FilterKeys). A filter may also be active on different threads at the same time. 2522 * 2523 * While the filter is active on thread 1, elapsed time is allocated to different buckets which 2524 * include: thread execution time (i.e., time thread 1 spent executing while filter was active), 2525 * thread waiting time (i.e., time thread 1 waited while other threads executed), and execution 2526 * time while waiting (i.e., time thread x spent executing while thread 1 was waiting). We also 2527 * keep track of the total waiting time for a given filter. 2528 * 2529 * Lastly, we keep track of remaining (un-allocated) time for cases in which we exit a method we 2530 * had not entered before, and that method happens to match the 'exit' key of a FilterKey. 2531 */ 2532 int filterMethod(MethodEntry* method, Filter* filter, int entry, int threadId, int numThreads, 2533 uint64_t elapsed, uint64_t remTime) 2534 { 2535 int ii, jj; 2536 int activeCount, addedWaitTimeThreadsCount; 2537 int* activeThreads; 2538 int* activationKeys; 2539 int* addedWaitTimeThreads; 2540 2541 // flags 2542 int addWaitTime = 0; 2543 int deactivation = 0; 2544 int addedExecutionTime = 0; 2545 int addedExecutionTimeWhileWaiting = 0; 2546 int addedWaitTime; 2547 int addedRemTime = 0; 2548 int threadKeyPairActive = 0; 2549 2550 if (filter->times.threadWaitTimes == NULL && filter->times.threadExecutionTimes == NULL && 2551 filter->times.threadExecutionTimesWhileWaiting == NULL) { 2552 filter->times.threadWaitTimes = (uint64_t*) calloc(MAX_THREADS, sizeof(uint64_t)); 2553 filter->times.threadExecutionTimesWhileWaiting = 2554 (uint64_t*) calloc(MAX_THREADS, sizeof(uint64_t)); 2555 filter->times.threadExecutionTimes = (uint64_t*) calloc(MAX_THREADS, sizeof(uint64_t)); 2556 } 2557 2558 int verbose = 0; 2559 2560 if (verbose) 2561 fprintf(stderr, 2562 "Running %s filter for class %s method %s, thread %d; activeCount: %d time: %llu\n", 2563 filter->filterName, method->className, method->methodName, threadId, 2564 filter->activeCount, elapsed); 2565 2566 // If active on some thread 2567 if (filter->activeCount > 0) { 2568 2569 // Initialize active structures in case there are any de-activations 2570 activeThreads = (int*) calloc(filter->activeCount, sizeof(int)); 2571 activationKeys = (int*) calloc(filter->activeCount, sizeof(int)); 2572 activeCount = 0; 2573 2574 // Initialize structure to help us determine which threads we've already added wait time to 2575 addedWaitTimeThreads = (int*) calloc(filter->activeCount, sizeof(int)); 2576 addedWaitTimeThreadsCount = 0; 2577 2578 // Add times to appropriate sums and de-activate (if necessary) 2579 for (ii = 0; ii < filter->activeCount; ii++) { 2580 2581 if (verbose) { 2582 fprintf(stderr, " Analyzing active thread with id %d, activated by key [%s, %s]\n", 2583 filter->activeThreads[ii], 2584 filter->filterKeys[filter->activationKeys[ii]].keys[0], 2585 filter->filterKeys[filter->activationKeys[ii]].keys[1]); 2586 } 2587 2588 // If active on THIS thread -> add to execution time (only add once!) 2589 if (filter->activeThreads[ii] == threadId && !addedExecutionTime) { 2590 if (verbose) 2591 fprintf(stderr, " Adding execution time to this thead\n"); 2592 filter->times.threadExecutionTimes[threadId] += elapsed; 2593 addedExecutionTime = 1; 2594 } 2595 2596 // If active on ANOTHER thread (or this one too) with CROSS_THREAD_FLAG -> add to 2597 // both thread's waiting time + total 2598 if (filter->filterKeys[filter->activationKeys[ii]].flags == 1) { 2599 2600 // Add time to thread that is waiting (add to each waiting thread at most once!) 2601 addedWaitTime = 0; 2602 for (jj = 0; jj < addedWaitTimeThreadsCount; jj++) { 2603 if (addedWaitTimeThreads[jj] == filter->activeThreads[ii]) 2604 addedWaitTime = 1; 2605 } 2606 if (!addedWaitTime) { 2607 if (verbose) 2608 fprintf(stderr, " Adding wait time to waiting thread\n"); 2609 filter->times.threadWaitTimes[filter->activeThreads[ii]] += elapsed; 2610 addedWaitTimeThreads[addedWaitTimeThreadsCount++] = filter->activeThreads[ii]; 2611 } 2612 2613 // Add execution time to this thread while the other is waiting (only add once!) 2614 // [Flag is needed only because outside for loop might iterate through same 2615 // thread twice?] TODO: verify 2616 if (!addedExecutionTimeWhileWaiting) { 2617 if (verbose) 2618 fprintf(stderr, " Adding exec time to this thread while thread waits\n"); 2619 filter->times.threadExecutionTimesWhileWaiting[threadId] += elapsed; 2620 addedExecutionTimeWhileWaiting = 1; 2621 } 2622 2623 addWaitTime = 1; 2624 } 2625 2626 // If a method exit matches the EXIT method of an ACTIVE key -> de-activate 2627 // the KEY (not the entire filter!!) 2628 if (!entry && keyMatchesMethod(filter->filterKeys[filter->activationKeys[ii]], 2629 method, 1)) { 2630 if (verbose) 2631 fprintf(stderr, " Exit key matched!\n"); 2632 2633 // Deactivate by removing (NOT adding) entries from activeThreads and activationKeys 2634 deactivation = 1; // singal that lists should be replaced 2635 } else { 2636 // No de-activation -> copy old entries into new lists 2637 activeThreads[activeCount] = filter->activeThreads[ii]; 2638 activationKeys[activeCount++] = filter->activationKeys[ii]; 2639 } 2640 } 2641 2642 // If waiting on ANY thread, add wait time to total (but only ONCE!) 2643 if (addWaitTime) { 2644 filter->times.totalWaitTime += elapsed; 2645 } 2646 2647 // If de-activation occurred, replace lists 2648 if (deactivation) { 2649 // TODO: Free memory from old lists 2650 2651 // Set new lists 2652 filter->activeThreads = activeThreads; 2653 filter->activationKeys = activationKeys; 2654 filter->activeCount = activeCount; 2655 } else { 2656 // TODO: Free memory from new lists 2657 } 2658 2659 } // Else, continue (we might be activating the filter on a different thread) 2660 2661 2662 if (entry) { // ENTRY 2663 if (verbose) 2664 fprintf(stderr, " Here at the entry\n"); 2665 // If method matches entry key -> activate thread (do not add time since it's a new entry!) 2666 for (ii = 0; ii < filter->numKeys; ii++) { 2667 if (keyMatchesMethod(filter->filterKeys[ii], method, 0)) { 2668 if (verbose) 2669 fprintf(stderr, " Entry key matched!\n"); 2670 // Activate thread only if thread/key pair is not already active 2671 for (jj = 0; jj < filter->activeCount; jj++) { 2672 if (filter->activeThreads[jj] == threadId && filter->activationKeys[jj] == ii) 2673 threadKeyPairActive = 1; 2674 } 2675 // TODO: WORRY ABOUT MEMORY WHEN ACTIVE_COUNT > DEFAULT_ACTIVE_THREAD (unlikely) 2676 // TODO: what if the same thread is active multiple times by different keys? 2677 // nothing, we just have to make sure we dont double-add, and we dont.. 2678 if (!threadKeyPairActive) { 2679 filter->activeThreads[filter->activeCount] = threadId; 2680 filter->activationKeys[filter->activeCount++] = ii; 2681 } 2682 } 2683 } 2684 } else { // EXIT 2685 // If method matches a terminal key -> add remTime to total (no need to active/de-activate) 2686 for (ii = 0; ii < filter->numKeys; ii++) { 2687 if (!deactivation && keyMatchesMethod(filter->filterKeys[ii], method, 1) && 2688 keyMatchesMethod(filter->filterKeys[ii], method, 0)) { 2689 // Add remTime(s) 2690 // TODO: think about how we should add remTimes.. should we add remTime to threads 2691 // that were waiting or being waited on? for now, keep it simple and just add the 2692 // execution time to the current thread. 2693 filter->times.threadExecutionTimes[threadId] += remTime; 2694 addedRemTime = 1; 2695 } 2696 } 2697 } 2698 2699 return addedExecutionTime | (addedRemTime << 1); 2700 } 2701 2702 void dumpFilters(Filter** filters) { 2703 int i; 2704 for (i = 0; i < numFilters; i++) { 2705 int j; 2706 fprintf(stderr, "FILTER %s\n", filters[i]->filterName); 2707 for (j = 0; j < filters[i]->numKeys; j++) { 2708 fprintf(stderr, "Keys: %s, type %d", filters[i]->filterKeys[j].keys[0], 2709 filters[i]->filterKeys[j].type[0]); 2710 if (filters[i]->filterKeys[j].keys[1] != NULL) { 2711 fprintf(stderr, " AND %s, type %d", filters[i]->filterKeys[j].keys[1], 2712 filters[i]->filterKeys[j].type[1]); 2713 } 2714 fprintf(stderr, "; flags: %d\n", filters[i]->filterKeys[j].flags); 2715 } 2716 } 2717 } 2718 2719 /* 2720 * See parseFilters for required data format. 2721 * 'data' must point to the beginning of a filter definition. 2722 */ 2723 char* parseFilter(char* data, char* dataEnd, Filter** filters, int num) { 2724 2725 Filter* filter; 2726 int next, count, i; 2727 int tmpOffset, tmpKeyLen; 2728 char* tmpKey; 2729 char* key1; 2730 char* key2; 2731 2732 filter = (Filter*) malloc(sizeof(Filter)); 2733 filter->activeCount = 0; 2734 filter->activeThreads = (int*) calloc(DEFAULT_ACTIVE_THREADS, sizeof(int)); 2735 filter->activationKeys = (int*) calloc(DEFAULT_ACTIVE_THREADS, sizeof(int)); 2736 2737 next = findNextChar(data + 1, dataEnd - data - 1, '\n'); 2738 if (next < 0) { 2739 // TODO: what should we do here? 2740 // End of file reached... 2741 } 2742 data[next+1] = '\0'; 2743 filter->filterName = data + 1; 2744 data += next + 2; // Careful 2745 2746 /* 2747 * Count the number of keys (one per line). 2748 */ 2749 count = countLinesToChar(data, dataEnd - data, FILTER_TAG); 2750 if (count <= 0) { 2751 fprintf(stderr, 2752 "ERROR: failed while parsing filter %s (found %d keys)\n", 2753 filter->filterName, count); 2754 return NULL; // TODO: Should do something else 2755 // Could return filter with 0 keys instead (probably better to avoid random segfaults) 2756 } 2757 2758 filter->filterKeys = (FilterKey*) malloc(sizeof(FilterKey) * count); 2759 2760 /* 2761 * Extract all entries. 2762 */ 2763 tmpOffset = 0; 2764 for (i = 0; i < count; i++) { 2765 next = findNextChar(data, dataEnd - data, '\n'); 2766 // assert(next > 0); // TODO: revise... (skip if next == 0 ?) 2767 data[next] = '\0'; 2768 tmpKey = data; 2769 2770 if (*data == FILTER_FLAG_THREAD) { 2771 filter->filterKeys[i].flags = 1; 2772 tmpKey++; 2773 } else { 2774 filter->filterKeys[i].flags = 0; 2775 } 2776 2777 tmpOffset = findNextChar(tmpKey, next, ','); 2778 2779 if (tmpOffset < 0) { 2780 // No comma, so only 1 key 2781 key1 = tmpKey; 2782 key2 = tmpKey; 2783 2784 // Get type for key1 2785 filter->filterKeys[i].type[0] = FILTER_TYPE_CLASS; // default 2786 tmpOffset = findNextChar(key1, next, '('); 2787 if (tmpOffset > 0) { 2788 if (findNextChar(key1, next, ')') == tmpOffset + 1) { 2789 filter->filterKeys[i].type[0] = FILTER_TYPE_METHOD; 2790 filter->filterKeys[i].type[1] = FILTER_TYPE_METHOD; 2791 } 2792 key1[tmpOffset] = '\0'; 2793 } 2794 } else { 2795 // Pair of keys 2796 tmpKey[tmpOffset] = '\0'; 2797 key1 = tmpKey; 2798 key2 = tmpKey + tmpOffset + 1; 2799 2800 // Get type for key1 2801 filter->filterKeys[i].type[0] = FILTER_TYPE_CLASS; 2802 tmpKeyLen = tmpOffset; 2803 tmpOffset = findNextChar(key1, tmpKeyLen, '('); 2804 if (tmpOffset > 0) { 2805 if (findNextChar(key1, tmpKeyLen, ')') == tmpOffset + 1) { 2806 filter->filterKeys[i].type[0] = FILTER_TYPE_METHOD; 2807 } 2808 key1[tmpOffset] = '\0'; 2809 } 2810 2811 // Get type for key2 2812 filter->filterKeys[i].type[1] = FILTER_TYPE_CLASS; 2813 tmpOffset = findNextChar(key2, next - tmpKeyLen, '('); 2814 if (tmpOffset > 0) { 2815 if (findNextChar(key2, next - tmpKeyLen, ')') == tmpOffset + 1) { 2816 filter->filterKeys[i].type[1] = FILTER_TYPE_METHOD; 2817 } 2818 key2[tmpOffset] = '\0'; 2819 } 2820 } 2821 2822 filter->filterKeys[i].keys[0] = key1; 2823 filter->filterKeys[i].keys[1] = key2; 2824 data += next+1; 2825 } 2826 2827 filter->numKeys = count; 2828 filters[num] = filter; 2829 2830 return data; 2831 } 2832 2833 /* 2834 * Parses filters from given file. The file must follow the following format: 2835 * 2836 * *FilterName <- creates a new filter with keys to follow 2837 * A.method() <- key that triggers whenever A.method() enters/exit 2838 * Class <- key that triggers whenever any method from Class enters/exits 2839 * +CrossThread <- same as above, but keeps track of execution times accross threads 2840 * B.m(),C.m() <- key that triggers filter on when B.m() enters and off when C.m() exits 2841 * 2842 * TODO: add concrete example to make things clear 2843 */ 2844 Filter** parseFilters(const char* filterFileName) { 2845 2846 Filter** filters = NULL; 2847 FILE* fp = NULL; 2848 long len; 2849 char* data; 2850 char* dataEnd; 2851 char* dataStart; 2852 int i, next, count; 2853 2854 fp = fopen(filterFileName, "r"); 2855 if (fp == NULL) 2856 goto bail; 2857 2858 if (fseek(fp, 0L, SEEK_END) != 0) { 2859 perror("fseek"); 2860 goto bail; 2861 } 2862 2863 len = ftell(fp); 2864 if (len == 0) { 2865 fprintf(stderr, "WARNING: Filter file is empty.\n"); 2866 goto bail; 2867 } 2868 rewind(fp); 2869 2870 data = (char*) malloc(len); 2871 if (data == NULL) { 2872 fprintf(stderr, "ERROR: unable to alloc %ld bytes for filter file\n", len); 2873 goto bail; 2874 } 2875 2876 // Read file into memory 2877 if (fread(data, 1, len, fp) != (size_t) len) { 2878 fprintf(stderr, "ERROR: unable to read %ld bytes from filter file\n", len); 2879 goto bail; 2880 } 2881 2882 dataStart = data; 2883 dataEnd = data + len; 2884 2885 // Figure out how many filters there are 2886 numFilters = 0; 2887 next = -1; 2888 2889 while (1) { 2890 if (*data == FILTER_TAG) 2891 numFilters++; 2892 next = findNextChar(data, len, '\n'); 2893 if (next < 0) 2894 break; 2895 data += next+1; 2896 len -= next+1; 2897 } 2898 2899 if (numFilters == 0) { 2900 fprintf(stderr, "WARNING: no filters found. Continuing without filters\n"); 2901 goto bail; 2902 } 2903 2904 filters = (Filter**) calloc(numFilters, sizeof(Filter *)); 2905 if (filters == NULL) { 2906 fprintf(stderr, "ERROR: unable to alloc memory for filters"); 2907 goto bail; 2908 } 2909 2910 data = dataStart; 2911 for (i = 0; i < numFilters; i++) { 2912 data = parseFilter(data, dataEnd, filters, i); 2913 } 2914 2915 return filters; 2916 2917 bail: 2918 if (fp != NULL) 2919 fclose(fp); 2920 2921 return NULL; 2922 2923 } 2924 2925 2926 /* 2927 * Read the key and data files and return the MethodEntries for those files 2928 */ 2929 DataKeys* parseDataKeys(TraceData* traceData, const char* traceFileName, 2930 uint64_t* threadTime, Filter** filters) 2931 { 2932 DataKeys* dataKeys = NULL; 2933 MethodEntry **pMethods = NULL; 2934 MethodEntry* method; 2935 FILE* dataFp = NULL; 2936 DataHeader dataHeader; 2937 int ii, jj, numThreads; 2938 uint64_t currentTime; 2939 MethodEntry* caller; 2940 2941 dataFp = fopen(traceFileName, "r"); 2942 if (dataFp == NULL) 2943 goto bail; 2944 2945 if ((dataKeys = parseKeys(dataFp, 0)) == NULL) 2946 goto bail; 2947 2948 if (parseDataHeader(dataFp, &dataHeader) < 0) 2949 goto bail; 2950 2951 numThreads = dataKeys->numThreads; 2952 2953 #if 0 2954 FILE *dumpStream = fopen("debug", "w"); 2955 #endif 2956 while (1) { 2957 int threadId; 2958 unsigned int methodVal; 2959 int action; 2960 unsigned int methodId; 2961 CallStack *pStack; 2962 2963 /* 2964 * Extract values from file. 2965 */ 2966 if (readDataRecord(dataFp, &threadId, &methodVal, ¤tTime)) 2967 break; 2968 2969 action = METHOD_ACTION(methodVal); 2970 methodId = METHOD_ID(methodVal); 2971 2972 /* Get the call stack for this thread */ 2973 pStack = traceData->stacks[threadId]; 2974 2975 /* If there is no call stack yet for this thread, then allocate one */ 2976 if (pStack == NULL) { 2977 pStack = malloc(sizeof(CallStack)); 2978 pStack->top = 0; 2979 pStack->lastEventTime = currentTime; 2980 pStack->threadStartTime = currentTime; 2981 pStack->remTimes = (uint64_t*) calloc(numFilters, sizeof(uint64_t)); 2982 traceData->stacks[threadId] = pStack; 2983 } 2984 2985 /* Lookup the current method */ 2986 method = lookupMethod(dataKeys, methodId); 2987 if (method == NULL) 2988 method = &dataKeys->methods[UNKNOWN_INDEX]; 2989 2990 #if 0 2991 if (method->methodName) { 2992 fprintf(dumpStream, "%2d %-8llu %d %8llu r %d c %d %s.%s %s\n", 2993 threadId, currentTime, action, pStack->threadStartTime, 2994 method->recursiveEntries, 2995 pStack->top, method->className, method->methodName, 2996 method->signature); 2997 } else { 2998 printf(dumpStream, "%2d %-8llu %d %8llu r %d c %d %s\n", 2999 threadId, currentTime, action, pStack->threadStartTime, 3000 method->recursiveEntries, 3001 pStack->top, method->className); 3002 } 3003 #endif 3004 3005 if (action == METHOD_TRACE_ENTER) { 3006 /* This is a method entry */ 3007 if (pStack->top >= MAX_STACK_DEPTH) { 3008 fprintf(stderr, "Stack overflow (exceeded %d frames)\n", 3009 MAX_STACK_DEPTH); 3010 exit(1); 3011 } 3012 3013 /* Get the caller method */ 3014 if (pStack->top >= 1) 3015 caller = pStack->calls[pStack->top - 1].method; 3016 else 3017 caller = &dataKeys->methods[TOPLEVEL_INDEX]; 3018 countRecursiveEntries(pStack, pStack->top, caller); 3019 caller->elapsedExclusive += currentTime - pStack->lastEventTime; 3020 #if 0 3021 if (caller->elapsedExclusive > 10000000) 3022 fprintf(dumpStream, "%llu current %llu last %llu diff %llu\n", 3023 caller->elapsedExclusive, currentTime, 3024 pStack->lastEventTime, 3025 currentTime - pStack->lastEventTime); 3026 #endif 3027 if (caller->recursiveEntries <= 1) { 3028 caller->topExclusive += currentTime - pStack->lastEventTime; 3029 } 3030 3031 /* Push the method on the stack for this thread */ 3032 pStack->calls[pStack->top].method = method; 3033 pStack->calls[pStack->top++].entryTime = currentTime; 3034 3035 // For each filter 3036 int result = 0; 3037 for (ii = 0; ii < numFilters; ii++) { 3038 result = filterMethod(method, filters[ii], 1, threadId, numThreads, 3039 currentTime - pStack->lastEventTime, pStack->remTimes[ii]); 3040 3041 // TODO: make remTimes work properly 3042 // Consider moving remTimes handling together with the rest 3043 // of time handling and clean up the return codes 3044 /* 3045 if (result == 0) { // no time added, no remTime added 3046 pStack->remTimes[ii] += currentTime - pStack->lastEventTime; 3047 } else if (result == 3 || result == 4) { // remTime added 3048 // Reset remTime, since it's been added 3049 pStack->remTimes[ii] = 0; 3050 } 3051 */ 3052 } 3053 3054 } else { 3055 /* This is a method exit */ 3056 uint64_t entryTime = 0; 3057 3058 /* Pop the method off the stack for this thread */ 3059 if (pStack->top > 0) { 3060 pStack->top -= 1; 3061 entryTime = pStack->calls[pStack->top].entryTime; 3062 if (method != pStack->calls[pStack->top].method) { 3063 if (method->methodName) { 3064 fprintf(stderr, 3065 "Exit from method %s.%s %s does not match stack:\n", 3066 method->className, method->methodName, 3067 method->signature); 3068 } else { 3069 fprintf(stderr, 3070 "Exit from method %s does not match stack:\n", 3071 method->className); 3072 } 3073 stackDump(pStack, pStack->top + 1); 3074 exit(1); 3075 } 3076 } 3077 3078 /* Get the caller method */ 3079 if (pStack->top >= 1) 3080 caller = pStack->calls[pStack->top - 1].method; 3081 else 3082 caller = &dataKeys->methods[TOPLEVEL_INDEX]; 3083 countRecursiveEntries(pStack, pStack->top, caller); 3084 countRecursiveEntries(pStack, pStack->top, method); 3085 uint64_t elapsed = currentTime - entryTime; 3086 addInclusiveTime(caller, method, elapsed); 3087 method->elapsedExclusive += currentTime - pStack->lastEventTime; 3088 if (method->recursiveEntries == 0) { 3089 method->topExclusive += currentTime - pStack->lastEventTime; 3090 } 3091 3092 // For each filter 3093 int result = 0; 3094 for (ii = 0; ii < numFilters; ii++) { 3095 result = filterMethod(method, filters[ii], 0, threadId, numThreads, 3096 currentTime - pStack->lastEventTime, pStack->remTimes[ii]); 3097 3098 // TODO: make remTimes work properly 3099 /* 3100 if (result == 0) { // no time added, no remTime added 3101 pStack->remTimes[ii] += currentTime - pStack->lastEventTime; 3102 } else if (result == 3 || result == 4) { // remTime added 3103 // Reset remTime, since it's been added 3104 pStack->remTimes[ii] = 0; 3105 } 3106 */ 3107 } 3108 3109 } 3110 /* Remember the time of the last entry or exit event */ 3111 pStack->lastEventTime = currentTime; 3112 } 3113 3114 /* If we have calls on the stack when the trace ends, then clean 3115 * up the stack and add time to the callers by pretending that we 3116 * are exiting from their methods now. 3117 */ 3118 CallStack *pStack; 3119 int threadId; 3120 uint64_t elapsedTime = 0; 3121 uint64_t sumThreadTime = 0; 3122 for (threadId = 0; threadId < MAX_THREADS; ++threadId) { 3123 3124 pStack = traceData->stacks[threadId]; 3125 3126 /* If this thread never existed, then continue with next thread */ 3127 if (pStack == NULL) 3128 continue; 3129 3130 /* Calculate times spent in thread, and add it to total time */ 3131 elapsedTime = pStack->lastEventTime - pStack->threadStartTime; 3132 sumThreadTime += elapsedTime; 3133 3134 for (ii = 0; ii < pStack->top; ++ii) { 3135 //printf("in loop\n"); 3136 3137 if (ii == 0) 3138 caller = &dataKeys->methods[TOPLEVEL_INDEX]; 3139 else 3140 caller = pStack->calls[ii - 1].method; 3141 method = pStack->calls[ii].method; 3142 countRecursiveEntries(pStack, ii, caller); 3143 countRecursiveEntries(pStack, ii, method); 3144 3145 uint64_t entryTime = pStack->calls[ii].entryTime; 3146 uint64_t elapsed = pStack->lastEventTime - entryTime; 3147 addInclusiveTime(caller, method, elapsed); 3148 3149 // For each filter 3150 int result = 0; 3151 for (ii = 0; ii < numFilters; ii++) { 3152 result = filterMethod(method, filters[ii], 0, threadId, numThreads, 3153 currentTime - pStack->lastEventTime, pStack->remTimes[ii]); 3154 3155 // TODO: make remTimes work properly 3156 /* 3157 if (result == 0) { // no time added, no remTime added 3158 pStack->remTimes[ii] += currentTime - pStack->lastEventTime; 3159 } else if (result == 3 || result == 4) { // remTime added 3160 // Reset remTime, since it's been added 3161 pStack->remTimes[ii] = 0; 3162 } 3163 */ 3164 } 3165 } 3166 3167 /* Save the per-thread elapsed time in the DataKeys struct */ 3168 for (ii = 0; ii < dataKeys->numThreads; ++ii) { 3169 if (dataKeys->threads[ii].threadId == threadId) { 3170 dataKeys->threads[ii].elapsedTime = elapsedTime; 3171 } 3172 } 3173 3174 3175 } 3176 caller = &dataKeys->methods[TOPLEVEL_INDEX]; 3177 caller->elapsedInclusive = sumThreadTime; 3178 3179 #if 0 3180 fclose(dumpStream); 3181 #endif 3182 3183 if (threadTime != NULL) { 3184 *threadTime = sumThreadTime; 3185 } 3186 3187 bail: 3188 if (dataFp != NULL) 3189 fclose(dataFp); 3190 3191 return dataKeys; 3192 } 3193 3194 MethodEntry** parseMethodEntries(DataKeys* dataKeys) 3195 { 3196 int ii; 3197 /* Create a new array of pointers to the methods and sort the pointers 3198 * instead of the actual MethodEntry structs. We need to do this 3199 * because there are other lists that contain pointers to the 3200 * MethodEntry structs. 3201 */ 3202 MethodEntry** pMethods = (MethodEntry**) malloc(sizeof(MethodEntry*) * dataKeys->numMethods); 3203 for (ii = 0; ii < dataKeys->numMethods; ++ii) { 3204 MethodEntry* entry = &dataKeys->methods[ii]; 3205 pMethods[ii] = entry; 3206 } 3207 3208 return pMethods; 3209 } 3210 3211 3212 /* 3213 * Produce a function profile from the following methods 3214 */ 3215 void profileTrace(TraceData* traceData, MethodEntry **pMethods, int numMethods, uint64_t sumThreadTime, 3216 ThreadEntry *pThreads, int numThreads, Filter** filters) 3217 { 3218 /* Print the html header, if necessary */ 3219 if (gOptions.outputHtml) { 3220 printf(htmlHeader, gOptions.sortableUrl); 3221 outputTableOfContents(); 3222 } 3223 3224 printExclusiveProfile(pMethods, numMethods, sumThreadTime); 3225 printInclusiveProfile(pMethods, numMethods, sumThreadTime); 3226 3227 printThreadProfile(pThreads, numThreads, sumThreadTime, filters); 3228 3229 createClassList(traceData, pMethods, numMethods); 3230 printClassProfiles(traceData, sumThreadTime); 3231 3232 createUniqueMethodList(traceData, pMethods, numMethods); 3233 printMethodProfiles(traceData, sumThreadTime); 3234 3235 if (gOptions.outputHtml) { 3236 printf("%s", htmlFooter); 3237 } 3238 } 3239 3240 int compareMethodNamesForDiff(const void *a, const void *b) 3241 { 3242 int result; 3243 3244 const MethodEntry *methodA = *(const MethodEntry**)a; 3245 const MethodEntry *methodB = *(const MethodEntry**)b; 3246 if (methodA->methodName == NULL || methodB->methodName == NULL) { 3247 return compareClassNames(a, b); 3248 } 3249 result = strcmp(methodA->methodName, methodB->methodName); 3250 if (result == 0) { 3251 result = strcmp(methodA->signature, methodB->signature); 3252 if (result == 0) { 3253 return strcmp(methodA->className, methodB->className); 3254 } 3255 } 3256 return result; 3257 } 3258 3259 int findMatch(MethodEntry** methods, int size, MethodEntry* matchThis) 3260 { 3261 int i; 3262 3263 for (i = 0 ; i < size ; i++) { 3264 MethodEntry* method = methods[i]; 3265 3266 if (method != NULL && !compareMethodNamesForDiff(&method, &matchThis)) { 3267 // printf("%s.%s == %s.%s<br>\n", matchThis->className, matchThis->methodName, 3268 // method->className, method->methodName); 3269 3270 return i; 3271 /* if (!compareMethodNames(&method, &matchThis)) { 3272 return i; 3273 } 3274 */ } 3275 } 3276 3277 return -1; 3278 } 3279 3280 int compareDiffEntriesExculsive(const void *a, const void *b) 3281 { 3282 int result; 3283 3284 const DiffEntry* entryA = (const DiffEntry*)a; 3285 const DiffEntry* entryB = (const DiffEntry*)b; 3286 3287 if (entryA->differenceExclusive < entryB->differenceExclusive) { 3288 return 1; 3289 } else if (entryA->differenceExclusive > entryB->differenceExclusive) { 3290 return -1; 3291 } 3292 3293 return 0; 3294 } 3295 3296 int compareDiffEntriesInculsive(const void *a, const void *b) 3297 { 3298 int result; 3299 3300 const DiffEntry* entryA = (const DiffEntry*)a; 3301 const DiffEntry* entryB = (const DiffEntry*)b; 3302 3303 if (entryA->differenceInclusive < entryB->differenceInclusive) { 3304 return 1; 3305 } else if (entryA->differenceInclusive > entryB->differenceInclusive) { 3306 return -1; 3307 } 3308 3309 return 0; 3310 } 3311 3312 void printMissingMethod(MethodEntry* method) 3313 { 3314 char classBuf[HTML_BUFSIZE]; 3315 char methodBuf[HTML_BUFSIZE]; 3316 char* className; 3317 char* methodName; 3318 3319 className = htmlEscape(method->className, classBuf, HTML_BUFSIZE); 3320 methodName = htmlEscape(method->methodName, methodBuf, HTML_BUFSIZE); 3321 3322 if (gOptions.outputHtml) printf("<tr><td>\n"); 3323 3324 printf("%s.%s ", className, methodName); 3325 if (gOptions.outputHtml) printf("</td><td>"); 3326 3327 printf("%lld ", method->elapsedExclusive); 3328 if (gOptions.outputHtml) printf("</td><td>"); 3329 3330 printf("%lld ", method->elapsedInclusive); 3331 if (gOptions.outputHtml) printf("</td><td>"); 3332 3333 printf("%d\n", method->numCalls[0]); 3334 if (gOptions.outputHtml) printf("</td><td>\n"); 3335 } 3336 3337 3338 void createDiff(DataKeys* d1, uint64_t sum1, DataKeys* d2, uint64_t sum2) 3339 { 3340 MethodEntry** methods1 = parseMethodEntries(d1); 3341 MethodEntry** methods2 = parseMethodEntries(d2); 3342 3343 // sort and assign the indicies 3344 int i; 3345 qsort(methods1, d1->numMethods, sizeof(MethodEntry*), compareElapsedInclusive); 3346 for (i = 0; i < d1->numMethods; ++i) { 3347 methods1[i]->index = i; 3348 } 3349 3350 qsort(methods2, d2->numMethods, sizeof(MethodEntry*), compareElapsedInclusive); 3351 for (i = 0; i < d2->numMethods; ++i) { 3352 methods2[i]->index = i; 3353 } 3354 3355 int max = (d1->numMethods < d2->numMethods) ? d2->numMethods : d1->numMethods; 3356 max++; 3357 DiffEntry* diffs = (DiffEntry*)malloc(max * sizeof(DiffEntry)); 3358 memset(diffs, 0, max * sizeof(DiffEntry)); 3359 DiffEntry* ptr = diffs; 3360 3361 // printf("<br>d1->numMethods: %d d1->numMethods: %d<br>\n", d1->numMethods, d2->numMethods); 3362 3363 int matches = 0; 3364 3365 for (i = 0 ; i < d1->numMethods ; i++) { 3366 int match = findMatch(methods2, d2->numMethods, methods1[i]); 3367 if (match >= 0) { 3368 ptr->method1 = methods1[i]; 3369 ptr->method2 = methods2[match]; 3370 3371 uint64_t e1 = ptr->method1->elapsedExclusive; 3372 uint64_t e2 = ptr->method2->elapsedExclusive; 3373 if (e1 > 0) { 3374 ptr->differenceExclusive = e2 - e1; 3375 ptr->differenceExclusivePercentage = ((double)e2 / (double)e1) * 100.0; 3376 } 3377 3378 uint64_t i1 = ptr->method1->elapsedInclusive; 3379 uint64_t i2 = ptr->method2->elapsedInclusive; 3380 if (i1 > 0) { 3381 ptr->differenceInclusive = i2 - i1; 3382 ptr->differenceInclusivePercentage = ((double)i2 / (double)i1) * 100.0; 3383 } 3384 3385 // clear these out so we don't find them again and we know which ones 3386 // we have left over 3387 methods1[i] = NULL; 3388 methods2[match] = NULL; 3389 ptr++; 3390 3391 matches++; 3392 } 3393 } 3394 ptr->method1 = NULL; 3395 ptr->method2 = NULL; 3396 3397 qsort(diffs, matches, sizeof(DiffEntry), compareDiffEntriesExculsive); 3398 ptr = diffs; 3399 3400 if (gOptions.outputHtml) { 3401 printf(htmlHeader, gOptions.sortableUrl); 3402 printf("<h3>Table of Contents</h3>\n"); 3403 printf("<ul>\n"); 3404 printf("<li><a href='#exclusive'>Exclusive</a>\n"); 3405 printf("<li><a href='#inclusive'>Inclusive</a>\n"); 3406 printf("</ul>\n"); 3407 printf("Run 1: %s<br>\n", gOptions.diffFileName); 3408 printf("Run 2: %s<br>\n", gOptions.traceFileName); 3409 printf("<a name=\"exclusive\"></a><h3 id=\"exclusive\">Exclusive</h3>\n"); 3410 printf(tableHeader, "exclusive_table"); 3411 } 3412 3413 char classBuf[HTML_BUFSIZE]; 3414 char methodBuf[HTML_BUFSIZE]; 3415 char* className; 3416 char* methodName; 3417 3418 while (ptr->method1 != NULL && ptr->method2 != NULL) { 3419 if (gOptions.outputHtml) printf("<tr><td>\n"); 3420 3421 className = htmlEscape(ptr->method1->className, classBuf, HTML_BUFSIZE); 3422 methodName = htmlEscape(ptr->method1->methodName, methodBuf, HTML_BUFSIZE); 3423 3424 printf("%s.%s ", className, methodName); 3425 if (gOptions.outputHtml) printf("</td><td>"); 3426 3427 printf("%lld ", ptr->method1->elapsedExclusive); 3428 if (gOptions.outputHtml) printf("</td><td>"); 3429 3430 printf("%llu ", ptr->method2->elapsedExclusive); 3431 if (gOptions.outputHtml) printf("</td><td>"); 3432 3433 printf("%lld ", ptr->differenceExclusive); 3434 if (gOptions.outputHtml) printf("</td><td>"); 3435 3436 printf("%.2f\n", ptr->differenceExclusivePercentage); 3437 if (gOptions.outputHtml) printf("</td><td>\n"); 3438 3439 printf("%d\n", ptr->method1->numCalls[0]); 3440 if (gOptions.outputHtml) printf("</td><td>\n"); 3441 3442 printf("%d\n", ptr->method2->numCalls[0]); 3443 if (gOptions.outputHtml) printf("</td></tr>\n"); 3444 3445 ptr++; 3446 } 3447 3448 if (gOptions.outputHtml) printf("</table>\n"); 3449 3450 if (gOptions.outputHtml) { 3451 printf(htmlHeader, gOptions.sortableUrl); 3452 printf("Run 1: %s<br>\n", gOptions.diffFileName); 3453 printf("Run 2: %s<br>\n", gOptions.traceFileName); 3454 printf("<a name=\"inclusive\"></a><h3 id=\"inculisve\">Inclusive</h3>\n"); 3455 printf(tableHeader, "inclusive_table"); 3456 } 3457 3458 qsort(diffs, matches, sizeof(DiffEntry), compareDiffEntriesInculsive); 3459 ptr = diffs; 3460 3461 while (ptr->method1 != NULL && ptr->method2 != NULL) { 3462 if (gOptions.outputHtml) printf("<tr><td>\n"); 3463 3464 className = htmlEscape(ptr->method1->className, classBuf, HTML_BUFSIZE); 3465 methodName = htmlEscape(ptr->method1->methodName, methodBuf, HTML_BUFSIZE); 3466 3467 printf("%s.%s ", className, methodName); 3468 if (gOptions.outputHtml) printf("</td><td>"); 3469 3470 printf("%lld ", ptr->method1->elapsedInclusive); 3471 if (gOptions.outputHtml) printf("</td><td>"); 3472 3473 printf("%llu ", ptr->method2->elapsedInclusive); 3474 if (gOptions.outputHtml) printf("</td><td>"); 3475 3476 printf("%lld ", ptr->differenceInclusive); 3477 if (gOptions.outputHtml) printf("</td><td>"); 3478 3479 printf("%.2f\n", ptr->differenceInclusivePercentage); 3480 if (gOptions.outputHtml) printf("</td><td>\n"); 3481 3482 printf("%d\n", ptr->method1->numCalls[0]); 3483 if (gOptions.outputHtml) printf("</td><td>\n"); 3484 3485 printf("%d\n", ptr->method2->numCalls[0]); 3486 if (gOptions.outputHtml) printf("</td></tr>\n"); 3487 3488 ptr++; 3489 } 3490 3491 if (gOptions.outputHtml) { 3492 printf("</table>\n"); 3493 printf("<h3>Run 1 methods not found in Run 2</h3>"); 3494 printf(tableHeaderMissing); 3495 } 3496 3497 for (i = 0; i < d1->numMethods; ++i) { 3498 if (methods1[i] != NULL) { 3499 printMissingMethod(methods1[i]); 3500 } 3501 } 3502 3503 if (gOptions.outputHtml) { 3504 printf("</table>\n"); 3505 printf("<h3>Run 2 methods not found in Run 1</h3>"); 3506 printf(tableHeaderMissing); 3507 } 3508 3509 for (i = 0; i < d2->numMethods; ++i) { 3510 if (methods2[i] != NULL) { 3511 printMissingMethod(methods2[i]); 3512 } 3513 } 3514 3515 if (gOptions.outputHtml) printf("</body></html\n"); 3516 } 3517 3518 int usage(const char *program) 3519 { 3520 fprintf(stderr, "usage: %s [-ho] [-s sortable] [-d trace-file-name] [-g outfile] [-f filter-file] trace-file-name\n", program); 3521 fprintf(stderr, " -d trace-file-name - Diff with this trace\n"); 3522 fprintf(stderr, " -g outfile - Write graph to 'outfile'\n"); 3523 fprintf(stderr, " -f filter-file - Filter functions as specified in file\n"); 3524 fprintf(stderr, " -k - When writing a graph, keep the intermediate DOT file\n"); 3525 fprintf(stderr, " -h - Turn on HTML output\n"); 3526 fprintf(stderr, " -o - Dump the dmtrace file instead of profiling\n"); 3527 fprintf(stderr, " -s - URL base to where the sortable javascript file\n"); 3528 fprintf(stderr, " -t threshold - Threshold percentage for including nodes in the graph\n"); 3529 return 2; 3530 } 3531 3532 // Returns true if there was an error 3533 int parseOptions(int argc, char **argv) 3534 { 3535 while (1) { 3536 int opt = getopt(argc, argv, "d:hg:kos:t:f:"); 3537 if (opt == -1) 3538 break; 3539 switch (opt) { 3540 case 'd': 3541 gOptions.diffFileName = optarg; 3542 break; 3543 case 'g': 3544 gOptions.graphFileName = optarg; 3545 break; 3546 case 'f': 3547 gOptions.filterFileName = optarg; 3548 break; 3549 case 'k': 3550 gOptions.keepDotFile = 1; 3551 break; 3552 case 'h': 3553 gOptions.outputHtml = 1; 3554 break; 3555 case 'o': 3556 gOptions.dump = 1; 3557 break; 3558 case 's': 3559 gOptions.sortableUrl = optarg; 3560 break; 3561 case 't': 3562 gOptions.threshold = atoi(optarg); 3563 break; 3564 default: 3565 return 1; 3566 } 3567 } 3568 return 0; 3569 } 3570 3571 /* 3572 * Parse args. 3573 */ 3574 int main(int argc, char** argv) 3575 { 3576 3577 gOptions.threshold = -1; 3578 3579 // Parse the options 3580 if (parseOptions(argc, argv) || argc - optind != 1) 3581 return usage(argv[0]); 3582 3583 gOptions.traceFileName = argv[optind]; 3584 3585 if (gOptions.threshold < 0 || 100 <= gOptions.threshold) { 3586 gOptions.threshold = 20; 3587 } 3588 3589 if (gOptions.dump) { 3590 dumpTrace(); 3591 return 0; 3592 } 3593 3594 uint64_t sumThreadTime = 0; 3595 3596 Filter** filters = NULL; 3597 if (gOptions.filterFileName != NULL) { 3598 filters = parseFilters(gOptions.filterFileName); 3599 } 3600 3601 TraceData data1; 3602 memset(&data1, 0, sizeof(data1)); 3603 DataKeys* dataKeys = parseDataKeys(&data1, gOptions.traceFileName, 3604 &sumThreadTime, filters); 3605 if (dataKeys == NULL) { 3606 fprintf(stderr, "Cannot read trace.\n"); 3607 exit(1); 3608 } 3609 3610 if (gOptions.diffFileName != NULL) { 3611 uint64_t sum2; 3612 TraceData data2; 3613 DataKeys* d2 = parseDataKeys(&data2, gOptions.diffFileName, &sum2, filters); 3614 3615 createDiff(d2, sum2, dataKeys, sumThreadTime); 3616 3617 freeDataKeys(d2); 3618 } else { 3619 MethodEntry** methods = parseMethodEntries(dataKeys); 3620 profileTrace(&data1, methods, dataKeys->numMethods, sumThreadTime, 3621 dataKeys->threads, dataKeys->numThreads, filters); 3622 if (gOptions.graphFileName != NULL) { 3623 createInclusiveProfileGraphNew(dataKeys); 3624 } 3625 free(methods); 3626 } 3627 3628 freeDataKeys(dataKeys); 3629 3630 return 0; 3631 } 3632