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