Implement debug strings.

This allows the interpreter author to insert special comments into the
trace IR for helping with debugging.

In the interpreter source code you can add a call like
`yk_debug_str(debug_string)` and when it is traced, a special `DebugStr`
bytecode is inserted into the JIT IR, which when printed, displays the
dynamic value of `debug_string` at the time the instruction was traced.

Under the hood, this works a lot like promotion. Calls to `yk_debug_str`
(when tracing is enabled) causes `debug_string` to be copied into a
vector which is passed down the pipeline.

Here's an example for yklua:
```diff
--- a/src/lvm.c
+++ b/src/lvm.c
@@ -27,6 +27,7 @@
 #include "lgc.h"
 #include "lobject.h"
 #include "lopcodes.h"
+#include "lopnames.h"
 #include "lstate.h"
 #include "lstring.h"
 #include "ltable.h"
@@ -1234,6 +1235,10 @@ void luaV_execute (lua_State *L, CallInfo *ci) {
     lua_assert(base <= L->top.p && L->top.p <= L->stack_last.p);
     /* invalidate top for instructions not expecting it */
     lua_assert(isIT(i) || (cast_void(L->top.p = base), 1));
+    char dbgmsg[128];
+    snprintf(dbgmsg, 128, "%s", opnames[GET_OPCODE(i)]);
+    yk_debug_str(dbgmsg);
+
     vmdispatch (GET_OPCODE(i)) {
       vmcase(OP_MOVE) {
         StkId ra = RA(i);
```

Will give a trace with debug strings inside like:
```
    ...
    %408: ptr = ptr_add %361, 152
    %409: ptr = load %408
    %410: i32 = call @snprintf(%320, 128i64, %364, %409)
    ; debug_str: NEWTABLE
    %412: ptr = ptr_add %351, 592
    %413: i32 = shl 1i32, 4294967295i32
    ...
```

The strings are formatted as a comment.

