Log profiler: prevent possible corruption from writing to the same file.
authorPaolo Molaro <lupus@oddwiz.org>
Fri, 12 Nov 2010 11:55:29 +0000 (12:55 +0100)
committerPaolo Molaro <lupus@oddwiz.org>
Fri, 12 Nov 2010 13:13:15 +0000 (14:13 +0100)
* proflog.c: we now unlink the output file before creating it to
prevent possible corruption from multiple processes writing to the
file. Added also extra checks for async events (which shouldn't happen).
* decode.c: fix file offset when using zlib.

mono/profiler/decode.c
mono/profiler/proflog.c

index d441af2e9f5a14a4765de896d479f2d46fb78fb4..0a33040a73dad76eee8e08ed67ef3ae928c7d3cf 100644 (file)
@@ -1048,7 +1048,12 @@ decode_buffer (ProfContext *ctx)
        int len, i;
        ThreadContext *thread;
 
-       file_offset = ftell (ctx->file);
+#ifdef HAVE_SYS_ZLIB
+       if (ctx->gzfile)
+               file_offset = gztell (ctx->gzfile);
+       else
+#endif
+               file_offset = ftell (ctx->file);
        if (!load_data (ctx, 48))
                return 0;
        p = ctx->buf;
@@ -1434,7 +1439,7 @@ decode_buffer (ProfContext *ctx)
                        break;
                }
                default:
-                       fprintf (outfile, "unhandled profiler event: 0x%x\n", *p);
+                       fprintf (outfile, "unhandled profiler event: 0x%x at file offset: %llu + %d (len: %d\n)\n", *p, file_offset, p - ctx->buf, len);
                        exit (1);
                }
        }
index d9f6c4ca91c358ba84a02e240b317f90b7ab68d9..06720a3b91536742795d54c2ddc0512c15f82ae2 100644 (file)
@@ -229,11 +229,15 @@ struct _LogBuffer {
        uintptr_t thread_id;
        unsigned char* data_end;
        unsigned char* data;
+       int locked;
        int size;
        int call_depth;
        unsigned char buf [1];
 };
 
