introduce "telemeh", a high-precision-time low-impact logger

also uses it in a bunch of places that seem interesting

hopefully the impact is very small when it's inactive ...

build/Makefile.in

@@ -204,6 +204,7 @@ OBJECTS = src/core/callsite@obj@ \
           src/profiler/log@obj@ \
           src/profiler/profile@obj@ \
           src/profiler/heapsnapshot@obj@ \
+          src/profiler/telemeh@obj@ \
           src/instrument/crossthreadwrite@obj@ \
           src/instrument/line_coverage@obj@ \
           src/moar@obj@ \
@@ -350,6 +351,7 @@ HEADERS = src/moar.h \
           src/profiler/log.h \
           src/profiler/profile.h \
           src/profiler/heapsnapshot.h \
+          src/profiler/telemeh.h \
           src/platform/mmap.h \
           src/platform/time.h \
           src/platform/threads.h \

src/6model/reprs/ConcBlockingQueue.c

@@ -107,6 +107,8 @@ static void at_pos(MVMThreadContext *tc, MVMSTable *st, MVMObject *root, void *d
 
     if (MVM_load(&cbq->elems) > 0) {
         MVMConcBlockingQueueNode *peeked;
+        unsigned int interval_id;
+        interval_id = startInterval(tc, "ConcBlockingQueue.at_pos");
         MVMROOT(tc, root, {
             MVM_gc_mark_thread_blocked(tc);
             uv_mutex_lock(&cbq->locks->head_lock);
@@ -117,6 +119,7 @@ static void at_pos(MVMThreadContext *tc, MVMSTable *st, MVMObject *root, void *d
         peeked = cbq->head->next;
         value->o = peeked ? peeked->value : tc->instance->VMNull;
         uv_mutex_unlock(&cbq->locks->head_lock);
+        stopInterval(tc, interval_id, "ConcBlockingQueue.at_pos");
     }
     else {
         value->o = tc->instance->VMNull;
@@ -133,6 +136,7 @@ static void push(MVMThreadContext *tc, MVMSTable *st, MVMObject *root, void *dat
     MVMConcBlockingQueueNode *add;
     AO_t orig_elems;
     MVMObject *to_add = value.o;
+    unsigned int interval_id;
 
     if (kind != MVM_reg_obj)
         MVM_exception_throw_adhoc(tc,
@@ -143,6 +147,7 @@ static void push(MVMThreadContext *tc, MVMSTable *st, MVMObject *root, void *dat
 
     add = MVM_calloc(1, sizeof(MVMConcBlockingQueueNode));
 
+    interval_id = startInterval(tc, "ConcBlockingQueue.push");
     MVMROOT(tc, root, {
     MVMROOT(tc, to_add, {
         MVM_gc_mark_thread_blocked(tc);
@@ -169,15 +174,18 @@ static void push(MVMThreadContext *tc, MVMSTable *st, MVMObject *root, void *dat
         uv_cond_signal(&cbq->locks->head_cond);
         uv_mutex_unlock(&cbq->locks->head_lock);
     }
+    stopInterval(tc, interval_id, "ConcBlockingQueue.push");
 }
 
 static void shift(MVMThreadContext *tc, MVMSTable *st, MVMObject *root, void *data, MVMRegister *value, MVMuint16 kind) {
     MVMConcBlockingQueueBody *cbq = (MVMConcBlockingQueueBody *)data;
     MVMConcBlockingQueueNode *taken;
+    unsigned int interval_id;
 
     if (kind != MVM_reg_obj)
         MVM_exception_throw_adhoc(tc, "Can only shift objects from a ConcBlockingQueue");
 
+    interval_id = startInterval(tc, "ConcBlockingQueue.shift");
     MVMROOT(tc, root, {
         MVM_gc_mark_thread_blocked(tc);
         uv_mutex_lock(&cbq->locks->head_lock);
@@ -206,6 +214,7 @@ static void shift(MVMThreadContext *tc, MVMSTable *st, MVMObject *root, void *da
         uv_cond_signal(&cbq->locks->head_cond);
 
     uv_mutex_unlock(&cbq->locks->head_lock);
+    stopInterval(tc, interval_id, "ConcBlockingQueue.shift");
 }
 
 /* Set the size of the STable. */
@@ -267,7 +276,9 @@ MVMObject * MVM_concblockingqueue_poll(MVMThreadContext *tc, MVMConcBlockingQueu
     MVMConcBlockingQueue *cbq = (MVMConcBlockingQueue *)queue;
     MVMConcBlockingQueueNode *taken;
     MVMObject *result = tc->instance->VMNull;
+    unsigned int interval_id;
 
+    interval_id = startInterval(tc, "ConcBlockingQueue.poll");
     MVMROOT(tc, cbq, {
         MVM_gc_mark_thread_blocked(tc);
         uv_mutex_lock(&cbq->body.locks->head_lock);
@@ -288,5 +299,6 @@ MVMObject * MVM_concblockingqueue_poll(MVMThreadContext *tc, MVMConcBlockingQueu
 
     uv_mutex_unlock(&cbq->body.locks->head_lock);
 
+    stopInterval(tc, interval_id, "ConcBlockingQueue.poll");
     return result;
 }

src/6model/reprs/ConditionVariable.c

@@ -124,10 +124,14 @@ MVMObject * MVM_conditionvariable_from_lock(MVMThreadContext *tc, MVMReentrantMu
 void MVM_conditionvariable_wait(MVMThreadContext *tc, MVMConditionVariable *cv) {
     MVMReentrantMutex *rm = (MVMReentrantMutex *)cv->body.mutex;
     AO_t orig_rec_level;
+    unsigned int interval_id;
 
     if (MVM_load(&rm->body.holder_id) != tc->thread_id)
         MVM_exception_throw_adhoc(tc,
             "Can only wait on a condition variable when holding mutex");
+
+    interval_id = startInterval(tc, "ConditionVariable.wait");
+    annotateInterval(cv->body.condvar, interval_id, "this condition variable");
     orig_rec_level = MVM_load(&rm->body.lock_count);
     MVM_store(&rm->body.holder_id, 0);
     MVM_store(&rm->body.lock_count, 0);
@@ -142,14 +146,17 @@ void MVM_conditionvariable_wait(MVMThreadContext *tc, MVMConditionVariable *cv)
 
     MVM_store(&rm->body.holder_id, tc->thread_id);
     MVM_store(&rm->body.lock_count, orig_rec_level);
+    stopInterval(tc, interval_id, "ConditionVariable.wait");
 }
 
 /* Signals one thread waiting on the condition. */
 void MVM_conditionvariable_signal_one(MVMThreadContext *tc, MVMConditionVariable *cv) {
+    takeTimeStamp(tc, "ConditionVariable.signal_one");
     uv_cond_signal(cv->body.condvar);
 }
 
 /* Signals all threads waiting on the condition. */
 void MVM_conditionvariable_signal_all(MVMThreadContext *tc, MVMConditionVariable *cv) {
+    takeTimeStamp(tc, "ConditionVariable.signal_all");
     uv_cond_broadcast(cv->body.condvar);
 }

src/6model/reprs/ReentrantMutex.c

@@ -117,12 +117,15 @@ static const MVMREPROps ReentrantMutex_this_repr = {
 
 /* Locks the mutex. */
 void MVM_reentrantmutex_lock(MVMThreadContext *tc, MVMReentrantMutex *rm) {
+    unsigned int interval_id;
     if (MVM_load(&rm->body.holder_id) == tc->thread_id) {
         /* We already hold the lock; bump the count. */
         MVM_incr(&rm->body.lock_count);
     }
     else {
         /* Not holding the lock; obtain it. */
+        /*interval_id = startInterval(tc, "ReentrantMutex obtains lock");*/
+        /*annotateInterval(rm->body.mutex, interval_id, "lock in question");*/
         MVMROOT(tc, rm, {
             MVM_gc_mark_thread_blocked(tc);
             uv_mutex_lock(rm->body.mutex);
@@ -131,6 +134,7 @@ void MVM_reentrantmutex_lock(MVMThreadContext *tc, MVMReentrantMutex *rm) {
         MVM_store(&rm->body.holder_id, tc->thread_id);
         MVM_store(&rm->body.lock_count, 1);
         tc->num_locks++;
+        /*stopInterval(tc, interval_id, "ReentrantMutex obtained lock");*/
     }
 }
 
@@ -143,6 +147,7 @@ void MVM_reentrantmutex_unlock(MVMThreadContext *tc, MVMReentrantMutex *rm) {
             MVM_store(&rm->body.holder_id, 0);
             uv_mutex_unlock(rm->body.mutex);
             tc->num_locks--;
+            /*takeTimeStamp(rm->body.mutex, "this ReentrantMutex unlocked");*/
         }
     }
     else {

src/6model/reprs/Semaphore.c

@@ -115,18 +115,24 @@ static const MVMREPROps Semaphore_this_repr = {
 };
 
 MVMint64 MVM_semaphore_tryacquire(MVMThreadContext *tc, MVMSemaphore *sem) {
-    int r = uv_sem_trywait(sem->body.sem);
+    int r;
+    takeTimeStamp(tc, "Semaphore.tryAcquire");
+    r = uv_sem_trywait(sem->body.sem);
     return !r;
 }
 
 void MVM_semaphore_acquire(MVMThreadContext *tc, MVMSemaphore *sem) {
+    unsigned int interval_id;
+    interval_id = startInterval(tc, "Semaphore.acquire");
     MVMROOT(tc, sem, {
         MVM_gc_mark_thread_blocked(tc);
         uv_sem_wait(sem->body.sem);
         MVM_gc_mark_thread_unblocked(tc);
     });
+    stopInterval(tc, interval_id, "Semaphore.acquire");
 }
 
 void MVM_semaphore_release(MVMThreadContext *tc, MVMSemaphore *sem) {
+    takeTimeStamp(tc, "Semaphore.release");
     uv_sem_post(sem->body.sem);
 }

src/core/nativecall_dyncall.c

@@ -211,13 +211,16 @@ static char callback_handler(DCCallback *cb, DCArgs *cb_args, DCValue *cb_result
     MVMint32 num_roots, i;
     MVMRegister res;
     MVMRegister *args;
+    unsigned int interval_id;
 
     /* Unblock GC if needed, so this thread can do work. */
     MVMThreadContext *tc = data->tc;
     MVMint32 was_blocked = MVM_gc_is_thread_blocked(tc);
     if (was_blocked)
         MVM_gc_mark_thread_unblocked(tc);
 
+    interval_id = startInterval(tc, "nativecall callback handler");
+
     /* Build a callsite and arguments buffer. */
     args = MVM_malloc(data->num_types * sizeof(MVMRegister));
     num_roots = 0;
@@ -303,6 +306,7 @@ static char callback_handler(DCCallback *cb, DCArgs *cb_args, DCValue *cb_result
                 args[i - 1].i64 = dcbArgULongLong(cb_args);
                 break;
             default:
+                stopInterval(tc, interval_id, "nativecall callback handler failed");
                 MVM_exception_throw_adhoc(tc,
                     "Internal error: unhandled dyncall callback argument type");
         }
@@ -412,6 +416,7 @@ static char callback_handler(DCCallback *cb, DCArgs *cb_args, DCValue *cb_result
             cb_result->l = MVM_nativecall_unmarshal_ulonglong(data->tc, res.o);
             break;
         default:
+            stopInterval(tc, interval_id, "nativecall callback handler failed");
             MVM_exception_throw_adhoc(data->tc,
                 "Internal error: unhandled dyncall callback return type");
     }
@@ -424,6 +429,8 @@ static char callback_handler(DCCallback *cb, DCArgs *cb_args, DCValue *cb_result
     if (was_blocked)
         MVM_gc_mark_thread_blocked(tc);
 
+    stopInterval(tc, interval_id, "nativecall callback handler");
+
     /* Indicate what we're producing as a result. */
     return get_signature_char(data->typeinfos[0]);
 }
@@ -475,11 +482,15 @@ MVMObject * MVM_nativecall_invoke(MVMThreadContext *tc, MVMObject *res_type,
     void     *entry_point = body->entry_point;
     void     *ptr         = NULL;
 
+    unsigned int interval_id;
+
     /* Create and set up call VM. */
     DCCallVM *vm = dcNewCallVM(8192);
     dcMode(vm, body->convention);
     dcReset(vm);
 
+    interval_id = startInterval(tc, "nativecall invoke");
+
     /* Process arguments. */
     for (i = 0; i < num_args; i++) {
         MVMObject *value = MVM_repr_at_pos_o(tc, args, i);
@@ -580,6 +591,7 @@ MVMObject * MVM_nativecall_invoke(MVMThreadContext *tc, MVMObject *res_type,
                 handle_arg("integer", cont_i, DCulonglong, i64, dcArgLongLong, MVM_nativecall_unmarshal_ulonglong);
                 break;
             default:
+                stopInterval(tc, interval_id, "nativecall invoke failed");
                 MVM_exception_throw_adhoc(tc, "Internal error: unhandled dyncall argument type");
         }
     }
@@ -720,6 +732,7 @@ MVMObject * MVM_nativecall_invoke(MVMThreadContext *tc, MVMObject *res_type,
                     break;
                 }
                 default:
+                    stopInterval(tc, interval_id, "nativecall invoke failed");
                     MVM_exception_throw_adhoc(tc, "Internal error: unhandled dyncall return type");
             }
         }
@@ -772,6 +785,7 @@ MVMObject * MVM_nativecall_invoke(MVMThreadContext *tc, MVMObject *res_type,
                         (MVMint64)*(DCpointer *)free_rws[num_rws]);
                     break;
                 default:
+                    stopInterval(tc, interval_id, "nativecall invoke failed");
                     MVM_exception_throw_adhoc(tc, "Internal error: unhandled dyncall argument type");
             }
             num_rws++;
@@ -796,5 +810,6 @@ MVMObject * MVM_nativecall_invoke(MVMThreadContext *tc, MVMObject *res_type,
     /* Finally, free call VM. */
     dcFree(vm);
 
+    stopInterval(tc, interval_id, "nativecall invoke");
     return result;
 }

src/core/nativecall_libffi.c

@@ -210,13 +210,16 @@ static void callback_handler(ffi_cif *cif, void *cb_result, void **cb_args, void
     MVMRegister *args;
     MVMNativeCallback *data = (MVMNativeCallback *)cb_data;
     void           **values = MVM_malloc(sizeof(void *) * (data->cs->arg_count ? data->cs->arg_count : 1));
+    unsigned int interval_id;
 
     /* Unblock GC if needed, so this thread can do work. */
     MVMThreadContext *tc = data->tc;
     MVMint32 was_blocked = MVM_gc_is_thread_blocked(tc);
     if (was_blocked)
         MVM_gc_mark_thread_unblocked(tc);
 
+    interval_id = startInterval(tc, "nativecall callback handler");
+
     /* Build a callsite and arguments buffer. */
     args = MVM_malloc(data->num_types * sizeof(MVMRegister));
     num_roots = 0;
@@ -296,6 +299,7 @@ static void callback_handler(ffi_cif *cif, void *cb_result, void **cb_args, void
                 args[i - 1].i64 = *(unsigned long long *)cb_args[i - 1];
                 break;
             default:
+                stopInterval(tc, interval_id, "nativecall callback handler failed");
                 MVM_exception_throw_adhoc(tc,
                     "Internal error: unhandled libffi callback argument type");
         }
@@ -405,6 +409,7 @@ static void callback_handler(ffi_cif *cif, void *cb_result, void **cb_args, void
             *(unsigned long long *)cb_result = MVM_nativecall_unmarshal_ulonglong(data->tc, res.o);
             break;
         default:
+                stopInterval(tc, interval_id, "nativecall callback handler failed");
             MVM_exception_throw_adhoc(data->tc,
                 "Internal error: unhandled libffi callback return type");
     }
@@ -417,6 +422,8 @@ static void callback_handler(ffi_cif *cif, void *cb_result, void **cb_args, void
     /* Re-block GC if needed, so other threads will be able to collect. */
     if (was_blocked)
         MVM_gc_mark_thread_blocked(tc);
+
+    stopInterval(tc, interval_id, "nativecall callback handler");
 }
 
 #define handle_arg(what, cont_X, dc_type, reg_slot, unmarshal_fun) do { \
@@ -476,9 +483,13 @@ MVMObject * MVM_nativecall_invoke(MVMThreadContext *tc, MVMObject *res_type,
     void     *entry_point = body->entry_point;
     void    **values      = MVM_malloc(sizeof(void *) * (num_args ? num_args : 1));
 
+    unsigned int interval_id;
+
     ffi_cif cif;
     ffi_status status  = ffi_prep_cif(&cif, body->convention, (unsigned int)num_args, body->ffi_ret_type, body->ffi_arg_types);
 
+    interval_id = startInterval(tc, "nativecall invoke");
+
     /* Process arguments. */
     for (i = 0; i < num_args; i++) {
         MVMObject *value = MVM_repr_at_pos_o(tc, args, i);
@@ -582,6 +593,7 @@ MVMObject * MVM_nativecall_invoke(MVMThreadContext *tc, MVMObject *res_type,
                 handle_arg("integer", cont_i, unsigned long long, i64, MVM_nativecall_unmarshal_ulonglong);
                 break;
             default:
+                stopInterval(tc, interval_id, "nativecall invoke failed");
                 MVM_exception_throw_adhoc(tc, "Internal error: unhandled libffi argument type");
         }
     }
@@ -686,6 +698,7 @@ MVMObject * MVM_nativecall_invoke(MVMThreadContext *tc, MVMObject *res_type,
                     handle_ret(tc, unsigned long long, ffi_arg, MVM_nativecall_make_int);
                     break;
                 default:
+                    stopInterval(tc, interval_id, "nativecall invoke failed");
                     MVM_exception_throw_adhoc(tc, "Internal error: unhandled libffi return type");
             }
         }
@@ -737,6 +750,7 @@ MVMObject * MVM_nativecall_invoke(MVMThreadContext *tc, MVMObject *res_type,
                         (MVMint64)*(void **)*(void **)values[i]);
                     break;
                 default:
+                    stopInterval(tc, interval_id, "nativecall invoke failed");
                     MVM_exception_throw_adhoc(tc, "Internal error: unhandled libffi argument type");
             }
         }
@@ -754,5 +768,7 @@ MVMObject * MVM_nativecall_invoke(MVMThreadContext *tc, MVMObject *res_type,
     if (values)
         MVM_free(values);
 
+    stopInterval(tc, interval_id, "nativecall invoke");
+
     return result;
 }

src/core/threads.c

@@ -12,6 +12,9 @@ typedef struct {
 MVMObject * MVM_thread_new(MVMThreadContext *tc, MVMObject *invokee, MVMint64 app_lifetime) {
     MVMThread *thread;
     MVMThreadContext *child_tc;
+    unsigned int interval_id;
+
+    interval_id = startInterval(tc, "spawning a new thread off of me");
 
     /* Create the Thread object and stash code to run and lifetime. */
     MVMROOT(tc, invokee, {
@@ -31,6 +34,8 @@ MVMObject * MVM_thread_new(MVMThreadContext *tc, MVMObject *invokee, MVMint64 ap
         /* Add one, since MVM_incr returns original. */
     thread->body.tc = child_tc;
 
+    stopInterval(child_tc, interval_id, "i'm the newly spawned thread.");
+
     /* Also make a copy of the thread ID in the thread object itself, so it
      * is available once the thread dies and its ThreadContext is gone. */
     thread->body.thread_id = child_tc->thread_id;
@@ -196,6 +201,7 @@ MVMint64 MVM_thread_native_id(MVMThreadContext *tc, MVMObject *thread_obj) {
 
 /* Yields control to another thread. */
 void MVM_thread_yield(MVMThreadContext *tc) {
+    takeTimeStamp(tc, "thread yielding");
     MVM_platform_thread_yield();
 }