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