2007-03-09 Jonathan Chambers <joncham@gmail.com>
[mono.git] / mono / metadata / profiler.c
index b66ab7e865bc9ec9f71685b1de43d3e311e21796..36ec3a382a99560c7b377530c13e6bf520655d70 100644 (file)
@@ -1,15 +1,27 @@
+/*
+ * profiler.c: Profiler interface for Mono
+ *
+ * Author:
+ *   Paolo Molaro (lupus@ximian.com)
+ *
+ * (C) 2001-2003 Ximian, Inc.
+ * (C) 2003-2006 Novell, Inc.
+ */
 
 #include "config.h"
 #include "mono/metadata/profiler-private.h"
 #include "mono/metadata/debug-helpers.h"
 #include "mono/metadata/mono-debug.h"
+#include "mono/metadata/debug-mono-symfile.h"
+#include "mono/metadata/metadata-internals.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 "mono/utils/mono-dl.h"
 #include <string.h>
+#include <unistd.h>
 #include <sys/time.h>
-#include <gmodule.h>
 #ifdef HAVE_BACKTRACE_SYMBOLS
 #include <execinfo.h>
 #endif
@@ -62,6 +74,17 @@ static CRITICAL_SECTION profiler_coverage_mutex;
 /* this is directly accessible to other mono libs. */
 MonoProfileFlags mono_profiler_events;
 
+/**
+ * mono_profiler_install:
+ * @prof: a MonoProfiler structure pointer, or a pointer to a derived structure.
+ * @callback: the function to invoke at shutdown
+ *
+ * Use mono_profiler_install to activate profiling in the Mono runtime.
+ * Typically developers of new profilers will create a new structure whose
+ * first field is a MonoProfiler and put any extra information that they need
+ * to access from the various profiling callbacks there.
+ *
+ */
 void
 mono_profiler_install (MonoProfiler *prof, MonoProfileFunc callback)
 {
@@ -72,18 +95,46 @@ mono_profiler_install (MonoProfiler *prof, MonoProfileFunc callback)
        InitializeCriticalSection (&profiler_coverage_mutex);
 }
 
+/**
+ * mono_profiler_set_events:
+ * @events: an ORed set of values made up of MONO_PROFILER_ flags
+ *
+ * The events descriped in the @events argument is a set of flags
+ * that represent which profiling events must be triggered.  For
+ * example if you have registered a set of methods for tracking
+ * JIT compilation start and end with mono_profiler_install_jit_compile,
+ * you will want to pass the MONO_PROFILE_JIT_COMPILATION flag to
+ * this routine.
+ *
+ * You can call mono_profile_set_events more than once and you can
+ * do this at runtime to modify which methods are invoked.
+ */
 void
 mono_profiler_set_events (MonoProfileFlags events)
 {
        mono_profiler_events = events;
 }
 
+/**
+ * mono_profiler_get_events:
+ *
+ * Returns a list of active events that will be intercepted. 
+ */
 MonoProfileFlags
 mono_profiler_get_events (void)
 {
        return mono_profiler_events;
 }
 
