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 }
 525
 526 static void
 527 gc_event (MonoProfiler *profiler, MonoGCEvent ev, int generation) {
 528         uint64_t now;
 529         LogBuffer *logbuffer = ensure_logbuf (10);
 530         now = current_time ();
 531         emit_byte (logbuffer, TYPE_GC_EVENT | TYPE_GC);
 532         emit_time (logbuffer, now);
 533         emit_value (logbuffer, ev);
 534         emit_value (logbuffer, generation);
 535         /* to deal with nested gen1 after gen0 started */
 536         if (ev == MONO_GC_EVENT_START) {
 537                 profiler->last_gc_gen_started = generation;
 538                 gc_count++;
 539         }
 540         if (ev == MONO_GC_EVENT_PRE_START_WORLD)
 541                 heap_walk (profiler);
 542         if (ev == MONO_GC_EVENT_POST_START_WORLD)
 543                 safe_dump (profiler, logbuffer);
 544         //printf ("gc event %d for generation %d\n", ev, generation);
 545 }
 546
 547 static void
 548 gc_resize (MonoProfiler *profiler, int64_t new_size) {
 549         uint64_t now;
 550         LogBuffer *logbuffer = ensure_logbuf (10);
 551         now = current_time ();
 552         emit_byte (logbuffer, TYPE_GC_RESIZE | TYPE_GC);
 553         emit_time (logbuffer, now);
 554         emit_value (logbuffer, new_size);
 555         //printf ("gc resized to %lld\n", new_size);
 556 }
 557
 558 #define MAX_FRAMES 16
 559 typedef struct {
 560         int count;
 561         MonoMethod* methods [MAX_FRAMES];
 562 } FrameData;
 563 static int num_frames = MAX_FRAMES / 2;
 564
 565 static mono_bool
 566 walk_stack (MonoMethod *method, int32_t native_offset, int32_t il_offset, mono_bool managed, void* data)
 567 {
 568         FrameData *frame = data;
 569         if (method && frame->count < num_frames) {
 570                 frame->methods [frame->count++] = method;
 571                 //printf ("In %d %s\n", frame->count, mono_method_get_name (method));
 572         }
 573         return frame->count == num_frames;
 574 }
 575
 576 /*
 577  * a note about stack walks: they can cause more profiler events to fire,
 578  * so we need to make sure they don't happen after we started emitting an
 579  * event, hence the collect_bt/emit_bt split.
 580  */
 581 static void
 582 collect_bt (FrameData *data)
 583 {
 584         data->count = 0;
 585         mono_stack_walk_no_il (walk_stack, data);
 586 }
 587
 588 static void
 589 emit_bt (LogBuffer *logbuffer, FrameData *data)
 590 {
 591         /* FIXME: this is actually tons of data and we should
 592          * just output it the first time and use an id the next
 593          */
 594         if (data->count > num_frames)
 595                 printf ("bad num frames: %d\n", data->count);
 596         emit_value (logbuffer, 0); /* flags */
 597         emit_value (logbuffer, data->count);
 598         //if (*p != data.count) {
 599         //      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);}
 600         while (data->count) {
 601                 emit_ptr (logbuffer, data->methods [--data->count]);
 602         }
 603 }
 604
 605 static void
 606 gc_alloc (MonoProfiler *prof, MonoObject *obj, MonoClass *klass)
 607 {
 608         uint64_t now;
 609         uintptr_t len;
 610         int do_bt = (nocalls && runtime_inited && !notraces)? TYPE_ALLOC_BT: 0;
 611         FrameData data;
 612         LogBuffer *logbuffer;
 613         len = mono_object_get_size (obj);
 614         /* account for object alignment in the heap */
 615         len += 7;
 616         len &= ~7;
 617         if (do_bt)
 618                 collect_bt (&data);
 619         logbuffer = ensure_logbuf (32 + MAX_FRAMES * 8);
 620         now = current_time ();
 621         emit_byte (logbuffer, do_bt | TYPE_ALLOC);
 622         emit_time (logbuffer, now);
 623         emit_ptr (logbuffer, klass);
 624         emit_obj (logbuffer, obj);
 625         emit_value (logbuffer, len);
 626         if (do_bt)
 627                 emit_bt (logbuffer, &data);
 628         if (logbuffer->next)
 629                 safe_dump (prof, logbuffer);
 630         //printf ("gc alloc %s at %p\n", mono_class_get_name (klass), obj);
 631 }
 632
 633 static void
 634 gc_moves (MonoProfiler *prof, void **objects, int num)
 635 {
 636         int i;
 637         uint64_t now;
 638         LogBuffer *logbuffer = ensure_logbuf (10 + num * 8);
 639         now = current_time ();
 640         emit_byte (logbuffer, TYPE_GC_MOVE | TYPE_GC);
 641         emit_time (logbuffer, now);
 642         emit_value (logbuffer, num);
 643         for (i = 0; i < num; ++i)
 644                 emit_obj (logbuffer, objects [i]);
 645         //printf ("gc moved %d objects\n", num/2);
 646 }
 647
 648 static void
 649 gc_handle (MonoProfiler *prof, int op, int type, uintptr_t handle, MonoObject *obj)
 650 {
 651         uint64_t now;
 652         LogBuffer *logbuffer = ensure_logbuf (16);
 653         now = current_time ();
 654         if (op == MONO_PROFILER_GC_HANDLE_CREATED)
 655                 emit_byte (logbuffer, TYPE_GC_HANDLE_CREATED | TYPE_GC);
 656         else if (op == MONO_PROFILER_GC_HANDLE_DESTROYED)
 657                 emit_byte (logbuffer, TYPE_GC_HANDLE_DESTROYED | TYPE_GC);
 658         else
 659                 return;
 660         emit_time (logbuffer, now);
 661         emit_value (logbuffer, type);
 662         emit_value (logbuffer, handle);
 663         if (op == MONO_PROFILER_GC_HANDLE_CREATED)
 664                 emit_obj (logbuffer, obj);
 665 }
 666
 667 static char*
 668 push_nesting (char *p, MonoClass *klass)
 669 {
 670         MonoClass *nesting;
 671         const char *name;
 672         const char *nspace;
 673         nesting = mono_class_get_nesting_type (klass);
 674         if (nesting) {
 675                 p = push_nesting (p, nesting);
 676                 *p++ = '/';
 677                 *p = 0;
 678         }
 679         name = mono_class_get_name (klass);
 680         nspace = mono_class_get_namespace (klass);
 681         if (*nspace) {
 682                 strcpy (p, nspace);
 683                 p += strlen (nspace);
 684                 *p++ = '.';
 685                 *p = 0;
 686         }
 687         strcpy (p, name);
 688         p += strlen (name);
 689         return p;
 690 }
 691
 692 static char*
 693 type_name (MonoClass *klass)
 694 {
 695         char buf [1024];
 696         char *p;
 697         push_nesting (buf, klass);
 698         p = malloc (strlen (buf) + 1);
 699         strcpy (p, buf);
 700         return p;
 701 }
 702
 703 static void
 704 image_loaded (MonoProfiler *prof, MonoImage *image, int result)
 705 {
 706         uint64_t now;
 707         const char *name;
 708         int nlen;
 709         LogBuffer *logbuffer;
 710         if (result != MONO_PROFILE_OK)
 711                 return;
 712         name = mono_image_get_filename (image);
 713         nlen = strlen (name) + 1;
 714         logbuffer = ensure_logbuf (16 + nlen);
 715         now = current_time ();
 716         emit_byte (logbuffer, TYPE_END_LOAD | TYPE_METADATA);
 717         emit_time (logbuffer, now);
 718         emit_byte (logbuffer, TYPE_IMAGE);
 719         emit_ptr (logbuffer, image);
 720         emit_value (logbuffer, 0); /* flags */
 721         memcpy (logbuffer->data, name, nlen);
 722         logbuffer->data += nlen;
 723         //printf ("loaded image %p (%s)\n", image, name);
 724         if (logbuffer->next)
 725                 safe_dump (prof, logbuffer);
 726 }
 727
 728 static void
 729 class_loaded (MonoProfiler *prof, MonoClass *klass, int result)
 730 {
 731         uint64_t now;
 732         char *name;
 733         int nlen;
 734         MonoImage *image;
 735         LogBuffer *logbuffer;
 736         if (result != MONO_PROFILE_OK)
 737                 return;
 738         if (runtime_inited)
 739                 name = mono_type_get_name (mono_class_get_type (klass));
 740         else
 741                 name = type_name (klass);
 742         nlen = strlen (name) + 1;
 743         image = mono_class_get_image (klass);
 744         logbuffer = ensure_logbuf (24 + nlen);
 745         now = current_time ();
 746         emit_byte (logbuffer, TYPE_END_LOAD | TYPE_METADATA);
 747         emit_time (logbuffer, now);
 748         emit_byte (logbuffer, TYPE_CLASS);
 749         emit_ptr (logbuffer, klass);
 750         emit_ptr (logbuffer, image);
 751         emit_value (logbuffer, 0); /* flags */
 752         memcpy (logbuffer->data, name, nlen);
 753         logbuffer->data += nlen;
 754         //printf ("loaded class %p (%s)\n", klass, name);
 755         if (runtime_inited)
 756                 mono_free (name);
 757         else
 758                 free (name);
 759         if (logbuffer->next)
 760                 safe_dump (prof, logbuffer);
 761 }
 762
 763 static void
 764 method_enter (MonoProfiler *prof, MonoMethod *method)
 765 {
 766         uint64_t now;
 767         LogBuffer *logbuffer = ensure_logbuf (16);
 768         if (logbuffer->call_depth++ > max_call_depth)
 769                 return;
 770         now = current_time ();
 771         emit_byte (logbuffer, TYPE_ENTER | TYPE_METHOD);
 772         emit_time (logbuffer, now);
 773         emit_method (logbuffer, method);
 774 }
 775
 776 static void
 777 method_leave (MonoProfiler *prof, MonoMethod *method)
 778 {
 779         uint64_t now;
 780         LogBuffer *logbuffer = ensure_logbuf (16);
 781         if (--logbuffer->call_depth > max_call_depth)
 782                 return;
 783         now = current_time ();
 784         emit_byte (logbuffer, TYPE_LEAVE | TYPE_METHOD);
 785         emit_time (logbuffer, now);
 786         emit_method (logbuffer, method);
 787         if (logbuffer->next)
 788                 safe_dump (prof, logbuffer);
 789 }
 790
 791 static void
 792 method_exc_leave (MonoProfiler *prof, MonoMethod *method)
 793 {
 794         uint64_t now;
 795         LogBuffer *logbuffer;
 796         if (nocalls)
 797                 return;
 798         logbuffer = ensure_logbuf (16);
 799         if (--logbuffer->call_depth > max_call_depth)
 800                 return;
 801         now = current_time ();
 802         emit_byte (logbuffer, TYPE_EXC_LEAVE | TYPE_METHOD);
 803         emit_time (logbuffer, now);
 804         emit_method (logbuffer, method);
 805 }
 806
 807 static void
 808 method_jitted (MonoProfiler *prof, MonoMethod *method, MonoJitInfo* jinfo, int result)
 809 {
 810         uint64_t now;
 811         char *name;
 812         int nlen;
 813         LogBuffer *logbuffer;
 814         if (result != MONO_PROFILE_OK)
 815                 return;
 816         name = mono_method_full_name (method, 1);
 817         nlen = strlen (name) + 1;
 818         logbuffer = ensure_logbuf (32 + nlen);
 819         now = current_time ();
 820         emit_byte (logbuffer, TYPE_JIT | TYPE_METHOD);
 821         emit_time (logbuffer, now);
 822         emit_method (logbuffer, method);
 823         emit_ptr (logbuffer, mono_jit_info_get_code_start (jinfo));
 824         emit_value (logbuffer, mono_jit_info_get_code_size (jinfo));
 825         memcpy (logbuffer->data, name, nlen);
 826         logbuffer->data += nlen;
 827         mono_free (name);
 828         if (logbuffer->next)
 829                 safe_dump (prof, logbuffer);
 830 }
 831
 832 static void
 833 throw_exc (MonoProfiler *prof, MonoObject *object)
 834 {
 835         int do_bt = (nocalls && runtime_inited && !notraces)? TYPE_EXCEPTION_BT: 0;
 836         uint64_t now;
 837         FrameData data;
 838         LogBuffer *logbuffer;
 839         if (do_bt)
 840                 collect_bt (&data);
 841         logbuffer = ensure_logbuf (16 + MAX_FRAMES * 8);
 842         now = current_time ();
 843         emit_byte (logbuffer, do_bt | TYPE_EXCEPTION);
 844         emit_time (logbuffer, now);
 845         emit_obj (logbuffer, object);
 846         if (do_bt)
 847                 emit_bt (logbuffer, &data);
 848 }
 849
 850 static void
 851 clause_exc (MonoProfiler *prof, MonoMethod *method, int clause_type, int clause_num)
 852 {
 853         uint64_t now;
 854         LogBuffer *logbuffer = ensure_logbuf (16);
 855         now = current_time ();
 856         emit_byte (logbuffer, TYPE_EXCEPTION | TYPE_CLAUSE);
 857         emit_time (logbuffer, now);
 858         emit_value (logbuffer, clause_type);
 859         emit_value (logbuffer, clause_num);
 860         emit_method (logbuffer, method);
 861 }
 862
 863 static void
 864 monitor_event (MonoProfiler *profiler, MonoObject *object, MonoProfilerMonitorEvent event)
 865 {
 866         int do_bt = (nocalls && runtime_inited && !notraces && event == MONO_PROFILER_MONITOR_CONTENTION)? TYPE_MONITOR_BT: 0;
 867         uint64_t now;
 868         FrameData data;
 869         LogBuffer *logbuffer;
 870         if (do_bt)
 871                 collect_bt (&data);
 872         logbuffer = ensure_logbuf (16 + MAX_FRAMES * 8);
 873         now = current_time ();
 874         emit_byte (logbuffer, (event << 4) | do_bt | TYPE_MONITOR);
 875         emit_time (logbuffer, now);
 876         emit_obj (logbuffer, object);
 877         if (do_bt)
 878                 emit_bt (logbuffer, &data);
 879 }
 880
 881 static void
 882 thread_start (MonoProfiler *prof, uintptr_t tid)
 883 {
 884         //printf ("thread start %p\n", (void*)tid);
 885         init_thread ();
 886 }
 887
 888 static void
 889 thread_end (MonoProfiler *prof, uintptr_t tid)
 890 {
 891         take_lock ();
 892         if (TLS_GET (tlsbuffer))
 893                 dump_buffer (prof, TLS_GET (tlsbuffer));
 894         release_lock ();
 895         TLS_SET (tlsbuffer, NULL);
 896 }
 897
 898 static void
 899 thread_name (MonoProfiler *prof, uintptr_t tid, const char *name)
 900 {
 901         int len = strlen (name) + 1;
 902         uint64_t now;
 903         LogBuffer *logbuffer;
 904         logbuffer = ensure_logbuf (10 + len);
 905         now = current_time ();
 906         emit_byte (logbuffer, TYPE_METADATA);
 907         emit_time (logbuffer, now);
 908         emit_byte (logbuffer, TYPE_THREAD);
 909         emit_ptr (logbuffer, (void*)tid);
 910         emit_value (logbuffer, 0); /* flags */
 911         memcpy (logbuffer->data, name, len);
 912         logbuffer->data += len;
 913 }
 914
 915 static void
 916 log_shutdown (MonoProfiler *prof)
 917 {
 918         take_lock ();
 919         if (TLS_GET (tlsbuffer))
 920                 dump_buffer (prof, TLS_GET (tlsbuffer));
 921         TLS_SET (tlsbuffer, NULL);
 922         release_lock ();
 923 #if defined (HAVE_ZLIB)
 924         if (prof->gzfile)
 925                 gzclose (prof->gzfile);
 926 #endif
 927         if (prof->pipe_output)
 928                 pclose (prof->file);
 929         else
 930                 fclose (prof->file);
 931         free (prof);
 932 }
 933
 934 static MonoProfiler*
 935 create_profiler (const char *filename)
 936 {
 937         MonoProfiler *prof;
 938         prof = calloc (1, sizeof (MonoProfiler));
 939         if (do_report) /* FIXME: use filename as output */
 940                 filename = "|mprof-report -";
 941
 942         if (!filename)
 943                 filename = "output.mlpd";
 944         if (*filename == '|') {
 945                 prof->file = popen (filename + 1, "w");
 946                 prof->pipe_output = 1;
 947         } else {
 948                 prof->file = fopen (filename, "wb");
 949         }
 950         if (!prof->file) {
 951                 printf ("Cannot create profiler output: %s\n", filename);
 952                 exit (1);
 953         }
 954 #if defined (HAVE_ZLIB)
 955         if (use_zip)
 956                 prof->gzfile = gzdopen (fileno (prof->file), "wb");
 957 #endif
 958         dump_header (prof);
 959         return prof;
 960 }
 961
 962 static void
 963 usage (int do_exit)
 964 {
 965         printf ("Log profiler version %d.%d (format: %d)\n", LOG_VERSION_MAJOR, LOG_VERSION_MINOR, LOG_DATA_VERSION);
 966         printf ("Usage: mono --profile=log[:OPTION1[,OPTION2...]] program.exe\n");
 967         printf ("Options:\n");
 968         printf ("\thelp             show this usage info\n");
 969         printf ("\t[no]alloc        enable/disable recording allocation info\n");
 970         printf ("\t[no]calls        enable/disable recording enter/leave method events\n");
 971         printf ("\theapshot         record heap shot info (by default at each major collection)\n");
 972         printf ("\thsmode=MODE      heapshot mode: every XXms milliseconds or every YYgc collections\n");
 973         printf ("\ttime=fast        use a faster (but more inaccurate) timer\n");
 974         printf ("\tmaxframes=NUM    collect up to NUM stack frames\n");
 975         printf ("\tcalldepth=NUM    ignore method events for call chain depth bigger than NUM\n");
 976         printf ("\toutput=FILENAME  write the data to file FILENAME\n");
 977         printf ("\toutput=|PROGRAM  write the data to the stdin of PROGRAM\n");
 978         printf ("\treport           create a report instead of writing the raw data to a file\n");
 979         printf ("\tzip              compress the output data\n");
 980         if (do_exit)
 981                 exit (1);
 982 }
 983
 984 static const char*
 985 match_option (const char* p, const char *opt, char **rval)
 986 {
 987         int len = strlen (opt);
 988         if (strncmp (p, opt, len) == 0) {
 989                 if (rval) {
 990                         if (p [len] == '=' && p [len + 1]) {
 991                                 const char *opt = p + len + 1;
 992                                 const char *end = strchr (opt, ',');
 993                                 char *val;
 994                                 int l;
 995                                 if (end == NULL) {
 996                                         l = strlen (opt);
 997                                 } else {
 998                                         l = end - opt;
 999                                 }
1000                                 val = malloc (l + 1);
1001                                 memcpy (val, opt, l);
1002                                 val [l] = 0;
1003                                 *rval = val;
1004                                 return opt + l;
1005                         }
1006                         usage (1);
1007                 } else {
1008                         if (p [len] == 0)
1009                                 return p + len;
1010                         if (p [len] == ',')
1011                                 return p + len + 1;
1012                 }
1013         }
1014         return p;
1015 }
1016
1017 /*
1018  * declaration to silence the compiler: this is the entry point that
1019  * mono will load from the shared library and call.
1020  */
1021 extern void
1022 mono_profiler_startup (const char *desc);
1023
1024 void
1025 mono_profiler_startup (const char *desc)
1026 {
1027         MonoProfiler *prof;
1028         char *filename = NULL;
1029         const char *p;
1030         const char *opt;
1031         int fast_time = 0;
1032         int calls_enabled = 0;
1033         int allocs_enabled = 0;
1034         int events = MONO_PROFILE_GC|MONO_PROFILE_ALLOCATIONS|
1035                 MONO_PROFILE_GC_MOVES|MONO_PROFILE_CLASS_EVENTS|MONO_PROFILE_THREADS|
1036                 MONO_PROFILE_ENTER_LEAVE|MONO_PROFILE_JIT_COMPILATION|MONO_PROFILE_EXCEPTIONS|
1037                 MONO_PROFILE_MONITOR_EVENTS|MONO_PROFILE_MODULE_EVENTS|MONO_PROFILE_GC_ROOTS;
1038
1039         p = desc;
1040         if (strncmp (p, "log", 3))
1041                 usage (1);
1042         p += 3;
1043         if (*p == ':')
1044                 p++;
1045         for (; *p; p = opt) {
1046                 char *val;
1047                 if (*p == ',') {
1048                         opt = p + 1;
1049                         continue;
1050                 }
1051                 if ((opt = match_option (p, "help", NULL)) != p) {
1052                         usage (0);
1053                         continue;
1054                 }
1055                 if ((opt = match_option (p, "calls", NULL)) != p) {
1056                         calls_enabled = 1;
1057                         continue;
1058                 }
1059                 if ((opt = match_option (p, "nocalls", NULL)) != p) {
1060                         events &= ~MONO_PROFILE_ENTER_LEAVE;
1061                         nocalls = 1;
1062                         continue;
1063                 }
1064                 if ((opt = match_option (p, "alloc", NULL)) != p) {
1065                         allocs_enabled = 1;
1066                         continue;
1067                 }
1068                 if ((opt = match_option (p, "noalloc", NULL)) != p) {
1069                         events &= ~MONO_PROFILE_ALLOCATIONS;
1070                         continue;
1071                 }
1072                 if ((opt = match_option (p, "time", &val)) != p) {
1073                         if (strcmp (val, "fast") == 0)
1074                                 fast_time = 1;
1075                         else if (strcmp (val, "null") == 0)
1076                                 fast_time = 2;
1077                         else
1078                                 usage (1);
1079                         free (val);
1080                         continue;
1081                 }
1082                 if ((opt = match_option (p, "report", NULL)) != p) {
1083                         do_report = 1;
1084                         continue;
1085                 }
1086                 if ((opt = match_option (p, "heapshot", NULL)) != p) {
1087                         events &= ~MONO_PROFILE_ALLOCATIONS;
1088                         events &= ~MONO_PROFILE_ENTER_LEAVE;
1089                         nocalls = 1;
1090                         do_heap_shot = 1;
1091                         continue;
1092                 }
1093                 if ((opt = match_option (p, "hsmode", &val)) != p) {
1094                         char *end;
1095                         unsigned int count = strtoul (val, &end, 10);
1096                         if (val == end)
1097                                 usage (1);
1098                         if (strcmp (end, "ms") == 0)
1099                                 hs_mode_ms = count;
1100                         else if (strcmp (end, "gc") == 0)
1101                                 hs_mode_gc = count;
1102                         else
1103                                 usage (1);
1104                         free (val);
1105                         continue;
1106                 }
1107                 if ((opt = match_option (p, "zip", NULL)) != p) {
1108                         use_zip = 1;
1109                         continue;
1110                 }
1111                 if ((opt = match_option (p, "output", &val)) != p) {
1112                         filename = val;
1113                         continue;
1114                 }
1115                 if ((opt = match_option (p, "maxframes", &val)) != p) {
1116                         char *end;
1117                         num_frames = strtoul (val, &end, 10);
1118                         if (num_frames > MAX_FRAMES)
1119                                 num_frames = MAX_FRAMES;
1120                         free (val);
1121                         notraces = num_frames == 0;
1122                         continue;
1123                 }
1124                 if ((opt = match_option (p, "calldepth", &val)) != p) {
1125                         char *end;
1126                         max_call_depth = strtoul (val, &end, 10);
1127                         free (val);
1128                         continue;
1129                 }
1130                 if (opt == p) {
1131                         usage (0);
1132                         exit (0);
1133                 }
1134         }
1135         if (calls_enabled) {
1136                 events |= MONO_PROFILE_ENTER_LEAVE;
1137                 nocalls = 0;
1138         }
1139         if (allocs_enabled)
1140                 events |= MONO_PROFILE_ALLOCATIONS;
1141         utils_init (fast_time);
1142
1143         prof = create_profiler (filename);
1144         init_thread ();
1145
1146         mono_profiler_install (prof, log_shutdown);
1147         mono_profiler_install_gc (gc_event, gc_resize);
1148         mono_profiler_install_allocation (gc_alloc);
1149         mono_profiler_install_gc_moves (gc_moves);
1150         mono_profiler_install_gc_roots (gc_handle);
1151         mono_profiler_install_class (NULL, class_loaded, NULL, NULL);
1152         mono_profiler_install_module (NULL, image_loaded, NULL, NULL);
1153         mono_profiler_install_thread (thread_start, thread_end);
1154         mono_profiler_install_thread_name (thread_name);
1155         mono_profiler_install_enter_leave (method_enter, method_leave);
1156         mono_profiler_install_jit_end (method_jitted);
1157         mono_profiler_install_exception (throw_exc, method_exc_leave, clause_exc);
1158         mono_profiler_install_monitor (monitor_event);
1159         mono_profiler_install_runtime_initialized (runtime_initialized);
1160
1161         mono_profiler_set_events (events);
1162
1163         TLS_INIT (tlsbuffer);
1164 }
1165