More log profiler doc clarifications.
[mono.git] / mono / profiler / proflog.c
index 34952bbf6e018d731dcc53871a76057734c35a32..5c4ccdd012c1ec10a10c680876ada9f7a2a473bd 100644 (file)
@@ -1,14 +1,29 @@
+/*
+ * proflog.c: mono log profiler
+ *
+ * Author:
+ *   Paolo Molaro (lupus@ximian.com)
+ *
+ * Copyright 2010 Novell, Inc (http://www.novell.com)
+ */
+
+#include <config.h>
 #include <mono/metadata/profiler.h>
 #include <mono/metadata/mono-gc.h>
 #include <mono/metadata/debug-helpers.h>
 #include <stdlib.h>
-#include <inttypes.h>
 #include <string.h>
+#if defined (HAVE_ZLIB)
 #include <zlib.h>
+#endif
 #include <assert.h>
+#ifdef HOST_WIN32
+#include <windows.h>
+#else
 #include <pthread.h>
+#endif
 
-#include "utils.h"
+#include "utils.c"
 #include "proflog.h"
 
 #define BUFFER_SIZE (4096 * 16)
@@ -37,34 +52,155 @@ static int runtime_inited = 0;
 typedef struct _LogBuffer LogBuffer;
 
 /*
- * file format: [OBSOLETE]
+ * file format:
  * [header] [buffer]*
- * each buffer contains events
+ *
+ * The file is composed by a header followed by 0 or more buffers.
+ * Each buffer contains events that happened on a thread: for a given thread
+ * buffers that appear later in the file are guaranteed to contain events
+ * that happened later in time. Buffers from separate threads could be interleaved,
+ * though.
+ * Buffers are not required to be aligned.
  *
  * header format:
- * [id: 4 bytes] [major: 1 byte] [minor: 1 byte] [length: 2 bytes]
- * [time: 8 bytes]
- * [bitness: 1 byte]
- * [mono version: variable]
- * [other data]
+ * [id: 4 bytes] constant value: LOG_HEADER_ID
+ * [major: 1 byte] [minor: 1 byte] major and minor version of the log profiler
+ * [format: 1 byte] version of the data format for the rest of the file
+ * [ptrsize: 1 byte] size in bytes of a pointer in the profiled program
+ * [startup time: 8 bytes] time in milliseconds since the unix epoch when the program started
+ * [timer overhead: 4 bytes] approximate overhead in nanoseconds of the timer
+ * [flags: 4 bytes] file format flags, should be 0 for now
+ * [pid: 4 bytes] pid of the profiled process
+ * [sysid: 4 bytes] operating system and architecture identifier
+ *
+ * The multiple byte integers are in little-endian format.
  *
  * buffer format:
- * [bufid: 4 bytes] [len: 4 bytes]
- * [time_base: 8 bytes]
- * [ptr_base: 8 bytes]
- * [obj_base: 8 bytes]
- * [thread id: 8 bytes]
+ * [buffer header] [event]*
+ * Buffers have a fixed-size header followed by 0 or more bytes of event data.
+ * Timing information and other values in the event data are usually stored
+ * as uleb128 or sleb128 integers. To save space, as noted for each item below,
+ * some data is represented as a difference between the actual value and
+ * either the last value of the same type (like for timing information) or
+ * as the difference from a value stored in a buffer header.
+ *
+ * For timing information the data is stored as uleb128, since timing
+ * increases in a monotonic way in each thread: the value is the number of
+ * nanoseconds to add to the last seen timing data in a buffer. The first value
+ * in a buffer will be calculated from the time_base field in the buffer head.
+ *
+ * Object or heap sizes are stored as uleb128.
+ * Pointer differences are stored as sleb128, instead.
+ *
+ * If an unexpected value is found, the rest of the buffer should be ignored,
+ * as generally the later values need the former to be interpreted correctly.
+ *
+ * buffer header format:
+ * [bufid: 4 bytes] constant value: BUF_ID
+ * [len: 4 bytes] size of the data following the buffer header
+ * [time_base: 8 bytes] time base in nanoseconds since an unspecified epoch
+ * [ptr_base: 8 bytes] base value for pointers
+ * [obj_base: 8 bytes] base value for object addresses
+ * [thread id: 8 bytes] system-specific thread ID (pthread_t for example)
+ * [method_base: 8 bytes] base value for MonoMethod pointers
  *
  * event format:
- * [extended type: 4 bits] [type: 4 bits]
- * The data that follows depend on type.
- * Time values are relative to the last time base of the buffer.
+ * [extended info: upper 4 bits] [type: lower 4 bits] [data]*
+ * The data that follows depends on type and the extended info.
+ * Type is one of the enum values in proflog.h: TYPE_ALLOC, TYPE_GC,
+ * TYPE_METADATA, TYPE_METHOD, TYPE_EXCEPTION, TYPE_MONITOR, TYPE_HEAP.
+ * The extended info bits are interpreted based on type, see
+ * each individual event description below.
+ * strings are represented as a 0-terminated utf8 sequence.
+ *
+ * backtrace format:
+ * [flags: uleb128] must be 0
+ * [num: uleb128] number of frames following
+ * [frame: sleb128]* num MonoMethod pointers as differences from ptr_base
  *
  * type alloc format:
- * [ptr: encoded] [class: encoded] [time: encoded] size?
+ * type: TYPE_ALLOC
+ * exinfo: flags: TYPE_ALLOC_BT
+ * [time diff: uleb128] nanoseconds since last timing
+ * [ptr: sleb128] class as a byte difference from ptr_base
+ * [obj: sleb128] object address as a byte difference from obj_base
+ * [size: uleb128] size of the object in the heap
+ * If the TYPE_ALLOC_BT flag is set, a backtrace follows.
  *
- * type enter/leave format:
- * [method: encoded] [time: encoded]
+ * type GC format:
+ * type: TYPE_GC
+ * exinfo: one of TYPE_GC_EVENT, TYPE_GC_RESIZE, TYPE_GC_MOVE
+ * [time diff: uleb128] nanoseconds since last timing
+ * if exinfo == TYPE_GC_RESIZE
+ *     [heap_size: uleb128] new heap size
+ * if exinfo == TYPE_GC_EVENT
+ *     [event type: uleb128] GC event (MONO_GC_EVENT_* from profiler.h)
+ *     [generation: uleb128] GC generation event refers to
+ * if exinfo == TYPE_GC_MOVE
+ *     [num_objects: uleb128] number of object moves that follow
+ *     [objaddr: sleb128]+ num_objects object pointer differences from obj_base
+ *     num is always an even number: the even items are the old
+ *     addresses, the odd numbers are the respective new object addresses
+ *
+ * type metadata format:
+ * type: TYPE_METADATA
+ * exinfo: flags: TYPE_LOAD_ERR
+ * [time diff: uleb128] nanoseconds since last timing
+ * [mtype: byte] metadata type, one of: TYPE_CLASS, TYPE_IMAGE, TYPE_ASSEMBLY, TYPE_DOMAIN
+ * [pointer: sleb128] pointer of the metadata type depending on mtype
+ * if mtype == TYPE_CLASS
+ *     [image: sleb128] MonoImage* as a pointer difference from ptr_base
+ *     [flags: uleb128] must be 0
+ *     [name: string] full class name
+ * if mtype == TYPE_IMAGE
+ *     [flags: uleb128] must be 0
+ *     [name: string] image file name
+ *
+ * type method format:
+ * type: TYPE_METHOD
+ * exinfo: one of: TYPE_LEAVE, TYPE_ENTER, TYPE_EXC_LEAVE, TYPE_JIT
+ * [time diff: uleb128] nanoseconds since last timing
+ * [method: sleb128] MonoMethod* as a pointer difference from the last such
+ * pointer or the buffer method_base
+ * if exinfo == TYPE_JIT
+ *     [code address: sleb128] pointer to the native code as a diff from ptr_base
+ *     [code size: uleb128] size of the generated code
+ *     [name: string] full method name
+ *
+ * type exception format:
+ * type: TYPE_EXCEPTION
+ * exinfo: TYPE_EXCEPTION_BT flag and one of: TYPE_THROW, TYPE_CLAUSE
+ * [time diff: uleb128] nanoseconds since last timing
+ * if exinfo.low3bits == TYPE_CLAUSE
+ *     [clause type: uleb128] finally/catch/fault/filter
+ *     [clause num: uleb128] the clause number in the method header
+ *     [method: sleb128] MonoMethod* as a pointer difference from the last such
+ *     pointer or the buffer method_base
+ * if exinfo.low3bits == TYPE_THROW
+ *     [object: sleb128] the object that was thrown as a difference from obj_base
+ *     If the TYPE_EXCEPTION_BT flag is set, a backtrace follows.
+ *
+ * type monitor format:
+ * type: TYPE_MONITOR
+ * exinfo: TYPE_MONITOR_BT flag and one of: MONO_PROFILER_MONITOR_(CONTENTION|FAIL|DONE)
+ * [time diff: uleb128] nanoseconds since last timing
+ * [object: sleb128] the lock object as a difference from obj_base
+ * if exinfo.low3bits == MONO_PROFILER_MONITOR_CONTENTION
+ *     If the TYPE_MONITOR_BT flag is set, a backtrace follows.
+ *
+ * type heap format
+ * type: TYPE_HEAP
+ * exinfo: one of TYPE_HEAP_START, TYPE_HEAP_END, TYPE_HEAP_OBJECT
+ * if exinfo == TYPE_HEAP_START
+ *     [time diff: uleb128] nanoseconds since last timing
+ * if exinfo == TYPE_HEAP_END
+ *     [time diff: uleb128] nanoseconds since last timing
+ * if exinfo == TYPE_HEAP_OBJECT
+ *     [object: sleb128] the object as a difference from obj_base
+ *     [class: sleb128] the object MonoClass* as a difference from ptr_base
+ *     [size: uleb128] size of the object on the heap
+ *     [num_refs: uleb128] number of object references
+ *     [objrefs: sleb128]+ object referenced as a difference from obj_base
  *
  */
 struct _LogBuffer {
@@ -86,12 +222,19 @@ struct _LogBuffer {
 struct _MonoProfiler {
        LogBuffer *buffers;
        FILE* file;
+#if defined (HAVE_ZLIB)
        gzFile *gzfile;
+#endif
        int pipe_output;
        int last_gc_gen_started;
 };
 
-#if HAVE_KW_THREAD
+#ifdef HOST_WIN32
+#define TLS_SET(x,y) TlsSetValue(x, y)
+#define TLS_GET(x) ((LogBuffer *) TlsGetValue(x))
+#define TLS_INIT(x) x = TlsAlloc ()
+static int tlsbuffer;
+#elif HAVE_KW_THREAD
 #define TLS_SET(x,y) x = y
 #define TLS_GET(x) x
 #define TLS_INIT(x)
@@ -248,11 +391,15 @@ dump_header (MonoProfiler *profiler)
        p = write_int32 (p, 0); /* flags */
        p = write_int32 (p, 0); /* pid */
        p = write_int32 (p, 0); /* opsystem */
+#if defined (HAVE_ZLIB)
        if (profiler->gzfile) {
                gzwrite (profiler->gzfile, hbuf, p - hbuf);
        } else {
                fwrite (hbuf, p - hbuf, 1, profiler->file);
        }
+#else
+       fwrite (hbuf, p - hbuf, 1, profiler->file);
+#endif
 }
 
 static void
@@ -269,13 +416,17 @@ dump_buffer (MonoProfiler *profiler, LogBuffer *buf)
        p = write_int64 (p, buf->obj_base);
        p = write_int64 (p, buf->thread_id);
        p = write_int64 (p, buf->method_base);
+#if defined (HAVE_ZLIB)
        if (profiler->gzfile) {
                gzwrite (profiler->gzfile, hbuf, p - hbuf);
                gzwrite (profiler->gzfile, buf->buf, buf->data - buf->buf);
        } else {
+#endif
                fwrite (hbuf, p - hbuf, 1, profiler->file);
                fwrite (buf->buf, buf->data - buf->buf, 1, profiler->file);
+#if defined (HAVE_ZLIB)
        }
+#endif
        free_buffer (buf, buf->size);
 }
 
