[profiler] Add mlpd stats dumping, use --reports=stats.
authorRodrigo Kumpera <kumpera@gmail.com>
Wed, 23 Sep 2015 20:40:55 +0000 (16:40 -0400)
committerRodrigo Kumpera <kumpera@gmail.com>
Wed, 23 Sep 2015 20:43:53 +0000 (16:43 -0400)
This add statistical collection of mlpd files. Right now it reports basic statics on number of events
and their overhead, plus general buffer overhead.

This should enable us better understand what a file is made of when figuring out ways to optimize it.

Here's a sample output:

```
Mlpd statistics
    Buffer count 13499  overhead 647952 (48 bytes per header)

Event details:
             TYPE_GC                 TYPE_GC_EVENT  count   6313    min   4 max      8  bytes 35802
             TYPE_GC                  TYPE_GC_MOVE  count  17737    min  12 max    262  bytes 4138055
             TYPE_GC        TYPE_GC_HANDLE_CREATED  count  29833    min   6 max     14  bytes 296379
             TYPE_GC      TYPE_GC_HANDLE_DESTROYED  count   6620    min   5 max     10  bytes 42515
       TYPE_METADATA                 TYPE_END_LOAD  count  15926    min  12 max    271  bytes 1112068
         TYPE_METHOD                      TYPE_JIT  count  10246    min  26 max   1015  bytes 1043018
      TYPE_EXCEPTION                   TYPE_CLAUSE  count      2    min   6 max      6  bytes 12
      TYPE_EXCEPTION             TYPE_EXCEPTION_BT  count      2    min  50 max     50  bytes 100
           TYPE_HEAP               TYPE_HEAP_START  count      1    min   3 max      3  bytes 3
           TYPE_HEAP                 TYPE_HEAP_END  count      1    min   4 max      4  bytes 4
           TYPE_HEAP              TYPE_HEAP_OBJECT  count 284536    min   5 max    654  bytes 4823852
           TYPE_HEAP                TYPE_HEAP_ROOT  count 2508919   min  11 max    355  bytes 750970914
         TYPE_SAMPLE     TYPE_SAMPLE_COUNTERS_DESC  count      3    min 256 max   2835  bytes 3712
         TYPE_SAMPLE          TYPE_SAMPLE_COUNTERS  count   1089    min   3 max    402  bytes 66219
        TYPE_RUNTIME                TYPE_JITHELPER  count  21191    min   6 max     29  bytes 252473
```

mono/profiler/decode.c

index 0df2d3cd1af74d33f445fa11a8beaef0d820a95e..4ee385504bea1c339957a3080e005c3bfaf02b41 100644 (file)
@@ -2183,6 +2183,28 @@ coverage_add_coverage (CoverageCoverage *coverage)
 #define OBJ_ADDR(diff) ((obj_base + diff) << 3)
 #define LOG_TIME(base,diff) /*fprintf("outfile, time %llu + %llu near offset %d\n", base, diff, p - ctx->buf)*/
 
