X-Git-Url: http://wien.tomnetworks.com/gitweb/?a=blobdiff_plain;f=mono%2Fmetadata%2Fprofiler.c;h=a953bde607e5c7b09efa9bfd27903ed90dc7cec2;hb=aae20b33d0f5235361bf19210c2a6f7d7ce88aa7;hp=f88579c5e07175c81eb53dacb7bf85c9675ff053;hpb=8e9965bda4636a9f13da0970ebc18c1cc2bd3942;p=mono.git diff --git a/mono/metadata/profiler.c b/mono/metadata/profiler.c index f88579c5e07..a953bde607e 100644 --- a/mono/metadata/profiler.c +++ b/mono/metadata/profiler.c @@ -1,7 +1,18 @@ +#include "config.h" #include "mono/metadata/profiler-private.h" #include "mono/metadata/debug-helpers.h" +#include "mono/metadata/mono-debug.h" +#include "mono/metadata/class-internals.h" +#include "mono/metadata/domain-internals.h" +#include "mono/metadata/gc-internal.h" +#include "mono/io-layer/io-layer.h" #include +#include +#include +#ifdef HAVE_BACKTRACE_SYMBOLS +#include +#endif static MonoProfiler * current_profiler = NULL; @@ -28,14 +39,25 @@ static MonoProfileClassFunc class_end_unload; static MonoProfileMethodFunc jit_start; static MonoProfileMethodResult jit_end; static MonoProfileMethodResult man_unman_transition; +static MonoProfileAllocFunc allocation_cb; +static MonoProfileStatFunc statistical_cb; static MonoProfileMethodFunc method_enter; static MonoProfileMethodFunc method_leave; static MonoProfileThreadFunc thread_start; static MonoProfileThreadFunc thread_end; +static MonoProfileCoverageFilterFunc coverage_filter_cb; + static MonoProfileFunc shutdown_callback; +static MonoProfileGCFunc gc_event; +static MonoProfileGCResizeFunc gc_heap_resize; + +#define mono_profiler_coverage_lock() EnterCriticalSection (&profiler_coverage_mutex) +#define mono_profiler_coverage_unlock() LeaveCriticalSection (&profiler_coverage_mutex) +static CRITICAL_SECTION profiler_coverage_mutex; + /* this is directly accessible to other mono libs. */ MonoProfileFlags mono_profiler_events; @@ -46,6 +68,7 @@ mono_profiler_install (MonoProfiler *prof, MonoProfileFunc callback) g_error ("profiler already setup"); current_profiler = prof; shutdown_callback = callback; + InitializeCriticalSection (&profiler_coverage_mutex); } void @@ -61,10 +84,10 @@ mono_profiler_get_events (void) } void -mono_profiler_install_enter_leave (MonoProfileMethodFunc enter, MonoProfileMethodFunc leave) +mono_profiler_install_enter_leave (MonoProfileMethodFunc enter, MonoProfileMethodFunc fleave) { method_enter = enter; - method_leave = leave; + method_leave = fleave; } void @@ -87,6 +110,24 @@ mono_profiler_install_transition (MonoProfileMethodResult callback) man_unman_transition = callback; } +void +mono_profiler_install_allocation (MonoProfileAllocFunc callback) +{ + allocation_cb = callback; +} + +void +mono_profiler_install_statistical (MonoProfileStatFunc callback) +{ + statistical_cb = callback; +} + +void +mono_profiler_install_coverage_filter (MonoProfileCoverageFilterFunc callback) +{ + coverage_filter_cb = callback; +} + void mono_profiler_install_appdomain (MonoProfileAppDomainFunc start_load, MonoProfileAppDomainResult end_load, MonoProfileAppDomainFunc start_unload, MonoProfileAppDomainFunc end_unload) @@ -163,18 +204,32 @@ mono_profiler_code_transition (MonoMethod *method, int result) man_unman_transition (current_profiler, method, result); } +void +mono_profiler_allocation (MonoObject *obj, MonoClass *klass) +{ + if ((mono_profiler_events & MONO_PROFILE_ALLOCATIONS) && allocation_cb) + allocation_cb (current_profiler, obj, klass); +} + void -mono_profiler_thread_start (HANDLE thread) +mono_profiler_stat_hit (guchar *ip, void *context) +{ + if ((mono_profiler_events & MONO_PROFILE_STATISTICAL) && statistical_cb) + statistical_cb (current_profiler, ip, context); +} + +void +mono_profiler_thread_start (gsize tid) { if ((mono_profiler_events & MONO_PROFILE_THREADS) && thread_start) - thread_start (current_profiler, thread); + thread_start (current_profiler, tid); } void -mono_profiler_thread_end (HANDLE thread) +mono_profiler_thread_end (gsize tid) { if ((mono_profiler_events & MONO_PROFILE_THREADS) && thread_end) - thread_end (current_profiler, thread); + thread_end (current_profiler, tid); } void @@ -308,6 +363,111 @@ mono_profiler_shutdown (void) shutdown_callback (current_profiler); } +void +mono_profiler_gc_heap_resize (gint64 new_size) +{ + if ((mono_profiler_events & MONO_PROFILE_GC) && gc_heap_resize) + gc_heap_resize (current_profiler, new_size); +} + +void +mono_profiler_gc_event (MonoGCEvent event, int generation) +{ + if ((mono_profiler_events & MONO_PROFILE_GC) && gc_event) + gc_event (current_profiler, event, generation); +} + +void +mono_profiler_install_gc (MonoProfileGCFunc callback, MonoProfileGCResizeFunc heap_resize_callback) +{ + mono_gc_enable_events (); + gc_event = callback; + gc_heap_resize = heap_resize_callback; +} + +static GHashTable *coverage_hash = NULL; + +MonoProfileCoverageInfo* +mono_profiler_coverage_alloc (MonoMethod *method, int entries) +{ + MonoProfileCoverageInfo *res; + + if (coverage_filter_cb) + if (! (*coverage_filter_cb) (current_profiler, method)) + return NULL; + + mono_profiler_coverage_lock (); + if (!coverage_hash) + coverage_hash = g_hash_table_new (NULL, NULL); + + res = g_malloc0 (sizeof (MonoProfileCoverageInfo) + sizeof (void*) * 2 * entries); + + res->entries = entries; + + g_hash_table_insert (coverage_hash, method, res); + mono_profiler_coverage_unlock (); + + return res; +} + +/* safe only when the method antive code has been unloaded */ +void +mono_profiler_coverage_free (MonoMethod *method) +{ + MonoProfileCoverageInfo* info; + + mono_profiler_coverage_lock (); + if (!coverage_hash) { + mono_profiler_coverage_unlock (); + return; + } + + info = g_hash_table_lookup (coverage_hash, method); + if (info) { + g_free (info); + g_hash_table_remove (coverage_hash, method); + } + mono_profiler_coverage_unlock (); +} + +void +mono_profiler_coverage_get (MonoProfiler *prof, MonoMethod *method, MonoProfileCoverageFunc func) +{ + MonoProfileCoverageInfo* info; + int i, offset; + guint32 line, col; + unsigned char *start, *end, *cil_code; + MonoMethodHeader *header; + MonoProfileCoverageEntry entry; + + mono_profiler_coverage_lock (); + info = g_hash_table_lookup (coverage_hash, method); + mono_profiler_coverage_unlock (); + + if (!info) + return; + + header = mono_method_get_header (method); + start = (unsigned char*)header->code; + end = start + header->code_size; + for (i = 0; i < info->entries; ++i) { + cil_code = info->data [i].cil_code; + if (cil_code && cil_code >= start && cil_code < end) { + offset = cil_code - start; + entry.iloffset = offset; + entry.method = method; + entry.counter = info->data [i].count; + /* the debug interface doesn't support column info, sigh */ + col = line = 1; + entry.filename = mono_debug_source_location_from_il_offset (method, offset, &line); + entry.line = line; + entry.col = col; + func (prof, &entry); + } + } +} + +#ifndef DISABLE_PROFILER /* * Small profiler extracted from mint: we should move it in a loadable module * and improve it to do graphs and more accurate timestamping with rdtsc. @@ -432,21 +592,34 @@ timeval_elapsed (MonoGLibTimer *t) #define MONO_TIMER_ELAPSED(t) timeval_elapsed (&(t)) #endif +typedef struct _AllocInfo AllocInfo; +typedef struct _CallerInfo CallerInfo; +typedef struct _LastCallerInfo LastCallerInfo; + struct _MonoProfiler { GHashTable *methods; - GHashTable *newobjs; + MonoMemPool *mempool; + /* info about JIT time */ MONO_TIMER_TYPE jit_timer; double jit_time; + double max_jit_time; + MonoMethod *max_jit_method; int methods_jitted; + + GSList *per_thread; + + /* chain of callers for the current thread */ + LastCallerInfo *callers; + /* LastCallerInfo nodes for faster allocation */ + LastCallerInfo *cstorage; }; typedef struct { - union { - MONO_TIMER_TYPE timer; - MonoMethod *method; - } u; + MonoMethod *method; guint64 count; double total; + AllocInfo *alloc_info; + CallerInfo *caller_info; } MethodProfile; typedef struct _MethodCallProfile MethodCallProfile; @@ -457,6 +630,63 @@ struct _MethodCallProfile { MonoMethod *method; }; +struct _AllocInfo { + AllocInfo *next; + MonoClass *klass; + guint count; + guint mem; +}; + +struct _CallerInfo { + CallerInfo *next; + MonoMethod *caller; + guint count; +}; + +struct _LastCallerInfo { + LastCallerInfo *next; + MonoMethod *method; + MONO_TIMER_TYPE timer; +}; + +static MonoProfiler* +create_profiler (void) +{ + MonoProfiler *prof = g_new0 (MonoProfiler, 1); + + prof->methods = g_hash_table_new (NULL, NULL); + MONO_TIMER_INIT (prof->jit_timer); + prof->mempool = mono_mempool_new (); + return prof; +} +#if 1 + +#ifdef HAVE_KW_THREAD + static __thread MonoProfiler * tls_profiler; +# define GET_PROFILER() tls_profiler +# define SET_PROFILER(x) tls_profiler = (x) +# define ALLOC_PROFILER() /* nop */ +#else + static guint32 profiler_thread_id = -1; +# define GET_PROFILER() ((MonoProfiler *)TlsGetValue (profiler_thread_id)) +# define SET_PROFILER(x) TlsSetValue (profiler_thread_id, x); +# define ALLOC_PROFILER() profiler_thread_id = TlsAlloc () +#endif + +#define GET_THREAD_PROF(prof) do { \ + MonoProfiler *_tprofiler = GET_PROFILER (); \ + if (!_tprofiler) { \ + _tprofiler = create_profiler (); \ + prof->per_thread = g_slist_prepend (prof->per_thread, _tprofiler); \ + SET_PROFILER (_tprofiler); \ + } \ + prof = _tprofiler; \ + } while (0) +#else +/* thread unsafe but faster variant */ +#define GET_THREAD_PROF(prof) +#endif + static gint compare_profile (MethodProfile *profa, MethodProfile *profb) { @@ -466,40 +696,55 @@ compare_profile (MethodProfile *profa, MethodProfile *profb) static void build_profile (MonoMethod *m, MethodProfile *prof, GList **funcs) { - MONO_TIMER_DESTROY (prof->u.timer); - prof->u.method = m; + prof->method = m; *funcs = g_list_insert_sorted (*funcs, prof, (GCompareFunc)compare_profile); } +static char* +method_get_name (MonoMethod* method) +{ + char *sig, *res; + + sig = mono_signature_get_desc (mono_method_signature (method), FALSE); + res = g_strdup_printf ("%s.%s::%s(%s)", method->klass->name_space, method->klass->name, + method->name, sig); + g_free (sig); + return res; +} + +static void output_callers (MethodProfile *p); + static void output_profile (GList *funcs) { GList *tmp; MethodProfile *p; - char buf [256]; - char *sig; + char *m; guint64 total_calls = 0; if (funcs) - g_print ("Method name\t\t\t\t\tTotal (ms) Calls Per call (ms)\n"); + g_print ("Time(ms) Count P/call(ms) Method name\n"); for (tmp = funcs; tmp; tmp = tmp->next) { p = tmp->data; total_calls += p->count; if (!(gint)(p->total*1000)) continue; - sig = mono_signature_get_desc (p->u.method->signature, FALSE); - g_snprintf (buf, sizeof (buf), "%s.%s::%s(%s)", - p->u.method->klass->name_space, p->u.method->klass->name, - p->u.method->name, sig); - g_free (sig); - printf ("%-52s %7d %7llu %7d\n", buf, - (gint)(p->total*1000), p->count, (gint)((p->total*1000)/p->count)); + m = method_get_name (p->method); + printf ("########################\n"); + printf ("% 8.3f ", (double) (p->total * 1000)); + printf ("%7llu ", (unsigned long long)p->count); + printf ("% 8.3f ", (double) (p->total * 1000)/(double)p->count); + printf (" %s\n", m); + + g_free (m); + /* callers */ + output_callers (p); } - printf ("Total number of calls: %lld\n", total_calls); + printf ("Total number of calls: %lld\n", (long long)total_calls); } typedef struct { - MonoClass *klass; + MethodProfile *mp; guint count; } NewobjProfile; @@ -510,67 +755,296 @@ compare_newobj_profile (NewobjProfile *profa, NewobjProfile *profb) } static void -build_newobj_profile (MonoClass *class, gpointer count, GList **funcs) +build_newobj_profile (MonoClass *class, MethodProfile *mprof, GList **funcs) { NewobjProfile *prof = g_new (NewobjProfile, 1); - prof->klass = class; - prof->count = GPOINTER_TO_UINT (count); + AllocInfo *tmp; + guint count = 0; + + prof->mp = mprof; + /* we use the total amount of memory to sort */ + for (tmp = mprof->alloc_info; tmp; tmp = tmp->next) + count += tmp->mem; + prof->count = count; *funcs = g_list_insert_sorted (*funcs, prof, (GCompareFunc)compare_newobj_profile); } +static int +compare_caller (CallerInfo *a, CallerInfo *b) +{ + return b->count - a->count; +} + +static int +compare_alloc (AllocInfo *a, AllocInfo *b) +{ + return b->mem - a->mem; +} + +static GSList* +sort_alloc_list (AllocInfo *ai) +{ + GSList *l = NULL; + AllocInfo *tmp; + for (tmp = ai; tmp; tmp = tmp->next) { + l = g_slist_insert_sorted (l, tmp, (GCompareFunc)compare_alloc); + } + return l; +} + +static GSList* +sort_caller_list (CallerInfo *ai) +{ + GSList *l = NULL; + CallerInfo *tmp; + for (tmp = ai; tmp; tmp = tmp->next) { + l = g_slist_insert_sorted (l, tmp, (GCompareFunc)compare_caller); + } + return l; +} + +static void +output_callers (MethodProfile *p) { + guint total_callers, percent; + GSList *sorted, *tmps; + CallerInfo *cinfo; + char *m; + + g_print (" Callers (with count) that contribute at least for 1%%:\n"); + total_callers = 0; + for (cinfo = p->caller_info; cinfo; cinfo = cinfo->next) { + total_callers += cinfo->count; + } + sorted = sort_caller_list (p->caller_info); + for (tmps = sorted; tmps; tmps = tmps->next) { + cinfo = tmps->data; + percent = (cinfo->count * 100)/total_callers; + if (percent < 1) + continue; + m = method_get_name (cinfo->caller); + g_print (" %8d % 3d %% %s\n", cinfo->count, percent, m); + g_free (m); + } +} + static void output_newobj_profile (GList *proflist) { GList *tmp; NewobjProfile *p; + MethodProfile *mp; + AllocInfo *ainfo; MonoClass *klass; const char* isarray; char buf [256]; + char *m; + guint total = 0; + GSList *sorted, *tmps; + + g_print ("\nAllocation profiler\n"); if (proflist) - g_print ("\n%-52s %9s\n", "Objects created:", "count"); + g_print ("%-9s %s\n", "Total mem", "Method"); for (tmp = proflist; tmp; tmp = tmp->next) { p = tmp->data; - klass = p->klass; - if (klass->rank) { - isarray = "[]"; - klass = klass->element_class; - } else { - isarray = ""; + total += p->count; + if (p->count < 50000) + continue; + mp = p->mp; + m = method_get_name (mp->method); + g_print ("########################\n%8d KB %s\n", p->count / 1024, m); + g_free (m); + sorted = sort_alloc_list (mp->alloc_info); + for (tmps = sorted; tmps; tmps = tmps->next) { + ainfo = tmps->data; + if (ainfo->mem < 50000) + continue; + klass = ainfo->klass; + if (klass->rank) { + isarray = "[]"; + klass = klass->element_class; + } else { + isarray = ""; + } + g_snprintf (buf, sizeof (buf), "%s.%s%s", + klass->name_space, klass->name, isarray); + g_print (" %8d KB %8d %-48s\n", ainfo->mem / 1024, ainfo->count, buf); + } + /* callers */ + output_callers (mp); + } + g_print ("Total memory allocated: %d KB\n", total / 1024); +} + +static void +merge_methods (MonoMethod *method, MethodProfile *profile, MonoProfiler *prof) +{ + MethodProfile *mprof; + AllocInfo *talloc_info, *alloc_info; + CallerInfo *tcaller_info, *caller_info; + + mprof = g_hash_table_lookup (prof->methods, method); + if (!mprof) { + /* the master thread didn't see this method, just transfer the info as is */ + g_hash_table_insert (prof->methods, method, profile); + return; + } + /* merge the info from profile into mprof */ + mprof->count += profile->count; + mprof->total += profile->total; + /* merge alloc info */ + for (talloc_info = profile->alloc_info; talloc_info; talloc_info = talloc_info->next) { + for (alloc_info = mprof->alloc_info; alloc_info; alloc_info = alloc_info->next) { + if (alloc_info->klass == talloc_info->klass) { + /* mprof already has a record for the klass, merge */ + alloc_info->count += talloc_info->count; + alloc_info->mem += talloc_info->mem; + break; + } + } + if (!alloc_info) { + /* mprof didn't have the info, just copy it over */ + alloc_info = mono_mempool_alloc0 (prof->mempool, sizeof (AllocInfo)); + *alloc_info = *talloc_info; + alloc_info->next = mprof->alloc_info; + mprof->alloc_info = alloc_info->next; + } + } + /* merge callers info */ + for (tcaller_info = profile->caller_info; tcaller_info; tcaller_info = tcaller_info->next) { + for (caller_info = mprof->caller_info; caller_info; caller_info = caller_info->next) { + if (caller_info->caller == tcaller_info->caller) { + /* mprof already has a record for the caller method, merge */ + caller_info->count += tcaller_info->count; + break; + } + } + if (!caller_info) { + /* mprof didn't have the info, just copy it over */ + caller_info = mono_mempool_alloc0 (prof->mempool, sizeof (CallerInfo)); + *caller_info = *tcaller_info; + caller_info->next = mprof->caller_info; + mprof->caller_info = caller_info; } - g_snprintf (buf, sizeof (buf), "%s.%s%s", - klass->name_space, klass->name, isarray); - g_print ("%-52s %9d\n", buf, p->count); } } +static void +merge_thread_data (MonoProfiler *master, MonoProfiler *tprof) +{ + master->jit_time += tprof->jit_time; + master->methods_jitted += tprof->methods_jitted; + if (master->max_jit_time < tprof->max_jit_time) { + master->max_jit_time = tprof->max_jit_time; + master->max_jit_method = tprof->max_jit_method; + } + + g_hash_table_foreach (tprof->methods, (GHFunc)merge_methods, master); +} + static void simple_method_enter (MonoProfiler *prof, MonoMethod *method) { MethodProfile *profile_info; + LastCallerInfo *callinfo; + GET_THREAD_PROF (prof); + /*g_print ("enter %p %s::%s in %d (%p)\n", method, method->klass->name, method->name, GetCurrentThreadId (), prof);*/ if (!(profile_info = g_hash_table_lookup (prof->methods, method))) { - profile_info = g_new0 (MethodProfile, 1); + profile_info = mono_mempool_alloc0 (prof->mempool, sizeof (MethodProfile)); MONO_TIMER_INIT (profile_info->u.timer); g_hash_table_insert (prof->methods, method, profile_info); } profile_info->count++; - MONO_TIMER_START (profile_info->u.timer); + if (prof->callers) { + CallerInfo *cinfo; + MonoMethod *caller = prof->callers->method; + for (cinfo = profile_info->caller_info; cinfo; cinfo = cinfo->next) { + if (cinfo->caller == caller) + break; + } + if (!cinfo) { + cinfo = mono_mempool_alloc0 (prof->mempool, sizeof (CallerInfo)); + cinfo->caller = caller; + cinfo->next = profile_info->caller_info; + profile_info->caller_info = cinfo; + } + cinfo->count++; + } + if (!(callinfo = prof->cstorage)) { + callinfo = mono_mempool_alloc (prof->mempool, sizeof (LastCallerInfo)); + MONO_TIMER_INIT (callinfo->timer); + } else { + prof->cstorage = prof->cstorage->next; + } + callinfo->method = method; + callinfo->next = prof->callers; + prof->callers = callinfo; + MONO_TIMER_START (callinfo->timer); } static void simple_method_leave (MonoProfiler *prof, MonoMethod *method) { MethodProfile *profile_info; - if (!(profile_info = g_hash_table_lookup (prof->methods, method))) - g_assert_not_reached (); + LastCallerInfo *callinfo, *newcallinfo = NULL; + + GET_THREAD_PROF (prof); + /*g_print ("leave %p %s::%s in %d (%p)\n", method, method->klass->name, method->name, GetCurrentThreadId (), prof);*/ + callinfo = prof->callers; + /* should really not happen, but we don't catch exceptions events, yet ... */ + while (callinfo) { + MONO_TIMER_STOP (callinfo->timer); + profile_info = g_hash_table_lookup (prof->methods, callinfo->method); + if (profile_info) + profile_info->total += MONO_TIMER_ELAPSED (callinfo->timer); + newcallinfo = callinfo->next; + callinfo->next = prof->cstorage; + prof->cstorage = callinfo; + if (callinfo->method == method) + break; + callinfo = newcallinfo; + } + prof->callers = newcallinfo; +} + +static void +simple_allocation (MonoProfiler *prof, MonoObject *obj, MonoClass *klass) +{ + MethodProfile *profile_info; + AllocInfo *tmp; + + GET_THREAD_PROF (prof); + if (prof->callers) { + MonoMethod *caller = prof->callers->method; - MONO_TIMER_STOP (profile_info->u.timer); - profile_info->total += MONO_TIMER_ELAPSED (profile_info->u.timer); + /* Otherwise all allocations are attributed to icall_wrapper_mono_object_new */ + if (caller->wrapper_type == MONO_WRAPPER_MANAGED_TO_NATIVE) + caller = prof->callers->next->method; + + if (!(profile_info = g_hash_table_lookup (prof->methods, caller))) + g_assert_not_reached (); + } else { + return; /* fine for now */ + } + + for (tmp = profile_info->alloc_info; tmp; tmp = tmp->next) { + if (tmp->klass == klass) + break; + } + if (!tmp) { + tmp = mono_mempool_alloc0 (prof->mempool, sizeof (AllocInfo)); + tmp->klass = klass; + tmp->next = profile_info->alloc_info; + profile_info->alloc_info = tmp; + } + tmp->count++; + tmp->mem += mono_object_get_size (obj); } static void simple_method_jit (MonoProfiler *prof, MonoMethod *method) { + GET_THREAD_PROF (prof); prof->methods_jitted++; MONO_TIMER_START (prof->jit_timer); } @@ -578,41 +1052,315 @@ simple_method_jit (MonoProfiler *prof, MonoMethod *method) static void simple_method_end_jit (MonoProfiler *prof, MonoMethod *method, int result) { + double jtime; + GET_THREAD_PROF (prof); MONO_TIMER_STOP (prof->jit_timer); - prof->jit_time += MONO_TIMER_ELAPSED (prof->jit_timer); + jtime = MONO_TIMER_ELAPSED (prof->jit_timer); + prof->jit_time += jtime; + if (jtime > prof->max_jit_time) { + prof->max_jit_time = jtime; + prof->max_jit_method = method; + } +} + +/* about 10 minutes of samples */ +#define MAX_PROF_SAMPLES (1000*60*10) +static int prof_counts = 0; +static int prof_ucounts = 0; +static gpointer* prof_addresses = NULL; +static GHashTable *prof_table = NULL; + +static void +simple_stat_hit (MonoProfiler *prof, guchar *ip, void *context) +{ + int pos; + + if (prof_counts >= MAX_PROF_SAMPLES) + return; + pos = InterlockedIncrement (&prof_counts); + prof_addresses [pos - 1] = ip; +} + +static int +compare_methods_prof (gconstpointer a, gconstpointer b) +{ + int ca = GPOINTER_TO_UINT (g_hash_table_lookup (prof_table, a)); + int cb = GPOINTER_TO_UINT (g_hash_table_lookup (prof_table, b)); + return cb-ca; +} + +static void +prof_foreach (char *method, gpointer c, gpointer data) +{ + GList **list = data; + *list = g_list_insert_sorted (*list, method, compare_methods_prof); +} + +typedef struct Addr2LineData Addr2LineData; + +struct Addr2LineData { + Addr2LineData *next; + FILE *pipein; + FILE *pipeout; + char *binary; + int child_pid; +}; + +static Addr2LineData *addr2line_pipes = NULL; + +static char* +try_addr2line (const char* binary, gpointer ip) +{ + char buf [1024]; + char *res; + Addr2LineData *addr2line; + + for (addr2line = addr2line_pipes; addr2line; addr2line = addr2line->next) { + if (strcmp (binary, addr2line->binary) == 0) + break; + } + if (!addr2line) { + const char *addr_argv[] = {"addr2line", "-f", "-e", binary, NULL}; + int child_pid; + int ch_in, ch_out; + if (!g_spawn_async_with_pipes (NULL, (char**)addr_argv, NULL, G_SPAWN_SEARCH_PATH, NULL, NULL, + &child_pid, &ch_in, &ch_out, NULL, NULL)) { + return g_strdup (binary); + } + addr2line = g_new0 (Addr2LineData, 1); + addr2line->child_pid = child_pid; + addr2line->binary = g_strdup (binary); + addr2line->pipein = fdopen (ch_in, "w"); + addr2line->pipeout = fdopen (ch_out, "r"); + addr2line->next = addr2line_pipes; + addr2line_pipes = addr2line; + } + fprintf (addr2line->pipein, "%p\n", ip); + fflush (addr2line->pipein); + /* we first get the func name and then file:lineno in a second line */ + if (fgets (buf, sizeof (buf), addr2line->pipeout) && buf [0] != '?') { + char *end = strchr (buf, '\n'); + if (end) + *end = 0; + res = g_strdup_printf ("%s(%s", binary, buf); + /* discard the filename/line info */ + fgets (buf, sizeof (buf), addr2line->pipeout); + } else { + res = g_strdup (binary); + } + return res; +} + +static void +stat_prof_report (void) +{ + MonoJitInfo *ji; + int count = prof_counts; + int i, c; + char *mn; + gpointer ip; + GList *tmp, *sorted = NULL; + int pcount = ++ prof_counts; + + prof_counts = MAX_PROF_SAMPLES; + for (i = 0; i < count; ++i) { + ip = prof_addresses [i]; + ji = mono_jit_info_table_find (mono_domain_get (), ip); + if (ji) { + mn = mono_method_full_name (ji->method, TRUE); + } else { +#ifdef HAVE_BACKTRACE_SYMBOLS + char **names; + char *send; + int no_func; + prof_ucounts++; + names = backtrace_symbols (&ip, 1); + send = strchr (names [0], '+'); + if (send) { + *send = 0; + no_func = 0; + } else { + no_func = 1; + } + send = strchr (names [0], '['); + if (send) + *send = 0; + if (no_func && names [0][0]) { + char *endp = strchr (names [0], 0); + while (--endp >= names [0] && g_ascii_isspace (*endp)) + *endp = 0; + mn = try_addr2line (names [0], ip); + } else { + mn = g_strdup (names [0]); + } + free (names); +#else + prof_ucounts++; + mn = g_strdup_printf ("unmanaged [%p]", ip); +#endif + } + c = GPOINTER_TO_UINT (g_hash_table_lookup (prof_table, mn)); + c++; + g_hash_table_insert (prof_table, mn, GUINT_TO_POINTER (c)); + if (c > 1) + g_free (mn); + } + g_print ("prof counts: total/unmanaged: %d/%d\n", pcount, prof_ucounts); + g_hash_table_foreach (prof_table, (GHFunc)prof_foreach, &sorted); + for (tmp = sorted; tmp; tmp = tmp->next) { + double perc; + c = GPOINTER_TO_UINT (g_hash_table_lookup (prof_table, tmp->data)); + perc = c*100.0/count; + g_print ("%7d\t%5.2f %% %s\n", c, perc, (char*)tmp->data); + } + g_list_free (sorted); +} + +static void +simple_appdomain_unload (MonoProfiler *prof, MonoDomain *domain) +{ + /* FIXME: we should actually record partial data for each domain, + * since the ip->ji->method mappings are going away at domain unload time. + */ + if (domain == mono_get_root_domain ()) + stat_prof_report (); } static void simple_shutdown (MonoProfiler *prof) { GList *profile = NULL; + MonoProfiler *tprof; + GSList *tmp; + char *str; + + for (tmp = prof->per_thread; tmp; tmp = tmp->next) { + tprof = tmp->data; + merge_thread_data (prof, tprof); + } printf("Total time spent compiling %d methods (sec): %.4g\n", prof->methods_jitted, prof->jit_time); + if (prof->max_jit_method) { + str = method_get_name (prof->max_jit_method); + printf("Slowest method to compile (sec): %.4g: %s\n", prof->max_jit_time, str); + g_free (str); + } g_hash_table_foreach (prof->methods, (GHFunc)build_profile, &profile); output_profile (profile); g_list_free (profile); profile = NULL; - g_hash_table_foreach (prof->newobjs, (GHFunc)build_newobj_profile, &profile); + g_hash_table_foreach (prof->methods, (GHFunc)build_newobj_profile, &profile); output_newobj_profile (profile); g_list_free (profile); + + g_free (prof_addresses); + prof_addresses = NULL; + g_hash_table_destroy (prof_table); } -void -mono_profiler_install_simple (void) +static void +mono_profiler_install_simple (const char *desc) { - MonoProfiler *prof = g_new0 (MonoProfiler, 1); + MonoProfiler *prof; + gchar **args, **ptr; + MonoProfileFlags flags = 0; MONO_TIMER_STARTUP; - prof->methods = g_hash_table_new (g_direct_hash, g_direct_equal); - prof->newobjs = g_hash_table_new (g_direct_hash, g_direct_equal); - MONO_TIMER_INIT (prof->jit_timer); + if (!desc) + desc = "alloc,time,jit"; + + if (desc) { + /* Parse options */ + if (strstr (desc, ":")) + desc = strstr (desc, ":") + 1; + else + desc = "alloc,time,jit"; + args = g_strsplit (desc, ",", -1); + + for (ptr = args; ptr && *ptr; ptr++) { + const char *arg = *ptr; + + if (!strcmp (arg, "time")) + flags |= MONO_PROFILE_ENTER_LEAVE; + else if (!strcmp (arg, "alloc")) + flags |= MONO_PROFILE_ALLOCATIONS; + else if (!strcmp (arg, "stat")) + flags |= MONO_PROFILE_STATISTICAL | MONO_PROFILE_APPDOMAIN_EVENTS; + else if (!strcmp (arg, "jit")) + flags |= MONO_PROFILE_JIT_COMPILATION; + else { + fprintf (stderr, "profiler : Unknown argument '%s'.\n", arg); + return; + } + } + } + + prof = create_profiler (); + ALLOC_PROFILER (); + SET_PROFILER (prof); + + /* statistical profiler data */ + prof_addresses = g_new0 (gpointer, MAX_PROF_SAMPLES); + prof_table = g_hash_table_new (g_str_hash, g_str_equal); mono_profiler_install (prof, simple_shutdown); - /* later do also object creation */ mono_profiler_install_enter_leave (simple_method_enter, simple_method_leave); mono_profiler_install_jit_compile (simple_method_jit, simple_method_end_jit); - mono_profiler_set_events (MONO_PROFILE_ENTER_LEAVE|MONO_PROFILE_JIT_COMPILATION); + mono_profiler_install_allocation (simple_allocation); + mono_profiler_install_appdomain (NULL, NULL, simple_appdomain_unload, NULL); + mono_profiler_install_statistical (simple_stat_hit); + mono_profiler_set_events (flags); +} + +#endif /* DISABLE_PROFILER */ + +typedef void (*ProfilerInitializer) (const char*); +#define INITIALIZER_NAME "mono_profiler_startup" + +void +mono_profiler_load (const char *desc) +{ +#ifndef DISABLE_PROFILER + if (!desc || (strcmp ("default", desc) == 0) || (strncmp (desc, "default:", 8) == 0)) { + mono_profiler_install_simple (desc); + return; + } +#else + if (!desc) { + desc = "default"; + } +#endif + { + GModule *pmodule; + const char* col = strchr (desc, ':'); + char* libname; + char* path; + char *mname; + if (col != NULL) { + mname = g_memdup (desc, col - desc); + mname [col - desc] = 0; + } else { + mname = g_strdup (desc); + } + libname = g_strdup_printf ("mono-profiler-%s", mname); + path = g_module_build_path (NULL, libname); + pmodule = g_module_open (path, G_MODULE_BIND_LAZY); + if (pmodule) { + ProfilerInitializer func; + if (!g_module_symbol (pmodule, INITIALIZER_NAME, (gpointer *)&func)) { + g_warning ("Cannot find initializer function %s in profiler module: %s", INITIALIZER_NAME, libname); + } else { + func (desc); + } + } else { + g_warning ("Error loading profiler module '%s': %s", libname, g_module_error ()); + } + + g_free (libname); + g_free (mname); + g_free (path); + } }