Log return value types under the caller's log ID

This means that we still log them if returning from specialized to
unspecialized code. Since it's an unspecialized caller that needs the
information, this makes a lot more sense. There are situations where a
callee called from many places is specialized before various of its
callers are. In the worst case (which has been observed happening in
real code) the caller has just one or two return type samples logged,
but these are poor examples of the overall type trend. Thus the guards
inserted based on the incomplete statistics may end up failing most of
the time, causing a huge number of deoptimizations.

Delightfully, this fix turns out to be a code simplification too, with
the popping of the simulation stack frame being naturally handled as
part of resoliving the correlation ID of the caller frame.

src/core/interp.c

@@ -456,23 +456,23 @@ void MVM_interp_run(MVMThreadContext *tc, void (*initial_invoke)(MVMThreadContex
                 goto NEXT;
             }
             OP(return_i):
-                if (MVM_spesh_log_is_logging(tc))
+                if (MVM_spesh_log_is_caller_logging(tc))
                     MVM_spesh_log_return_type(tc, NULL);
                 MVM_args_set_result_int(tc, GET_REG(cur_op, 0).i64,
                     MVM_RETURN_CALLER_FRAME);
                 if (MVM_frame_try_return(tc) == 0)
                     goto return_label;
                 goto NEXT;
             OP(return_n):
-                if (MVM_spesh_log_is_logging(tc))
+                if (MVM_spesh_log_is_caller_logging(tc))
                     MVM_spesh_log_return_type(tc, NULL);
                 MVM_args_set_result_num(tc, GET_REG(cur_op, 0).n64,
                     MVM_RETURN_CALLER_FRAME);
                 if (MVM_frame_try_return(tc) == 0)
                     goto return_label;
                 goto NEXT;
             OP(return_s):
-                if (MVM_spesh_log_is_logging(tc))
+                if (MVM_spesh_log_is_caller_logging(tc))
                     MVM_spesh_log_return_type(tc, NULL);
                 MVM_args_set_result_str(tc, GET_REG(cur_op, 0).s,
                     MVM_RETURN_CALLER_FRAME);
@@ -481,7 +481,7 @@ void MVM_interp_run(MVMThreadContext *tc, void (*initial_invoke)(MVMThreadContex
                 goto NEXT;
             OP(return_o): {
                 MVMObject *value = GET_REG(cur_op, 0).o;
-                if (MVM_spesh_log_is_logging(tc)) {
+                if (MVM_spesh_log_is_caller_logging(tc)) {
                     MVMROOT(tc, value, {
                         MVM_spesh_log_return_type(tc, value);
                     });
@@ -492,7 +492,7 @@ void MVM_interp_run(MVMThreadContext *tc, void (*initial_invoke)(MVMThreadContex
                 goto NEXT;
             }
             OP(return):
-                if (MVM_spesh_log_is_logging(tc))
+                if (MVM_spesh_log_is_caller_logging(tc))
                     MVM_spesh_log_return_type(tc, NULL);
                 MVM_args_assert_void_return_ok(tc, MVM_RETURN_CALLER_FRAME);
                 if (MVM_frame_try_return(tc) == 0)

src/spesh/log.c

@@ -194,7 +194,8 @@ void MVM_spesh_log_invoke_target(MVMThreadContext *tc, MVMObject *invoke_target,
 /* Log the type returned to a frame after an invocation. */
 void MVM_spesh_log_return_type(MVMThreadContext *tc, MVMObject *value) {
     MVMSpeshLog *sl = tc->spesh_log;
-    MVMint32 cid = tc->cur_frame->spesh_correlation_id;
+    MVMFrame *caller = tc->cur_frame->caller;
+    MVMint32 cid = caller->spesh_correlation_id;
     MVMSpeshLogEntry *entry = &(sl->body.entries[sl->body.used]);
     entry->kind = MVM_SPESH_LOG_RETURN;
     entry->id = cid;
@@ -206,7 +207,8 @@ void MVM_spesh_log_return_type(MVMThreadContext *tc, MVMObject *value) {
         entry->type.type = NULL;
         entry->type.flags = 0;
     }
-    entry->type.bytecode_offset = 0; /* Not relevant for this case. */
+    entry->type.bytecode_offset = (caller->return_address - caller->static_info->body.bytecode)
+        - (caller->return_type == MVM_RETURN_VOID ? 4 : 6);
     commit_entry(tc, sl);
 }
 

src/spesh/log.h

@@ -24,11 +24,16 @@ struct MVMSpeshLogGuard {
  * thresholds.c, but we set it higher to allow more data collection. */
 #define MVM_SPESH_LOG_LOGGED_ENOUGH 1000
 
-/* Quick check if we are logging, to save function call overhead. */
+/* Quick inline checks if we are logging, to save function call overhead. */
 MVM_STATIC_INLINE MVMint32 MVM_spesh_log_is_logging(MVMThreadContext *tc) {
     MVMFrame *cur_frame = tc->cur_frame;
     return cur_frame->spesh_cand == NULL && cur_frame->spesh_correlation_id && tc->spesh_log;
 }
+MVM_STATIC_INLINE MVMint32 MVM_spesh_log_is_caller_logging(MVMThreadContext *tc) {
+    MVMFrame *caller_frame = tc->cur_frame->caller;
+    return caller_frame && caller_frame->spesh_cand == NULL &&
+        caller_frame->spesh_correlation_id && tc->spesh_log;
+}
 
 void MVM_spesh_log_initialize_thread(MVMThreadContext *tc, MVMint32 main_thread);
 MVMSpeshLog * MVM_spesh_log_create(MVMThreadContext *tc, MVMThread *target_thread);

src/spesh/stats.c

@@ -592,13 +592,14 @@ void MVM_spesh_stats_update(MVMThreadContext *tc, MVMSpeshLog *sl, MVMObject *sf
                 break;
             }
             case MVM_SPESH_LOG_TYPE:
+            case MVM_SPESH_LOG_RETURN:
             case MVM_SPESH_LOG_INVOKE:
             case MVM_SPESH_LOG_PLUGIN_RESOLUTION: {
                 /* We only incorporate these into the model later, and only
                  * then if we need to. For now, just keep references to
                  * them. */
                 MVMSpeshSimStackFrame *simf = sim_stack_find(tc, sims, e->id, sf_updated);
-                if (simf) {
+                if (simf && (e->kind != MVM_SPESH_LOG_RETURN || e->type.type)) {
                     if (simf->offset_logs_used == simf->offset_logs_limit) {
                         simf->offset_logs_limit += 32;
                         simf->offset_logs = MVM_realloc(simf->offset_logs,
@@ -624,26 +625,6 @@ void MVM_spesh_stats_update(MVMThreadContext *tc, MVMSpeshLog *sl, MVMObject *sf
                     add_static_value(tc, simf, e->value.bytecode_offset, e->value.value);
                 break;
             }
-            case MVM_SPESH_LOG_RETURN: {
-                MVMSpeshSimStackFrame *simf = sim_stack_find(tc, sims, e->id, sf_updated);
-                if (simf) {
-                    MVMStaticFrame *called_sf = simf->sf;
-                    sim_stack_pop(tc, sims, sf_updated);
-                    if (e->type.type && sims->used) {
-                        MVMSpeshSimStackFrame *caller = &(sims->frames[sims->used - 1]);
-                        if (called_sf == caller->last_invoke_sf) {
-                            if (caller->offset_logs_used == caller->offset_logs_limit) {
-                                caller->offset_logs_limit += 32;
-                                caller->offset_logs = MVM_realloc(caller->offset_logs,
-                                    caller->offset_logs_limit * sizeof(MVMSpeshLogEntry *));
-                            }
-                            e->type.bytecode_offset = caller->last_invoke_offset;
-                            caller->offset_logs[caller->offset_logs_used++] = e;
-                        }
-                    }
-                }
-                break;
-            }
         }
     }
     save_or_free_sim_stack(tc, sims, log_from_tc, sf_updated);