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>
16 #if defined (HAVE_ZLIB)
29 #define BUFFER_SIZE (4096 * 16)
30 static int nocalls = 0;
31 static int notraces = 0;
32 static int use_zip = 0;
33 static int do_report = 0;
34 static int do_heap_shot = 0;
35 static int max_call_depth = 100;
36 static int runtime_inited = 0;
38 /* For linux compile with:
39 * gcc -fPIC -shared -o libmono-profiler-log.so proflog.c utils.c -Wall -g -lz `pkg-config --cflags --libs mono-2`
40 * gcc -o mprof-report decode.c utils.c -Wall -g -lz -lrt -lpthread `pkg-config --cflags mono-2`
42 * For osx compile with:
43 * 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
44 * gcc -m32 -o mprof-report decode.c utils.c -Wall -g -lz -lrt -lpthread `pkg-config --cflags mono-2`
47 * sudo cp mprof-report /usr/local/bin
48 * sudo cp libmono-profiler-log.so /usr/local/lib
52 typedef struct _LogBuffer LogBuffer;
58 * The file is composed by a header followed by 0 or more buffers.
59 * Each buffer contains events that happened on a thread: for a given thread
60 * buffers that appear later in the file are guaranteed to contain events
61 * that happened later in time. Buffers from separate threads could be interleaved,
63 * Buffers are not required to be aligned.
66 * [id: 4 bytes] constant value: LOG_HEADER_ID
67 * [major: 1 byte] [minor: 1 byte] major and minor version of the log profiler
68 * [format: 1 byte] version of the data format for the rest of the file
69 * [ptrsize: 1 byte] size in bytes of a pointer in the profiled program
70 * [startup time: 8 bytes] time in milliseconds since the unix epoch when the program started
71 * [timer overhead: 4 bytes] approximate overhead in nanoseconds of the timer
72 * [flags: 4 bytes] file format flags, should be 0 for now
73 * [pid: 4 bytes] pid of the profiled process
74 * [sysid: 4 bytes] operating system and architecture identifier
76 * The multiple byte integers are in little-endian format.
79 * [buffer header] [event]*
80 * Buffers have a fixed-size header followed by 0 or more bytes of event data.
81 * Timing information and other values in the event data are usually stored
82 * as uleb128 or sleb128 integers. To save space, as noted for each item below,
83 * some data is represented as a difference between the actual value and
84 * either the last value of the same type (like for timing information) or
85 * as the difference from a value stored in a buffer header.
87 * For timing information the data is stored as uleb128, since timing
88 * increases in a monotonic way in each thread: the value is the number of
89 * nanoseconds to add to the last seen timing data in a buffer. The first value
90 * in a buffer will be calculated from the time_base field in the buffer head.
92 * Object or heap sizes are stored as uleb128.
93 * Pointer differences are stored as sleb128, instead.
95 * If an unexpected value is found, the rest of the buffer should be ignored,
96 * as generally the later values need the former to be interpreted correctly.
98 * buffer header format:
99 * [bufid: 4 bytes] constant value: BUF_ID
100 * [len: 4 bytes] size of the data following the buffer header
101 * [time_base: 8 bytes] time base in nanoseconds since an unspecified epoch
102 * [ptr_base: 8 bytes] base value for pointers
103 * [obj_base: 8 bytes] base value for object addresses
104 * [thread id: 8 bytes] system-specific thread ID (pthread_t for example)
105 * [method_base: 8 bytes] base value for MonoMethod pointers
108 * [extended info: upper 4 bits] [type: lower 4 bits] [data]*
109 * The data that follows depends on type and the extended info.
110 * Type is one of the enum values in proflog.h: TYPE_ALLOC, TYPE_GC,
111 * TYPE_METADATA, TYPE_METHOD, TYPE_EXCEPTION, TYPE_MONITOR, TYPE_HEAP.
112 * The extended info bits are interpreted based on type, see
113 * each individual event description below.
114 * strings are represented as a 0-terminated utf8 sequence.
117 * [flags: uleb128] must be 0
118 * [num: uleb128] number of frames following
119 * [frame: sleb128]* num MonoMethod pointers as differences from ptr_base
123 * exinfo: flags: TYPE_ALLOC_BT
124 * [time diff: uleb128] nanoseconds since last timing
125 * [ptr: sleb128] class as a byte difference from ptr_base
126 * [obj: sleb128] object address as a byte difference from obj_base
127 * [size: uleb128] size of the object in the heap
128 * If the TYPE_ALLOC_BT flag is set, a backtrace follows.
132 * exinfo: one of TYPE_GC_EVENT, TYPE_GC_RESIZE, TYPE_GC_MOVE
133 * [time diff: uleb128] nanoseconds since last timing
134 * if exinfo == TYPE_GC_RESIZE
135 * [heap_size: uleb128] new heap size
136 * if exinfo == TYPE_GC_EVENT
137 * [event type: uleb128] GC event (MONO_GC_EVENT_* from profiler.h)
138 * [generation: uleb128] GC generation event refers to
139 * if exinfo == TYPE_GC_MOVE
140 * [num_objects: uleb128] number of object moves that follow
141 * [objaddr: sleb128]+ num_objects object pointer differences from obj_base
142 * num is always an even number: the even items are the old
143 * addresses, the odd numbers are the respective new object addresses
145 * type metadata format:
146 * type: TYPE_METADATA
147 * exinfo: flags: TYPE_LOAD_ERR
148 * [time diff: uleb128] nanoseconds since last timing
149 * [mtype: byte] metadata type, one of: TYPE_CLASS, TYPE_IMAGE, TYPE_ASSEMBLY, TYPE_DOMAIN
150 * [pointer: sleb128] pointer of the metadata type depending on mtype
151 * if mtype == TYPE_CLASS
152 * [image: sleb128] MonoImage* as a pointer difference from ptr_base
153 * [flags: uleb128] must be 0
154 * [name: string] full class name
155 * if mtype == TYPE_IMAGE
156 * [flags: uleb128] must be 0
157 * [name: string] image file name
159 * type method format:
161 * exinfo: one of: TYPE_LEAVE, TYPE_ENTER, TYPE_EXC_LEAVE, TYPE_JIT
162 * [time diff: uleb128] nanoseconds since last timing
163 * [method: sleb128] MonoMethod* as a pointer difference from the last such
164 * pointer or the buffer method_base
165 * if exinfo == TYPE_JIT
166 * [code address: sleb128] pointer to the native code as a diff from ptr_base
167 * [code size: uleb128] size of the generated code
168 * [name: string] full method name
170 * type exception format:
171 * type: TYPE_EXCEPTION
172 * exinfo: TYPE_EXCEPTION_BT flag and one of: TYPE_THROW, TYPE_CLAUSE
173 * [time diff: uleb128] nanoseconds since last timing
174 * if exinfo.low3bits == TYPE_CLAUSE
175 * [clause type: uleb128] finally/catch/fault/filter
176 * [clause num: uleb128] the clause number in the method header
177 * [method: sleb128] MonoMethod* as a pointer difference from the last such
178 * pointer or the buffer method_base
179 * if exinfo.low3bits == TYPE_THROW
180 * [object: sleb128] the object that was thrown as a difference from obj_base
181 * If the TYPE_EXCEPTION_BT flag is set, a backtrace follows.
183 * type monitor format:
185 * exinfo: TYPE_MONITOR_BT flag and one of: MONO_PROFILER_MONITOR_(CONTENTION|FAIL|DONE)
186 * [time diff: uleb128] nanoseconds since last timing
187 * [object: sleb128] the lock object as a difference from obj_base
188 * if exinfo.low3bits == MONO_PROFILER_MONITOR_CONTENTION
189 * If the TYPE_MONITOR_BT flag is set, a backtrace follows.
193 * exinfo: one of TYPE_HEAP_START, TYPE_HEAP_END, TYPE_HEAP_OBJECT
194 * if exinfo == TYPE_HEAP_START
195 * [time diff: uleb128] nanoseconds since last timing
196 * if exinfo == TYPE_HEAP_END
197 * [time diff: uleb128] nanoseconds since last timing
198 * if exinfo == TYPE_HEAP_OBJECT
199 * [object: sleb128] the object as a difference from obj_base
200 * [class: sleb128] the object MonoClass* as a difference from ptr_base
201 * [size: uleb128] size of the object on the heap
202 * [num_refs: uleb128] number of object references
203 * [objrefs: sleb128]+ object referenced as a difference from obj_base
211 uintptr_t method_base;
212 uintptr_t last_method;
215 unsigned char* data_end;
219 unsigned char buf [1];
222 struct _MonoProfiler {
225 #if defined (HAVE_ZLIB)
229 int last_gc_gen_started;
233 #define TLS_SET(x,y) TlsSetValue(x, y)
234 #define TLS_GET(x) ((LogBuffer *) TlsGetValue(x))
235 #define TLS_INIT(x) x = TlsAlloc ()
236 static int tlsbuffer;
238 #define TLS_SET(x,y) x = y
241 static __thread LogBuffer* tlsbuffer = NULL;
243 #define TLS_SET(x,y) pthread_setspecific(x, y)
244 #define TLS_GET(x) ((LogBuffer *) pthread_getspecific(x))
245 #define TLS_INIT(x) pthread_key_create(&x, NULL)
246 static pthread_key_t tlsbuffer;
252 LogBuffer* buf = alloc_buffer (BUFFER_SIZE);
253 buf->size = BUFFER_SIZE;
254 buf->time_base = current_time ();
255 buf->last_time = buf->time_base;
256 buf->data_end = (unsigned char*)buf + buf->size;
257 buf->data = buf->buf;
264 LogBuffer *logbuffer;
265 if (TLS_GET (tlsbuffer))
267 logbuffer = create_buffer ();
268 TLS_SET (tlsbuffer, logbuffer);
269 logbuffer->thread_id = thread_id ();
270 //printf ("thread %p at time %llu\n", (void*)logbuffer->thread_id, logbuffer->time_base);
274 ensure_logbuf (int bytes)
276 LogBuffer *old = TLS_GET (tlsbuffer);
277 if (old && old->data + bytes + 100 < old->data_end)
279 TLS_SET (tlsbuffer, NULL);
281 TLS_GET (tlsbuffer)->next = old;
283 TLS_GET (tlsbuffer)->call_depth = old->call_depth;
284 //printf ("new logbuffer\n");
285 return TLS_GET (tlsbuffer);
289 emit_byte (LogBuffer *logbuffer, int value)
291 logbuffer->data [0] = value;
293 assert (logbuffer->data <= logbuffer->data_end);
297 emit_value (LogBuffer *logbuffer, int value)
299 encode_uleb128 (value, logbuffer->data, &logbuffer->data);
300 assert (logbuffer->data <= logbuffer->data_end);
304 emit_time (LogBuffer *logbuffer, uint64_t value)
306 uint64_t tdiff = value - logbuffer->last_time;
308 if (value < logbuffer->last_time)
309 printf ("time went backwards\n");
310 //if (tdiff > 1000000)
311 // printf ("large time offset: %llu\n", tdiff);
313 encode_uleb128 (tdiff, logbuffer->data, &logbuffer->data);
314 /*if (tdiff != decode_uleb128 (p, &p))
315 printf ("incorrect encoding: %llu\n", tdiff);*/
316 logbuffer->last_time = value;
317 assert (logbuffer->data <= logbuffer->data_end);
321 emit_svalue (LogBuffer *logbuffer, int64_t value)
323 encode_sleb128 (value, logbuffer->data, &logbuffer->data);
324 assert (logbuffer->data <= logbuffer->data_end);
328 emit_ptr (LogBuffer *logbuffer, void *ptr)
330 if (!logbuffer->ptr_base)
331 logbuffer->ptr_base = (uintptr_t)ptr;
332 emit_svalue (logbuffer, (intptr_t)ptr - logbuffer->ptr_base);
333 assert (logbuffer->data <= logbuffer->data_end);
337 emit_method (LogBuffer *logbuffer, void *method)
339 if (!logbuffer->method_base) {
340 logbuffer->method_base = (intptr_t)method;
341 logbuffer->last_method = (intptr_t)method;
343 encode_sleb128 ((intptr_t)((char*)method - (char*)logbuffer->last_method), logbuffer->data, &logbuffer->data);
344 logbuffer->last_method = (intptr_t)method;
345 assert (logbuffer->data <= logbuffer->data_end);
349 emit_obj (LogBuffer *logbuffer, void *ptr)
351 if (!logbuffer->obj_base)
352 logbuffer->obj_base = (uintptr_t)ptr >> 3;
353 emit_svalue (logbuffer, ((uintptr_t)ptr >> 3) - logbuffer->obj_base);
354 assert (logbuffer->data <= logbuffer->data_end);
358 write_int32 (char *buf, int32_t value)
361 for (i = 0; i < 4; ++i) {
369 write_int64 (char *buf, int64_t value)
372 for (i = 0; i < 8; ++i) {
380 dump_header (MonoProfiler *profiler)
384 p = write_int32 (p, LOG_HEADER_ID);
385 *p++ = LOG_VERSION_MAJOR;
386 *p++ = LOG_VERSION_MINOR;
387 *p++ = LOG_DATA_VERSION;
388 *p++ = sizeof (void*);
389 p = write_int64 (p, ((uint64_t)time (NULL)) * 1000); /* startup time */
390 p = write_int32 (p, get_timer_overhead ()); /* timer overhead */
391 p = write_int32 (p, 0); /* flags */
392 p = write_int32 (p, 0); /* pid */
393 p = write_int32 (p, 0); /* opsystem */
394 #if defined (HAVE_ZLIB)
395 if (profiler->gzfile) {
396 gzwrite (profiler->gzfile, hbuf, p - hbuf);
398 fwrite (hbuf, p - hbuf, 1, profiler->file);
401 fwrite (hbuf, p - hbuf, 1, profiler->file);
406 dump_buffer (MonoProfiler *profiler, LogBuffer *buf)
411 dump_buffer (profiler, buf->next);
412 p = write_int32 (p, BUF_ID);
413 p = write_int32 (p, buf->data - buf->buf);
414 p = write_int64 (p, buf->time_base);
415 p = write_int64 (p, buf->ptr_base);
416 p = write_int64 (p, buf->obj_base);
417 p = write_int64 (p, buf->thread_id);
418 p = write_int64 (p, buf->method_base);
419 #if defined (HAVE_ZLIB)
420 if (profiler->gzfile) {
421 gzwrite (profiler->gzfile, hbuf, p - hbuf);
422 gzwrite (profiler->gzfile, buf->buf, buf->data - buf->buf);
425 fwrite (hbuf, p - hbuf, 1, profiler->file);
426 fwrite (buf->buf, buf->data - buf->buf, 1, profiler->file);
427 #if defined (HAVE_ZLIB)
430 free_buffer (buf, buf->size);
434 runtime_initialized (MonoProfiler *profiler)
440 * Can be called only at safe callback locations.
443 safe_dump (MonoProfiler *profiler, LogBuffer *logbuffer)
445 int cd = logbuffer->call_depth;
447 dump_buffer (profiler, TLS_GET (tlsbuffer));
449 TLS_SET (tlsbuffer, NULL);
451 TLS_GET (tlsbuffer)->call_depth = cd;
455 gc_reference (MonoObject *obj, MonoClass *klass, uintptr_t size, uintptr_t num, MonoObject **refs, void *data)
458 //const char *name = mono_class_get_name (klass);
459 LogBuffer *logbuffer = ensure_logbuf (20 + num * 8);
460 emit_byte (logbuffer, TYPE_HEAP_OBJECT | TYPE_HEAP);
461 emit_obj (logbuffer, obj);
462 emit_ptr (logbuffer, klass);
463 /* account for object alignment in the heap */
466 emit_value (logbuffer, size);
467 emit_value (logbuffer, num);
468 for (i = 0; i < num; ++i)
469 emit_obj (logbuffer, refs [i]);
471 // printf ("obj: %p, klass: %s, refs: %d, size: %d\n", obj, name, (int)num, (int)size);
475 static unsigned int hs_mode_ms = 0;
476 static unsigned int hs_mode_gc = 0;
477 static unsigned int gc_count = 0;
478 static uint64_t last_hs_time = 0;
481 heap_walk (MonoProfiler *profiler)
485 LogBuffer *logbuffer;
488 logbuffer = ensure_logbuf (10);
489 now = current_time ();
490 if (hs_mode_ms && (now - last_hs_time)/1000000 >= hs_mode_ms)
492 else if (hs_mode_gc && (gc_count % hs_mode_gc) == 0)
494 else if (!hs_mode_ms && !hs_mode_gc && profiler->last_gc_gen_started == mono_gc_max_generation ())
499 emit_byte (logbuffer, TYPE_HEAP_START | TYPE_HEAP);
500 emit_time (logbuffer, now);
501 mono_gc_walk_heap (0, gc_reference, NULL);
502 logbuffer = ensure_logbuf (10);
503 now = current_time ();
504 emit_byte (logbuffer, TYPE_HEAP_END | TYPE_HEAP);
505 emit_time (logbuffer, now);
509 gc_event (MonoProfiler *profiler, MonoGCEvent ev, int generation) {
511 LogBuffer *logbuffer = ensure_logbuf (10);
512 now = current_time ();
513 emit_byte (logbuffer, TYPE_GC_EVENT | TYPE_GC);
514 emit_time (logbuffer, now);
515 emit_value (logbuffer, ev);
516 emit_value (logbuffer, generation);
517 /* to deal with nested gen1 after gen0 started */
518 if (ev == MONO_GC_EVENT_START) {
519 profiler->last_gc_gen_started = generation;
522 if (ev == MONO_GC_EVENT_PRE_START_WORLD)
523 heap_walk (profiler);
524 if (ev == MONO_GC_EVENT_POST_START_WORLD)
525 safe_dump (profiler, logbuffer);
526 //printf ("gc event %d for generation %d\n", ev, generation);
530 gc_resize (MonoProfiler *profiler, int64_t new_size) {
532 LogBuffer *logbuffer = ensure_logbuf (10);
533 now = current_time ();
534 emit_byte (logbuffer, TYPE_GC_RESIZE | TYPE_GC);
535 emit_time (logbuffer, now);
536 emit_value (logbuffer, new_size);
537 //printf ("gc resized to %lld\n", new_size);
540 #define MAX_FRAMES 16
543 MonoMethod* methods [MAX_FRAMES];
545 static int num_frames = MAX_FRAMES / 2;
548 walk_stack (MonoMethod *method, int32_t native_offset, int32_t il_offset, mono_bool managed, void* data)
550 FrameData *frame = data;
551 if (method && frame->count < num_frames) {
552 frame->methods [frame->count++] = method;
553 //printf ("In %d %s\n", frame->count, mono_method_get_name (method));
555 return frame->count == num_frames;
559 * a note about stack walks: they can cause more profiler events to fire,
560 * so we need to make sure they don't happen after we started emitting an
561 * event, hence the collect_bt/emit_bt split.
564 collect_bt (FrameData *data)
567 mono_stack_walk_no_il (walk_stack, data);
571 emit_bt (LogBuffer *logbuffer, FrameData *data)
573 /* FIXME: this is actually tons of data and we should
574 * just output it the first time and use an id the next
576 if (data->count > num_frames)
577 printf ("bad num frames: %d\n", data->count);
578 emit_value (logbuffer, 0); /* flags */
579 emit_value (logbuffer, data->count);
580 //if (*p != data.count) {
581 // 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);}
582 while (data->count) {
583 emit_ptr (logbuffer, data->methods [--data->count]);
588 gc_alloc (MonoProfiler *prof, MonoObject *obj, MonoClass *klass)
592 int do_bt = (nocalls && runtime_inited && !notraces)? TYPE_ALLOC_BT: 0;
594 LogBuffer *logbuffer;
595 len = mono_object_get_size (obj);
596 /* account for object alignment in the heap */
601 logbuffer = ensure_logbuf (32 + MAX_FRAMES * 8);
602 now = current_time ();
603 emit_byte (logbuffer, do_bt | TYPE_ALLOC);
604 emit_time (logbuffer, now);
605 emit_ptr (logbuffer, klass);
606 emit_obj (logbuffer, obj);
607 emit_value (logbuffer, len);
609 emit_bt (logbuffer, &data);
611 safe_dump (prof, logbuffer);
612 //printf ("gc alloc %s at %p\n", mono_class_get_name (klass), obj);
616 gc_moves (MonoProfiler *prof, void **objects, int num)
620 LogBuffer *logbuffer = ensure_logbuf (10 + num * 8);
621 now = current_time ();
622 emit_byte (logbuffer, TYPE_GC_MOVE | TYPE_GC);
623 emit_time (logbuffer, now);
624 emit_value (logbuffer, num);
625 for (i = 0; i < num; ++i)
626 emit_obj (logbuffer, objects [i]);
627 //printf ("gc moved %d objects\n", num/2);
631 push_nesting (char *p, MonoClass *klass)
636 nesting = mono_class_get_nesting_type (klass);
638 p = push_nesting (p, nesting);
642 name = mono_class_get_name (klass);
643 nspace = mono_class_get_namespace (klass);
646 p += strlen (nspace);
656 type_name (MonoClass *klass)
660 push_nesting (buf, klass);
661 p = malloc (strlen (buf) + 1);
667 image_loaded (MonoProfiler *prof, MonoImage *image, int result)
672 LogBuffer *logbuffer;
673 if (result != MONO_PROFILE_OK)
675 name = mono_image_get_filename (image);
676 nlen = strlen (name) + 1;
677 logbuffer = ensure_logbuf (16 + nlen);
678 now = current_time ();
679 emit_byte (logbuffer, TYPE_END_LOAD | TYPE_METADATA);
680 emit_time (logbuffer, now);
681 emit_byte (logbuffer, TYPE_IMAGE);
682 emit_ptr (logbuffer, image);
683 emit_value (logbuffer, 0); /* flags */
684 memcpy (logbuffer->data, name, nlen);
685 logbuffer->data += nlen;
686 //printf ("loaded image %p (%s)\n", image, name);
688 safe_dump (prof, logbuffer);
692 class_loaded (MonoProfiler *prof, MonoClass *klass, int result)
698 LogBuffer *logbuffer;
699 if (result != MONO_PROFILE_OK)
702 name = mono_type_get_name (mono_class_get_type (klass));
704 name = type_name (klass);
705 nlen = strlen (name) + 1;
706 image = mono_class_get_image (klass);
707 logbuffer = ensure_logbuf (24 + nlen);
708 now = current_time ();
709 emit_byte (logbuffer, TYPE_END_LOAD | TYPE_METADATA);
710 emit_time (logbuffer, now);
711 emit_byte (logbuffer, TYPE_CLASS);
712 emit_ptr (logbuffer, klass);
713 emit_ptr (logbuffer, image);
714 emit_value (logbuffer, 0); /* flags */
715 memcpy (logbuffer->data, name, nlen);
716 logbuffer->data += nlen;
717 //printf ("loaded class %p (%s)\n", klass, name);
723 safe_dump (prof, logbuffer);
727 method_enter (MonoProfiler *prof, MonoMethod *method)
730 LogBuffer *logbuffer = ensure_logbuf (16);
731 if (logbuffer->call_depth++ > max_call_depth)
733 now = current_time ();
734 emit_byte (logbuffer, TYPE_ENTER | TYPE_METHOD);
735 emit_time (logbuffer, now);
736 emit_method (logbuffer, method);
740 method_leave (MonoProfiler *prof, MonoMethod *method)
743 LogBuffer *logbuffer = ensure_logbuf (16);
744 if (--logbuffer->call_depth > max_call_depth)
746 now = current_time ();
747 emit_byte (logbuffer, TYPE_LEAVE | TYPE_METHOD);
748 emit_time (logbuffer, now);
749 emit_method (logbuffer, method);
751 safe_dump (prof, logbuffer);
755 method_exc_leave (MonoProfiler *prof, MonoMethod *method)
758 LogBuffer *logbuffer;
761 logbuffer = ensure_logbuf (16);
762 if (--logbuffer->call_depth > max_call_depth)
764 now = current_time ();
765 emit_byte (logbuffer, TYPE_EXC_LEAVE | TYPE_METHOD);
766 emit_time (logbuffer, now);
767 emit_method (logbuffer, method);
771 method_jitted (MonoProfiler *prof, MonoMethod *method, MonoJitInfo* jinfo, int result)
776 LogBuffer *logbuffer;
777 if (result != MONO_PROFILE_OK)
779 name = mono_method_full_name (method, 1);
780 nlen = strlen (name) + 1;
781 logbuffer = ensure_logbuf (32 + nlen);
782 now = current_time ();
783 emit_byte (logbuffer, TYPE_JIT | TYPE_METHOD);
784 emit_time (logbuffer, now);
785 emit_method (logbuffer, method);
786 emit_ptr (logbuffer, mono_jit_info_get_code_start (jinfo));
787 emit_value (logbuffer, mono_jit_info_get_code_size (jinfo));
788 memcpy (logbuffer->data, name, nlen);
789 logbuffer->data += nlen;
792 safe_dump (prof, logbuffer);
796 throw_exc (MonoProfiler *prof, MonoObject *object)
798 int do_bt = (nocalls && runtime_inited && !notraces)? TYPE_EXCEPTION_BT: 0;
801 LogBuffer *logbuffer;
804 logbuffer = ensure_logbuf (16 + MAX_FRAMES * 8);
805 now = current_time ();
806 emit_byte (logbuffer, do_bt | TYPE_EXCEPTION);
807 emit_time (logbuffer, now);
808 emit_obj (logbuffer, object);
810 emit_bt (logbuffer, &data);
814 clause_exc (MonoProfiler *prof, MonoMethod *method, int clause_type, int clause_num)
817 LogBuffer *logbuffer = ensure_logbuf (16);
818 now = current_time ();
819 emit_byte (logbuffer, TYPE_EXCEPTION | TYPE_CLAUSE);
820 emit_time (logbuffer, now);
821 emit_value (logbuffer, clause_type);
822 emit_value (logbuffer, clause_num);
823 emit_method (logbuffer, method);
827 monitor_event (MonoProfiler *profiler, MonoObject *object, MonoProfilerMonitorEvent event)
829 int do_bt = (nocalls && runtime_inited && !notraces && event == MONO_PROFILER_MONITOR_CONTENTION)? TYPE_MONITOR_BT: 0;
832 LogBuffer *logbuffer;
835 logbuffer = ensure_logbuf (16 + MAX_FRAMES * 8);
836 now = current_time ();
837 emit_byte (logbuffer, (event << 4) | do_bt | TYPE_MONITOR);
838 emit_time (logbuffer, now);
839 emit_obj (logbuffer, object);
841 emit_bt (logbuffer, &data);
845 thread_start (MonoProfiler *prof, uintptr_t tid)
847 //printf ("thread start %p\n", (void*)tid);
852 thread_end (MonoProfiler *prof, uintptr_t tid)
855 if (TLS_GET (tlsbuffer))
856 dump_buffer (prof, TLS_GET (tlsbuffer));
858 TLS_SET (tlsbuffer, NULL);
862 log_shutdown (MonoProfiler *prof)
865 if (TLS_GET (tlsbuffer))
866 dump_buffer (prof, TLS_GET (tlsbuffer));
867 TLS_SET (tlsbuffer, NULL);
869 #if defined (HAVE_ZLIB)
871 gzclose (prof->gzfile);
873 if (prof->pipe_output)
881 create_profiler (const char *filename)
884 prof = calloc (1, sizeof (MonoProfiler));
885 if (do_report) /* FIXME: use filename as output */
886 filename = "|mprof-report -";
889 filename = "output.mlpd";
890 if (*filename == '|') {
891 prof->file = popen (filename + 1, "w");
892 prof->pipe_output = 1;
894 prof->file = fopen (filename, "wb");
897 printf ("Cannot create profiler output: %s\n", filename);
900 #if defined (HAVE_ZLIB)
902 prof->gzfile = gzdopen (fileno (prof->file), "wb");
911 printf ("Log profiler version %d.%d (format: %d)\n", LOG_VERSION_MAJOR, LOG_VERSION_MINOR, LOG_DATA_VERSION);
912 printf ("Usage: mono --profile=log[:OPTION1[,OPTION2...]] program.exe\n");
913 printf ("Options:\n");
914 printf ("\thelp show this usage info\n");
915 printf ("\t[no]alloc enable/disable recording allocation info\n");
916 printf ("\t[no]calls enable/disable recording enter/leave method events\n");
917 printf ("\theapshot record heap shot info (by default at each major collection)\n");
918 printf ("\thsmode=MODE heapshot mode: every XXms milliseconds or every YYgc collections\n");
919 printf ("\ttime=fast use a faster (but more inaccurate) timer\n");
920 printf ("\tmaxframes=NUM collect up to NUM stack frames\n");
921 printf ("\tcalldepth=NUM ignore method events for call chain depth bigger than NUM\n");
922 printf ("\toutput=FILENAME write the data to file FILENAME\n");
923 printf ("\toutput=|PROGRAM write the data to the stdin of PROGRAM\n");
924 printf ("\treport create a report instead of writing the raw data to a file\n");
925 printf ("\tzip compress the output data\n");
931 match_option (const char* p, const char *opt, char **rval)
933 int len = strlen (opt);
934 if (strncmp (p, opt, len) == 0) {
936 if (p [len] == '=' && p [len + 1]) {
937 const char *opt = p + len + 1;
938 const char *end = strchr (opt, ',');
946 val = malloc (l + 1);
947 memcpy (val, opt, l);
964 * declaration to silence the compiler: this is the entry point that
965 * mono will load from the shared library and call.
968 mono_profiler_startup (const char *desc);
971 mono_profiler_startup (const char *desc)
974 char *filename = NULL;
978 int calls_enabled = 0;
979 int allocs_enabled = 0;
980 int events = MONO_PROFILE_GC|MONO_PROFILE_ALLOCATIONS|
981 MONO_PROFILE_GC_MOVES|MONO_PROFILE_CLASS_EVENTS|MONO_PROFILE_THREADS|
982 MONO_PROFILE_ENTER_LEAVE|MONO_PROFILE_JIT_COMPILATION|MONO_PROFILE_EXCEPTIONS|
983 MONO_PROFILE_MONITOR_EVENTS|MONO_PROFILE_MODULE_EVENTS;
986 if (strncmp (p, "log", 3))
991 for (; *p; p = opt) {
997 if ((opt = match_option (p, "help", NULL)) != p) {
1001 if ((opt = match_option (p, "calls", NULL)) != p) {
1005 if ((opt = match_option (p, "nocalls", NULL)) != p) {
1006 events &= ~MONO_PROFILE_ENTER_LEAVE;
1010 if ((opt = match_option (p, "alloc", NULL)) != p) {
1014 if ((opt = match_option (p, "noalloc", NULL)) != p) {
1015 events &= ~MONO_PROFILE_ALLOCATIONS;
1018 if ((opt = match_option (p, "time", &val)) != p) {
1019 if (strcmp (val, "fast") == 0)
1021 else if (strcmp (val, "null") == 0)
1028 if ((opt = match_option (p, "report", NULL)) != p) {
1032 if ((opt = match_option (p, "heapshot", NULL)) != p) {
1033 events &= ~MONO_PROFILE_ALLOCATIONS;
1034 events &= ~MONO_PROFILE_ENTER_LEAVE;
1039 if ((opt = match_option (p, "hsmode", &val)) != p) {
1041 unsigned int count = strtoul (val, &end, 10);
1044 if (strcmp (end, "ms") == 0)
1046 else if (strcmp (end, "gc") == 0)
1053 if ((opt = match_option (p, "zip", NULL)) != p) {
1057 if ((opt = match_option (p, "output", &val)) != p) {
1061 if ((opt = match_option (p, "maxframes", &val)) != p) {
1063 num_frames = strtoul (val, &end, 10);
1064 if (num_frames > MAX_FRAMES)
1065 num_frames = MAX_FRAMES;
1067 notraces = num_frames == 0;
1070 if ((opt = match_option (p, "calldepth", &val)) != p) {
1072 max_call_depth = strtoul (val, &end, 10);
1081 if (calls_enabled) {
1082 events |= MONO_PROFILE_ENTER_LEAVE;
1086 events |= MONO_PROFILE_ALLOCATIONS;
1087 utils_init (fast_time);
1089 prof = create_profiler (filename);
1092 mono_profiler_install (prof, log_shutdown);
1093 mono_profiler_install_gc (gc_event, gc_resize);
1094 mono_profiler_install_allocation (gc_alloc);
1095 mono_profiler_install_gc_moves (gc_moves);
1096 mono_profiler_install_class (NULL, class_loaded, NULL, NULL);
1097 mono_profiler_install_module (NULL, image_loaded, NULL, NULL);
1098 mono_profiler_install_thread (thread_start, thread_end);
1099 mono_profiler_install_enter_leave (method_enter, method_leave);
1100 mono_profiler_install_jit_end (method_jitted);
1101 mono_profiler_install_exception (throw_exc, method_exc_leave, clause_exc);
1102 mono_profiler_install_monitor (monitor_event);
1103 mono_profiler_install_runtime_initialized (runtime_initialized);
1105 mono_profiler_set_events (events);
1107 TLS_INIT (tlsbuffer);