* test-9.il: New test, test instaniating a class
[mono.git] / mono / metadata / profiler.c
index b6887653d2819bbf4dae79aa44861e0c83ed2fe8..2a7498096a26e8f5511db451f4b328c071723df4 100644 (file)
@@ -28,6 +28,7 @@ static MonoProfileClassFunc   class_end_unload;
 static MonoProfileMethodFunc   jit_start;
 static MonoProfileMethodResult jit_end;
 static MonoProfileMethodResult man_unman_transition;
+static MonoProfileAllocFunc    allocation_cb;
 static MonoProfileMethodFunc   method_enter;
 static MonoProfileMethodFunc   method_leave;
 
@@ -87,6 +88,12 @@ mono_profiler_install_transition (MonoProfileMethodResult callback)
        man_unman_transition = callback;
 }
 
+void 
+mono_profiler_install_allocation (MonoProfileAllocFunc callback)
+{
+       allocation_cb = callback;
+}
+
 void 
 mono_profiler_install_appdomain   (MonoProfileAppDomainFunc start_load, MonoProfileAppDomainResult end_load,
                                    MonoProfileAppDomainFunc start_unload, MonoProfileAppDomainFunc end_unload)
@@ -163,18 +170,25 @@ 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_thread_start (guint32 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 (guint32 tid)
 {
        if ((mono_profiler_events & MONO_PROFILE_THREADS) && thread_end)
-               thread_end (current_profiler, thread);
+               thread_end (current_profiler, tid);
 }
 
 void 
@@ -314,6 +328,7 @@ mono_profiler_shutdown (void)
  */
 
 #define USE_X86TSC 0
+#define USE_WIN32COUNTER 0
 #if USE_X86TSC
 
 typedef struct {
@@ -371,23 +386,77 @@ have_rdtsc (void) {
 #define MONO_TIMER_STOP(t) rdtsc ((t).lowe, (t).highe);
 #define MONO_TIMER_ELAPSED(t) rdtsc_elapsed (&(t))
 
+#elif USE_WIN32COUNTER
+#include <windows.h>
+
+typedef struct {
+       LARGE_INTEGER start, stop;
+} MonoWin32Timer;
+
+static int freq;
+
+static double
+win32_elapsed (MonoWin32Timer *t)
+{
+       LONGLONG diff = t->stop.QuadPart - t->start.QuadPart;
+       return ((double)diff / freq) / 1000000; /* have to return the result in seconds */
+}
+
+static int 
+have_win32counter (void) {
+       LARGE_INTEGER f;
+
+       if (!QueryPerformanceFrequency (&f))
+               return 0;
+       return f.LowPart;
+}
+
+#define MONO_TIMER_STARTUP     \
+       if (!(freq = have_win32counter ())) g_error ("Compiled with Win32 counter support, but none found");
+#define MONO_TIMER_TYPE  MonoWin32Timer
+#define MONO_TIMER_INIT(t)
+#define MONO_TIMER_DESTROY(t)
+#define MONO_TIMER_START(t) QueryPerformanceCounter (&(t).start)
+#define MONO_TIMER_STOP(t) QueryPerformanceCounter (&(t).stop)
+#define MONO_TIMER_ELAPSED(t) win32_elapsed (&(t))
+
 #else
 
+typedef struct {
+       GTimeVal start, stop;
+} MonoGLibTimer;
+
+static double
+timeval_elapsed (MonoGLibTimer *t)
+{
+       if (t->start.tv_usec > t->stop.tv_usec) {
+               t->stop.tv_usec += G_USEC_PER_SEC;
+               t->stop.tv_sec--;
+       }
+       return (t->stop.tv_sec - t->start.tv_sec) 
+               + ((double)(t->stop.tv_usec - t->start.tv_usec))/ G_USEC_PER_SEC;
+}
+
 #define MONO_TIMER_STARTUP
-#define MONO_TIMER_TYPE GTimer *
-#define MONO_TIMER_INIT(t) (t) = g_timer_new ()
-#define MONO_TIMER_DESTROY(t) g_timer_destroy ((t))
-#define MONO_TIMER_START(t) g_timer_start ((t))
-#define MONO_TIMER_STOP(t) g_timer_stop ((t))
-#define MONO_TIMER_ELAPSED(t) g_timer_elapsed ((t), NULL)
+#define MONO_TIMER_TYPE MonoGLibTimer
+#define MONO_TIMER_INIT(t)
+#define MONO_TIMER_DESTROY(t)
+#define MONO_TIMER_START(t) g_get_current_time (&(t).start)
+#define MONO_TIMER_STOP(t) g_get_current_time (&(t).stop)
+#define MONO_TIMER_ELAPSED(t) timeval_elapsed (&(t))
 #endif
 
+typedef struct _AllocInfo AllocInfo;
+typedef struct _CallerInfo CallerInfo;
+
 struct _MonoProfiler {
        GHashTable *methods;
-       GHashTable *newobjs;
        MONO_TIMER_TYPE jit_timer;
        double      jit_time;
        int         methods_jitted;
+       GSList     *callers;
+       /* allocations unassigned to an IL method */
+       AllocInfo  *alloc_info;
 };
 
 typedef struct {
@@ -397,8 +466,31 @@ typedef struct {
        } u;
        guint64 count;
        double total;
+       AllocInfo *alloc_info;
+       CallerInfo *caller_info;
 } MethodProfile;
 
+typedef struct _MethodCallProfile MethodCallProfile;
+
+struct _MethodCallProfile {
+       MethodCallProfile *next;
+       MONO_TIMER_TYPE timer;
+       MonoMethod *method;
+};
+
+struct _AllocInfo {
+       AllocInfo *next;
+       MonoClass *klass;
+       guint count;
+       guint mem;
+};
+
+struct _CallerInfo {
+       CallerInfo *next;
+       MonoMethod *caller;
+       guint count;
+};
+
 static gint
 compare_profile (MethodProfile *profa, MethodProfile *profb)
 {
@@ -413,32 +505,47 @@ build_profile (MonoMethod *m, MethodProfile *prof, GList **funcs)
        *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 (method->signature, 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->u.method);
+               printf ("########################\n% 8.3f %7llu % 8.3f  %s\n",
+                       (double)(p->total*1000), p->count, (double)(p->total*1000)/(double)p->count, m);
+               g_free (m);
+               /* callers */
+               output_callers (p);
        }
+       printf ("Total number of calls: %lld\n", total_calls);
 }
 
 typedef struct {
-       MonoClass *klass;
+       MethodProfile *mp;
        guint count;
 } NewobjProfile;
 
@@ -449,38 +556,125 @@ 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 (strcmp (klass->name, "Array") == 0) {
-                       isarray = "[]";
-                       klass = klass->element_class;
-               } else {
-                       isarray = "";
+               total += p->count;
+               if (p->count < 50000)
+                       continue;
+               mp = p->mp;
+               m = method_get_name (mp->u.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);
                }
-               g_snprintf (buf, sizeof (buf), "%s.%s%s",
-                       klass->name_space, klass->name, isarray);
-               g_print ("%-52s %9d\n", buf, p->count);
+               /* callers */
+               output_callers (mp);
        }
+       g_print ("Total memory allocated: %d KB\n", total / 1024);
 }
 
 static void
