mono/profiler/decode.c

   1 /*
   2  * decode.c: mprof-report program source: decode and analyze the log profiler data
   3  *
   4  * Author:
   5  *   Paolo Molaro (lupus@ximian.com)
   6  *
   7  * Copyright 2010 Novell, Inc (http://www.novell.com)
   8  */
   9 #include <config.h>
  10 #include "utils.c"
  11 #include "proflog.h"
  12 #include <string.h>
  13 #include <stdio.h>
  14 #if !defined(__APPLE__)
  15 #include <malloc.h>
  16 #endif
  17 #include <unistd.h>
  18 #include <stdlib.h>
  19 #if defined (HAVE_ZLIB)
  20 #include <zlib.h>
  21 #endif
  22 #include <mono/metadata/profiler.h>
  23 #include <mono/metadata/object.h>
  24 #include <mono/metadata/debug-helpers.h>
  25
  26 #define HASH_SIZE 9371
  27 #define SMALL_HASH_SIZE 31
  28
  29 static int debug = 0;
  30 static int collect_traces = 0;
  31 static int show_traces = 0;
  32 static int trace_max = 6;
  33 static int verbose = 0;
  34 static uintptr_t *tracked_objects = 0;
  35 static int num_tracked_objects = 0;
  36 static uintptr_t thread_filter = 0;
  37 static uint64_t find_size = 0;
  38 static const char* find_name = NULL;
  39 static uint64_t time_from = 0;
  40 static uint64_t time_to = 0xffffffffffffffffULL;
  41 static uint64_t startup_time = 0;
  42 static FILE* outfile = NULL;
  43
  44 static int32_t
  45 read_int32 (unsigned char *p)
  46 {
  47         int32_t value = *p++;
  48         value |= (*p++) << 8;
  49         value |= (*p++) << 16;
  50         value |= (uint32_t)(*p++) << 24;
  51         return value;
  52 }
  53
  54 static int64_t
  55 read_int64 (unsigned char *p)
  56 {
  57         uint64_t value = *p++;
  58         value |= (*p++) << 8;
  59         value |= (*p++) << 16;
  60         value |= (uint64_t)(*p++) << 24;
  61         value |= (uint64_t)(*p++) << 32;
  62         value |= (uint64_t)(*p++) << 40;
  63         value |= (uint64_t)(*p++) << 48;
  64         value |= (uint64_t)(*p++) << 54;
  65         return value;
  66 }
  67
  68 static char*
  69 pstrdup (const char *s)
  70 {
  71         int len = strlen (s) + 1;
  72         char *p = malloc (len);
  73         memcpy (p, s, len);
  74         return p;
  75 }
  76
  77 static int num_images;
  78 typedef struct _ImageDesc ImageDesc;
  79 struct _ImageDesc {
  80         ImageDesc *next;
  81         intptr_t image;
  82         char *filename;
  83 };
  84
  85 static ImageDesc* image_hash [SMALL_HASH_SIZE] = {0};
  86
  87 static void
  88 add_image (intptr_t image, char *name)
  89 {
  90         int slot = ((image >> 2) & 0xffff) % SMALL_HASH_SIZE;
  91         ImageDesc *cd = malloc (sizeof (ImageDesc));
  92         cd->image = image;
  93         cd->filename = pstrdup (name);
  94         cd->next = image_hash [slot];
  95         image_hash [slot] = cd;
  96         num_images++;
  97 }
  98
  99 typedef struct _BackTrace BackTrace;
 100 typedef struct {
 101         uint64_t count;
 102         BackTrace *bt;
 103 } CallContext;
 104
 105 typedef struct {
 106         int count;
 107         int size;
 108         CallContext *traces;
 109 } TraceDesc;
 110
 111 typedef struct _ClassDesc ClassDesc;
 112 struct _ClassDesc {
 113         ClassDesc *next;
 114         intptr_t klass;
 115         char *name;
 116         intptr_t allocs;
 117         uint64_t alloc_size;
 118         TraceDesc traces;
 119 };
 120
 121 static ClassDesc* class_hash [HASH_SIZE] = {0};
 122 static int num_classes = 0;
 123
 124 static ClassDesc*
 125 add_class (intptr_t klass, const char *name)
 126 {
 127         int slot = ((klass >> 2) & 0xffff) % HASH_SIZE;
 128         ClassDesc *cd;
 129         cd = class_hash [slot];
 130         while (cd && cd->klass != klass)
 131                 cd = cd->next;
 132         /* we resolved an unknown class (unless we had the code unloaded) */
 133         if (cd) {
 134                 /*printf ("resolved unknown: %s\n", name);*/
 135                 free (cd->name);
 136                 cd->name = pstrdup (name);
 137                 return cd;
 138         }
 139         cd = calloc (sizeof (ClassDesc), 1);
 140         cd->klass = klass;
 141         cd->name = pstrdup (name);
 142         cd->next = class_hash [slot];
 143         cd->allocs = 0;
 144         cd->alloc_size = 0;
 145         cd->traces.count = 0;
 146         cd->traces.size = 0;
 147         cd->traces.traces = NULL;
 148         class_hash [slot] = cd;
 149         num_classes++;
 150         return cd;
 151 }
 152
 153 static ClassDesc *
 154 lookup_class (intptr_t klass)
 155 {
 156         int slot = ((klass >> 2) & 0xffff) % HASH_SIZE;
 157         ClassDesc *cd = class_hash [slot];
 158         while (cd && cd->klass != klass)
 159                 cd = cd->next;
 160         if (!cd)
 161                 return add_class (klass, "unresolved class");
 162         return cd;
 163 }
 164
 165 typedef struct _MethodDesc MethodDesc;
 166 struct _MethodDesc {
 167         MethodDesc *next;
 168         intptr_t method;
 169         char *name;
 170         intptr_t code;
 171         int len;
 172         int recurse_count;
 173         uint64_t calls;
 174         uint64_t total_time;
 175         uint64_t callee_time;
 176         uint64_t self_time;
 177         TraceDesc traces;
 178 };
 179
 180 static MethodDesc* method_hash [HASH_SIZE] = {0};
 181 static int num_methods = 0;
 182
 183 static MethodDesc*
 184 add_method (intptr_t method, const char *name, intptr_t code, int len)
 185 {
 186         int slot = ((method >> 2) & 0xffff) % HASH_SIZE;
 187         MethodDesc *cd;
 188         cd = method_hash [slot];
 189         while (cd && cd->method != method)
 190                 cd = cd->next;
 191         /* we resolved an unknown method (unless we had the code unloaded) */
 192         if (cd) {
 193                 cd->code = code;
 194                 cd->len = len;
 195                 /*printf ("resolved unknown: %s\n", name);*/
 196                 free (cd->name);
 197                 cd->name = pstrdup (name);
 198                 return cd;
 199         }
 200         cd = calloc (sizeof (MethodDesc), 1);
 201         cd->method = method;
 202         cd->name = pstrdup (name);
 203         cd->code = code;
 204         cd->len = len;
 205         cd->calls = 0;
 206         cd->total_time = 0;
 207         cd->traces.count = 0;
 208         cd->traces.size = 0;
 209         cd->traces.traces = NULL;
 210         cd->next = method_hash [slot];
 211         method_hash [slot] = cd;
 212         num_methods++;
 213         return cd;
 214 }
 215
 216 static MethodDesc *
 217 lookup_method (intptr_t method)
 218 {
 219         int slot = ((method >> 2) & 0xffff) % HASH_SIZE;
 220         MethodDesc *cd = method_hash [slot];
 221         while (cd && cd->method != method)
 222                 cd = cd->next;
 223         if (!cd)
 224                 return add_method (method, "unknown method", 0, 0);
 225         return cd;
 226 }
 227
 228 typedef struct {
 229         ClassDesc *klass;
 230         int64_t count;
 231         int64_t total_size;
 232 } HeapClassDesc;
 233
 234 typedef struct _HeapShot HeapShot;
 235 struct _HeapShot {
 236         HeapShot *next;
 237         uint64_t timestamp;
 238         int class_count;
 239         int hash_size;
 240         HeapClassDesc **class_hash;
 241         HeapClassDesc **sorted;
 242 };
 243
 244 static HeapShot *heap_shots = NULL;
 245 static HeapShot *current_heap_shot = NULL;
 246
 247 static HeapShot*
 248 new_heap_shot (uint64_t timestamp)
 249 {
 250         HeapShot *p;
 251         HeapShot *hs = calloc (sizeof (HeapShot), 1);
 252         hs->hash_size = 4;
 253         hs->class_hash = calloc (sizeof (void*), hs->hash_size);
 254         hs->timestamp = timestamp;
 255         /* append it to the list */
 256         p = heap_shots;
 257         while (p && p->next)
 258                 p = p->next;
 259         if (p)
 260                 p->next = hs;
 261         else
 262                 heap_shots = hs;
 263         return hs;
 264 }
 265
 266 static HeapClassDesc*
 267 heap_class_lookup (HeapShot *hs, ClassDesc *klass)
 268 {
 269         int i;
 270         unsigned int start_pos;
 271         start_pos = ((uintptr_t)klass->klass >> 2) % hs->hash_size;
 272         i = start_pos;
 273         do {
 274                 HeapClassDesc* cd = hs->class_hash [i];
 275                 if (!cd)
 276                         return NULL;
 277                 if (cd->klass == klass)
 278                         return cd;
 279                 /* wrap around */
 280                 if (++i == hs->hash_size)
 281                         i = 0;
 282         } while (i != start_pos);
 283         return NULL;
 284 }
 285
 286 static int
 287 add_heap_hashed (HeapClassDesc **hash, int hsize, ClassDesc *klass, uint64_t size, uint64_t count)
 288 {
 289         int i;
 290         unsigned int start_pos;
 291         start_pos = ((uintptr_t)klass->klass >> 2) % hsize;
 292         i = start_pos;
 293         do {
 294                 if (hash [i] && hash [i]->klass == klass) {
 295                         hash [i]->total_size += size;
 296                         hash [i]->count += count;
 297                         return 0;
 298                 } else if (!hash [i]) {
 299                         hash [i] = calloc (sizeof (HeapClassDesc), 1);
 300                         hash [i]->klass = klass;
 301                         hash [i]->total_size += size;
 302                         hash [i]->count += count;
 303                         return 1;
 304                 }
 305                 /* wrap around */
 306                 if (++i == hsize)
 307                         i = 0;
 308         } while (i != start_pos);
 309         /* should not happen */
 310         printf ("failed heap class store\n");
 311         return 0;
 312 }
 313
 314 static void
 315 add_heap_shot_obj (HeapShot *hs, ClassDesc *klass, uint64_t size)
 316 {
 317         int i;
 318         if (hs->class_count * 2 >= hs->hash_size) {
 319                 HeapClassDesc **n;
 320                 int old_size = hs->hash_size;
 321                 hs->hash_size *= 2;
 322                 if (hs->hash_size == 0)
 323                         hs->hash_size = 4;
 324                 n = calloc (sizeof (void*) * hs->hash_size, 1);
 325                 for (i = 0; i < old_size; ++i) {
 326                         if (hs->class_hash [i])
 327                                 add_heap_hashed (n, hs->hash_size, hs->class_hash [i]->klass, hs->class_hash [i]->total_size, hs->class_hash [i]->count);
 328                 }
 329                 if (hs->class_hash)
 330                         free (hs->class_hash);
 331                 hs->class_hash = n;
 332         }
 333         hs->class_count += add_heap_hashed (hs->class_hash, hs->hash_size, klass, size, 1);
 334 }
 335
 336 struct _BackTrace {
 337         BackTrace *next;
 338         unsigned int hash;
 339         int count;
 340         int id;
 341         MethodDesc *methods [1];
 342 };
 343
 344 static BackTrace *backtrace_hash [HASH_SIZE];
 345 static BackTrace **backtraces = NULL;
 346 static int num_backtraces = 0;
 347 static int next_backtrace = 0;
 348
 349 static int
 350 hash_backtrace (int count, MethodDesc **methods)
 351 {
 352         int hash = count;
 353         int i;
 354         for (i = 0; i < count; ++i) {
 355                 hash = (hash << 5) - hash + methods [i]->method;
 356         }
 357         return hash;
 358 }
 359
 360 static int
 361 compare_backtrace (BackTrace *bt, int count, MethodDesc **methods)
 362 {
 363         int i;
 364         if (bt->count != count)
 365                 return 0;
 366         for (i = 0; i < count; ++i)
 367                 if (methods [i] != bt->methods [i])
 368                         return 0;
 369         return 1;
 370 }
 371
 372 static BackTrace*
 373 add_backtrace (int count, MethodDesc **methods)
 374 {
 375         int hash = hash_backtrace (count, methods);
 376         int slot = (hash & 0xffff) % HASH_SIZE;
 377         BackTrace *bt = backtrace_hash [slot];
 378         while (bt) {
 379                 if (bt->hash == hash && compare_backtrace (bt, count, methods))
 380                         return bt;
 381                 bt = bt->next;
 382         }
 383         bt = malloc (sizeof (BackTrace) + ((count - 1) * sizeof (void*)));
 384         bt->next = backtrace_hash [slot];
 385         backtrace_hash [slot] = bt;
 386         if (next_backtrace == num_backtraces) {
 387                 num_backtraces *= 2;
 388                 if (!num_backtraces)
 389                         num_backtraces = 16;
 390                 backtraces = realloc (backtraces, sizeof (void*) * num_backtraces);
 391         }
 392         bt->id = next_backtrace++;
 393         backtraces [bt->id] = bt;
 394         bt->count = count;
 395         bt->hash = hash;
 396         for (slot = 0; slot < count; ++slot)
 397                 bt->methods [slot] = methods [slot];
 398
 399         return bt;
 400 }
 401
 402 typedef struct _MonitorDesc MonitorDesc;
 403 typedef struct _ThreadContext ThreadContext;
 404
 405 typedef struct {
 406         FILE *file;
 407 #if defined (HAVE_ZLIB)
 408         gzFile *gzfile;
 409 #endif
 410         unsigned char *buf;
 411         int size;
 412         int data_version;
 413         int version_major;
 414         int version_minor;
 415         int timer_overhead;
 416         uint64_t startup_time;
 417         ThreadContext *threads;
 418         ThreadContext *current;
 419 } ProfContext;
 420
 421 struct _ThreadContext {
 422         ThreadContext *next;
 423         intptr_t thread_id;
 424         /* emulated stack */
 425         MethodDesc **stack;
 426         uint64_t *time_stack;
 427         uint64_t *callee_time_stack;
 428         uint64_t last_time;
 429         uint64_t contention_start;
 430         MonitorDesc *monitor;
 431         int stack_size;
 432         int stack_id;
 433 };
 434
 435 static void
 436 ensure_buffer (ProfContext *ctx, int size)
 437 {
 438         if (ctx->size < size) {
 439                 ctx->buf = realloc (ctx->buf, size);
 440                 ctx->size = size;
 441         }
 442 }
 443
 444 static int
 445 load_data (ProfContext *ctx, int size)
 446 {
 447         ensure_buffer (ctx, size);
 448 #if defined (HAVE_ZLIB)
 449         if (ctx->gzfile)
 450                 return gzread (ctx->gzfile, ctx->buf, size) == size;
 451         else
 452 #endif
 453                 return fread (ctx->buf, size, 1, ctx->file);
 454 }
 455
 456 static ThreadContext*
 457 load_thread (ProfContext *ctx, intptr_t thread_id)
 458 {
 459         ThreadContext *thread;
 460         if (ctx->current && ctx->current->thread_id == thread_id)
 461                 return ctx->current;
 462         thread = ctx->threads;
 463         while (thread) {
 464                 if (thread->thread_id == thread_id) {
 465                         ctx->current = thread;
 466                         return thread;
 467                 }
 468                 thread = thread->next;
 469         }
 470         thread = calloc (sizeof (ThreadContext), 1);
 471         thread->next = ctx->threads;
 472         ctx->threads = thread;
 473         ctx->current = thread;
 474         thread->thread_id = thread_id;
 475         thread->last_time = 0;
 476         thread->stack_id = 0;
 477         thread->stack_size = 32;
 478         thread->stack = malloc (thread->stack_size * sizeof (void*));
 479         thread->time_stack = malloc (thread->stack_size * sizeof (uint64_t));
 480         thread->callee_time_stack = malloc (thread->stack_size * sizeof (uint64_t));
 481         return thread;
 482 }
 483
 484 static void
 485 ensure_thread_stack (ThreadContext *thread)
 486 {
 487         if (thread->stack_id == thread->stack_size) {
 488                 thread->stack_size *= 2;
 489                 thread->stack = realloc (thread->stack, thread->stack_size * sizeof (void*));
 490                 thread->time_stack = realloc (thread->time_stack, thread->stack_size * sizeof (uint64_t));
 491                 thread->callee_time_stack = realloc (thread->callee_time_stack, thread->stack_size * sizeof (uint64_t));
 492         }
 493 }
 494
 495 static int
 496 add_trace_hashed (CallContext *traces, int size, BackTrace *bt, uint64_t value)
 497 {
 498         int i;
 499         unsigned int start_pos;
 500         start_pos = bt->hash % size;
 501         i = start_pos;
 502         do {
 503                 if (traces [i].bt == bt) {
 504                         traces [i].count += value;
 505                         return 0;
 506                 } else if (!traces [i].bt) {
 507                         traces [i].bt = bt;
 508                         traces [i].count += value;
 509                         return 1;
 510                 }
 511                 /* wrap around */
 512                 if (++i == size)
 513                         i = 0;
 514         } while (i != start_pos);
 515         /* should not happen */
 516         printf ("failed trace store\n");
 517         return 0;
 518 }
 519
 520 static void
 521 add_trace_bt (BackTrace *bt, TraceDesc *trace, uint64_t value)
 522 {
 523         int i;
 524         if (!collect_traces)
 525                 return;
 526         if (trace->count * 2 >= trace->size) {
 527                 CallContext *n;
 528                 int old_size = trace->size;
 529                 trace->size *= 2;
 530                 if (trace->size == 0)
 531                         trace->size = 4;
 532                 n = calloc (sizeof (CallContext) * trace->size, 1);
 533                 for (i = 0; i < old_size; ++i) {
 534                         if (trace->traces [i].bt)
 535                                 add_trace_hashed (n, trace->size, trace->traces [i].bt, trace->traces [i].count);
 536                 }
 537                 if (trace->traces)
 538                         free (trace->traces);
 539                 trace->traces = n;
 540         }
 541         trace->count += add_trace_hashed (trace->traces, trace->size, bt, value);
 542 }
 543
 544 static BackTrace*
 545 add_trace_thread (ThreadContext *thread, TraceDesc *trace, uint64_t value)
 546 {
 547         BackTrace *bt;
 548         int count = thread->stack_id;
 549         if (!collect_traces)
 550                 return NULL;
 551         if (count > trace_max)
 552                 count = trace_max;
 553         bt = add_backtrace (count, thread->stack + thread->stack_id - count);
 554         add_trace_bt (bt, trace, value);
 555         return bt;
 556 }
 557
 558 static BackTrace*
 559 add_trace_methods (MethodDesc **methods, int count, TraceDesc *trace, uint64_t value)
 560 {
 561         BackTrace *bt;
 562         if (!collect_traces)
 563                 return NULL;
 564         if (count > trace_max)
 565                 count = trace_max;
 566         bt = add_backtrace (count, methods);
 567         add_trace_bt (bt, trace, value);
 568         return bt;
 569 }
 570
 571 static int
 572 compare_callc (const void *a, const void *b)
 573 {
 574         const CallContext *A = a;
 575         const CallContext *B = b;
 576         if (B->count == A->count)
 577                 return 0;
 578         if (B->count < A->count)
 579                 return -1;
 580         return 1;
 581 }
 582
 583 static void
 584 sort_context_array (TraceDesc* traces)
 585 {
 586         int i, j;
 587         for (i = 0, j = 0; i < traces->size; ++i) {
 588                 if (traces->traces [i].bt) {
 589                         traces->traces [j].bt = traces->traces [i].bt;
 590                         traces->traces [j].count = traces->traces [i].count;
 591                         j++;
 592                 }
 593         }
 594         qsort (traces->traces, traces->count, sizeof (CallContext), compare_callc);
 595 }
 596
 597 static void
 598 push_method (ThreadContext *thread, MethodDesc *method, uint64_t timestamp)
 599 {
 600         ensure_thread_stack (thread);
 601         thread->time_stack [thread->stack_id] = timestamp;
 602         thread->callee_time_stack [thread->stack_id] = 0;
 603         thread->stack [thread->stack_id++] = method;
 604         method->recurse_count++;
 605 }
 606
 607 static void
 608 pop_method (ThreadContext *thread, MethodDesc *method, uint64_t timestamp)
 609 {
 610         method->recurse_count--;
 611         if (thread->stack_id > 0 && thread->stack [thread->stack_id - 1] == method) {
 612                 uint64_t tdiff;
 613                 thread->stack_id--;
 614                 method->calls++;
 615                 if (timestamp < thread->time_stack [thread->stack_id])
 616                         fprintf (outfile, "time went backwards for %s\n", method->name);
 617                 tdiff = timestamp - thread->time_stack [thread->stack_id];
 618                 if (thread->callee_time_stack [thread->stack_id] > tdiff)
 619                         fprintf (outfile, "callee time bigger for %s\n", method->name);
 620                 method->self_time += tdiff - thread->callee_time_stack [thread->stack_id];
 621                 method->callee_time += thread->callee_time_stack [thread->stack_id];
 622                 if (thread->stack_id)
 623                         thread->callee_time_stack [thread->stack_id - 1] += tdiff;
 624                 //fprintf (outfile, "method %s took %d\n", method->name, (int)(tdiff/1000));
 625         } else {
 626                 fprintf (outfile, "unmatched leave at stack pos: %d for method %s\n", thread->stack_id, method->name);
 627         }
 628 }
 629
 630 typedef struct {
 631         uint64_t start_time; /* move this per-thread? */
 632         uint64_t total_time;
 633         uint64_t max_time;
 634         int count;
 635 } GCDesc;
 636 static GCDesc gc_info [3];
 637 static uint64_t max_heap_size;
 638 static uint64_t gc_object_moves;
 639 static int gc_resizes;
 640
 641 static const char*
 642 gc_event_name (int ev)
 643 {
 644         switch (ev) {
 645         case MONO_GC_EVENT_START: return "start";
 646         case MONO_GC_EVENT_MARK_START: return "mark start";
 647         case MONO_GC_EVENT_MARK_END: return "mark end";
 648         case MONO_GC_EVENT_RECLAIM_START: return "reclaim start";
 649         case MONO_GC_EVENT_RECLAIM_END: return "reclaim end";
 650         case MONO_GC_EVENT_END: return "end";
 651         case MONO_GC_EVENT_PRE_STOP_WORLD: return "pre stop";
 652         case MONO_GC_EVENT_POST_STOP_WORLD: return "post stop";
 653         case MONO_GC_EVENT_PRE_START_WORLD: return "pre start";
 654         case MONO_GC_EVENT_POST_START_WORLD: return "post start";
 655         default:
 656                 return "unknown";
 657         }
 658 }
 659
 660 static uint64_t clause_summary [MONO_EXCEPTION_CLAUSE_FAULT + 1];
 661 static uint64_t throw_count = 0;
 662 static TraceDesc exc_traces;
 663
 664 static const char*
 665 clause_name (int type)
 666 {
 667         switch (type) {
 668         case MONO_EXCEPTION_CLAUSE_NONE: return "catch";
 669         case MONO_EXCEPTION_CLAUSE_FILTER: return "filter";
 670         case MONO_EXCEPTION_CLAUSE_FINALLY: return "finally";
 671         case MONO_EXCEPTION_CLAUSE_FAULT: return "fault";
 672         default: return "invalid";
 673         }
 674 }
 675
 676 static uint64_t monitor_contention;
 677 static uint64_t monitor_failed;
 678 static uint64_t monitor_acquired;
 679
 680 struct _MonitorDesc {
 681         MonitorDesc *next;
 682         uintptr_t objid;
 683         uintptr_t contentions;
 684         uint64_t wait_time;
 685         uint64_t max_wait_time;
 686         TraceDesc traces;
 687 };
 688
 689 static MonitorDesc* monitor_hash [SMALL_HASH_SIZE] = {0};
 690 static int num_monitors = 0;
 691
 692 static MonitorDesc*
 693 lookup_monitor (uintptr_t objid)
 694 {
 695         int slot = ((objid >> 3) & 0xffff) % SMALL_HASH_SIZE;
 696         MonitorDesc *cd = monitor_hash [slot];
 697         while (cd && cd->objid != objid)
 698                 cd = cd->next;
 699         if (!cd) {
 700                 cd = calloc (sizeof (MonitorDesc), 1);
 701                 cd->objid = objid;
 702                 cd->next = monitor_hash [slot];
 703                 monitor_hash [slot] = cd;
 704                 num_monitors++;
 705         }
 706         return cd;
 707 }
 708
 709 static const char*
 710 monitor_ev_name (int ev)
 711 {
 712         switch (ev) {
 713         case MONO_PROFILER_MONITOR_CONTENTION: return "contended";
 714         case MONO_PROFILER_MONITOR_DONE: return "acquired";
 715         case MONO_PROFILER_MONITOR_FAIL: return "not taken";
 716         default: return "invalid";
 717         }
 718 }
 719
 720 static MethodDesc**
 721 decode_bt (MethodDesc** sframes, int *size, unsigned char *p, unsigned char **endp, intptr_t ptr_base)
 722 {
 723         MethodDesc **frames;
 724         int i;
 725         int flags = decode_uleb128 (p, &p);
 726         int count = decode_uleb128 (p, &p);
 727         if (flags != 0)
 728                 return NULL;
 729         if (count > *size)
 730                 frames = malloc (count * sizeof (void*));
 731         else
 732                 frames = sframes;
 733         for (i = 0; i < count; ++i) {
 734                 intptr_t ptrdiff = decode_sleb128 (p, &p);
 735                 frames [i] = lookup_method (ptr_base + ptrdiff);
 736         }
 737         *size = count;
 738         *endp = p;
 739         return frames;
 740 }
 741
 742 static void
 743 tracked_creation (uintptr_t obj, ClassDesc *cd, uint64_t size, BackTrace *bt, uint64_t timestamp)
 744 {
 745         int i;
 746         for (i = 0; i < num_tracked_objects; ++i) {
 747                 if (tracked_objects [i] != obj)
 748                         continue;
 749                 fprintf (outfile, "Object %p created (%s, %llu bytes) at %.3f secs.\n", (void*)obj, cd->name, size, (timestamp - startup_time)/1000000000.0);
 750                 if (bt && bt->count) {
 751                         int k;
 752                         for (k = 0; k < bt->count; ++k)
 753                                 fprintf (outfile, "\t%s\n", bt->methods [k]->name);
 754                 }
 755         }
 756 }
 757
 758 static void
 759 track_move (uintptr_t src, uintptr_t dst)
 760 {
 761         int i;
 762         for (i = 0; i < num_tracked_objects; ++i) {
 763                 if (tracked_objects [i] == src)
 764                         fprintf (outfile, "Object %p moved to %p\n", (void*)src, (void*)dst);
 765                 else if (tracked_objects [i] == dst)
 766                         fprintf (outfile, "Object %p moved from %p\n", (void*)dst, (void*)src);
 767         }
 768 }
 769
 770 static void
 771 track_obj_reference (uintptr_t obj, uintptr_t parent, ClassDesc *cd)
 772 {
 773         int i;
 774         for (i = 0; i < num_tracked_objects; ++i) {
 775                 if (tracked_objects [i] == obj)
 776                         fprintf (outfile, "Object %p referenced from %p (%s).\n", (void*)obj, (void*)parent, cd->name);
 777         }
 778 }
 779
 780 static void
 781 found_object (uintptr_t obj)
 782 {
 783         num_tracked_objects ++;
 784         tracked_objects = realloc (tracked_objects, num_tracked_objects * sizeof (tracked_objects [0]));
 785         tracked_objects [num_tracked_objects - 1] = obj;
 786 }
 787
 788 #define OBJ_ADDR(diff) ((obj_base + diff) << 3)
 789 #define LOG_TIME(base,diff) /*fprintf("outfile, time %llu + %llu near offset %d\n", base, diff, p - ctx->buf)*/
 790
 791 static int
 792 decode_buffer (ProfContext *ctx)
 793 {
 794         unsigned char *p;
 795         unsigned char *end;
 796         intptr_t thread_id;
 797         intptr_t ptr_base;
 798         intptr_t obj_base;
 799         intptr_t method_base;
 800         uint64_t time_base;
 801         uint64_t file_offset;
 802         int len, i;
 803         ThreadContext *thread;
 804
 805         file_offset = ftell (ctx->file);
 806         if (!load_data (ctx, 48))
 807                 return 0;
 808         p = ctx->buf;
 809         if (read_int32 (p) != BUF_ID)
 810                 return 0;
 811         len = read_int32 (p + 4);
 812         time_base = read_int64 (p + 8);
 813         ptr_base = read_int64 (p + 16);
 814         obj_base = read_int64 (p + 24);
 815         thread_id = read_int64 (p + 32);
 816         method_base = read_int64 (p + 40);
 817         if (debug)
 818                 fprintf (outfile, "buf: thread:%x, len: %d, time: %llu, file offset: %llu\n", thread_id, len, time_base, file_offset);
 819         thread = load_thread (ctx, thread_id);
 820         if (!load_data (ctx, len))
 821                 return 0;
 822         if (!startup_time) {
 823                 startup_time = time_base;
 824                 if (time_from) {
 825                         time_from += startup_time;
 826                         time_to += startup_time;
 827                 }
 828         }
 829         for (i = 0; i < thread->stack_id; ++i)
 830                 thread->stack [i]->recurse_count++;
 831         p = ctx->buf;
 832         end = p + len;
 833         while (p < end) {
 834                 switch (*p & 0xf) {
 835                 case TYPE_GC: {
 836                         int subtype = *p & 0xf0;
 837                         uint64_t tdiff = decode_uleb128 (p + 1, &p);
 838                         LOG_TIME (time_base, tdiff);
 839                         time_base += tdiff;
 840                         if (subtype == TYPE_GC_RESIZE) {
 841                                 uint64_t new_size = decode_uleb128 (p, &p);
 842                                 if (debug)
 843                                         fprintf (outfile, "gc heap resized to %llu\n", new_size);
 844                                 gc_resizes++;
 845                                 if (new_size > max_heap_size)
 846                                         max_heap_size = new_size;
 847                         } else if (subtype == TYPE_GC_EVENT) {
 848                                 uint64_t ev = decode_uleb128 (p, &p);
 849                                 int gen = decode_uleb128 (p, &p);
 850                                 if (debug)
 851                                         fprintf (outfile, "gc event for gen%d: %s at %llu\n", gen - 1, gc_event_name (ev), time_base);
 852                                 if (gen > 2) {
 853                                         fprintf (outfile, "incorrect gc gen: %d\n", gen);
 854                                         break;
 855                                 }
 856                                 if (ev == MONO_GC_EVENT_START) {
 857                                         gc_info [gen].start_time = time_base;
 858                                         gc_info [gen].count++;
 859                                 } else if (ev == MONO_GC_EVENT_END) {
 860                                         tdiff = time_base - gc_info [gen].start_time;
 861                                         gc_info [gen].total_time += tdiff;
 862                                         if (tdiff > gc_info [gen].max_time)
 863                                                 gc_info [gen].max_time = tdiff;
 864                                 }
 865                         } else if (subtype == TYPE_GC_MOVE) {
 866                                 int j, num = decode_uleb128 (p, &p);
 867                                 gc_object_moves += num / 2;
 868                                 for (j = 0; j < num; j += 2) {
 869                                         intptr_t obj1diff = decode_sleb128 (p, &p);
 870                                         intptr_t obj2diff = decode_sleb128 (p, &p);
 871                                         if (num_tracked_objects)
 872                                                 track_move (OBJ_ADDR (obj1diff), OBJ_ADDR (obj2diff));
 873                                         if (debug) {
 874                                                 fprintf (outfile, "moved obj %p to %p\n", (void*)OBJ_ADDR (obj1diff), (void*)OBJ_ADDR (obj2diff));
 875                                         }
 876                                 }
 877                         }
 878                         break;
 879                 }
 880                 case TYPE_METADATA: {
 881                         int error = *p & TYPE_LOAD_ERR;
 882                         uint64_t tdiff = decode_uleb128 (p + 1, &p);
 883                         int mtype = *p++;
 884                         intptr_t ptrdiff = decode_sleb128 (p, &p);
 885                         LOG_TIME (time_base, tdiff);
 886                         time_base += tdiff;
 887                         if (mtype == TYPE_CLASS) {
 888                                 intptr_t imptrdiff = decode_sleb128 (p, &p);
 889                                 uint64_t flags = decode_uleb128 (p, &p);
 890                                 if (flags) {
 891                                         fprintf (outfile, "non-zero flags in class\n");
 892                                         return 0;
 893                                 }
 894                                 if (debug)
 895                                         fprintf (outfile, "loaded class %p (%s in %p) at %llu\n", (void*)(ptr_base + ptrdiff), p, (void*)(ptr_base + imptrdiff), time_base);
 896                                 if (!error)
 897                                         add_class (ptr_base + ptrdiff, (char*)p);
 898                                 while (*p) p++;
 899                                 p++;
 900                         } else if (mtype == TYPE_IMAGE) {
 901                                 uint64_t flags = decode_uleb128 (p, &p);
 902                                 if (flags) {
 903                                         fprintf (outfile, "non-zero flags in image\n");
 904                                         return 0;
 905                                 }
 906                                 if (debug)
 907                                         fprintf (outfile, "loaded image %p (%s) at %llu\n", (void*)(ptr_base + ptrdiff), p, time_base);
 908                                 if (!error)
 909                                         add_image (ptr_base + ptrdiff, (char*)p);
 910                                 while (*p) p++;
 911                                 p++;
 912                         }
 913                         break;
 914                 }
 915                 case TYPE_ALLOC: {
 916                         int has_bt = *p & TYPE_ALLOC_BT;
 917                         uint64_t tdiff = decode_uleb128 (p + 1, &p);
 918                         intptr_t ptrdiff = decode_sleb128 (p, &p);
 919                         intptr_t objdiff = decode_sleb128 (p, &p);
 920                         uint64_t len;
 921                         int num_bt = 0;
 922                         MethodDesc* sframes [8];
 923                         MethodDesc** frames = sframes;
 924                         ClassDesc *cd = lookup_class (ptr_base + ptrdiff);
 925                         len = decode_uleb128 (p, &p);
 926                         LOG_TIME (time_base, tdiff);
 927                         time_base += tdiff;
 928                         if (debug)
 929                                 fprintf (outfile, "alloced object %p, size %llu (%s) at %llu\n", (void*)OBJ_ADDR (objdiff), len, lookup_class (ptr_base + ptrdiff)->name, time_base);
 930                         if (has_bt) {
 931                                 num_bt = 8;
 932                                 frames = decode_bt (sframes, &num_bt, p, &p, ptr_base);
 933                                 if (!frames) {
 934                                         fprintf (outfile, "Cannot load backtrace\n");
 935                                         return 0;
 936                                 }
 937                         }
 938                         if ((thread_filter && thread_filter == thread->thread_id) || (time_base >= time_from && time_base < time_to)) {
 939                                 BackTrace *bt;
 940                                 cd->allocs++;
 941                                 cd->alloc_size += len;
 942                                 if (has_bt)
 943                                         bt = add_trace_methods (frames, num_bt, &cd->traces, len);
 944                                 else
 945                                         bt = add_trace_thread (thread, &cd->traces, len);
 946                                 if (find_size && len >= find_size) {
 947                                         if (!find_name || strstr (cd->name, find_name))
 948                                                 found_object (OBJ_ADDR (objdiff));
 949                                 } else if (!find_size && find_name && strstr (cd->name, find_name)) {
 950                                         found_object (OBJ_ADDR (objdiff));
 951                                 }
 952                                 if (num_tracked_objects)
 953                                         tracked_creation (OBJ_ADDR (objdiff), cd, len, bt, time_base);
 954                         }
 955                         if (frames != sframes)
 956                                 free (frames);
 957                         break;
 958                 }
 959                 case TYPE_METHOD: {
 960                         int subtype = *p & 0xf0;
 961                         uint64_t tdiff = decode_uleb128 (p + 1, &p);
 962                         int64_t ptrdiff = decode_sleb128 (p, &p);
 963                         LOG_TIME (time_base, tdiff);
 964                         time_base += tdiff;
 965                         method_base += ptrdiff;
 966                         if (subtype == TYPE_JIT) {
 967                                 intptr_t codediff = decode_sleb128 (p, &p);
 968                                 int codelen = decode_uleb128 (p, &p);
 969                                 if (debug)
 970                                         fprintf (outfile, "jitted method %p (%s), size: %d\n", (void*)(method_base), p, codelen);
 971                                 add_method (method_base, (char*)p, ptr_base + codediff, codelen);
 972                                 while (*p) p++;
 973                                 p++;
 974                         } else {
 975                                 MethodDesc *method;
 976                                 if ((thread_filter && thread_filter != thread->thread_id))
 977                                         break;
 978                                 method = lookup_method (method_base);
 979                                 if (subtype == TYPE_ENTER) {
 980                                         add_trace_thread (thread, &method->traces, 1);
 981                                         push_method (thread, method, time_base);
 982                                 } else {
 983                                         pop_method (thread, method, time_base);
 984                                 }
 985                                 if (debug)
 986                                         fprintf (outfile, "%s method %s\n", subtype == TYPE_ENTER? "enter": subtype == TYPE_EXC_LEAVE? "exleave": "leave", method->name);
 987                         }
 988                         break;
 989                 }
 990                 case TYPE_HEAP: {
 991                         int subtype = *p & 0xf0;
 992                         if (subtype == TYPE_HEAP_OBJECT) {
 993                                 int i;
 994                                 intptr_t objdiff = decode_sleb128 (p + 1, &p);
 995                                 intptr_t ptrdiff = decode_sleb128 (p, &p);
 996                                 uint64_t size = decode_uleb128 (p, &p);
 997                                 int num = decode_uleb128 (p, &p);
 998                                 ClassDesc *cd = lookup_class (ptr_base + ptrdiff);
 999                                 for (i = 0; i < num; ++i) {
1000                                         /* FIXME: use object distance to measure how good
1001                                          * the GC is at keeping related objects close
1002                                          */
1003                                         intptr_t obj1diff = decode_sleb128 (p, &p);
1004                                         if (num_tracked_objects)
1005                                                 track_obj_reference (OBJ_ADDR (obj1diff), OBJ_ADDR (objdiff), cd);
1006                                 }
1007                                 if (debug && size)
1008                                         fprintf (outfile, "traced object %p, size %llu (%s), refs: %d\n", (void*)OBJ_ADDR (objdiff), size, cd->name, num);
1009                                 if (size)
1010                                         add_heap_shot_obj (current_heap_shot, cd, size);
1011                         } else if (subtype == TYPE_HEAP_END) {
1012                                 uint64_t tdiff = decode_uleb128 (p + 1, &p);
1013                                 LOG_TIME (time_base, tdiff);
1014                                 time_base += tdiff;
1015                                 if (debug)
1016                                         fprintf (outfile, "heap shot end\n");
1017                                 current_heap_shot = NULL;
1018                         } else if (subtype == TYPE_HEAP_START) {
1019                                 uint64_t tdiff = decode_uleb128 (p + 1, &p);
1020                                 LOG_TIME (time_base, tdiff);
1021                                 time_base += tdiff;
1022                                 if (debug)
1023                                         fprintf (outfile, "heap shot start\n");
1024                                 current_heap_shot = new_heap_shot (time_base);
1025                         }
1026                         break;
1027                 }
1028                 case TYPE_MONITOR: {
1029                         int event = (*p >> 4) & 0x3;
1030                         int has_bt = *p & TYPE_MONITOR_BT;
1031                         uint64_t tdiff = decode_uleb128 (p + 1, &p);
1032                         intptr_t objdiff = decode_sleb128 (p, &p);
1033                         MethodDesc* sframes [8];
1034                         MethodDesc** frames = sframes;
1035                         int record;
1036                         int num_bt = 0;
1037                         LOG_TIME (time_base, tdiff);
1038                         time_base += tdiff;
1039                         record = (!thread_filter || thread_filter == thread->thread_id);
1040                         if (event == MONO_PROFILER_MONITOR_CONTENTION) {
1041                                 MonitorDesc *mdesc = lookup_monitor (OBJ_ADDR (objdiff));
1042                                 if (record) {
1043                                         monitor_contention++;
1044                                         mdesc->contentions++;
1045                                         thread->monitor = mdesc;
1046                                         thread->contention_start = time_base;
1047                                 }
1048                                 if (has_bt) {
1049                                         num_bt = 8;
1050                                         frames = decode_bt (sframes, &num_bt, p, &p, ptr_base);
1051                                         if (!frames) {
1052                                                 fprintf (outfile, "Cannot load backtrace\n");
1053                                                 return 0;
1054                                         }
1055                                         if (record)
1056                                                 add_trace_methods (frames, num_bt, &mdesc->traces, 1);
1057                                 } else {
1058                                         if (record)
1059                                                 add_trace_thread (thread, &mdesc->traces, 1);
1060                                 }
1061                         } else if (event == MONO_PROFILER_MONITOR_FAIL) {
1062                                 if (record) {
1063                                         monitor_failed++;
1064                                         if (thread->monitor && thread->contention_start) {
1065                                                 uint64_t wait_time = time_base - thread->contention_start;
1066                                                 if (wait_time > thread->monitor->max_wait_time)
1067                                                         thread->monitor->max_wait_time = wait_time;
1068                                                 thread->monitor->wait_time += wait_time;
1069                                                 thread->monitor = NULL;
1070                                                 thread->contention_start = 0;
1071                                         }
1072                                 }
1073                         } else if (event == MONO_PROFILER_MONITOR_DONE) {
1074                                 if (record) {
1075                                         monitor_acquired++;
1076                                         if (thread->monitor && thread->contention_start) {
1077                                                 uint64_t wait_time = time_base - thread->contention_start;
1078                                                 if (wait_time > thread->monitor->max_wait_time)
1079                                                         thread->monitor->max_wait_time = wait_time;
1080                                                 thread->monitor->wait_time += wait_time;
1081                                                 thread->monitor = NULL;
1082                                                 thread->contention_start = 0;
1083                                         }
1084                                 }
1085                         }
1086                         if (debug)
1087                                 fprintf (outfile, "monitor %s for object %p\n", monitor_ev_name (event), (void*)OBJ_ADDR (objdiff));
1088                         if (frames != sframes)
1089                                 free (frames);
1090                         break;
1091                 }
1092                 case TYPE_EXCEPTION: {
1093                         int subtype = *p & 0x70;
1094                         int has_bt = *p & TYPE_EXCEPTION_BT;
1095                         uint64_t tdiff = decode_uleb128 (p + 1, &p);
1096                         MethodDesc* sframes [8];
1097                         MethodDesc** frames = sframes;
1098                         int record;
1099                         LOG_TIME (time_base, tdiff);
1100                         time_base += tdiff;
1101                         record = (!thread_filter || thread_filter == thread->thread_id);
1102                         if (subtype == TYPE_CLAUSE) {
1103                                 int clause_type = decode_uleb128 (p, &p);
1104                                 int clause_num = decode_uleb128 (p, &p);
1105                                 int64_t ptrdiff = decode_sleb128 (p, &p);
1106                                 method_base += ptrdiff;
1107                                 if (record)
1108                                         clause_summary [clause_type]++;
1109                                 if (debug)
1110                                         fprintf (outfile, "clause %s (%d) in method %s\n", clause_name (clause_type), clause_num, lookup_method (method_base)->name);
1111                         } else {
1112                                 intptr_t objdiff = decode_sleb128 (p, &p);
1113                                 if (record)
1114                                         throw_count++;
1115                                 if (has_bt) {
1116                                         has_bt = 8;
1117                                         frames = decode_bt (sframes, &has_bt, p, &p, ptr_base);
1118                                         if (!frames) {
1119                                                 fprintf (outfile, "Cannot load backtrace\n");
1120                                                 return 0;
1121                                         }
1122                                         if (record)
1123                                                 add_trace_methods (frames, has_bt, &exc_traces, 1);
1124                                 } else {
1125                                         if (record)
1126                                                 add_trace_thread (thread, &exc_traces, 1);
1127                                 }
1128                                 if (frames != sframes)
1129                                         free (frames);
1130                                 if (debug)
1131                                         fprintf (outfile, "throw %p\n", (void*)OBJ_ADDR (objdiff));
1132                         }
1133                         break;
1134                 }
1135                 default:
1136                         fprintf (outfile, "unhandled profiler event: 0x%x\n", *p);
1137                         exit (1);
1138                 }
1139         }
1140         thread->last_time = time_base;
1141         for (i = 0; i < thread->stack_id; ++i)
1142                 thread->stack [i]->recurse_count = 0;
1143         return 1;
1144 }
1145
1146 static ProfContext*
1147 load_file (char *name)
1148 {
1149         unsigned char *p;
1150         ProfContext *ctx = calloc (sizeof (ProfContext), 1);
1151         if (strcmp (name, "-") == 0)
1152                 ctx->file = stdin;
1153         else
1154                 ctx->file = fopen (name, "rb");
1155         if (!ctx->file) {
1156                 printf ("Cannot open file: %s\n", name);
1157                 exit (1);
1158         }
1159 #if defined (HAVE_ZLIB)
1160         ctx->gzfile = gzdopen (fileno (ctx->file), "rb");
1161 #endif
1162         if (!load_data (ctx, 32))
1163                 return NULL;
1164         p = ctx->buf;
1165         if (read_int32 (p) != LOG_HEADER_ID || p [6] != LOG_DATA_VERSION)
1166                 return NULL;
1167         ctx->version_major = p [4];
1168         ctx->version_minor = p [5];
1169         ctx->data_version = p [6];
1170         /* reading 64 bit files on 32 bit systems not supported yet */
1171         if (p [7] > sizeof (void*))
1172                 return NULL;
1173         if (read_int32 (p + 20)) /* flags must be 0 */
1174                 return NULL;
1175         ctx->startup_time = read_int64 (p + 8);
1176         ctx->timer_overhead = read_int32 (p + 16);
1177         return ctx;
1178 }
1179
1180 enum {
1181         ALLOC_SORT_BYTES,
1182         ALLOC_SORT_COUNT
1183 };
1184 static int alloc_sort_mode = ALLOC_SORT_BYTES;
1185
1186 static int
1187 compare_class (const void *a, const void *b)
1188 {
1189         ClassDesc *const*A = a;
1190         ClassDesc *const*B = b;
1191         uint64_t vala, valb;
1192         if (alloc_sort_mode == ALLOC_SORT_BYTES) {
1193                 vala = (*A)->alloc_size;
1194                 valb = (*B)->alloc_size;
1195         } else {
1196                 vala = (*A)->allocs;
1197                 valb = (*B)->allocs;
1198         }
1199         if (valb == vala)
1200                 return 0;
1201         if (valb < vala)
1202                 return -1;
1203         return 1;
1204 }
1205
1206 static void
1207 dump_header (ProfContext *ctx)
1208 {
1209         time_t st = ctx->startup_time / 1000;
1210         char *t = ctime (&st);
1211         fprintf (outfile, "\nMono log profiler data\n");
1212         fprintf (outfile, "\tProfiler version: %d.%d\n", ctx->version_major, ctx->version_minor);
1213         fprintf (outfile, "\tData version: %d\n", ctx->data_version);
1214         fprintf (outfile, "\tMean timer overhead: %d nanoseconds\n", ctx->timer_overhead);
1215         fprintf (outfile, "\tProgram startup: %s\n", t);
1216 }
1217
1218 static void
1219 dump_traces (TraceDesc *traces, const char *desc)
1220 {
1221         int j;
1222         if (!show_traces)
1223                 return;
1224         if (!traces->count)
1225                 return;
1226         sort_context_array (traces);
1227         for (j = 0; j < traces->count; ++j) {
1228                 int k;
1229                 BackTrace *bt;
1230                 bt = traces->traces [j].bt;
1231                 if (!bt->count)
1232                         continue;
1233                 fprintf (outfile, "\t%llu %s from:\n", traces->traces [j].count, desc);
1234                 for (k = 0; k < bt->count; ++k)
1235                         fprintf (outfile, "\t\t%s\n", bt->methods [k]->name);
1236         }
1237 }
1238
1239 static void
1240 dump_threads (ProfContext *ctx)
1241 {
1242         ThreadContext *thread;
1243         fprintf (outfile, "\nThread summary\n");
1244         for (thread = ctx->threads; thread; thread = thread->next) {
1245                 fprintf (outfile, "\tThread: %p\n", (void*)thread->thread_id);
1246         }
1247 }
1248
1249 static void
1250 dump_exceptions (void)
1251 {
1252         int i;
1253         fprintf (outfile, "\nException summary\n");
1254         fprintf (outfile, "\tThrows: %llu\n", throw_count);
1255         dump_traces (&exc_traces, "throws");
1256         for (i = 0; i <= MONO_EXCEPTION_CLAUSE_FAULT; ++i) {
1257                 if (!clause_summary [i])
1258                         continue;
1259                 fprintf (outfile, "\tExecuted %s clauses: %llu\n", clause_name (i), clause_summary [i]);
1260         }
1261 }
1262
1263 static int
1264 compare_monitor (const void *a, const void *b)
1265 {
1266         MonitorDesc *const*A = a;
1267         MonitorDesc *const*B = b;
1268         if ((*B)->wait_time == (*A)->wait_time)
1269                 return 0;
1270         if ((*B)->wait_time < (*A)->wait_time)
1271                 return -1;
1272         return 1;
1273 }
1274
1275 static void
1276 dump_monitors (void)
1277 {
1278         MonitorDesc **monitors;
1279         int i, j;
1280         if (!num_monitors)
1281                 return;
1282         monitors = malloc (sizeof (void*) * num_monitors);
1283         for (i = 0, j = 0; i < SMALL_HASH_SIZE; ++i) {
1284                 MonitorDesc *mdesc = monitor_hash [i];
1285                 while (mdesc) {
1286                         monitors [j++] = mdesc;
1287                         mdesc = mdesc->next;
1288                 }
1289         }
1290         qsort (monitors, num_monitors, sizeof (void*), compare_monitor);
1291         fprintf (outfile, "\nMonitor lock summary\n");
1292         for (i = 0; i < num_monitors; ++i) {
1293                 MonitorDesc *mdesc = monitors [i];
1294                 fprintf (outfile, "\tLock object %p: %d contentions\n", (void*)mdesc->objid, (int)mdesc->contentions);
1295                 fprintf (outfile, "\t\t%.6f secs total wait time, %.6f max, %.6f average\n",
1296                         mdesc->wait_time/1000000000.0, mdesc->max_wait_time/1000000000.0, mdesc->wait_time/1000000000.0/mdesc->contentions);
1297                 dump_traces (&mdesc->traces, "contentions");
1298         }
1299         fprintf (outfile, "\tLock contentions: %llu\n", monitor_contention);
1300         fprintf (outfile, "\tLock acquired: %llu\n", monitor_acquired);
1301         fprintf (outfile, "\tLock failures: %llu\n", monitor_failed);
1302 }
1303
1304 static void
1305 dump_gcs (void)
1306 {
1307         int i;
1308         fprintf (outfile, "\nGC summary\n");
1309         fprintf (outfile, "\tGC resizes: %d\n", gc_resizes);
1310         fprintf (outfile, "\tMax heap size: %llu\n", max_heap_size);
1311         fprintf (outfile, "\tObject moves: %llu\n", gc_object_moves);
1312         for (i = 0; i < 3; ++i) {
1313                 if (!gc_info [i].count)
1314                         continue;
1315                 fprintf (outfile, "\tGen%d collections: %d, max time: %lluus, total time: %lluus, average: %lluus\n",
1316                         i, gc_info [i].count, gc_info [i].max_time / 1000, gc_info [i].total_time / 1000,
1317                         gc_info [i].total_time / gc_info [i].count / 1000);
1318         }
1319 }
1320
1321 static void
1322 dump_allocations (void)
1323 {
1324         int i, c;
1325         intptr_t allocs = 0;
1326         uint64_t size = 0;
1327         int header_done = 0;
1328         ClassDesc **classes = malloc (num_classes * sizeof (void*));
1329         ClassDesc *cd;
1330         c = 0;
1331         for (i = 0; i < HASH_SIZE; ++i) {
1332                 cd = class_hash [i];
1333                 while (cd) {
1334                         classes [c++] = cd;
1335                         cd = cd->next;
1336                 }
1337         }
1338         qsort (classes, num_classes, sizeof (void*), compare_class);
1339         for (i = 0; i < num_classes; ++i) {
1340                 cd = classes [i];
1341                 if (!cd->allocs)
1342                         continue;
1343                 allocs += cd->allocs;
1344                 size += cd->alloc_size;
1345                 if (!header_done++) {
1346                         fprintf (outfile, "\nAllocation summary\n");
1347                         fprintf (outfile, "%10s %10s %8s Type name\n", "Bytes", "Count", "Average");
1348                 }
1349                 fprintf (outfile, "%10llu %10d %8llu %s\n", cd->alloc_size, cd->allocs, cd->alloc_size / cd->allocs, cd->name);
1350                 dump_traces (&cd->traces, "bytes");
1351         }
1352         if (allocs)
1353                 fprintf (outfile, "Total memory allocated: %llu bytes in %d objects\n", size, allocs);
1354 }
1355
1356 enum {
1357         METHOD_SORT_TOTAL,
1358         METHOD_SORT_SELF,
1359         METHOD_SORT_CALLS
1360 };
1361
1362 static int method_sort_mode = METHOD_SORT_TOTAL;
1363
1364 static int
1365 compare_method (const void *a, const void *b)
1366 {
1367         MethodDesc *const*A = a;
1368         MethodDesc *const*B = b;
1369         uint64_t vala, valb;
1370         if (method_sort_mode == METHOD_SORT_SELF) {
1371                 vala = (*A)->self_time;
1372                 valb = (*B)->self_time;
1373         } else if (method_sort_mode == METHOD_SORT_CALLS) {
1374                 vala = (*A)->calls;
1375                 valb = (*B)->calls;
1376         } else {
1377                 vala = (*A)->total_time;
1378                 valb = (*B)->total_time;
1379         }
1380         if (vala == valb)
1381                 return 0;
1382         if (valb < vala)
1383                 return -1;
1384         return 1;
1385 }
1386
1387 static void
1388 dump_metadata (void)
1389 {
1390         fprintf (outfile, "\nMetadata summary\n");
1391         fprintf (outfile, "\tLoaded images: %d\n", num_images);
1392         if (verbose) {
1393                 ImageDesc *image;
1394                 int i;
1395                 for (i = 0; i < SMALL_HASH_SIZE; ++i) {
1396                         image = image_hash [i];
1397                         while (image) {
1398                                 fprintf (outfile, "\t\t%s\n", image->filename);
1399                                 image = image->next;
1400                         }
1401                 }
1402         }
1403
1404 }
1405
1406 static void
1407 dump_methods (void)
1408 {
1409         int i, c;
1410         uint64_t calls = 0;
1411         int header_done = 0;
1412         MethodDesc **methods = malloc (num_methods * sizeof (void*));
1413         MethodDesc *cd;
1414         c = 0;
1415         for (i = 0; i < HASH_SIZE; ++i) {
1416                 cd = method_hash [i];
1417                 while (cd) {
1418                         cd->total_time = cd->self_time + cd->callee_time;
1419                         methods [c++] = cd;
1420                         cd = cd->next;
1421                 }
1422         }
1423         qsort (methods, num_methods, sizeof (void*), compare_method);
1424         for (i = 0; i < num_methods; ++i) {
1425                 uint64_t msecs;
1426                 uint64_t smsecs;
1427                 cd = methods [i];
1428                 if (!cd->calls)
1429                         continue;
1430                 calls += cd->calls;
1431                 msecs = cd->total_time / 1000000;
1432                 smsecs = (cd->total_time - cd->callee_time) / 1000000;
1433                 if (!msecs && !verbose)
1434                         continue;
1435                 if (!header_done++) {
1436                         fprintf (outfile, "\nMethod call summary\n");
1437                         fprintf (outfile, "%8s %8s %10s Method name\n", "Total(ms)", "Self(ms)", "Calls");
1438                 }
1439                 fprintf (outfile, "%8llu %8llu %10llu %s\n", msecs, smsecs, cd->calls, cd->name);
1440                 dump_traces (&cd->traces, "calls");
1441         }
1442         if (calls)
1443                 fprintf (outfile, "Total calls: %llu\n", calls);
1444 }
1445
1446 static int
1447 compare_heap_class (const void *a, const void *b)
1448 {
1449         HeapClassDesc *const*A = a;
1450         HeapClassDesc *const*B = b;
1451         uint64_t vala, valb;
1452         if (alloc_sort_mode == ALLOC_SORT_BYTES) {
1453                 vala = (*A)->total_size;
1454                 valb = (*B)->total_size;
1455         } else {
1456                 vala = (*A)->count;
1457                 valb = (*B)->count;
1458         }
1459         if (valb == vala)
1460                 return 0;
1461         if (valb < vala)
1462                 return -1;
1463         return 1;
1464 }
1465
1466 static void
1467 heap_shot_summary (HeapShot *hs, int hs_num, HeapShot *last_hs)
1468 {
1469         uint64_t size = 0;
1470         uint64_t count = 0;
1471         int ccount = 0;
1472         int i;
1473         HeapClassDesc *cd;
1474         HeapClassDesc **sorted;
1475         sorted = malloc (sizeof (void*) * hs->class_count);
1476         for (i = 0; i < hs->hash_size; ++i) {
1477                 cd = hs->class_hash [i];
1478                 if (!cd)
1479                         continue;
1480                 count += cd->count;
1481                 size += cd->total_size;
1482                 sorted [ccount++] = cd;
1483         }
1484         hs->sorted = sorted;
1485         qsort (sorted, ccount, sizeof (void*), compare_heap_class);
1486         fprintf (outfile, "\n\tHeap shot %d at %.3f secs: size: %llu, object count: %llu, class count: %d\n",
1487                 hs_num, (hs->timestamp - startup_time)/1000000000.0, size, count, ccount);
1488         if (!verbose && ccount > 30)
1489                 ccount = 30;
1490         fprintf (outfile, "\t%10s %10s %8s Class name\n", "Bytes", "Count", "Average");
1491         for (i = 0; i < ccount; ++i) {
1492                 HeapClassDesc *ocd = NULL;
1493                 cd = sorted [i];
1494                 if (last_hs)
1495                         ocd = heap_class_lookup (last_hs, cd->klass);
1496                 fprintf (outfile, "\t%10llu %10llu %8llu %s", cd->total_size, cd->count, cd->total_size / cd->count, cd->klass->name);
1497                 if (ocd) {
1498                         int64_t bdiff = cd->total_size - ocd->total_size;
1499                         int64_t cdiff = cd->count - ocd->count;
1500                         fprintf (outfile, " (bytes: %+lld, count: %+lld)\n", bdiff, cdiff);
1501                 } else {
1502                         fprintf (outfile, "\n");
1503                 }
1504         }
1505 }
1506
1507 static void
1508 dump_heap_shots (void)
1509 {
1510         HeapShot *hs;
1511         HeapShot *last_hs = NULL;
1512         int i;
1513         if (!heap_shots)
1514                 return;
1515         fprintf (outfile, "\nHeap shot summary\n");
1516         i = 0;
1517         for (hs = heap_shots; hs; hs = hs->next) {
1518                 heap_shot_summary (hs, i++, last_hs);
1519                 last_hs = hs;
1520         }
1521 }
1522
1523 static void
1524 flush_context (ProfContext *ctx)
1525 {
1526         ThreadContext *thread;
1527         /* FIXME: sometimes there are leftovers: indagate */
1528         for (thread = ctx->threads; thread; thread = thread->next) {
1529                 while (thread->stack_id) {
1530                         if (debug)
1531                                 fprintf (outfile, "thread %p has %d items on stack\n", (void*)thread->thread_id, thread->stack_id);
1532                         pop_method (thread, thread->stack [thread->stack_id - 1], thread->last_time);
1533                 }
1534         }
1535 }
1536
1537 static const char *reports = "header,gc,alloc,call,metadata,exception,monitor,thread,heapshot";
1538
1539 static const char*
1540 match_option (const char *p, const char *opt)
1541 {
1542         int len = strlen (opt);
1543         if (strncmp (p, opt, len) == 0) {
1544                 if (p [len] == ',')
1545                         len++;
1546                 return p + len;
1547         }
1548         return p;
1549 }
1550
1551 static int
1552 print_reports (ProfContext *ctx, const char *reps, int parse_only)
1553 {
1554         const char *opt;
1555         const char *p;
1556         for (p = reps; *p; p = opt) {
1557                 if ((opt = match_option (p, "header")) != p) {
1558                         if (!parse_only)
1559                                 dump_header (ctx);
1560                         continue;
1561                 }
1562                 if ((opt = match_option (p, "thread")) != p) {
1563                         if (!parse_only)
1564                                 dump_threads (ctx);
1565                         continue;
1566                 }
1567                 if ((opt = match_option (p, "gc")) != p) {
1568                         if (!parse_only)
1569                                 dump_gcs ();
1570                         continue;
1571                 }
1572                 if ((opt = match_option (p, "alloc")) != p) {
1573                         if (!parse_only)
1574                                 dump_allocations ();
1575                         continue;
1576                 }
1577                 if ((opt = match_option (p, "call")) != p) {
1578                         if (!parse_only)
1579                                 dump_methods ();
1580                         continue;
1581                 }
1582                 if ((opt = match_option (p, "metadata")) != p) {
1583                         if (!parse_only)
1584                                 dump_metadata ();
1585                         continue;
1586                 }
1587                 if ((opt = match_option (p, "exception")) != p) {
1588                         if (!parse_only)
1589                                 dump_exceptions ();
1590                         continue;
1591                 }
1592                 if ((opt = match_option (p, "monitor")) != p) {
1593                         if (!parse_only)
1594                                 dump_monitors ();
1595                         continue;
1596                 }
1597                 if ((opt = match_option (p, "heapshot")) != p) {
1598                         if (!parse_only)
1599                                 dump_heap_shots ();
1600                         continue;
1601                 }
1602                 return 0;
1603         }
1604         return 1;
1605 }
1606
1607 static int
1608 add_find_spec (const char *p)
1609 {
1610         if (p [0] == 'S' && p [1] == ':') {
1611                 char *vale;
1612                 find_size = strtoul (p + 2, &vale, 10);
1613                 return 1;
1614         } else if (p [0] == 'T' && p [1] == ':') {
1615                 find_name = p + 2;
1616                 return 1;
1617         }
1618         return 0;
1619 }
1620
1621 static void
1622 usage (void)
1623 {
1624         printf ("Mono log profiler report version %d.%d\n", LOG_VERSION_MAJOR, LOG_VERSION_MINOR);
1625         printf ("Usage: mprof-report [OPTIONS] FILENAME\n");
1626         printf ("FILENAME can be '-' to read from standard input.\n");
1627         printf ("Options:\n");
1628         printf ("\t--help               display this help\n");
1629         printf ("\t--out=FILE           write to FILE instead of stdout\n");
1630         printf ("\t--traces             collect and show backtraces\n");
1631         printf ("\t--maxframes=NUM      limit backtraces to NUM entries\n");
1632         printf ("\t--reports=R1[,R2...] print the specified reports. Defaults are:\n");
1633         printf ("\t                     %s\n", reports);
1634         printf ("\t--method-sort=MODE   sort methods according to MODE: total, self, calls\n");
1635         printf ("\t--alloc-sort=MODE    sort allocations according to MODE: bytes, count\n");
1636         printf ("\t--track=OB1[,OB2...] track what happens to objects OBJ1, O2 etc.\n");
1637         printf ("\t--find=FINDSPEC      find and track objects matching FINFSPEC, where FINDSPEC is:\n");
1638         printf ("\t                     S:minimum_size or T:partial_name\n");
1639         printf ("\t--thread=THREADID    consider just the data for thread THREADID\n");
1640         printf ("\t--time=FROM-TO       consider data FROM seconds from startup up to TO seconds\n");
1641         printf ("\t--verbose            increase verbosity level\n");
1642         printf ("\t--debug              display decoding debug info for mprof-report devs\n");
1643 }
1644
1645 int
1646 main (int argc, char *argv[])
1647 {
1648         ProfContext *ctx;
1649         int i;
1650         outfile = stdout;
1651         for (i = 1; i < argc; ++i) {
1652                 if (strcmp ("--debug", argv [i]) == 0) {
1653                         debug++;
1654                 } else if (strcmp ("--help", argv [i]) == 0) {
1655                         usage ();
1656                         return 0;
1657                 } else if (strncmp ("--alloc-sort=", argv [i], 13) == 0) {
1658                         const char *val = argv [i] + 13;
1659                         if (strcmp (val, "bytes") == 0) {
1660                                 alloc_sort_mode = ALLOC_SORT_BYTES;
1661                         } else if (strcmp (val, "count") == 0) {
1662                                 alloc_sort_mode = ALLOC_SORT_COUNT;
1663                         } else {
1664                                 usage ();
1665                                 return 1;
1666                         }
1667                 } else if (strncmp ("--method-sort=", argv [i], 14) == 0) {
1668                         const char *val = argv [i] + 14;
1669                         if (strcmp (val, "total") == 0) {
1670                                 method_sort_mode = METHOD_SORT_TOTAL;
1671                         } else if (strcmp (val, "self") == 0) {
1672                                 method_sort_mode = METHOD_SORT_SELF;
1673                         } else if (strcmp (val, "calls") == 0) {
1674                                 method_sort_mode = METHOD_SORT_CALLS;
1675                         } else {
1676                                 usage ();
1677                                 return 1;
1678                         }
1679                 } else if (strncmp ("--reports=", argv [i], 10) == 0) {
1680                         const char *val = argv [i] + 10;
1681                         if (!print_reports (NULL, val, 1)) {
1682                                 usage ();
1683                                 return 1;
1684                         }
1685                         reports = val;
1686                 } else if (strncmp ("--out=", argv [i], 6) == 0) {
1687                         const char *val = argv [i] + 6;
1688                         outfile = fopen (val, "w");
1689                         if (!outfile) {
1690                                 printf ("Cannot open output file: %s\n", val);
1691                                 return 1;
1692                         }
1693                 } else if (strncmp ("--maxframes=", argv [i], 12) == 0) {
1694                         const char *val = argv [i] + 12;
1695                         char *vale;
1696                         trace_max = strtoul (val, &vale, 10);
1697                 } else if (strncmp ("--find=", argv [i], 7) == 0) {
1698                         const char *val = argv [i] + 7;
1699                         if (!add_find_spec (val)) {
1700                                 usage ();
1701                                 return 1;
1702                         }
1703                 } else if (strncmp ("--track=", argv [i], 8) == 0) {
1704                         const char *val = argv [i] + 8;
1705                         char *vale;
1706                         while (*val) {
1707                                 uintptr_t tracked_obj;
1708                                 if (*val == ',') {
1709                                         val++;
1710                                         continue;
1711                                 }
1712                                 tracked_obj = strtoul (val, &vale, 0);
1713                                 found_object (tracked_obj);
1714                                 val = vale;
1715                         }
1716                 } else if (strncmp ("--thread=", argv [i], 9) == 0) {
1717                         const char *val = argv [i] + 9;
1718                         char *vale;
1719                         thread_filter = strtoul (val, &vale, 0);
1720                 } else if (strncmp ("--time=", argv [i], 7) == 0) {
1721                         char *val = pstrdup (argv [i] + 7);
1722                         double from_secs, to_secs;
1723                         char *top = strchr (val, '-');
1724                         if (!top) {
1725                                 usage ();
1726                                 return 1;
1727                         }
1728                         *top++ = 0;
1729                         from_secs = atof (val);
1730                         to_secs = atof (top);
1731                         free (val);
1732                         if (from_secs > to_secs) {
1733                                 usage ();
1734                                 return 1;
1735                         }
1736                         time_from = from_secs * 1000000000;
1737                         time_to = to_secs * 1000000000;
1738                 } else if (strcmp ("--verbose", argv [i]) == 0) {
1739                         verbose++;
1740                 } else if (strcmp ("--traces", argv [i]) == 0) {
1741                         show_traces = 1;
1742                         collect_traces = 1;
1743                 } else {
1744                         break;
1745                 }
1746         }
1747         if (i >= argc) {
1748                 usage ();
1749                 return 2;
1750         }
1751         ctx = load_file (argv [i]);
1752         if (!ctx) {
1753                 printf ("Not a log profiler data file (or unsupported version).\n");
1754                 return 1;
1755         }
1756         while (decode_buffer (ctx));
1757         flush_context (ctx);
1758         if (num_tracked_objects)
1759                 return 0;
1760         print_reports (ctx, reports, 0);
1761         return 0;
1762 }
1763