mono/metadata/profiler.c

   1
   2 #include "mono/metadata/profiler-private.h"
   3 #include "mono/metadata/debug-helpers.h"
   4 #include "mono/metadata/mono-debug.h"
   5 #include "mono/metadata/class-internals.h"
   6 #include "mono/io-layer/io-layer.h"
   7 #include <string.h>
   8 #include <gmodule.h>
   9
  10 static MonoProfiler * current_profiler = NULL;
  11
  12 static MonoProfileAppDomainFunc   domain_start_load;
  13 static MonoProfileAppDomainResult domain_end_load;
  14 static MonoProfileAppDomainFunc   domain_start_unload;
  15 static MonoProfileAppDomainFunc   domain_end_unload;
  16
  17 static MonoProfileAssemblyFunc   assembly_start_load;
  18 static MonoProfileAssemblyResult assembly_end_load;
  19 static MonoProfileAssemblyFunc   assembly_start_unload;
  20 static MonoProfileAssemblyFunc   assembly_end_unload;
  21
  22 static MonoProfileModuleFunc   module_start_load;
  23 static MonoProfileModuleResult module_end_load;
  24 static MonoProfileModuleFunc   module_start_unload;
  25 static MonoProfileModuleFunc   module_end_unload;
  26
  27 static MonoProfileClassFunc   class_start_load;
  28 static MonoProfileClassResult class_end_load;
  29 static MonoProfileClassFunc   class_start_unload;
  30 static MonoProfileClassFunc   class_end_unload;
  31
  32 static MonoProfileMethodFunc   jit_start;
  33 static MonoProfileMethodResult jit_end;
  34 static MonoProfileMethodResult man_unman_transition;
  35 static MonoProfileAllocFunc    allocation_cb;
  36 static MonoProfileMethodFunc   method_enter;
  37 static MonoProfileMethodFunc   method_leave;
  38
  39 static MonoProfileThreadFunc   thread_start;
  40 static MonoProfileThreadFunc   thread_end;
  41
  42 static MonoProfileCoverageFilterFunc coverage_filter_cb;
  43
  44 static MonoProfileFunc shutdown_callback;
  45
  46 static CRITICAL_SECTION profiler_coverage_mutex;
  47
  48 /* this is directly accessible to other mono libs. */
  49 MonoProfileFlags mono_profiler_events;
  50
  51 void
  52 mono_profiler_install (MonoProfiler *prof, MonoProfileFunc callback)
  53 {
  54         if (current_profiler)
  55                 g_error ("profiler already setup");
  56         current_profiler = prof;
  57         shutdown_callback = callback;
  58         InitializeCriticalSection (&profiler_coverage_mutex);
  59 }
  60
  61 void
  62 mono_profiler_set_events (MonoProfileFlags events)
  63 {
  64         mono_profiler_events = events;
  65 }
  66
  67 MonoProfileFlags
  68 mono_profiler_get_events (void)
  69 {
  70         return mono_profiler_events;
  71 }
  72
  73 void
  74 mono_profiler_install_enter_leave (MonoProfileMethodFunc enter, MonoProfileMethodFunc fleave)
  75 {
  76         method_enter = enter;
  77         method_leave = fleave;
  78 }
  79
  80 void
  81 mono_profiler_install_jit_compile (MonoProfileMethodFunc start, MonoProfileMethodResult end)
  82 {
  83         jit_start = start;
  84         jit_end = end;
  85 }
  86
  87 void
  88 mono_profiler_install_thread (MonoProfileThreadFunc start, MonoProfileThreadFunc end)
  89 {
  90         thread_start = start;
  91         thread_end = end;
  92 }
  93
  94 void
  95 mono_profiler_install_transition (MonoProfileMethodResult callback)
  96 {
  97         man_unman_transition = callback;
  98 }
  99
 100 void
 101 mono_profiler_install_allocation (MonoProfileAllocFunc callback)
 102 {
 103         allocation_cb = callback;
 104 }
 105
 106 void
 107 mono_profiler_install_coverage_filter (MonoProfileCoverageFilterFunc callback)
 108 {
 109         coverage_filter_cb = callback;
 110 }
 111
 112 void
 113 mono_profiler_install_appdomain   (MonoProfileAppDomainFunc start_load, MonoProfileAppDomainResult end_load,
 114                                    MonoProfileAppDomainFunc start_unload, MonoProfileAppDomainFunc end_unload)
 115
 116 {
 117         domain_start_load = start_load;
 118         domain_end_load = end_load;
 119         domain_start_unload = start_unload;
 120         domain_end_unload = end_unload;
 121 }
 122
 123 void
 124 mono_profiler_install_assembly    (MonoProfileAssemblyFunc start_load, MonoProfileAssemblyResult end_load,
 125                                    MonoProfileAssemblyFunc start_unload, MonoProfileAssemblyFunc end_unload)
 126 {
 127         assembly_start_load = start_load;
 128         assembly_end_load = end_load;
 129         assembly_start_unload = start_unload;
 130         assembly_end_unload = end_unload;
 131 }
 132
 133 void
 134 mono_profiler_install_module      (MonoProfileModuleFunc start_load, MonoProfileModuleResult end_load,
 135                                    MonoProfileModuleFunc start_unload, MonoProfileModuleFunc end_unload)
 136 {
 137         module_start_load = start_load;
 138         module_end_load = end_load;
 139         module_start_unload = start_unload;
 140         module_end_unload = end_unload;
 141 }
 142
 143 void
 144 mono_profiler_install_class       (MonoProfileClassFunc start_load, MonoProfileClassResult end_load,
 145                                    MonoProfileClassFunc start_unload, MonoProfileClassFunc end_unload)
 146 {
 147         class_start_load = start_load;
 148         class_end_load = end_load;
 149         class_start_unload = start_unload;
 150         class_end_unload = end_unload;
 151 }
 152
 153 void
 154 mono_profiler_method_enter (MonoMethod *method)
 155 {
 156         if ((mono_profiler_events & MONO_PROFILE_ENTER_LEAVE) && method_enter)
 157                 method_enter (current_profiler, method);
 158 }
 159
 160 void
 161 mono_profiler_method_leave (MonoMethod *method)
 162 {
 163         if ((mono_profiler_events & MONO_PROFILE_ENTER_LEAVE) && method_leave)
 164                 method_leave (current_profiler, method);
 165 }
 166
 167 void
 168 mono_profiler_method_jit (MonoMethod *method)
 169 {
 170         if ((mono_profiler_events & MONO_PROFILE_JIT_COMPILATION) && jit_start)
 171                 jit_start (current_profiler, method);
 172 }
 173
 174 void
 175 mono_profiler_method_end_jit (MonoMethod *method, int result)
 176 {
 177         if ((mono_profiler_events & MONO_PROFILE_JIT_COMPILATION) && jit_end)
 178                 jit_end (current_profiler, method, result);
 179 }
 180
 181 void
 182 mono_profiler_code_transition (MonoMethod *method, int result)
 183 {
 184         if ((mono_profiler_events & MONO_PROFILE_TRANSITIONS) && man_unman_transition)
 185                 man_unman_transition (current_profiler, method, result);
 186 }
 187
 188 void
 189 mono_profiler_allocation (MonoObject *obj, MonoClass *klass)
 190 {
 191         if ((mono_profiler_events & MONO_PROFILE_ALLOCATIONS) && allocation_cb)
 192                 allocation_cb (current_profiler, obj, klass);
 193 }
 194
 195 void
 196 mono_profiler_thread_start (guint32 tid)
 197 {
 198         if ((mono_profiler_events & MONO_PROFILE_THREADS) && thread_start)
 199                 thread_start (current_profiler, tid);
 200 }
 201
 202 void
 203 mono_profiler_thread_end (guint32 tid)
 204 {
 205         if ((mono_profiler_events & MONO_PROFILE_THREADS) && thread_end)
 206                 thread_end (current_profiler, tid);
 207 }
 208
 209 void
 210 mono_profiler_assembly_event  (MonoAssembly *assembly, int code)
 211 {
 212         if (!(mono_profiler_events & MONO_PROFILE_ASSEMBLY_EVENTS))
 213                 return;
 214
 215         switch (code) {
 216         case MONO_PROFILE_START_LOAD:
 217                 if (assembly_start_load)
 218                         assembly_start_load (current_profiler, assembly);
 219                 break;
 220         case MONO_PROFILE_START_UNLOAD:
 221                 if (assembly_start_unload)
 222                         assembly_start_unload (current_profiler, assembly);
 223                 break;
 224         case MONO_PROFILE_END_UNLOAD:
 225                 if (assembly_end_unload)
 226                         assembly_end_unload (current_profiler, assembly);
 227                 break;
 228         default:
 229                 g_assert_not_reached ();
 230         }
 231 }
 232
 233 void
 234 mono_profiler_assembly_loaded (MonoAssembly *assembly, int result)
 235 {
 236         if ((mono_profiler_events & MONO_PROFILE_ASSEMBLY_EVENTS) && assembly_end_load)
 237                 assembly_end_load (current_profiler, assembly, result);
 238 }
 239
 240 void
 241 mono_profiler_module_event  (MonoImage *module, int code)
 242 {
 243         if (!(mono_profiler_events & MONO_PROFILE_MODULE_EVENTS))
 244                 return;
 245
 246         switch (code) {
 247         case MONO_PROFILE_START_LOAD:
 248                 if (module_start_load)
 249                         module_start_load (current_profiler, module);
 250                 break;
 251         case MONO_PROFILE_START_UNLOAD:
 252                 if (module_start_unload)
 253                         module_start_unload (current_profiler, module);
 254                 break;
 255         case MONO_PROFILE_END_UNLOAD:
 256                 if (module_end_unload)
 257                         module_end_unload (current_profiler, module);
 258                 break;
 259         default:
 260                 g_assert_not_reached ();
 261         }
 262 }
 263
 264 void
 265 mono_profiler_module_loaded (MonoImage *module, int result)
 266 {
 267         if ((mono_profiler_events & MONO_PROFILE_MODULE_EVENTS) && module_end_load)
 268                 module_end_load (current_profiler, module, result);
 269 }
 270
 271 void
 272 mono_profiler_class_event  (MonoClass *klass, int code)
 273 {
 274         if (!(mono_profiler_events & MONO_PROFILE_CLASS_EVENTS))
 275                 return;
 276
 277         switch (code) {
 278         case MONO_PROFILE_START_LOAD:
 279                 if (class_start_load)
 280                         class_start_load (current_profiler, klass);
 281                 break;
 282         case MONO_PROFILE_START_UNLOAD:
 283                 if (class_start_unload)
 284                         class_start_unload (current_profiler, klass);
 285                 break;
 286         case MONO_PROFILE_END_UNLOAD:
 287                 if (class_end_unload)
 288                         class_end_unload (current_profiler, klass);
 289                 break;
 290         default:
 291                 g_assert_not_reached ();
 292         }
 293 }
 294
 295 void
 296 mono_profiler_class_loaded (MonoClass *klass, int result)
 297 {
 298         if ((mono_profiler_events & MONO_PROFILE_CLASS_EVENTS) && class_end_load)
 299                 class_end_load (current_profiler, klass, result);
 300 }
 301
 302 void
 303 mono_profiler_appdomain_event  (MonoDomain *domain, int code)
 304 {
 305         if (!(mono_profiler_events & MONO_PROFILE_APPDOMAIN_EVENTS))
 306                 return;
 307
 308         switch (code) {
 309         case MONO_PROFILE_START_LOAD:
 310                 if (domain_start_load)
 311                         domain_start_load (current_profiler, domain);
 312                 break;
 313         case MONO_PROFILE_START_UNLOAD:
 314                 if (domain_start_unload)
 315                         domain_start_unload (current_profiler, domain);
 316                 break;
 317         case MONO_PROFILE_END_UNLOAD:
 318                 if (domain_end_unload)
 319                         domain_end_unload (current_profiler, domain);
 320                 break;
 321         default:
 322                 g_assert_not_reached ();
 323         }
 324 }
 325
 326 void
 327 mono_profiler_appdomain_loaded (MonoDomain *domain, int result)
 328 {
 329         if ((mono_profiler_events & MONO_PROFILE_APPDOMAIN_EVENTS) && domain_end_load)
 330                 domain_end_load (current_profiler, domain, result);
 331 }
 332
 333 void
 334 mono_profiler_shutdown (void)
 335 {
 336         if (current_profiler && shutdown_callback)
 337                 shutdown_callback (current_profiler);
 338 }
 339
 340 static GHashTable *coverage_hash = NULL;
 341
 342 MonoProfileCoverageInfo*
 343 mono_profiler_coverage_alloc (MonoMethod *method, int entries)
 344 {
 345         MonoProfileCoverageInfo *res;
 346
 347         if (coverage_filter_cb)
 348                 if (! (*coverage_filter_cb) (current_profiler, method))
 349                         return NULL;
 350
 351         EnterCriticalSection (&profiler_coverage_mutex);
 352         if (!coverage_hash)
 353                 coverage_hash = g_hash_table_new (NULL, NULL);
 354
 355         res = g_malloc0 (sizeof (MonoProfileCoverageInfo) + sizeof (void*) * 2 * entries);
 356
 357         res->entries = entries;
 358
 359         g_hash_table_insert (coverage_hash, method, res);
 360         LeaveCriticalSection (&profiler_coverage_mutex);
 361
 362         return res;
 363 }
 364
 365 /* safe only when the method antive code has been unloaded */
 366 void
 367 mono_profiler_coverage_free (MonoMethod *method)
 368 {
 369         MonoProfileCoverageInfo* info;
 370
 371         EnterCriticalSection (&profiler_coverage_mutex);
 372         if (!coverage_hash) {
 373                 LeaveCriticalSection (&profiler_coverage_mutex);
 374                 return;
 375         }
 376
 377         info = g_hash_table_lookup (coverage_hash, method);
 378         if (info) {
 379                 g_free (info);
 380                 g_hash_table_remove (coverage_hash, method);
 381         }
 382         LeaveCriticalSection (&profiler_coverage_mutex);
 383 }
 384
 385 void
 386 mono_profiler_coverage_get (MonoProfiler *prof, MonoMethod *method, MonoProfileCoverageFunc func)
 387 {
 388         MonoProfileCoverageInfo* info;
 389         int i, offset;
 390         guint32 line, col;
 391         unsigned char *start, *end, *cil_code;
 392         MonoMethodHeader *header;
 393         MonoProfileCoverageEntry entry;
 394
 395         EnterCriticalSection (&profiler_coverage_mutex);
 396         info = g_hash_table_lookup (coverage_hash, method);
 397         LeaveCriticalSection (&profiler_coverage_mutex);
 398
 399         if (!info)
 400                 return;
 401
 402         header = mono_method_get_header (method);
 403         start = (unsigned char*)header->code;
 404         end = start + header->code_size;
 405         for (i = 0; i < info->entries; ++i) {
 406                 cil_code = info->data [i].cil_code;
 407                 if (cil_code && cil_code >= start && cil_code < end) {
 408                         offset = cil_code - start;
 409                         entry.iloffset = offset;
 410                         entry.method = method;
 411                         entry.counter = info->data [i].count;
 412                         /* the debug interface doesn't support column info, sigh */
 413                         col = line = 1;
 414                         entry.filename = mono_debug_source_location_from_il_offset (method, offset, &line);
 415                         entry.line = line;
 416                         entry.col = col;
 417                         func (prof, &entry);
 418                 }
 419         }
 420 }
 421
 422 /*
 423  * Small profiler extracted from mint: we should move it in a loadable module
 424  * and improve it to do graphs and more accurate timestamping with rdtsc.
 425  */
 426
 427 #define USE_X86TSC 0
 428 #define USE_WIN32COUNTER 0
 429 #if USE_X86TSC
 430
 431 typedef struct {
 432         unsigned int lows, highs, lowe, highe;
 433 } MonoRdtscTimer;
 434
 435 #define rdtsc(low,high) \
 436         __asm__ __volatile__("rdtsc" : "=a" (low), "=d" (high))
 437
 438 static int freq;
 439
 440 static double
 441 rdtsc_elapsed (MonoRdtscTimer *t)
 442 {
 443         unsigned long long diff;
 444         unsigned int highe = t->highe;
 445         if (t->lowe < t->lows)
 446                 highe--;
 447         diff = (((unsigned long long) highe - t->highs) << 32) + (t->lowe - t->lows);
 448         return ((double)diff / freq) / 1000000; /* have to return the result in seconds */
 449 }
 450
 451 static int
 452 have_rdtsc (void) {
 453         char buf[256];
 454         int have_freq = 0;
 455         int have_flag = 0;
 456         float val;
 457         FILE *cpuinfo;
 458
 459         if (!(cpuinfo = fopen ("/proc/cpuinfo", "r")))
 460                 return 0;
 461         while (fgets (buf, sizeof(buf), cpuinfo)) {
 462                 if (sscanf (buf, "cpu MHz : %f", &val) == 1) {
 463                         /*printf ("got mh: %f\n", val);*/
 464                         have_freq = val;
 465                 }
 466                 if (strncmp (buf, "flags", 5) == 0) {
 467                         if (strstr (buf, "tsc")) {
 468                                 have_flag = 1;
 469                                 /*printf ("have tsc\n");*/
 470                         }
 471                 }
 472         }
 473         fclose (cpuinfo);
 474         return have_flag? have_freq: 0;
 475 }
 476
 477 #define MONO_TIMER_STARTUP      \
 478         if (!(freq = have_rdtsc ())) g_error ("Compiled with TSC support, but none found");
 479 #define MONO_TIMER_TYPE  MonoRdtscTimer
 480 #define MONO_TIMER_INIT(t)
 481 #define MONO_TIMER_DESTROY(t)
 482 #define MONO_TIMER_START(t) rdtsc ((t).lows, (t).highs);
 483 #define MONO_TIMER_STOP(t) rdtsc ((t).lowe, (t).highe);
 484 #define MONO_TIMER_ELAPSED(t) rdtsc_elapsed (&(t))
 485
 486 #elif USE_WIN32COUNTER
 487 #include <windows.h>
 488
 489 typedef struct {
 490         LARGE_INTEGER start, stop;
 491 } MonoWin32Timer;
 492
 493 static int freq;
 494
 495 static double
 496 win32_elapsed (MonoWin32Timer *t)
 497 {
 498         LONGLONG diff = t->stop.QuadPart - t->start.QuadPart;
 499         return ((double)diff / freq) / 1000000; /* have to return the result in seconds */
 500 }
 501
 502 static int
 503 have_win32counter (void) {
 504         LARGE_INTEGER f;
 505
 506         if (!QueryPerformanceFrequency (&f))
 507                 return 0;
 508         return f.LowPart;
 509 }
 510
 511 #define MONO_TIMER_STARTUP      \
 512         if (!(freq = have_win32counter ())) g_error ("Compiled with Win32 counter support, but none found");
 513 #define MONO_TIMER_TYPE  MonoWin32Timer
 514 #define MONO_TIMER_INIT(t)
 515 #define MONO_TIMER_DESTROY(t)
 516 #define MONO_TIMER_START(t) QueryPerformanceCounter (&(t).start)
 517 #define MONO_TIMER_STOP(t) QueryPerformanceCounter (&(t).stop)
 518 #define MONO_TIMER_ELAPSED(t) win32_elapsed (&(t))
 519
 520 #else
 521
 522 typedef struct {
 523         GTimeVal start, stop;
 524 } MonoGLibTimer;
 525
 526 static double
 527 timeval_elapsed (MonoGLibTimer *t)
 528 {
 529         if (t->start.tv_usec > t->stop.tv_usec) {
 530                 t->stop.tv_usec += G_USEC_PER_SEC;
 531                 t->stop.tv_sec--;
 532         }
 533         return (t->stop.tv_sec - t->start.tv_sec)
 534                 + ((double)(t->stop.tv_usec - t->start.tv_usec))/ G_USEC_PER_SEC;
 535 }
 536
 537 #define MONO_TIMER_STARTUP
 538 #define MONO_TIMER_TYPE MonoGLibTimer
 539 #define MONO_TIMER_INIT(t)
 540 #define MONO_TIMER_DESTROY(t)
 541 #define MONO_TIMER_START(t) g_get_current_time (&(t).start)
 542 #define MONO_TIMER_STOP(t) g_get_current_time (&(t).stop)
 543 #define MONO_TIMER_ELAPSED(t) timeval_elapsed (&(t))
 544 #endif
 545
 546 typedef struct _AllocInfo AllocInfo;
 547 typedef struct _CallerInfo CallerInfo;
 548 typedef struct _LastCallerInfo LastCallerInfo;
 549
 550 struct _MonoProfiler {
 551         GHashTable *methods;
 552         MonoMemPool *mempool;
 553         /* info about JIT time */
 554         MONO_TIMER_TYPE jit_timer;
 555         double      jit_time;
 556         double      max_jit_time;
 557         MonoMethod *max_jit_method;
 558         int         methods_jitted;
 559
 560         GSList     *per_thread;
 561
 562         /* chain of callers for the current thread */
 563         LastCallerInfo *callers;
 564         /* LastCallerInfo nodes for faster allocation */
 565         LastCallerInfo *cstorage;
 566 };
 567
 568 typedef struct {
 569         MonoMethod *method;
 570         guint64 count;
 571         double total;
 572         AllocInfo *alloc_info;
 573         CallerInfo *caller_info;
 574 } MethodProfile;
 575
 576 typedef struct _MethodCallProfile MethodCallProfile;
 577
 578 struct _MethodCallProfile {
 579         MethodCallProfile *next;
 580         MONO_TIMER_TYPE timer;
 581         MonoMethod *method;
 582 };
 583
 584 struct _AllocInfo {
 585         AllocInfo *next;
 586         MonoClass *klass;
 587         guint count;
 588         guint mem;
 589 };
 590
 591 struct _CallerInfo {
 592         CallerInfo *next;
 593         MonoMethod *caller;
 594         guint count;
 595 };
 596
 597 struct _LastCallerInfo {
 598         LastCallerInfo *next;
 599         MonoMethod *method;
 600         MONO_TIMER_TYPE timer;
 601 };
 602
 603 static MonoProfiler*
 604 create_profiler (void)
 605 {
 606         MonoProfiler *prof = g_new0 (MonoProfiler, 1);
 607
 608         prof->methods = g_hash_table_new (NULL, NULL);
 609         MONO_TIMER_INIT (prof->jit_timer);
 610         prof->mempool = mono_mempool_new ();
 611         return prof;
 612 }
 613 #if 1
 614
 615 #ifdef HAVE_KW_THREAD
 616         static __thread MonoProfiler * tls_profiler;
 617 #       define GET_PROFILER() tls_profiler
 618 #       define SET_PROFILER(x) tls_profiler = (x)
 619 #       define ALLOC_PROFILER() /* nop */
 620 #else
 621         static guint32 profiler_thread_id = -1;
 622 #       define GET_PROFILER() ((MonoProfiler *)TlsGetValue (profiler_thread_id))
 623 #       define SET_PROFILER(x) TlsSetValue (profiler_thread_id, x);
 624 #       define ALLOC_PROFILER() profiler_thread_id = TlsAlloc ()
 625 #endif
 626
 627 #define GET_THREAD_PROF(prof) do {                                                           \
 628                 MonoProfiler *_tprofiler = GET_PROFILER ();                                  \
 629                 if (!_tprofiler) {                                                           \
 630                         _tprofiler = create_profiler ();                                     \
 631                         prof->per_thread = g_slist_prepend (prof->per_thread, _tprofiler);   \
 632                         SET_PROFILER (_tprofiler);                                           \
 633                 }                                                                            \
 634                 prof = _tprofiler;                                                           \
 635         } while (0)
 636 #else
 637 /* thread unsafe but faster variant */
 638 #define GET_THREAD_PROF(prof)
 639 #endif
 640
 641 static gint
 642 compare_profile (MethodProfile *profa, MethodProfile *profb)
 643 {
 644         return (gint)((profb->total - profa->total)*1000);
 645 }
 646
 647 static void
 648 build_profile (MonoMethod *m, MethodProfile *prof, GList **funcs)
 649 {
 650         prof->method = m;
 651         *funcs = g_list_insert_sorted (*funcs, prof, (GCompareFunc)compare_profile);
 652 }
 653
 654 static char*
 655 method_get_name (MonoMethod* method)
 656 {
 657         char *sig, *res;
 658
 659         sig = mono_signature_get_desc (method->signature, FALSE);
 660         res = g_strdup_printf ("%s.%s::%s(%s)", method->klass->name_space, method->klass->name,
 661                 method->name, sig);
 662         g_free (sig);
 663         return res;
 664 }
 665
 666 static void output_callers (MethodProfile *p);
 667
 668 static void
 669 output_profile (GList *funcs)
 670 {
 671         GList *tmp;
 672         MethodProfile *p;
 673         char *m;
 674         guint64 total_calls = 0;
 675
 676         if (funcs)
 677                 g_print ("Time(ms) Count   P/call(ms) Method name\n");
 678         for (tmp = funcs; tmp; tmp = tmp->next) {
 679                 p = tmp->data;
 680                 total_calls += p->count;
 681                 if (!(gint)(p->total*1000))
 682                         continue;
 683                 m = method_get_name (p->method);
 684                 printf ("########################\n");
 685                 printf ("% 8.3f ", (double) (p->total * 1000));
 686                 printf ("%7llu ", p->count);
 687                 printf ("% 8.3f ", (double) (p->total * 1000)/(double)p->count);
 688                 printf ("  %s\n", m);
 689
 690                 g_free (m);
 691                 /* callers */
 692                 output_callers (p);
 693         }
 694         printf ("Total number of calls: %lld\n", total_calls);
 695 }
 696
 697 typedef struct {
 698         MethodProfile *mp;
 699         guint count;
 700 } NewobjProfile;
 701
 702 static gint
 703 compare_newobj_profile (NewobjProfile *profa, NewobjProfile *profb)
 704 {
 705         return (gint)profb->count - (gint)profa->count;
 706 }
 707
 708 static void
 709 build_newobj_profile (MonoClass *class, MethodProfile *mprof, GList **funcs)
 710 {
 711         NewobjProfile *prof = g_new (NewobjProfile, 1);
 712         AllocInfo *tmp;
 713         guint count = 0;
 714
 715         prof->mp = mprof;
 716         /* we use the total amount of memory to sort */
 717         for (tmp = mprof->alloc_info; tmp; tmp = tmp->next)
 718                 count += tmp->mem;
 719         prof->count = count;
 720         *funcs = g_list_insert_sorted (*funcs, prof, (GCompareFunc)compare_newobj_profile);
 721 }
 722
 723 static int
 724 compare_caller (CallerInfo *a, CallerInfo *b)
 725 {
 726         return b->count - a->count;
 727 }
 728
 729 static int
 730 compare_alloc (AllocInfo *a, AllocInfo *b)
 731 {
 732         return b->mem - a->mem;
 733 }
 734
 735 static GSList*
 736 sort_alloc_list (AllocInfo *ai)
 737 {
 738         GSList *l = NULL;
 739         AllocInfo *tmp;
 740         for (tmp = ai; tmp; tmp = tmp->next) {
 741                 l = g_slist_insert_sorted (l, tmp, (GCompareFunc)compare_alloc);
 742         }
 743         return l;
 744 }
 745
 746 static GSList*
 747 sort_caller_list (CallerInfo *ai)
 748 {
 749         GSList *l = NULL;
 750         CallerInfo *tmp;
 751         for (tmp = ai; tmp; tmp = tmp->next) {
 752                 l = g_slist_insert_sorted (l, tmp, (GCompareFunc)compare_caller);
 753         }
 754         return l;
 755 }
 756
 757 static void
 758 output_callers (MethodProfile *p) {
 759         guint total_callers, percent;
 760         GSList *sorted, *tmps;
 761         CallerInfo *cinfo;
 762         char *m;
 763
 764         g_print ("  Callers (with count) that contribute at least for 1%%:\n");
 765         total_callers = 0;
 766         for (cinfo = p->caller_info; cinfo; cinfo = cinfo->next) {
 767                 total_callers += cinfo->count;
 768         }
 769         sorted = sort_caller_list (p->caller_info);
 770         for (tmps = sorted; tmps; tmps = tmps->next) {
 771                 cinfo = tmps->data;
 772                 percent = (cinfo->count * 100)/total_callers;
 773                 if (percent < 1)
 774                         continue;
 775                 m = method_get_name (cinfo->caller);
 776                 g_print ("    %8d % 3d %% %s\n", cinfo->count, percent, m);
 777                 g_free (m);
 778         }
 779 }
 780
 781 static void
 782 output_newobj_profile (GList *proflist)
 783 {
 784         GList *tmp;
 785         NewobjProfile *p;
 786         MethodProfile *mp;
 787         AllocInfo *ainfo;
 788         MonoClass *klass;
 789         const char* isarray;
 790         char buf [256];
 791         char *m;
 792         guint total = 0;
 793         GSList *sorted, *tmps;
 794
 795         g_print ("\nAllocation profiler\n");
 796
 797         if (proflist)
 798                 g_print ("%-9s %s\n", "Total mem", "Method");
 799         for (tmp = proflist; tmp; tmp = tmp->next) {
 800                 p = tmp->data;
 801                 total += p->count;
 802                 if (p->count < 50000)
 803                         continue;
 804                 mp = p->mp;
 805                 m = method_get_name (mp->method);
 806                 g_print ("########################\n%8d KB %s\n", p->count / 1024, m);
 807                 g_free (m);
 808                 sorted = sort_alloc_list (mp->alloc_info);
 809                 for (tmps = sorted; tmps; tmps = tmps->next) {
 810                         ainfo = tmps->data;
 811                         if (ainfo->mem < 50000)
 812                                 continue;
 813                         klass = ainfo->klass;
 814                         if (klass->rank) {
 815                                 isarray = "[]";
 816                                 klass = klass->element_class;
 817                         } else {
 818                                 isarray = "";
 819                         }
 820                         g_snprintf (buf, sizeof (buf), "%s.%s%s",
 821                                 klass->name_space, klass->name, isarray);
 822                         g_print ("    %8d KB %8d %-48s\n", ainfo->mem / 1024, ainfo->count, buf);
 823                 }
 824                 /* callers */
 825                 output_callers (mp);
 826         }
 827         g_print ("Total memory allocated: %d KB\n", total / 1024);
 828 }
 829
 830 static void
 831 merge_methods (MonoMethod *method, MethodProfile *profile, MonoProfiler *prof)
 832 {
 833         MethodProfile *mprof;
 834         AllocInfo *talloc_info, *alloc_info;
 835         CallerInfo *tcaller_info, *caller_info;
 836
 837         mprof = g_hash_table_lookup (prof->methods, method);
 838         if (!mprof) {
 839                 /* the master thread didn't see this method, just transfer the info as is */
 840                 g_hash_table_insert (prof->methods, method, profile);
 841                 return;
 842         }
 843         /* merge the info from profile into mprof */
 844         mprof->count += profile->count;
 845         mprof->total += profile->total;
 846         /* merge alloc info */
 847         for (talloc_info = profile->alloc_info; talloc_info; talloc_info = talloc_info->next) {
 848                 for (alloc_info = mprof->alloc_info; alloc_info; alloc_info = alloc_info->next) {
 849                         if (alloc_info->klass == talloc_info->klass) {
 850                                 /* mprof already has a record for the klass, merge */
 851                                 alloc_info->count += talloc_info->count;
 852                                 alloc_info->mem += talloc_info->mem;
 853                                 break;
 854                         }
 855                 }
 856                 if (!alloc_info) {
 857                         /* mprof didn't have the info, just copy it over */
 858                         alloc_info = mono_mempool_alloc0 (prof->mempool, sizeof (AllocInfo));
 859                         *alloc_info = *talloc_info;
 860                         alloc_info->next = mprof->alloc_info;
 861                         mprof->alloc_info = alloc_info->next;
 862                 }
 863         }
 864         /* merge callers info */
 865         for (tcaller_info = profile->caller_info; tcaller_info; tcaller_info = tcaller_info->next) {
 866                 for (caller_info = mprof->caller_info; caller_info; caller_info = caller_info->next) {
 867                         if (caller_info->caller == tcaller_info->caller) {
 868                                 /* mprof already has a record for the caller method, merge */
 869                                 caller_info->count += tcaller_info->count;
 870                                 break;
 871                         }
 872                 }
 873                 if (!caller_info) {
 874                         /* mprof didn't have the info, just copy it over */
 875                         caller_info = mono_mempool_alloc0 (prof->mempool, sizeof (CallerInfo));
 876                         *caller_info = *tcaller_info;
 877                         caller_info->next = mprof->caller_info;
 878                         mprof->caller_info = caller_info;
 879                 }
 880         }
 881 }
 882
 883 static void
 884 merge_thread_data (MonoProfiler *master, MonoProfiler *tprof)
 885 {
 886         master->jit_time += tprof->jit_time;
 887         master->methods_jitted += tprof->methods_jitted;
 888         if (master->max_jit_time < tprof->max_jit_time) {
 889                 master->max_jit_time = tprof->max_jit_time;
 890                 master->max_jit_method = tprof->max_jit_method;
 891         }
 892
 893         g_hash_table_foreach (tprof->methods, (GHFunc)merge_methods, master);
 894 }
 895
 896 static void
 897 simple_method_enter (MonoProfiler *prof, MonoMethod *method)
 898 {
 899         MethodProfile *profile_info;
 900         LastCallerInfo *callinfo;
 901         GET_THREAD_PROF (prof);
 902         /*g_print ("enter %p %s::%s in %d (%p)\n", method, method->klass->name, method->name, GetCurrentThreadId (), prof);*/
 903         if (!(profile_info = g_hash_table_lookup (prof->methods, method))) {
 904                 profile_info = mono_mempool_alloc0 (prof->mempool, sizeof (MethodProfile));
 905                 MONO_TIMER_INIT (profile_info->u.timer);
 906                 g_hash_table_insert (prof->methods, method, profile_info);
 907         }
 908         profile_info->count++;
 909         if (prof->callers) {
 910                 CallerInfo *cinfo;
 911                 MonoMethod *caller = prof->callers->method;
 912                 for (cinfo = profile_info->caller_info; cinfo; cinfo = cinfo->next) {
 913                         if (cinfo->caller == caller)
 914                                 break;
 915                 }
 916                 if (!cinfo) {
 917                         cinfo = mono_mempool_alloc0 (prof->mempool, sizeof (CallerInfo));
 918                         cinfo->caller = caller;
 919                         cinfo->next = profile_info->caller_info;
 920                         profile_info->caller_info = cinfo;
 921                 }
 922                 cinfo->count++;
 923         }
 924         if (!(callinfo = prof->cstorage)) {
 925                 callinfo = mono_mempool_alloc (prof->mempool, sizeof (LastCallerInfo));
 926                 MONO_TIMER_INIT (callinfo->timer);
 927         } else {
 928                 prof->cstorage = prof->cstorage->next;
 929         }
 930         callinfo->method = method;
 931         callinfo->next = prof->callers;
 932         prof->callers = callinfo;
 933         MONO_TIMER_START (callinfo->timer);
 934 }
 935
 936 static void
 937 simple_method_leave (MonoProfiler *prof, MonoMethod *method)
 938 {
 939         MethodProfile *profile_info;
 940         LastCallerInfo *callinfo, *newcallinfo = NULL;
 941
 942         GET_THREAD_PROF (prof);
 943         /*g_print ("leave %p %s::%s in %d (%p)\n", method, method->klass->name, method->name, GetCurrentThreadId (), prof);*/
 944         callinfo = prof->callers;
 945         /* should really not happen, but we don't catch exceptions events, yet ... */
 946         while (callinfo) {
 947                 MONO_TIMER_STOP (callinfo->timer);
 948                 profile_info = g_hash_table_lookup (prof->methods, callinfo->method);
 949                 if (profile_info)
 950                         profile_info->total += MONO_TIMER_ELAPSED (callinfo->timer);
 951                 newcallinfo = callinfo->next;
 952                 callinfo->next = prof->cstorage;
 953                 prof->cstorage = callinfo;
 954                 if (callinfo->method == method)
 955                         break;
 956                 callinfo = newcallinfo;
 957         }
 958         prof->callers = newcallinfo;
 959 }
 960
 961 static void
 962 simple_allocation (MonoProfiler *prof, MonoObject *obj, MonoClass *klass)
 963 {
 964         MethodProfile *profile_info;
 965         AllocInfo *tmp;
 966
 967         GET_THREAD_PROF (prof);
 968         if (prof->callers) {
 969                 MonoMethod *caller = prof->callers->method;
 970
 971                 /* Otherwise all allocations are attributed to icall_wrapper_mono_object_new */
 972                 if (caller->wrapper_type == MONO_WRAPPER_MANAGED_TO_NATIVE)
 973                         caller = prof->callers->next->method;
 974
 975                 if (!(profile_info = g_hash_table_lookup (prof->methods, caller)))
 976                         g_assert_not_reached ();
 977         } else {
 978                 return; /* fine for now */
 979         }
 980
 981         for (tmp = profile_info->alloc_info; tmp; tmp = tmp->next) {
 982                 if (tmp->klass == klass)
 983                         break;
 984         }
 985         if (!tmp) {
 986                 tmp = mono_mempool_alloc0 (prof->mempool, sizeof (AllocInfo));
 987                 tmp->klass = klass;
 988                 tmp->next = profile_info->alloc_info;
 989                 profile_info->alloc_info = tmp;
 990         }
 991         tmp->count++;
 992         if (klass == mono_defaults.string_class) {
 993                 tmp->mem += sizeof (MonoString) + 2 * mono_string_length ((MonoString*)obj) + 2;
 994         } else if (klass->parent == mono_defaults.array_class) {
 995                 tmp->mem += sizeof (MonoArray) + mono_array_element_size (klass) * mono_array_length ((MonoArray*)obj);
 996         } else {
 997                 tmp->mem += mono_class_instance_size (klass);
 998         }
 999 }