+/**
+ * mono_profiler_install_enter_leave:
+ * @enter: the routine to be called on each method entry
+ * @fleave: the routine to be called each time a method returns
+ *
+ * Use this routine to install routines that will be called everytime
+ * a method enters and leaves.   The routines will receive as an argument
+ * the MonoMethod representing the method that is entering or leaving.
+ */
 void
 mono_profiler_install_enter_leave (MonoProfileMethodFunc enter, MonoProfileMethodFunc fleave)
 {
@@ -91,6 +142,14 @@ mono_profiler_install_enter_leave (MonoProfileMethodFunc enter, MonoProfileMetho
        method_leave = fleave;
 }
 
+/**
+ * mono_profiler_install_jit_compile:
+ * @start: the routine to be called when the JIT process starts.
+ * @end: the routine to be called when the JIT process ends.
+ *
+ * Use this routine to install routines that will be called when JIT 
+ * compilation of a method starts and completes.
+ */
 void 
 mono_profiler_install_jit_compile (MonoProfileMethodFunc start, MonoProfileMethodResult end)
 {
@@ -441,15 +500,28 @@ mono_profiler_coverage_free (MonoMethod *method)
        mono_profiler_coverage_unlock ();
 }
 
+/**
+ * mono_profiler_coverage_get:
+ * @prof: The profiler handle, installed with mono_profiler_install
+ * @method: the method to gather information from.
+ * @func: A routine that will be called back with the results
+ *
+ * If the MONO_PROFILER_INS_COVERAGE flag was active during JIT compilation
+ * it is posisble to obtain coverage information about a give method.
+ *
+ * The function @func will be invoked repeatedly with instances of the
+ * MonoProfileCoverageEntry structure.
+ */
 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;
+       guint32 code_size;
+       const unsigned char *start, *end, *cil_code;
        MonoMethodHeader *header;
        MonoProfileCoverageEntry entry;
+       MonoDebugMethodInfo *debug_minfo;
 
        mono_profiler_coverage_lock ();
        info = g_hash_table_lookup (coverage_hash, method);
@@ -459,21 +531,34 @@ mono_profiler_coverage_get (MonoProfiler *prof, MonoMethod *method, MonoProfileC
                return;
 
        header = mono_method_get_header (method);
-       start = (unsigned char*)header->code;
-       end = start + header->code_size;
+       start = mono_method_header_get_code (header, &code_size, NULL);
+       debug_minfo = mono_debug_lookup_method (method);
+
+       end = start + 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) {
+                       char *fname = NULL;
                        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;
+                       entry.line = entry.col = 1;
+                       entry.filename = NULL;
+                       if (debug_minfo) {
+                               MonoDebugSourceLocation *location;
+
+                               location = mono_debug_symfile_lookup_location (debug_minfo, offset);
+                               if (location) {
+                                       entry.line = location->row;
+                                       entry.col = location->column;
+                                       entry.filename = fname = g_strdup (location->source_file);
+                                       mono_debug_free_source_location (location);
+                               }
+                       }
+
                        func (prof, &entry);
+                       g_free (fname);
                }
        }
 }