+#define ENTER_LOG(lb,str) if ((lb)->locked) {write(2, str, strlen(str)); write(2, "\n", 1);return;} else {(lb)->locked++;}
+#define EXIT_LOG(lb) (lb)->locked--;
+
 struct _MonoProfiler {
        LogBuffer *buffers;
        FILE* file;
@@ -526,6 +530,7 @@ gc_event (MonoProfiler *profiler, MonoGCEvent ev, int generation) {
        uint64_t now;
        LogBuffer *logbuffer = ensure_logbuf (10);
        now = current_time ();
+       ENTER_LOG (logbuffer, "gcevent");
        emit_byte (logbuffer, TYPE_GC_EVENT | TYPE_GC);
        emit_time (logbuffer, now);
        emit_value (logbuffer, ev);
@@ -537,6 +542,7 @@ gc_event (MonoProfiler *profiler, MonoGCEvent ev, int generation) {
        }
        if (ev == MONO_GC_EVENT_PRE_START_WORLD)
                heap_walk (profiler);
+       EXIT_LOG (logbuffer);
        if (ev == MONO_GC_EVENT_POST_START_WORLD)
                safe_dump (profiler, logbuffer);
        //printf ("gc event %d for generation %d\n", ev, generation);
@@ -547,10 +553,12 @@ gc_resize (MonoProfiler *profiler, int64_t new_size) {
        uint64_t now;
        LogBuffer *logbuffer = ensure_logbuf (10);
        now = current_time ();
+       ENTER_LOG (logbuffer, "gcresize");
        emit_byte (logbuffer, TYPE_GC_RESIZE | TYPE_GC);
        emit_time (logbuffer, now);
        emit_value (logbuffer, new_size);
        //printf ("gc resized to %lld\n", new_size);
+       EXIT_LOG (logbuffer);
 }
 
 #define MAX_FRAMES 16
@@ -616,6 +624,7 @@ gc_alloc (MonoProfiler *prof, MonoObject *obj, MonoClass *klass)
                collect_bt (&data);
        logbuffer = ensure_logbuf (32 + MAX_FRAMES * 8);
        now = current_time ();
+       ENTER_LOG (logbuffer, "gcalloc");
        emit_byte (logbuffer, do_bt | TYPE_ALLOC);
        emit_time (logbuffer, now);
        emit_ptr (logbuffer, klass);
@@ -623,6 +632,7 @@ gc_alloc (MonoProfiler *prof, MonoObject *obj, MonoClass *klass)
        emit_value (logbuffer, len);
        if (do_bt)
                emit_bt (logbuffer, &data);
+       EXIT_LOG (logbuffer);
        if (logbuffer->next)
                safe_dump (prof, logbuffer);
        //printf ("gc alloc %s at %p\n", mono_class_get_name (klass), obj);
@@ -635,12 +645,14 @@ gc_moves (MonoProfiler *prof, void **objects, int num)
        uint64_t now;
        LogBuffer *logbuffer = ensure_logbuf (10 + num * 8);
        now = current_time ();
+       ENTER_LOG (logbuffer, "gcmove");
        emit_byte (logbuffer, TYPE_GC_MOVE | TYPE_GC);
        emit_time (logbuffer, now);
        emit_value (logbuffer, num);
        for (i = 0; i < num; ++i)
                emit_obj (logbuffer, objects [i]);
        //printf ("gc moved %d objects\n", num/2);
+       EXIT_LOG (logbuffer);
 }
 
 static void
@@ -649,6 +661,7 @@ gc_handle (MonoProfiler *prof, int op, int type, uintptr_t handle, MonoObject *o
        uint64_t now;
        LogBuffer *logbuffer = ensure_logbuf (16);
        now = current_time ();
+       ENTER_LOG (logbuffer, "gchandle");
        if (op == MONO_PROFILER_GC_HANDLE_CREATED)
                emit_byte (logbuffer, TYPE_GC_HANDLE_CREATED | TYPE_GC);
        else if (op == MONO_PROFILER_GC_HANDLE_DESTROYED)
@@ -660,6 +673,7 @@ gc_handle (MonoProfiler *prof, int op, int type, uintptr_t handle, MonoObject *o
        emit_value (logbuffer, handle);
        if (op == MONO_PROFILER_GC_HANDLE_CREATED)
                emit_obj (logbuffer, obj);
+       EXIT_LOG (logbuffer);
 }
 
 static char*
@@ -711,6 +725,7 @@ image_loaded (MonoProfiler *prof, MonoImage *image, int result)
        nlen = strlen (name) + 1;
        logbuffer = ensure_logbuf (16 + nlen);
        now = current_time ();
+       ENTER_LOG (logbuffer, "image");
        emit_byte (logbuffer, TYPE_END_LOAD | TYPE_METADATA);
        emit_time (logbuffer, now);
        emit_byte (logbuffer, TYPE_IMAGE);
@@ -719,6 +734,7 @@ image_loaded (MonoProfiler *prof, MonoImage *image, int result)
        memcpy (logbuffer->data, name, nlen);
        logbuffer->data += nlen;
        //printf ("loaded image %p (%s)\n", image, name);
+       EXIT_LOG (logbuffer);
        if (logbuffer->next)
                safe_dump (prof, logbuffer);
 }
@@ -741,6 +757,7 @@ class_loaded (MonoProfiler *prof, MonoClass *klass, int result)
        image = mono_class_get_image (klass);
        logbuffer = ensure_logbuf (24 + nlen);
        now = current_time ();
+       ENTER_LOG (logbuffer, "class");
        emit_byte (logbuffer, TYPE_END_LOAD | TYPE_METADATA);
        emit_time (logbuffer, now);
        emit_byte (logbuffer, TYPE_CLASS);
@@ -754,6 +771,7 @@ class_loaded (MonoProfiler *prof, MonoClass *klass, int result)
                mono_free (name);
        else
                free (name);
+       EXIT_LOG (logbuffer);
        if (logbuffer->next)
                safe_dump (prof, logbuffer);
 }
@@ -766,9 +784,11 @@ method_enter (MonoProfiler *prof, MonoMethod *method)
        if (logbuffer->call_depth++ > max_call_depth)
                return;
        now = current_time ();
+       ENTER_LOG (logbuffer, "enter");
        emit_byte (logbuffer, TYPE_ENTER | TYPE_METHOD);
        emit_time (logbuffer, now);
        emit_method (logbuffer, method);
+       EXIT_LOG (logbuffer);
 }
 
 static void
@@ -779,9 +799,11 @@ method_leave (MonoProfiler *prof, MonoMethod *method)
        if (--logbuffer->call_depth > max_call_depth)
                return;
        now = current_time ();
+       ENTER_LOG (logbuffer, "leave");
        emit_byte (logbuffer, TYPE_LEAVE | TYPE_METHOD);
        emit_time (logbuffer, now);
        emit_method (logbuffer, method);
