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 /* Reduce our allocation now that we know where the end of the key section is. */ 1064 pKeys->fileData = (char *)realloc(pKeys->fileData, offset); 1065 pKeys->fileLen = offset; 1066 /* Leave fp pointing to the beginning of the data section. */ 1067 fseek(fp, offset, SEEK_SET); 1068 1069 sortThreadList(pKeys); 1070 sortMethodList(pKeys); 1071 1072 /* 1073 * Dump list of threads. 1074 */ 1075 if (verbose) { 1076 printf("Threads (%d):\n", pKeys->numThreads); 1077 for (i = 0; i < pKeys->numThreads; i++) { 1078 printf("%2d %s\n", 1079 pKeys->threads[i].threadId, pKeys->threads[i].threadName); 1080 } 1081 } 1082 1083 #if 0 1084 /* 1085 * Dump list of methods. 1086 */ 1087 if (verbose) { 1088 printf("Methods (%d):\n", pKeys->numMethods); 1089 for (i = 0; i < pKeys->numMethods; i++) { 1090 printf("0x%08x %s : %s : %s\n", 1091 pKeys->methods[i].methodId >> 2, pKeys->methods[i].className, 1092 pKeys->methods[i].methodName, pKeys->methods[i].signature); 1093 } 1094 } 1095 #endif 1096 1097 return pKeys; 1098 1099 fail: 1100 freeDataKeys(pKeys); 1101 return NULL; 1102 } 1103 1104 1105 /* 1106 * Read values from the binary data file. 1107 */ 1108 1109 /* Make the return value "unsigned int" instead of "unsigned short" so that 1110 * we can detect EOF. 1111 */ 1112 unsigned int read2LE(FILE* fp) 1113 { 1114 unsigned int val; 1115 1116 val = getc(fp); 1117 val |= getc(fp) << 8; 1118 return val; 1119 } 1120 unsigned int read4LE(FILE* fp) 1121 { 1122 unsigned int val; 1123 1124 val = getc(fp); 1125 val |= getc(fp) << 8; 1126 val |= getc(fp) << 16; 1127 val |= getc(fp) << 24; 1128 return val; 1129 } 1130 unsigned long long read8LE(FILE* fp) 1131 { 1132 unsigned long long val; 1133 1134 val = getc(fp); 1135 val |= (unsigned long long) getc(fp) << 8; 1136 val |= (unsigned long long) getc(fp) << 16; 1137 val |= (unsigned long long) getc(fp) << 24; 1138 val |= (unsigned long long) getc(fp) << 32; 1139 val |= (unsigned long long) getc(fp) << 40; 1140 val |= (unsigned long long) getc(fp) << 48; 1141 val |= (unsigned long long) getc(fp) << 56; 1142 return val; 1143 } 1144 1145 /* 1146 * Parse the header of the data section. 1147 * 1148 * Returns with the file positioned at the start of the record data. 1149 */ 1150 int parseDataHeader(FILE *fp, DataHeader* pHeader) 1151 { 1152 pHeader->magic = read4LE(fp); 1153 pHeader->version = read2LE(fp); 1154 pHeader->offsetToData = read2LE(fp); 1155 pHeader->startWhen = read8LE(fp); 1156 1157 if (fseek(fp, pHeader->offsetToData - 16, SEEK_CUR) != 0) { 1158 return -1; 1159 } 1160 1161 return 0; 1162 } 1163 1164 /* 1165 * Look up a method by its method ID (using binary search). 1166 * 1167 * Returns NULL if no matching method was found. 1168 */ 1169 MethodEntry* lookupMethod(DataKeys* pKeys, unsigned int methodId) 1170 { 1171 int hi, lo, mid; 1172 unsigned int id; 1173 int hashedId; 1174 1175 /* Create cache if it doesn't already exist */ 1176 if (pKeys->methodCache == NULL) { 1177 pKeys->methodCache = (int*) malloc(sizeof(int) * METHOD_CACHE_SIZE); 1178 } 1179 1180 // ids are multiples of 4, so shift 1181 hashedId = (methodId >> 2) & METHOD_CACHE_SIZE_MASK; 1182 if (pKeys->methodCache[hashedId]) /* cache hit */ 1183 if (pKeys->methods[pKeys->methodCache[hashedId]].methodId == methodId) 1184 return &pKeys->methods[pKeys->methodCache[hashedId]]; 1185 1186 lo = 0; 1187 hi = pKeys->numMethods - 1; 1188 1189 while (hi >= lo) { 1190 mid = (hi + lo) / 2; 1191 1192 id = pKeys->methods[mid].methodId; 1193 if (id == methodId) { /* match, put in cache */ 1194 hashedId = (methodId >> 2) & METHOD_CACHE_SIZE_MASK; 1195 pKeys->methodCache[hashedId] = mid; 1196 return &pKeys->methods[mid]; 1197 } else if (id < methodId) /* too low */ 1198 lo = mid + 1; 1199 else /* too high */ 1200 hi = mid - 1; 1201 } 1202 1203 return NULL; 1204 } 1205 1206 /* 1207 * Reads the next data record, and assigns the data values to threadId, 1208 * methodVal and elapsedTime. On end-of-file, the threadId, methodVal, 1209 * and elapsedTime are unchanged. Returns 1 on end-of-file, otherwise 1210 * returns 0. 1211 */ 1212 int readDataRecord(FILE *dataFp, int *threadId, unsigned int *methodVal, 1213 uint64_t *elapsedTime) 1214 { 1215 int id; 1216 1217 /* 1218 * TODO: 1219 * This SHOULD NOT be keyed off of the global version number! Use 1220 * a name=value setting in the version area instead! 1221 */ 1222 if (versionNumber == 1) { 1223 id = getc(dataFp); 1224 } else { 1225 id = read2LE(dataFp); 1226 } 1227 if (id == EOF) 1228 return 1; 1229 *threadId = id; 1230 1231 *methodVal = read4LE(dataFp); 1232 *elapsedTime = read4LE(dataFp); 1233 if (feof(dataFp)) { 1234 fprintf(stderr, "WARNING: hit EOF mid-record\n"); 1235 return 1; 1236 } 1237 return 0; 1238 } 1239 1240 /* 1241 * Read the key file and use it to produce formatted output from the 1242 * data file. 1243 */ 1244 void dumpTrace() 1245 { 1246 static const char* actionStr[] = { "ent", "xit", "unr", "???" }; 1247 MethodEntry bogusMethod = { 0, "???", "???", "???", "???", -1, 0, 0, 0, 0, 1248 {NULL, NULL}, {NULL, NULL}, {0, 0}, 0, 0, -1 }; 1249 char bogusBuf[80]; 1250 char spaces[MAX_STACK_DEPTH+1]; 1251 FILE* dataFp = NULL; 1252 DataHeader dataHeader; 1253 DataKeys* pKeys = NULL; 1254 int i; 1255 TraceData traceData; 1256 1257 //printf("Dumping '%s' '%s'\n", dataFileName, keyFileName); 1258 1259 memset(spaces, '.', MAX_STACK_DEPTH); 1260 spaces[MAX_STACK_DEPTH] = '\0'; 1261 1262 for (i = 0; i < MAX_THREADS; i++) 1263 traceData.depth[i] = 2; // adjust for return from start function 1264 1265 dataFp = fopen(gOptions.traceFileName, "r"); 1266 if (dataFp == NULL) 1267 goto bail; 1268 1269 if ((pKeys = parseKeys(dataFp, 1)) == NULL) 1270 goto bail; 1271 1272 if (parseDataHeader(dataFp, &dataHeader) < 0) 1273 goto bail; 1274 1275 printf("Trace (threadID action usecs class.method signature):\n"); 1276 1277 while (1) { 1278 MethodEntry* method; 1279 int threadId; 1280 unsigned int methodVal; 1281 uint64_t elapsedTime; 1282 int action, printDepth; 1283 unsigned int methodId, lastEnter = 0; 1284 int mismatch = 0; 1285 char depthNote; 1286 1287 /* 1288 * Extract values from file. 1289 */ 1290 if (readDataRecord(dataFp, &threadId, &methodVal, &elapsedTime)) 1291 break; 1292 1293 action = METHOD_ACTION(methodVal); 1294 methodId = METHOD_ID(methodVal); 1295 1296 /* 1297 * Generate a line of output. 1298 */ 1299 if (action == METHOD_TRACE_ENTER) { 1300 traceData.depth[threadId]++; 1301 lastEnter = methodId; 1302 } else { 1303 /* quick test for mismatched adjacent enter/exit */ 1304 if (lastEnter != 0 && lastEnter != methodId) 1305 mismatch = 1; 1306 } 1307 1308 printDepth = traceData.depth[threadId]; 1309 depthNote = ' '; 1310 if (printDepth < 0) { 1311 printDepth = 0; 1312 depthNote = '-'; 1313 } else if (printDepth > MAX_STACK_DEPTH) { 1314 printDepth = MAX_STACK_DEPTH; 1315 depthNote = '+'; 1316 } 1317 1318 method = lookupMethod(pKeys, methodId); 1319 if (method == NULL) { 1320 method = &bogusMethod; 1321 sprintf(bogusBuf, "methodId: 0x%x", methodId); 1322 method->signature = bogusBuf; 1323 } 1324 1325 if (method->methodName) { 1326 printf("%2d %s%c %8lld%c%s%s.%s %s\n", threadId, 1327 actionStr[action], mismatch ? '!' : ' ', 1328 elapsedTime, depthNote, 1329 spaces + (MAX_STACK_DEPTH - printDepth), 1330 method->className, method->methodName, method->signature); 1331 } else { 1332 printf("%2d %s%c %8lld%c%s%s\n", threadId, 1333 actionStr[action], mismatch ? '!' : ' ', 1334 elapsedTime, depthNote, 1335 spaces + (MAX_STACK_DEPTH - printDepth), 1336 method->className); 1337 } 1338 1339 if (action != METHOD_TRACE_ENTER) { 1340 traceData.depth[threadId]--; /* METHOD_TRACE_EXIT or METHOD_TRACE_UNROLL */ 1341 lastEnter = 0; 1342 } 1343 1344 mismatch = 0; 1345 } 1346 1347 bail: 1348 if (dataFp != NULL) 1349 fclose(dataFp); 1350 if (pKeys != NULL) 1351 freeDataKeys(pKeys); 1352 } 1353 1354 /* This routine adds the given time to the parent and child methods. 1355 * This is called when the child routine exits, after the child has 1356 * been popped from the stack. The elapsedTime parameter is the 1357 * duration of the child routine, including time spent in called routines. 1358 */ 1359 void addInclusiveTime(MethodEntry *parent, MethodEntry *child, 1360 uint64_t elapsedTime) 1361 { 1362 TimedMethod *pTimed; 1363 1364 #if 0 1365 bool verbose = false; 1366 if (strcmp(child->className, debugClassName) == 0) 1367 verbose = true; 1368 #endif 1369 1370 int childIsRecursive = (child->recursiveEntries > 0); 1371 int parentIsRecursive = (parent->recursiveEntries > 1); 1372 1373 if (child->recursiveEntries == 0) { 1374 child->elapsedInclusive += elapsedTime; 1375 } else if (child->recursiveEntries == 1) { 1376 child->recursiveInclusive += elapsedTime; 1377 } 1378 child->numCalls[childIsRecursive] += 1; 1379 1380 #if 0 1381 if (verbose) { 1382 fprintf(stderr, 1383 "%s %d elapsedTime: %lld eI: %lld, rI: %lld\n", 1384 child->className, child->recursiveEntries, 1385 elapsedTime, child->elapsedInclusive, 1386 child->recursiveInclusive); 1387 } 1388 #endif 1389 1390 /* Find the child method in the parent */ 1391 TimedMethod *children = parent->children[parentIsRecursive]; 1392 for (pTimed = children; pTimed; pTimed = pTimed->next) { 1393 if (pTimed->method == child) { 1394 pTimed->elapsedInclusive += elapsedTime; 1395 pTimed->numCalls += 1; 1396 break; 1397 } 1398 } 1399 if (pTimed == NULL) { 1400 /* Allocate a new TimedMethod */ 1401 pTimed = (TimedMethod *) malloc(sizeof(TimedMethod)); 1402 pTimed->elapsedInclusive = elapsedTime; 1403 pTimed->numCalls = 1; 1404 pTimed->method = child; 1405 1406 /* Add it to the front of the list */ 1407 pTimed->next = children; 1408 parent->children[parentIsRecursive] = pTimed; 1409 } 1410 1411 /* Find the parent method in the child */ 1412 TimedMethod *parents = child->parents[childIsRecursive]; 1413 for (pTimed = parents; pTimed; pTimed = pTimed->next) { 1414 if (pTimed->method == parent) { 1415 pTimed->elapsedInclusive += elapsedTime; 1416 pTimed->numCalls += 1; 1417 break; 1418 } 1419 } 1420 if (pTimed == NULL) { 1421 /* Allocate a new TimedMethod */ 1422 pTimed = (TimedMethod *) malloc(sizeof(TimedMethod)); 1423 pTimed->elapsedInclusive = elapsedTime; 1424 pTimed->numCalls = 1; 1425 pTimed->method = parent; 1426 1427 /* Add it to the front of the list */ 1428 pTimed->next = parents; 1429 child->parents[childIsRecursive] = pTimed; 1430 } 1431 1432 #if 0 1433 if (verbose) { 1434 fprintf(stderr, 1435 " %s %d eI: %lld\n", 1436 parent->className, parent->recursiveEntries, 1437 pTimed->elapsedInclusive); 1438 } 1439 #endif 1440 } 1441 1442 /* Sorts a linked list and returns a newly allocated array containing 1443 * the sorted entries. 1444 */ 1445 TimedMethod *sortTimedMethodList(TimedMethod *list, int *num) 1446 { 1447 int ii; 1448 TimedMethod *pTimed, *sorted; 1449 1450 /* Count the elements */ 1451 int num_entries = 0; 1452 for (pTimed = list; pTimed; pTimed = pTimed->next) 1453 num_entries += 1; 1454 *num = num_entries; 1455 if (num_entries == 0) 1456 return NULL; 1457 1458 /* Copy all the list elements to a new array and sort them */ 1459 sorted = (TimedMethod *) malloc(sizeof(TimedMethod) * num_entries); 1460 for (ii = 0, pTimed = list; pTimed; pTimed = pTimed->next, ++ii) 1461 memcpy(&sorted[ii], pTimed, sizeof(TimedMethod)); 1462 qsort(sorted, num_entries, sizeof(TimedMethod), compareTimedMethod); 1463 1464 /* Fix up the "next" pointers so that they work. */ 1465 for (ii = 0; ii < num_entries - 1; ++ii) 1466 sorted[ii].next = &sorted[ii + 1]; 1467 sorted[num_entries - 1].next = NULL; 1468 1469 return sorted; 1470 } 1471 1472 /* Define flag values for printInclusiveMethod() */ 1473 static const int kIsRecursive = 1; 1474 1475 /* This prints the inclusive stats for all the parents or children of a 1476 * method, depending on the list that is passed in. 1477 */ 1478 void printInclusiveMethod(MethodEntry *method, TimedMethod *list, int numCalls, 1479 int flags) 1480 { 1481 int num; 1482 TimedMethod *pTimed; 1483 char buf[80]; 1484 char *anchor_close; 1485 char *spaces = " "; /* 6 spaces */ 1486 int num_spaces = strlen(spaces); 1487 char *space_ptr = &spaces[num_spaces]; 1488 char *className, *methodName, *signature; 1489 char classBuf[HTML_BUFSIZE], methodBuf[HTML_BUFSIZE]; 1490 char signatureBuf[HTML_BUFSIZE]; 1491 1492 anchor_close = ""; 1493 if (gOptions.outputHtml) 1494 anchor_close = "</a>"; 1495 1496 TimedMethod *sorted = sortTimedMethodList(list, &num); 1497 double methodTotal = method->elapsedInclusive; 1498 for (pTimed = sorted; pTimed; pTimed = pTimed->next) { 1499 MethodEntry *relative = pTimed->method; 1500 className = (char*)(relative->className); 1501 methodName = (char*)(relative->methodName); 1502 signature = (char*)(relative->signature); 1503 double per = 100.0 * pTimed->elapsedInclusive / methodTotal; 1504 sprintf(buf, "[%d]", relative->index); 1505 if (gOptions.outputHtml) { 1506 int len = strlen(buf); 1507 if (len > num_spaces) 1508 len = num_spaces; 1509 sprintf(buf, "<a href=\"#m%d\">[%d]", 1510 relative->index, relative->index); 1511 space_ptr = &spaces[len]; 1512 className = htmlEscape(className, classBuf, HTML_BUFSIZE); 1513 methodName = htmlEscape(methodName, methodBuf, HTML_BUFSIZE); 1514 signature = htmlEscape(signature, signatureBuf, HTML_BUFSIZE); 1515 } 1516 int nCalls = numCalls; 1517 if (nCalls == 0) 1518 nCalls = relative->numCalls[0] + relative->numCalls[1]; 1519 if (relative->methodName) { 1520 if (flags & kIsRecursive) { 1521 // Don't display percentages for recursive functions 1522 printf("%6s %5s %6s %s%6s%s %6d/%-6d %9llu %s.%s %s\n", 1523 "", "", "", 1524 space_ptr, buf, anchor_close, 1525 pTimed->numCalls, nCalls, 1526 pTimed->elapsedInclusive, 1527 className, methodName, signature); 1528 } else { 1529 printf("%6s %5s %5.1f%% %s%6s%s %6d/%-6d %9llu %s.%s %s\n", 1530 "", "", per, 1531 space_ptr, buf, anchor_close, 1532 pTimed->numCalls, nCalls, 1533 pTimed->elapsedInclusive, 1534 className, methodName, signature); 1535 } 1536 } else { 1537 if (flags & kIsRecursive) { 1538 // Don't display percentages for recursive functions 1539 printf("%6s %5s %6s %s%6s%s %6d/%-6d %9llu %s\n", 1540 "", "", "", 1541 space_ptr, buf, anchor_close, 1542 pTimed->numCalls, nCalls, 1543 pTimed->elapsedInclusive, 1544 className); 1545 } else { 1546 printf("%6s %5s %5.1f%% %s%6s%s %6d/%-6d %9llu %s\n", 1547 "", "", per, 1548 space_ptr, buf, anchor_close, 1549 pTimed->numCalls, nCalls, 1550 pTimed->elapsedInclusive, 1551 className); 1552 } 1553 } 1554 } 1555 } 1556 1557 void countRecursiveEntries(CallStack *pStack, int top, MethodEntry *method) 1558 { 1559 int ii; 1560 1561 method->recursiveEntries = 0; 1562 for (ii = 0; ii < top; ++ii) { 1563 if (pStack->calls[ii].method == method) 1564 method->recursiveEntries += 1; 1565 } 1566 } 1567 1568 void stackDump(CallStack *pStack, int top) 1569 { 1570 int ii; 1571 1572 for (ii = 0; ii < top; ++ii) { 1573 MethodEntry *method = pStack->calls[ii].method; 1574 uint64_t entryTime = pStack->calls[ii].entryTime; 1575 if (method->methodName) { 1576 fprintf(stderr, " %2d: %8llu %s.%s %s\n", ii, entryTime, 1577 method->className, method->methodName, method->signature); 1578 } else { 1579 fprintf(stderr, " %2d: %8llu %s\n", ii, entryTime, method->className); 1580 } 1581 } 1582 } 1583 1584 void outputTableOfContents() 1585 { 1586 printf("<a name=\"contents\"></a>\n"); 1587 printf("<h2>Table of Contents</h2>\n"); 1588 printf("<ul>\n"); 1589 printf(" <li><a href=\"#exclusive\">Exclusive profile</a></li>\n"); 1590 printf(" <li><a href=\"#inclusive\">Inclusive profile</a></li>\n"); 1591 printf(" <li><a href=\"#thread\">Thread profile</a></li>\n"); 1592 printf(" <li><a href=\"#class\">Class/method profile</a></li>\n"); 1593 printf(" <li><a href=\"#method\">Method/class profile</a></li>\n"); 1594 printf("</ul>\n\n"); 1595 } 1596 1597 void outputNavigationBar() 1598 { 1599 printf("<a href=\"#contents\">[Top]</a>\n"); 1600 printf("<a href=\"#exclusive\">[Exclusive]</a>\n"); 1601 printf("<a href=\"#inclusive\">[Inclusive]</a>\n"); 1602 printf("<a href=\"#thread\">[Thread]</a>\n"); 1603 printf("<a href=\"#class\">[Class]</a>\n"); 1604 printf("<a href=\"#method\">[Method]</a>\n"); 1605 printf("<br><br>\n"); 1606 } 1607 1608 void printExclusiveProfile(MethodEntry **pMethods, int numMethods, 1609 uint64_t sumThreadTime) 1610 { 1611 int ii; 1612 MethodEntry* method; 1613 double total, sum, per, sum_per; 1614 char classBuf[HTML_BUFSIZE], methodBuf[HTML_BUFSIZE]; 1615 char signatureBuf[HTML_BUFSIZE]; 1616 char anchor_buf[80]; 1617 char *anchor_close = ""; 1618 1619 total = sumThreadTime; 1620 anchor_buf[0] = 0; 1621 if (gOptions.outputHtml) { 1622 anchor_close = "</a>"; 1623 printf("<a name=\"exclusive\"></a>\n"); 1624 printf("<hr>\n"); 1625 outputNavigationBar(); 1626 } else { 1627 printf("\n%s\n", profileSeparator); 1628 } 1629 1630 /* First, sort the methods into decreasing order of inclusive 1631 * elapsed time so that we can assign the method indices. 1632 */ 1633 qsort(pMethods, numMethods, sizeof(MethodEntry*), compareElapsedInclusive); 1634 1635 for (ii = 0; ii < numMethods; ++ii) 1636 pMethods[ii]->index = ii; 1637 1638 /* Sort the methods into decreasing order of exclusive elapsed time. 1639 */ 1640 qsort(pMethods, numMethods, sizeof(MethodEntry*), 1641 compareElapsedExclusive); 1642 1643 printf("Total cycles: %llu\n\n", sumThreadTime); 1644 if (gOptions.outputHtml) { 1645 printf("<br><br>\n"); 1646 } 1647 printf("Exclusive elapsed times for each method, not including time spent in\n"); 1648 printf("children, sorted by exclusive time.\n\n"); 1649 if (gOptions.outputHtml) { 1650 printf("<br><br>\n<pre>\n"); 1651 } 1652 1653 printf(" Usecs self %% sum %% Method\n"); 1654 sum = 0; 1655 1656 for (ii = 0; ii < numMethods; ++ii) { 1657 char *className, *methodName, *signature; 1658 1659 method = pMethods[ii]; 1660 /* Don't show methods with zero cycles */ 1661 if (method->elapsedExclusive == 0) 1662 break; 1663 className = (char*)(method->className); 1664 methodName = (char*)(method->methodName); 1665 signature = (char*)(method->signature); 1666 sum += method->elapsedExclusive; 1667 per = 100.0 * method->elapsedExclusive / total; 1668 sum_per = 100.0 * sum / total; 1669 if (gOptions.outputHtml) { 1670 sprintf(anchor_buf, "<a href=\"#m%d\">", method->index); 1671 className = htmlEscape(className, classBuf, HTML_BUFSIZE); 1672 methodName = htmlEscape(methodName, methodBuf, HTML_BUFSIZE); 1673 signature = htmlEscape(signature, signatureBuf, HTML_BUFSIZE); 1674 } 1675 if (method->methodName) { 1676 printf("%9llu %6.2f %6.2f %s[%d]%s %s.%s %s\n", 1677 method->elapsedExclusive, per, sum_per, 1678 anchor_buf, method->index, anchor_close, 1679 className, methodName, signature); 1680 } else { 1681 printf("%9llu %6.2f %6.2f %s[%d]%s %s\n", 1682 method->elapsedExclusive, per, sum_per, 1683 anchor_buf, method->index, anchor_close, 1684 className); 1685 } 1686 } 1687 if (gOptions.outputHtml) { 1688 printf("</pre>\n"); 1689 } 1690 } 1691 1692 /* check to make sure that the child method meets the threshold of the parent */ 1693 int checkThreshold(MethodEntry* parent, MethodEntry* child) 1694 { 1695 double parentTime = parent->elapsedInclusive; 1696 double childTime = child->elapsedInclusive; 1697 int64_t percentage = (childTime / parentTime) * 100.0; 1698 return (percentage < gOptions.threshold) ? 0 : 1; 1699 } 1700 1701 void createLabels(FILE* file, MethodEntry* method) 1702 { 1703 fprintf(file, "node%d[label = \"[%d] %s.%s (%llu, %llu, %d)\"]\n", 1704 method->index, method->index, method->className, method->methodName, 1705 method->elapsedInclusive / 1000, 1706 method->elapsedExclusive / 1000, 1707 method->numCalls[0]); 1708 1709 method->graphState = GRAPH_LABEL_VISITED; 1710 1711 TimedMethod* child; 1712 for (child = method->children[0] ; child ; child = child->next) { 1713 MethodEntry* childMethod = child->method; 1714 1715 if ((childMethod->graphState & GRAPH_LABEL_VISITED) == 0 && checkThreshold(method, childMethod)) { 1716 createLabels(file, child->method); 1717 } 1718 } 1719 } 1720 1721 void createLinks(FILE* file, MethodEntry* method) 1722 { 1723 method->graphState |= GRAPH_NODE_VISITED; 1724 1725 TimedMethod* child; 1726 for (child = method->children[0] ; child ; child = child->next) { 1727 MethodEntry* childMethod = child->method; 1728 if (checkThreshold(method, child->method)) { 1729 fprintf(file, "node%d -> node%d\n", method->index, child->method->index); 1730 // only visit children that haven't been visited before 1731 if ((childMethod->graphState & GRAPH_NODE_VISITED) == 0) { 1732 createLinks(file, child->method); 1733 } 1734 } 1735 } 1736 } 1737 1738 void createInclusiveProfileGraphNew(DataKeys* dataKeys) 1739 { 1740 // create a temporary file in /tmp 1741 char path[FILENAME_MAX]; 1742 if (gOptions.keepDotFile) { 1743 snprintf(path, FILENAME_MAX, "%s.dot", gOptions.graphFileName); 1744 } else { 1745 snprintf(path, FILENAME_MAX, "/tmp/dot-%d-%d.dot", (int)time(NULL), rand()); 1746 } 1747 1748 FILE* file = fopen(path, "w+"); 1749 1750 fprintf(file, "digraph g {\nnode [shape = record,height=.1];\n"); 1751 1752 createLabels(file, dataKeys->methods); 1753 createLinks(file, dataKeys->methods); 1754 1755 fprintf(file, "}"); 1756 fclose(file); 1757 1758 // now that we have the dot file generate the image 1759 char command[1024]; 1760 snprintf(command, 1024, "dot -Tpng -o '%s' '%s'", gOptions.graphFileName, path); 1761 1762 system(command); 1763 1764 if (! gOptions.keepDotFile) { 1765 remove(path); 1766 } 1767 } 1768 1769 void printInclusiveProfile(MethodEntry **pMethods, int numMethods, 1770 uint64_t sumThreadTime) 1771 { 1772 int ii; 1773 MethodEntry* method; 1774 double total, sum, per, sum_per; 1775 char classBuf[HTML_BUFSIZE], methodBuf[HTML_BUFSIZE]; 1776 char signatureBuf[HTML_BUFSIZE]; 1777 char anchor_buf[80]; 1778 1779 total = sumThreadTime; 1780 anchor_buf[0] = 0; 1781 if (gOptions.outputHtml) { 1782 printf("<a name=\"inclusive\"></a>\n"); 1783 printf("<hr>\n"); 1784 outputNavigationBar(); 1785 } else { 1786 printf("\n%s\n", profileSeparator); 1787 } 1788 1789 /* Sort the methods into decreasing order of inclusive elapsed time. */ 1790 qsort(pMethods, numMethods, sizeof(MethodEntry*), 1791 compareElapsedInclusive); 1792 1793 printf("\nInclusive elapsed times for each method and its parents and children,\n"); 1794 printf("sorted by inclusive time.\n\n"); 1795 1796 if (gOptions.outputHtml) { 1797 printf("<br><br>\n<pre>\n"); 1798 } 1799 1800 printf("index %%/total %%/self index calls usecs name\n"); 1801 for (ii = 0; ii < numMethods; ++ii) { 1802 int num; 1803 TimedMethod *pTimed; 1804 double excl_per; 1805 char buf[40]; 1806 char *className, *methodName, *signature; 1807 1808 method = pMethods[ii]; 1809 /* Don't show methods with zero cycles */ 1810 if (method->elapsedInclusive == 0) 1811 break; 1812 1813 className = (char*)(method->className); 1814 methodName = (char*)(method->methodName); 1815 signature = (char*)(method->signature); 1816 1817 if (gOptions.outputHtml) { 1818 printf("<a name=\"m%d\"></a>", method->index); 1819 className = htmlEscape(className, classBuf, HTML_BUFSIZE); 1820 methodName = htmlEscape(methodName, methodBuf, HTML_BUFSIZE); 1821 signature = htmlEscape(signature, signatureBuf, HTML_BUFSIZE); 1822 } 1823 printf("----------------------------------------------------\n"); 1824 1825 /* Sort and print the parents */ 1826 int numCalls = method->numCalls[0] + method->numCalls[1]; 1827 printInclusiveMethod(method, method->parents[0], numCalls, 0); 1828 if (method->parents[1]) { 1829 printf(" +++++++++++++++++++++++++\n"); 1830 printInclusiveMethod(method, method->parents[1], numCalls, 1831 kIsRecursive); 1832 } 1833 1834 per = 100.0 * method->elapsedInclusive / total; 1835 sprintf(buf, "[%d]", ii); 1836 if (method->methodName) { 1837 printf("%-6s %5.1f%% %5s %6s %6d+%-6d %9llu %s.%s %s\n", 1838 buf, 1839 per, "", "", method->numCalls[0], method->numCalls[1], 1840 method->elapsedInclusive, 1841 className, methodName, signature); 1842 } else { 1843 printf("%-6s %5.1f%% %5s %6s %6d+%-6d %9llu %s\n", 1844 buf, 1845 per, "", "", method->numCalls[0], method->numCalls[1], 1846 method->elapsedInclusive, 1847 className); 1848 } 1849 excl_per = 100.0 * method->topExclusive / method->elapsedInclusive; 1850 printf("%6s %5s %5.1f%% %6s %6s %6s %9llu\n", 1851 "", "", excl_per, "excl", "", "", method->topExclusive); 1852 1853 /* Sort and print the children */ 1854 printInclusiveMethod(method, method->children[0], 0, 0); 1855 if (method->children[1]) { 1856 printf(" +++++++++++++++++++++++++\n"); 1857 printInclusiveMethod(method, method->children[1], 0, 1858 kIsRecursive); 1859 } 1860 } 1861 if (gOptions.outputHtml) { 1862 printf("</pre>\n"); 1863 } 1864 } 1865 1866 void printThreadProfile(ThreadEntry *pThreads, int numThreads, uint64_t sumThreadTime, Filter** filters) 1867 { 1868 int ii, jj; 1869 ThreadEntry thread; 1870 double total, per, sum_per; 1871 uint64_t sum; 1872 char threadBuf[HTML_BUFSIZE]; 1873 char anchor_buf[80]; 1874 int drawTable; 1875 1876 total = sumThreadTime; 1877 anchor_buf[0] = 0; 1878 if (gOptions.outputHtml) { 1879 printf("<a name=\"thread\"></a>\n"); 1880 printf("<hr>\n"); 1881 outputNavigationBar(); 1882 } else { 1883 printf("\n%s\n", profileSeparator); 1884 } 1885 1886 /* Sort the threads into decreasing order of elapsed time. */ 1887 qsort(pThreads, numThreads, sizeof(ThreadEntry), compareElapsed); 1888 1889 printf("\nElapsed times for each thread, sorted by elapsed time.\n"); 1890 printf("Also includes percentage of time spent during the <i>execution</i> of any filters.\n\n"); 1891 1892 if (gOptions.outputHtml) { 1893 printf("<br><br>\n<pre>\n"); 1894 } 1895 1896 printf(" Usecs self %% sum %%"); 1897 for (ii = 0; ii < numFilters; ++ii) { 1898 printf(" %s %%", filters[ii]->filterName); 1899 } 1900 printf(" tid ThreadName\n"); 1901 sum = 0; 1902 1903 for (ii = 0; ii < numThreads; ++ii) { 1904 int threadId; 1905 char *threadName; 1906 uint64_t time; 1907 1908 thread = pThreads[ii]; 1909 1910 threadId = thread.threadId; 1911 threadName = (char*)(thread.threadName); 1912 time = thread.elapsedTime; 1913 1914 sum += time; 1915 per = 100.0 * time / total; 1916 sum_per = 100.0 * sum / total; 1917 1918 if (gOptions.outputHtml) { 1919 threadName = htmlEscape(threadName, threadBuf, HTML_BUFSIZE); 1920 } 1921 1922 printf("%9llu %6.2f %6.2f", time, per, sum_per); 1923 for (jj = 0; jj < numFilters; jj++) { 1924 printf(" %6.2f", 100.0 * filters[jj]->times.threadExecutionTimes[threadId] / time); 1925 } 1926 printf(" %3d %s\n", threadId, threadName); 1927 } 1928 1929 if (gOptions.outputHtml) 1930 printf("</pre><br />"); 1931 1932 printf("\n\nBreak-down of portion of time spent by each thread while waiting on a filter method.\n"); 1933 1934 for (ii = 0; ii < numFilters; ++ii) { 1935 // Draw a table for each filter that measures wait time 1936 drawTable = 0; 1937 for (jj = 0; jj < filters[ii]->numKeys; jj++) 1938 if (filters[ii]->filterKeys[jj].flags == 1) 1939 drawTable = 1; 1940 1941 if (drawTable) { 1942 1943 if (gOptions.outputHtml) 1944 printf("<br/><br/>\n<pre>\n"); 1945 printf("Filter: %s\n", filters[ii]->filterName); 1946 printf("Total waiting cycles: %llu (%6.2f%% of total)\n", 1947 filters[ii]->times.totalWaitTime, 1948 100.0 * filters[ii]->times.totalWaitTime / sum); 1949 1950 if (filters[ii]->times.totalWaitTime > 0) { 1951 1952 printf("Details: \n\n"); 1953 1954 printf(" Waiting cycles %% of total waiting time execution time while waiting thread name\n"); 1955 1956 for (jj = 0; jj < numThreads; jj++) { 1957 1958 thread = pThreads[jj]; 1959 1960 char *threadName; 1961 threadName = (char*) thread.threadName; 1962 if (gOptions.outputHtml) { 1963 threadName = htmlEscape(threadName, threadBuf, HTML_BUFSIZE); 1964 } 1965 1966 printf(" %9llu %6.2f %6.2f %s\n", 1967 filters[ii]->times.threadWaitTimes[thread.threadId], 1968 100.0 * filters[ii]->times.threadWaitTimes[thread.threadId] / filters[ii]->times.totalWaitTime, 1969 100.0 * filters[ii]->times.threadExecutionTimesWhileWaiting[thread.threadId] / filters[ii]->times.totalWaitTime, 1970 threadName); 1971 } 1972 } 1973 1974 if (gOptions.outputHtml) 1975 printf("</pre>\n"); 1976 1977 } 1978 } 1979 1980 } 1981 1982 void createClassList(TraceData* traceData, MethodEntry **pMethods, int numMethods) 1983 { 1984 int ii; 1985 1986 /* Sort the methods into alphabetical order to find the unique class 1987 * names. 1988 */ 1989 qsort(pMethods, numMethods, sizeof(MethodEntry*), compareClassNames); 1990 1991 /* Count the number of unique class names. */ 1992 const char *currentClassName = ""; 1993 const char *firstClassName = NULL; 1994 traceData->numClasses = 0; 1995 for (ii = 0; ii < numMethods; ++ii) { 1996 if (pMethods[ii]->methodName == NULL) { 1997 continue; 1998 } 1999 if (strcmp(pMethods[ii]->className, currentClassName) != 0) { 2000 // Remember the first one 2001 if (firstClassName == NULL) { 2002 firstClassName = pMethods[ii]->className; 2003 } 2004 traceData->numClasses += 1; 2005 currentClassName = pMethods[ii]->className; 2006 } 2007 } 2008 2009 if (traceData->numClasses == 0) { 2010 traceData->classes = NULL; 2011 return; 2012 } 2013 2014 /* Allocate space for all of the unique class names */ 2015 traceData->classes = (ClassEntry *) malloc(sizeof(ClassEntry) * traceData->numClasses); 2016 2017 /* Initialize the classes array */ 2018 memset(traceData->classes, 0, sizeof(ClassEntry) * traceData->numClasses); 2019 ClassEntry *pClass = traceData->classes; 2020 pClass->className = currentClassName = firstClassName; 2021 int prevNumMethods = 0; 2022 for (ii = 0; ii < numMethods; ++ii) { 2023 if (pMethods[ii]->methodName == NULL) { 2024 continue; 2025 } 2026 if (strcmp(pMethods[ii]->className, currentClassName) != 0) { 2027 pClass->numMethods = prevNumMethods; 2028 (++pClass)->className = currentClassName = pMethods[ii]->className; 2029 prevNumMethods = 0; 2030 } 2031 prevNumMethods += 1; 2032 } 2033 pClass->numMethods = prevNumMethods; 2034 2035 /* Create the array of MethodEntry pointers for each class */ 2036 pClass = NULL; 2037 currentClassName = ""; 2038 int nextMethod = 0; 2039 for (ii = 0; ii < numMethods; ++ii) { 2040 if (pMethods[ii]->methodName == NULL) { 2041 continue; 2042 } 2043 if (strcmp(pMethods[ii]->className, currentClassName) != 0) { 2044 currentClassName = pMethods[ii]->className; 2045 if (pClass == NULL) 2046 pClass = traceData->classes; 2047 else 2048 pClass++; 2049 /* Allocate space for the methods array */ 2050 int nbytes = sizeof(MethodEntry*) * pClass->numMethods; 2051 pClass->methods = (MethodEntry**) malloc(nbytes); 2052 nextMethod = 0; 2053 } 2054 pClass->methods[nextMethod++] = pMethods[ii]; 2055 } 2056 } 2057 2058 /* Prints a number of html non-breaking spaces according so that the length 2059 * of the string "buf" is at least "width" characters wide. If width is 2060 * negative, then trailing spaces are added instead of leading spaces. 2061 */ 2062 void printHtmlField(char *buf, int width) 2063 { 2064 int ii; 2065 2066 int leadingSpaces = 1; 2067 if (width < 0) { 2068 width = -width; 2069 leadingSpaces = 0; 2070 } 2071 int len = strlen(buf); 2072 int numSpaces = width - len; 2073 if (numSpaces <= 0) { 2074 printf("%s", buf); 2075 return; 2076 } 2077 if (leadingSpaces == 0) 2078 printf("%s", buf); 2079 for (ii = 0; ii < numSpaces; ++ii) 2080 printf(" "); 2081 if (leadingSpaces == 1) 2082 printf("%s", buf); 2083 } 2084 2085 void printClassProfiles(TraceData* traceData, uint64_t sumThreadTime) 2086 { 2087 int ii, jj; 2088 MethodEntry* method; 2089 double total, sum, per, sum_per; 2090 char classBuf[HTML_BUFSIZE], methodBuf[HTML_BUFSIZE]; 2091 char signatureBuf[HTML_BUFSIZE]; 2092 2093 total = sumThreadTime; 2094 if (gOptions.outputHtml) { 2095 printf("<a name=\"class\"></a>\n"); 2096 printf("<hr>\n"); 2097 outputNavigationBar(); 2098 } else { 2099 printf("\n%s\n", profileSeparator); 2100 } 2101 2102 if (traceData->numClasses == 0) { 2103 printf("\nNo classes.\n"); 2104 if (gOptions.outputHtml) { 2105 printf("<br><br>\n"); 2106 } 2107 return; 2108 } 2109 2110 printf("\nExclusive elapsed time for each class, summed over all the methods\n"); 2111 printf("in the class.\n\n"); 2112 if (gOptions.outputHtml) { 2113 printf("<br><br>\n"); 2114 } 2115 2116 /* For each class, sum the exclusive times in all of the methods 2117 * in that class. Also sum the number of method calls. Also 2118 * sort the methods so the most expensive appear at the top. 2119 */ 2120 ClassEntry *pClass = traceData->classes; 2121 for (ii = 0; ii < traceData->numClasses; ++ii, ++pClass) { 2122 //printf("%s %d methods\n", pClass->className, pClass->numMethods); 2123 int numMethods = pClass->numMethods; 2124 for (jj = 0; jj < numMethods; ++jj) { 2125 method = pClass->methods[jj]; 2126 pClass->elapsedExclusive += method->elapsedExclusive; 2127 pClass->numCalls[0] += method->numCalls[0]; 2128 pClass->numCalls[1] += method->numCalls[1]; 2129 } 2130 2131 /* Sort the methods into decreasing order of exclusive time */ 2132 qsort(pClass->methods, numMethods, sizeof(MethodEntry*), 2133 compareElapsedExclusive); 2134 } 2135 2136 /* Allocate an array of pointers to the classes for more efficient 2137 * sorting. 2138 */ 2139 ClassEntry **pClasses; 2140 pClasses = (ClassEntry**) malloc(sizeof(ClassEntry*) * traceData->numClasses); 2141 for (ii = 0; ii < traceData->numClasses; ++ii) 2142 pClasses[ii] = &traceData->classes[ii]; 2143 2144 /* Sort the classes into decreasing order of exclusive time */ 2145 qsort(pClasses, traceData->numClasses, sizeof(ClassEntry*), compareClassExclusive); 2146 2147 if (gOptions.outputHtml) { 2148 printf("<div class=\"header\"><span class=\"parent\"> </span> "); 2149 printf("Cycles %%/total Cumul.%% Calls+Recur Class</div>\n"); 2150 } else { 2151 printf(" Cycles %%/total Cumul.%% Calls+Recur Class\n"); 2152 } 2153 2154 sum = 0; 2155 for (ii = 0; ii < traceData->numClasses; ++ii) { 2156 char *className, *methodName, *signature; 2157 2158 /* Skip classes with zero cycles */ 2159 pClass = pClasses[ii]; 2160 if (pClass->elapsedExclusive == 0) 2161 break; 2162 2163 per = 100.0 * pClass->elapsedExclusive / total; 2164 sum += pClass->elapsedExclusive; 2165 sum_per = 100.0 * sum / total; 2166 className = (char*)(pClass->className); 2167 if (gOptions.outputHtml) { 2168 char buf[80]; 2169 2170 className = htmlEscape(className, classBuf, HTML_BUFSIZE); 2171 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); 2172 sprintf(buf, "%llu", pClass->elapsedExclusive); 2173 printHtmlField(buf, 9); 2174 printf(" "); 2175 sprintf(buf, "%.1f", per); 2176 printHtmlField(buf, 7); 2177 printf(" "); 2178 sprintf(buf, "%.1f", sum_per); 2179 printHtmlField(buf, 7); 2180 printf(" "); 2181 sprintf(buf, "%d", pClass->numCalls[0]); 2182 printHtmlField(buf, 6); 2183 printf("+"); 2184 sprintf(buf, "%d", pClass->numCalls[1]); 2185 printHtmlField(buf, -6); 2186 printf(" "); 2187 printf("%s", className); 2188 printf("</div>\n"); 2189 printf("<div class=\"parent\" id=\"d%d\">\n", ii); 2190 } else { 2191 printf("---------------------------------------------\n"); 2192 printf("%9llu %7.1f %7.1f %6d+%-6d %s\n", 2193 pClass->elapsedExclusive, per, sum_per, 2194 pClass->numCalls[0], pClass->numCalls[1], 2195 className); 2196 } 2197 2198 int numMethods = pClass->numMethods; 2199 double classExclusive = pClass->elapsedExclusive; 2200 double sumMethods = 0; 2201 for (jj = 0; jj < numMethods; ++jj) { 2202 method = pClass->methods[jj]; 2203 methodName = (char*)(method->methodName); 2204 signature = (char*)(method->signature); 2205 per = 100.0 * method->elapsedExclusive / classExclusive; 2206 sumMethods += method->elapsedExclusive; 2207 sum_per = 100.0 * sumMethods / classExclusive; 2208 if (gOptions.outputHtml) { 2209 char buf[80]; 2210 2211 methodName = htmlEscape(methodName, methodBuf, HTML_BUFSIZE); 2212 signature = htmlEscape(signature, signatureBuf, HTML_BUFSIZE); 2213 printf("<div class=\"leaf\"><span class=\"leaf\"> </span>"); 2214 sprintf(buf, "%llu", method->elapsedExclusive); 2215 printHtmlField(buf, 9); 2216 printf(" "); 2217 sprintf(buf, "%llu", method->elapsedInclusive); 2218 printHtmlField(buf, 9); 2219 printf(" "); 2220 sprintf(buf, "%.1f", per); 2221 printHtmlField(buf, 7); 2222 printf(" "); 2223 sprintf(buf, "%.1f", sum_per); 2224 printHtmlField(buf, 7); 2225 printf(" "); 2226 sprintf(buf, "%d", method->numCalls[0]); 2227 printHtmlField(buf, 6); 2228 printf("+"); 2229 sprintf(buf, "%d", method->numCalls[1]); 2230 printHtmlField(buf, -6); 2231 printf(" "); 2232 printf("<a href=\"#m%d\">[%d]</a> %s %s", 2233 method->index, method->index, methodName, signature); 2234 printf("</div>\n"); 2235 } else { 2236 printf("%9llu %9llu %7.1f %7.1f %6d+%-6d [%d] %s %s\n", 2237 method->elapsedExclusive, 2238 method->elapsedInclusive, 2239 per, sum_per, 2240 method->numCalls[0], method->numCalls[1], 2241 method->index, methodName, signature); 2242 } 2243 } 2244 if (gOptions.outputHtml) { 2245 printf("</div>\n"); 2246 } 2247 } 2248 } 2249 2250 void createUniqueMethodList(TraceData* traceData, MethodEntry **pMethods, int numMethods) 2251 { 2252 int ii; 2253 2254 /* Sort the methods into alphabetical order of method names 2255 * to find the unique method names. 2256 */ 2257 qsort(pMethods, numMethods, sizeof(MethodEntry*), compareMethodNames); 2258 2259 /* Count the number of unique method names, ignoring class and 2260 * signature. 2261 */ 2262 const char *currentMethodName = ""; 2263 traceData->numUniqueMethods = 0; 2264 for (ii = 0; ii < numMethods; ++ii) { 2265 if (pMethods[ii]->methodName == NULL) 2266 continue; 2267 if (strcmp(pMethods[ii]->methodName, currentMethodName) != 0) { 2268 traceData->numUniqueMethods += 1; 2269 currentMethodName = pMethods[ii]->methodName; 2270 } 2271 } 2272 if (traceData->numUniqueMethods == 0) 2273 return; 2274 2275 /* Allocate space for pointers to all of the unique methods */ 2276 int nbytes = sizeof(UniqueMethodEntry) * traceData->numUniqueMethods; 2277 traceData->uniqueMethods = (UniqueMethodEntry *) malloc(nbytes); 2278 2279 /* Initialize the uniqueMethods array */ 2280 memset(traceData->uniqueMethods, 0, nbytes); 2281 UniqueMethodEntry *pUnique = traceData->uniqueMethods; 2282 currentMethodName = NULL; 2283 int prevNumMethods = 0; 2284 for (ii = 0; ii < numMethods; ++ii) { 2285 if (pMethods[ii]->methodName == NULL) 2286 continue; 2287 if (currentMethodName == NULL) 2288 currentMethodName = pMethods[ii]->methodName; 2289 if (strcmp(pMethods[ii]->methodName, currentMethodName) != 0) { 2290 currentMethodName = pMethods[ii]->methodName; 2291 pUnique->numMethods = prevNumMethods; 2292 pUnique++; 2293 prevNumMethods = 0; 2294 } 2295 prevNumMethods += 1; 2296 } 2297 pUnique->numMethods = prevNumMethods; 2298 2299 /* Create the array of MethodEntry pointers for each unique method */ 2300 pUnique = NULL; 2301 currentMethodName = ""; 2302 int nextMethod = 0; 2303 for (ii = 0; ii < numMethods; ++ii) { 2304 if (pMethods[ii]->methodName == NULL) 2305 continue; 2306 if (strcmp(pMethods[ii]->methodName, currentMethodName) != 0) { 2307 currentMethodName = pMethods[ii]->methodName; 2308 if (pUnique == NULL) 2309 pUnique = traceData->uniqueMethods; 2310 else 2311 pUnique++; 2312 /* Allocate space for the methods array */ 2313 int nbytes = sizeof(MethodEntry*) * pUnique->numMethods; 2314 pUnique->methods = (MethodEntry**) malloc(nbytes); 2315 nextMethod = 0; 2316 } 2317 pUnique->methods[nextMethod++] = pMethods[ii]; 2318 } 2319 } 2320 2321 void printMethodProfiles(TraceData* traceData, uint64_t sumThreadTime) 2322 { 2323 int ii, jj; 2324 MethodEntry* method; 2325 double total, sum, per, sum_per; 2326 char classBuf[HTML_BUFSIZE], methodBuf[HTML_BUFSIZE]; 2327 char signatureBuf[HTML_BUFSIZE]; 2328 2329 if (traceData->numUniqueMethods == 0) 2330 return; 2331 2332 total = sumThreadTime; 2333 if (gOptions.outputHtml) { 2334 printf("<a name=\"method\"></a>\n"); 2335 printf("<hr>\n"); 2336 outputNavigationBar(); 2337 } else { 2338 printf("\n%s\n", profileSeparator); 2339 } 2340 2341 printf("\nExclusive elapsed time for each method, summed over all the classes\n"); 2342 printf("that contain a method with the same name.\n\n"); 2343 if (gOptions.outputHtml) { 2344 printf("<br><br>\n"); 2345 } 2346 2347 /* For each unique method, sum the exclusive times in all of the methods 2348 * with the same name. Also sum the number of method calls. Also 2349 * sort the methods so the most expensive appear at the top. 2350 */ 2351 UniqueMethodEntry *pUnique = traceData->uniqueMethods; 2352 for (ii = 0; ii < traceData->numUniqueMethods; ++ii, ++pUnique) { 2353 int numMethods = pUnique->numMethods; 2354 for (jj = 0; jj < numMethods; ++jj) { 2355 method = pUnique->methods[jj]; 2356 pUnique->elapsedExclusive += method->elapsedExclusive; 2357 pUnique->numCalls[0] += method->numCalls[0]; 2358 pUnique->numCalls[1] += method->numCalls[1]; 2359 } 2360 2361 /* Sort the methods into decreasing order of exclusive time */ 2362 qsort(pUnique->methods, numMethods, sizeof(MethodEntry*), 2363 compareElapsedExclusive); 2364 } 2365 2366 /* Allocate an array of pointers to the methods for more efficient 2367 * sorting. 2368 */ 2369 UniqueMethodEntry **pUniqueMethods; 2370 int nbytes = sizeof(UniqueMethodEntry*) * traceData->numUniqueMethods; 2371 pUniqueMethods = (UniqueMethodEntry**) malloc(nbytes); 2372 for (ii = 0; ii < traceData->numUniqueMethods; ++ii) 2373 pUniqueMethods[ii] = &traceData->uniqueMethods[ii]; 2374 2375 /* Sort the methods into decreasing order of exclusive time */ 2376 qsort(pUniqueMethods, traceData->numUniqueMethods, sizeof(UniqueMethodEntry*), 2377 compareUniqueExclusive); 2378 2379 if (gOptions.outputHtml) { 2380 printf("<div class=\"header\"><span class=\"parent\"> </span> "); 2381 printf("Cycles %%/total Cumul.%% Calls+Recur Method</div>\n"); 2382 } else { 2383 printf(" Cycles %%/total Cumul.%% Calls+Recur Method\n"); 2384 } 2385 2386 sum = 0; 2387 for (ii = 0; ii < traceData->numUniqueMethods; ++ii) { 2388 char *className, *methodName, *signature; 2389 2390 /* Skip methods with zero cycles */ 2391 pUnique = pUniqueMethods[ii]; 2392 if (pUnique->elapsedExclusive == 0) 2393 break; 2394 2395 per = 100.0 * pUnique->elapsedExclusive / total; 2396 sum += pUnique->elapsedExclusive; 2397 sum_per = 100.0 * sum / total; 2398 methodName = (char*)(pUnique->methods[0]->methodName); 2399 if (gOptions.outputHtml) { 2400 char buf[80]; 2401 2402 methodName = htmlEscape(methodName, methodBuf, HTML_BUFSIZE); 2403 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); 2404 sprintf(buf, "%llu", pUnique->elapsedExclusive); 2405 printHtmlField(buf, 9); 2406 printf(" "); 2407 sprintf(buf, "%.1f", per); 2408 printHtmlField(buf, 7); 2409 printf(" "); 2410 sprintf(buf, "%.1f", sum_per); 2411 printHtmlField(buf, 7); 2412 printf(" "); 2413 sprintf(buf, "%d", pUnique->numCalls[0]); 2414 printHtmlField(buf, 6); 2415 printf("+"); 2416 sprintf(buf, "%d", pUnique->numCalls[1]); 2417 printHtmlField(buf, -6); 2418 printf(" "); 2419 printf("%s", methodName); 2420 printf("</div>\n"); 2421 printf("<div class=\"parent\" id=\"e%d\">\n", ii); 2422 } else { 2423 printf("---------------------------------------------\n"); 2424 printf("%9llu %7.1f %7.1f %6d+%-6d %s\n", 2425 pUnique->elapsedExclusive, per, sum_per, 2426 pUnique->numCalls[0], pUnique->numCalls[1], 2427 methodName); 2428 } 2429 int numMethods = pUnique->numMethods; 2430 double methodExclusive = pUnique->elapsedExclusive; 2431 double sumMethods = 0; 2432 for (jj = 0; jj < numMethods; ++jj) { 2433 method = pUnique->methods[jj]; 2434 className = (char*)(method->className); 2435 signature = (char*)(method->signature); 2436 per = 100.0 * method->elapsedExclusive / methodExclusive; 2437 sumMethods += method->elapsedExclusive; 2438 sum_per = 100.0 * sumMethods / methodExclusive; 2439 if (gOptions.outputHtml) { 2440 char buf[80]; 2441 2442 className = htmlEscape(className, classBuf, HTML_BUFSIZE); 2443 signature = htmlEscape(signature, signatureBuf, HTML_BUFSIZE); 2444 printf("<div class=\"leaf\"><span class=\"leaf\"> </span>"); 2445 sprintf(buf, "%llu", method->elapsedExclusive); 2446 printHtmlField(buf, 9); 2447 printf(" "); 2448 sprintf(buf, "%llu", method->elapsedInclusive); 2449 printHtmlField(buf, 9); 2450 printf(" "); 2451 sprintf(buf, "%.1f", per); 2452 printHtmlField(buf, 7); 2453 printf(" "); 2454 sprintf(buf, "%.1f", sum_per); 2455 printHtmlField(buf, 7); 2456 printf(" "); 2457 sprintf(buf, "%d", method->numCalls[0]); 2458 printHtmlField(buf, 6); 2459 printf("+"); 2460 sprintf(buf, "%d", method->numCalls[1]); 2461 printHtmlField(buf, -6); 2462 printf(" "); 2463 printf("<a href=\"#m%d\">[%d]</a> %s.%s %s", 2464 method->index, method->index, 2465 className, methodName, signature); 2466 printf("</div>\n"); 2467 } else { 2468 printf("%9llu %9llu %7.1f %7.1f %6d+%-6d [%d] %s.%s %s\n", 2469 method->elapsedExclusive, 2470 method->elapsedInclusive, 2471 per, sum_per, 2472 method->numCalls[0], method->numCalls[1], 2473 method->index, className, methodName, signature); 2474 } 2475 } 2476 if (gOptions.outputHtml) { 2477 printf("</div>\n"); 2478 } 2479 } 2480 } 2481 2482 /* 2483 * Determines whether the given FilterKey matches the method. The FilterKey's 2484 * key that is used to match against the method is determined by index. 2485 */ 2486 int keyMatchesMethod(FilterKey filterKey, MethodEntry* method, int index) 2487 { 2488 if (filterKey.type[index] == 0) { // Class 2489 #if 0 2490 fprintf(stderr, " class is %s; filter key is %s\n", method->className, filterKey.keys[index]); 2491 #endif 2492 if (strcmp(method->className, filterKey.keys[index]) == 0) { 2493 return 1; 2494 } 2495 } else { // Method 2496 if (method->methodName != NULL) { 2497 // Get fully-qualified name 2498 // TODO: parse class name and method name an put them in structure to avoid 2499 // allocating memory here 2500 char* str = malloc ((strlen(method->className) + strlen(method->methodName) + 2) * sizeof(char)); 2501 strcpy(str, method->className); 2502 strcat(str, "."); 2503 strcat(str, method->methodName); 2504 #if 0 2505 fprintf(stderr, " method is %s; filter key is %s\n", str, filterKey.keys[index]); 2506 #endif 2507 if (strcmp(str, filterKey.keys[index]) == 0) { 2508 free(str); 2509 return 1; 2510 } 2511 free(str); 2512 } 2513 } 2514 return 0; 2515 } 2516 2517 /* 2518 * Adds the appropriate times to the given filter based on the given method. Activates and 2519 * de-activates filters as necessary. 2520 * 2521 * A filter is activated when the given method matches the 'entry' key of one of its FilterKeys. 2522 * It is de-activated when the method matches the 'exit' key of the same FilterKey that activated it 2523 * in the first place. Thus, a filter may be active more than once on the same thread (activated by 2524 * different FilterKeys). A filter may also be active on different threads at the same time. 2525 * 2526 * While the filter is active on thread 1, elapsed time is allocated to different buckets which 2527 * include: thread execution time (i.e., time thread 1 spent executing while filter was active), 2528 * thread waiting time (i.e., time thread 1 waited while other threads executed), and execution 2529 * time while waiting (i.e., time thread x spent executing while thread 1 was waiting). We also 2530 * keep track of the total waiting time for a given filter. 2531 * 2532 * Lastly, we keep track of remaining (un-allocated) time for cases in which we exit a method we 2533 * had not entered before, and that method happens to match the 'exit' key of a FilterKey. 2534 */ 2535 int filterMethod(MethodEntry* method, Filter* filter, int entry, int threadId, int numThreads, 2536 uint64_t elapsed, uint64_t remTime) 2537 { 2538 int ii, jj; 2539 int activeCount, addedWaitTimeThreadsCount; 2540 int* activeThreads; 2541 int* activationKeys; 2542 int* addedWaitTimeThreads; 2543 2544 // flags 2545 int addWaitTime = 0; 2546 int deactivation = 0; 2547 int addedExecutionTime = 0; 2548 int addedExecutionTimeWhileWaiting = 0; 2549 int addedWaitTime; 2550 int addedRemTime = 0; 2551 int threadKeyPairActive = 0; 2552 2553 if (filter->times.threadWaitTimes == NULL && filter->times.threadExecutionTimes == NULL && 2554 filter->times.threadExecutionTimesWhileWaiting == NULL) { 2555 filter->times.threadWaitTimes = (uint64_t*) calloc(MAX_THREADS, sizeof(uint64_t)); 2556 filter->times.threadExecutionTimesWhileWaiting = 2557 (uint64_t*) calloc(MAX_THREADS, sizeof(uint64_t)); 2558 filter->times.threadExecutionTimes = (uint64_t*) calloc(MAX_THREADS, sizeof(uint64_t)); 2559 } 2560 2561 int verbose = 0; 2562 2563 if (verbose) 2564 fprintf(stderr, 2565 "Running %s filter for class %s method %s, thread %d; activeCount: %d time: %llu\n", 2566 filter->filterName, method->className, method->methodName, threadId, 2567 filter->activeCount, elapsed); 2568 2569 // If active on some thread 2570 if (filter->activeCount > 0) { 2571 2572 // Initialize active structures in case there are any de-activations 2573 activeThreads = (int*) calloc(filter->activeCount, sizeof(int)); 2574 activationKeys = (int*) calloc(filter->activeCount, sizeof(int)); 2575 activeCount = 0; 2576 2577 // Initialize structure to help us determine which threads we've already added wait time to 2578 addedWaitTimeThreads = (int*) calloc(filter->activeCount, sizeof(int)); 2579 addedWaitTimeThreadsCount = 0; 2580 2581 // Add times to appropriate sums and de-activate (if necessary) 2582 for (ii = 0; ii < filter->activeCount; ii++) { 2583 2584 if (verbose) { 2585 fprintf(stderr, " Analyzing active thread with id %d, activated by key [%s, %s]\n", 2586 filter->activeThreads[ii], 2587 filter->filterKeys[filter->activationKeys[ii]].keys[0], 2588 filter->filterKeys[filter->activationKeys[ii]].keys[1]); 2589 } 2590 2591 // If active on THIS thread -> add to execution time (only add once!) 2592 if (filter->activeThreads[ii] == threadId && !addedExecutionTime) { 2593 if (verbose) 2594 fprintf(stderr, " Adding execution time to this thead\n"); 2595 filter->times.threadExecutionTimes[threadId] += elapsed; 2596 addedExecutionTime = 1; 2597 } 2598 2599 // If active on ANOTHER thread (or this one too) with CROSS_THREAD_FLAG -> add to 2600 // both thread's waiting time + total 2601 if (filter->filterKeys[filter->activationKeys[ii]].flags == 1) { 2602 2603 // Add time to thread that is waiting (add to each waiting thread at most once!) 2604 addedWaitTime = 0; 2605 for (jj = 0; jj < addedWaitTimeThreadsCount; jj++) { 2606 if (addedWaitTimeThreads[jj] == filter->activeThreads[ii]) 2607 addedWaitTime = 1; 2608 } 2609 if (!addedWaitTime) { 2610 if (verbose) 2611 fprintf(stderr, " Adding wait time to waiting thread\n"); 2612 filter->times.threadWaitTimes[filter->activeThreads[ii]] += elapsed; 2613 addedWaitTimeThreads[addedWaitTimeThreadsCount++] = filter->activeThreads[ii]; 2614 } 2615 2616 // Add execution time to this thread while the other is waiting (only add once!) 2617 // [Flag is needed only because outside for loop might iterate through same 2618 // thread twice?] TODO: verify 2619 if (!addedExecutionTimeWhileWaiting) { 2620 if (verbose) 2621 fprintf(stderr, " Adding exec time to this thread while thread waits\n"); 2622 filter->times.threadExecutionTimesWhileWaiting[threadId] += elapsed; 2623 addedExecutionTimeWhileWaiting = 1; 2624 } 2625 2626 addWaitTime = 1; 2627 } 2628 2629 // If a method exit matches the EXIT method of an ACTIVE key -> de-activate 2630 // the KEY (not the entire filter!!) 2631 if (!entry && keyMatchesMethod(filter->filterKeys[filter->activationKeys[ii]], 2632 method, 1)) { 2633 if (verbose) 2634 fprintf(stderr, " Exit key matched!\n"); 2635 2636 // Deactivate by removing (NOT adding) entries from activeThreads and activationKeys 2637 deactivation = 1; // singal that lists should be replaced 2638 } else { 2639 // No de-activation -> copy old entries into new lists 2640 activeThreads[activeCount] = filter->activeThreads[ii]; 2641 activationKeys[activeCount++] = filter->activationKeys[ii]; 2642 } 2643 } 2644 2645 // If waiting on ANY thread, add wait time to total (but only ONCE!) 2646 if (addWaitTime) { 2647 filter->times.totalWaitTime += elapsed; 2648 } 2649 2650 // If de-activation occurred, replace lists 2651 if (deactivation) { 2652 // TODO: Free memory from old lists 2653 2654 // Set new lists 2655 filter->activeThreads = activeThreads; 2656 filter->activationKeys = activationKeys; 2657 filter->activeCount = activeCount; 2658 } else { 2659 // TODO: Free memory from new lists 2660 } 2661 2662 } // Else, continue (we might be activating the filter on a different thread) 2663 2664 2665 if (entry) { // ENTRY 2666 if (verbose) 2667 fprintf(stderr, " Here at the entry\n"); 2668 // If method matches entry key -> activate thread (do not add time since it's a new entry!) 2669 for (ii = 0; ii < filter->numKeys; ii++) { 2670 if (keyMatchesMethod(filter->filterKeys[ii], method, 0)) { 2671 if (verbose) 2672 fprintf(stderr, " Entry key matched!\n"); 2673 // Activate thread only if thread/key pair is not already active 2674 for (jj = 0; jj < filter->activeCount; jj++) { 2675 if (filter->activeThreads[jj] == threadId && filter->activationKeys[jj] == ii) 2676 threadKeyPairActive = 1; 2677 } 2678 // TODO: WORRY ABOUT MEMORY WHEN ACTIVE_COUNT > DEFAULT_ACTIVE_THREAD (unlikely) 2679 // TODO: what if the same thread is active multiple times by different keys? 2680 // nothing, we just have to make sure we dont double-add, and we dont.. 2681 if (!threadKeyPairActive) { 2682 filter->activeThreads[filter->activeCount] = threadId; 2683 filter->activationKeys[filter->activeCount++] = ii; 2684 } 2685 } 2686 } 2687 } else { // EXIT 2688 // If method matches a terminal key -> add remTime to total (no need to active/de-activate) 2689 for (ii = 0; ii < filter->numKeys; ii++) { 2690 if (!deactivation && keyMatchesMethod(filter->filterKeys[ii], method, 1) && 2691 keyMatchesMethod(filter->filterKeys[ii], method, 0)) { 2692 // Add remTime(s) 2693 // TODO: think about how we should add remTimes.. should we add remTime to threads 2694 // that were waiting or being waited on? for now, keep it simple and just add the 2695 // execution time to the current thread. 2696 filter->times.threadExecutionTimes[threadId] += remTime; 2697 addedRemTime = 1; 2698 } 2699 } 2700 } 2701 2702 return addedExecutionTime | (addedRemTime << 1); 2703 } 2704 2705 void dumpFilters(Filter** filters) { 2706 int i; 2707 for (i = 0; i < numFilters; i++) { 2708 int j; 2709 fprintf(stderr, "FILTER %s\n", filters[i]->filterName); 2710 for (j = 0; j < filters[i]->numKeys; j++) { 2711 fprintf(stderr, "Keys: %s, type %d", filters[i]->filterKeys[j].keys[0], 2712 filters[i]->filterKeys[j].type[0]); 2713 if (filters[i]->filterKeys[j].keys[1] != NULL) { 2714 fprintf(stderr, " AND %s, type %d", filters[i]->filterKeys[j].keys[1], 2715 filters[i]->filterKeys[j].type[1]); 2716 } 2717 fprintf(stderr, "; flags: %d\n", filters[i]->filterKeys[j].flags); 2718 } 2719 } 2720 } 2721 2722 /* 2723 * See parseFilters for required data format. 2724 * 'data' must point to the beginning of a filter definition. 2725 */ 2726 char* parseFilter(char* data, char* dataEnd, Filter** filters, int num) { 2727 2728 Filter* filter; 2729 int next, count, i; 2730 int tmpOffset, tmpKeyLen; 2731 char* tmpKey; 2732 char* key1; 2733 char* key2; 2734 2735 filter = (Filter*) malloc(sizeof(Filter)); 2736 filter->activeCount = 0; 2737 filter->activeThreads = (int*) calloc(DEFAULT_ACTIVE_THREADS, sizeof(int)); 2738 filter->activationKeys = (int*) calloc(DEFAULT_ACTIVE_THREADS, sizeof(int)); 2739 2740 next = findNextChar(data + 1, dataEnd - data - 1, '\n'); 2741 if (next < 0) { 2742 // TODO: what should we do here? 2743 // End of file reached... 2744 } 2745 data[next+1] = '\0'; 2746 filter->filterName = data + 1; 2747 data += next + 2; // Careful 2748 2749 /* 2750 * Count the number of keys (one per line). 2751 */ 2752 count = countLinesToChar(data, dataEnd - data, FILTER_TAG); 2753 if (count <= 0) { 2754 fprintf(stderr, 2755 "ERROR: failed while parsing filter %s (found %d keys)\n", 2756 filter->filterName, count); 2757 return NULL; // TODO: Should do something else 2758 // Could return filter with 0 keys instead (probably better to avoid random segfaults) 2759 } 2760 2761 filter->filterKeys = (FilterKey*) malloc(sizeof(FilterKey) * count); 2762 2763 /* 2764 * Extract all entries. 2765 */ 2766 tmpOffset = 0; 2767 for (i = 0; i < count; i++) { 2768 next = findNextChar(data, dataEnd - data, '\n'); 2769 // assert(next > 0); // TODO: revise... (skip if next == 0 ?) 2770 data[next] = '\0'; 2771 tmpKey = data; 2772 2773 if (*data == FILTER_FLAG_THREAD) { 2774 filter->filterKeys[i].flags = 1; 2775 tmpKey++; 2776 } else { 2777 filter->filterKeys[i].flags = 0; 2778 } 2779 2780 tmpOffset = findNextChar(tmpKey, next, ','); 2781 2782 if (tmpOffset < 0) { 2783 // No comma, so only 1 key 2784 key1 = tmpKey; 2785 key2 = tmpKey; 2786 2787 // Get type for key1 2788 filter->filterKeys[i].type[0] = FILTER_TYPE_CLASS; // default 2789 tmpOffset = findNextChar(key1, next, '('); 2790 if (tmpOffset > 0) { 2791 if (findNextChar(key1, next, ')') == tmpOffset + 1) { 2792 filter->filterKeys[i].type[0] = FILTER_TYPE_METHOD; 2793 filter->filterKeys[i].type[1] = FILTER_TYPE_METHOD; 2794 } 2795 key1[tmpOffset] = '\0'; 2796 } 2797 } else { 2798 // Pair of keys 2799 tmpKey[tmpOffset] = '\0'; 2800 key1 = tmpKey; 2801 key2 = tmpKey + tmpOffset + 1; 2802 2803 // Get type for key1 2804 filter->filterKeys[i].type[0] = FILTER_TYPE_CLASS; 2805 tmpKeyLen = tmpOffset; 2806 tmpOffset = findNextChar(key1, tmpKeyLen, '('); 2807 if (tmpOffset > 0) { 2808 if (findNextChar(key1, tmpKeyLen, ')') == tmpOffset + 1) { 2809 filter->filterKeys[i].type[0] = FILTER_TYPE_METHOD; 2810 } 2811 key1[tmpOffset] = '\0'; 2812 } 2813 2814 // Get type for key2 2815 filter->filterKeys[i].type[1] = FILTER_TYPE_CLASS; 2816 tmpOffset = findNextChar(key2, next - tmpKeyLen, '('); 2817 if (tmpOffset > 0) { 2818 if (findNextChar(key2, next - tmpKeyLen, ')') == tmpOffset + 1) { 2819 filter->filterKeys[i].type[1] = FILTER_TYPE_METHOD; 2820 } 2821 key2[tmpOffset] = '\0'; 2822 } 2823 } 2824 2825 filter->filterKeys[i].keys[0] = key1; 2826 filter->filterKeys[i].keys[1] = key2; 2827 data += next+1; 2828 } 2829 2830 filter->numKeys = count; 2831 filters[num] = filter; 2832 2833 return data; 2834 } 2835 2836 /* 2837 * Parses filters from given file. The file must follow the following format: 2838 * 2839 * *FilterName <- creates a new filter with keys to follow 2840 * A.method() <- key that triggers whenever A.method() enters/exit 2841 * Class <- key that triggers whenever any method from Class enters/exits 2842 * +CrossThread <- same as above, but keeps track of execution times accross threads 2843 * B.m(),C.m() <- key that triggers filter on when B.m() enters and off when C.m() exits 2844 * 2845 * TODO: add concrete example to make things clear 2846 */ 2847 Filter** parseFilters(const char* filterFileName) { 2848 2849 Filter** filters = NULL; 2850 FILE* fp = NULL; 2851 long len; 2852 char* data; 2853 char* dataEnd; 2854 char* dataStart; 2855 int i, next, count; 2856 2857 fp = fopen(filterFileName, "r"); 2858 if (fp == NULL) 2859 goto bail; 2860 2861 if (fseek(fp, 0L, SEEK_END) != 0) { 2862 perror("fseek"); 2863 goto bail; 2864 } 2865 2866 len = ftell(fp); 2867 if (len == 0) { 2868 fprintf(stderr, "WARNING: Filter file is empty.\n"); 2869 goto bail; 2870 } 2871 rewind(fp); 2872 2873 data = (char*) malloc(len); 2874 if (data == NULL) { 2875 fprintf(stderr, "ERROR: unable to alloc %ld bytes for filter file\n", len); 2876 goto bail; 2877 } 2878 2879 // Read file into memory 2880 if (fread(data, 1, len, fp) != (size_t) len) { 2881 fprintf(stderr, "ERROR: unable to read %ld bytes from filter file\n", len); 2882 goto bail; 2883 } 2884 2885 dataStart = data; 2886 dataEnd = data + len; 2887 2888 // Figure out how many filters there are 2889 numFilters = 0; 2890 next = -1; 2891 2892 while (1) { 2893 if (*data == FILTER_TAG) 2894 numFilters++; 2895 next = findNextChar(data, len, '\n'); 2896 if (next < 0) 2897 break; 2898 data += next+1; 2899 len -= next+1; 2900 } 2901 2902 if (numFilters == 0) { 2903 fprintf(stderr, "WARNING: no filters found. Continuing without filters\n"); 2904 goto bail; 2905 } 2906 2907 filters = (Filter**) calloc(numFilters, sizeof(Filter *)); 2908 if (filters == NULL) { 2909 fprintf(stderr, "ERROR: unable to alloc memory for filters"); 2910 goto bail; 2911 } 2912 2913 data = dataStart; 2914 for (i = 0; i < numFilters; i++) { 2915 data = parseFilter(data, dataEnd, filters, i); 2916 } 2917 2918 return filters; 2919 2920 bail: 2921 if (fp != NULL) 2922 fclose(fp); 2923 2924 return NULL; 2925 2926 } 2927 2928 2929 /* 2930 * Read the key and data files and return the MethodEntries for those files 2931 */ 2932 DataKeys* parseDataKeys(TraceData* traceData, const char* traceFileName, 2933 uint64_t* threadTime, Filter** filters) 2934 { 2935 DataKeys* dataKeys = NULL; 2936 MethodEntry **pMethods = NULL; 2937 MethodEntry* method; 2938 FILE* dataFp = NULL; 2939 DataHeader dataHeader; 2940 int ii, jj, numThreads; 2941 uint64_t currentTime; 2942 MethodEntry* caller; 2943 2944 dataFp = fopen(traceFileName, "r"); 2945 if (dataFp == NULL) 2946 goto bail; 2947 2948 if ((dataKeys = parseKeys(dataFp, 0)) == NULL) 2949 goto bail; 2950 2951 if (parseDataHeader(dataFp, &dataHeader) < 0) 2952 goto bail; 2953 2954 numThreads = dataKeys->numThreads; 2955 2956 #if 0 2957 FILE *dumpStream = fopen("debug", "w"); 2958 #endif 2959 while (1) { 2960 int threadId; 2961 unsigned int methodVal; 2962 int action; 2963 unsigned int methodId; 2964 CallStack *pStack; 2965 2966 /* 2967 * Extract values from file. 2968 */ 2969 if (readDataRecord(dataFp, &threadId, &methodVal, ¤tTime)) 2970 break; 2971 2972 action = METHOD_ACTION(methodVal); 2973 methodId = METHOD_ID(methodVal); 2974 2975 /* Get the call stack for this thread */ 2976 pStack = traceData->stacks[threadId]; 2977 2978 /* If there is no call stack yet for this thread, then allocate one */ 2979 if (pStack == NULL) { 2980 pStack = malloc(sizeof(CallStack)); 2981 pStack->top = 0; 2982 pStack->lastEventTime = currentTime; 2983 pStack->threadStartTime = currentTime; 2984 pStack->remTimes = (uint64_t*) calloc(numFilters, sizeof(uint64_t)); 2985 traceData->stacks[threadId] = pStack; 2986 } 2987 2988 /* Lookup the current method */ 2989 method = lookupMethod(dataKeys, methodId); 2990 if (method == NULL) 2991 method = &dataKeys->methods[UNKNOWN_INDEX]; 2992 2993 #if 0 2994 if (method->methodName) { 2995 fprintf(dumpStream, "%2d %-8llu %d %8llu r %d c %d %s.%s %s\n", 2996 threadId, currentTime, action, pStack->threadStartTime, 2997 method->recursiveEntries, 2998 pStack->top, method->className, method->methodName, 2999 method->signature); 3000 } else { 3001 printf(dumpStream, "%2d %-8llu %d %8llu r %d c %d %s\n", 3002 threadId, currentTime, action, pStack->threadStartTime, 3003 method->recursiveEntries, 3004 pStack->top, method->className); 3005 } 3006 #endif 3007 3008 if (action == METHOD_TRACE_ENTER) { 3009 /* This is a method entry */ 3010 if (pStack->top >= MAX_STACK_DEPTH) { 3011 fprintf(stderr, "Stack overflow (exceeded %d frames)\n", 3012 MAX_STACK_DEPTH); 3013 exit(1); 3014 } 3015 3016 /* Get the caller method */ 3017 if (pStack->top >= 1) 3018 caller = pStack->calls[pStack->top - 1].method; 3019 else 3020 caller = &dataKeys->methods[TOPLEVEL_INDEX]; 3021 countRecursiveEntries(pStack, pStack->top, caller); 3022 caller->elapsedExclusive += currentTime - pStack->lastEventTime; 3023 #if 0 3024 if (caller->elapsedExclusive > 10000000) 3025 fprintf(dumpStream, "%llu current %llu last %llu diff %llu\n", 3026 caller->elapsedExclusive, currentTime, 3027 pStack->lastEventTime, 3028 currentTime - pStack->lastEventTime); 3029 #endif 3030 if (caller->recursiveEntries <= 1) { 3031 caller->topExclusive += currentTime - pStack->lastEventTime; 3032 } 3033 3034 /* Push the method on the stack for this thread */ 3035 pStack->calls[pStack->top].method = method; 3036 pStack->calls[pStack->top++].entryTime = currentTime; 3037 3038 // For each filter 3039 int result = 0; 3040 for (ii = 0; ii < numFilters; ii++) { 3041 result = filterMethod(method, filters[ii], 1, threadId, numThreads, 3042 currentTime - pStack->lastEventTime, pStack->remTimes[ii]); 3043 3044 // TODO: make remTimes work properly 3045 // Consider moving remTimes handling together with the rest 3046 // of time handling and clean up the return codes 3047 /* 3048 if (result == 0) { // no time added, no remTime added 3049 pStack->remTimes[ii] += currentTime - pStack->lastEventTime; 3050 } else if (result == 3 || result == 4) { // remTime added 3051 // Reset remTime, since it's been added 3052 pStack->remTimes[ii] = 0; 3053 } 3054 */ 3055 } 3056 3057 } else { 3058 /* This is a method exit */ 3059 uint64_t entryTime = 0; 3060 3061 /* Pop the method off the stack for this thread */ 3062 if (pStack->top > 0) { 3063 pStack->top -= 1; 3064 entryTime = pStack->calls[pStack->top].entryTime; 3065 if (method != pStack->calls[pStack->top].method) { 3066 if (method->methodName) { 3067 fprintf(stderr, 3068 "Exit from method %s.%s %s does not match stack:\n", 3069 method->className, method->methodName, 3070 method->signature); 3071 } else { 3072 fprintf(stderr, 3073 "Exit from method %s does not match stack:\n", 3074 method->className); 3075 } 3076 stackDump(pStack, pStack->top + 1); 3077 exit(1); 3078 } 3079 } 3080 3081 /* Get the caller method */ 3082 if (pStack->top >= 1) 3083 caller = pStack->calls[pStack->top - 1].method; 3084 else 3085 caller = &dataKeys->methods[TOPLEVEL_INDEX]; 3086 countRecursiveEntries(pStack, pStack->top, caller); 3087 countRecursiveEntries(pStack, pStack->top, method); 3088 uint64_t elapsed = currentTime - entryTime; 3089 addInclusiveTime(caller, method, elapsed); 3090 method->elapsedExclusive += currentTime - pStack->lastEventTime; 3091 if (method->recursiveEntries == 0) { 3092 method->topExclusive += currentTime - pStack->lastEventTime; 3093 } 3094 3095 // For each filter 3096 int result = 0; 3097 for (ii = 0; ii < numFilters; ii++) { 3098 result = filterMethod(method, filters[ii], 0, threadId, numThreads, 3099 currentTime - pStack->lastEventTime, pStack->remTimes[ii]); 3100 3101 // TODO: make remTimes work properly 3102 /* 3103 if (result == 0) { // no time added, no remTime added 3104 pStack->remTimes[ii] += currentTime - pStack->lastEventTime; 3105 } else if (result == 3 || result == 4) { // remTime added 3106 // Reset remTime, since it's been added 3107 pStack->remTimes[ii] = 0; 3108 } 3109 */ 3110 } 3111 3112 } 3113 /* Remember the time of the last entry or exit event */ 3114 pStack->lastEventTime = currentTime; 3115 } 3116 3117 /* If we have calls on the stack when the trace ends, then clean 3118 * up the stack and add time to the callers by pretending that we 3119 * are exiting from their methods now. 3120 */ 3121 CallStack *pStack; 3122 int threadId; 3123 uint64_t elapsedTime = 0; 3124 uint64_t sumThreadTime = 0; 3125 for (threadId = 0; threadId < MAX_THREADS; ++threadId) { 3126 3127 pStack = traceData->stacks[threadId]; 3128 3129 /* If this thread never existed, then continue with next thread */ 3130 if (pStack == NULL) 3131 continue; 3132 3133 /* Calculate times spent in thread, and add it to total time */ 3134 elapsedTime = pStack->lastEventTime - pStack->threadStartTime; 3135 sumThreadTime += elapsedTime; 3136 3137 for (ii = 0; ii < pStack->top; ++ii) { 3138 //printf("in loop\n"); 3139 3140 if (ii == 0) 3141 caller = &dataKeys->methods[TOPLEVEL_INDEX]; 3142 else 3143 caller = pStack->calls[ii - 1].method; 3144 method = pStack->calls[ii].method; 3145 countRecursiveEntries(pStack, ii, caller); 3146 countRecursiveEntries(pStack, ii, method); 3147 3148 uint64_t entryTime = pStack->calls[ii].entryTime; 3149 uint64_t elapsed = pStack->lastEventTime - entryTime; 3150 addInclusiveTime(caller, method, elapsed); 3151 3152 // For each filter 3153 int result = 0; 3154 for (ii = 0; ii < numFilters; ii++) { 3155 result = filterMethod(method, filters[ii], 0, threadId, numThreads, 3156 currentTime - pStack->lastEventTime, pStack->remTimes[ii]); 3157 3158 // TODO: make remTimes work properly 3159 /* 3160 if (result == 0) { // no time added, no remTime added 3161 pStack->remTimes[ii] += currentTime - pStack->lastEventTime; 3162 } else if (result == 3 || result == 4) { // remTime added 3163 // Reset remTime, since it's been added 3164 pStack->remTimes[ii] = 0; 3165 } 3166 */ 3167 } 3168 } 3169 3170 /* Save the per-thread elapsed time in the DataKeys struct */ 3171 for (ii = 0; ii < dataKeys->numThreads; ++ii) { 3172 if (dataKeys->threads[ii].threadId == threadId) { 3173 dataKeys->threads[ii].elapsedTime = elapsedTime; 3174 } 3175 } 3176 3177 3178 } 3179 caller = &dataKeys->methods[TOPLEVEL_INDEX]; 3180 caller->elapsedInclusive = sumThreadTime; 3181 3182 #if 0 3183 fclose(dumpStream); 3184 #endif 3185 3186 if (threadTime != NULL) { 3187 *threadTime = sumThreadTime; 3188 } 3189 3190 bail: 3191 if (dataFp != NULL) 3192 fclose(dataFp); 3193 3194 return dataKeys; 3195 } 3196 3197 MethodEntry** parseMethodEntries(DataKeys* dataKeys) 3198 { 3199 int ii; 3200 /* Create a new array of pointers to the methods and sort the pointers 3201 * instead of the actual MethodEntry structs. We need to do this 3202 * because there are other lists that contain pointers to the 3203 * MethodEntry structs. 3204 */ 3205 MethodEntry** pMethods = (MethodEntry**) malloc(sizeof(MethodEntry*) * dataKeys->numMethods); 3206 for (ii = 0; ii < dataKeys->numMethods; ++ii) { 3207 MethodEntry* entry = &dataKeys->methods[ii]; 3208 pMethods[ii] = entry; 3209 } 3210 3211 return pMethods; 3212 } 3213 3214 3215 /* 3216 * Produce a function profile from the following methods 3217 */ 3218 void profileTrace(TraceData* traceData, MethodEntry **pMethods, int numMethods, uint64_t sumThreadTime, 3219 ThreadEntry *pThreads, int numThreads, Filter** filters) 3220 { 3221 /* Print the html header, if necessary */ 3222 if (gOptions.outputHtml) { 3223 printf(htmlHeader, gOptions.sortableUrl); 3224 outputTableOfContents(); 3225 } 3226 3227 printExclusiveProfile(pMethods, numMethods, sumThreadTime); 3228 printInclusiveProfile(pMethods, numMethods, sumThreadTime); 3229 3230 printThreadProfile(pThreads, numThreads, sumThreadTime, filters); 3231 3232 createClassList(traceData, pMethods, numMethods); 3233 printClassProfiles(traceData, sumThreadTime); 3234 3235 createUniqueMethodList(traceData, pMethods, numMethods); 3236 printMethodProfiles(traceData, sumThreadTime); 3237 3238 if (gOptions.outputHtml) { 3239 printf("%s", htmlFooter); 3240 } 3241 } 3242 3243 int compareMethodNamesForDiff(const void *a, const void *b) 3244 { 3245 int result; 3246 3247 const MethodEntry *methodA = *(const MethodEntry**)a; 3248 const MethodEntry *methodB = *(const MethodEntry**)b; 3249 if (methodA->methodName == NULL || methodB->methodName == NULL) { 3250 return compareClassNames(a, b); 3251 } 3252 result = strcmp(methodA->methodName, methodB->methodName); 3253 if (result == 0) { 3254 result = strcmp(methodA->signature, methodB->signature); 3255 if (result == 0) { 3256 return strcmp(methodA->className, methodB->className); 3257 } 3258 } 3259 return result; 3260 } 3261 3262 int findMatch(MethodEntry** methods, int size, MethodEntry* matchThis) 3263 { 3264 int i; 3265 3266 for (i = 0 ; i < size ; i++) { 3267 MethodEntry* method = methods[i]; 3268 3269 if (method != NULL && !compareMethodNamesForDiff(&method, &matchThis)) { 3270 // printf("%s.%s == %s.%s<br>\n", matchThis->className, matchThis->methodName, 3271 // method->className, method->methodName); 3272 3273 return i; 3274 /* if (!compareMethodNames(&method, &matchThis)) { 3275 return i; 3276 } 3277 */ } 3278 } 3279 3280 return -1; 3281 } 3282 3283 int compareDiffEntriesExculsive(const void *a, const void *b) 3284 { 3285 int result; 3286 3287 const DiffEntry* entryA = (const DiffEntry*)a; 3288 const DiffEntry* entryB = (const DiffEntry*)b; 3289 3290 if (entryA->differenceExclusive < entryB->differenceExclusive) { 3291 return 1; 3292 } else if (entryA->differenceExclusive > entryB->differenceExclusive) { 3293 return -1; 3294 } 3295 3296 return 0; 3297 } 3298 3299 int compareDiffEntriesInculsive(const void *a, const void *b) 3300 { 3301 int result; 3302 3303 const DiffEntry* entryA = (const DiffEntry*)a; 3304 const DiffEntry* entryB = (const DiffEntry*)b; 3305 3306 if (entryA->differenceInclusive < entryB->differenceInclusive) { 3307 return 1; 3308 } else if (entryA->differenceInclusive > entryB->differenceInclusive) { 3309 return -1; 3310 } 3311 3312 return 0; 3313 } 3314 3315 void printMissingMethod(MethodEntry* method) 3316 { 3317 char classBuf[HTML_BUFSIZE]; 3318 char methodBuf[HTML_BUFSIZE]; 3319 char* className; 3320 char* methodName; 3321 3322 className = htmlEscape(method->className, classBuf, HTML_BUFSIZE); 3323 methodName = htmlEscape(method->methodName, methodBuf, HTML_BUFSIZE); 3324 3325 if (gOptions.outputHtml) printf("<tr><td>\n"); 3326 3327 printf("%s.%s ", className, methodName); 3328 if (gOptions.outputHtml) printf("</td><td>"); 3329 3330 printf("%lld ", method->elapsedExclusive); 3331 if (gOptions.outputHtml) printf("</td><td>"); 3332 3333 printf("%lld ", method->elapsedInclusive); 3334 if (gOptions.outputHtml) printf("</td><td>"); 3335 3336 printf("%d\n", method->numCalls[0]); 3337 if (gOptions.outputHtml) printf("</td><td>\n"); 3338 } 3339 3340 3341 void createDiff(DataKeys* d1, uint64_t sum1, DataKeys* d2, uint64_t sum2) 3342 { 3343 MethodEntry** methods1 = parseMethodEntries(d1); 3344 MethodEntry** methods2 = parseMethodEntries(d2); 3345 3346 // sort and assign the indicies 3347 int i; 3348 qsort(methods1, d1->numMethods, sizeof(MethodEntry*), compareElapsedInclusive); 3349 for (i = 0; i < d1->numMethods; ++i) { 3350 methods1[i]->index = i; 3351 } 3352 3353 qsort(methods2, d2->numMethods, sizeof(MethodEntry*), compareElapsedInclusive); 3354 for (i = 0; i < d2->numMethods; ++i) { 3355 methods2[i]->index = i; 3356 } 3357 3358 int max = (d1->numMethods < d2->numMethods) ? d2->numMethods : d1->numMethods; 3359 max++; 3360 DiffEntry* diffs = (DiffEntry*)malloc(max * sizeof(DiffEntry)); 3361 memset(diffs, 0, max * sizeof(DiffEntry)); 3362 DiffEntry* ptr = diffs; 3363 3364 // printf("<br>d1->numMethods: %d d1->numMethods: %d<br>\n", d1->numMethods, d2->numMethods); 3365 3366 int matches = 0; 3367 3368 for (i = 0 ; i < d1->numMethods ; i++) { 3369 int match = findMatch(methods2, d2->numMethods, methods1[i]); 3370 if (match >= 0) { 3371 ptr->method1 = methods1[i]; 3372 ptr->method2 = methods2[match]; 3373 3374 uint64_t e1 = ptr->method1->elapsedExclusive; 3375 uint64_t e2 = ptr->method2->elapsedExclusive; 3376 if (e1 > 0) { 3377 ptr->differenceExclusive = e2 - e1; 3378 ptr->differenceExclusivePercentage = ((double)e2 / (double)e1) * 100.0; 3379 } 3380 3381 uint64_t i1 = ptr->method1->elapsedInclusive; 3382 uint64_t i2 = ptr->method2->elapsedInclusive; 3383 if (i1 > 0) { 3384 ptr->differenceInclusive = i2 - i1; 3385 ptr->differenceInclusivePercentage = ((double)i2 / (double)i1) * 100.0; 3386 } 3387 3388 // clear these out so we don't find them again and we know which ones 3389 // we have left over 3390 methods1[i] = NULL; 3391 methods2[match] = NULL; 3392 ptr++; 3393 3394 matches++; 3395 } 3396 } 3397 ptr->method1 = NULL; 3398 ptr->method2 = NULL; 3399 3400 qsort(diffs, matches, sizeof(DiffEntry), compareDiffEntriesExculsive); 3401 ptr = diffs; 3402 3403 if (gOptions.outputHtml) { 3404 printf(htmlHeader, gOptions.sortableUrl); 3405 printf("<h3>Table of Contents</h3>\n"); 3406 printf("<ul>\n"); 3407 printf("<li><a href='#exclusive'>Exclusive</a>\n"); 3408 printf("<li><a href='#inclusive'>Inclusive</a>\n"); 3409 printf("</ul>\n"); 3410 printf("Run 1: %s<br>\n", gOptions.diffFileName); 3411 printf("Run 2: %s<br>\n", gOptions.traceFileName); 3412 printf("<a name=\"exclusive\"></a><h3 id=\"exclusive\">Exclusive</h3>\n"); 3413 printf(tableHeader, "exclusive_table"); 3414 } 3415 3416 char classBuf[HTML_BUFSIZE]; 3417 char methodBuf[HTML_BUFSIZE]; 3418 char* className; 3419 char* methodName; 3420 3421 while (ptr->method1 != NULL && ptr->method2 != NULL) { 3422 if (gOptions.outputHtml) printf("<tr><td>\n"); 3423 3424 className = htmlEscape(ptr->method1->className, classBuf, HTML_BUFSIZE); 3425 methodName = htmlEscape(ptr->method1->methodName, methodBuf, HTML_BUFSIZE); 3426 3427 printf("%s.%s ", className, methodName); 3428 if (gOptions.outputHtml) printf("</td><td>"); 3429 3430 printf("%lld ", ptr->method1->elapsedExclusive); 3431 if (gOptions.outputHtml) printf("</td><td>"); 3432 3433 printf("%llu ", ptr->method2->elapsedExclusive); 3434 if (gOptions.outputHtml) printf("</td><td>"); 3435 3436 printf("%lld ", ptr->differenceExclusive); 3437 if (gOptions.outputHtml) printf("</td><td>"); 3438 3439 printf("%.2f\n", ptr->differenceExclusivePercentage); 3440 if (gOptions.outputHtml) printf("</td><td>\n"); 3441 3442 printf("%d\n", ptr->method1->numCalls[0]); 3443 if (gOptions.outputHtml) printf("</td><td>\n"); 3444 3445 printf("%d\n", ptr->method2->numCalls[0]); 3446 if (gOptions.outputHtml) printf("</td></tr>\n"); 3447 3448 ptr++; 3449 } 3450 3451 if (gOptions.outputHtml) printf("</table>\n"); 3452 3453 if (gOptions.outputHtml) { 3454 printf(htmlHeader, gOptions.sortableUrl); 3455 printf("Run 1: %s<br>\n", gOptions.diffFileName); 3456 printf("Run 2: %s<br>\n", gOptions.traceFileName); 3457 printf("<a name=\"inclusive\"></a><h3 id=\"inculisve\">Inclusive</h3>\n"); 3458 printf(tableHeader, "inclusive_table"); 3459 } 3460 3461 qsort(diffs, matches, sizeof(DiffEntry), compareDiffEntriesInculsive); 3462 ptr = diffs; 3463 3464 while (ptr->method1 != NULL && ptr->method2 != NULL) { 3465 if (gOptions.outputHtml) printf("<tr><td>\n"); 3466 3467 className = htmlEscape(ptr->method1->className, classBuf, HTML_BUFSIZE); 3468 methodName = htmlEscape(ptr->method1->methodName, methodBuf, HTML_BUFSIZE); 3469 3470 printf("%s.%s ", className, methodName); 3471 if (gOptions.outputHtml) printf("</td><td>"); 3472 3473 printf("%lld ", ptr->method1->elapsedInclusive); 3474 if (gOptions.outputHtml) printf("</td><td>"); 3475 3476 printf("%llu ", ptr->method2->elapsedInclusive); 3477 if (gOptions.outputHtml) printf("</td><td>"); 3478 3479 printf("%lld ", ptr->differenceInclusive); 3480 if (gOptions.outputHtml) printf("</td><td>"); 3481 3482 printf("%.2f\n", ptr->differenceInclusivePercentage); 3483 if (gOptions.outputHtml) printf("</td><td>\n"); 3484 3485 printf("%d\n", ptr->method1->numCalls[0]); 3486 if (gOptions.outputHtml) printf("</td><td>\n"); 3487 3488 printf("%d\n", ptr->method2->numCalls[0]); 3489 if (gOptions.outputHtml) printf("</td></tr>\n"); 3490 3491 ptr++; 3492 } 3493 3494 if (gOptions.outputHtml) { 3495 printf("</table>\n"); 3496 printf("<h3>Run 1 methods not found in Run 2</h3>"); 3497 printf(tableHeaderMissing); 3498 } 3499 3500 for (i = 0; i < d1->numMethods; ++i) { 3501 if (methods1[i] != NULL) { 3502 printMissingMethod(methods1[i]); 3503 } 3504 } 3505 3506 if (gOptions.outputHtml) { 3507 printf("</table>\n"); 3508 printf("<h3>Run 2 methods not found in Run 1</h3>"); 3509 printf(tableHeaderMissing); 3510 } 3511 3512 for (i = 0; i < d2->numMethods; ++i) { 3513 if (methods2[i] != NULL) { 3514 printMissingMethod(methods2[i]); 3515 } 3516 } 3517 3518 if (gOptions.outputHtml) printf("</body></html\n"); 3519 } 3520 3521 int usage(const char *program) 3522 { 3523 fprintf(stderr, "usage: %s [-ho] [-s sortable] [-d trace-file-name] [-g outfile] [-f filter-file] trace-file-name\n", program); 3524 fprintf(stderr, " -d trace-file-name - Diff with this trace\n"); 3525 fprintf(stderr, " -g outfile - Write graph to 'outfile'\n"); 3526 fprintf(stderr, " -f filter-file - Filter functions as specified in file\n"); 3527 fprintf(stderr, " -k - When writing a graph, keep the intermediate DOT file\n"); 3528 fprintf(stderr, " -h - Turn on HTML output\n"); 3529 fprintf(stderr, " -o - Dump the dmtrace file instead of profiling\n"); 3530 fprintf(stderr, " -s - URL base to where the sortable javascript file\n"); 3531 fprintf(stderr, " -t threshold - Threshold percentage for including nodes in the graph\n"); 3532 return 2; 3533 } 3534 3535 // Returns true if there was an error 3536 int parseOptions(int argc, char **argv) 3537 { 3538 while (1) { 3539 int opt = getopt(argc, argv, "d:hg:kos:t:f:"); 3540 if (opt == -1) 3541 break; 3542 switch (opt) { 3543 case 'd': 3544 gOptions.diffFileName = optarg; 3545 break; 3546 case 'g': 3547 gOptions.graphFileName = optarg; 3548 break; 3549 case 'f': 3550 gOptions.filterFileName = optarg; 3551 break; 3552 case 'k': 3553 gOptions.keepDotFile = 1; 3554 break; 3555 case 'h': 3556 gOptions.outputHtml = 1; 3557 break; 3558 case 'o': 3559 gOptions.dump = 1; 3560 break; 3561 case 's': 3562 gOptions.sortableUrl = optarg; 3563 break; 3564 case 't': 3565 gOptions.threshold = atoi(optarg); 3566 break; 3567 default: 3568 return 1; 3569 } 3570 } 3571 return 0; 3572 } 3573 3574 /* 3575 * Parse args. 3576 */ 3577 int main(int argc, char** argv) 3578 { 3579 3580 gOptions.threshold = -1; 3581 3582 // Parse the options 3583 if (parseOptions(argc, argv) || argc - optind != 1) 3584 return usage(argv[0]); 3585 3586 gOptions.traceFileName = argv[optind]; 3587 3588 if (gOptions.threshold < 0 || 100 <= gOptions.threshold) { 3589 gOptions.threshold = 20; 3590 } 3591 3592 if (gOptions.dump) { 3593 dumpTrace(); 3594 return 0; 3595 } 3596 3597 uint64_t sumThreadTime = 0; 3598 3599 Filter** filters = NULL; 3600 if (gOptions.filterFileName != NULL) { 3601 filters = parseFilters(gOptions.filterFileName); 3602 } 3603 3604 TraceData data1; 3605 DataKeys* dataKeys = parseDataKeys(&data1, gOptions.traceFileName, 3606 &sumThreadTime, filters); 3607 if (dataKeys == NULL) { 3608 fprintf(stderr, "Cannot read trace.\n"); 3609 exit(1); 3610 } 3611 3612 if (gOptions.diffFileName != NULL) { 3613 uint64_t sum2; 3614 TraceData data2; 3615 DataKeys* d2 = parseDataKeys(&data2, gOptions.diffFileName, &sum2, filters); 3616 3617 createDiff(d2, sum2, dataKeys, sumThreadTime); 3618 3619 freeDataKeys(d2); 3620 } else { 3621 MethodEntry** methods = parseMethodEntries(dataKeys); 3622 profileTrace(&data1, methods, dataKeys->numMethods, sumThreadTime, 3623 dataKeys->threads, dataKeys->numThreads, filters); 3624 if (gOptions.graphFileName != NULL) { 3625 createInclusiveProfileGraphNew(dataKeys); 3626 } 3627 free(methods); 3628 } 3629 3630 freeDataKeys(dataKeys); 3631 3632 return 0; 3633 } 3634