(Obviously you'd probably want to guard the debug string logic in the
interpreter somehow so the overhead doesn't arise in production)

For this facility to be useful, the `DebugStr` bytecode must never be
optimised out. We tell the trace optimiser that this bytecode is an
"internal" bytecode, which stops DCE from killing it.

When adding the code to outline the contents of `yk_debug_str()` I
needed to copy logic from `handle_promote()` and found several other
copies of that same code in other places in the trace builder. Thic
change also de-duplicates the copies into a function
`outline_until_after_call()`.

tests/c/yk_debug_str.c

@@ -0,0 +1,70 @@
+// Run-time:
+//   env-var: YKD_LOG_IR=aot,jit-pre-opt,jit-post-opt
+//   env-var: YKD_SERIALISE_COMPILATION=1
+//   env-var: YK_LOG=4
+//   stderr:
+//     ...
+//     --- Begin aot ---
+//     ...
+//     debug_str %{{10_0}}
+//     ...
+//     ...call fprintf(...
+//     ...
+//     debug_str %{{13_0}}
+//     ...
+//     --- End aot ---
+//     ...
+//     --- Begin jit-pre-opt ---
+//     ...
+//     ; debug_str: before fprintf: 4
+//     ...
+//     ...call @fprintf(...
+//     ...
+//     ; debug_str: after fprintf: 5
+//     ...
+//     --- End jit-pre-opt ---
+//     ...
+//     --- Begin jit-post-opt ---
+//     ...
+//     ; debug_str: before fprintf: 4
+//     ...
+//     ...call @fprintf(...
+//     ...
+//     ; debug_str: after fprintf: 5
+//     ...
+//     --- End jit-post-opt ---
+//     ...
+
+// Check that yk_debug_str() works and is not optimised out.
+
+#include <assert.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#include <yk.h>
+#include <yk_testing.h>
+
+#define MAX_MSG 128
+
+int main(int argc, char **argv) {
+  YkMT *mt = yk_mt_new(NULL);
+  yk_mt_hot_threshold_set(mt, 0);
+  YkLocation loc = yk_location_new();
+  char msg[MAX_MSG];
+
+  int i = 4;
+  NOOPT_VAL(loc);
+  NOOPT_VAL(i);
+  while (i > 0) {
+    yk_mt_control_point(mt, &loc);
+    snprintf(msg, MAX_MSG, "before fprintf: %d", i);
+    yk_debug_str(msg);
+    fprintf(stderr, "%d\n", i);
+    snprintf(msg, MAX_MSG, "after fprintf: %d", i + 1);
+    yk_debug_str(msg);
+    i--;
+  }
+  yk_location_drop(loc);
+  yk_mt_shutdown(mt);
+  return (EXIT_SUCCESS);
+}

tests/c/yk_debug_str_outline.c

@@ -0,0 +1,76 @@
+// Run-time:
+//   env-var: YKD_LOG_IR=aot,jit-pre-opt,jit-post-opt
+//   env-var: YKD_SERIALISE_COMPILATION=1
+//   env-var: YK_LOG=4
+//   stderr:
+//     ...
+//     --- Begin aot ---
+//     ...
+//     debug_str %{{10_0}}
+//     ...
+//     ...call fprintf(...
+//     ...
+//     debug_str %{{13_0}}
+//     ...
+//     --- End aot ---
+//     ...
+//     --- Begin jit-pre-opt ---
+//     ...
+//     ; debug_str: before fprintf: 4
+//     ...
+//     ...call @fprintf(...
+//     ...
+//     ; debug_str: after fprintf: 5
+//     ...
+//     --- End jit-pre-opt ---
+//     ...
+//     --- Begin jit-post-opt ---
+//     ...
+//     ; debug_str: before fprintf: 4
+//     ...
+//     ...call @fprintf(...
+//     ...
+//     ; debug_str: after fprintf: 5
+//     ...
+//     --- End jit-post-opt ---
+//     ...
+
+// Check that yk_debug_str() works and is not optimised out.
+
+#include <assert.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+#include <yk.h>
+#include <yk_testing.h>
+
+#define MAX_MSG 128
+
+__attribute__((yk_outline,noinline))
+void f() {
+  yk_debug_str("inside f");
+}
+
+int main(int argc, char **argv) {
+  YkMT *mt = yk_mt_new(NULL);
+  yk_mt_hot_threshold_set(mt, 0);
+  YkLocation loc = yk_location_new();
+  char msg[MAX_MSG];
+
+  int i = 4;
+  NOOPT_VAL(loc);
+  NOOPT_VAL(i);
+  while (i > 0) {
+    yk_mt_control_point(mt, &loc);
+    snprintf(msg, MAX_MSG, "before fprintf: %d", i);
+    yk_debug_str(msg);
+    f();
+    fprintf(stderr, "%d\n", i);
+    snprintf(msg, MAX_MSG, "after fprintf: %d", i + 1);
+    yk_debug_str(msg);
+    i--;
+  }
+  yk_location_drop(loc);
+  yk_mt_shutdown(mt);
+  return (EXIT_SUCCESS);
+}

ykcapi/src/lib.rs

@@ -6,6 +6,12 @@
 //! The sane solution is to have only one `cdylib` crate in our workspace (this crate) and all
 //! other crates are regular `rlibs`.
 
+// FIXME: This crate was designed to contain the entire public C API surface of Yk. Over time C API
+// functions have leaked elsewhere. For example yk_debug_str() and yk_promote_*() are defined
+// elsewhere. We should either move all the C API back into this file, or maybe move all of the C
+// API into (e.g.) `ykrt::api::c` (and make ykrt a cdylib). The former means you have to `pub`
+// stuff in `ykrt`, so perhaps the latter?
+
 #![allow(clippy::missing_safety_doc)]
 #![feature(naked_functions)]
 

ykcapi/yk.h

@@ -82,4 +82,12 @@ long long __yk_promote_c_long_long(long long);
 // Rust defines `usize` to be layout compatible with `uintptr_t`.
 uintptr_t __yk_promote_usize(uintptr_t);
 
+/// Insert a debugging string.
+///
+/// When a call to this function is traced, the dynamic value of `msg` will be
+/// shown when the trace is displayed.
+///
+/// `msg` must be a pointer to a UTF-8 compatible string.
+void yk_debug_str(char *fmt, ...);
+
 #endif

ykrt/src/compile/jitc_yk/aot_ir.rs

@@ -1002,6 +1002,8 @@ pub(crate) enum Inst {
     },
     #[deku(id = "20")]
     FNeg { val: Operand },
+    #[deku(id = "21")]
+    DebugStr { msg: Operand },
     #[deku(id = "255")]
     Unimplemented {
         tyidx: TyIdx,
@@ -1095,6 +1097,7 @@ impl Inst {
             Self::FCmp { tyidx, .. } => Some(m.type_(*tyidx)),
             Self::Promote { tyidx, .. } => Some(m.type_(*tyidx)),
             Self::FNeg { val } => Some(val.type_(m)),
+            Self::DebugStr { .. } => None,
         }
     }
 
@@ -1383,6 +1386,7 @@ impl fmt::Display for DisplayableInst<'_> {
             Inst::FNeg { val } => {
                 write!(f, "fneg {}", val.display(self.m),)
             }
+            Inst::DebugStr { msg } => write!(f, "debug_str {}", msg.display(self.m)),
         }
     }
 }

