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