1000
1001 static void
1002 simple_method_jit (MonoProfiler *prof, MonoMethod *method)
1003 {
1004         GET_THREAD_PROF (prof);
1005         prof->methods_jitted++;
1006         MONO_TIMER_START (prof->jit_timer);
1007 }
1008
1009 static void
1010 simple_method_end_jit (MonoProfiler *prof, MonoMethod *method, int result)
1011 {
1012         double jtime;
1013         GET_THREAD_PROF (prof);
1014         MONO_TIMER_STOP (prof->jit_timer);
1015         jtime = MONO_TIMER_ELAPSED (prof->jit_timer);
1016         prof->jit_time += jtime;
1017         if (jtime > prof->max_jit_time) {
1018                 prof->max_jit_time = jtime;
1019                 prof->max_jit_method = method;
1020         }
1021 }
1022
1023 static void
1024 simple_shutdown (MonoProfiler *prof)
1025 {
1026         GList *profile = NULL;
1027         MonoProfiler *tprof;
1028         GSList *tmp;
1029         char *str;
1030
1031         for (tmp = prof->per_thread; tmp; tmp = tmp->next) {
1032                 tprof = tmp->data;
1033                 merge_thread_data (prof, tprof);
1034         }
1035
1036         printf("Total time spent compiling %d methods (sec): %.4g\n", prof->methods_jitted, prof->jit_time);
1037         if (prof->max_jit_method) {
1038                 str = method_get_name (prof->max_jit_method);
1039                 printf("Slowest method to compile (sec): %.4g: %s\n", prof->max_jit_time, str);
1040                 g_free (str);
1041         }
1042         g_hash_table_foreach (prof->methods, (GHFunc)build_profile, &profile);
1043         output_profile (profile);
1044         g_list_free (profile);
1045         profile = NULL;
1046
1047         g_hash_table_foreach (prof->methods, (GHFunc)build_newobj_profile, &profile);
1048         output_newobj_profile (profile);
1049         g_list_free (profile);
1050 }
1051
1052 static void
1053 mono_profiler_install_simple (const char *desc)
1054 {
1055         MonoProfiler *prof;
1056         gchar **args, **ptr;
1057         MonoProfileFlags flags = MONO_PROFILE_ENTER_LEAVE|MONO_PROFILE_JIT_COMPILATION|MONO_PROFILE_ALLOCATIONS;
1058
1059         MONO_TIMER_STARTUP;
1060
1061         if (desc) {
1062                 /* Parse options */
1063                 if (strstr (desc, ":"))
1064                         desc = strstr (desc, ":") + 1;
1065                 else
1066                         desc = NULL;
1067                 args = g_strsplit (desc ? desc : "", ",", -1);
1068
1069                 for (ptr = args; ptr && *ptr; ptr++) {
1070                         const char *arg = *ptr;
1071
1072                         if (!strcmp (arg, "-time"))
1073                                 flags &= ~MONO_PROFILE_ENTER_LEAVE;
1074                         else
1075                            if (!strcmp (arg, "-alloc"))
1076                                    flags &= ~MONO_PROFILE_ALLOCATIONS;
1077                            else {
1078                                    fprintf (stderr, "profiler : Unknown argument '%s'.\n", arg);
1079                                    return;
1080                            }
1081                 }
1082         }
1083
1084         prof = create_profiler ();
1085         ALLOC_PROFILER ();
1086         SET_PROFILER (prof);
1087
1088         mono_profiler_install (prof, simple_shutdown);
1089         /* later do also object creation */
1090         mono_profiler_install_enter_leave (simple_method_enter, simple_method_leave);
1091         mono_profiler_install_jit_compile (simple_method_jit, simple_method_end_jit);
1092         mono_profiler_install_allocation (simple_allocation);
1093         mono_profiler_set_events (flags);
1094 }
1095
1096 typedef void (*ProfilerInitializer) (const char*);
1097 #define INITIALIZER_NAME "mono_profiler_startup"
1098
1099 void
1100 mono_profiler_load (const char *desc)
1101 {
1102         if (!desc || (strcmp ("default", desc) == 0) || (strncmp (desc, "default:", 8) == 0)) {
1103                 mono_profiler_install_simple (desc);
1104         } else {
1105                 GModule *pmodule;
1106                 const char* col = strchr (desc, ':');
1107                 char* libname;
1108                 char* path;
1109                 char *mname;
1110                 if (col != NULL) {
1111                         mname = g_memdup (desc, col - desc);
1112                         mname [col - desc] = 0;
1113                 } else {
1114                         mname = g_strdup (desc);
1115                 }
1116                 libname = g_strdup_printf ("mono-profiler-%s", mname);
1117                 path = g_module_build_path (NULL, libname);
1118                 pmodule = g_module_open (path, G_MODULE_BIND_LAZY);
1119                 if (pmodule) {
1120                         ProfilerInitializer func;
1121                         if (!g_module_symbol (pmodule, INITIALIZER_NAME, (gpointer *)&func)) {
1122                                 g_warning ("Cannot find initializer function %s in profiler module: %s", INITIALIZER_NAME, libname);
1123                         } else {
1124                                 func (desc);
1125                         }
1126                 } else {
1127                         g_warning ("Error loading profiler module '%s': %s", libname, g_module_error ());
1128                 }
1129
1130                 g_free (libname);
1131                 g_free (mname);
1132                 g_free (path);
1133         }
1134 }
1135