+
+/* Stats */
+#define BUFFER_HEADER_SIZE 48
+
+typedef struct {
+       int count, min_size, max_size, bytes;
+} EventStat;
+
+static int buffer_count;
+static EventStat stats [256];
+
+static void
+record_event_stats (int type, int size)
+{
+       ++stats [type].count;
+       if (!stats [type].min_size)
+               stats [type].min_size = size;
+       stats [type].min_size = MIN (stats [type].min_size, size);
+       stats [type].max_size = MAX (stats [type].max_size, size);
+       stats [type].bytes += size;
+}
+
 static int
 decode_buffer (ProfContext *ctx)
 {
@@ -2224,6 +2246,9 @@ decode_buffer (ProfContext *ctx)
        thread = load_thread (ctx, thread_id);
        if (!load_data (ctx, len))
                return 0;
+
+       ++buffer_count;
+
        if (!startup_time) {
                startup_time = time_base;
                if (use_time_filter) {
@@ -2238,6 +2263,8 @@ decode_buffer (ProfContext *ctx)
        p = ctx->buf;
        end = p + len;
        while (p < end) {
+               unsigned char *start = p;
+               unsigned char event = *p;
                switch (*p & 0xf) {
                case TYPE_GC: {
                        int subtype = *p & 0xf0;
@@ -3010,6 +3037,7 @@ decode_buffer (ProfContext *ctx)
                        fprintf (outfile, "unhandled profiler event: 0x%x at file offset: %llu + %lld (len: %d\n)\n", *p, (unsigned long long) file_offset, (long long) (p - ctx->buf), len);
                        exit (1);
                }
+               record_event_stats (event, p - start);
        }
        thread->last_time = time_base;
        for (i = 0; i < thread->stack_id; ++i)
@@ -3699,6 +3727,73 @@ dump_coverage (void)
        }
 }
 
+#define DUMP_EVENT_STAT(EVENT,SUBTYPE) dump_event (#EVENT, #SUBTYPE, EVENT, SUBTYPE);
+
+static void
+dump_event (const char *event_name, const char *subtype_name, int event, int subtype)
+{
+       int idx = event | subtype;
+       EventStat evt = stats [idx];
+       if (!evt.count)
+               return;
+
+       fprintf (outfile, "\t%16s\t%26s\tcount %6d\tmin %3d\tmax %6d\tbytes %d\n", event_name, subtype_name, evt.count, evt.min_size, evt.max_size, evt.bytes);
+}
+
+static void
+dump_stats (void)
+{
+       fprintf (outfile, "\nMlpd statistics\n");
+       fprintf (outfile, "\tBuffer count %d\toverhead %d (%d bytes per header)\n", buffer_count, buffer_count * BUFFER_HEADER_SIZE, BUFFER_HEADER_SIZE);
+       fprintf (outfile, "\nEvent details:\n");
+
+       DUMP_EVENT_STAT (TYPE_ALLOC, TYPE_ALLOC_NO_BT);
+       DUMP_EVENT_STAT (TYPE_ALLOC, TYPE_ALLOC_BT);
+
+       DUMP_EVENT_STAT (TYPE_GC, TYPE_GC_EVENT);
+       DUMP_EVENT_STAT (TYPE_GC, TYPE_GC_RESIZE);
+       DUMP_EVENT_STAT (TYPE_GC, TYPE_GC_MOVE);
+       DUMP_EVENT_STAT (TYPE_GC, TYPE_GC_HANDLE_CREATED);
+       DUMP_EVENT_STAT (TYPE_GC, TYPE_GC_HANDLE_DESTROYED);
+       DUMP_EVENT_STAT (TYPE_GC, TYPE_GC_HANDLE_CREATED_BT);
+       DUMP_EVENT_STAT (TYPE_GC, TYPE_GC_HANDLE_DESTROYED_BT);
+
+       DUMP_EVENT_STAT (TYPE_METADATA, TYPE_END_LOAD);
+       DUMP_EVENT_STAT (TYPE_METADATA, TYPE_END_UNLOAD);
+
+       DUMP_EVENT_STAT (TYPE_METHOD, TYPE_LEAVE);
+       DUMP_EVENT_STAT (TYPE_METHOD, TYPE_ENTER);
+       DUMP_EVENT_STAT (TYPE_METHOD, TYPE_EXC_LEAVE);
+       DUMP_EVENT_STAT (TYPE_METHOD, TYPE_JIT);
+
+       DUMP_EVENT_STAT (TYPE_EXCEPTION, TYPE_THROW);
+       DUMP_EVENT_STAT (TYPE_EXCEPTION, TYPE_CLAUSE);
+       DUMP_EVENT_STAT (TYPE_EXCEPTION, TYPE_EXCEPTION_BT);
+
+       DUMP_EVENT_STAT (TYPE_MONITOR, TYPE_MONITOR_NO_BT);
+       DUMP_EVENT_STAT (TYPE_MONITOR, TYPE_MONITOR_BT);
+
+       DUMP_EVENT_STAT (TYPE_HEAP, TYPE_HEAP_START);
+       DUMP_EVENT_STAT (TYPE_HEAP, TYPE_HEAP_END);
+       DUMP_EVENT_STAT (TYPE_HEAP, TYPE_HEAP_OBJECT);
+       DUMP_EVENT_STAT (TYPE_HEAP, TYPE_HEAP_ROOT);
+
+       DUMP_EVENT_STAT (TYPE_SAMPLE, TYPE_SAMPLE_HIT);
+       DUMP_EVENT_STAT (TYPE_SAMPLE, TYPE_SAMPLE_USYM);
+       DUMP_EVENT_STAT (TYPE_SAMPLE, TYPE_SAMPLE_UBIN);
+       DUMP_EVENT_STAT (TYPE_SAMPLE, TYPE_SAMPLE_COUNTERS_DESC);
+       DUMP_EVENT_STAT (TYPE_SAMPLE, TYPE_SAMPLE_COUNTERS);
+
+       DUMP_EVENT_STAT (TYPE_RUNTIME, TYPE_JITHELPER);
+
+       DUMP_EVENT_STAT (TYPE_COVERAGE, TYPE_COVERAGE_ASSEMBLY);
+       DUMP_EVENT_STAT (TYPE_COVERAGE, TYPE_COVERAGE_METHOD);
+       DUMP_EVENT_STAT (TYPE_COVERAGE, TYPE_COVERAGE_STATEMENT);
+       DUMP_EVENT_STAT (TYPE_COVERAGE, TYPE_COVERAGE_CLASS);
+}
+
+
+
 static void
 flush_context (ProfContext *ctx)
 {
@@ -3808,6 +3903,11 @@ print_reports (ProfContext *ctx, const char *reps, int parse_only)
                                dump_coverage ();
                        continue;
                }
+               if ((opt = match_option (p, "stats")) != p) {
+                       if (!parse_only)
+                               dump_stats ();
+                       continue;
+               }
                return 0;
        }
        return 1;