@@ -309,6 +460,9 @@ gc_reference (MonoObject *obj, MonoClass *klass, uintptr_t size, uintptr_t num,
        emit_byte (logbuffer, TYPE_HEAP_OBJECT | TYPE_HEAP);
        emit_obj (logbuffer, obj);
        emit_ptr (logbuffer, klass);
+       /* account for object alignment in the heap */
+       size += 7;
+       size &= ~7;
        emit_value (logbuffer, size);
        emit_value (logbuffer, num);
        for (i = 0; i < num; ++i)
@@ -439,6 +593,9 @@ gc_alloc (MonoProfiler *prof, MonoObject *obj, MonoClass *klass)
        FrameData data;
        LogBuffer *logbuffer;
        len = mono_object_get_size (obj);
+       /* account for object alignment in the heap */
+       len += 7;
+       len &= ~7;
        if (do_bt)
                collect_bt (&data);
        logbuffer = ensure_logbuf (32 + MAX_FRAMES * 8);
@@ -709,8 +866,10 @@ log_shutdown (MonoProfiler *prof)
                dump_buffer (prof, TLS_GET (tlsbuffer));
        TLS_SET (tlsbuffer, NULL);
        release_lock ();
+#if defined (HAVE_ZLIB)
        if (prof->gzfile)
                gzclose (prof->gzfile);
+#endif
        if (prof->pipe_output)
                pclose (prof->file);
        else
@@ -719,7 +878,7 @@ log_shutdown (MonoProfiler *prof)
 }
 
 static MonoProfiler*
-create_profiler (char *filename)
+create_profiler (const char *filename)
 {
        MonoProfiler *prof;
        prof = calloc (1, sizeof (MonoProfiler));
@@ -738,8 +897,10 @@ create_profiler (char *filename)
                printf ("Cannot create profiler output: %s\n", filename);
                exit (1);
        }
+#if defined (HAVE_ZLIB)
        if (use_zip)
                prof->gzfile = gzdopen (fileno (prof->file), "wb");
+#endif
        dump_header (prof);
        return prof;
 }
@@ -766,7 +927,7 @@ usage (int do_exit)
                exit (1);
 }
 
-const char*
+static const char*
 match_option (const char* p, const char *opt, char **rval)
 {
        int len = strlen (opt);
@@ -799,6 +960,13 @@ match_option (const char* p, const char *opt, char **rval)
        return p;
 }
 
+/* 
+ * declaration to silence the compiler: this is the entry point that
+ * mono will load from the shared library and call.
+ */
+extern void
+mono_profiler_startup (const char *desc);
+
 void
 mono_profiler_startup (const char *desc)
 {