Merge pull request #1540 from vext01/debug-anchors

Implement debug strings

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)
     }
 }