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