@@ -494,6 +688,22 @@ simple_method_enter (MonoProfiler *prof, MonoMethod *method)
        }
        profile_info->count++;
        MONO_TIMER_START (profile_info->u.timer);
+       if (prof->callers) {
+               CallerInfo *cinfo;
+               MonoMethod *caller = prof->callers->data;
+               for (cinfo = profile_info->caller_info; cinfo; cinfo = cinfo->next) {
+                       if (cinfo->caller == caller)
+                               break;
+               }
+               if (!cinfo) {
+                       cinfo = g_new0 (CallerInfo, 1);
+                       cinfo->caller = caller;
+                       cinfo->next = profile_info->caller_info;
+                       profile_info->caller_info = cinfo;
+               }
+               cinfo->count++;
+       }
+       prof->callers = g_slist_prepend (prof->callers, method);
 }
 
 static void
@@ -505,13 +715,47 @@ simple_method_leave (MonoProfiler *prof, MonoMethod *method)
 
        MONO_TIMER_STOP (profile_info->u.timer);
        profile_info->total += MONO_TIMER_ELAPSED (profile_info->u.timer);
+       prof->callers = g_slist_remove (prof->callers, method);
+}
+
+static void
+simple_allocation (MonoProfiler *prof, MonoObject *obj, MonoClass *klass)
+{
+       MethodProfile *profile_info;
+       AllocInfo *tmp;
+
+       if (prof->callers) {
+               if (!(profile_info = g_hash_table_lookup (prof->methods, prof->callers->data)))
+                       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 = g_new0 (AllocInfo, 1);
+               tmp->klass = klass;
+               tmp->next = profile_info->alloc_info;
+               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);
+       }
 }
 
 static void
 simple_method_jit (MonoProfiler *prof, MonoMethod *method)
 {
-       MONO_TIMER_START (prof->jit_timer);
        prof->methods_jitted++;
+       MONO_TIMER_START (prof->jit_timer);
 }
 
 static void
@@ -532,7 +776,7 @@ simple_shutdown (MonoProfiler *prof)
        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);
 }
@@ -545,13 +789,13 @@ mono_profiler_install_simple (void)
        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);
 
        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_set_events (MONO_PROFILE_ENTER_LEAVE|MONO_PROFILE_JIT_COMPILATION|MONO_PROFILE_ALLOCATIONS);
 }