ykrt/src/compile/jitc_yk/codegen/x64/mod.rs

@@ -652,6 +652,7 @@ impl<'a> Assemble<'a> {
                 jit_ir::Inst::FCmp(i) => self.cg_fcmp(iidx, i),
                 jit_ir::Inst::FPToSI(i) => self.cg_fptosi(iidx, i),
                 jit_ir::Inst::FNeg(i) => self.cg_fneg(iidx, i),
+                jit_ir::Inst::DebugStr(..) => (),
             }
 
             next = iter.next();

ykrt/src/compile/jitc_yk/jit_ir/mod.rs

@@ -200,6 +200,11 @@ pub(crate) struct Module {
     /// array will be absent.
     #[cfg(not(test))]
     globalvar_ptrs: &'static [*const ()],
+    /// The dynamically recorded debug strings, in the order that the corresponding
+    /// `yk_debug_str()` calls were encountered in the trace.
+    ///
+    /// Indexed by [DebugStrIdx].
+    debug_strs: Vec<String>,
 }
 
 impl Module {
@@ -309,6 +314,7 @@ impl Module {
             trace_header_end: Vec::new(),
             #[cfg(not(test))]
             globalvar_ptrs,
+            debug_strs: Vec::new(),
         })
     }
 
@@ -650,6 +656,10 @@ impl Module {
         self.trace_header_start.push(PackedOperand::new(&op));
     }
 
+    pub(crate) fn push_debug_str(&mut self, msg: String) -> Result<DebugStrIdx, CompilationError> {
+        DebugStrIdx::try_from(self.debug_strs.len()).inspect(|_| self.debug_strs.push(msg))
+    }
+
     /// Return the loop jump operands.
     pub(crate) fn trace_body_end(&self) -> &[PackedOperand] {
         &self.trace_body_end
@@ -912,6 +922,11 @@ index_16bit!(InstIdx);
 pub(crate) struct ParamIdx(u16);
 index_16bit!(ParamIdx);
 
+/// An index into [Module::debug_strs]
+#[derive(Debug, Copy, Clone, Eq, Hash, Ord, PartialEq, PartialOrd)]
+pub(crate) struct DebugStrIdx(u16);
+index_16bit!(DebugStrIdx);
+
 /// A function's type.
 #[derive(Clone, Debug, Eq, Hash, PartialEq)]
 pub(crate) struct FuncTy {
@@ -1450,6 +1465,7 @@ pub(crate) enum Inst {
     FPToSI(FPToSIInst),
     BitCast(BitCastInst),
     FNeg(FNegInst),
+    DebugStr(DebugStrInst),
 }
 
 impl Inst {
@@ -1511,6 +1527,7 @@ impl Inst {
             Self::FCmp(_) => m.int1_tyidx(),
             Self::FPToSI(i) => i.dest_tyidx(),
             Self::FNeg(i) => i.val(m).tyidx(m),
+            Self::DebugStr(..) => m.void_tyidx(),
         }
     }
 
@@ -1548,6 +1565,7 @@ impl Inst {
                 | Inst::TraceBodyEnd
                 | Inst::SidetraceEnd
                 | Inst::Param(_)
+                | Inst::DebugStr(..)
         )
     }
 
@@ -1663,6 +1681,7 @@ impl Inst {
             }
             Inst::FPToSI(FPToSIInst { val, .. }) => val.unpack(m).map_iidx(f),
             Inst::FNeg(FNegInst { val }) => val.unpack(m).map_iidx(f),
+            Inst::DebugStr(..) => (),
         }
     }
 
