Merge pull request #2720 from mono/fix-39325
[mono.git] / mono / profiler / proflog.c
index c563105892c9c33d35c28f5a3b1447279d015808..188a40a26479643bb1e32c3b4ca84e439d8d22da 100644 (file)
@@ -7,6 +7,7 @@
  *
  * Copyright 2010 Novell, Inc (http://www.novell.com)
  * Copyright 2011 Xamarin Inc (http://www.xamarin.com)
+ * Licensed under the MIT license. See LICENSE file in the project root for full license information.
  */
 
 #include <config.h>
@@ -34,6 +35,9 @@
 #ifdef HAVE_UNISTD_H
 #include <unistd.h>
 #endif
+#ifdef HAVE_SCHED_GETAFFINITY
+#include <sched.h>
+#endif
 #include <fcntl.h>
 #include <errno.h>
 #if defined(HOST_WIN32) || defined(DISABLE_SOCKETS)
@@ -413,8 +417,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;
@@ -422,11 +430,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];
 };
 
@@ -438,12 +454,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];
 };
 
@@ -534,8 +576,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;
 }
 
@@ -546,8 +588,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;
 }
 
@@ -570,7 +612,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 ();
@@ -601,16 +643,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
@@ -621,25 +663,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
@@ -648,7 +690,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
@@ -658,9 +700,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);
 }
 
 /*
@@ -752,7 +794,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
@@ -862,7 +904,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);
@@ -871,11 +913,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)
        }
@@ -1091,7 +1133,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]);
        }
@@ -1304,8 +1346,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)
@@ -1334,8 +1376,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)
@@ -1368,8 +1410,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);
@@ -1401,8 +1443,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);
@@ -1446,8 +1488,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);
@@ -1489,8 +1531,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)
@@ -1621,8 +1663,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);
@@ -1849,8 +1891,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)
@@ -1936,8 +1978,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)
@@ -2007,13 +2049,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 {
@@ -2032,12 +2074,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;
@@ -2127,8 +2170,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
 
@@ -2147,8 +2190,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. */
@@ -2412,11 +2455,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);
@@ -2440,6 +2483,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)
@@ -2494,12 +2538,12 @@ dump_sample_hits (MonoProfiler *prof, StatBuffer *sbuf)
 static int
 mono_cpu_count (void)
 {
-       int count = 0;
 #ifdef PLATFORM_ANDROID
        /* Android tries really hard to save power by powering off CPUs on SMP phones which
         * means the normal way to query cpu count returns a wrong value with userspace API.
         * Instead we use /sys entries to query the actual hardware CPU count.
         */
+       int count = 0;
        char buffer[8] = {'\0'};
        int present = open ("/sys/devices/system/cpu/present", O_RDONLY);
        /* Format of the /sys entry is a cpulist of indexes which in the case
@@ -2514,13 +2558,42 @@ mono_cpu_count (void)
        if (count > 0)
                return count + 1;
 #endif
+
+#if defined(HOST_ARM) || defined (HOST_ARM64)
+
+       /* ARM platforms tries really hard to save power by powering off CPUs on SMP phones which
+        * means the normal way to query cpu count returns a wrong value with userspace API. */
+
+#ifdef _SC_NPROCESSORS_CONF
+       {
+               int count = sysconf (_SC_NPROCESSORS_CONF);
+               if (count > 0)
+                       return count;
+       }
+#endif
+
+#else
+
+#ifdef HAVE_SCHED_GETAFFINITY
+       {
+               cpu_set_t set;
+               if (sched_getaffinity (getpid (), sizeof (set), &set) == 0)
+                       return CPU_COUNT (&set);
+       }
+#endif
 #ifdef _SC_NPROCESSORS_ONLN
-       count = sysconf (_SC_NPROCESSORS_ONLN);
-       if (count > 0)
-               return count;
+       {
+               int count = sysconf (_SC_NPROCESSORS_ONLN);
+               if (count > 0)
+                       return count;
+       }
 #endif
+
+#endif /* defined(HOST_ARM) || defined (HOST_ARM64) */
+
 #ifdef USE_SYSCTL
        {
+               int count;
                int mib [2];
                size_t len = sizeof (int);
                mib [0] = CTL_HW;
@@ -4236,8 +4309,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);