From: monojenkins Date: Thu, 31 Mar 2016 19:05:17 +0000 (+0100) Subject: Merge pull request #2816 from xmcclure/profile-clean-0 X-Git-Url: http://wien.tomnetworks.com/gitweb/?a=commitdiff_plain;h=1c385f99e1c5e5c76e03c49e838ac29739a2e9e2;hp=58e8a9f85176c9607e605b888ef45db01a0f6997;p=mono.git Merge pull request #2816 from xmcclure/profile-clean-0 Various cleanups on profiler 3 commits: Assist on profiler module loading - Add a MONO_PROFILER_LIB_DIR from which profiler modules are dynamically loading, in case it is not the normal library path - Add information about profiler loading to mono_trace Comments and clarity in proflog.c - Add comments on structures - Rename 'data' and 'data_end' to 'cursor' and 'buf_end' in LogBuffer/StatsBuffer as the old names were confusing - Add new assert when processing samples Improve a safety check when writing data into StatBuffer - The safety check should occur such that if the new value for StatBuffer::cursor is beyond the bounds of the StatBuffer, the cursor is not updated. --- diff --git a/man/mono.1 b/man/mono.1 index a3829ae79a5..7eb8055fb4f 100644 --- a/man/mono.1 +++ b/man/mono.1 @@ -786,7 +786,8 @@ to Mono, like this: .PP In the above sample Mono will load the user defined profiler from the shared library `mono-profiler-custom.so'. This profiler module must -be on your dynamic linker library path. +be on your dynamic linker library path, or in the MONO_PROFILER_LIB_DIR +path (see "RUNTIME OPTIONS" below). .PP A list of other third party profilers is available from Mono's web site (www.mono-project.com/docs/advanced/performance-tips/) @@ -1507,6 +1508,12 @@ libraries side-by-side with the main executable. For a complete description of recommended practices for application deployment, see http://www.mono-project.com/docs/getting-started/application-deployment/ +.TP +\fBMONO_PROFILER_LIB_DIR\fR +Provides a search path to the runtime where to look for custom profilers. See the +section "CUSTOM PROFILERS" above for more information. Custom profilers will be +searched for in the MONO_PROFILER_LIB_DIR path before the standard library paths. + .TP \fBMONO_RTC\fR Experimental RTC support in the statistical profiler: if the user has diff --git a/mono/metadata/profiler.c b/mono/metadata/profiler.c index b2620ecf030..d74a273d085 100644 --- a/mono/metadata/profiler.c +++ b/mono/metadata/profiler.c @@ -24,6 +24,7 @@ #include "mono/metadata/mono-config-dirs.h" #include "mono/io-layer/io-layer.h" #include "mono/utils/mono-dl.h" +#include #include #ifdef HAVE_UNISTD_H #include @@ -1168,10 +1169,13 @@ load_profiler_from_directory (const char *directory, const char *libname, const char *err; void *iter; + mono_trace (G_LOG_LEVEL_INFO, MONO_TRACE_ASSEMBLY, "Attempting to load profiler %s from %s (desc %s)", libname, directory, desc); + iter = NULL; err = NULL; while ((path = mono_dl_build_path (directory, libname, &iter))) { pmodule = mono_dl_open (path, MONO_DL_LAZY, &err); + mono_trace (G_LOG_LEVEL_INFO, MONO_TRACE_ASSEMBLY, "Attempting to load profiler: %s %ssuccessful, err: %s", path, pmodule?"":"not ", err); g_free (path); g_free (err); if (pmodule) @@ -1250,7 +1254,10 @@ mono_profiler_load (const char *desc) } if (!load_embedded_profiler (desc, mname)) { libname = g_strdup_printf ("mono-profiler-%s", mname); - if (mono_config_get_assemblies_dir ()) + char *profiler_lib_dir = getenv ("MONO_PROFILER_LIB_DIR"); + if (profiler_lib_dir) + res = load_profiler_from_directory (profiler_lib_dir, libname, desc); + if (!res && mono_config_get_assemblies_dir ()) res = load_profiler_from_directory (mono_assembly_getrootdir (), libname, desc); if (!res) res = load_profiler_from_directory (NULL, libname, desc); diff --git a/mono/profiler/proflog.c b/mono/profiler/proflog.c index ed46b6d4cc9..c32f40c62d3 100644 --- a/mono/profiler/proflog.c +++ b/mono/profiler/proflog.c @@ -416,8 +416,12 @@ typedef struct _LogBuffer LogBuffer; * be done to the format. */ +// Pending data to be written to the log, for a single thread. +// Threads periodically flush their own LogBuffers by calling safe_send struct _LogBuffer { + // Next (older) LogBuffer in processing queue LogBuffer *next; + uint64_t time_base; uint64_t last_time; uintptr_t ptr_base; @@ -425,11 +429,19 @@ struct _LogBuffer { uintptr_t last_method; uintptr_t obj_base; uintptr_t thread_id; - unsigned char* data_end; - unsigned char* data; int locked; - int size; int call_depth; + + // Bytes allocated for this LogBuffer + int size; + + // Start of currently unused space in buffer + unsigned char* cursor; + + // Pointer to start-of-structure-plus-size (for convenience) + unsigned char* buf_end; + + // Start of data in buffer. Contents follow "buffer format" described above. unsigned char buf [1]; }; @@ -441,12 +453,38 @@ ign_res (int G_GNUC_UNUSED unused, ...) #define ENTER_LOG(lb,str) if ((lb)->locked) {ign_res (write(2, str, strlen(str))); ign_res (write(2, "\n", 1));return;} else {(lb)->locked++;} #define EXIT_LOG(lb) (lb)->locked--; +// Shared queue of sample snapshots taken at signal time. +// The queue is written into by signal handlers for all threads; +// the helper thread later unqueues and writes into its own LogBuffer. typedef struct _StatBuffer StatBuffer; struct _StatBuffer { + // Next (older) StatBuffer in processing queue StatBuffer *next; + + // Bytes allocated for this StatBuffer uintptr_t size; - uintptr_t *data_end; - uintptr_t *data; + + // Start of currently unused space in buffer + uintptr_t *cursor; + + // Pointer to start-of-structure-plus-size (for convenience) + uintptr_t *buf_end; + + // Start of data in buffer. + // Data consists of a series of sample packets consisting of: + // 1 ptrword: Metadata + // Low 8 bits: COUNT, the count of native stack frames in this sample (currently always 1) + // Next 8 bits: MBT_COUNT, the count of managed stacks in this sample + // Next 8 bits: TYPE. See "sampling sources" enum in proflog.h. Usually SAMPLE_CYCLES (1) + // 1 ptrword: Thread ID + // 1 ptrword: Timestamp + // COUNT ptrwords: Native stack frames + // Each word is an IP (first is IP where the signal did the interruption) + // MBT_COUNT * 4 ptrwords: Managed stack frames (AsyncFrameInfo, repacked) + // Word 1: MonoMethod ptr + // Word 2: MonoDomain ptr + // Word 3: Base address of method + // Word 4: Offset within method uintptr_t buf [1]; }; @@ -537,8 +575,8 @@ create_stat_buffer (void) { StatBuffer* buf = (StatBuffer *)alloc_buffer (BUFFER_SIZE); buf->size = BUFFER_SIZE; - buf->data_end = (uintptr_t*)((unsigned char*)buf + buf->size); - buf->data = buf->buf; + buf->buf_end = (uintptr_t*)((unsigned char*)buf + buf->size); + buf->cursor = buf->buf; return buf; } @@ -549,8 +587,8 @@ create_buffer (void) buf->size = BUFFER_SIZE; buf->time_base = current_time (); buf->last_time = buf->time_base; - buf->data_end = (unsigned char*)buf + buf->size; - buf->data = buf->buf; + buf->buf_end = (unsigned char*)buf + buf->size; + buf->cursor = buf->buf; return buf; } @@ -573,7 +611,7 @@ init_thread (void) static LogBuffer * ensure_logbuf_inner (LogBuffer *old, int bytes) { - if (old && old->data + bytes + 100 < old->data_end) + if (old && old->cursor + bytes + 100 < old->buf_end) return old; LogBuffer *new_ = (LogBuffer *)create_buffer (); @@ -604,16 +642,16 @@ ensure_logbuf (int bytes) static void emit_byte (LogBuffer *logbuffer, int value) { - logbuffer->data [0] = value; - logbuffer->data++; - assert (logbuffer->data <= logbuffer->data_end); + logbuffer->cursor [0] = value; + logbuffer->cursor++; + assert (logbuffer->cursor <= logbuffer->buf_end); } static void emit_value (LogBuffer *logbuffer, int value) { - encode_uleb128 (value, logbuffer->data, &logbuffer->data); - assert (logbuffer->data <= logbuffer->data_end); + encode_uleb128 (value, logbuffer->cursor, &logbuffer->cursor); + assert (logbuffer->cursor <= logbuffer->buf_end); } static void @@ -624,25 +662,25 @@ emit_time (LogBuffer *logbuffer, uint64_t value) // printf ("time went backwards\n"); //if (tdiff > 1000000) // printf ("large time offset: %llu\n", tdiff); - encode_uleb128 (tdiff, logbuffer->data, &logbuffer->data); + encode_uleb128 (tdiff, logbuffer->cursor, &logbuffer->cursor); /*if (tdiff != decode_uleb128 (p, &p)) printf ("incorrect encoding: %llu\n", tdiff);*/ logbuffer->last_time = value; - assert (logbuffer->data <= logbuffer->data_end); + assert (logbuffer->cursor <= logbuffer->buf_end); } static void emit_svalue (LogBuffer *logbuffer, int64_t value) { - encode_sleb128 (value, logbuffer->data, &logbuffer->data); - assert (logbuffer->data <= logbuffer->data_end); + encode_sleb128 (value, logbuffer->cursor, &logbuffer->cursor); + assert (logbuffer->cursor <= logbuffer->buf_end); } static void emit_uvalue (LogBuffer *logbuffer, uint64_t value) { - encode_uleb128 (value, logbuffer->data, &logbuffer->data); - assert (logbuffer->data <= logbuffer->data_end); + encode_uleb128 (value, logbuffer->cursor, &logbuffer->cursor); + assert (logbuffer->cursor <= logbuffer->buf_end); } static void @@ -651,7 +689,7 @@ emit_ptr (LogBuffer *logbuffer, void *ptr) if (!logbuffer->ptr_base) logbuffer->ptr_base = (uintptr_t)ptr; emit_svalue (logbuffer, (intptr_t)ptr - logbuffer->ptr_base); - assert (logbuffer->data <= logbuffer->data_end); + assert (logbuffer->cursor <= logbuffer->buf_end); } static void @@ -661,9 +699,9 @@ emit_method_inner (LogBuffer *logbuffer, void *method) logbuffer->method_base = (intptr_t)method; logbuffer->last_method = (intptr_t)method; } - encode_sleb128 ((intptr_t)((char*)method - (char*)logbuffer->last_method), logbuffer->data, &logbuffer->data); + encode_sleb128 ((intptr_t)((char*)method - (char*)logbuffer->last_method), logbuffer->cursor, &logbuffer->cursor); logbuffer->last_method = (intptr_t)method; - assert (logbuffer->data <= logbuffer->data_end); + assert (logbuffer->cursor <= logbuffer->buf_end); } /* @@ -755,7 +793,7 @@ emit_obj (LogBuffer *logbuffer, void *ptr) if (!logbuffer->obj_base) logbuffer->obj_base = (uintptr_t)ptr >> 3; emit_svalue (logbuffer, ((uintptr_t)ptr >> 3) - logbuffer->obj_base); - assert (logbuffer->data <= logbuffer->data_end); + assert (logbuffer->cursor <= logbuffer->buf_end); } static void @@ -865,7 +903,7 @@ dump_buffer (MonoProfiler *profiler, LogBuffer *buf) if (buf->next) dump_buffer (profiler, buf->next); p = write_int32 (p, BUF_ID); - p = write_int32 (p, buf->data - buf->buf); + p = write_int32 (p, buf->cursor - buf->buf); p = write_int64 (p, buf->time_base); p = write_int64 (p, buf->ptr_base); p = write_int64 (p, buf->obj_base); @@ -874,11 +912,11 @@ dump_buffer (MonoProfiler *profiler, LogBuffer *buf) #if defined (HAVE_SYS_ZLIB) if (profiler->gzfile) { gzwrite (profiler->gzfile, hbuf, p - hbuf); - gzwrite (profiler->gzfile, buf->buf, buf->data - buf->buf); + gzwrite (profiler->gzfile, buf->buf, buf->cursor - buf->buf); } else { #endif fwrite (hbuf, p - hbuf, 1, profiler->file); - fwrite (buf->buf, buf->data - buf->buf, 1, profiler->file); + fwrite (buf->buf, buf->cursor - buf->buf, 1, profiler->file); fflush (profiler->file); #if defined (HAVE_SYS_ZLIB) } @@ -1094,7 +1132,7 @@ emit_bt (MonoProfiler *prof, LogBuffer *logbuffer, FrameData *data) emit_value (logbuffer, 0); /* flags */ emit_value (logbuffer, data->count); //if (*p != data.count) { - // 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);} + // printf ("bad num frames enc at %d: %d -> %d\n", count, data.count, *p); printf ("frames end: %p->%p\n", p, logbuffer->cursor); exit(0);} while (data->count) { emit_method_as_ptr (prof, logbuffer, data->methods [--data->count]); } @@ -1307,8 +1345,8 @@ image_loaded (MonoProfiler *prof, MonoImage *image, int result) emit_byte (logbuffer, TYPE_IMAGE); emit_ptr (logbuffer, image); emit_value (logbuffer, 0); /* flags */ - memcpy (logbuffer->data, name, nlen); - logbuffer->data += nlen; + memcpy (logbuffer->cursor, name, nlen); + logbuffer->cursor += nlen; //printf ("loaded image %p (%s)\n", image, name); EXIT_LOG (logbuffer); if (logbuffer->next) @@ -1337,8 +1375,8 @@ image_unloaded (MonoProfiler *prof, MonoImage *image) emit_byte (logbuffer, TYPE_IMAGE); emit_ptr (logbuffer, image); emit_value (logbuffer, 0); /* flags */ - memcpy (logbuffer->data, name, nlen); - logbuffer->data += nlen; + memcpy (logbuffer->cursor, name, nlen); + logbuffer->cursor += nlen; EXIT_LOG (logbuffer); if (logbuffer->next) @@ -1371,8 +1409,8 @@ assembly_loaded (MonoProfiler *prof, MonoAssembly *assembly, int result) emit_byte (logbuffer, TYPE_ASSEMBLY); emit_ptr (logbuffer, assembly); emit_value (logbuffer, 0); /* flags */ - memcpy (logbuffer->data, name, nlen); - logbuffer->data += nlen; + memcpy (logbuffer->cursor, name, nlen); + logbuffer->cursor += nlen; EXIT_LOG (logbuffer); mono_free (name); @@ -1404,8 +1442,8 @@ assembly_unloaded (MonoProfiler *prof, MonoAssembly *assembly) emit_byte (logbuffer, TYPE_ASSEMBLY); emit_ptr (logbuffer, assembly); emit_value (logbuffer, 0); /* flags */ - memcpy (logbuffer->data, name, nlen); - logbuffer->data += nlen; + memcpy (logbuffer->cursor, name, nlen); + logbuffer->cursor += nlen; EXIT_LOG (logbuffer); mono_free (name); @@ -1449,8 +1487,8 @@ class_loaded (MonoProfiler *prof, MonoClass *klass, int result) emit_ptr (logbuffer, klass); emit_ptr (logbuffer, image); emit_value (logbuffer, 0); /* flags */ - memcpy (logbuffer->data, name, nlen); - logbuffer->data += nlen; + memcpy (logbuffer->cursor, name, nlen); + logbuffer->cursor += nlen; //printf ("loaded class %p (%s)\n", klass, name); if (runtime_inited) mono_free (name); @@ -1492,8 +1530,8 @@ class_unloaded (MonoProfiler *prof, MonoClass *klass) emit_ptr (logbuffer, klass); emit_ptr (logbuffer, image); emit_value (logbuffer, 0); /* flags */ - memcpy (logbuffer->data, name, nlen); - logbuffer->data += nlen; + memcpy (logbuffer->cursor, name, nlen); + logbuffer->cursor += nlen; EXIT_LOG (logbuffer); if (runtime_inited) @@ -1624,8 +1662,8 @@ code_buffer_new (MonoProfiler *prof, void *buffer, int size, MonoProfilerCodeBuf emit_ptr (logbuffer, buffer); emit_value (logbuffer, size); if (name) { - memcpy (logbuffer->data, name, nlen); - logbuffer->data += nlen; + memcpy (logbuffer->cursor, name, nlen); + logbuffer->cursor += nlen; } EXIT_LOG (logbuffer); process_requests (prof); @@ -1852,8 +1890,8 @@ domain_name (MonoProfiler *prof, MonoDomain *domain, const char *name) emit_byte (logbuffer, TYPE_DOMAIN); emit_ptr (logbuffer, (void*)(uintptr_t) mono_domain_get_id (domain)); emit_value (logbuffer, 0); /* flags */ - memcpy (logbuffer->data, name, nlen); - logbuffer->data += nlen; + memcpy (logbuffer->cursor, name, nlen); + logbuffer->cursor += nlen; EXIT_LOG (logbuffer); if (logbuffer->next) @@ -1939,8 +1977,8 @@ thread_name (MonoProfiler *prof, uintptr_t tid, const char *name) emit_byte (logbuffer, TYPE_THREAD); emit_ptr (logbuffer, (void*)tid); emit_value (logbuffer, 0); /* flags */ - memcpy (logbuffer->data, name, len); - logbuffer->data += len; + memcpy (logbuffer->cursor, name, len); + logbuffer->cursor += len; EXIT_LOG (logbuffer); if (logbuffer->next) @@ -2010,13 +2048,13 @@ mono_sample_hit (MonoProfiler *profiler, unsigned char *ip, void *context) if (!sbuf) return; /* flush the buffer at 1 second intervals */ - if (sbuf->data > sbuf->buf && (elapsed - sbuf->buf [2]) > 100000) { + if (sbuf->cursor > sbuf->buf && (elapsed - sbuf->buf [2]) > 100000) { timedout = 1; } /* overflow: 400 slots is a big enough number to reduce the chance of losing this event if many * threads hit this same spot at the same time */ - if (timedout || (sbuf->data + 400 >= sbuf->data_end)) { + if (timedout || (sbuf->cursor + 400 >= sbuf->buf_end)) { StatBuffer *oldsb, *foundsb; sbuf = create_stat_buffer (); do { @@ -2035,12 +2073,13 @@ mono_sample_hit (MonoProfiler *profiler, unsigned char *ip, void *context) } } do { - old_data = sbuf->data; + old_data = sbuf->cursor; new_data = old_data + SAMPLE_EVENT_SIZE_IN_SLOTS (bt_data.count); - data = (uintptr_t *)InterlockedCompareExchangePointer ((void * volatile*)&sbuf->data, new_data, old_data); + if (new_data > sbuf->buf_end) + return; /* Not enough room in buf to hold this event-- lost event */ + data = (uintptr_t *)InterlockedCompareExchangePointer ((void * volatile*)&sbuf->cursor, new_data, old_data); } while (data != old_data); - if (old_data >= sbuf->data_end) - return; /* lost event */ + old_data [0] = 1 | (sample_type << 16) | (bt_data.count << 8); old_data [1] = thread_id (); old_data [2] = elapsed; @@ -2130,8 +2169,8 @@ dump_ubin (const char *filename, uintptr_t load_addr, uint64_t offset, uintptr_t emit_svalue (logbuffer, load_addr); emit_uvalue (logbuffer, offset); emit_uvalue (logbuffer, size); - memcpy (logbuffer->data, filename, len); - logbuffer->data += len; + memcpy (logbuffer->cursor, filename, len); + logbuffer->cursor += len; } #endif @@ -2150,8 +2189,8 @@ dump_usym (const char *name, uintptr_t value, uintptr_t size) emit_byte (logbuffer, TYPE_SAMPLE | TYPE_SAMPLE_USYM); emit_ptr (logbuffer, (void*)value); emit_value (logbuffer, size); - memcpy (logbuffer->data, name, len); - logbuffer->data += len; + memcpy (logbuffer->cursor, name, len); + logbuffer->cursor += len; } /* ELF code crashes on some systems. */ @@ -2415,11 +2454,11 @@ dump_sample_hits (MonoProfiler *prof, StatBuffer *sbuf) g_ptr_array_set_size (prof->sorted_sample_events, 0); - for (uintptr_t *sample = sbuf->buf; sample < sbuf->data;) { + for (uintptr_t *sample = sbuf->buf; sample < sbuf->cursor;) { int count = sample [0] & 0xff; int mbt_count = (sample [0] & 0xff00) >> 8; - if (sample + SAMPLE_EVENT_SIZE_IN_SLOTS (mbt_count) > sbuf->data) + if (sample + SAMPLE_EVENT_SIZE_IN_SLOTS (mbt_count) > sbuf->cursor) break; g_ptr_array_add (prof->sorted_sample_events, sample); @@ -2443,6 +2482,7 @@ dump_sample_hits (MonoProfiler *prof, StatBuffer *sbuf) void *address = (void*)managed_sample_base [i * 4 + 2]; if (!method) { + g_assert (domain); MonoJitInfo *ji = mono_jit_info_table_find (domain, (char *)address); if (ji) @@ -4252,8 +4292,8 @@ writer_thread (void *arg) emit_ptr (method_buffer, cstart); emit_value (method_buffer, csize); - memcpy (method_buffer->data, name, nlen); - method_buffer->data += nlen; + memcpy (method_buffer->cursor, name, nlen); + method_buffer->cursor += nlen; mono_free (name); free (info); diff --git a/mono/profiler/proflog.h b/mono/profiler/proflog.h index f1c8af5bf8b..1fbad58d9e7 100644 --- a/mono/profiler/proflog.h +++ b/mono/profiler/proflog.h @@ -93,6 +93,8 @@ enum { TYPE_END }; +// Sampling sources +// Unless you have compiled with --enable-perf-events, only SAMPLE_CYCLES is available enum { SAMPLE_CYCLES = 1, SAMPLE_INSTRUCTIONS, diff --git a/mono/profiler/ptestrunner.pl b/mono/profiler/ptestrunner.pl index 2113c25135f..5215621c2fd 100755 --- a/mono/profiler/ptestrunner.pl +++ b/mono/profiler/ptestrunner.pl @@ -15,8 +15,7 @@ my $minibuilddir = $builddir . "/mono/mini"; # Setup the execution environment # for the profiler module -append_path ("LD_LIBRARY_PATH", $profbuilddir . "/.libs"); -append_path ("DYLD_LIBRARY_PATH", $profbuilddir . "/.libs"); +append_path ("MONO_PROFILER_LIB_DIR", $profbuilddir . "/.libs"); append_path ("DYLD_LIBRARY_PATH", $minibuilddir . "/.libs"); # for mprof-report append_path ("PATH", $profbuilddir);