@@ -1851,6 +1870,7 @@ impl Inst {
                 val: mapper(m, val),
                 dest_tyidx: *dest_tyidx,
             }),
+            Inst::DebugStr(DebugStrInst { idx }) => Inst::DebugStr(DebugStrInst { idx: *idx }),
             e => todo!("{:?}", e),
         };
         Ok(inst)
@@ -2138,6 +2158,7 @@ impl fmt::Display for DisplayableInst<'_> {
             ),
             Inst::FPToSI(i) => write!(f, "fp_to_si {}", i.val(self.m).display(self.m)),
             Inst::FNeg(i) => write!(f, "fneg {}", i.val(self.m).display(self.m)),
+            Inst::DebugStr(i) => write!(f, "; debug_str: {}", i.msg(self.m)),
         }
     }
 }
@@ -2174,6 +2195,7 @@ inst!(FCmp, FCmpInst);
 inst!(FPToSI, FPToSIInst);
 inst!(BitCast, BitCastInst);
 inst!(FNeg, FNegInst);
+inst!(DebugStr, DebugStrInst);
 
 /// The operands for a [Instruction::BinOp]
 ///
@@ -2635,6 +2657,28 @@ impl FNegInst {
     }
 }
 
+/// The operands for a [Inst::DebugStr]
+///
+/// # Semantics
+///
+/// In terms of program semantics, this instruction is a no-op. It serves only to allow the
+/// insertion of debugging strings into the JIT IR when displayed.
+#[derive(Clone, Copy, Debug)]
+pub struct DebugStrInst {
+    idx: DebugStrIdx,
+}
+
+impl DebugStrInst {
+    pub(crate) fn new(idx: DebugStrIdx) -> Self {
+        Self { idx }
+    }
+
+    /// Returns the message.
+    pub(crate) fn msg<'a>(&self, m: &'a Module) -> &'a str {
+        &m.debug_strs[usize::from(self.idx)]
+    }
+}
+
 /// An instruction that adds a constant offset to a pointer.
 ///
 /// # Semantics

ykrt/src/compile/jitc_yk/mod.rs

@@ -132,6 +132,7 @@ impl<Register: Send + Sync + 'static> JITCYk<Register> {
         sti: Option<Arc<dyn SideTraceInfo>>,
         hl: Arc<Mutex<HotLocation>>,
         promotions: Box<[u8]>,
+        debug_strs: Vec<String>,
     ) -> Result<Arc<dyn CompiledTrace>, CompilationError> {
         // If either `unwrap` fails, there is no chance of the system working correctly.
         let aot_mod = &*AOT_MOD;
@@ -154,6 +155,7 @@ impl<Register: Send + Sync + 'static> JITCYk<Register> {
             aottrace_iter,
             sti,
             promotions,
+            debug_strs,
         )?;
 
         if should_log_ir(IRPhase::PreOpt) {
@@ -201,8 +203,9 @@ impl<Register: Send + Sync + 'static> Compiler for JITCYk<Register> {
         aottrace_iter: Box<dyn AOTTraceIterator>,
         hl: Arc<Mutex<HotLocation>>,
         promotions: Box<[u8]>,
+        debug_strs: Vec<String>,
     ) -> Result<Arc<dyn CompiledTrace>, CompilationError> {
-        self.compile(mt, aottrace_iter, None, hl, promotions)
+        self.compile(mt, aottrace_iter, None, hl, promotions, debug_strs)
     }
 
     fn sidetrace_compile(
@@ -212,8 +215,9 @@ impl<Register: Send + Sync + 'static> Compiler for JITCYk<Register> {
         sti: Arc<dyn SideTraceInfo>,
         hl: Arc<Mutex<HotLocation>>,
         promotions: Box<[u8]>,
+        debug_strs: Vec<String>,
     ) -> Result<Arc<dyn CompiledTrace>, CompilationError> {
-        self.compile(mt, aottrace_iter, Some(sti), hl, promotions)
+        self.compile(mt, aottrace_iter, Some(sti), hl, promotions, debug_strs)
     }
 }