Remove profiling overhead from profiles

By calculating the average cost of executing the profiling functions and
then subtracting that times the number of entries from the exclusive
cost of an HLL block.

src/core/instance.h

@@ -503,6 +503,9 @@ struct MVMInstance {
     FILE *coverage_log_fh;
     MVMuint32  coverage_control;
 
+    /* The time it takes to run the profiler instrumentation. */
+    MVMuint64 profiling_overhead;
+
     /************************************************************************
      * Debugging
      ************************************************************************/

src/profiler/instrument.c

@@ -390,27 +390,44 @@ static void bind_extra_info(MVMThreadContext *tc, MVMObject *storage, MVMString
 static MVMObject * dump_call_graph_node(MVMThreadContext *tc, ProfDumpStrs *pds, const MVMProfileCallNode *pcn, MVMObject *types_array);
 static MVMObject * dump_call_graph_node_loop(ProfTcPdsStruct *tcpds, const MVMProfileCallNode *pcn) {
     MVMuint32 i;
+    MVMuint64 exclusive_time = pcn->total_time;
+    MVMuint64 overhead       = pcn->total_entries * tcpds->tc->instance->profiling_overhead;
     MVMObject *node_hash;
 
+    /* Subtract profiling overhead, unless that would underflow, in which case just clamp to 0. */
+    if (exclusive_time - overhead > exclusive_time)
+        exclusive_time = 0;
+    else
+        exclusive_time -= overhead;
+
     node_hash = dump_call_graph_node(tcpds->tc, tcpds->pds, pcn, tcpds->types_array);
 
     /* Visit successors in the call graph, dumping them and working out the
      * exclusive time. */
     if (pcn->num_succ) {
-        MVMObject *callees        = new_array(tcpds->tc);
-        MVMuint64  exclusive_time = pcn->total_time;
+        MVMObject *callees = new_array(tcpds->tc);
         for (i = 0; i < pcn->num_succ; i++) {
+            MVMuint64 succ_exclusive_time = pcn->succ[i]->total_time;
+            MVMuint64 succ_overhead       = pcn->succ[i]->total_entries * tcpds->tc->instance->profiling_overhead;
+
             MVM_repr_push_o(tcpds->tc, callees,
                 dump_call_graph_node_loop(tcpds, pcn->succ[i]));
-            exclusive_time -= pcn->succ[i]->total_time;
+
+            /* Subtract profiling overhead, unless that would underflow, in which case just clamp to 0. */
+            if (succ_exclusive_time - succ_overhead > succ_exclusive_time)
+                succ_exclusive_time = 0;
+            else
+                succ_exclusive_time -= succ_overhead;
+
+            exclusive_time -= succ_exclusive_time;
         }
         MVM_repr_bind_key_o(tcpds->tc, node_hash, tcpds->pds->exclusive_time,
             box_i(tcpds->tc, exclusive_time / 1000));
         MVM_repr_bind_key_o(tcpds->tc, node_hash, tcpds->pds->callees, callees);
     }
     else {
         MVM_repr_bind_key_o(tcpds->tc, node_hash, tcpds->pds->exclusive_time,
-            box_i(tcpds->tc, pcn->total_time / 1000));
+            box_i(tcpds->tc, exclusive_time / 1000));
     }
 
     return node_hash;

src/profiler/profile.c

@@ -8,8 +8,33 @@ void MVM_profile_start(MVMThreadContext *tc, MVMObject *config) {
     if (MVM_repr_exists_key(tc, config, tc->instance->str_consts.kind)) {
         MVMString *kind = MVM_repr_get_str(tc,
             MVM_repr_at_key_o(tc, config, tc->instance->str_consts.kind));
-        if (MVM_string_equal(tc, kind, tc->instance->str_consts.instrumented))
+        if (MVM_string_equal(tc, kind, tc->instance->str_consts.instrumented)) {
+            MVMuint64 s, e;
             MVM_profile_instrumented_start(tc, config);
+
+            /* Call the profiling functions a bunch of times and record how long they took. */
+            s = uv_hrtime();
+            for (int i = 0; i < 1000; i++) {
+                MVM_profile_log_enter(tc, tc->cur_frame->static_info, MVM_PROFILE_ENTER_NORMAL);
+                MVM_profile_log_exit(tc);
+            }
+            e = uv_hrtime();
+            tc->instance->profiling_overhead = (MVMuint64) ((e - s) / 1000) * 0.9;
+
+            /* Disable profiling and discard the data we just collected. */
+            uv_mutex_lock(&(tc->instance->mutex_spesh_sync));
+            while (tc->instance->spesh_working != 0)
+                uv_cond_wait(&(tc->instance->cond_spesh_sync), &(tc->instance->mutex_spesh_sync));
+            tc->instance->profiling = 0;
+            MVM_free(tc->prof_data->collected_data);
+            tc->prof_data->collected_data = NULL;
+            MVM_free(tc->prof_data);
+            tc->prof_data = NULL;
+            uv_mutex_unlock(&(tc->instance->mutex_spesh_sync));
+
+            /* Now start profiling for real. */
+            MVM_profile_instrumented_start(tc, config);
+        }
         else if (MVM_string_equal(tc, kind, tc->instance->str_consts.heap))
             MVM_profile_heap_start(tc, config);
         else