+       EXIT_LOG (logbuffer);
        if (logbuffer->next)
                safe_dump (prof, logbuffer);
 }
@@ -797,9 +819,11 @@ method_exc_leave (MonoProfiler *prof, MonoMethod *method)
        if (--logbuffer->call_depth > max_call_depth)
                return;
        now = current_time ();
+       ENTER_LOG (logbuffer, "eleave");
        emit_byte (logbuffer, TYPE_EXC_LEAVE | TYPE_METHOD);
        emit_time (logbuffer, now);
        emit_method (logbuffer, method);
+       EXIT_LOG (logbuffer);
 }
 
 static void
@@ -815,6 +839,7 @@ method_jitted (MonoProfiler *prof, MonoMethod *method, MonoJitInfo* jinfo, int r
        nlen = strlen (name) + 1;
        logbuffer = ensure_logbuf (32 + nlen);
        now = current_time ();
+       ENTER_LOG (logbuffer, "jit");
        emit_byte (logbuffer, TYPE_JIT | TYPE_METHOD);
        emit_time (logbuffer, now);
        emit_method (logbuffer, method);
@@ -823,6 +848,7 @@ method_jitted (MonoProfiler *prof, MonoMethod *method, MonoJitInfo* jinfo, int r
        memcpy (logbuffer->data, name, nlen);
        logbuffer->data += nlen;
        mono_free (name);
+       EXIT_LOG (logbuffer);
        if (logbuffer->next)
                safe_dump (prof, logbuffer);
 }
@@ -838,11 +864,13 @@ throw_exc (MonoProfiler *prof, MonoObject *object)
                collect_bt (&data);
        logbuffer = ensure_logbuf (16 + MAX_FRAMES * 8);
        now = current_time ();
+       ENTER_LOG (logbuffer, "throw");
        emit_byte (logbuffer, do_bt | TYPE_EXCEPTION);
        emit_time (logbuffer, now);
        emit_obj (logbuffer, object);
        if (do_bt)
                emit_bt (logbuffer, &data);
+       EXIT_LOG (logbuffer);
 }
 
 static void
@@ -851,11 +879,13 @@ clause_exc (MonoProfiler *prof, MonoMethod *method, int clause_type, int clause_
        uint64_t now;
        LogBuffer *logbuffer = ensure_logbuf (16);
        now = current_time ();
+       ENTER_LOG (logbuffer, "clause");
        emit_byte (logbuffer, TYPE_EXCEPTION | TYPE_CLAUSE);
        emit_time (logbuffer, now);
        emit_value (logbuffer, clause_type);
        emit_value (logbuffer, clause_num);
        emit_method (logbuffer, method);
+       EXIT_LOG (logbuffer);
 }
 
 static void
@@ -869,11 +899,13 @@ monitor_event (MonoProfiler *profiler, MonoObject *object, MonoProfilerMonitorEv
                collect_bt (&data);
        logbuffer = ensure_logbuf (16 + MAX_FRAMES * 8);
        now = current_time ();
+       ENTER_LOG (logbuffer, "monitor");
        emit_byte (logbuffer, (event << 4) | do_bt | TYPE_MONITOR);
        emit_time (logbuffer, now);
        emit_obj (logbuffer, object);
        if (do_bt)
                emit_bt (logbuffer, &data);
+       EXIT_LOG (logbuffer);
 }
 
 static void
@@ -901,6 +933,7 @@ thread_name (MonoProfiler *prof, uintptr_t tid, const char *name)
        LogBuffer *logbuffer;
        logbuffer = ensure_logbuf (10 + len);
        now = current_time ();
+       ENTER_LOG (logbuffer, "tname");
        emit_byte (logbuffer, TYPE_METADATA);
        emit_time (logbuffer, now);
        emit_byte (logbuffer, TYPE_THREAD);
@@ -908,6 +941,7 @@ thread_name (MonoProfiler *prof, uintptr_t tid, const char *name)
        emit_value (logbuffer, 0); /* flags */
        memcpy (logbuffer->data, name, len);
        logbuffer->data += len;
+       EXIT_LOG (logbuffer);
 }
 
 static void
@@ -943,6 +977,7 @@ create_profiler (const char *filename)
                prof->file = popen (filename + 1, "w");
                prof->pipe_output = 1;
        } else {
+               unlink (filename);
                prof->file = fopen (filename, "wb");
        }
        if (!prof->file) {