(wait_for_tids_or_state_change): We were using the wrong variable
[mono.git] / mono / metadata / profiler.c
index 3743623259ae94f0d18ce8966fc02cec0d19a47f..99d9020465db414eb3f92a1cf949286404a79991 100644 (file)
@@ -1,10 +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 <string.h>
+#include <sys/time.h>
 #include <gmodule.h>
+#ifdef HAVE_BACKTRACE_SYMBOLS
+#include <execinfo.h>
+#endif
 
 static MonoProfiler * current_profiler = NULL;
 
@@ -32,6 +40,7 @@ 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;
 
@@ -42,6 +51,9 @@ static MonoProfileCoverageFilterFunc coverage_filter_cb;
 
 static MonoProfileFunc shutdown_callback;
 
+static MonoProfileGCFunc        gc_event;
+static MonoProfileGCResizeFunc  gc_heap_resize;
+
 static CRITICAL_SECTION profiler_coverage_mutex;
 
 /* this is directly accessible to other mono libs. */
@@ -102,6 +114,12 @@ 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)
 {
@@ -191,6 +209,13 @@ mono_profiler_allocation (MonoObject *obj, MonoClass *klass)
                allocation_cb (current_profiler, obj, klass);
 }
 
+void
+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 (guint32 tid)
 {
@@ -336,6 +361,28 @@ 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* 
@@ -398,7 +445,7 @@ mono_profiler_coverage_get (MonoProfiler *prof, MonoMethod *method, MonoProfileC
        if (!info)
                return;
 
-       header = ((MonoMethodNormal *)method)->header;
+       header = mono_method_get_header (method);
        start = (unsigned char*)header->code;
        end = start + header->code_size;
        for (i = 0; i < info->entries; ++i) {
@@ -418,6 +465,7 @@ mono_profiler_coverage_get (MonoProfiler *prof, MonoMethod *method, MonoProfileC
        }
 }
 
+#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.
@@ -556,8 +604,6 @@ struct _MonoProfiler {
        MonoMethod *max_jit_method;
        int         methods_jitted;
        
-       /* tls_id is the id for the TLS slot where MonoProfiler is stored */
-       int         tls_id;
        GSList     *per_thread;
        
        /* chain of callers for the current thread */
@@ -612,14 +658,27 @@ create_profiler (void)
        return prof;
 }
 #if 1
-#define GET_THREAD_PROF(prof) do {\
-               MonoProfiler *_tprofiler = TlsGetValue ((prof)->tls_id);        \
-               if (!_tprofiler) {      \
-                       _tprofiler = create_profiler ();        \
-                       prof->per_thread = g_slist_prepend (prof->per_thread, _tprofiler);      \
-                       TlsSetValue ((prof)->tls_id, _tprofiler);       \
-               }       \
-               prof = _tprofiler;      \
+
+#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 */
@@ -644,7 +703,7 @@ method_get_name (MonoMethod* method)
 {
        char *sig, *res;
        
-       sig = mono_signature_get_desc (method->signature, FALSE);
+       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);
@@ -671,7 +730,7 @@ output_profile (GList *funcs)
                m = method_get_name (p->method);
                printf ("########################\n");
                printf ("% 8.3f ", (double) (p->total * 1000));
-               printf ("%7llu ", p->count);
+               printf ("%7llu ", (unsigned long long)p->count);
                printf ("% 8.3f ", (double) (p->total * 1000)/(double)p->count);
                printf ("  %s\n", m);
 
@@ -679,7 +738,7 @@ output_profile (GList *funcs)
                /* 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 {
@@ -954,7 +1013,13 @@ simple_allocation (MonoProfiler *prof, MonoObject *obj, MonoClass *klass)
 
        GET_THREAD_PROF (prof);
        if (prof->callers) {
-               if (!(profile_info = g_hash_table_lookup (prof->methods, prof->callers->method)))
+               MonoMethod *caller = prof->callers->method;
+
+               /* 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 */
@@ -971,13 +1036,7 @@ simple_allocation (MonoProfiler *prof, MonoObject *obj, MonoClass *klass)
                profile_info->alloc_info = tmp;
        }
        tmp->count++;
-       if (klass == mono_defaults.string_class) {
-               tmp->mem += sizeof (MonoString) + 2 * mono_string_length ((MonoString*)obj) + 2;
-       } else if (klass->parent == mono_defaults.array_class) {
-               tmp->mem += sizeof (MonoArray) + mono_array_element_size (klass) * mono_array_length ((MonoArray*)obj);
-       } else {
-               tmp->mem += mono_class_instance_size (klass);
-       }
+       tmp->mem += mono_object_get_size (obj);
 }
 
 static void
@@ -1002,6 +1061,169 @@ simple_method_end_jit (MonoProfiler *prof, MonoMethod *method, int result)
        }
 }
 
+/* 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)
 {
@@ -1029,6 +1251,10 @@ simple_shutdown (MonoProfiler *prof)
        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);
 }
 
 static void
@@ -1036,54 +1262,75 @@ mono_profiler_install_simple (const char *desc)
 {
        MonoProfiler *prof;
        gchar **args, **ptr;
-       MonoProfileFlags flags = MONO_PROFILE_ENTER_LEAVE|MONO_PROFILE_JIT_COMPILATION|MONO_PROFILE_ALLOCATIONS;
+       MonoProfileFlags flags = 0;
 
        MONO_TIMER_STARTUP;
 
+       if (!desc)
+               desc = "alloc,time,jit";
+
        if (desc) {
                /* Parse options */
                if (strstr (desc, ":"))
                        desc = strstr (desc, ":") + 1;
                else
-                       desc = NULL;
-               args = g_strsplit (desc ? desc : "", ",", -1);
+                       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 {
-                                  fprintf (stderr, "profiler : Unknown argument '%s'.\n", arg);
-                                  return;
-                          }
+                       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 ();
-       prof->tls_id = TlsAlloc ();
-       TlsSetValue (prof->tls_id, prof);
+       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_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);
-       } else {
+               return;
+       }
+#else
+       if (!desc) {
+               desc = "default";
+       }
+#endif
+       {
                GModule *pmodule;
                const char* col = strchr (desc, ':');
                char* libname;