@@ -484,6 +569,8 @@ mono_profiler_coverage_get (MonoProfiler *prof, MonoMethod *method, MonoProfileC
  * and improve it to do graphs and more accurate timestamping with rdtsc.
  */
 
+static FILE* poutput = NULL;
+
 #define USE_X86TSC 0
 #define USE_WIN32COUNTER 0
 #if USE_X86TSC
@@ -665,7 +752,7 @@ create_profiler (void)
 {
        MonoProfiler *prof = g_new0 (MonoProfiler, 1);
 
-       prof->methods = g_hash_table_new (NULL, NULL);
+       prof->methods = g_hash_table_new (mono_aligned_addr_hash, NULL);
        MONO_TIMER_INIT (prof->jit_timer);
        prof->mempool = mono_mempool_new ();
        return prof;
@@ -726,6 +813,14 @@ method_get_name (MonoMethod* method)
 
 static void output_callers (MethodProfile *p);
 
+/* This isn't defined on older glib versions and on some platforms */
+#ifndef G_GUINT64_FORMAT
+#define G_GUINT64_FORMAT "ul"
+#endif
+#ifndef G_GINT64_FORMAT
+#define G_GINT64_FORMAT "lld"
+#endif
+
 static void
 output_profile (GList *funcs)
 {
@@ -735,24 +830,24 @@ output_profile (GList *funcs)
        guint64 total_calls = 0;
 
        if (funcs)
-               g_print ("Time(ms) Count   P/call(ms) Method name\n");
+               fprintf (poutput, "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;
                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);
+               fprintf (poutput, "########################\n");
+               fprintf (poutput, "% 8.3f ", (double) (p->total * 1000));
+               fprintf (poutput, "%7" G_GUINT64_FORMAT " ", (unsigned long long)p->count);
+               fprintf (poutput, "% 8.3f ", (double) (p->total * 1000)/(double)p->count);
+               fprintf (poutput, "  %s\n", m);
 
                g_free (m);
                /* callers */
                output_callers (p);
        }
-       printf ("Total number of calls: %lld\n", (long long)total_calls);
+       fprintf (poutput, "Total number of calls: %" G_GINT64_FORMAT "\n", (long long)total_calls);
 }
 
 typedef struct {
@@ -825,7 +920,7 @@ output_callers (MethodProfile *p) {
        CallerInfo *cinfo;
        char *m;
        
-       g_print ("  Callers (with count) that contribute at least for 1%%:\n");
+       fprintf (poutput, "  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;
@@ -837,16 +932,11 @@ output_callers (MethodProfile *p) {
                if (percent < 1)
                        continue;
                m = method_get_name (cinfo->caller);
-               g_print ("    %8d % 3d %% %s\n", cinfo->count, percent, m);
+               fprintf (poutput, "    %8d % 3d %% %s\n", cinfo->count, percent, m);
                g_free (m);
        }
 }
 
-/* This isn't defined on older glib versions and on some platforms */
-#ifndef G_GUINT64_FORMAT
-#define G_GUINT64_FORMAT "ul"
-#endif
-
 static void
 output_newobj_profile (GList *proflist)
 {
@@ -861,10 +951,10 @@ output_newobj_profile (GList *proflist)
        guint64 total = 0;
        GSList *sorted, *tmps;
 
-       g_print ("\nAllocation profiler\n");
+       fprintf (poutput, "\nAllocation profiler\n");
 
        if (proflist)
-               g_print ("%-9s %s\n", "Total mem", "Method");
+               fprintf (poutput, "%-9s %s\n", "Total mem", "Method");
        for (tmp = proflist; tmp; tmp = tmp->next) {
                p = tmp->data;
                total += p->count;
@@ -872,7 +962,7 @@ output_newobj_profile (GList *proflist)
                        continue;
                mp = p->mp;
                m = method_get_name (mp->method);
-               g_print ("########################\n%8" G_GUINT64_FORMAT " KB %s\n", (p->count / 1024), m);
+               fprintf (poutput, "########################\n%8" G_GUINT64_FORMAT " KB %s\n", (p->count / 1024), m);
                g_free (m);
                sorted = sort_alloc_list (mp->alloc_info);
                for (tmps = sorted; tmps; tmps = tmps->next) {
@@ -888,12 +978,12 @@ output_newobj_profile (GList *proflist)
                        }
                        g_snprintf (buf, sizeof (buf), "%s%s%s%s",
                                klass->name_space, klass->name_space ? "." : "", klass->name, isarray);
-                       g_print ("    %8" G_GUINT64_FORMAT " KB %8" G_GUINT64_FORMAT " %-48s\n", (ainfo->mem / 1024), ainfo->count, buf);
+                       fprintf (poutput, "    %8" G_GUINT64_FORMAT " KB %8" G_GUINT64_FORMAT " %-48s\n", (ainfo->mem / 1024), ainfo->count, buf);
                }
                /* callers */
                output_callers (mp);
        }
-       g_print ("Total memory allocated: %" G_GUINT64_FORMAT " KB\n", total / 1024);
+       fprintf (poutput, "Total memory allocated: %" G_GUINT64_FORMAT " KB\n", total / 1024);
 }
 
 static void
@@ -1143,6 +1233,17 @@ try_addr2line (const char* binary, gpointer ip)
                const char *addr_argv[] = {"addr2line", "-f", "-e", binary, NULL};
                int child_pid;
                int ch_in, ch_out;
+#ifdef __linux__
+               char monobin [1024];
+               /* non-linux platforms will need different code here */
+               if (strcmp (binary, "mono") == 0) {
+                       int count = readlink ("/proc/self/exe", monobin, sizeof (monobin));
+                       if (count >= 0 && count < sizeof (monobin)) {
+                               monobin [count] = 0;
+                               addr_argv [3] = monobin;
+                       }
+               }
+#endif
                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);
@@ -1225,13 +1326,13 @@ stat_prof_report (void)
                if (c > 1)
                        g_free (mn);
        }
-       g_print ("prof counts: total/unmanaged: %d/%d\n", pcount, prof_ucounts);
+       fprintf (poutput, "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);
+               fprintf (poutput, "%7d\t%5.2f %% %s\n", c, perc, (char*)tmp->data);
        }
        g_list_free (sorted);
 }
