mono/metadata/profiler.c

   1
   2 #include "mono/metadata/profiler-private.h"
   3 #include "mono/metadata/debug-helpers.h"
   4 #include <string.h>
   5
   6 static MonoProfiler * current_profiler = NULL;
   7
   8 static MonoProfileAppDomainFunc   domain_start_load;
   9 static MonoProfileAppDomainResult domain_end_load;
  10 static MonoProfileAppDomainFunc   domain_start_unload;
  11 static MonoProfileAppDomainFunc   domain_end_unload;
  12
  13 static MonoProfileAssemblyFunc   assembly_start_load;
  14 static MonoProfileAssemblyResult assembly_end_load;
  15 static MonoProfileAssemblyFunc   assembly_start_unload;
  16 static MonoProfileAssemblyFunc   assembly_end_unload;
  17
  18 static MonoProfileModuleFunc   module_start_load;
  19 static MonoProfileModuleResult module_end_load;
  20 static MonoProfileModuleFunc   module_start_unload;
  21 static MonoProfileModuleFunc   module_end_unload;
  22
  23 static MonoProfileClassFunc   class_start_load;
  24 static MonoProfileClassResult class_end_load;
  25 static MonoProfileClassFunc   class_start_unload;
  26 static MonoProfileClassFunc   class_end_unload;
  27
  28 static MonoProfileMethodFunc   jit_start;
  29 static MonoProfileMethodResult jit_end;
  30 static MonoProfileMethodResult man_unman_transition;
  31 static MonoProfileMethodFunc   method_enter;
  32 static MonoProfileMethodFunc   method_leave;
  33
  34 static MonoProfileThreadFunc   thread_start;
  35 static MonoProfileThreadFunc   thread_end;
  36
  37 static MonoProfileFunc shutdown_callback;
  38
  39 /* this is directly accessible to other mono libs. */
  40 MonoProfileFlags mono_profiler_events;
  41
  42 void
  43 mono_profiler_install (MonoProfiler *prof, MonoProfileFunc callback)
  44 {
  45         if (current_profiler)
  46                 g_error ("profiler already setup");
  47         current_profiler = prof;
  48         shutdown_callback = callback;
  49 }
  50
  51 void
  52 mono_profiler_set_events (MonoProfileFlags events)
  53 {
  54         mono_profiler_events = events;
  55 }
  56
  57 MonoProfileFlags
  58 mono_profiler_get_events (void)
  59 {
  60         return mono_profiler_events;
  61 }
  62
  63 void
  64 mono_profiler_install_enter_leave (MonoProfileMethodFunc enter, MonoProfileMethodFunc leave)
  65 {
  66         method_enter = enter;
  67         method_leave = leave;
  68 }
  69
  70 void
  71 mono_profiler_install_jit_compile (MonoProfileMethodFunc start, MonoProfileMethodResult end)
  72 {
  73         jit_start = start;
  74         jit_end = end;
  75 }
  76
  77 void
  78 mono_profiler_install_thread (MonoProfileThreadFunc start, MonoProfileThreadFunc end)
  79 {
  80         thread_start = start;
  81         thread_end = end;
  82 }
  83
  84 void
  85 mono_profiler_install_transition (MonoProfileMethodResult callback)
  86 {
  87         man_unman_transition = callback;
  88 }
  89
  90 void
  91 mono_profiler_install_appdomain   (MonoProfileAppDomainFunc start_load, MonoProfileAppDomainResult end_load,
  92                                    MonoProfileAppDomainFunc start_unload, MonoProfileAppDomainFunc end_unload)
  93
  94 {
  95         domain_start_load = start_load;
  96         domain_end_load = end_load;
  97         domain_start_unload = start_unload;
  98         domain_end_unload = end_unload;
  99 }
 100
 101 void
 102 mono_profiler_install_assembly    (MonoProfileAssemblyFunc start_load, MonoProfileAssemblyResult end_load,
 103                                    MonoProfileAssemblyFunc start_unload, MonoProfileAssemblyFunc end_unload)
 104 {
 105         assembly_start_load = start_load;
 106         assembly_end_load = end_load;
 107         assembly_start_unload = start_unload;
 108         assembly_end_unload = end_unload;
 109 }
 110
 111 void
 112 mono_profiler_install_module      (MonoProfileModuleFunc start_load, MonoProfileModuleResult end_load,
 113                                    MonoProfileModuleFunc start_unload, MonoProfileModuleFunc end_unload)
 114 {
 115         module_start_load = start_load;
 116         module_end_load = end_load;
 117         module_start_unload = start_unload;
 118         module_end_unload = end_unload;
 119 }
 120
 121 void
 122 mono_profiler_install_class       (MonoProfileClassFunc start_load, MonoProfileClassResult end_load,
 123                                    MonoProfileClassFunc start_unload, MonoProfileClassFunc end_unload)
 124 {
 125         class_start_load = start_load;
 126         class_end_load = end_load;
 127         class_start_unload = start_unload;
 128         class_end_unload = end_unload;
 129 }
 130
 131 void
 132 mono_profiler_method_enter (MonoMethod *method)
 133 {
 134         if ((mono_profiler_events & MONO_PROFILE_ENTER_LEAVE) && method_enter)
 135                 method_enter (current_profiler, method);
 136 }
 137
 138 void
 139 mono_profiler_method_leave (MonoMethod *method)
 140 {
 141         if ((mono_profiler_events & MONO_PROFILE_ENTER_LEAVE) && method_leave)
 142                 method_leave (current_profiler, method);
 143 }
 144
 145 void
 146 mono_profiler_method_jit (MonoMethod *method)
 147 {
 148         if ((mono_profiler_events & MONO_PROFILE_JIT_COMPILATION) && jit_start)
 149                 jit_start (current_profiler, method);
 150 }
 151
 152 void
 153 mono_profiler_method_end_jit (MonoMethod *method, int result)
 154 {
 155         if ((mono_profiler_events & MONO_PROFILE_JIT_COMPILATION) && jit_end)
 156                 jit_end (current_profiler, method, result);
 157 }
 158
 159 void
 160 mono_profiler_code_transition (MonoMethod *method, int result)
 161 {
 162         if ((mono_profiler_events & MONO_PROFILE_TRANSITIONS) && man_unman_transition)
 163                 man_unman_transition (current_profiler, method, result);
 164 }
 165
 166 void
 167 mono_profiler_thread_start (HANDLE thread)
 168 {
 169         if ((mono_profiler_events & MONO_PROFILE_THREADS) && thread_start)
 170                 thread_start (current_profiler, thread);
 171 }
 172
 173 void
 174 mono_profiler_thread_end (HANDLE thread)
 175 {
 176         if ((mono_profiler_events & MONO_PROFILE_THREADS) && thread_end)
 177                 thread_end (current_profiler, thread);
 178 }
 179
 180 void
 181 mono_profiler_assembly_event  (MonoAssembly *assembly, int code)
 182 {
 183         if (!(mono_profiler_events & MONO_PROFILE_ASSEMBLY_EVENTS))
 184                 return;
 185
 186         switch (code) {
 187         case MONO_PROFILE_START_LOAD:
 188                 if (assembly_start_load)
 189                         assembly_start_load (current_profiler, assembly);
 190                 break;
 191         case MONO_PROFILE_START_UNLOAD:
 192                 if (assembly_start_unload)
 193                         assembly_start_unload (current_profiler, assembly);
 194                 break;
 195         case MONO_PROFILE_END_UNLOAD:
 196                 if (assembly_end_unload)
 197                         assembly_end_unload (current_profiler, assembly);
 198                 break;
 199         default:
 200                 g_assert_not_reached ();
 201         }
 202 }
 203
 204 void
 205 mono_profiler_assembly_loaded (MonoAssembly *assembly, int result)
 206 {
 207         if ((mono_profiler_events & MONO_PROFILE_ASSEMBLY_EVENTS) && assembly_end_load)
 208                 assembly_end_load (current_profiler, assembly, result);
 209 }
 210
 211 void
 212 mono_profiler_module_event  (MonoImage *module, int code)
 213 {
 214         if (!(mono_profiler_events & MONO_PROFILE_MODULE_EVENTS))
 215                 return;
 216
 217         switch (code) {
 218         case MONO_PROFILE_START_LOAD:
 219                 if (module_start_load)
 220                         module_start_load (current_profiler, module);
 221                 break;
 222         case MONO_PROFILE_START_UNLOAD:
 223                 if (module_start_unload)
 224                         module_start_unload (current_profiler, module);
 225                 break;
 226         case MONO_PROFILE_END_UNLOAD:
 227                 if (module_end_unload)
 228                         module_end_unload (current_profiler, module);
 229                 break;
 230         default:
 231                 g_assert_not_reached ();
 232         }
 233 }
 234
 235 void
 236 mono_profiler_module_loaded (MonoImage *module, int result)
 237 {
 238         if ((mono_profiler_events & MONO_PROFILE_MODULE_EVENTS) && module_end_load)
 239                 module_end_load (current_profiler, module, result);
 240 }
 241
 242 void
 243 mono_profiler_class_event  (MonoClass *klass, int code)
 244 {
 245         if (!(mono_profiler_events & MONO_PROFILE_CLASS_EVENTS))
 246                 return;
 247
 248         switch (code) {
 249         case MONO_PROFILE_START_LOAD:
 250                 if (class_start_load)
 251                         class_start_load (current_profiler, klass);
 252                 break;
 253         case MONO_PROFILE_START_UNLOAD:
 254                 if (class_start_unload)
 255                         class_start_unload (current_profiler, klass);
 256                 break;
 257         case MONO_PROFILE_END_UNLOAD:
 258                 if (class_end_unload)
 259                         class_end_unload (current_profiler, klass);
 260                 break;
 261         default:
 262                 g_assert_not_reached ();
 263         }
 264 }
 265
 266 void
 267 mono_profiler_class_loaded (MonoClass *klass, int result)
 268 {
 269         if ((mono_profiler_events & MONO_PROFILE_CLASS_EVENTS) && class_end_load)
 270                 class_end_load (current_profiler, klass, result);
 271 }
 272
 273 void
 274 mono_profiler_appdomain_event  (MonoDomain *domain, int code)
 275 {
 276         if (!(mono_profiler_events & MONO_PROFILE_APPDOMAIN_EVENTS))
 277                 return;
 278
 279         switch (code) {
 280         case MONO_PROFILE_START_LOAD:
 281                 if (domain_start_load)
 282                         domain_start_load (current_profiler, domain);
 283                 break;
 284         case MONO_PROFILE_START_UNLOAD:
 285                 if (domain_start_unload)
 286                         domain_start_unload (current_profiler, domain);
 287                 break;
 288         case MONO_PROFILE_END_UNLOAD:
 289                 if (domain_end_unload)
 290                         domain_end_unload (current_profiler, domain);
 291                 break;
 292         default:
 293                 g_assert_not_reached ();
 294         }
 295 }
 296
 297 void
 298 mono_profiler_appdomain_loaded (MonoDomain *domain, int result)
 299 {
 300         if ((mono_profiler_events & MONO_PROFILE_APPDOMAIN_EVENTS) && domain_end_load)
 301                 domain_end_load (current_profiler, domain, result);
 302 }
 303
 304 void
 305 mono_profiler_shutdown (void)
 306 {
 307         if (current_profiler && shutdown_callback)
 308                 shutdown_callback (current_profiler);
 309 }
 310
 311 /*
 312  * Small profiler extracted from mint: we should move it in a loadable module
 313  * and improve it to do graphs and more accurate timestamping with rdtsc.
 314  */
 315
 316 #define USE_X86TSC 0
 317 #define USE_WIN32COUNTER 0
 318 #if USE_X86TSC
 319
 320 typedef struct {
 321         unsigned int lows, highs, lowe, highe;
 322 } MonoRdtscTimer;
 323
 324 #define rdtsc(low,high) \
 325         __asm__ __volatile__("rdtsc" : "=a" (low), "=d" (high))
 326
 327 static int freq;
 328
 329 static double
 330 rdtsc_elapsed (MonoRdtscTimer *t)
 331 {
 332         unsigned long long diff;
 333         unsigned int highe = t->highe;
 334         if (t->lowe < t->lows)
 335                 highe--;
 336         diff = (((unsigned long long) highe - t->highs) << 32) + (t->lowe - t->lows);
 337         return ((double)diff / freq) / 1000000; /* have to return the result in seconds */
 338 }
 339
 340 static int
 341 have_rdtsc (void) {
 342         char buf[256];
 343         int have_freq = 0;
 344         int have_flag = 0;
 345         float val;
 346         FILE *cpuinfo;
 347
 348         if (!(cpuinfo = fopen ("/proc/cpuinfo", "r")))
 349                 return 0;
 350         while (fgets (buf, sizeof(buf), cpuinfo)) {
 351                 if (sscanf (buf, "cpu MHz : %f", &val) == 1) {
 352                         /*printf ("got mh: %f\n", val);*/
 353                         have_freq = val;
 354                 }
 355                 if (strncmp (buf, "flags", 5) == 0) {
 356                         if (strstr (buf, "tsc")) {
 357                                 have_flag = 1;
 358                                 /*printf ("have tsc\n");*/
 359                         }
 360                 }
 361         }
 362         fclose (cpuinfo);
 363         return have_flag? have_freq: 0;
 364 }
 365
 366 #define MONO_TIMER_STARTUP      \
 367         if (!(freq = have_rdtsc ())) g_error ("Compiled with TSC support, but none found");
 368 #define MONO_TIMER_TYPE  MonoRdtscTimer
 369 #define MONO_TIMER_INIT(t)
 370 #define MONO_TIMER_DESTROY(t)
 371 #define MONO_TIMER_START(t) rdtsc ((t).lows, (t).highs);
 372 #define MONO_TIMER_STOP(t) rdtsc ((t).lowe, (t).highe);
 373 #define MONO_TIMER_ELAPSED(t) rdtsc_elapsed (&(t))
 374
 375 #elif USE_WIN32COUNTER
 376 #include <windows.h>
 377
 378 typedef struct {
 379         LARGE_INTEGER start, stop;
 380 } MonoWin32Timer;
 381
 382 static int freq;
 383
 384 static double
 385 win32_elapsed (MonoWin32Timer *t)
 386 {
 387         LONGLONG diff = t->stop.QuadPart - t->start.QuadPart;
 388         return ((double)diff / freq) / 1000000; /* have to return the result in seconds */
 389 }
 390
 391 static int
 392 have_win32counter (void) {
 393         LARGE_INTEGER f;
 394
 395         if (!QueryPerformanceFrequency (&f))
 396                 return 0;
 397         return f.LowPart;
 398 }
 399
 400 #define MONO_TIMER_STARTUP      \
 401         if (!(freq = have_win32counter ())) g_error ("Compiled with Win32 counter support, but none found");
 402 #define MONO_TIMER_TYPE  MonoWin32Timer
 403 #define MONO_TIMER_INIT(t)
 404 #define MONO_TIMER_DESTROY(t)
 405 #define MONO_TIMER_START(t) QueryPerformanceCounter (&(t).start)
 406 #define MONO_TIMER_STOP(t) QueryPerformanceCounter (&(t).stop)
 407 #define MONO_TIMER_ELAPSED(t) win32_elapsed (&(t))
 408
 409 #else
 410
 411 typedef struct {
 412         GTimeVal start, stop;
 413 } MonoGLibTimer;
 414
 415 static double
 416 timeval_elapsed (MonoGLibTimer *t)
 417 {
 418         if (t->start.tv_usec > t->stop.tv_usec) {
 419                 t->stop.tv_usec += G_USEC_PER_SEC;
 420                 t->stop.tv_sec--;
 421         }
 422         return (t->stop.tv_sec - t->start.tv_sec)
 423                 + ((double)(t->stop.tv_usec - t->start.tv_usec))/ G_USEC_PER_SEC;
 424 }
 425
 426 #define MONO_TIMER_STARTUP
 427 #define MONO_TIMER_TYPE MonoGLibTimer
 428 #define MONO_TIMER_INIT(t)
 429 #define MONO_TIMER_DESTROY(t)
 430 #define MONO_TIMER_START(t) g_get_current_time (&(t).start)
 431 #define MONO_TIMER_STOP(t) g_get_current_time (&(t).stop)
 432 #define MONO_TIMER_ELAPSED(t) timeval_elapsed (&(t))
 433 #endif
 434
 435 struct _MonoProfiler {
 436         GHashTable *methods;
 437         GHashTable *newobjs;
 438         MONO_TIMER_TYPE jit_timer;
 439         double      jit_time;
 440         int         methods_jitted;
 441 };
 442
 443 typedef struct {
 444         union {
 445                 MONO_TIMER_TYPE timer;
 446                 MonoMethod *method;
 447         } u;
 448         guint64 count;
 449         double total;
 450 } MethodProfile;
 451
 452 typedef struct _MethodCallProfile MethodCallProfile;
 453
 454 struct _MethodCallProfile {
 455         MethodCallProfile *next;
 456         MONO_TIMER_TYPE timer;
 457         MonoMethod *method;
 458 };
 459
 460 static gint
 461 compare_profile (MethodProfile *profa, MethodProfile *profb)
 462 {
 463         return (gint)((profb->total - profa->total)*1000);
 464 }
 465
 466 static void
 467 build_profile (MonoMethod *m, MethodProfile *prof, GList **funcs)
 468 {
 469         MONO_TIMER_DESTROY (prof->u.timer);
 470         prof->u.method = m;
 471         *funcs = g_list_insert_sorted (*funcs, prof, (GCompareFunc)compare_profile);
 472 }
 473
 474 static void
 475 output_profile (GList *funcs)
 476 {
 477         GList *tmp;
 478         MethodProfile *p;
 479         char buf [256];
 480         char *sig;
 481         guint64 total_calls = 0;
 482
 483         if (funcs)
 484                 g_print ("Method name\t\t\t\t\tTotal (ms) Calls Per call (ms)\n");
 485         for (tmp = funcs; tmp; tmp = tmp->next) {
 486                 p = tmp->data;
 487                 total_calls += p->count;
 488                 if (!(gint)(p->total*1000))
 489                         continue;
 490                 sig = mono_signature_get_desc (p->u.method->signature, FALSE);
 491                 g_snprintf (buf, sizeof (buf), "%s.%s::%s(%s)",
 492                         p->u.method->klass->name_space, p->u.method->klass->name,
 493                         p->u.method->name, sig);
 494                 g_free (sig);
 495                 printf ("%-52s %7d %7llu %7d\n", buf,
 496                         (gint)(p->total*1000), p->count, (gint)((p->total*1000)/p->count));
 497         }
 498         printf ("Total number of calls: %lld\n", total_calls);
 499 }
 500
 501 typedef struct {
 502         MonoClass *klass;
 503         guint count;
 504 } NewobjProfile;
 505
 506 static gint
 507 compare_newobj_profile (NewobjProfile *profa, NewobjProfile *profb)
 508 {
 509         return (gint)profb->count - (gint)profa->count;
 510 }
 511
 512 static void
 513 build_newobj_profile (MonoClass *class, gpointer count, GList **funcs)
 514 {
 515         NewobjProfile *prof = g_new (NewobjProfile, 1);
 516         prof->klass = class;
 517         prof->count = GPOINTER_TO_UINT (count);
 518         *funcs = g_list_insert_sorted (*funcs, prof, (GCompareFunc)compare_newobj_profile);
 519 }
 520
 521 static void
 522 output_newobj_profile (GList *proflist)
 523 {
 524         GList *tmp;
 525         NewobjProfile *p;
 526         MonoClass *klass;
 527         const char* isarray;
 528         char buf [256];
 529
 530         if (proflist)
 531                 g_print ("\n%-52s %9s\n", "Objects created:", "count");
 532         for (tmp = proflist; tmp; tmp = tmp->next) {
 533                 p = tmp->data;
 534                 klass = p->klass;
 535                 if (klass->rank) {
 536                         isarray = "[]";
 537                         klass = klass->element_class;
 538                 } else {
 539                         isarray = "";
 540                 }
 541                 g_snprintf (buf, sizeof (buf), "%s.%s%s",
 542                         klass->name_space, klass->name, isarray);
 543                 g_print ("%-52s %9d\n", buf, p->count);
 544         }
 545 }
 546
 547 static void
 548 simple_method_enter (MonoProfiler *prof, MonoMethod *method)
 549 {
 550         MethodProfile *profile_info;
 551         if (!(profile_info = g_hash_table_lookup (prof->methods, method))) {
 552                 profile_info = g_new0 (MethodProfile, 1);
 553                 MONO_TIMER_INIT (profile_info->u.timer);
 554                 g_hash_table_insert (prof->methods, method, profile_info);
 555         }
 556         profile_info->count++;
 557         MONO_TIMER_START (profile_info->u.timer);
 558 }
 559
 560 static void
 561 simple_method_leave (MonoProfiler *prof, MonoMethod *method)
 562 {
 563         MethodProfile *profile_info;
 564         if (!(profile_info = g_hash_table_lookup (prof->methods, method)))
 565                 g_assert_not_reached ();
 566
 567         MONO_TIMER_STOP (profile_info->u.timer);
 568         profile_info->total += MONO_TIMER_ELAPSED (profile_info->u.timer);
 569 }
 570
 571 static void
 572 simple_method_jit (MonoProfiler *prof, MonoMethod *method)
 573 {
 574         prof->methods_jitted++;
 575         MONO_TIMER_START (prof->jit_timer);
 576 }
 577
 578 static void
 579 simple_method_end_jit (MonoProfiler *prof, MonoMethod *method, int result)
 580 {
 581         MONO_TIMER_STOP (prof->jit_timer);
 582         prof->jit_time += MONO_TIMER_ELAPSED (prof->jit_timer);
 583 }
 584
 585 static void
 586 simple_shutdown (MonoProfiler *prof)
 587 {
 588         GList *profile = NULL;
 589
 590         printf("Total time spent compiling %d methods (sec): %.4g\n", prof->methods_jitted, prof->jit_time);
 591         g_hash_table_foreach (prof->methods, (GHFunc)build_profile, &profile);
 592         output_profile (profile);
 593         g_list_free (profile);
 594         profile = NULL;
 595
 596         g_hash_table_foreach (prof->newobjs, (GHFunc)build_newobj_profile, &profile);
 597         output_newobj_profile (profile);
 598         g_list_free (profile);
 599 }
 600
 601 void
 602 mono_profiler_install_simple (void)
 603 {
 604         MonoProfiler *prof = g_new0 (MonoProfiler, 1);
 605
 606         MONO_TIMER_STARTUP;
 607
 608         prof->methods = g_hash_table_new (g_direct_hash, g_direct_equal);
 609         prof->newobjs = g_hash_table_new (g_direct_hash, g_direct_equal);
 610         MONO_TIMER_INIT (prof->jit_timer);
 611
 612         mono_profiler_install (prof, simple_shutdown);
 613         /* later do also object creation */
 614         mono_profiler_install_enter_leave (simple_method_enter, simple_method_leave);
 615         mono_profiler_install_jit_compile (simple_method_jit, simple_method_end_jit);
 616         mono_profiler_set_events (MONO_PROFILE_ENTER_LEAVE|MONO_PROFILE_JIT_COMPILATION);
 617 }
 618