mono/profiler/proflog.c

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