@@ -1259,10 +1360,10 @@ simple_shutdown (MonoProfiler *prof)
                merge_thread_data (prof, tprof);
        }
 
-       printf("Total time spent compiling %d methods (sec): %.4g\n", prof->methods_jitted, prof->jit_time);
+       fprintf (poutput, "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);
+               fprintf (poutput, "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);
@@ -1287,6 +1388,7 @@ mono_profiler_install_simple (const char *desc)
        MonoProfileFlags flags = 0;
 
        MONO_TIMER_STARTUP;
+       poutput = stdout;
 
        if (!desc)
                desc = "alloc,time,jit";
@@ -1310,12 +1412,22 @@ mono_profiler_install_simple (const char *desc)
                                flags |= MONO_PROFILE_STATISTICAL | MONO_PROFILE_APPDOMAIN_EVENTS;
                        else if (!strcmp (arg, "jit"))
                                flags |= MONO_PROFILE_JIT_COMPILATION;
-                       else {
+                       else if (strncmp (arg, "file=", 5) == 0) {
+                               poutput = fopen (arg + 5, "wb");
+                               if (!poutput) {
+                                       poutput = stdout;
+                                       fprintf (stderr, "profiler : cannot open profile output file '%s'.\n", arg + 5);
+                               }
+                       } else {
                                fprintf (stderr, "profiler : Unknown argument '%s'.\n", arg);
                                return;
                        }
                }
        }
+       if (flags & MONO_PROFILE_ALLOCATIONS)
+               flags |= MONO_PROFILE_ENTER_LEAVE;
+       if (!flags)
+               flags = MONO_PROFILE_ENTER_LEAVE | MONO_PROFILE_ALLOCATIONS | MONO_PROFILE_JIT_COMPILATION;
 
        prof = create_profiler ();
        ALLOC_PROFILER ();
@@ -1339,6 +1451,16 @@ mono_profiler_install_simple (const char *desc)
 typedef void (*ProfilerInitializer) (const char*);
 #define INITIALIZER_NAME "mono_profiler_startup"
 
+/**
+ * mono_profiler_load:
+ * @desc: arguments to configure the profiler
+ *
+ * Invoke this method to initialize the profiler.   This will drive the
+ * loading of the internal ("default") or any external profilers.
+ *
+ * This routine is invoked by Mono's driver, but must be called manually
+ * if you embed Mono into your application.
+ */
 void 
 mono_profiler_load (const char *desc)
 {
@@ -1353,11 +1475,13 @@ mono_profiler_load (const char *desc)
        }
 #endif
        {
-               GModule *pmodule;
+               MonoDl *pmodule;
                const char* col = strchr (desc, ':');
                char* libname;
                char* path;
                char *mname;
+               char *err;
+               void *iter;
                if (col != NULL) {
                        mname = g_memdup (desc, col - desc);
                        mname [col - desc] = 0;
@@ -1365,19 +1489,28 @@ mono_profiler_load (const char *desc)
                        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);
+               iter = NULL;
+               err = NULL;
+               while ((path = mono_dl_build_path (NULL, libname, &iter))) {
+                       g_free (err);
+                       pmodule = mono_dl_open (path, MONO_DL_LAZY, &err);
+                       if (pmodule) {
+                               ProfilerInitializer func;
+                               if ((err = mono_dl_symbol (pmodule, INITIALIZER_NAME, (gpointer *)&func))) {
+                                       g_warning ("Cannot find initializer function %s in profiler module: %s (%s)", INITIALIZER_NAME, libname, err);
+                                       g_free (err);
+                                       err = NULL;
+                               } else {
+                                       func (desc);
+                               }
+                               break;
                        }
-               } else {
-                       g_warning ("Error loading profiler module '%s': %s", libname, g_module_error ());
+                       g_free (path);
+               }
+               if (!pmodule) {
+                       g_warning ("Error loading profiler module '%s': %s", libname, err);
+                       g_free (err);
                }
-
                g_free (libname);
                g_free (mname);
                g_free (path);