mono/profiler/proflog.c

   1 #include <mono/metadata/profiler.h>
   2 #include <mono/metadata/mono-gc.h>
   3 #include <mono/metadata/debug-helpers.h>
   4 #include <stdlib.h>
   5 #include <inttypes.h>
   6 #include <string.h>
   7 #include <zlib.h>
   8 #include <assert.h>
   9 #include <pthread.h>
  10
  11 #include "utils.h"
  12 #include "proflog.h"
  13
  14 #define BUFFER_SIZE (4096 * 16)
  15 static int nocalls = 0;
  16 static int notraces = 0;
  17 static int use_zip = 0;
  18 static int do_report = 0;
  19 static int do_heap_shot = 0;
  20 static int max_call_depth = 100;
  21 static int runtime_inited = 0;
  22
  23 /* For linux compile with:
  24  * gcc -fPIC -shared -o libmono-profiler-log.so proflog.c utils.c -Wall -g -lz `pkg-config --cflags --libs mono-2`
  25  * gcc -o mprof-report decode.c utils.c -Wall -g -lz -lrt -lpthread `pkg-config --cflags mono-2`
  26  *
  27  * For osx compile with:
  28  * gcc -m32 -Dmono_free=free shared -o libmono-profiler-log.dylib proflog.c utils.c -Wall -g -lz `pkg-config --cflags mono-2` -undefined suppress -flat_namespace
  29  * gcc -m32 -o mprof-report decode.c utils.c -Wall -g -lz -lrt -lpthread `pkg-config --cflags mono-2`
  30  *
  31  * Install with:
  32  * sudo cp mprof-report /usr/local/bin
  33  * sudo cp libmono-profiler-log.so /usr/local/lib
  34  * sudo ldconfig
  35  */
  36
  37 typedef struct _LogBuffer LogBuffer;
  38
  39 /*
  40  * file format:
  41  * [header] [buffer]*
  42  *
  43  * The file is composed by a header followed by 0 or more buffers.
  44  * Each buffer contains events that happened on a thread: for a given thread
  45  * buffers that appear later in the file are guaranteed to contain events
  46  * that happened later in time. Buffers from separate threads could be interleaved,
  47  * though.
  48  * Buffers are not required to be aligned.
  49  *
  50  * header format:
  51  * [id: 4 bytes] constant value: LOG_HEADER_ID
  52  * [major: 1 byte] [minor: 1 byte] major and minor version of the log profiler
  53  * [format: 1 byte] version of the data format for the rest of the file
  54  * [ptrsize: 1 byte] size in bytes of a pointer in the profiled program
  55  * [startup time: 8 bytes] time in milliseconds since the unix epoch when the program started
  56  * [timer overhead: 4 bytes] approximate overhead in nanoseconds of the timer
  57  * [flags: 4 bytes] file format flags, should be 0 for now
  58  * [pid: 4 bytes] pid of the profiled process
  59  * [sysid: 4 bytes] operating system and architecture identifier
  60  *
  61  * The multiple byte integers are in little-endian format.
  62  *
  63  * buffer format:
  64  * [buffer header] [event]*
  65  * Buffers have a fixed-size header followed by 0 or more bytes of event data.
  66  * Timing information and other values in the event data are usually stored
  67  * as uleb128 or sleb128 integers. To save space, as noted for each item below,
  68  * some data is represented as a difference between the actual value and
  69  * either the last value of the same type (like for timing information) or
  70  * as the difference from a value stored in a buffer header.
  71  *
  72  * For timing information the data is stored as uleb128, since timing
  73  * increases in a monotonic way in each thread: the value is the number of
  74  * nanoseconds to add to the last seen timing data in a buffer. The first value
  75  * in a buffer will be calculated from the time_base field in the buffer head.
  76  *
  77  * Object or heap sizes are stored as uleb128.
  78  * Pointer differences are stored as sleb128, instead.
  79  *
  80  * If an unexpected value is found, the rest of the buffer should be ignored,
  81  * as generally the later values need the former to be interpreted correctly.
  82  *
  83  * buffer header format:
  84  * [bufid: 4 bytes] constant value: BUF_ID
  85  * [len: 4 bytes] size of the data following the buffer header
  86  * [time_base: 8 bytes] time base in nanoseconds since an unspecified epoch
  87  * [ptr_base: 8 bytes] base value for pointers
  88  * [obj_base: 8 bytes] base value for object addresses
  89  * [thread id: 8 bytes] system-specific thread ID (pthread_t for example)
  90  * [method_base: 8 bytes] base value for MonoMethod pointers
  91  *
  92  * event format:
  93  * [extended info: upper 4 bits] [type: lower 4 bits] [data]*
  94  * The data that follows depends on type and the extended info.
  95  * Type is one of the enum values in proflog.h: TYPE_ALLOC, TYPE_GC,
  96  * TYPE_METADATA, TYPE_METHOD, TYPE_EXCEPTION, TYPE_MONITOR, TYPE_HEAP.
  97  * The extended info bits are interpreted based on type, see
  98  * each individual event description below.
  99  * strings are represented as a 0-terminated utf8 sequence.
 100  *
 101  * backtrace format:
 102  * [flags: uleb128] must be 0
 103  * [num: uleb128] number of frames following
 104  * [frame: sleb128]* num MonoMethod pointers as differences from ptr_base
 105  *
 106  * type alloc format:
 107  * type: TYPE_ALLOC
 108  * exinfo: flags: TYPE_ALLOC_BT
 109  * [time diff: uleb128] nanoseconds since last timing
 110  * [ptr: sleb128] class as a byte difference from ptr_base
 111  * [obj: sleb128] object address as a byte difference from obj_base
 112  * [size: uleb128] size of the object in the heap
 113  * If the TYPE_ALLOC_BT flag is set, a backtrace follows.
 114  *
 115  * type GC format:
 116  * type: TYPE_GC
 117  * exinfo: one of TYPE_GC_EVENT, TYPE_GC_RESIZE, TYPE_GC_MOVE
 118  * [time diff: uleb128] nanoseconds since last timing
 119  * if exinfo == TYPE_GC_RESIZE
 120  *      [heap_size: uleb128] new heap size
 121  * if exinfo == TYPE_GC_EVENT
 122  *      [event type: uleb128] GC event (MONO_GC_EVENT_* from profiler.h)
 123  *      [generation: uleb128] GC generation event refers to
 124  * if exinfo == TYPE_GC_MOVE
 125  *      [num_objects: uleb128] number of object moves that follow
 126  *      [objaddr: sleb128]+ num_objects object pointer differences from obj_base
 127  *      num is always an even number: the even items are the old
 128  *      addresses, the odd numbers are the respective new object addresses
 129  *
 130  * type metadata format:
 131  * type: TYPE_METADATA
 132  * exinfo: flags: TYPE_LOAD_ERR
 133  * [time diff: uleb128] nanoseconds since last timing
 134  * [mtype: byte] metadata type, one of: TYPE_CLASS, TYPE_IMAGE, TYPE_ASSEMBLY, TYPE_DOMAIN
 135  * [pointer: sleb128] pointer of the metadata type depending on mtype
 136  * if mtype == TYPE_CLASS
 137  *      [image: sleb128] MonoImage* as a pointer difference from ptr_base
 138  *      [flags: uleb128] must be 0
 139  *      [name: string] full class name
 140  * if mtype == TYPE_IMAGE
 141  *      [flags: uleb128] must be 0
 142  *      [name: string] image file name
 143  *
 144  * type method format:
 145  * type: TYPE_METHOD
 146  * exinfo: one of: TYPE_LEAVE, TYPE_ENTER, TYPE_EXC_LEAVE, TYPE_JIT
 147  * [time diff: uleb128] nanoseconds since last timing
 148  * [method: sleb128] MonoMethod* as a pointer difference from the last such
 149  * pointer or the buffer method_base
 150  * if exinfo == TYPE_JIT
 151  *      [code address: sleb128] pointer to the native code as a diff from ptr_base
 152  *      [code size: uleb128] size of the generated code
 153  *      [name: string] full method name
 154  *
 155  * type exception format:
 156  * type: TYPE_EXCEPTION
 157  * exinfo: TYPE_EXCEPTION_BT flag and one of: TYPE_THROW, TYPE_CLAUSE
 158  * [time diff: uleb128] nanoseconds since last timing
 159  * if exinfo.low3bits == TYPE_CLAUSE
 160  *      [clause type: uleb128] finally/catch/fault/filter
 161  *      [clause num: uleb128] the clause number in the method header
 162  *      [method: sleb128] MonoMethod* as a pointer difference from the last such
 163  *      pointer or the buffer method_base
 164  * if exinfo.low3bits == TYPE_THROW
 165  *      [object: sleb128] the object that was thrown as a difference from obj_base
 166  *      If the TYPE_EXCEPTION_BT flag is set, a backtrace follows.
 167  *
 168  * type monitor format:
 169  * type: TYPE_MONITOR
 170  * exinfo: TYPE_MONITOR_BT flag and one of: MONO_PROFILER_MONITOR_(CONTENTION|FAIL|DONE)
 171  * [time diff: uleb128] nanoseconds since last timing
 172  * [object: sleb128] the lock object as a difference from obj_base
 173  * if exinfo.low3bits == MONO_PROFILER_MONITOR_CONTENTION
 174  *      If the TYPE_MONITOR_BT flag is set, a backtrace follows.
 175  *
 176  * type heap format
 177  * type: TYPE_HEAP
 178  * exinfo: one of TYPE_HEAP_START, TYPE_HEAP_END, TYPE_HEAP_OBJECT
 179  * if exinfo == TYPE_HEAP_START
 180  *      [time diff: uleb128] nanoseconds since last timing
 181  * if exinfo == TYPE_HEAP_END
 182  *      [time diff: uleb128] nanoseconds since last timing
 183  * if exinfo == TYPE_HEAP_OBJECT
 184  *      [object: sleb128] the object as a difference from obj_base
 185  *      [class: sleb128] the object MonoClass* as a difference from ptr_base
 186  *      [size: uleb128] size of the object on the heap
 187  *      [num_refs: uleb128] number of object references
 188  *      [objrefs: sleb128]+ object referenced as a difference from obj_base
 189  *
 190  */
 191 struct _LogBuffer {
 192         LogBuffer *next;
 193         uint64_t time_base;
 194         uint64_t last_time;
 195         uintptr_t ptr_base;
 196         uintptr_t method_base;
 197         uintptr_t last_method;
 198         uintptr_t obj_base;
 199         uintptr_t thread_id;
 200         unsigned char* data_end;
 201         unsigned char* data;
 202         int size;
 203         int call_depth;
 204         unsigned char buf [1];
 205 };
 206
 207 struct _MonoProfiler {
 208         LogBuffer *buffers;
 209         FILE* file;
 210         gzFile *gzfile;
 211         int pipe_output;
 212         int last_gc_gen_started;
 213 };
 214
 215 #if HAVE_KW_THREAD
 216 #define TLS_SET(x,y) x = y
 217 #define TLS_GET(x) x
 218 #define TLS_INIT(x)
 219 static __thread LogBuffer* tlsbuffer = NULL;
 220 #else
 221 #define TLS_SET(x,y) pthread_setspecific(x, y)
 222 #define TLS_GET(x) ((LogBuffer *) pthread_getspecific(x))
 223 #define TLS_INIT(x) pthread_key_create(&x, NULL)
 224 static pthread_key_t tlsbuffer;
 225 #endif
 226
 227 static LogBuffer*
 228 create_buffer (void)
 229 {
 230         LogBuffer* buf = alloc_buffer (BUFFER_SIZE);
 231         buf->size = BUFFER_SIZE;
 232         buf->time_base = current_time ();
 233         buf->last_time = buf->time_base;
 234         buf->data_end = (unsigned char*)buf + buf->size;
 235         buf->data = buf->buf;
 236         return buf;
 237 }
 238
 239 static void
 240 init_thread (void)
 241 {
 242         LogBuffer *logbuffer;
 243         if (TLS_GET (tlsbuffer))
 244                 return;
 245         logbuffer = create_buffer ();
 246         TLS_SET (tlsbuffer, logbuffer);
 247         logbuffer->thread_id = thread_id ();
 248         //printf ("thread %p at time %llu\n", (void*)logbuffer->thread_id, logbuffer->time_base);
 249 }
 250
 251 static LogBuffer*
 252 ensure_logbuf (int bytes)
 253 {
 254         LogBuffer *old = TLS_GET (tlsbuffer);
 255         if (old && old->data + bytes + 100 < old->data_end)
 256                 return old;
 257         TLS_SET (tlsbuffer, NULL);
 258         init_thread ();
 259         TLS_GET (tlsbuffer)->next = old;
 260         if (old)
 261                 TLS_GET (tlsbuffer)->call_depth = old->call_depth;
 262         //printf ("new logbuffer\n");
 263         return TLS_GET (tlsbuffer);
 264 }
 265
 266 static void
 267 emit_byte (LogBuffer *logbuffer, int value)
 268 {
 269         logbuffer->data [0] = value;
 270         logbuffer->data++;
 271         assert (logbuffer->data <= logbuffer->data_end);
 272 }
 273
 274 static void
 275 emit_value (LogBuffer *logbuffer, int value)
 276 {
 277         encode_uleb128 (value, logbuffer->data, &logbuffer->data);
 278         assert (logbuffer->data <= logbuffer->data_end);
 279 }
 280
 281 static void
 282 emit_time (LogBuffer *logbuffer, uint64_t value)
 283 {
 284         uint64_t tdiff = value - logbuffer->last_time;
 285         unsigned char *p;
 286         if (value < logbuffer->last_time)
 287                 printf ("time went backwards\n");
 288         //if (tdiff > 1000000)
 289         //      printf ("large time offset: %llu\n", tdiff);
 290         p = logbuffer->data;
 291         encode_uleb128 (tdiff, logbuffer->data, &logbuffer->data);
 292         /*if (tdiff != decode_uleb128 (p, &p))
 293                 printf ("incorrect encoding: %llu\n", tdiff);*/
 294         logbuffer->last_time = value;
 295         assert (logbuffer->data <= logbuffer->data_end);
 296 }
 297
 298 static void
 299 emit_svalue (LogBuffer *logbuffer, int64_t value)
 300 {
 301         encode_sleb128 (value, logbuffer->data, &logbuffer->data);
 302         assert (logbuffer->data <= logbuffer->data_end);
 303 }
 304
 305 static void
 306 emit_ptr (LogBuffer *logbuffer, void *ptr)
 307 {
 308         if (!logbuffer->ptr_base)
 309                 logbuffer->ptr_base = (uintptr_t)ptr;
 310         emit_svalue (logbuffer, (intptr_t)ptr - logbuffer->ptr_base);
 311         assert (logbuffer->data <= logbuffer->data_end);
 312 }
 313
 314 static void
 315 emit_method (LogBuffer *logbuffer, void *method)
 316 {
 317         if (!logbuffer->method_base) {
 318                 logbuffer->method_base = (intptr_t)method;
 319                 logbuffer->last_method = (intptr_t)method;
 320         }
 321         encode_sleb128 ((intptr_t)((char*)method - (char*)logbuffer->last_method), logbuffer->data, &logbuffer->data);
 322         logbuffer->last_method = (intptr_t)method;
 323         assert (logbuffer->data <= logbuffer->data_end);
 324 }
 325
 326 static void
 327 emit_obj (LogBuffer *logbuffer, void *ptr)
 328 {
 329         if (!logbuffer->obj_base)
 330                 logbuffer->obj_base = (uintptr_t)ptr >> 3;
 331         emit_svalue (logbuffer, ((uintptr_t)ptr >> 3) - logbuffer->obj_base);
 332         assert (logbuffer->data <= logbuffer->data_end);
 333 }
 334
 335 static char*
 336 write_int32 (char *buf, int32_t value)
 337 {
 338         int i;
 339         for (i = 0; i < 4; ++i) {
 340                 buf [i] = value;
 341                 value >>= 8;
 342         }
 343         return buf + 4;
 344 }
 345
 346 static char*
 347 write_int64 (char *buf, int64_t value)
 348 {
 349         int i;
 350         for (i = 0; i < 8; ++i) {
 351                 buf [i] = value;
 352                 value >>= 8;
 353         }
 354         return buf + 8;
 355 }
 356
 357 static void
 358 dump_header (MonoProfiler *profiler)
 359 {
 360         char hbuf [128];
 361         char *p = hbuf;
 362         p = write_int32 (p, LOG_HEADER_ID);
 363         *p++ = LOG_VERSION_MAJOR;
 364         *p++ = LOG_VERSION_MINOR;
 365         *p++ = LOG_DATA_VERSION;
 366         *p++ = sizeof (void*);
 367         p = write_int64 (p, 0); /* startup time */
 368         p = write_int32 (p, 0); /* timer overhead */
 369         p = write_int32 (p, 0); /* flags */
 370         p = write_int32 (p, 0); /* pid */
 371         p = write_int32 (p, 0); /* opsystem */
 372         if (profiler->gzfile) {
 373                 gzwrite (profiler->gzfile, hbuf, p - hbuf);
 374         } else {
 375                 fwrite (hbuf, p - hbuf, 1, profiler->file);
 376         }
 377 }
 378
 379 static void
 380 dump_buffer (MonoProfiler *profiler, LogBuffer *buf)
 381 {
 382         char hbuf [128];
 383         char *p = hbuf;
 384         if (buf->next)
 385                 dump_buffer (profiler, buf->next);
 386         p = write_int32 (p, BUF_ID);
 387         p = write_int32 (p, buf->data - buf->buf);
 388         p = write_int64 (p, buf->time_base);
 389         p = write_int64 (p, buf->ptr_base);
 390         p = write_int64 (p, buf->obj_base);
 391         p = write_int64 (p, buf->thread_id);
 392         p = write_int64 (p, buf->method_base);
 393         if (profiler->gzfile) {
 394                 gzwrite (profiler->gzfile, hbuf, p - hbuf);
 395                 gzwrite (profiler->gzfile, buf->buf, buf->data - buf->buf);
 396         } else {
 397                 fwrite (hbuf, p - hbuf, 1, profiler->file);
 398                 fwrite (buf->buf, buf->data - buf->buf, 1, profiler->file);
 399         }
 400         free_buffer (buf, buf->size);
 401 }
 402
 403 static void
 404 runtime_initialized (MonoProfiler *profiler)
 405 {
 406         runtime_inited = 1;
 407 }
 408
 409 /*
 410  * Can be called only at safe callback locations.
 411  */
 412 static void
 413 safe_dump (MonoProfiler *profiler, LogBuffer *logbuffer)
 414 {
 415         int cd = logbuffer->call_depth;
 416         take_lock ();
 417         dump_buffer (profiler, TLS_GET (tlsbuffer));
 418         release_lock ();
 419         TLS_SET (tlsbuffer, NULL);
 420         init_thread ();
 421         TLS_GET (tlsbuffer)->call_depth = cd;
 422 }
 423
 424 static int
 425 gc_reference (MonoObject *obj, MonoClass *klass, uintptr_t size, uintptr_t num, MonoObject **refs, void *data)
 426 {
 427         int i;
 428         //const char *name = mono_class_get_name (klass);
 429         LogBuffer *logbuffer = ensure_logbuf (20 + num * 8);
 430         emit_byte (logbuffer, TYPE_HEAP_OBJECT | TYPE_HEAP);
 431         emit_obj (logbuffer, obj);
 432         emit_ptr (logbuffer, klass);
 433         emit_value (logbuffer, size);
 434         emit_value (logbuffer, num);
 435         for (i = 0; i < num; ++i)
 436                 emit_obj (logbuffer, refs [i]);
 437         //if (num)
 438         //      printf ("obj: %p, klass: %s, refs: %d, size: %d\n", obj, name, (int)num, (int)size);
 439         return 0;
 440 }
 441
 442 static unsigned int hs_mode_ms = 0;
 443 static unsigned int hs_mode_gc = 0;
 444 static unsigned int gc_count = 0;
 445 static uint64_t last_hs_time = 0;
 446
 447 static void
 448 heap_walk (MonoProfiler *profiler)
 449 {
 450         int do_walk = 0;
 451         uint64_t now;
 452         LogBuffer *logbuffer;
 453         if (!do_heap_shot)
 454                 return;
 455         logbuffer = ensure_logbuf (10);
 456         now = current_time ();
 457         if (hs_mode_ms && (now - last_hs_time)/1000000 >= hs_mode_ms)
 458                 do_walk = 1;
 459         else if (hs_mode_gc && (gc_count % hs_mode_gc) == 0)
 460                 do_walk = 1;
 461         else if (!hs_mode_ms && !hs_mode_gc && profiler->last_gc_gen_started == mono_gc_max_generation ())
 462                 do_walk = 1;
 463
 464         if (!do_walk)
 465                 return;
 466         emit_byte (logbuffer, TYPE_HEAP_START | TYPE_HEAP);
 467         emit_time (logbuffer, now);
 468         mono_gc_walk_heap (0, gc_reference, NULL);
 469         logbuffer = ensure_logbuf (10);
 470         now = current_time ();
 471         emit_byte (logbuffer, TYPE_HEAP_END | TYPE_HEAP);
 472         emit_time (logbuffer, now);
 473 }
 474
 475 static void
 476 gc_event (MonoProfiler *profiler, MonoGCEvent ev, int generation) {
 477         uint64_t now;
 478         LogBuffer *logbuffer = ensure_logbuf (10);
 479         now = current_time ();
 480         emit_byte (logbuffer, TYPE_GC_EVENT | TYPE_GC);
 481         emit_time (logbuffer, now);
 482         emit_value (logbuffer, ev);
 483         emit_value (logbuffer, generation);
 484         /* to deal with nested gen1 after gen0 started */
 485         if (ev == MONO_GC_EVENT_START) {
 486                 profiler->last_gc_gen_started = generation;
 487                 gc_count++;
 488         }
 489         if (ev == MONO_GC_EVENT_PRE_START_WORLD)
 490                 heap_walk (profiler);
 491         if (ev == MONO_GC_EVENT_POST_START_WORLD)
 492                 safe_dump (profiler, logbuffer);
 493         //printf ("gc event %d for generation %d\n", ev, generation);
 494 }
 495
 496 static void
 497 gc_resize (MonoProfiler *profiler, int64_t new_size) {
 498         uint64_t now;
 499         LogBuffer *logbuffer = ensure_logbuf (10);
 500         now = current_time ();
 501         emit_byte (logbuffer, TYPE_GC_RESIZE | TYPE_GC);
 502         emit_time (logbuffer, now);
 503         emit_value (logbuffer, new_size);
 504         //printf ("gc resized to %lld\n", new_size);
 505 }
 506
 507 #define MAX_FRAMES 16
 508 typedef struct {
 509         int count;
 510         MonoMethod* methods [MAX_FRAMES];
 511 } FrameData;
 512 static int num_frames = MAX_FRAMES / 2;
 513
 514 static mono_bool
 515 walk_stack (MonoMethod *method, int32_t native_offset, int32_t il_offset, mono_bool managed, void* data)
 516 {
 517         FrameData *frame = data;
 518         if (method && frame->count < num_frames) {
 519                 frame->methods [frame->count++] = method;
 520                 //printf ("In %d %s\n", frame->count, mono_method_get_name (method));
 521         }
 522         return frame->count == num_frames;
 523 }
 524
 525 /*
 526  * a note about stack walks: they can cause more profiler events to fire,
 527  * so we need to make sure they don't happen after we started emitting an
 528  * event, hence the collect_bt/emit_bt split.
 529  */
 530 static void
 531 collect_bt (FrameData *data)
 532 {
 533         data->count = 0;
 534         mono_stack_walk_no_il (walk_stack, data);
 535 }
 536
 537 static void
 538 emit_bt (LogBuffer *logbuffer, FrameData *data)
 539 {
 540         /* FIXME: this is actually tons of data and we should
 541          * just output it the first time and use an id the next
 542          */
 543         if (data->count > num_frames)
 544                 printf ("bad num frames: %d\n", data->count);
 545         emit_value (logbuffer, 0); /* flags */
 546         emit_value (logbuffer, data->count);
 547         //if (*p != data.count) {
 548         //      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);}
 549         while (data->count) {
 550                 emit_ptr (logbuffer, data->methods [--data->count]);
 551         }
 552 }
 553
 554 static void
 555 gc_alloc (MonoProfiler *prof, MonoObject *obj, MonoClass *klass)
 556 {
 557         uint64_t now;
 558         uintptr_t len;
 559         int do_bt = (nocalls && runtime_inited && !notraces)? TYPE_ALLOC_BT: 0;
 560         FrameData data;
 561         LogBuffer *logbuffer;
 562         len = mono_object_get_size (obj);
 563         if (do_bt)
 564                 collect_bt (&data);
 565         logbuffer = ensure_logbuf (32 + MAX_FRAMES * 8);
 566         now = current_time ();
 567         emit_byte (logbuffer, do_bt | TYPE_ALLOC);
 568         emit_time (logbuffer, now);
 569         emit_ptr (logbuffer, klass);
 570         emit_obj (logbuffer, obj);
 571         emit_value (logbuffer, len);
 572         if (do_bt)
 573                 emit_bt (logbuffer, &data);
 574         if (logbuffer->next)
 575                 safe_dump (prof, logbuffer);
 576         //printf ("gc alloc %s at %p\n", mono_class_get_name (klass), obj);
 577 }
 578
 579 static void
 580 gc_moves (MonoProfiler *prof, void **objects, int num)
 581 {
 582         int i;
 583         uint64_t now;
 584         LogBuffer *logbuffer = ensure_logbuf (10 + num * 8);
 585         now = current_time ();
 586         emit_byte (logbuffer, TYPE_GC_MOVE | TYPE_GC);
 587         emit_time (logbuffer, now);
 588         emit_value (logbuffer, num);
 589         for (i = 0; i < num; ++i)
 590                 emit_obj (logbuffer, objects [i]);
 591         //printf ("gc moved %d objects\n", num/2);
 592 }
 593
 594 static char*
 595 push_nesting (char *p, MonoClass *klass)
 596 {
 597         MonoClass *nesting;
 598         const char *name;
 599         const char *nspace;
 600         nesting = mono_class_get_nesting_type (klass);
 601         if (nesting) {
 602                 p = push_nesting (p, nesting);
 603                 *p++ = '/';
 604                 *p = 0;
 605         }
 606         name = mono_class_get_name (klass);
 607         nspace = mono_class_get_namespace (klass);
 608         if (*nspace) {
 609                 strcpy (p, nspace);
 610                 p += strlen (nspace);
 611                 *p++ = '.';
 612                 *p = 0;
 613         }
 614         strcpy (p, name);
 615         p += strlen (name);
 616         return p;
 617 }
 618
 619 static char*
 620 type_name (MonoClass *klass)
 621 {
 622         char buf [1024];
 623         char *p;
 624         push_nesting (buf, klass);
 625         p = malloc (strlen (buf) + 1);
 626         strcpy (p, buf);
 627         return p;
 628 }
 629
 630 static void
 631 image_loaded (MonoProfiler *prof, MonoImage *image, int result)
 632 {
 633         uint64_t now;
 634         const char *name;
 635         int nlen;
 636         LogBuffer *logbuffer;
 637         if (result != MONO_PROFILE_OK)
 638                 return;
 639         name = mono_image_get_filename (image);
 640         nlen = strlen (name) + 1;
 641         logbuffer = ensure_logbuf (16 + nlen);
 642         now = current_time ();
 643         emit_byte (logbuffer, TYPE_END_LOAD | TYPE_METADATA);
 644         emit_time (logbuffer, now);
 645         emit_byte (logbuffer, TYPE_IMAGE);
 646         emit_ptr (logbuffer, image);
 647         emit_value (logbuffer, 0); /* flags */
 648         memcpy (logbuffer->data, name, nlen);
 649         logbuffer->data += nlen;
 650         //printf ("loaded image %p (%s)\n", image, name);
 651         if (logbuffer->next)
 652                 safe_dump (prof, logbuffer);
 653 }
 654
 655 static void
 656 class_loaded (MonoProfiler *prof, MonoClass *klass, int result)
 657 {
 658         uint64_t now;
 659         char *name;
 660         int nlen;
 661         MonoImage *image;
 662         LogBuffer *logbuffer;
 663         if (result != MONO_PROFILE_OK)
 664                 return;
 665         if (runtime_inited)
 666                 name = mono_type_get_name (mono_class_get_type (klass));
 667         else
 668                 name = type_name (klass);
 669         nlen = strlen (name) + 1;
 670         image = mono_class_get_image (klass);
 671         logbuffer = ensure_logbuf (24 + nlen);
 672         now = current_time ();
 673         emit_byte (logbuffer, TYPE_END_LOAD | TYPE_METADATA);
 674         emit_time (logbuffer, now);
 675         emit_byte (logbuffer, TYPE_CLASS);
 676         emit_ptr (logbuffer, klass);
 677         emit_ptr (logbuffer, image);
 678         emit_value (logbuffer, 0); /* flags */
 679         memcpy (logbuffer->data, name, nlen);
 680         logbuffer->data += nlen;
 681         //printf ("loaded class %p (%s)\n", klass, name);
 682         if (runtime_inited)
 683                 mono_free (name);
 684         else
 685                 free (name);
 686         if (logbuffer->next)
 687                 safe_dump (prof, logbuffer);
 688 }
 689
 690 static void
 691 method_enter (MonoProfiler *prof, MonoMethod *method)
 692 {
 693         uint64_t now;
 694         LogBuffer *logbuffer = ensure_logbuf (16);
 695         if (logbuffer->call_depth++ > max_call_depth)
 696                 return;
 697         now = current_time ();
 698         emit_byte (logbuffer, TYPE_ENTER | TYPE_METHOD);
 699         emit_time (logbuffer, now);
 700         emit_method (logbuffer, method);
 701 }
 702
 703 static void
 704 method_leave (MonoProfiler *prof, MonoMethod *method)
 705 {
 706         uint64_t now;
 707         LogBuffer *logbuffer = ensure_logbuf (16);
 708         if (--logbuffer->call_depth > max_call_depth)
 709                 return;
 710         now = current_time ();
 711         emit_byte (logbuffer, TYPE_LEAVE | TYPE_METHOD);
 712         emit_time (logbuffer, now);
 713         emit_method (logbuffer, method);
 714         if (logbuffer->next)
 715                 safe_dump (prof, logbuffer);
 716 }
 717
 718 static void
 719 method_exc_leave (MonoProfiler *prof, MonoMethod *method)
 720 {
 721         uint64_t now;
 722         LogBuffer *logbuffer;
 723         if (nocalls)
 724                 return;
 725         logbuffer = ensure_logbuf (16);
 726         if (--logbuffer->call_depth > max_call_depth)
 727                 return;
 728         now = current_time ();
 729         emit_byte (logbuffer, TYPE_EXC_LEAVE | TYPE_METHOD);
 730         emit_time (logbuffer, now);
 731         emit_method (logbuffer, method);
 732 }
 733
 734 static void
 735 method_jitted (MonoProfiler *prof, MonoMethod *method, MonoJitInfo* jinfo, int result)
 736 {
 737         uint64_t now;
 738         char *name;
 739         int nlen;
 740         LogBuffer *logbuffer;
 741         if (result != MONO_PROFILE_OK)
 742                 return;
 743         name = mono_method_full_name (method, 1);
 744         nlen = strlen (name) + 1;
 745         logbuffer = ensure_logbuf (32 + nlen);
 746         now = current_time ();
 747         emit_byte (logbuffer, TYPE_JIT | TYPE_METHOD);
 748         emit_time (logbuffer, now);
 749         emit_method (logbuffer, method);
 750         emit_ptr (logbuffer, mono_jit_info_get_code_start (jinfo));
 751         emit_value (logbuffer, mono_jit_info_get_code_size (jinfo));
 752         memcpy (logbuffer->data, name, nlen);
 753         logbuffer->data += nlen;
 754         mono_free (name);
 755         if (logbuffer->next)
 756                 safe_dump (prof, logbuffer);
 757 }
 758
 759 static void
 760 throw_exc (MonoProfiler *prof, MonoObject *object)
 761 {
 762         int do_bt = (nocalls && runtime_inited && !notraces)? TYPE_EXCEPTION_BT: 0;
 763         uint64_t now;
 764         FrameData data;
 765         LogBuffer *logbuffer;
 766         if (do_bt)
 767                 collect_bt (&data);
 768         logbuffer = ensure_logbuf (16 + MAX_FRAMES * 8);
 769         now = current_time ();
 770         emit_byte (logbuffer, do_bt | TYPE_EXCEPTION);
 771         emit_time (logbuffer, now);
 772         emit_obj (logbuffer, object);
 773         if (do_bt)
 774                 emit_bt (logbuffer, &data);
 775 }
 776
 777 static void
 778 clause_exc (MonoProfiler *prof, MonoMethod *method, int clause_type, int clause_num)
 779 {
 780         uint64_t now;
 781         LogBuffer *logbuffer = ensure_logbuf (16);
 782         now = current_time ();
 783         emit_byte (logbuffer, TYPE_EXCEPTION | TYPE_CLAUSE);
 784         emit_time (logbuffer, now);
 785         emit_value (logbuffer, clause_type);
 786         emit_value (logbuffer, clause_num);
 787         emit_method (logbuffer, method);
 788 }
 789
 790 static void
 791 monitor_event (MonoProfiler *profiler, MonoObject *object, MonoProfilerMonitorEvent event)
 792 {
 793         int do_bt = (nocalls && runtime_inited && !notraces && event == MONO_PROFILER_MONITOR_CONTENTION)? TYPE_MONITOR_BT: 0;
 794         uint64_t now;
 795         FrameData data;
 796         LogBuffer *logbuffer;
 797         if (do_bt)
 798                 collect_bt (&data);
 799         logbuffer = ensure_logbuf (16 + MAX_FRAMES * 8);
 800         now = current_time ();
 801         emit_byte (logbuffer, (event << 4) | do_bt | TYPE_MONITOR);
 802         emit_time (logbuffer, now);
 803         emit_obj (logbuffer, object);
 804         if (do_bt)
 805                 emit_bt (logbuffer, &data);
 806 }
 807
 808 static void
 809 thread_start (MonoProfiler *prof, uintptr_t tid)
 810 {
 811         //printf ("thread start %p\n", (void*)tid);
 812         init_thread ();
 813 }
 814
 815 static void
 816 thread_end (MonoProfiler *prof, uintptr_t tid)
 817 {
 818         take_lock ();
 819         if (TLS_GET (tlsbuffer))
 820                 dump_buffer (prof, TLS_GET (tlsbuffer));
 821         release_lock ();
 822         TLS_SET (tlsbuffer, NULL);
 823 }
 824
 825 static void
 826 log_shutdown (MonoProfiler *prof)
 827 {
 828         take_lock ();
 829         if (TLS_GET (tlsbuffer))
 830                 dump_buffer (prof, TLS_GET (tlsbuffer));
 831         TLS_SET (tlsbuffer, NULL);
 832         release_lock ();
 833         if (prof->gzfile)
 834                 gzclose (prof->gzfile);
 835         if (prof->pipe_output)
 836                 pclose (prof->file);
 837         else
 838                 fclose (prof->file);
 839         free (prof);
 840 }
 841
 842 static MonoProfiler*
 843 create_profiler (char *filename)
 844 {
 845         MonoProfiler *prof;
 846         prof = calloc (1, sizeof (MonoProfiler));
 847         if (do_report) /* FIXME: use filename as output */
 848                 filename = "|mprof-report -";
 849
 850         if (!filename)
 851                 filename = "output.mlpd";
 852         if (*filename == '|') {
 853                 prof->file = popen (filename + 1, "w");
 854                 prof->pipe_output = 1;
 855         } else {
 856                 prof->file = fopen (filename, "wb");
 857         }
 858         if (!prof->file) {
 859                 printf ("Cannot create profiler output: %s\n", filename);
 860                 exit (1);
 861         }
 862         if (use_zip)
 863                 prof->gzfile = gzdopen (fileno (prof->file), "wb");
 864         dump_header (prof);
 865         return prof;
 866 }
 867
 868 static void
 869 usage (int do_exit)
 870 {
 871         printf ("Log profiler version %d.%d (format: %d)\n", LOG_VERSION_MAJOR, LOG_VERSION_MINOR, LOG_DATA_VERSION);
 872         printf ("Usage: mono --profile=log[:OPTION1[,OPTION2...]] program.exe\n");
 873         printf ("Options:\n");
 874         printf ("\thelp             show this usage info\n");
 875         printf ("\t[no]alloc        enable/disable recording allocation info\n");
 876         printf ("\t[no]calls        enable/disable recording enter/leave method events\n");
 877         printf ("\theapshot         record heap shot info (by default at each major collection)\n");
 878         printf ("\thsmode=MODE      heapshot mode: every XXms milliseconds or every YYgc collections\n");
 879         printf ("\ttime=fast        use a faster (but more inaccurate) timer\n");
 880         printf ("\tmaxframes=NUM    collect up to NUM stack frames\n");
 881         printf ("\tcalldepth=NUM    ignore method events for call chain depth bigger than NUM\n");
 882         printf ("\toutput=FILENAME  write the data to file FILENAME\n");
 883         printf ("\toutput=|PROGRAM  write the data to the stdin of PROGRAM\n");
 884         printf ("\treport           create a report instead of writing the raw data to a file\n");
 885         printf ("\tzip              compress the output data\n");
 886         if (do_exit)
 887                 exit (1);
 888 }
 889
 890 const char*
 891 match_option (const char* p, const char *opt, char **rval)
 892 {
 893         int len = strlen (opt);
 894         if (strncmp (p, opt, len) == 0) {
 895                 if (rval) {
 896                         if (p [len] == '=' && p [len + 1]) {
 897                                 const char *opt = p + len + 1;
 898                                 const char *end = strchr (opt, ',');
 899                                 char *val;
 900                                 int l;
 901                                 if (end == NULL) {
 902                                         l = strlen (opt);
 903                                 } else {
 904                                         l = end - opt;
 905                                 }
 906                                 val = malloc (l + 1);
 907                                 memcpy (val, opt, l);
 908                                 val [l] = 0;
 909                                 *rval = val;
 910                                 return opt + l;
 911                         }
 912                         usage (1);
 913                 } else {
 914                         if (p [len] == 0)
 915                                 return p + len;
 916                         if (p [len] == ',')
 917                                 return p + len + 1;
 918                 }
 919         }
 920         return p;
 921 }
 922
 923 void
 924 mono_profiler_startup (const char *desc)
 925 {
 926         MonoProfiler *prof;
 927         char *filename = NULL;
 928         const char *p;
 929         const char *opt;
 930         int fast_time = 0;
 931         int calls_enabled = 0;
 932         int allocs_enabled = 0;
 933         int events = MONO_PROFILE_GC|MONO_PROFILE_ALLOCATIONS|
 934                 MONO_PROFILE_GC_MOVES|MONO_PROFILE_CLASS_EVENTS|MONO_PROFILE_THREADS|
 935                 MONO_PROFILE_ENTER_LEAVE|MONO_PROFILE_JIT_COMPILATION|MONO_PROFILE_EXCEPTIONS|
 936                 MONO_PROFILE_MONITOR_EVENTS|MONO_PROFILE_MODULE_EVENTS;
 937
 938         p = desc;
 939         if (strncmp (p, "log", 3))
 940                 usage (1);
 941         p += 3;
 942         if (*p == ':')
 943                 p++;
 944         for (; *p; p = opt) {
 945                 char *val;
 946                 if (*p == ',') {
 947                         opt = p + 1;
 948                         continue;
 949                 }
 950                 if ((opt = match_option (p, "help", NULL)) != p) {
 951                         usage (0);
 952                         continue;
 953                 }
 954                 if ((opt = match_option (p, "calls", NULL)) != p) {
 955                         calls_enabled = 1;
 956                         continue;
 957                 }
 958                 if ((opt = match_option (p, "nocalls", NULL)) != p) {
 959                         events &= ~MONO_PROFILE_ENTER_LEAVE;
 960                         nocalls = 1;
 961                         continue;
 962                 }
 963                 if ((opt = match_option (p, "alloc", NULL)) != p) {
 964                         allocs_enabled = 1;
 965                         continue;
 966                 }
 967                 if ((opt = match_option (p, "noalloc", NULL)) != p) {
 968                         events &= ~MONO_PROFILE_ALLOCATIONS;
 969                         continue;
 970                 }
 971                 if ((opt = match_option (p, "time", &val)) != p) {
 972                         if (strcmp (val, "fast") == 0)
 973                                 fast_time = 1;
 974                         else if (strcmp (val, "null") == 0)
 975                                 fast_time = 2;
 976                         else
 977                                 usage (1);
 978                         free (val);
 979                         continue;
 980                 }
 981                 if ((opt = match_option (p, "report", NULL)) != p) {
 982                         do_report = 1;
 983                         continue;
 984                 }
 985                 if ((opt = match_option (p, "heapshot", NULL)) != p) {
 986                         events &= ~MONO_PROFILE_ALLOCATIONS;
 987                         events &= ~MONO_PROFILE_ENTER_LEAVE;
 988                         nocalls = 1;
 989                         do_heap_shot = 1;
 990                         continue;
 991                 }
 992                 if ((opt = match_option (p, "hsmode", &val)) != p) {
 993                         char *end;
 994                         unsigned int count = strtoul (val, &end, 10);
 995                         if (val == end)
 996                                 usage (1);
 997                         if (strcmp (end, "ms") == 0)
 998                                 hs_mode_ms = count;
 999                         else if (strcmp (end, "gc") == 0)
1000                                 hs_mode_gc = count;
1001                         else
1002                                 usage (1);
1003                         free (val);
1004                         continue;
1005                 }
1006                 if ((opt = match_option (p, "zip", NULL)) != p) {
1007                         use_zip = 1;
1008                         continue;
1009                 }
1010                 if ((opt = match_option (p, "output", &val)) != p) {
1011                         filename = val;
1012                         continue;
1013                 }
1014                 if ((opt = match_option (p, "maxframes", &val)) != p) {
1015                         char *end;
1016                         num_frames = strtoul (val, &end, 10);
1017                         if (num_frames > MAX_FRAMES)
1018                                 num_frames = MAX_FRAMES;
1019                         free (val);
1020                         notraces = num_frames == 0;
1021                         continue;
1022                 }
1023                 if ((opt = match_option (p, "calldepth", &val)) != p) {
1024                         char *end;
1025                         max_call_depth = strtoul (val, &end, 10);
1026                         free (val);
1027                         continue;
1028                 }
1029                 if (opt == p) {
1030                         usage (0);
1031                         exit (0);
1032                 }
1033         }
1034         if (calls_enabled) {
1035                 events |= MONO_PROFILE_ENTER_LEAVE;
1036                 nocalls = 0;
1037         }
1038         if (allocs_enabled)
1039                 events |= MONO_PROFILE_ALLOCATIONS;
1040         utils_init (fast_time);
1041
1042         prof = create_profiler (filename);
1043         init_thread ();
1044
1045         mono_profiler_install (prof, log_shutdown);
1046         mono_profiler_install_gc (gc_event, gc_resize);
1047         mono_profiler_install_allocation (gc_alloc);
1048         mono_profiler_install_gc_moves (gc_moves);
1049         mono_profiler_install_class (NULL, class_loaded, NULL, NULL);
1050         mono_profiler_install_module (NULL, image_loaded, NULL, NULL);
1051         mono_profiler_install_thread (thread_start, thread_end);
1052         mono_profiler_install_enter_leave (method_enter, method_leave);
1053         mono_profiler_install_jit_end (method_jitted);
1054         mono_profiler_install_exception (throw_exc, method_exc_leave, clause_exc);
1055         mono_profiler_install_monitor (monitor_event);
1056         mono_profiler_install_runtime_initialized (runtime_initialized);
1057
1058         mono_profiler_set_events (events);
1059
1060         TLS_INIT (tlsbuffer);
1061 }
1062