2 * proflog.c: mono log profiler
5 * Paolo Molaro (lupus@ximian.com)
7 * Copyright 2010 Novell, Inc (http://www.novell.com)
11 #include <mono/metadata/profiler.h>
12 #include <mono/metadata/mono-gc.h>
13 #include <mono/metadata/debug-helpers.h>
29 #if defined (HAVE_ZLIB)
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;
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`
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`
51 * sudo cp mprof-report /usr/local/bin
52 * sudo cp libmono-profiler-log.so /usr/local/lib
56 typedef struct _LogBuffer LogBuffer;
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,
67 * Buffers are not required to be aligned.
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
80 * The multiple byte integers are in little-endian 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.
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.
96 * Object or heap sizes are stored as uleb128.
97 * Pointer differences are stored as sleb128, instead.
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.
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
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.
121 * [flags: uleb128] must be 0
122 * [num: uleb128] number of frames following
123 * [frame: sleb128]* num MonoMethod pointers as differences from ptr_base
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.
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
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,
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
177 * type method format:
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
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.
201 * type monitor format:
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.
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
229 uintptr_t method_base;
230 uintptr_t last_method;
233 unsigned char* data_end;
237 unsigned char buf [1];
240 struct _MonoProfiler {
243 #if defined (HAVE_ZLIB)
247 int last_gc_gen_started;
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;
256 #define TLS_SET(x,y) x = y
259 static __thread LogBuffer* tlsbuffer = NULL;
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;
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;
282 LogBuffer *logbuffer;
283 if (TLS_GET (tlsbuffer))
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);
292 ensure_logbuf (int bytes)
294 LogBuffer *old = TLS_GET (tlsbuffer);
295 if (old && old->data + bytes + 100 < old->data_end)
297 TLS_SET (tlsbuffer, NULL);
299 TLS_GET (tlsbuffer)->next = old;
301 TLS_GET (tlsbuffer)->call_depth = old->call_depth;
302 //printf ("new logbuffer\n");
303 return TLS_GET (tlsbuffer);
307 emit_byte (LogBuffer *logbuffer, int value)
309 logbuffer->data [0] = value;
311 assert (logbuffer->data <= logbuffer->data_end);
315 emit_value (LogBuffer *logbuffer, int value)
317 encode_uleb128 (value, logbuffer->data, &logbuffer->data);
318 assert (logbuffer->data <= logbuffer->data_end);
322 emit_time (LogBuffer *logbuffer, uint64_t value)
324 uint64_t tdiff = value - logbuffer->last_time;
326 if (value < logbuffer->last_time)
327 printf ("time went backwards\n");
328 //if (tdiff > 1000000)
329 // printf ("large time offset: %llu\n", tdiff);
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);
339 emit_svalue (LogBuffer *logbuffer, int64_t value)
341 encode_sleb128 (value, logbuffer->data, &logbuffer->data);
342 assert (logbuffer->data <= logbuffer->data_end);
346 emit_ptr (LogBuffer *logbuffer, void *ptr)
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);
355 emit_method (LogBuffer *logbuffer, void *method)
357 if (!logbuffer->method_base) {
358 logbuffer->method_base = (intptr_t)method;
359 logbuffer->last_method = (intptr_t)method;
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);
367 emit_obj (LogBuffer *logbuffer, void *ptr)
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);
376 write_int32 (char *buf, int32_t value)
379 for (i = 0; i < 4; ++i) {
387 write_int64 (char *buf, int64_t value)
390 for (i = 0; i < 8; ++i) {
398 dump_header (MonoProfiler *profiler)
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);
416 fwrite (hbuf, p - hbuf, 1, profiler->file);
419 fwrite (hbuf, p - hbuf, 1, profiler->file);
424 dump_buffer (MonoProfiler *profiler, LogBuffer *buf)
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);
443 fwrite (hbuf, p - hbuf, 1, profiler->file);
444 fwrite (buf->buf, buf->data - buf->buf, 1, profiler->file);
445 #if defined (HAVE_ZLIB)
448 free_buffer (buf, buf->size);
452 runtime_initialized (MonoProfiler *profiler)
458 * Can be called only at safe callback locations.
461 safe_dump (MonoProfiler *profiler, LogBuffer *logbuffer)
463 int cd = logbuffer->call_depth;
465 dump_buffer (profiler, TLS_GET (tlsbuffer));
467 TLS_SET (tlsbuffer, NULL);
469 TLS_GET (tlsbuffer)->call_depth = cd;
473 gc_reference (MonoObject *obj, MonoClass *klass, uintptr_t size, uintptr_t num, MonoObject **refs, void *data)
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 */
484 emit_value (logbuffer, size);
485 emit_value (logbuffer, num);
486 for (i = 0; i < num; ++i)
487 emit_obj (logbuffer, refs [i]);
489 // printf ("obj: %p, klass: %s, refs: %d, size: %d\n", obj, name, (int)num, (int)size);
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;
499 heap_walk (MonoProfiler *profiler)
503 LogBuffer *logbuffer;
506 logbuffer = ensure_logbuf (10);
507 now = current_time ();
508 if (hs_mode_ms && (now - last_hs_time)/1000000 >= hs_mode_ms)
510 else if (hs_mode_gc && (gc_count % hs_mode_gc) == 0)
512 else if (!hs_mode_ms && !hs_mode_gc && profiler->last_gc_gen_started == mono_gc_max_generation ())
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);
527 gc_event (MonoProfiler *profiler, MonoGCEvent ev, int generation) {
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;
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);
548 gc_resize (MonoProfiler *profiler, int64_t new_size) {
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);
558 #define MAX_FRAMES 16
561 MonoMethod* methods [MAX_FRAMES];
563 static int num_frames = MAX_FRAMES / 2;
566 walk_stack (MonoMethod *method, int32_t native_offset, int32_t il_offset, mono_bool managed, void* data)
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));
573 return frame->count == num_frames;
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.
582 collect_bt (FrameData *data)
585 mono_stack_walk_no_il (walk_stack, data);
589 emit_bt (LogBuffer *logbuffer, FrameData *data)
591 /* FIXME: this is actually tons of data and we should
592 * just output it the first time and use an id the next
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]);
606 gc_alloc (MonoProfiler *prof, MonoObject *obj, MonoClass *klass)
610 int do_bt = (nocalls && runtime_inited && !notraces)? TYPE_ALLOC_BT: 0;
612 LogBuffer *logbuffer;
613 len = mono_object_get_size (obj);
614 /* account for object alignment in the heap */
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);
627 emit_bt (logbuffer, &data);
629 safe_dump (prof, logbuffer);
630 //printf ("gc alloc %s at %p\n", mono_class_get_name (klass), obj);
634 gc_moves (MonoProfiler *prof, void **objects, int num)
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);
649 gc_handle (MonoProfiler *prof, int op, int type, uintptr_t handle, MonoObject *obj)
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);
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);
668 push_nesting (char *p, MonoClass *klass)
673 nesting = mono_class_get_nesting_type (klass);
675 p = push_nesting (p, nesting);
679 name = mono_class_get_name (klass);
680 nspace = mono_class_get_namespace (klass);
683 p += strlen (nspace);
693 type_name (MonoClass *klass)
697 push_nesting (buf, klass);
698 p = malloc (strlen (buf) + 1);
704 image_loaded (MonoProfiler *prof, MonoImage *image, int result)
709 LogBuffer *logbuffer;
710 if (result != MONO_PROFILE_OK)
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);
725 safe_dump (prof, logbuffer);
729 class_loaded (MonoProfiler *prof, MonoClass *klass, int result)
735 LogBuffer *logbuffer;
736 if (result != MONO_PROFILE_OK)
739 name = mono_type_get_name (mono_class_get_type (klass));
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);
760 safe_dump (prof, logbuffer);
764 method_enter (MonoProfiler *prof, MonoMethod *method)
767 LogBuffer *logbuffer = ensure_logbuf (16);
768 if (logbuffer->call_depth++ > max_call_depth)
770 now = current_time ();
771 emit_byte (logbuffer, TYPE_ENTER | TYPE_METHOD);
772 emit_time (logbuffer, now);
773 emit_method (logbuffer, method);
777 method_leave (MonoProfiler *prof, MonoMethod *method)
780 LogBuffer *logbuffer = ensure_logbuf (16);
781 if (--logbuffer->call_depth > max_call_depth)
783 now = current_time ();
784 emit_byte (logbuffer, TYPE_LEAVE | TYPE_METHOD);
785 emit_time (logbuffer, now);
786 emit_method (logbuffer, method);
788 safe_dump (prof, logbuffer);
792 method_exc_leave (MonoProfiler *prof, MonoMethod *method)
795 LogBuffer *logbuffer;
798 logbuffer = ensure_logbuf (16);
799 if (--logbuffer->call_depth > max_call_depth)
801 now = current_time ();
802 emit_byte (logbuffer, TYPE_EXC_LEAVE | TYPE_METHOD);
803 emit_time (logbuffer, now);
804 emit_method (logbuffer, method);
808 method_jitted (MonoProfiler *prof, MonoMethod *method, MonoJitInfo* jinfo, int result)
813 LogBuffer *logbuffer;
814 if (result != MONO_PROFILE_OK)
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;
829 safe_dump (prof, logbuffer);
833 throw_exc (MonoProfiler *prof, MonoObject *object)
835 int do_bt = (nocalls && runtime_inited && !notraces)? TYPE_EXCEPTION_BT: 0;
838 LogBuffer *logbuffer;
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);
847 emit_bt (logbuffer, &data);
851 clause_exc (MonoProfiler *prof, MonoMethod *method, int clause_type, int clause_num)
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);
864 monitor_event (MonoProfiler *profiler, MonoObject *object, MonoProfilerMonitorEvent event)
866 int do_bt = (nocalls && runtime_inited && !notraces && event == MONO_PROFILER_MONITOR_CONTENTION)? TYPE_MONITOR_BT: 0;
869 LogBuffer *logbuffer;
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);
878 emit_bt (logbuffer, &data);
882 thread_start (MonoProfiler *prof, uintptr_t tid)
884 //printf ("thread start %p\n", (void*)tid);
889 thread_end (MonoProfiler *prof, uintptr_t tid)
892 if (TLS_GET (tlsbuffer))
893 dump_buffer (prof, TLS_GET (tlsbuffer));
895 TLS_SET (tlsbuffer, NULL);
899 thread_name (MonoProfiler *prof, uintptr_t tid, const char *name)
901 int len = strlen (name) + 1;
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;
916 log_shutdown (MonoProfiler *prof)
919 if (TLS_GET (tlsbuffer))
920 dump_buffer (prof, TLS_GET (tlsbuffer));
921 TLS_SET (tlsbuffer, NULL);
923 #if defined (HAVE_ZLIB)
925 gzclose (prof->gzfile);
927 if (prof->pipe_output)
935 create_profiler (const char *filename)
938 prof = calloc (1, sizeof (MonoProfiler));
939 if (do_report) /* FIXME: use filename as output */
940 filename = "|mprof-report -";
943 filename = "output.mlpd";
944 if (*filename == '|') {
945 prof->file = popen (filename + 1, "w");
946 prof->pipe_output = 1;
948 prof->file = fopen (filename, "wb");
951 printf ("Cannot create profiler output: %s\n", filename);
954 #if defined (HAVE_ZLIB)
956 prof->gzfile = gzdopen (fileno (prof->file), "wb");
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");
985 match_option (const char* p, const char *opt, char **rval)
987 int len = strlen (opt);
988 if (strncmp (p, opt, len) == 0) {
990 if (p [len] == '=' && p [len + 1]) {
991 const char *opt = p + len + 1;
992 const char *end = strchr (opt, ',');
1000 val = malloc (l + 1);
1001 memcpy (val, opt, l);
1018 * declaration to silence the compiler: this is the entry point that
1019 * mono will load from the shared library and call.
1022 mono_profiler_startup (const char *desc);
1025 mono_profiler_startup (const char *desc)
1028 char *filename = NULL;
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;
1040 if (strncmp (p, "log", 3))
1045 for (; *p; p = opt) {
1051 if ((opt = match_option (p, "help", NULL)) != p) {
1055 if ((opt = match_option (p, "calls", NULL)) != p) {
1059 if ((opt = match_option (p, "nocalls", NULL)) != p) {
1060 events &= ~MONO_PROFILE_ENTER_LEAVE;
1064 if ((opt = match_option (p, "alloc", NULL)) != p) {
1068 if ((opt = match_option (p, "noalloc", NULL)) != p) {
1069 events &= ~MONO_PROFILE_ALLOCATIONS;
1072 if ((opt = match_option (p, "time", &val)) != p) {
1073 if (strcmp (val, "fast") == 0)
1075 else if (strcmp (val, "null") == 0)
1082 if ((opt = match_option (p, "report", NULL)) != p) {
1086 if ((opt = match_option (p, "heapshot", NULL)) != p) {
1087 events &= ~MONO_PROFILE_ALLOCATIONS;
1088 events &= ~MONO_PROFILE_ENTER_LEAVE;
1093 if ((opt = match_option (p, "hsmode", &val)) != p) {
1095 unsigned int count = strtoul (val, &end, 10);
1098 if (strcmp (end, "ms") == 0)
1100 else if (strcmp (end, "gc") == 0)
1107 if ((opt = match_option (p, "zip", NULL)) != p) {
1111 if ((opt = match_option (p, "output", &val)) != p) {
1115 if ((opt = match_option (p, "maxframes", &val)) != p) {
1117 num_frames = strtoul (val, &end, 10);
1118 if (num_frames > MAX_FRAMES)
1119 num_frames = MAX_FRAMES;
1121 notraces = num_frames == 0;
1124 if ((opt = match_option (p, "calldepth", &val)) != p) {
1126 max_call_depth = strtoul (val, &end, 10);
1135 if (calls_enabled) {
1136 events |= MONO_PROFILE_ENTER_LEAVE;
1140 events |= MONO_PROFILE_ALLOCATIONS;
1141 utils_init (fast_time);
1143 prof = create_profiler (filename);
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);
1161 mono_profiler_set_events (events);
1163 TLS_INIT (tlsbuffer);