From 617f1e9a17fafc4291af80430727a4d52b455015 Mon Sep 17 00:00:00 2001 From: Edd Barrett Date: Thu, 9 Jan 2025 14:58:06 +0000 Subject: [PATCH] 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 | 70 ++++++++++ tests/c/yk_debug_str_outline.c | 76 +++++++++++ ykcapi/src/lib.rs | 6 + ykcapi/yk.h | 8 ++ ykllvm | 2 +- ykrt/src/compile/jitc_yk/aot_ir.rs | 4 + ykrt/src/compile/jitc_yk/codegen/x64/mod.rs | 1 + ykrt/src/compile/jitc_yk/jit_ir/mod.rs | 44 ++++++ ykrt/src/compile/jitc_yk/mod.rs | 8 +- ykrt/src/compile/jitc_yk/trace_builder.rs | 140 +++++++++++--------- ykrt/src/compile/mod.rs | 2 + ykrt/src/lib.rs | 10 +- ykrt/src/mt.rs | 44 ++++-- 13 files changed, 341 insertions(+), 74 deletions(-) create mode 100644 tests/c/yk_debug_str.c create mode 100644 tests/c/yk_debug_str_outline.c diff --git a/tests/c/yk_debug_str.c b/tests/c/yk_debug_str.c new file mode 100644 index 000000000..a8d873790 --- /dev/null +++ b/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 +#include +#include +#include +#include +#include + +#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); +} diff --git a/tests/c/yk_debug_str_outline.c b/tests/c/yk_debug_str_outline.c new file mode 100644 index 000000000..3dc6ddfa7 --- /dev/null +++ b/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 +#include +#include +#include +#include +#include + +#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); +} diff --git a/ykcapi/src/lib.rs b/ykcapi/src/lib.rs index ba06dcc3f..16a4767b5 100644 --- a/ykcapi/src/lib.rs +++ b/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)] diff --git a/ykcapi/yk.h b/ykcapi/yk.h index fad7223ca..d83b5c466 100644 --- a/ykcapi/yk.h +++ b/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 diff --git a/ykllvm b/ykllvm index 73865729d..5c652113e 160000 --- a/ykllvm +++ b/ykllvm @@ -1 +1 @@ -Subproject commit 73865729d9cb56493e51a768b93007a787ad955f +Subproject commit 5c652113e2c1c2eb632b49226095253d2861651f diff --git a/ykrt/src/compile/jitc_yk/aot_ir.rs b/ykrt/src/compile/jitc_yk/aot_ir.rs index 70a360183..1cd02e46f 100644 --- a/ykrt/src/compile/jitc_yk/aot_ir.rs +++ b/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)), } } } diff --git a/ykrt/src/compile/jitc_yk/codegen/x64/mod.rs b/ykrt/src/compile/jitc_yk/codegen/x64/mod.rs index f711a2125..3b234535e 100644 --- a/ykrt/src/compile/jitc_yk/codegen/x64/mod.rs +++ b/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(); diff --git a/ykrt/src/compile/jitc_yk/jit_ir/mod.rs b/ykrt/src/compile/jitc_yk/jit_ir/mod.rs index 171c2a461..86936323e 100644 --- a/ykrt/src/compile/jitc_yk/jit_ir/mod.rs +++ b/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, } 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::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 diff --git a/ykrt/src/compile/jitc_yk/mod.rs b/ykrt/src/compile/jitc_yk/mod.rs index b00a3caf7..a1e98fc72 100644 --- a/ykrt/src/compile/jitc_yk/mod.rs +++ b/ykrt/src/compile/jitc_yk/mod.rs @@ -132,6 +132,7 @@ impl JITCYk { sti: Option>, hl: Arc>, promotions: Box<[u8]>, + debug_strs: Vec, ) -> Result, CompilationError> { // If either `unwrap` fails, there is no chance of the system working correctly. let aot_mod = &*AOT_MOD; @@ -154,6 +155,7 @@ impl JITCYk { aottrace_iter, sti, promotions, + debug_strs, )?; if should_log_ir(IRPhase::PreOpt) { @@ -201,8 +203,9 @@ impl Compiler for JITCYk { aottrace_iter: Box, hl: Arc>, promotions: Box<[u8]>, + debug_strs: Vec, ) -> Result, 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 Compiler for JITCYk { sti: Arc, hl: Arc>, promotions: Box<[u8]>, + debug_strs: Vec, ) -> Result, CompilationError> { - self.compile(mt, aottrace_iter, Some(sti), hl, promotions) + self.compile(mt, aottrace_iter, Some(sti), hl, promotions, debug_strs) } } diff --git a/ykrt/src/compile/jitc_yk/trace_builder.rs b/ykrt/src/compile/jitc_yk/trace_builder.rs index 24766b5d1..923ca50f7 100644 --- a/ykrt/src/compile/jitc_yk/trace_builder.rs +++ b/ykrt/src/compile/jitc_yk/trace_builder.rs @@ -40,6 +40,11 @@ pub(crate) struct TraceBuilder { /// The trace's current position in the promotions array. promote_idx: usize, phantom: PhantomData, + /// The dynamically recorded debug strings, in the order that the corresponding + /// `yk_debug_str()` calls were encountered in the trace. + debug_strs: Vec, + /// The trace's current position in the [Self::debug_strs] vector. + debug_str_idx: usize, } impl TraceBuilder { @@ -49,11 +54,13 @@ impl TraceBuilder { /// - `aot_mod`: The AOT IR module that the trace flows through. /// - `mtrace`: The mapped trace. /// - `promotions`: Values promoted to constants during runtime. + /// - `debug_archors`: Debug strs recorded during runtime. fn new( tracekind: TraceKind, ctr_id: u64, aot_mod: &'static Module, promotions: Box<[u8]>, + debug_strs: Vec, ) -> Result { Ok(Self { aot_mod, @@ -74,6 +81,8 @@ impl TraceBuilder { promotions, promote_idx: 0, phantom: PhantomData, + debug_strs, + debug_str_idx: 0, }) } @@ -140,23 +149,33 @@ impl TraceBuilder { Ok(()) } - /// Process promotions inside an otherwise outlined block. - fn process_promotions_only(&mut self, bid: &aot_ir::BBlockId) -> Result<(), CompilationError> { + /// Process (skip) promotions and debug strings inside an otherwise outlined block. + fn process_promotions_and_debug_strs_only( + &mut self, + bid: &aot_ir::BBlockId, + ) -> Result<(), CompilationError> { let blk = self.aot_mod.bblock(bid); for inst in blk.insts.iter() { - if let aot_ir::Inst::Promote { - val: aot_ir::Operand::LocalVariable(_), - tyidx, - .. - } = inst - { - let width_bits = match self.aot_mod.type_(*tyidx) { - aot_ir::Ty::Integer(x) => x.bitw(), - _ => unreachable!(), - }; - let width_bytes = usize::try_from(width_bits.div_ceil(8)).unwrap(); - self.promote_idx += width_bytes; + match inst { + aot_ir::Inst::Promote { + val: aot_ir::Operand::LocalVariable(_), + tyidx, + .. + } => { + // Consume the correct number of bytes from the promoted values array. + let width_bits = match self.aot_mod.type_(*tyidx) { + aot_ir::Ty::Integer(x) => x.bitw(), + _ => unreachable!(), + }; + let width_bytes = usize::try_from(width_bits.div_ceil(8)).unwrap(); + self.promote_idx += width_bytes; + } + aot_ir::Inst::DebugStr { .. } => { + // Skip this debug string. + self.debug_str_idx += 1; + } + _ => (), } } Ok(()) @@ -288,6 +307,10 @@ impl TraceBuilder { self.handle_promote(bid, iidx, val, safepoint, tyidx, nextinst) } aot_ir::Inst::FNeg { val } => self.handle_fneg(bid, iidx, val), + aot_ir::Inst::DebugStr { .. } => { + let nextinst = blk.insts.last().unwrap(); + self.handle_debug_str(bid, iidx, nextinst) + } _ => todo!("{:?}", inst), }?; } @@ -673,24 +696,7 @@ impl TraceBuilder { // "yk_outline". For now we have to be conservative here and outline all indirect calls. // One solution would be to stop including the AOT IR for functions annotated with // "yk_outline". Any mappable, indirect call is then guaranteed to be inline safe. - - match nextinst { - aot_ir::Inst::Br { succ } => { - // We can only stop outlining when we see the succesor block and we are not in - // the middle of recursion. - let succbid = BBlockId::new(bid.funcidx(), *succ); - self.outline_target_blk = Some(succbid); - self.recursion_count = 0; - } - aot_ir::Inst::CondBr { .. } => { - // Currently, the successor of a call is always an unconditional branch due to - // the block spitting pass. However, there's a FIXME in that pass which could - // lead to conditional branches showing up here. Leave a todo here so we know - // when this happens. - todo!() - } - _ => panic!(), - } + self.outline_until_after_call(bid, nextinst); let jit_callop = self.handle_operand(callop)?; let jit_tyidx = self.handle_type(self.aot_mod.type_(*ftyidx))?; @@ -770,23 +776,7 @@ impl TraceBuilder { } else { // This call can't be inlined. It is either unmappable (a declaration or an indirect // call) or the compiler annotated it with `yk_outline`. - match nextinst { - aot_ir::Inst::Br { succ } => { - // We can only stop outlining when we see the succesor block and we are not in - // the middle of recursion. - let succbid = BBlockId::new(bid.funcidx(), *succ); - self.outline_target_blk = Some(succbid); - self.recursion_count = 0; - } - aot_ir::Inst::CondBr { .. } => { - // Currently, the successor of a call is always an unconditional branch due to - // the block spitting pass. However, there's a FIXME in that pass which could - // lead to conditional branches showing up here. Leave a todo here so we know - // when this happens. - todo!() - } - _ => panic!(), - } + self.outline_until_after_call(bid, nextinst); let jit_func_decl_idx = self.handle_func(*callee)?; let inst = jit_ir::DirectCallInst::new(&mut self.jit_mod, jit_func_decl_idx, jit_args)?.into(); @@ -1050,16 +1040,14 @@ impl TraceBuilder { self.copy_inst(inst, bid, aot_inst_idx) } - fn handle_promote( - &mut self, - bid: &aot_ir::BBlockId, - aot_inst_idx: usize, - val: &aot_ir::Operand, - safepoint: &'static aot_ir::DeoptSafepoint, - tyidx: &aot_ir::TyIdx, - nextinst: &'static aot_ir::Inst, - ) -> Result<(), CompilationError> { - match nextinst { + /// Turn outlining until the specified call has been consumed from the trace. + /// + /// `terminst` is the terminating instruction immediately after the call, guaranteed to be + /// present due to ykllvm's block splitting pass. + /// + /// `bid` is the [BBlockId] containing the call. + fn outline_until_after_call(&mut self, bid: &BBlockId, terminst: &'static aot_ir::Inst) { + match terminst { aot_ir::Inst::Br { succ } => { // We can only stop outlining when we see the succesor block and we are not in // the middle of recursion. @@ -1076,6 +1064,18 @@ impl TraceBuilder { } _ => panic!(), } + } + + fn handle_promote( + &mut self, + bid: &aot_ir::BBlockId, + aot_inst_idx: usize, + val: &aot_ir::Operand, + safepoint: &'static aot_ir::DeoptSafepoint, + tyidx: &aot_ir::TyIdx, + nextinst: &'static aot_ir::Inst, + ) -> Result<(), CompilationError> { + self.outline_until_after_call(&bid, nextinst); match self.handle_operand(val)? { jit_ir::Operand::Var(ref_iidx) => { self.jit_mod.push(jit_ir::Inst::Copy(ref_iidx))?; @@ -1134,6 +1134,21 @@ impl TraceBuilder { self.copy_inst(inst, bid, aot_inst_idx) } + fn handle_debug_str( + &mut self, + bid: &aot_ir::BBlockId, + aot_inst_idx: usize, + nextinst: &'static aot_ir::Inst, + ) -> Result<(), CompilationError> { + self.outline_until_after_call(&bid, nextinst); + let msg = self.debug_strs[self.debug_str_idx].to_owned(); + let inst = + jit_ir::Inst::DebugStr(jit_ir::DebugStrInst::new(self.jit_mod.push_debug_str(msg)?)); + self.copy_inst(inst, bid, aot_inst_idx)?; + self.debug_str_idx += 1; + Ok(()) + } + /// Entry point for building an IR trace. /// /// Consumes the trace builder, returning a JIT module. @@ -1333,7 +1348,7 @@ impl TraceBuilder { continue; } } - self.process_promotions_only(&bid)?; + self.process_promotions_and_debug_strs_only(&bid)?; prev_bid = Some(bid); continue; } @@ -1388,6 +1403,7 @@ impl TraceBuilder { } debug_assert_eq!(self.promote_idx, self.promotions.len()); + debug_assert_eq!(self.debug_str_idx, self.debug_strs.len()); let blk = self.aot_mod.bblock(self.cp_block.as_ref().unwrap()); let cpcall = blk.insts.iter().rev().nth(1).unwrap(); debug_assert!(cpcall.is_control_point(self.aot_mod)); @@ -1435,11 +1451,13 @@ pub(super) fn build( ta_iter: Box, sti: Option>>, promotions: Box<[u8]>, + debug_strs: Vec, ) -> Result { let tracekind = if let Some(x) = sti { TraceKind::Sidetrace(x) } else { TraceKind::HeaderOnly }; - TraceBuilder::::new(tracekind, ctr_id, aot_mod, promotions)?.build(ta_iter) + TraceBuilder::::new(tracekind, ctr_id, aot_mod, promotions, debug_strs)? + .build(ta_iter) } diff --git a/ykrt/src/compile/mod.rs b/ykrt/src/compile/mod.rs index 15d049a5b..91dd4f25d 100644 --- a/ykrt/src/compile/mod.rs +++ b/ykrt/src/compile/mod.rs @@ -49,6 +49,7 @@ pub(crate) trait Compiler: Send + Sync { aottrace_iter: Box, hl: Arc>, promotions: Box<[u8]>, + debug_strs: Vec, ) -> Result, CompilationError>; /// Compile a mapped root trace into machine code. @@ -59,6 +60,7 @@ pub(crate) trait Compiler: Send + Sync { sti: Arc, hl: Arc>, promotions: Box<[u8]>, + debug_strs: Vec, ) -> Result, CompilationError>; } diff --git a/ykrt/src/lib.rs b/ykrt/src/lib.rs index 8d97fbb4f..418559c86 100644 --- a/ykrt/src/lib.rs +++ b/ykrt/src/lib.rs @@ -20,4 +20,12 @@ pub(crate) mod thread_intercept; pub mod trace; pub use self::location::Location; -pub use self::mt::{HotThreshold, MT}; +pub use self::mt::{HotThreshold, MTThread, MT}; +use std::ffi::{c_char, CStr}; + +#[no_mangle] +pub extern "C" fn yk_debug_str(msg: *const c_char) { + MTThread::with(|mtt| { + mtt.insert_debug_str(unsafe { CStr::from_ptr(msg).to_str().unwrap().to_owned() }); + }); +} diff --git a/ykrt/src/mt.rs b/ykrt/src/mt.rs index 19eaad461..a32c2f03f 100644 --- a/ykrt/src/mt.rs +++ b/ykrt/src/mt.rs @@ -265,7 +265,7 @@ impl MT { /// job is related to. fn queue_root_compile_job( self: &Arc, - trace_iter: (Box, Box<[u8]>), + trace_iter: (Box, Box<[u8]>, Vec), hl_arc: Arc>, ) { self.stats.trace_recorded_ok(); @@ -281,6 +281,7 @@ impl MT { trace_iter.0, Arc::clone(&hl_arc), trace_iter.1, + trace_iter.2, ) { Ok(ct) => { let mut hl = hl_arc.lock(); @@ -336,7 +337,7 @@ impl MT { /// * `guardid` is the ID of the guard in `parent_ctr` which failed. fn queue_sidetrace_compile_job( self: &Arc, - trace_iter: (Box, Box<[u8]>), + trace_iter: (Box, Box<[u8]>, Vec), hl_arc: Arc>, root_ctr: Arc, parent_ctr: Arc, @@ -360,6 +361,7 @@ impl MT { sti, Arc::clone(&hl_arc), trace_iter.1, + trace_iter.2, ) { Ok(ct) => { parent_ctr.guard(guardid).set_ctr(ct); @@ -450,6 +452,7 @@ impl MT { hl, thread_tracer: tt, promotions: Vec::new(), + debug_strs: Vec::new(), frameaddr, }; }), @@ -480,17 +483,18 @@ impl MT { TransitionControlPoint::StopTracing => { // Assuming no bugs elsewhere, the `unwrap`s cannot fail, because `StartTracing` // will have put a `Some` in the `Rc`. - let (hl, thread_tracer, promotions) = + let (hl, thread_tracer, promotions, debug_strs) = MTThread::with( |mtt| match mtt.tstate.replace(MTThreadState::Interpreting) { MTThreadState::Tracing { hl, thread_tracer, promotions, + debug_strs, frameaddr: tracing_frameaddr, } => { assert_eq!(frameaddr, tracing_frameaddr); - (hl, thread_tracer, promotions) + (hl, thread_tracer, promotions, debug_strs) } _ => unreachable!(), }, @@ -499,7 +503,10 @@ impl MT { Ok(utrace) => { self.stats.timing_state(TimingState::None); self.log.log(Verbosity::JITEvent, "stop-tracing"); - self.queue_root_compile_job((utrace, promotions.into_boxed_slice()), hl); + self.queue_root_compile_job( + (utrace, promotions.into_boxed_slice(), debug_strs), + hl, + ); } Err(e) => { self.stats.timing_state(TimingState::None); @@ -516,17 +523,18 @@ impl MT { } => { // Assuming no bugs elsewhere, the `unwrap`s cannot fail, because // `StartSideTracing` will have put a `Some` in the `Rc`. - let (hl, thread_tracer, promotions) = + let (hl, thread_tracer, promotions, debug_strs) = MTThread::with( |mtt| match mtt.tstate.replace(MTThreadState::Interpreting) { MTThreadState::Tracing { hl, thread_tracer, promotions, + debug_strs, frameaddr: tracing_frameaddr, } => { assert_eq!(frameaddr, tracing_frameaddr); - (hl, thread_tracer, promotions) + (hl, thread_tracer, promotions, debug_strs) } _ => unreachable!(), }, @@ -537,7 +545,7 @@ impl MT { self.stats.timing_state(TimingState::None); self.log.log(Verbosity::JITEvent, "stop-tracing"); self.queue_sidetrace_compile_job( - (utrace, promotions.into_boxed_slice()), + (utrace, promotions.into_boxed_slice(), debug_strs), hl, root_ctr, parent_ctr, @@ -869,6 +877,7 @@ impl MT { hl, thread_tracer: tt, promotions: Vec::new(), + debug_strs: Vec::new(), frameaddr, }; }), @@ -932,6 +941,8 @@ enum MTThreadState { thread_tracer: Box, /// Records the content of data recorded via `yk_promote`. promotions: Vec, + /// Records the content of data recorded via `yk_debug_str`. + debug_strs: Vec, /// The `frameaddr` when tracing started. This allows us to tell if we're finishing tracing /// at the same point that we started. frameaddr: *mut c_void, @@ -958,7 +969,7 @@ enum MTThreadState { /// Meta-tracer per-thread state. Note that this struct is neither `Send` nor `Sync`: it can only /// be accessed from within a single thread. -pub(crate) struct MTThread { +pub struct MTThread { /// Where in the "interpreting/tracing/executing" is this thread? tstate: RefCell, // Raw pointers are neither send nor sync. @@ -1081,6 +1092,17 @@ impl MTThread { } true } + + /// Record a debug string. + pub fn insert_debug_str(&self, msg: String) -> bool { + if let MTThreadState::Tracing { + ref mut debug_strs, .. + } = *self.tstate.borrow_mut() + { + debug_strs.push(msg); + } + true + } } /// What action should a caller of [MT::transition_control_point] take? @@ -1153,6 +1175,7 @@ mod tests { hl, thread_tracer: Box::new(DummyTraceRecorder), promotions: Vec::new(), + debug_strs: Vec::new(), frameaddr: ptr::null_mut(), }; }); @@ -1179,6 +1202,7 @@ mod tests { hl, thread_tracer: Box::new(DummyTraceRecorder), promotions: Vec::new(), + debug_strs: Vec::new(), frameaddr: ptr::null_mut(), }; }); @@ -1301,6 +1325,7 @@ mod tests { hl, thread_tracer: Box::new(DummyTraceRecorder), promotions: Vec::new(), + debug_strs: Vec::new(), frameaddr: ptr::null_mut(), }; }); @@ -1495,6 +1520,7 @@ mod tests { hl, thread_tracer: Box::new(DummyTraceRecorder), promotions: Vec::new(), + debug_strs: Vec::new(), frameaddr: ptr::null_mut(), }; });