From 6612c9b9fd48aa95d950f3603a79b1e11f8e1c13 Mon Sep 17 00:00:00 2001 From: Paolo Molaro Date: Fri, 5 Nov 2010 16:35:11 +0100 Subject: [PATCH] First cut of the new log profiler and report generator. This is the first preview version of the new log profiler. It is not included in the build yet because it needs some portability cleanups, see the top of proflog.c for compilation instructions. It currently works on Linux x86 (64 bit support may work but it is untested). The documentation is included in the log-profiler.txt file. --- mono/profiler/decode.c | 1599 ++++++++++++++++++++++++++++++++ mono/profiler/log-profiler.txt | 331 +++++++ mono/profiler/proflog.c | 924 ++++++++++++++++++ mono/profiler/proflog.h | 53 ++ mono/profiler/utils.c | 296 ++++++ mono/profiler/utils.h | 21 + 6 files changed, 3224 insertions(+) create mode 100644 mono/profiler/decode.c create mode 100644 mono/profiler/log-profiler.txt create mode 100644 mono/profiler/proflog.c create mode 100644 mono/profiler/proflog.h create mode 100644 mono/profiler/utils.c create mode 100644 mono/profiler/utils.h diff --git a/mono/profiler/decode.c b/mono/profiler/decode.c new file mode 100644 index 00000000000..1640ae88963 --- /dev/null +++ b/mono/profiler/decode.c @@ -0,0 +1,1599 @@ +#include "utils.h" +#include "proflog.h" +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#define HASH_SIZE 9371 +#define SMALL_HASH_SIZE 31 + +static int debug = 0; +static int collect_traces = 0; +static int show_traces = 0; +static int trace_max = 6; +static int verbose = 0; +static uintptr_t tracked_obj = 0; +static uintptr_t thread_filter = 0; +static uint64_t time_from = 0; +static uint64_t time_to = 0xffffffffffffffffULL; +static uint64_t startup_time = 0; +static FILE* outfile = NULL; + +static int32_t +read_int32 (unsigned char *p) +{ + int32_t value = *p++; + value |= (*p++) << 8; + value |= (*p++) << 16; + value |= (uint32_t)(*p++) << 24; + return value; +} + +static int64_t +read_int64 (unsigned char *p) +{ + uint64_t value = *p++; + value |= (*p++) << 8; + value |= (*p++) << 16; + value |= (uint64_t)(*p++) << 24; + value |= (uint64_t)(*p++) << 32; + value |= (uint64_t)(*p++) << 40; + value |= (uint64_t)(*p++) << 48; + value |= (uint64_t)(*p++) << 54; + return value; +} + +static char* +pstrdup (const char *s) +{ + int len = strlen (s) + 1; + char *p = malloc (len); + memcpy (p, s, len); + return p; +} + +static int num_images; +typedef struct _ImageDesc ImageDesc; +struct _ImageDesc { + ImageDesc *next; + intptr_t image; + char *filename; +}; + +static ImageDesc* image_hash [SMALL_HASH_SIZE] = {0}; + +static void +add_image (intptr_t image, char *name) +{ + int slot = ((image >> 2) & 0xffff) % SMALL_HASH_SIZE; + ImageDesc *cd = malloc (sizeof (ImageDesc)); + cd->image = image; + cd->filename = pstrdup (name); + cd->next = image_hash [slot]; + image_hash [slot] = cd; + num_images++; +} + +typedef struct _BackTrace BackTrace; +typedef struct { + uint64_t count; + BackTrace *bt; +} CallContext; + +typedef struct { + int count; + int size; + CallContext *traces; +} TraceDesc; + +typedef struct _ClassDesc ClassDesc; +struct _ClassDesc { + ClassDesc *next; + intptr_t klass; + char *name; + intptr_t allocs; + uint64_t alloc_size; + TraceDesc traces; +}; + +static ClassDesc* class_hash [HASH_SIZE] = {0}; +static ClassDesc default_class = { + NULL, 0, + "unknown class", + 0, 0, + {0, 0, NULL} +}; + +static int num_classes = 0; + +static void +add_class (intptr_t klass, char *name) +{ + int slot = ((klass >> 2) & 0xffff) % HASH_SIZE; + ClassDesc *cd = malloc (sizeof (ClassDesc)); + cd->klass = klass; + cd->name = pstrdup (name); + cd->next = class_hash [slot]; + cd->allocs = 0; + cd->alloc_size = 0; + cd->traces.count = 0; + cd->traces.size = 0; + cd->traces.traces = NULL; + class_hash [slot] = cd; + num_classes++; +} + +static ClassDesc * +lookup_class (intptr_t klass) +{ + int slot = ((klass >> 2) & 0xffff) % HASH_SIZE; + ClassDesc *cd = class_hash [slot]; + while (cd && cd->klass != klass) + cd = cd->next; + if (!cd) + return &default_class; + return cd; +} + +typedef struct _MethodDesc MethodDesc; +struct _MethodDesc { + MethodDesc *next; + intptr_t method; + char *name; + intptr_t code; + int len; + int recurse_count; + uint64_t calls; + uint64_t total_time; + uint64_t callee_time; + uint64_t self_time; + TraceDesc traces; +}; + +static MethodDesc* method_hash [HASH_SIZE] = {0}; +static int num_methods = 0; + +static MethodDesc* +add_method (intptr_t method, char *name, intptr_t code, int len) +{ + int slot = ((method >> 2) & 0xffff) % HASH_SIZE; + MethodDesc *cd; + cd = method_hash [slot]; + while (cd && cd->method != method) + cd = cd->next; + /* we resolved an unknown method (unless we had the code unloaded) */ + if (cd) { + cd->code = code; + cd->len = len; + /*printf ("resolved unknown: %s\n", name);*/ + free (cd->name); + cd->name = pstrdup (name); + return cd; + } + cd = calloc (sizeof (MethodDesc), 1); + cd->method = method; + cd->name = pstrdup (name); + cd->code = code; + cd->len = len; + cd->calls = 0; + cd->total_time = 0; + cd->traces.count = 0; + cd->traces.size = 0; + cd->traces.traces = NULL; + cd->next = method_hash [slot]; + method_hash [slot] = cd; + num_methods++; + return cd; +} + +static MethodDesc * +lookup_method (intptr_t method) +{ + int slot = ((method >> 2) & 0xffff) % HASH_SIZE; + MethodDesc *cd = method_hash [slot]; + while (cd && cd->method != method) + cd = cd->next; + if (!cd) + return add_method (method, "unknown method", 0, 0); + return cd; +} + +typedef struct { + ClassDesc *klass; + int64_t count; + int64_t total_size; +} HeapClassDesc; + +typedef struct _HeapShot HeapShot; +struct _HeapShot { + HeapShot *next; + uint64_t timestamp; + int class_count; + int hash_size; + HeapClassDesc **class_hash; + HeapClassDesc **sorted; +}; + +static HeapShot *heap_shots = NULL; +static HeapShot *current_heap_shot = NULL; + +static HeapShot* +new_heap_shot (uint64_t timestamp) +{ + HeapShot *p; + HeapShot *hs = calloc (sizeof (HeapShot), 1); + hs->hash_size = 4; + hs->class_hash = calloc (sizeof (void*), hs->hash_size); + hs->timestamp = timestamp; + /* append it to the list */ + p = heap_shots; + while (p && p->next) + p = p->next; + if (p) + p->next = hs; + else + heap_shots = hs; + return hs; +} + +static HeapClassDesc* +heap_class_lookup (HeapShot *hs, ClassDesc *klass) +{ + int i; + unsigned int start_pos; + start_pos = ((uintptr_t)klass->klass >> 2) % hs->hash_size; + i = start_pos; + do { + HeapClassDesc* cd = hs->class_hash [i]; + if (!cd) + return NULL; + if (cd->klass == klass) + return cd; + /* wrap around */ + if (++i == hs->hash_size) + i = 0; + } while (i != start_pos); + return NULL; +} + +static int +add_heap_hashed (HeapClassDesc **hash, int hsize, ClassDesc *klass, uint64_t size, uint64_t count) +{ + int i; + unsigned int start_pos; + start_pos = ((uintptr_t)klass->klass >> 2) % hsize; + i = start_pos; + do { + if (hash [i] && hash [i]->klass == klass) { + hash [i]->total_size += size; + hash [i]->count += count; + return 0; + } else if (!hash [i]) { + hash [i] = calloc (sizeof (HeapClassDesc), 1); + hash [i]->klass = klass; + hash [i]->total_size += size; + hash [i]->count += count; + return 1; + } + /* wrap around */ + if (++i == hsize) + i = 0; + } while (i != start_pos); + /* should not happen */ + printf ("failed heap class store\n"); + return 0; +} + +static void +add_heap_shot_obj (HeapShot *hs, ClassDesc *klass, uint64_t size) +{ + int i; + if (hs->class_count * 2 >= hs->hash_size) { + HeapClassDesc **n; + int old_size = hs->hash_size; + hs->hash_size *= 2; + if (hs->hash_size == 0) + hs->hash_size = 4; + n = calloc (sizeof (void*) * hs->hash_size, 1); + for (i = 0; i < old_size; ++i) { + if (hs->class_hash [i]) + add_heap_hashed (n, hs->hash_size, hs->class_hash [i]->klass, hs->class_hash [i]->total_size, hs->class_hash [i]->count); + } + if (hs->class_hash) + free (hs->class_hash); + hs->class_hash = n; + } + hs->class_count += add_heap_hashed (hs->class_hash, hs->hash_size, klass, size, 1); +} + +struct _BackTrace { + BackTrace *next; + unsigned int hash; + int count; + int id; + MethodDesc *methods [1]; +}; + +static BackTrace *backtrace_hash [HASH_SIZE]; +static BackTrace **backtraces = NULL; +static int num_backtraces = 0; +static int next_backtrace = 0; + +static int +hash_backtrace (int count, MethodDesc **methods) +{ + int hash = count; + int i; + for (i = 0; i < count; ++i) { + hash = (hash << 5) - hash + methods [i]->method; + } + return hash; +} + +static int +compare_backtrace (BackTrace *bt, int count, MethodDesc **methods) +{ + int i; + if (bt->count != count) + return 0; + for (i = 0; i < count; ++i) + if (methods [i] != bt->methods [i]) + return 0; + return 1; +} + +static BackTrace* +add_backtrace (int count, MethodDesc **methods) +{ + int hash = hash_backtrace (count, methods); + int slot = (hash & 0xffff) % HASH_SIZE; + BackTrace *bt = backtrace_hash [slot]; + while (bt) { + if (bt->hash == hash && compare_backtrace (bt, count, methods)) + return bt; + bt = bt->next; + } + bt = malloc (sizeof (BackTrace) + ((count - 1) * sizeof (void*))); + bt->next = backtrace_hash [slot]; + backtrace_hash [slot] = bt; + if (next_backtrace == num_backtraces) { + num_backtraces *= 2; + if (!num_backtraces) + num_backtraces = 16; + backtraces = realloc (backtraces, sizeof (void*) * num_backtraces); + } + bt->id = next_backtrace++; + backtraces [bt->id] = bt; + bt->count = count; + bt->hash = hash; + for (slot = 0; slot < count; ++slot) + bt->methods [slot] = methods [slot]; + + return bt; +} + +typedef struct _ThreadContext ThreadContext; + +typedef struct { + FILE *file; + gzFile *gzfile; + unsigned char *buf; + int size; + int data_version; + ThreadContext *threads; + ThreadContext *current; +} ProfContext; + +struct _ThreadContext { + ThreadContext *next; + intptr_t thread_id; + /* emulated stack */ + MethodDesc **stack; + uint64_t *time_stack; + uint64_t *callee_time_stack; + uint64_t last_time; + int stack_size; + int stack_id; +}; + +static void +ensure_buffer (ProfContext *ctx, int size) +{ + if (ctx->size < size) { + ctx->buf = realloc (ctx->buf, size); + ctx->size = size; + } +} + +static int +load_data (ProfContext *ctx, int size) +{ + ensure_buffer (ctx, size); + if (ctx->gzfile) + return gzread (ctx->gzfile, ctx->buf, size) == size; + else + return fread (ctx->buf, size, 1, ctx->file); +} + +static ThreadContext* +load_thread (ProfContext *ctx, intptr_t thread_id) +{ + ThreadContext *thread; + if (ctx->current && ctx->current->thread_id == thread_id) + return ctx->current; + thread = ctx->threads; + while (thread) { + if (thread->thread_id == thread_id) { + ctx->current = thread; + return thread; + } + thread = thread->next; + } + thread = malloc (sizeof (ThreadContext)); + thread->next = ctx->threads; + ctx->threads = thread; + ctx->current = thread; + thread->thread_id = thread_id; + thread->last_time = 0; + thread->stack_id = 0; + thread->stack_size = 32; + thread->stack = malloc (thread->stack_size * sizeof (void*)); + thread->time_stack = malloc (thread->stack_size * sizeof (uint64_t)); + thread->callee_time_stack = malloc (thread->stack_size * sizeof (uint64_t)); + return thread; +} + +static void +ensure_thread_stack (ThreadContext *thread) +{ + if (thread->stack_id == thread->stack_size) { + thread->stack_size *= 2; + thread->stack = realloc (thread->stack, thread->stack_size * sizeof (void*)); + thread->time_stack = realloc (thread->time_stack, thread->stack_size * sizeof (uint64_t)); + thread->callee_time_stack = realloc (thread->callee_time_stack, thread->stack_size * sizeof (uint64_t)); + } +} + +static int +add_trace_hashed (CallContext *traces, int size, BackTrace *bt, uint64_t value) +{ + int i; + unsigned int start_pos; + start_pos = bt->hash % size; + i = start_pos; + do { + if (traces [i].bt == bt) { + traces [i].count += value; + return 0; + } else if (!traces [i].bt) { + traces [i].bt = bt; + traces [i].count += value; + return 1; + } + /* wrap around */ + if (++i == size) + i = 0; + } while (i != start_pos); + /* should not happen */ + printf ("failed trace store\n"); + return 0; +} + +static void +add_trace_bt (BackTrace *bt, TraceDesc *trace, uint64_t value) +{ + int i; + if (!collect_traces) + return; + if (trace->count * 2 >= trace->size) { + CallContext *n; + int old_size = trace->size; + trace->size *= 2; + if (trace->size == 0) + trace->size = 4; + n = calloc (sizeof (CallContext) * trace->size, 1); + for (i = 0; i < old_size; ++i) { + if (trace->traces [i].bt) + add_trace_hashed (n, trace->size, trace->traces [i].bt, trace->traces [i].count); + } + if (trace->traces) + free (trace->traces); + trace->traces = n; + } + trace->count += add_trace_hashed (trace->traces, trace->size, bt, value); +} + +static BackTrace* +add_trace_thread (ThreadContext *thread, TraceDesc *trace, uint64_t value) +{ + BackTrace *bt; + int count = thread->stack_id; + if (!collect_traces) + return NULL; + if (count > trace_max) + count = trace_max; + bt = add_backtrace (count, thread->stack + thread->stack_id - count); + add_trace_bt (bt, trace, value); + return bt; +} + +static BackTrace* +add_trace_methods (MethodDesc **methods, int count, TraceDesc *trace, uint64_t value) +{ + BackTrace *bt; + if (!collect_traces) + return NULL; + if (count > trace_max) + count = trace_max; + bt = add_backtrace (count, methods); + add_trace_bt (bt, trace, value); + return bt; +} + +static int +compare_callc (const void *a, const void *b) +{ + const CallContext *A = a; + const CallContext *B = b; + if (B->count == A->count) + return 0; + if (B->count < A->count) + return -1; + return 1; +} + +static void +sort_context_array (TraceDesc* traces) +{ + int i, j; + for (i = 0, j = 0; i < traces->size; ++i) { + if (traces->traces [i].bt) { + traces->traces [j].bt = traces->traces [i].bt; + traces->traces [j].count = traces->traces [i].count; + j++; + } + } + qsort (traces->traces, traces->count, sizeof (CallContext), compare_callc); +} + +static void +push_method (ThreadContext *thread, MethodDesc *method, uint64_t timestamp) +{ + ensure_thread_stack (thread); + thread->time_stack [thread->stack_id] = timestamp; + thread->callee_time_stack [thread->stack_id] = 0; + thread->stack [thread->stack_id++] = method; + method->recurse_count++; +} + +static void +pop_method (ThreadContext *thread, MethodDesc *method, uint64_t timestamp) +{ + method->recurse_count--; + if (thread->stack_id > 0 && thread->stack [thread->stack_id - 1] == method) { + uint64_t tdiff; + thread->stack_id--; + method->calls++; + if (timestamp < thread->time_stack [thread->stack_id]) + fprintf (outfile, "time went backwards for %s\n", method->name); + tdiff = timestamp - thread->time_stack [thread->stack_id]; + if (thread->callee_time_stack [thread->stack_id] > tdiff) + fprintf (outfile, "callee time bigger for %s\n", method->name); + method->self_time += tdiff - thread->callee_time_stack [thread->stack_id]; + method->callee_time += thread->callee_time_stack [thread->stack_id]; + if (thread->stack_id) + thread->callee_time_stack [thread->stack_id - 1] += tdiff; + //fprintf (outfile, "method %s took %d\n", method->name, (int)(tdiff/1000)); + } else { + fprintf (outfile, "unmatched leave at stack pos: %d for method %s\n", thread->stack_id, method->name); + } +} + +typedef struct { + uint64_t start_time; /* move this per-thread? */ + uint64_t total_time; + uint64_t max_time; + int count; +} GCDesc; +static GCDesc gc_info [3]; +static uint64_t max_heap_size; +static uint64_t gc_object_moves; +static int gc_resizes; + +static const char* +gc_event_name (int ev) +{ + switch (ev) { + case MONO_GC_EVENT_START: return "start"; + case MONO_GC_EVENT_MARK_START: return "mark start"; + case MONO_GC_EVENT_MARK_END: return "mark end"; + case MONO_GC_EVENT_RECLAIM_START: return "reclaim start"; + case MONO_GC_EVENT_RECLAIM_END: return "reclaim end"; + case MONO_GC_EVENT_END: return "end"; + case MONO_GC_EVENT_PRE_STOP_WORLD: return "pre stop"; + case MONO_GC_EVENT_POST_STOP_WORLD: return "post stop"; + case MONO_GC_EVENT_PRE_START_WORLD: return "pre start"; + case MONO_GC_EVENT_POST_START_WORLD: return "post start"; + default: + return "unknown"; + } +} + +static uint64_t clause_summary [MONO_EXCEPTION_CLAUSE_FAULT + 1]; +static uint64_t throw_count = 0; +static TraceDesc exc_traces; + +static const char* +clause_name (int type) +{ + switch (type) { + case MONO_EXCEPTION_CLAUSE_NONE: return "catch"; + case MONO_EXCEPTION_CLAUSE_FILTER: return "filter"; + case MONO_EXCEPTION_CLAUSE_FINALLY: return "finally"; + case MONO_EXCEPTION_CLAUSE_FAULT: return "fault"; + default: return "invalid"; + } +} + +static uint64_t monitor_contention; +static uint64_t monitor_failed; +static uint64_t monitor_acquired; + +typedef struct _MonitorDesc MonitorDesc; +struct _MonitorDesc { + MonitorDesc *next; + uintptr_t objid; + uintptr_t contentions; + TraceDesc traces; +}; + +static MonitorDesc* monitor_hash [SMALL_HASH_SIZE] = {0}; +static int num_monitors = 0; + +static MonitorDesc* +lookup_monitor (uintptr_t objid) +{ + int slot = ((objid >> 3) & 0xffff) % SMALL_HASH_SIZE; + MonitorDesc *cd = monitor_hash [slot]; + while (cd && cd->objid != objid) + cd = cd->next; + if (!cd) { + cd = calloc (sizeof (MonitorDesc), 1); + cd->objid = objid; + cd->next = monitor_hash [slot]; + monitor_hash [slot] = cd; + num_monitors++; + } + return cd; +} + +static const char* +monitor_ev_name (int ev) +{ + switch (ev) { + case MONO_PROFILER_MONITOR_CONTENTION: return "contended"; + case MONO_PROFILER_MONITOR_DONE: return "acquired"; + case MONO_PROFILER_MONITOR_FAIL: return "not taken"; + default: return "invalid"; + } +} + +static MethodDesc** +decode_bt (MethodDesc** sframes, int *size, unsigned char *p, unsigned char **endp, intptr_t ptr_base) +{ + MethodDesc **frames; + int i; + int flags = decode_uleb128 (p, &p); + int count = decode_uleb128 (p, &p); + if (count > *size) + frames = malloc (count * sizeof (void*)); + else + frames = sframes; + for (i = 0; i < count; ++i) { + intptr_t ptrdiff = decode_sleb128 (p, &p); + frames [i] = lookup_method (ptr_base + ptrdiff); + } + *size = count; + *endp = p; + return frames; +} + +static void +tracked_creation (uintptr_t obj, ClassDesc *cd, uint64_t size, BackTrace *bt, uint64_t timestamp) +{ + fprintf (outfile, "Object %p (%s, %llu bytes) created at %.3f secs.\n", (void*)obj, cd->name, size, (timestamp - startup_time)/1000000000.0); + if (bt && bt->count) { + int k; + for (k = 0; k < bt->count; ++k) + fprintf (outfile, "\t%s\n", bt->methods [k]->name); + } +} + +#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)*/ + +static int +decode_buffer (ProfContext *ctx) +{ + unsigned char *p; + unsigned char *end; + intptr_t thread_id; + intptr_t ptr_base; + intptr_t obj_base; + intptr_t method_base; + uint64_t time_base; + uint64_t file_offset; + int len, i; + ThreadContext *thread; + + file_offset = ftell (ctx->file); + if (!load_data (ctx, 48)) + return 0; + p = ctx->buf; + if (read_int32 (p) != BUF_ID) + return 0; + len = read_int32 (p + 4); + time_base = read_int64 (p + 8); + ptr_base = read_int64 (p + 16); + obj_base = read_int64 (p + 24); + thread_id = read_int64 (p + 32); + method_base = read_int64 (p + 40); + if (debug) + fprintf (outfile, "buf: thread:%x, len: %d, time: %llu, file offset: %llu\n", thread_id, len, time_base, file_offset); + thread = load_thread (ctx, thread_id); + if (!load_data (ctx, len)) + return 0; + if (!startup_time) { + startup_time = time_base; + if (time_from) { + time_from += startup_time; + time_to += startup_time; + } + } + for (i = 0; i < thread->stack_id; ++i) + thread->stack [i]->recurse_count++; + p = ctx->buf; + end = p + len; + while (p < end) { + switch (*p & 0xf) { + case TYPE_GC: { + int subtype = *p & 0xf0; + uint64_t tdiff = decode_uleb128 (p + 1, &p); + LOG_TIME (time_base, tdiff); + time_base += tdiff; + if (subtype == TYPE_GC_RESIZE) { + uint64_t new_size = decode_uleb128 (p, &p); + if (debug) + fprintf (outfile, "gc heap resized to %llu\n", new_size); + gc_resizes++; + if (new_size > max_heap_size) + max_heap_size = new_size; + } else if (subtype == TYPE_GC_EVENT) { + uint64_t ev = decode_uleb128 (p, &p); + int gen = decode_uleb128 (p, &p); + if (debug) + fprintf (outfile, "gc event for gen%d: %s at %llu\n", gen - 1, gc_event_name (ev), time_base); + if (gen > 2) { + fprintf (outfile, "incorrect gc gen: %d\n", gen); + break; + } + if (ev == MONO_GC_EVENT_START) { + gc_info [gen].start_time = time_base; + gc_info [gen].count++; + } else if (ev == MONO_GC_EVENT_END) { + tdiff = time_base - gc_info [gen].start_time; + gc_info [gen].total_time += tdiff; + if (tdiff > gc_info [gen].max_time) + gc_info [gen].max_time = tdiff; + } + } else if (subtype == TYPE_GC_MOVE) { + int j, num = decode_uleb128 (p, &p); + gc_object_moves += num / 2; + for (j = 0; j < num; j += 2) { + int64_t obj1diff = decode_sleb128 (p, &p); + int64_t obj2diff = decode_sleb128 (p, &p); + if (tracked_obj == OBJ_ADDR (obj1diff)) + fprintf (outfile, "Object %p moved to %p\n", (void*)OBJ_ADDR (obj1diff), (void*)OBJ_ADDR (obj2diff)); + else if (tracked_obj == OBJ_ADDR (obj2diff)) + fprintf (outfile, "Object %p moved from %p\n", (void*)OBJ_ADDR (obj2diff), (void*)OBJ_ADDR (obj1diff)); + if (debug) { + fprintf (outfile, "moved obj %p to %p\n", (void*)OBJ_ADDR (obj1diff), (void*)OBJ_ADDR (obj2diff)); + } + } + } + break; + } + case TYPE_METADATA: { + int type = *p & 0x30; + int error = *p & TYPE_LOAD_ERR; + uint64_t tdiff = decode_uleb128 (p + 1, &p); + int mtype = *p++; + int64_t ptrdiff = decode_sleb128 (p, &p); + LOG_TIME (time_base, tdiff); + time_base += tdiff; + if (mtype == TYPE_CLASS) { + int64_t imptrdiff = decode_sleb128 (p, &p); + uint64_t flags = decode_uleb128 (p, &p); + if (debug) + fprintf (outfile, "loaded class %p (%s in %p) at %llu\n", (void*)(ptr_base + ptrdiff), p, (void*)(ptr_base + imptrdiff), time_base); + add_class (ptr_base + ptrdiff, p); + while (*p) p++; + p++; + } else if (mtype == TYPE_IMAGE) { + uint64_t flags = decode_uleb128 (p, &p); + if (debug) + fprintf (outfile, "loaded image %p (%s) at %llu\n", (void*)(ptr_base + ptrdiff), p, time_base); + add_image (ptr_base + ptrdiff, p); + while (*p) p++; + p++; + } + break; + } + case TYPE_ALLOC: { + int has_bt = *p & TYPE_ALLOC_BT; + const char *sp = p; + uint64_t tdiff = decode_uleb128 (p + 1, &p); + int64_t ptrdiff = decode_sleb128 (p, &p); + int64_t objdiff = decode_sleb128 (p, &p); + uint64_t len; + int num_bt = 0; + MethodDesc* sframes [8]; + MethodDesc** frames = sframes; + ClassDesc *cd = lookup_class (ptr_base + ptrdiff); + len = decode_uleb128 (p, &p); + LOG_TIME (time_base, tdiff); + time_base += tdiff; + if (debug) + fprintf (outfile, "alloced object %p, size %llu (%s) at %llu (%p)\n", (void*)OBJ_ADDR (objdiff), len, lookup_class (ptr_base + ptrdiff)->name, time_base, sp); + if (has_bt) { + num_bt = 8; + frames = decode_bt (sframes, &num_bt, p, &p, ptr_base); + } + if ((thread_filter && thread_filter == thread->thread_id) || (time_base >= time_from && time_base < time_to)) { + BackTrace *bt; + cd->allocs++; + cd->alloc_size += len; + if (has_bt) + bt = add_trace_methods (frames, num_bt, &cd->traces, len); + else + bt = add_trace_thread (thread, &cd->traces, len); + if (tracked_obj == OBJ_ADDR (objdiff)) + tracked_creation (OBJ_ADDR (objdiff), cd, len, bt, time_base); + } + if (frames != sframes) + free (frames); + break; + } + case TYPE_METHOD: { + int subtype = *p & 0xf0; + uint64_t tdiff = decode_uleb128 (p + 1, &p); + int64_t ptrdiff = decode_sleb128 (p, &p); + LOG_TIME (time_base, tdiff); + time_base += tdiff; + method_base += ptrdiff; + if (subtype == TYPE_JIT) { + int64_t codediff = decode_sleb128 (p, &p); + int codelen = decode_uleb128 (p, &p); + if (debug) + fprintf (outfile, "jitted method %p (%s), size: %d\n", (void*)(method_base), p, codelen); + add_method (method_base, p, ptr_base + codediff, codelen); + while (*p) p++; + p++; + } else { + MethodDesc *method; + if ((thread_filter && thread_filter != thread->thread_id)) + break; + method = lookup_method (method_base); + if (subtype == TYPE_ENTER) { + add_trace_thread (thread, &method->traces, 1); + push_method (thread, method, time_base); + } else { + pop_method (thread, method, time_base); + } + if (debug) + fprintf (outfile, "%s method %s\n", subtype == TYPE_ENTER? "enter": subtype == TYPE_EXC_LEAVE? "exleave": "leave", method->name); + } + break; + } + case TYPE_HEAP: { + int subtype = *p & 0xf0; + if (subtype == TYPE_HEAP_OBJECT) { + int i; + int64_t objdiff = decode_sleb128 (p + 1, &p); + int64_t ptrdiff = decode_sleb128 (p, &p); + uint64_t size = decode_uleb128 (p, &p); + int num = decode_uleb128 (p, &p); + ClassDesc *cd = lookup_class (ptr_base + ptrdiff); + for (i = 0; i < num; ++i) { + int64_t obj1diff = decode_sleb128 (p, &p); + } + if (debug && size) + fprintf (outfile, "traced object %p, size %llu (%s), refs: %d\n", (void*)OBJ_ADDR (objdiff), size, cd->name, num); + if (size) + add_heap_shot_obj (current_heap_shot, cd, size); + } else if (subtype == TYPE_HEAP_END) { + uint64_t tdiff = decode_uleb128 (p + 1, &p); + LOG_TIME (time_base, tdiff); + time_base += tdiff; + if (debug) + fprintf (outfile, "heap shot end\n"); + current_heap_shot = NULL; + } else if (subtype == TYPE_HEAP_START) { + uint64_t tdiff = decode_uleb128 (p + 1, &p); + LOG_TIME (time_base, tdiff); + time_base += tdiff; + if (debug) + fprintf (outfile, "heap shot start\n"); + current_heap_shot = new_heap_shot (time_base); + } + break; + } + case TYPE_MONITOR: { + int event = (*p >> 4) & 0x3; + int has_bt = *p & TYPE_MONITOR_BT; + uint64_t tdiff = decode_uleb128 (p + 1, &p); + int64_t objdiff = decode_sleb128 (p, &p); + MethodDesc* sframes [8]; + MethodDesc** frames = sframes; + int record; + int num_bt = 0; + LOG_TIME (time_base, tdiff); + time_base += tdiff; + record = (!thread_filter || thread_filter == thread->thread_id); + if (event == MONO_PROFILER_MONITOR_CONTENTION) { + MonitorDesc *mdesc = lookup_monitor (OBJ_ADDR (objdiff)); + if (record) { + monitor_contention++; + mdesc->contentions++; + } + if (has_bt) { + num_bt = 8; + frames = decode_bt (sframes, &num_bt, p, &p, ptr_base); + if (record) + add_trace_methods (frames, num_bt, &mdesc->traces, 1); + } else { + if (record) + add_trace_thread (thread, &mdesc->traces, 1); + } + } else if (event == MONO_PROFILER_MONITOR_FAIL) { + if (record) + monitor_failed++; + } else if (event == MONO_PROFILER_MONITOR_DONE) { + if (record) + monitor_acquired++; + } + if (debug) + fprintf (outfile, "monitor %s for object %p\n", monitor_ev_name (event), (void*)OBJ_ADDR (objdiff)); + if (frames != sframes) + free (frames); + break; + } + case TYPE_EXCEPTION: { + int subtype = *p & 0x70; + int has_bt = *p & TYPE_EXCEPTION_BT; + uint64_t tdiff = decode_uleb128 (p + 1, &p); + MethodDesc* sframes [8]; + MethodDesc** frames = sframes; + int record; + LOG_TIME (time_base, tdiff); + time_base += tdiff; + record = (!thread_filter || thread_filter == thread->thread_id); + if (subtype == TYPE_CLAUSE) { + int clause_type = decode_uleb128 (p, &p); + int clause_num = decode_uleb128 (p, &p); + int64_t ptrdiff = decode_sleb128 (p, &p); + method_base += ptrdiff; + if (record) + clause_summary [clause_type]++; + if (debug) + fprintf (outfile, "clause %s (%d) in method %s\n", clause_name (clause_type), clause_num, lookup_method (method_base)->name); + } else { + int64_t objdiff = decode_sleb128 (p, &p); + if (record) + throw_count++; + if (has_bt) { + has_bt = 8; + frames = decode_bt (sframes, &has_bt, p, &p, ptr_base); + if (record) + add_trace_methods (frames, has_bt, &exc_traces, 1); + } else { + if (record) + add_trace_thread (thread, &exc_traces, 1); + } + if (frames != sframes) + free (frames); + if (debug) + fprintf (outfile, "throw %p\n", (void*)OBJ_ADDR (objdiff)); + } + break; + } + default: + fprintf (outfile, "unhandled profiler event: 0x%x\n", *p); + exit (1); + } + } + thread->last_time = time_base; + for (i = 0; i < thread->stack_id; ++i) + thread->stack [i]->recurse_count = 0; + return 1; +} + +static ProfContext* +load_file (char *name) +{ + char *p; + ProfContext *ctx = calloc (sizeof (ProfContext), 1); + if (strcmp (name, "-") == 0) + ctx->file = stdin; + else + ctx->file = fopen (name, "rb"); + if (!ctx->file) { + printf ("Cannot open file: %s\n", name); + exit (1); + } + ctx->gzfile = gzdopen (fileno (ctx->file), "rb"); + if (!load_data (ctx, 32)) + return NULL; + p = ctx->buf; + if (read_int32 (p) != LOG_HEADER_ID || p [6] != LOG_DATA_VERSION) + return NULL; + ctx->data_version = p [6]; + if (read_int32 (p + 12)) /* flags must be 0 */ + return NULL; + return ctx; +} + +enum { + ALLOC_SORT_BYTES, + ALLOC_SORT_COUNT +}; +static int alloc_sort_mode = ALLOC_SORT_BYTES; + +static int +compare_class (const void *a, const void *b) +{ + ClassDesc *const*A = a; + ClassDesc *const*B = b; + uint64_t vala, valb; + if (alloc_sort_mode == ALLOC_SORT_BYTES) { + vala = (*A)->alloc_size; + valb = (*B)->alloc_size; + } else { + vala = (*A)->allocs; + valb = (*B)->allocs; + } + if (valb == vala) + return 0; + if (valb < vala) + return -1; + return 1; +} + +static void +dump_header (ProfContext *ctx) +{ + fprintf (outfile, "\nMono log profiler data\n"); + fprintf (outfile, "\tData version: %d\n", ctx->data_version); +} + +static void +dump_traces (TraceDesc *traces, const char *desc) +{ + int j; + if (!show_traces) + return; + if (!traces->count) + return; + sort_context_array (traces); + for (j = 0; j < traces->count; ++j) { + int k; + BackTrace *bt; + bt = traces->traces [j].bt; + if (!bt->count) + continue; + fprintf (outfile, "\t%llu %s from:\n", traces->traces [j].count, desc); + for (k = 0; k < bt->count; ++k) + fprintf (outfile, "\t\t%s\n", bt->methods [k]->name); + } +} + +static void +dump_threads (ProfContext *ctx) +{ + ThreadContext *thread; + fprintf (outfile, "\nThread summary\n"); + for (thread = ctx->threads; thread; thread = thread->next) { + fprintf (outfile, "\tThread: %p\n", (void*)thread->thread_id); + } +} + +static void +dump_exceptions () +{ + int i; + fprintf (outfile, "\nException summary\n"); + fprintf (outfile, "\tThrows: %llu\n", throw_count); + dump_traces (&exc_traces, "throws"); + for (i = 0; i <= MONO_EXCEPTION_CLAUSE_FAULT; ++i) { + if (!clause_summary [i]) + continue; + fprintf (outfile, "\tExecuted %s clauses: %llu\n", clause_name (i), clause_summary [i]); + } +} + +static int +compare_monitor (const void *a, const void *b) +{ + MonitorDesc *const*A = a; + MonitorDesc *const*B = b; + if ((*B)->contentions == (*A)->contentions) + return 0; + if ((*B)->contentions < (*A)->contentions) + return -1; + return 1; +} + +static void +dump_monitors () +{ + MonitorDesc **monitors; + int i, j; + if (!num_monitors) + return; + monitors = malloc (sizeof (void*) * num_monitors); + for (i = 0, j = 0; i < SMALL_HASH_SIZE; ++i) { + MonitorDesc *mdesc = monitor_hash [i]; + while (mdesc) { + monitors [j++] = mdesc; + mdesc = mdesc->next; + } + } + qsort (monitors, num_monitors, sizeof (void*), compare_monitor); + fprintf (outfile, "\nMonitor lock summary\n"); + for (i = 0; i < num_monitors; ++i) { + MonitorDesc *mdesc = monitors [i]; + fprintf (outfile, "\tLock object %p: %d contentions\n", (void*)mdesc->objid, (int)mdesc->contentions); + dump_traces (&mdesc->traces, "contentions"); + } + fprintf (outfile, "\tLock contentions: %llu\n", monitor_contention); + fprintf (outfile, "\tLock acquired: %llu\n", monitor_acquired); + fprintf (outfile, "\tLock failures: %llu\n", monitor_failed); +} + +static void +dump_gcs (void) +{ + int i; + fprintf (outfile, "\nGC summary\n"); + fprintf (outfile, "\tGC resizes: %d\n", gc_resizes); + fprintf (outfile, "\tMax heap size: %llu\n", max_heap_size); + fprintf (outfile, "\tObject moves: %llu\n", gc_object_moves); + for (i = 0; i < 3; ++i) { + if (!gc_info [i].count) + continue; + fprintf (outfile, "\tGen%d collections: %d, max time: %lluus, total time: %lluus, average: %lluus\n", + i, gc_info [i].count, gc_info [i].max_time / 1000, gc_info [i].total_time / 1000, + gc_info [i].total_time / gc_info [i].count / 1000); + } +} + +static void +dump_allocations (void) +{ + int i, c; + intptr_t allocs = 0; + uint64_t size = 0; + int header_done = 0; + ClassDesc **classes = malloc (num_classes * sizeof (void*)); + ClassDesc *cd; + c = 0; + for (i = 0; i < HASH_SIZE; ++i) { + cd = class_hash [i]; + while (cd) { + classes [c++] = cd; + cd = cd->next; + } + } + qsort (classes, num_classes, sizeof (void*), compare_class); + for (i = 0; i < num_classes; ++i) { + cd = classes [i]; + if (!cd->allocs) + continue; + allocs += cd->allocs; + size += cd->alloc_size; + if (!header_done++) { + fprintf (outfile, "\nAllocation summary\n"); + fprintf (outfile, "%10s %10s %8s Type name\n", "Bytes", "Count", "Average"); + } + fprintf (outfile, "%10llu %10d %8llu %s\n", cd->alloc_size, cd->allocs, cd->alloc_size / cd->allocs, cd->name); + dump_traces (&cd->traces, "bytes"); + } + if (allocs) + fprintf (outfile, "Total memory allocated: %llu bytes in %d objects\n", size, allocs); +} + +enum { + METHOD_SORT_TOTAL, + METHOD_SORT_SELF, + METHOD_SORT_CALLS +}; + +static int method_sort_mode = METHOD_SORT_TOTAL; + +static int +compare_method (const void *a, const void *b) +{ + MethodDesc *const*A = a; + MethodDesc *const*B = b; + uint64_t vala, valb; + if (method_sort_mode == METHOD_SORT_SELF) { + vala = (*A)->self_time; + valb = (*B)->self_time; + } else if (method_sort_mode == METHOD_SORT_CALLS) { + vala = (*A)->calls; + valb = (*B)->calls; + } else { + vala = (*A)->total_time; + valb = (*B)->total_time; + } + if (vala == valb) + return 0; + if (valb < vala) + return -1; + return 1; +} + +static void +dump_metadata (void) +{ + fprintf (outfile, "\nMetadata summary\n"); + fprintf (outfile, "\tLoaded images: %d\n", num_images); + if (verbose) { + ImageDesc *image; + int i; + for (i = 0; i < SMALL_HASH_SIZE; ++i) { + image = image_hash [i]; + while (image) { + fprintf (outfile, "\t\t%s\n", image->filename); + image = image->next; + } + } + } + +} + +static void +dump_methods (void) +{ + int i, c; + uint64_t calls = 0; + int header_done = 0; + MethodDesc **methods = malloc (num_methods * sizeof (void*)); + MethodDesc *cd; + c = 0; + for (i = 0; i < HASH_SIZE; ++i) { + cd = method_hash [i]; + while (cd) { + cd->total_time = cd->self_time + cd->callee_time; + methods [c++] = cd; + cd = cd->next; + } + } + qsort (methods, num_methods, sizeof (void*), compare_method); + for (i = 0; i < num_methods; ++i) { + uint64_t msecs; + uint64_t smsecs; + cd = methods [i]; + if (!cd->calls) + continue; + calls += cd->calls; + msecs = cd->total_time / 1000000; + smsecs = (cd->total_time - cd->callee_time) / 1000000; + if (!msecs && !verbose) + continue; + if (!header_done++) { + fprintf (outfile, "\nMethod call summary\n"); + fprintf (outfile, "%8s %8s %10s Method name\n", "Total(ms)", "Self(ms)", "Calls"); + } + fprintf (outfile, "%8llu %8llu %10llu %s\n", msecs, smsecs, cd->calls, cd->name); + dump_traces (&cd->traces, "calls"); + } + if (calls) + fprintf (outfile, "Total calls: %llu\n", calls); +} + +static int +compare_heap_class (const void *a, const void *b) +{ + HeapClassDesc *const*A = a; + HeapClassDesc *const*B = b; + uint64_t vala, valb; + if (alloc_sort_mode == ALLOC_SORT_BYTES) { + vala = (*A)->total_size; + valb = (*B)->total_size; + } else { + vala = (*A)->count; + valb = (*B)->count; + } + if (valb == vala) + return 0; + if (valb < vala) + return -1; + return 1; +} + +static void +heap_shot_summary (HeapShot *hs, int hs_num, HeapShot *last_hs) +{ + uint64_t size = 0; + uint64_t count = 0; + int ccount = 0; + int i; + HeapClassDesc *cd; + HeapClassDesc **sorted; + sorted = malloc (sizeof (void*) * hs->class_count); + for (i = 0; i < hs->hash_size; ++i) { + cd = hs->class_hash [i]; + if (!cd) + continue; + count += cd->count; + size += cd->total_size; + sorted [ccount++] = cd; + } + hs->sorted = sorted; + qsort (sorted, ccount, sizeof (void*), compare_heap_class); + fprintf (outfile, "\n\tHeap shot %d at %.3f secs: size: %llu, object count: %llu, class count: %d\n", + hs_num, (hs->timestamp - startup_time)/1000000000.0, size, count, ccount); + if (!verbose && ccount > 30) + ccount = 30; + fprintf (outfile, "\t%10s %10s %8s Class name\n", "Bytes", "Count", "Average"); + for (i = 0; i < ccount; ++i) { + HeapClassDesc *ocd = NULL; + cd = sorted [i]; + if (last_hs) + ocd = heap_class_lookup (last_hs, cd->klass); + fprintf (outfile, "\t%10llu %10llu %8llu %s", cd->total_size, cd->count, cd->total_size / cd->count, cd->klass->name); + if (ocd) { + int64_t bdiff = cd->total_size - ocd->total_size; + int64_t cdiff = cd->count - ocd->count; + fprintf (outfile, " (bytes: %+lld, count: %+lld)\n", bdiff, cdiff); + } else { + fprintf (outfile, "\n"); + } + } +} + +static void +dump_heap_shots (void) +{ + HeapShot *hs; + HeapShot *last_hs = NULL; + int i; + if (!heap_shots) + return; + fprintf (outfile, "\nHeap shot summary\n"); + i = 0; + for (hs = heap_shots; hs; hs = hs->next) { + heap_shot_summary (hs, i++, last_hs); + last_hs = hs; + } +} + +static void +flush_context (ProfContext *ctx) +{ + ThreadContext *thread; + /* FIXME: sometimes there are leftovers: indagate */ + for (thread = ctx->threads; thread; thread = thread->next) { + while (thread->stack_id) { + if (debug) + fprintf (outfile, "thread %p has %d items on stack\n", (void*)thread->thread_id, thread->stack_id); + pop_method (thread, thread->stack [thread->stack_id - 1], thread->last_time); + } + } +} + +static const char *reports = "header,gc,alloc,call,metadata,exception,monitor,thread,heapshot"; + +static const char* +match_option (const char *p, char *opt) +{ + int len = strlen (opt); + if (strncmp (p, opt, len) == 0) { + if (p [len] == ',') + len++; + return p + len; + } + return p; +} + +static int +print_reports (ProfContext *ctx, const char *reps, int parse_only) +{ + const char *opt; + const char *p; + for (p = reps; *p; p = opt) { + if ((opt = match_option (p, "header")) != p) { + if (!parse_only) + dump_header (ctx); + continue; + } + if ((opt = match_option (p, "thread")) != p) { + if (!parse_only) + dump_threads (ctx); + continue; + } + if ((opt = match_option (p, "gc")) != p) { + if (!parse_only) + dump_gcs (); + continue; + } + if ((opt = match_option (p, "alloc")) != p) { + if (!parse_only) + dump_allocations (); + continue; + } + if ((opt = match_option (p, "call")) != p) { + if (!parse_only) + dump_methods (); + continue; + } + if ((opt = match_option (p, "metadata")) != p) { + if (!parse_only) + dump_metadata (); + continue; + } + if ((opt = match_option (p, "exception")) != p) { + if (!parse_only) + dump_exceptions (); + continue; + } + if ((opt = match_option (p, "monitor")) != p) { + if (!parse_only) + dump_monitors (); + continue; + } + if ((opt = match_option (p, "heapshot")) != p) { + if (!parse_only) + dump_heap_shots (); + continue; + } + return 0; + } + return 1; +} + +static void +usage (void) +{ + // FIXME: add --find="FINDSPEC" + // obj=addr size=<>num type=name + printf ("Mono log profiler report version %d.%d\n", LOG_VERSION_MAJOR, LOG_VERSION_MINOR); + printf ("Usage: mprof-report [OPTIONS] FILENAME\n"); + printf ("FILENAME can be '-' to read from standard input.\n"); + printf ("Options:\n"); + printf ("\t--help display this help\n"); + printf ("\t--out=FILE write to FILE instead of stdout\n"); + printf ("\t--traces collect and show backtraces\n"); + printf ("\t--maxframes=NUM limit backtraces to NUM entries\n"); + printf ("\t--reports=R1[,R2...] print the specified reports. Defaults are:\n"); + printf ("\t %s\n", reports); + printf ("\t--method-sort=MODE sort methods according to MODE: total, self, calls\n"); + printf ("\t--alloc-sort=MODE sort allocations according to MODE: bytes, count\n"); + printf ("\t--track=OBJID track what happens to object OBJID\n"); + printf ("\t--thread=THREADID consider just the data for thread THREADID\n"); + printf ("\t--time=FROM-TO consider data FROM seconds from startup up to TO seconds\n"); + printf ("\t--verbose increase verbosity level\n"); + printf ("\t--debug display decoding debug info for mprof-report devs\n"); +} + +int +main (int argc, char *argv[]) +{ + ProfContext *ctx; + int i; + outfile = stdout; + for (i = 1; i < argc; ++i) { + if (strcmp ("--debug", argv [i]) == 0) { + debug++; + } else if (strcmp ("--help", argv [i]) == 0) { + usage (); + return 0; + } else if (strncmp ("--alloc-sort=", argv [i], 13) == 0) { + const char *val = argv [i] + 13; + if (strcmp (val, "bytes") == 0) { + alloc_sort_mode = ALLOC_SORT_BYTES; + } else if (strcmp (val, "count") == 0) { + alloc_sort_mode = ALLOC_SORT_COUNT; + } else { + usage (); + return 1; + } + } else if (strncmp ("--method-sort=", argv [i], 14) == 0) { + const char *val = argv [i] + 14; + if (strcmp (val, "total") == 0) { + method_sort_mode = METHOD_SORT_TOTAL; + } else if (strcmp (val, "self") == 0) { + method_sort_mode = METHOD_SORT_SELF; + } else if (strcmp (val, "calls") == 0) { + method_sort_mode = METHOD_SORT_CALLS; + } else { + usage (); + return 1; + } + } else if (strncmp ("--reports=", argv [i], 10) == 0) { + const char *val = argv [i] + 10; + if (!print_reports (NULL, val, 1)) { + usage (); + return 1; + } + reports = val; + } else if (strncmp ("--out=", argv [i], 6) == 0) { + const char *val = argv [i] + 6; + outfile = fopen (val, "w"); + if (!outfile) { + printf ("Cannot open output file: %s\n", val); + return 1; + } + } else if (strncmp ("--maxframes=", argv [i], 12) == 0) { + const char *val = argv [i] + 12; + char *vale; + trace_max = strtoul (val, &vale, 10); + } else if (strncmp ("--track=", argv [i], 8) == 0) { + const char *val = argv [i] + 8; + char *vale; + tracked_obj = strtoul (val, &vale, 0); + } else if (strncmp ("--thread=", argv [i], 9) == 0) { + const char *val = argv [i] + 9; + char *vale; + thread_filter = strtoul (val, &vale, 0); + } else if (strncmp ("--time=", argv [i], 7) == 0) { + char *val = pstrdup (argv [i] + 7); + double from_secs, to_secs; + char *top = strchr (val, '-'); + if (!top) { + usage (); + return 1; + } + *top++ = 0; + from_secs = atof (val); + to_secs = atof (top); + free (val); + if (from_secs > to_secs) { + usage (); + return 1; + } + time_from = from_secs * 1000000000; + time_to = to_secs * 1000000000; + } else if (strcmp ("--verbose", argv [i]) == 0) { + verbose++; + } else if (strcmp ("--traces", argv [i]) == 0) { + show_traces = 1; + collect_traces = 1; + } else { + break; + } + } + if (i >= argc) { + usage (); + return 2; + } + ctx = load_file (argv [i]); + if (!ctx) { + printf ("Not a log profiler data file (or unsupported version).\n"); + return 1; + } + while (decode_buffer (ctx)); + flush_context (ctx); + if (tracked_obj) + return 0; + print_reports (ctx, reports, 0); + return 0; +} + diff --git a/mono/profiler/log-profiler.txt b/mono/profiler/log-profiler.txt new file mode 100644 index 00000000000..b21d2588c3b --- /dev/null +++ b/mono/profiler/log-profiler.txt @@ -0,0 +1,331 @@ +# The Mono log profiler + +The Mono *log* profiler can be used to collect a lot of information about +a program running in the Mono runtime. This data can be used (both while the process +is running and later) to do analyses of the program behaviour, determine +resource usage, performance issues or even look for particular execution patterns. + +This is accomplished by logging the events provided by the Mono runtime through the +profiling interface and periodically writing them to a file which can be later +inspected with the command line *mprof-report* program or with a GUI (not developed yet). + +The events collected include (among others): + +* method enter and leave +* object allocation +* garbage collection +* JIT compilation +* metadata loading +* lock contention +* exceptions + +In addition, the profiler can periodically collect info about all the objects +present in the heap at the end of a garbage collection (this is called heap shot +and currently implemented only for the sgen garbage collector). + +## Basic profiler usage + +The simpler way to use the profiler is the following: + +`mono --profile=log program.exe` + +At the end of the execution the file *output.mlpd* will be found in the current +directory. A summary report of the data can be printed by running: + +`mprof-report output.mlpd` + +With this invocation a huge amount of data is collected about the program execution +and collecting and saving this data can significantly slow down program execution. +If saving the profiling data is not needed, a report can be generated directly with: + +`mono --profile=log:report program.exe` + +If the information about allocations is not of interest, it can be excluded: + +`mono --profile=log:noalloc program.exe` + +On the other hand, if method call timing is not important, while allocations are, +the needed info can be gathered with: + +`mono --profile=log:nocalls program.exe` + +You will still be able to inspect information about the sequence of calls that lead +to each allocation because at each object allocation a stack trace is collected as well. + +To periodically collect heap shots (and exclude method and allocation events) use the +following options (making sure you run with the sgen garbage collector): + +`mono --gc=sgen --profile=log:heapshot program.exe` + +## Profiler option documentation + +By default the *log* profiler will gather all the events provided by the Mono runtime +and write them to a file named *output.mlpd*. When no option is specified, it +is equivalent to using: + +`--profile=log:calls,alloc,output=output.mlpd,maxframes=8,calldepth=100` + +The following options can be used to modify this default behaviour. Each option +is separated from the next by a `,` character, with no spaces and all the options +are included after the *log:* profile module specifier. + +* *help*: display concise help info about each available option + +* *[no]alloc*: *noalloc* disables collecting object allocation info, *alloc* enables +it if it was disabled by another option like *heapshot*. + +* *[no]calls*: *nocalls* disables collecting method enter and leave events. When this +option is used at each object allocation and at some other events (like lock contentions +and exception throws) a stack trace is collected by default. See the *maxframes* option to +control this behaviour. *calls* enables method enter/leave events if they were disabled +by another option like *heapshot*. + +* *heapshot*: collect heap shot data at each major collection. The frequency of the +heap shots can be changed with the *hsmode* option below. When this option is used +allocation events and method enter/leave events are not recorded by default: if they +are needed, they need to be enabled explicitly. + +* *hsmode=MODE*: modify the default heap shot frequency according to MODE. +hsmode can be used multiple times with different modes: in that case a heap shot is +taken if either of the conditions are met. +MODE can be one of: + * *NUM*ms: perform a heap shot if at least *NUM* milliseconds passed since + the last one. + * *NUM*gc: perform a heap shot every *NUM* garbage collections (either + minor or major). + + +* *time=TIMER*: use the TIMER timestamp mode. TIMER can have the following values: + * *fast*: a usually faster but possibly more inaccurate timer + +* *maxframes=NUM*: when a stack trace needs to be performed, collect *NUM* frames +at the most. + +* *calldepth=NUM*: ignore method enter/leave events when the call chain depth is +bigger than NUM. + +* *zip*: automatically compress the output data in gzip format. + +* *output=OUTSPEC*: instead of writing the profiling data to the output.mlpd file, +do according to *OUTSPEC*: + * if *OUTSPEC* begins with a *|* character, execute the rest as a program + and feed the data to its standard input + * otherwise write the data the the named file + +* *report*: the profiling data is sent to mprof-report, which will print a summary +report. This is equivalent to the option: `output=mprof-report -`. + +## Analyzing the profile data + +Currently there is a command line program (*mprof-report*) to analyze the +data produced by the profiler. This is ran automatically when the *report* +profiler option is used. +Simply run: + +`mprof-report output.mlpd` + +to see a summary report of the data included in the file. + +### Trace information for events + +Often it is important for some events, like allocations, lock contention +and exception throws to know where they happened. Or we may want to see +what sequence of calls leads to a particular method invocation. To see this +info invoke mprof-report as follows: + +`mprof-report --traces output.mlpd` + +The maximum number of methods in each stack trace can be specified with the +*--maxframes=NUM* option: + +`mprof-report --traces --maxframes=4 output.mlpd` + +The stack trace info will be available if method enter/leave events have been +recorded or if stack trace collection wasn't explicitly disabled with the +*maxframes=0* option. + +### Sort order for methods and allocations + +When a list of methods is printed the default sort order is based on the total time +spent in the method. This time is wall clock time (that is, it includes the time +spent, for example, in a sleep call, even if actual cpu time would be basically 0). +Also, if the method has been ran on different threads, the time will be a sum +of the time used in each thread. + +To change the sort order, use the option: + +`--method-sort=MODE` + +where *MODE* can be: + +* *self*: amount of time spent in the method itself and not in its callees +* *calls*: the number of method invocations +* *total*: the total time spent in the method. + +Object allocation lists are sorted by default depending on the total amount +of bytes used by each type. + +To change the sort order of object allocations, use the option: + +`--alloc-sort=MODE` + +where *MODE* can be: + +* *count*: the number of allocated objects of the given type +* *bytes*: the total number of bytes used by objects of the given type + +### Selecting what data to report + +The profiler by default collects data about many runtime subsystems and mprof-report +prints a summary of all the subsystems that are found in the data file. It is possible +to tell mprof-report to only show information about some of them with the following +option: + +`--reports=R1[,R2...]` + +where the report names R1, R2 etc. can be: + +* *gc*: garbage collection information +* *alloc*: object allocation information +* *call*: method profiling information +* *metadata*: metadata events like image loads +* *exception*: exception throw and handling information +* *monitor*: lock contention information +* *thread*: thread information +* *heapshot*: live heap usage at heap shots + +It is possible to limit some of the data displayed to a timeframe of the +program execution with the option: + +`--time=FROM-TO` + +where *FROM* and *TO* are seconds since application startup (they can be +floating point numbers). + +Another interesting option is to consider only events happening on a particular +thread with the following option: + +`--thread=THREADID` + +where *THREADID* is one of the numbers listed in the thread summary report +(or a thread name when present). + +By default long lists of methods or other information like object allocations +are limited to the most important data. To increase the amount of information +printed you can use the option: + +`--verbose` + +### Saving a profiler report + +By default mprof-report will print the summary data to the console. +To print it to a file, instead, use the option: + +`--out=FILENAME` + +## Dealing with profiler slowness + +If the profiler needs to collect lots of data, the execution of the program will +slow down significantly, usually 10 to 20 times slower. There are several +ways to reduce the impact of the profiler on the program execution. + +### Collect less data + +Collecting method enter/leave events can be very expensive, especially in programs +that perform many millions of tiny calls. The profiler option *nocalls* can be +used to avoid collecting this data or it can be limited to only a few call levels +with the *calldepth* option. + +Object allocation information is expensive as well, though much less than +method enter/leave events. If it's not needed, it can be skipped with the +*noalloc* profiler option. Note that when method enter/leave events are +discarded, by default stack traces are collected at each allocation and this +can be expensive as well. The impact of stack trace information can be reduced +by setting a low value with the *maxframes* option or by eliminating them +completely, by setting it to 0. + +The other major source of data is the heapshot profiler option: especially +if the managed heap is big, since every object needs to be inspected. The *hsmode* +option can be used to reduce the frequency of the heap shots. + +### Reduce the timestamp overhead + +On many operating systems or architectures what actually slows down profiling +is the function provided by the system to get timestamp information. +The *time=fast* profiler option can be usually used to speed up this operation, +but, depending on the system, time accounting may have some level of approximation +(though statistically the data should be still fairly valuable). + +### Use a statistical profiler instead + +See the mono manpage for the use of a statistical (sampling) profiler. +The *log* profiler will be enhanced to provide sampling info in the future. + +## Dealing with the size of the data files + +When collecting a lot of information about a profiled program, huge data +files can be generated. There are a few ways to minimize the amount of data, +for example by not collecting some of the more space-consuming information +or by compressing the information on the fly or by just generating a summary +report. + +### Reducing the amount of data + +Method enter/leave events can be excluded completely with the *nocalls* option +or they can be limited to just a few levels of calls with the *calldepth* option. +For example, the option: + +`calldepth=10` + +will ignore the method events when there are more than 10 managed stack frames. +This is very useful for programs that have deep recursion or for programs that +perform many millions of tiny calls deep enough in the call stack. The optimal +number for the calldepth option depends on the program and it needs to be balanced +between providing enough profiling information and allowing fast execution speed. + +Note that by default, if method events are not recorded at all, the profiler will +collect stack trace information at events like allocations. To avoid gathering this +data, use the *maxframes=0* profiler option. + +Allocation events can be eliminated with the *noalloc* option. + +Heap shot data can also be huge: by default it is collected at each major collection. +To reduce the frequency, you can use the *hsmode* profiler option to collect for example +every 5 collections (including major and minor): + +`hsmode=5gc` + +or when at least 5 seconds passed since the last heap shot: + +`hsmode=5000ms` + +### Compressing the data + +To reduce the amout of disk space used by the data, the data can be compressed +either after it has been generated with the gzip command: + +`gzip -9 output.mlpd` + +or it can be compressed automatically by using the *zip* profiler option. Note +that in this case there could be a significant slowdown of the profiled program. + +The mprof-report program will tranparently deal with either compressed or +uncompressed data files. + +### Generating only a summary report + +Often it's enough to look at the profiler summary report to diagnose an issue and in this +case it's possible to avoid saving the profiler data file to disk. This can be +accomplished with the *report* profiler option, which will basically send the data +to the mprof-report program for display. + +To have more control of what summary information is reported (or to use a completely +different program to decode the profiler data), the *output* profiler option can be +used, with `|` as the first character: the rest of the output name will be +executed as a program with the data fed in on the standard input. + +For example, to print only the Monitor summary with stack trace information, you +could use it like this: + +`output=|mprof-report --reports=monitor --traces -` + diff --git a/mono/profiler/proflog.c b/mono/profiler/proflog.c new file mode 100644 index 00000000000..4bfac72351a --- /dev/null +++ b/mono/profiler/proflog.c @@ -0,0 +1,924 @@ +#include +#include +#include +#include +#include +#include +#include +#include + +#include "utils.h" +#include "proflog.h" + +#define BUFFER_SIZE (4096 * 16) +static int nocalls = 0; +static int notraces = 0; +static int use_zip = 0; +static int do_report = 0; +static int do_heap_shot = 0; +static int max_call_depth = 100; +static int runtime_inited = 0; + +/* Compile with: + * gcc -shared -o libmono-profiler-log.so proflog.c utils.c -Wall -g -lz `pkg-config --cflags --libs mono-2` + * and: + * gcc -o mprof-report decode.c utils.c -Wall -g -lz -lrt -lpthread `pkg-config --cflags mono-2` + * Install with: + * sudo cp mprof-report /usr/local/bin + * sudo cp libmono-profiler-log.so /usr/local/lib + * sudo ldconfig + */ + +typedef struct _LogBuffer LogBuffer; + +/* + * file format: [OBSOLETE] + * [header] [buffer]* + * each buffer contains events + * + * header format: + * [id: 4 bytes] [major: 1 byte] [minor: 1 byte] [length: 2 bytes] + * [time: 8 bytes] + * [bitness: 1 byte] + * [mono version: variable] + * [other data] + * + * buffer format: + * [bufid: 4 bytes] [len: 4 bytes] + * [time_base: 8 bytes] + * [ptr_base: 8 bytes] + * [obj_base: 8 bytes] + * [thread id: 8 bytes] + * + * event format: + * [extended type: 4 bits] [type: 4 bits] + * The data that follows depend on type. + * Time values are relative to the last time base of the buffer. + * + * type alloc format: + * [ptr: encoded] [class: encoded] [time: encoded] size? + * + * type enter/leave format: + * [method: encoded] [time: encoded] + * + */ +struct _LogBuffer { + LogBuffer *next; + uint64_t time_base; + uint64_t last_time; + uintptr_t ptr_base; + uintptr_t method_base; + uintptr_t last_method; + uintptr_t obj_base; + uintptr_t thread_id; + unsigned char* data_end; + unsigned char* data; + int size; + int call_depth; + unsigned char buf [1]; +}; + +struct _MonoProfiler { + LogBuffer *buffers; + FILE* file; + gzFile *gzfile; + int pipe_output; + int last_gc_gen_started; +}; + +static __thread LogBuffer* tlsbuffer = NULL; + +static LogBuffer* +create_buffer (void) +{ + LogBuffer* buf = alloc_buffer (BUFFER_SIZE); + buf->size = BUFFER_SIZE; + buf->time_base = current_time (); + buf->last_time = buf->time_base; + buf->data_end = (unsigned char*)buf + buf->size; + buf->data = buf->buf; + return buf; +} + +static void +init_thread (void) +{ + LogBuffer *logbuffer; + if (tlsbuffer) + return; + logbuffer = create_buffer (); + tlsbuffer = logbuffer; + logbuffer->thread_id = thread_id (); + /*printf ("thread %p at time %llu\n", (void*)logbuffer->thread_id, logbuffer->time_base);*/ +} + +static LogBuffer* +ensure_logbuf (int bytes) +{ + LogBuffer *old = tlsbuffer; + if (old && old->data + bytes + 100 < old->data_end) + return old; + tlsbuffer = NULL; + init_thread (); + tlsbuffer->next = old; + if (old) + tlsbuffer->call_depth = old->call_depth; + //printf ("new logbuffer\n"); + return tlsbuffer; +} + +static void +emit_byte (LogBuffer *logbuffer, int value) +{ + logbuffer->data [0] = value; + logbuffer->data++; + assert (logbuffer->data <= logbuffer->data_end); +} + +static void +emit_value (LogBuffer *logbuffer, int value) +{ + encode_uleb128 (value, logbuffer->data, &logbuffer->data); + assert (logbuffer->data <= logbuffer->data_end); +} + +static void +emit_time (LogBuffer *logbuffer, uint64_t value) +{ + uint64_t tdiff = value - logbuffer->last_time; + unsigned char *p; + if (value < logbuffer->last_time) + printf ("time went backwards\n"); + //if (tdiff > 1000000) + // printf ("large time offset: %llu\n", tdiff); + p = logbuffer->data; + encode_uleb128 (tdiff, logbuffer->data, &logbuffer->data); + /*if (tdiff != decode_uleb128 (p, &p)) + printf ("incorrect encoding: %llu\n", tdiff);*/ + logbuffer->last_time = value; + assert (logbuffer->data <= logbuffer->data_end); +} + +static void +emit_svalue (LogBuffer *logbuffer, int64_t value) +{ + encode_sleb128 (value, logbuffer->data, &logbuffer->data); + assert (logbuffer->data <= logbuffer->data_end); +} + +static void +emit_ptr (LogBuffer *logbuffer, void *ptr) +{ + if (!logbuffer->ptr_base) + logbuffer->ptr_base = (uintptr_t)ptr; + emit_svalue (logbuffer, (intptr_t)ptr - logbuffer->ptr_base); + assert (logbuffer->data <= logbuffer->data_end); +} + +static void +emit_method (LogBuffer *logbuffer, void *method) +{ + if (!logbuffer->method_base) { + logbuffer->method_base = (intptr_t)method; + logbuffer->last_method = (intptr_t)method; + } + encode_sleb128 ((intptr_t)((char*)method - (char*)logbuffer->last_method), logbuffer->data, &logbuffer->data); + logbuffer->last_method = (intptr_t)method; + assert (logbuffer->data <= logbuffer->data_end); +} + +static void +emit_obj (LogBuffer *logbuffer, void *ptr) +{ + if (!logbuffer->obj_base) + logbuffer->obj_base = (uintptr_t)ptr >> 3; + emit_svalue (logbuffer, ((uintptr_t)ptr >> 3) - logbuffer->obj_base); + assert (logbuffer->data <= logbuffer->data_end); +} + +static char* +write_int32 (char *buf, int32_t value) +{ + int i; + for (i = 0; i < 4; ++i) { + buf [i] = value; + value >>= 8; + } + return buf + 4; +} + +static char* +write_int64 (char *buf, int64_t value) +{ + int i; + for (i = 0; i < 8; ++i) { + buf [i] = value; + value >>= 8; + } + return buf + 8; +} + +static void +dump_header (MonoProfiler *profiler) +{ + char hbuf [128]; + char *p = hbuf; + p = write_int32 (p, LOG_HEADER_ID); + *p++ = LOG_VERSION_MAJOR; + *p++ = LOG_VERSION_MINOR; + *p++ = LOG_DATA_VERSION; + *p++ = sizeof (void*); + p = write_int64 (p, 0); /* startup time */ + p = write_int32 (p, 0); /* timer overhead */ + p = write_int32 (p, 0); /* flags */ + p = write_int32 (p, 0); /* pid */ + p = write_int32 (p, 0); /* opsystem */ + if (profiler->gzfile) { + gzwrite (profiler->gzfile, hbuf, p - hbuf); + } else { + fwrite (hbuf, p - hbuf, 1, profiler->file); + } +} + +static void +dump_buffer (MonoProfiler *profiler, LogBuffer *buf) +{ + char hbuf [128]; + char *p = hbuf; + if (buf->next) + dump_buffer (profiler, buf->next); + p = write_int32 (p, BUF_ID); + p = write_int32 (p, buf->data - buf->buf); + p = write_int64 (p, buf->time_base); + p = write_int64 (p, buf->ptr_base); + p = write_int64 (p, buf->obj_base); + p = write_int64 (p, buf->thread_id); + p = write_int64 (p, buf->method_base); + if (profiler->gzfile) { + gzwrite (profiler->gzfile, hbuf, p - hbuf); + gzwrite (profiler->gzfile, buf->buf, buf->data - buf->buf); + } else { + fwrite (hbuf, p - hbuf, 1, profiler->file); + fwrite (buf->buf, buf->data - buf->buf, 1, profiler->file); + } + free_buffer (buf, buf->size); +} + +static void +runtime_initialized (MonoProfiler *profiler) +{ + runtime_inited = 1; +} + +/* + * Can be called only at safe callback locations. + */ +static void +safe_dump (MonoProfiler *profiler, LogBuffer *logbuffer) +{ + int cd = logbuffer->call_depth; + take_lock (); + dump_buffer (profiler, tlsbuffer); + release_lock (); + tlsbuffer = NULL; + init_thread (); + tlsbuffer->call_depth = cd; +} + +static int +gc_reference (MonoObject *obj, MonoClass *klass, uintptr_t size, uintptr_t num, MonoObject **refs, void *data) +{ + int i; + //const char *name = mono_class_get_name (klass); + LogBuffer *logbuffer = ensure_logbuf (20 + num * 8); + emit_byte (logbuffer, TYPE_HEAP_OBJECT | TYPE_HEAP); + emit_obj (logbuffer, obj); + emit_ptr (logbuffer, klass); + emit_value (logbuffer, size); + emit_value (logbuffer, num); + for (i = 0; i < num; ++i) + emit_obj (logbuffer, refs [i]); + //if (num) + // printf ("obj: %p, klass: %s, refs: %d, size: %d\n", obj, name, (int)num, (int)size); + return 0; +} + +static unsigned int hs_mode_ms = 0; +static unsigned int hs_mode_gc = 0; +static unsigned int gc_count = 0; +static uint64_t last_hs_time = 0; + +static void +heap_walk (MonoProfiler *profiler) +{ + int do_walk = 0; + uint64_t now; + LogBuffer *logbuffer; + if (!do_heap_shot) + return; + logbuffer = ensure_logbuf (10); + now = current_time (); + if (hs_mode_ms && (now - last_hs_time)/1000000 >= hs_mode_ms) + do_walk = 1; + else if (hs_mode_gc && (gc_count % hs_mode_gc) == 0) + do_walk = 1; + else if (!hs_mode_ms && !hs_mode_gc && profiler->last_gc_gen_started == mono_gc_max_generation ()) + do_walk = 1; + + if (!do_walk) + return; + emit_byte (logbuffer, TYPE_HEAP_START | TYPE_HEAP); + emit_time (logbuffer, now); + mono_gc_walk_heap (0, gc_reference, NULL); + logbuffer = ensure_logbuf (10); + now = current_time (); + emit_byte (logbuffer, TYPE_HEAP_END | TYPE_HEAP); + emit_time (logbuffer, now); +} + +static void +gc_event (MonoProfiler *profiler, MonoGCEvent ev, int generation) { + uint64_t now; + LogBuffer *logbuffer = ensure_logbuf (10); + now = current_time (); + emit_byte (logbuffer, TYPE_GC_EVENT | TYPE_GC); + emit_time (logbuffer, now); + emit_value (logbuffer, ev); + emit_value (logbuffer, generation); + /* to deal with nested gen1 after gen0 started */ + if (ev == MONO_GC_EVENT_START) { + profiler->last_gc_gen_started = generation; + gc_count++; + } + if (ev == MONO_GC_EVENT_PRE_START_WORLD) + heap_walk (profiler); + if (ev == MONO_GC_EVENT_POST_START_WORLD) + safe_dump (profiler, logbuffer); + //printf ("gc event %d for generation %d\n", ev, generation); +} + +static void +gc_resize (MonoProfiler *profiler, int64_t new_size) { + uint64_t now; + LogBuffer *logbuffer = ensure_logbuf (10); + now = current_time (); + emit_byte (logbuffer, TYPE_GC_RESIZE | TYPE_GC); + emit_time (logbuffer, now); + emit_value (logbuffer, new_size); + //printf ("gc resized to %lld\n", new_size); +} + +#define MAX_FRAMES 16 +typedef struct { + int count; + MonoMethod* methods [MAX_FRAMES]; +} FrameData; +static int num_frames = MAX_FRAMES / 2; + +static mono_bool +walk_stack (MonoMethod *method, int32_t native_offset, int32_t il_offset, mono_bool managed, void* data) +{ + FrameData *frame = data; + if (method && frame->count < num_frames) { + frame->methods [frame->count++] = method; + //printf ("In %d %s\n", frame->count, mono_method_get_name (method)); + } + return frame->count == num_frames; +} + +/* + * a note about stack walks: they can cause more profiler events to fire, + * so we need to make sure they don't happen after we started emitting an + * event, hence the collect_bt/emit_bt split. + */ +static void +collect_bt (FrameData *data) +{ + data->count = 0; + mono_stack_walk_no_il (walk_stack, data); +} + +static void +emit_bt (LogBuffer *logbuffer, FrameData *data) +{ + /* FIXME: this is actually tons of data and we should + * just output it the first time and use an id the next + */ + if (data->count > num_frames) + printf ("bad num frames: %d\n", data->count); + emit_value (logbuffer, 0); /* flags */ + emit_value (logbuffer, data->count); + //if (*p != data.count) { + // printf ("bad num frames enc at %d: %d -> %d\n", count, data.count, *p); printf ("frames end: %p->%p\n", p, logbuffer->data); exit(0);} + while (data->count) { + emit_ptr (logbuffer, data->methods [--data->count]); + } +} + +static void +gc_alloc (MonoProfiler *prof, MonoObject *obj, MonoClass *klass) +{ + uint64_t now; + uintptr_t len; + int do_bt = (nocalls && runtime_inited && !notraces)? TYPE_ALLOC_BT: 0; + FrameData data; + LogBuffer *logbuffer; + len = mono_object_get_size (obj); + if (do_bt) + collect_bt (&data); + logbuffer = ensure_logbuf (32 + MAX_FRAMES * 8); + now = current_time (); + emit_byte (logbuffer, do_bt | TYPE_ALLOC); + emit_time (logbuffer, now); + emit_ptr (logbuffer, klass); + emit_obj (logbuffer, obj); + emit_value (logbuffer, len); + if (do_bt) + emit_bt (logbuffer, &data); + if (logbuffer->next) + safe_dump (prof, logbuffer); + //printf ("gc alloc %s at %p\n", mono_class_get_name (klass), obj); +} + +static void +gc_moves (MonoProfiler *prof, void **objects, int num) +{ + int i; + uint64_t now; + LogBuffer *logbuffer = ensure_logbuf (10 + num * 8); + now = current_time (); + emit_byte (logbuffer, TYPE_GC_MOVE | TYPE_GC); + emit_time (logbuffer, now); + emit_value (logbuffer, num); + for (i = 0; i < num; ++i) + emit_obj (logbuffer, objects [i]); + //printf ("gc moved %d objects\n", num/2); +} + +static char* +push_nesting (char *p, MonoClass *klass) +{ + MonoClass *nesting; + const char *name; + const char *nspace; + nesting = mono_class_get_nesting_type (klass); + if (nesting) { + p = push_nesting (p, nesting); + *p++ = '/'; + *p = 0; + } + name = mono_class_get_name (klass); + nspace = mono_class_get_namespace (klass); + if (*nspace) { + strcpy (p, nspace); + p += strlen (nspace); + *p++ = '.'; + *p = 0; + } + strcpy (p, name); + p += strlen (name); + return p; +} + +static char* +type_name (MonoClass *klass) +{ + char buf [1024]; + char *p; + push_nesting (buf, klass); + p = malloc (strlen (buf) + 1); + strcpy (p, buf); + return p; +} + +static void +image_loaded (MonoProfiler *prof, MonoImage *image, int result) +{ + uint64_t now; + const char *name; + int nlen; + LogBuffer *logbuffer; + if (result != MONO_PROFILE_OK) + return; + name = mono_image_get_filename (image); + nlen = strlen (name) + 1; + logbuffer = ensure_logbuf (16 + nlen); + now = current_time (); + emit_byte (logbuffer, TYPE_END_LOAD | TYPE_METADATA); + emit_time (logbuffer, now); + emit_byte (logbuffer, TYPE_IMAGE); + emit_ptr (logbuffer, image); + emit_value (logbuffer, 0); /* flags */ + memcpy (logbuffer->data, name, nlen); + logbuffer->data += nlen; + //printf ("loaded image %p (%s)\n", image, name); + if (logbuffer->next) + safe_dump (prof, logbuffer); +} + +static void +class_loaded (MonoProfiler *prof, MonoClass *klass, int result) +{ + uint64_t now; + char *name; + int nlen; + MonoImage *image; + LogBuffer *logbuffer; + if (result != MONO_PROFILE_OK) + return; + if (runtime_inited) + name = mono_type_get_name (mono_class_get_type (klass)); + else + name = type_name (klass); + nlen = strlen (name) + 1; + image = mono_class_get_image (klass); + logbuffer = ensure_logbuf (24 + nlen); + now = current_time (); + emit_byte (logbuffer, TYPE_END_LOAD | TYPE_METADATA); + emit_time (logbuffer, now); + emit_byte (logbuffer, TYPE_CLASS); + emit_ptr (logbuffer, klass); + emit_ptr (logbuffer, image); + emit_value (logbuffer, 0); /* flags */ + memcpy (logbuffer->data, name, nlen); + logbuffer->data += nlen; + //printf ("loaded class %p (%s)\n", klass, name); + if (runtime_inited) + mono_free (name); + else + free (name); + if (logbuffer->next) + safe_dump (prof, logbuffer); +} + +static void +method_enter (MonoProfiler *prof, MonoMethod *method) +{ + uint64_t now; + LogBuffer *logbuffer = ensure_logbuf (16); + if (logbuffer->call_depth++ > max_call_depth) + return; + now = current_time (); + emit_byte (logbuffer, TYPE_ENTER | TYPE_METHOD); + emit_time (logbuffer, now); + emit_method (logbuffer, method); +} + +static void +method_leave (MonoProfiler *prof, MonoMethod *method) +{ + uint64_t now; + LogBuffer *logbuffer = ensure_logbuf (16); + if (--logbuffer->call_depth > max_call_depth) + return; + now = current_time (); + emit_byte (logbuffer, TYPE_LEAVE | TYPE_METHOD); + emit_time (logbuffer, now); + emit_method (logbuffer, method); + if (logbuffer->next) + safe_dump (prof, logbuffer); +} + +static void +method_exc_leave (MonoProfiler *prof, MonoMethod *method) +{ + uint64_t now; + LogBuffer *logbuffer; + if (nocalls) + return; + logbuffer = ensure_logbuf (16); + if (--logbuffer->call_depth > max_call_depth) + return; + now = current_time (); + emit_byte (logbuffer, TYPE_EXC_LEAVE | TYPE_METHOD); + emit_time (logbuffer, now); + emit_method (logbuffer, method); +} + +static void +method_jitted (MonoProfiler *prof, MonoMethod *method, MonoJitInfo* jinfo, int result) +{ + uint64_t now; + char *name; + int nlen; + LogBuffer *logbuffer; + if (result != MONO_PROFILE_OK) + return; + name = mono_method_full_name (method, 1); + nlen = strlen (name) + 1; + logbuffer = ensure_logbuf (32 + nlen); + now = current_time (); + emit_byte (logbuffer, TYPE_JIT | TYPE_METHOD); + emit_time (logbuffer, now); + emit_method (logbuffer, method); + emit_ptr (logbuffer, mono_jit_info_get_code_start (jinfo)); + emit_value (logbuffer, mono_jit_info_get_code_size (jinfo)); + memcpy (logbuffer->data, name, nlen); + logbuffer->data += nlen; + mono_free (name); + if (logbuffer->next) + safe_dump (prof, logbuffer); +} + +static void +throw_exc (MonoProfiler *prof, MonoObject *object) +{ + int do_bt = (nocalls && runtime_inited && !notraces)? TYPE_EXCEPTION_BT: 0; + uint64_t now; + FrameData data; + LogBuffer *logbuffer; + if (do_bt) + collect_bt (&data); + logbuffer = ensure_logbuf (16 + MAX_FRAMES * 8); + now = current_time (); + emit_byte (logbuffer, do_bt | TYPE_EXCEPTION); + emit_time (logbuffer, now); + emit_obj (logbuffer, object); + if (do_bt) + emit_bt (logbuffer, &data); +} + +static void +clause_exc (MonoProfiler *prof, MonoMethod *method, int clause_type, int clause_num) +{ + uint64_t now; + LogBuffer *logbuffer = ensure_logbuf (16); + now = current_time (); + emit_byte (logbuffer, TYPE_EXCEPTION | TYPE_CLAUSE); + emit_time (logbuffer, now); + emit_value (logbuffer, clause_type); + emit_value (logbuffer, clause_num); + emit_method (logbuffer, method); +} + +static void +monitor_event (MonoProfiler *profiler, MonoObject *object, MonoProfilerMonitorEvent event) +{ + int do_bt = (nocalls && runtime_inited && !notraces && event == MONO_PROFILER_MONITOR_CONTENTION)? TYPE_MONITOR_BT: 0; + uint64_t now; + FrameData data; + LogBuffer *logbuffer; + if (do_bt) + collect_bt (&data); + logbuffer = ensure_logbuf (16 + MAX_FRAMES * 8); + now = current_time (); + emit_byte (logbuffer, (event << 4) | do_bt | TYPE_MONITOR); + emit_time (logbuffer, now); + emit_obj (logbuffer, object); + if (do_bt) + emit_bt (logbuffer, &data); +} + +static void +thread_start (MonoProfiler *prof, uintptr_t tid) +{ + //printf ("thread start %p\n", (void*)tid); + init_thread (); +} + +static void +thread_end (MonoProfiler *prof, uintptr_t tid) +{ + take_lock (); + if (tlsbuffer) + dump_buffer (prof, tlsbuffer); + release_lock (); + tlsbuffer = NULL; +} + +static void +log_shutdown (MonoProfiler *prof) +{ + take_lock (); + if (tlsbuffer) + dump_buffer (prof, tlsbuffer); + tlsbuffer = NULL; + release_lock (); + if (prof->gzfile) + gzclose (prof->gzfile); + if (prof->pipe_output) + pclose (prof->file); + else + fclose (prof->file); + free (prof); +} + +static MonoProfiler* +create_profiler (char *filename) +{ + MonoProfiler *prof; + prof = calloc (1, sizeof (MonoProfiler)); + if (do_report) /* FIXME: use filename as output */ + filename = "|mprof-report -"; + + if (!filename) + filename = "output.mlpd"; + if (*filename == '|') { + prof->file = popen (filename + 1, "w"); + prof->pipe_output = 1; + } else { + prof->file = fopen (filename, "wb"); + } + if (!prof->file) { + printf ("Cannot create profiler output: %s\n", filename); + exit (1); + } + if (use_zip) + prof->gzfile = gzdopen (fileno (prof->file), "wb"); + dump_header (prof); + return prof; +} + +static void +usage (int do_exit) +{ + printf ("Log profiler version %d.%d (format: %d)\n", LOG_VERSION_MAJOR, LOG_VERSION_MINOR, LOG_DATA_VERSION); + printf ("Usage: mono --profile=log[:OPTION1[,OPTION2...]] program.exe\n"); + printf ("Options:\n"); + printf ("\thelp show this usage info\n"); + printf ("\t[no]alloc enable/disable recording allocation info\n"); + printf ("\t[no]calls enable/disable recording enter/leave method events\n"); + printf ("\theapshot record heap shot info (by default at each major collection)\n"); + printf ("\thsmode=MODE heapshot mode: every XXms milliseconds or every YYgc collections\n"); + printf ("\ttime=fast use a faster (but more inaccurate) timer\n"); + printf ("\tmaxframes=NUM collect up to NUM stack frames\n"); + printf ("\tcalldepth=NUM ignore method events for call chain depth bigger than NUM\n"); + printf ("\toutput=FILENAME write the data to file FILENAME\n"); + printf ("\toutput=|PROGRAM write the data to the stdin of PROGRAM\n"); + printf ("\treport create a report instead of writing the raw data to a file\n"); + printf ("\tzip compress the output data\n"); + if (do_exit) + exit (1); +} + +const char* +match_option (const char* p, const char *opt, char **rval) +{ + int len = strlen (opt); + if (strncmp (p, opt, len) == 0) { + if (rval) { + if (p [len] == '=' && p [len + 1]) { + const char *opt = p + len + 1; + const char *end = strchr (opt, ','); + char *val; + int l; + if (end == NULL) { + l = strlen (opt); + } else { + l = end - opt; + } + val = malloc (l + 1); + memcpy (val, opt, l); + val [l] = 0; + *rval = val; + return opt + l; + } + usage (1); + } else { + if (p [len] == 0) + return p + len; + if (p [len] == ',') + return p + len + 1; + } + } + return p; +} + +void +mono_profiler_startup (const char *desc) +{ + MonoProfiler *prof; + char *filename = NULL; + const char *p; + const char *opt; + int fast_time = 0; + int calls_enabled = 0; + int allocs_enabled = 0; + int events = MONO_PROFILE_GC|MONO_PROFILE_ALLOCATIONS| + MONO_PROFILE_GC_MOVES|MONO_PROFILE_CLASS_EVENTS|MONO_PROFILE_THREADS| + MONO_PROFILE_ENTER_LEAVE|MONO_PROFILE_JIT_COMPILATION|MONO_PROFILE_EXCEPTIONS| + MONO_PROFILE_MONITOR_EVENTS|MONO_PROFILE_MODULE_EVENTS; + + p = desc; + if (strncmp (p, "log", 3)) + usage (1); + p += 3; + if (*p == ':') + p++; + for (; *p; p = opt) { + char *val; + if (*p == ',') { + opt = p + 1; + continue; + } + if ((opt = match_option (p, "help", NULL)) != p) { + usage (0); + continue; + } + if ((opt = match_option (p, "calls", NULL)) != p) { + calls_enabled = 1; + continue; + } + if ((opt = match_option (p, "nocalls", NULL)) != p) { + events &= ~MONO_PROFILE_ENTER_LEAVE; + nocalls = 1; + continue; + } + if ((opt = match_option (p, "alloc", NULL)) != p) { + allocs_enabled = 1; + continue; + } + if ((opt = match_option (p, "noalloc", NULL)) != p) { + events &= ~MONO_PROFILE_ALLOCATIONS; + continue; + } + if ((opt = match_option (p, "time", &val)) != p) { + if (strcmp (val, "fast") == 0) + fast_time = 1; + else if (strcmp (val, "null") == 0) + fast_time = 2; + else + usage (1); + free (val); + continue; + } + if ((opt = match_option (p, "report", NULL)) != p) { + do_report = 1; + continue; + } + if ((opt = match_option (p, "heapshot", NULL)) != p) { + events &= ~MONO_PROFILE_ALLOCATIONS; + events &= ~MONO_PROFILE_ENTER_LEAVE; + nocalls = 1; + do_heap_shot = 1; + continue; + } + if ((opt = match_option (p, "hsmode", &val)) != p) { + char *end; + unsigned int count = strtoul (val, &end, 10); + if (val == end) + usage (1); + if (strcmp (end, "ms") == 0) + hs_mode_ms = count; + else if (strcmp (end, "gc") == 0) + hs_mode_gc = count; + else + usage (1); + free (val); + continue; + } + if ((opt = match_option (p, "zip", NULL)) != p) { + use_zip = 1; + continue; + } + if ((opt = match_option (p, "output", &val)) != p) { + filename = val; + continue; + } + if ((opt = match_option (p, "maxframes", &val)) != p) { + char *end; + num_frames = strtoul (val, &end, 10); + if (num_frames > MAX_FRAMES) + num_frames = MAX_FRAMES; + free (val); + notraces = num_frames == 0; + continue; + } + if ((opt = match_option (p, "calldepth", &val)) != p) { + char *end; + max_call_depth = strtoul (val, &end, 10); + free (val); + continue; + } + if (opt == p) { + usage (0); + exit (0); + } + } + if (calls_enabled) { + events |= MONO_PROFILE_ENTER_LEAVE; + nocalls = 0; + } + if (allocs_enabled) + events |= MONO_PROFILE_ALLOCATIONS; + utils_init (fast_time); + + prof = create_profiler (filename); + init_thread (); + + mono_profiler_install (prof, log_shutdown); + mono_profiler_install_gc (gc_event, gc_resize); + mono_profiler_install_allocation (gc_alloc); + mono_profiler_install_gc_moves (gc_moves); + mono_profiler_install_class (NULL, class_loaded, NULL, NULL); + mono_profiler_install_module (NULL, image_loaded, NULL, NULL); + mono_profiler_install_thread (thread_start, thread_end); + mono_profiler_install_enter_leave (method_enter, method_leave); + mono_profiler_install_jit_end (method_jitted); + mono_profiler_install_exception (throw_exc, method_exc_leave, clause_exc); + mono_profiler_install_monitor (monitor_event); + mono_profiler_install_runtime_initialized (runtime_initialized); + + mono_profiler_set_events (events); +} + diff --git a/mono/profiler/proflog.h b/mono/profiler/proflog.h new file mode 100644 index 00000000000..11de752836a --- /dev/null +++ b/mono/profiler/proflog.h @@ -0,0 +1,53 @@ +#ifndef __MONO_PROFLOG_H__ +#define __MONO_PROFLOG_H__ + +#define BUF_ID 0x4D504C01 +#define LOG_HEADER_ID 0x4D505A01 +#define LOG_VERSION_MAJOR 0 +#define LOG_VERSION_MINOR 1 +#define LOG_DATA_VERSION 1 + +enum { + TYPE_ALLOC, + TYPE_GC, + TYPE_METADATA, + TYPE_METHOD, + TYPE_EXCEPTION, + TYPE_MONITOR, + TYPE_HEAP, + TYPE_EXTENDED, + /* extended type for TYPE_HEAP */ + TYPE_HEAP_START = 0 << 4, + TYPE_HEAP_END = 1 << 4, + TYPE_HEAP_OBJECT = 2 << 4, + /* extended type for TYPE_METADATA */ + TYPE_START_LOAD = 1 << 4, + TYPE_END_LOAD = 2 << 4, + TYPE_START_UNLOAD = 3 << 4, + TYPE_END_UNLOAD = 4 << 4, + TYPE_LOAD_ERR = 1 << 7, + TYPE_CLASS = 1, + TYPE_IMAGE = 2, + TYPE_ASSEMBLY = 3, + TYPE_DOMAIN = 4, + /* extended type for TYPE_GC */ + TYPE_GC_EVENT = 1 << 4, + TYPE_GC_RESIZE = 2 << 4, + TYPE_GC_MOVE = 3 << 4, + /* extended type for TYPE_METHOD */ + TYPE_LEAVE = 1 << 4, + TYPE_ENTER = 2 << 4, + TYPE_EXC_LEAVE = 3 << 4, + TYPE_JIT = 4 << 4, + /* extended type for TYPE_EXCEPTION */ + TYPE_CLAUSE = 1 << 4, + TYPE_EXCEPTION_BT = 1 << 7, + /* extended type for TYPE_ALLOC */ + TYPE_ALLOC_BT = 1 << 4, + /* extended type for TYPE_MONITOR */ + TYPE_MONITOR_BT = 1 << 7, + TYPE_END +}; + +#endif /* __MONO_PROFLOG_H__ */ + diff --git a/mono/profiler/utils.c b/mono/profiler/utils.c new file mode 100644 index 00000000000..9ad33f8df43 --- /dev/null +++ b/mono/profiler/utils.c @@ -0,0 +1,296 @@ +#include +#include +#include +#include +#include +#include +#include + +#include "utils.h" + +//#ifdef HAVE_SYS_TIME_H +#include +//#endif +//#if HAVE_SYS_MMAN_H +#include +//#endif + +#define TICKS_PER_SEC 1000000000LL + +typedef struct { + unsigned int timer_count; + int last_cpu; + uint64_t last_rdtsc; + uint64_t last_time; +} TlsData; + +static __thread TlsData tls_data; +#define DECL_TLS_DATA TlsData *tls = &tls_data + +static pthread_mutex_t log_lock = PTHREAD_MUTEX_INITIALIZER; + +static uint64_t time_inc = 0; +typedef uint64_t (*TimeFunc)(void); + +static TimeFunc time_func; + +static uint64_t +clock_time (void) +{ + struct timespec tspec; + clock_gettime (CLOCK_MONOTONIC, &tspec); + return ((uint64_t)tspec.tv_sec * TICKS_PER_SEC + tspec.tv_nsec); +} + +/* must be power of two */ +#define TIME_ADJ 8 + +static uint64_t +fast_current_time (void) +{ + DECL_TLS_DATA; + if (tls->timer_count++ & (TIME_ADJ - 1)) { + tls->last_time += time_inc; + return tls->last_time; + } + tls->last_time = clock_time (); + return tls->last_time; +} + +#define rdtsc(low,high) \ + __asm__ __volatile__("rdtsc" : "=a" (low), "=d" (high)) + +static uint64_t +safe_rdtsc (int *cpu) +{ + unsigned int low, high; + int c1 = sched_getcpu (); + int c2; + rdtsc (low, high); + c2 = sched_getcpu (); + if (c1 != c2) { + *cpu = -1; + return 0; + } + *cpu = c1; + return (((uint64_t) high) << 32) + (uint64_t)low; +} + +static double cpu_freq; + +static int +have_rdtsc (void) { + char buf[256]; + int have_freq = 0; + int have_flag = 0; + float val; + FILE *cpuinfo; + + if (!(cpuinfo = fopen ("/proc/cpuinfo", "r"))) + return 0; + while (fgets (buf, sizeof(buf), cpuinfo)) { + if (sscanf (buf, "cpu MHz : %f", &val) == 1) { + /*printf ("got mh: %f\n", val);*/ + have_freq = 1; + cpu_freq = val * 1000000; + } + if (strncmp (buf, "flags :", 5) == 0) { + if (strstr (buf, "constant_tsc")) { + have_flag = 1; + /*printf ("have tsc\n");*/ + } + } + } + fclose (cpuinfo); + return have_flag? have_freq: 0; +} + +static uint64_t +rdtsc_current_time (void) +{ + DECL_TLS_DATA; + if (tls->timer_count++ & (TIME_ADJ*8 - 1)) { + int cpu; + uint64_t tsc = safe_rdtsc (&cpu); + if (cpu != -1 && cpu == tls->last_cpu) { + int64_t diff = tsc - tls->last_rdtsc; + uint64_t nsecs; + if (diff > 0) { + nsecs = (double)diff/cpu_freq; + //printf ("%llu cycles: %llu nsecs\n", diff, nsecs); + return tls->last_time + nsecs; + } else { + printf ("tsc went backwards\n"); + } + } else { + //printf ("wrong cpu: %d\n", cpu); + } + } + tls->last_time = clock_time (); + tls->last_rdtsc = safe_rdtsc (&tls->last_cpu); + return tls->last_time; +} + +static uint64_t +null_time (void) +{ + static uint64_t timer = 0; + return timer++; +} + +void +utils_init (int fast_time) +{ + if (fast_time > 1) { + time_func = null_time; + } else if (fast_time) { + uint64_t timea; + uint64_t timeb; + int cpu = sched_getcpu (); + clock_time (); + timea = clock_time (); + timeb = clock_time (); + time_inc = (timeb - timea) / TIME_ADJ; + /*printf ("time inc: %llu, timea: %llu, timeb: %llu, diff: %llu\n", time_inc, timea, timeb, timec-timeb);*/ + if (cpu != -1 && have_rdtsc ()) + time_func = rdtsc_current_time; + else + time_func = fast_current_time; + } else { + time_func = clock_time; + } +} + +uint64_t +current_time (void) +{ + return time_func (); +} + +void* +alloc_buffer (int size) +{ + void *ptr; + ptr = mmap (NULL, size, PROT_READ|PROT_WRITE, MAP_ANONYMOUS|MAP_PRIVATE, -1, 0); + if (ptr == (void*)-1) + return NULL; + return ptr; +} + +void +free_buffer (void *buf, int size) +{ + munmap (buf, size); +} + +void +take_lock (void) +{ + pthread_mutex_lock (&log_lock); +} + +void +release_lock (void) +{ + pthread_mutex_unlock (&log_lock); +} + +void +encode_uleb128 (uint64_t value, uint8_t *buf, uint8_t **endbuf) +{ + uint8_t *p = buf; + + do { + uint8_t b = value & 0x7f; + value >>= 7; + if (value != 0) /* more bytes to come */ + b |= 0x80; + *p ++ = b; + } while (value); + + *endbuf = p; +} + +/* FIXME: make sure this works for 64 bit systems/values */ +void +encode_sleb128 (intptr_t value, uint8_t *buf, uint8_t **endbuf) +{ + int more = 1; + int negative = (value < 0); + unsigned int size = 32; + uint8_t byte; + uint8_t *p = buf; + + while (more) { + byte = value & 0x7f; + value >>= 7; + /* the following is unnecessary if the + * implementation of >>= uses an arithmetic rather + * than logical shift for a signed left operand + */ + if (negative) + /* sign extend */ + value |= - (1 <<(size - 7)); + /* sign bit of byte is second high order bit (0x40) */ + if ((value == 0 && !(byte & 0x40)) || + (value == -1 && (byte & 0x40))) + more = 0; + else + byte |= 0x80; + *p ++= byte; + } + + *endbuf = p; +} + +uint64_t +decode_uleb128 (uint8_t *buf, uint8_t **endbuf) +{ + uint64_t res = 0; + int shift = 0; + + while (1) { + uint8_t b = *buf++; + + res |= (((uint64_t)(b & 0x7f)) << shift); + if (!(b & 0x80)) + break; + shift += 7; + } + + *endbuf = buf; + + return res; +} + +intptr_t +decode_sleb128 (uint8_t *buf, uint8_t **endbuf) +{ + uint8_t *p = buf; + intptr_t res = 0; + int shift = 0; + + while (1) { + uint8_t b = *p; + p ++; + + res = res | (((int)(b & 0x7f)) << shift); + shift += 7; + if (!(b & 0x80)) { + if (shift < 32 && (b & 0x40)) + res |= - (1 << shift); + break; + } + } + + *endbuf = p; + + return res; +} + +uintptr_t +thread_id (void) +{ + return (uintptr_t)pthread_self (); +} + diff --git a/mono/profiler/utils.h b/mono/profiler/utils.h new file mode 100644 index 00000000000..b59072b4e9e --- /dev/null +++ b/mono/profiler/utils.h @@ -0,0 +1,21 @@ +#ifndef __MONO_MPLOG_UTILS_H__ +#define __MONO_MPLOG_UTILS_H__ + +#include + +void utils_init (int fast_time); +uint64_t current_time (void); +void* alloc_buffer (int size); +void free_buffer (void *buf, int size); +void take_lock (void); +void release_lock (void); +uintptr_t thread_id (void); + +void encode_uleb128 (uint64_t value, uint8_t *buf, uint8_t **endbuf); +void encode_sleb128 (intptr_t value, uint8_t *buf, uint8_t **endbuf); +uint64_t decode_uleb128 (uint8_t *buf, uint8_t **endbuf); +intptr_t decode_sleb128 (uint8_t *buf, uint8_t **endbuf); + + +#endif /* __MONO_MPLOG_UTILS_H__ */ + -- 2.25.1