T0b1/wasmtime
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Provide filename/line number information in Trap (#2452)

Browse Source 
* Provide filename/line number information in `Trap`

This commit extends the `Trap` type and `Store` to retain DWARF debug
information found in a wasm file unconditionally, if it's present. This
then enables us to print filenames and line numbers which point back to
actual source code when a trap backtrace is printed. Additionally the
`FrameInfo` type has been souped up to return filename/line number
information as well.

The implementation here is pretty simplistic currently. The meat of all
the work happens in `gimli` and `addr2line`, and otherwise wasmtime is
just schlepping around bytes of dwarf debuginfo here and there!

The general goal here is to assist with debugging when using wasmtime
because filenames and line numbers are generally orders of magnitude
better even when you already have a stack trace. Another nicety here is
that backtraces will display inlined frames (learned through debug
information), improving the experience in release mode as well.

An example of this is that with this file:

```rust
fn main() {
    panic!("hello");
}
```

we get this stack trace:

```
$ rustc foo.rs --target wasm32-wasi -g
$ cargo run foo.wasm
    Finished dev [unoptimized + debuginfo] target(s) in 0.16s
     Running `target/debug/wasmtime foo.wasm`
thread 'main' panicked at 'hello', foo.rs:2:5
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
Error: failed to run main module `foo.wasm`

Caused by:
    0: failed to invoke command default
    1: wasm trap: unreachable
       wasm backtrace:
           0: 0x6c1c - panic_abort::__rust_start_panic::abort::h2d60298621b1ccbf
                           at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/panic_abort/src/lib.rs:77:17
                     - __rust_start_panic
                           at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/panic_abort/src/lib.rs:32:5
           1: 0x68c7 - rust_panic
                           at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:626:9
           2: 0x65a1 - std::panicking::rust_panic_with_hook::h2345fb0909b53e12
                           at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:596:5
           3: 0x1436 - std::panicking::begin_panic::{{closure}}::h106f151a6db8c8fb
                           at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:506:9
           4:  0xda8 - std::sys_common::backtrace::__rust_end_short_backtrace::he55aa13f22782798
                           at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys_common/backtrace.rs:153:18
           5: 0x1324 - std::panicking::begin_panic::h1727e7d1d719c76f
                           at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:505:12
           6:  0xfde - foo::main::h2db1313a64510850
                           at /Users/acrichton/code/wasmtime/foo.rs:2:5
           7: 0x11d5 - core::ops::function::FnOnce::call_once::h20ee1cc04aeff1fc
                           at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/core/src/ops/function.rs:227:5
           8:  0xddf - std::sys_common::backtrace::__rust_begin_short_backtrace::h054493e41e27e69c
                           at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/sys_common/backtrace.rs:137:18
           9: 0x1d5a - std::rt::lang_start::{{closure}}::hd83784448d3fcb42
                           at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/rt.rs:66:18
          10: 0x69d8 - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::h564d3dad35014917
                           at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/core/src/ops/function.rs:259:13
                     - std::panicking::try::do_call::hdca4832ace5a8603
                           at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:381:40
                     - std::panicking::try::ha8624a1a6854b456
                           at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panicking.rs:345:19
                     - std::panic::catch_unwind::h71421f57cf2bc688
                           at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/panic.rs:382:14
                     - std::rt::lang_start_internal::h260050c92cd470af
                           at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/rt.rs:51:25
          11: 0x1d0c - std::rt::lang_start::h0b4bcf3c5e498224
                           at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4/library/std/src/rt.rs:65:5
          12:  0xffc - <unknown>!__original_main
          13:  0x393 - __muloti4
                           at /cargo/registry/src/github.com-1ecc6299db9ec823/compiler_builtins-0.1.35/src/macros.rs:269
```

This is relatively noisy by default but there's filenames and line
numbers! Additionally frame 10 can be seen to have lots of frames
inlined into it. All information is always available to the embedder but
we could try to handle the `__rust_begin_short_backtrace` and
`__rust_end_short_backtrace` markers to trim the backtrace by default as
well.

The only gotcha here is that it looks like `__muloti4` is out of place.
That's because the libc that Rust ships with doesn't have dwarf
information, although I'm not sure why we land in that function for
symbolizing it...

* Add a configuration switch for debuginfo

* Control debuginfo by default with `WASM_BACKTRACE_DETAILS`

* Try cpp_demangle on demangling as well

* Rename to WASMTIME_BACKTRACE_DETAILS
This commit is contained in:
Alex Crichton
2020-12-01 16:56:23 -06:00
committed by GitHub
parent 88a8a8993a
commit 51c1d4bbd6
16 changed files with 568 additions and 62 deletions
Download Patch File Download Diff File Expand all files Collapse all files

1
crates/wasmtime/Cargo.toml
View File

@@ -23,6 +23,7 @@ libc = "0.2"
cfg-if = "1.0"
backtrace = "0.3.42"
rustc-demangle = "0.1.16"
cpp_demangle = "0.3.2"
log = "0.4.8"
wat = { version = "1.0.18", optional = true }
smallvec = "1.4.0"

55
crates/wasmtime/src/config.rs
View File

@@ -32,6 +32,7 @@ pub struct Config {
pub(crate) memory_creator: Option<MemoryCreatorProxy>,
pub(crate) max_wasm_stack: usize,
pub(crate) features: WasmFeatures,
pub(crate) wasm_backtrace_details_env_used: bool,
}
impl Config {
@@ -61,7 +62,7 @@ impl Config {
.set("enable_probestack", "false")
.expect("should be valid flag");
Config {
let mut ret = Config {
tunables: Tunables::default(),
flags,
isa_flags: native::builder(),
@@ -71,13 +72,16 @@ impl Config {
profiler: Arc::new(NullProfilerAgent),
memory_creator: None,
max_wasm_stack: 1 << 20,
wasm_backtrace_details_env_used: false,
features: WasmFeatures {
reference_types: true,
bulk_memory: true,
multi_value: true,
..WasmFeatures::default()
},
}
};
ret.wasm_backtrace_details(WasmBacktraceDetails::Environment);
return ret;
}
/// Configures whether DWARF debug information will be emitted during
@@ -85,7 +89,33 @@ impl Config {
///
/// By default this option is `false`.
pub fn debug_info(&mut self, enable: bool) -> &mut Self {
self.tunables.debug_info = enable;
self.tunables.generate_native_debuginfo = enable;
self
}
/// Configures backtraces in `Trap` will parse debuginfo in the wasm file to
/// have filename/line number information.
///
/// When enabled this will causes modules to retain debugging information
/// found in wasm binaries. This debug information will be used when a trap
/// happens to symbolicate each stack frame and attempt to print a
/// filename/line number for each wasm frame in the stack trace.
///
/// By default this option is `WasmBacktraceDetails::Environment`, meaning
/// that wasm will read `WASMTIME_BACKTRACE_DETAILS` to indicate whether details
/// should be parsed.
pub fn wasm_backtrace_details(&mut self, enable: WasmBacktraceDetails) -> &mut Self {
self.wasm_backtrace_details_env_used = false;
self.tunables.parse_wasm_debuginfo = match enable {
WasmBacktraceDetails::Enable => true,
WasmBacktraceDetails::Disable => false,
WasmBacktraceDetails::Environment => {
self.wasm_backtrace_details_env_used = true;
std::env::var("WASMTIME_BACKTRACE_DETAILS")
.map(|s| s == "1")
.unwrap_or(false)
}
};
self
}
@@ -640,7 +670,8 @@ impl Default for Config {
impl fmt::Debug for Config {
fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
f.debug_struct("Config")
.field("debug_info", &self.tunables.debug_info)
.field("debug_info", &self.tunables.generate_native_debuginfo)
.field("parse_wasm_debuginfo", &self.tunables.parse_wasm_debuginfo)
.field("strategy", &self.strategy)
.field("wasm_threads", &self.features.threads)
.field("wasm_reference_types", &self.features.reference_types)
@@ -712,3 +743,19 @@ pub enum ProfilingStrategy {
/// Collect profiling info using the "ittapi", used with `VTune` on Linux.
VTune,
}
/// Select how wasm backtrace detailed information is handled.
#[derive(Debug, Clone, Copy)]
pub enum WasmBacktraceDetails {
/// Support is unconditionally enabled and wasmtime will parse and read
/// debug information.
Enable,
/// Support is disabled, and wasmtime will not parse debug information for
/// backtrace details.
Disable,
/// Support for backtrace details is conditional on the
/// `WASMTIME_BACKTRACE_DETAILS` environment variable.
Environment,
}

127
crates/wasmtime/src/frame_info.rs
View File

@@ -5,7 +5,7 @@ use wasmtime_environ::entity::EntityRef;
use wasmtime_environ::ir;
use wasmtime_environ::wasm::FuncIndex;
use wasmtime_environ::{FunctionAddressMap, Module, TrapInformation};
use wasmtime_jit::CompiledModule;
use wasmtime_jit::{CompiledModule, SymbolizeContext};
#[derive(Default)]
pub struct StoreFrameInfo {
@@ -25,6 +25,8 @@ struct ModuleFrameInfo {
start: usize,
functions: BTreeMap<usize, FunctionInfo>,
module: Arc<Module>,
symbolize: Option<SymbolizeContext>,
has_unparsed_debuginfo: bool,
}
struct FunctionInfo {
@@ -38,8 +40,10 @@ impl StoreFrameInfo {
/// Fetches frame information about a program counter in a backtrace.
///
/// Returns an object if this `pc` is known to some previously registered
/// module, or returns `None` if no information can be found.
pub fn lookup_frame_info(&self, pc: usize) -> Option<FrameInfo> {
/// module, or returns `None` if no information can be found. The boolean
/// returned indicates whether the original module has unparsed debug
/// information due to the compiler's configuration.
pub fn lookup_frame_info(&self, pc: usize) -> Option<(FrameInfo, bool)> {
let (module, func) = self.func(pc)?;
// Use our relative position from the start of the function to find the
@@ -72,13 +76,49 @@ impl StoreFrameInfo {
Some(pos) => func.instr_map.instructions[pos].srcloc,
None => func.instr_map.start_srcloc,
};
Some(FrameInfo {
module_name: module.module.name.clone(),
func_index: func.index.index() as u32,
func_name: module.module.func_names.get(&func.index).cloned(),
instr,
func_start: func.instr_map.start_srcloc,
})
// Use our wasm-relative pc to symbolize this frame. If there's a
// symbolication context (dwarf debug info) available then we can try to
// look this up there.
//
// Note that dwarf pcs are code-section-relative, hence the subtraction
// from the location of `instr`. Also note that all errors are ignored
// here for now since technically wasm modules can always have any
// custom section contents.
let mut symbols = Vec::new();
if let Some(s) = &module.symbolize {
let to_lookup = (instr.bits() as u64) - s.code_section_offset();
if let Ok(mut frames) = s.addr2line().find_frames(to_lookup) {
while let Ok(Some(frame)) = frames.next() {
symbols.push(FrameSymbol {
name: frame
.function
.as_ref()
.and_then(|l| l.raw_name().ok())
.map(|s| s.to_string()),
file: frame
.location
.as_ref()
.and_then(|l| l.file)
.map(|s| s.to_string()),
line: frame.location.as_ref().and_then(|l| l.line),
column: frame.location.as_ref().and_then(|l| l.column),
});
}
}
}
Some((
FrameInfo {
module_name: module.module.name.clone(),
func_index: func.index.index() as u32,
func_name: module.module.func_names.get(&func.index).cloned(),
instr,
func_start: func.instr_map.start_srcloc,
symbols,
},
module.has_unparsed_debuginfo,
))
}
/// Returns whether the `pc` specified is contaained within some module's
@@ -160,6 +200,8 @@ impl StoreFrameInfo {
start: min,
functions,
module: module.module().clone(),
symbolize: module.symbolize_context().ok().and_then(|c| c),
has_unparsed_debuginfo: module.has_unparsed_debuginfo(),
},
);
assert!(prev.is_none());
@@ -180,6 +222,20 @@ pub struct FrameInfo {
func_name: Option<String>,
func_start: ir::SourceLoc,
instr: ir::SourceLoc,
symbols: Vec<FrameSymbol>,
}
/// Debug information for a symbol that is attached to a [`FrameInfo`].
///
/// When DWARF debug information is present in a wasm file then this structure
/// can be found on a [`FrameInfo`] and can be used to learn about filenames,
/// line numbers, etc, which are the origin of a function in a stack trace.
#[derive(Debug)]
pub struct FrameSymbol {
name: Option<String>,
file: Option<String>,
line: Option<u32>,
column: Option<u32>,
}
impl FrameInfo {
@@ -240,6 +296,55 @@ impl FrameInfo {
pub fn func_offset(&self) -> usize {
(self.instr.bits() - self.func_start.bits()) as usize
}
/// Returns the debug symbols found, if any, for this function frame.
///
/// When a wasm program is compiled with DWARF debug information then this
/// function may be populated to return symbols which contain extra debug
/// information about a frame including the filename and line number. If no
/// debug information was found or if it was malformed then this will return
/// an empty array.
pub fn symbols(&self) -> &[FrameSymbol] {
&self.symbols
}
}
impl FrameSymbol {
/// Returns the function name associated with this symbol.
///
/// Note that this may not be present with malformed debug information, or
/// the debug information may not include it. Also note that the symbol is
/// frequently mangled, so you might need to run some form of demangling
/// over it.
pub fn name(&self) -> Option<&str> {
self.name.as_deref()
}
/// Returns the source code filename this symbol was defined in.
///
/// Note that this may not be present with malformed debug information, or
/// the debug information may not include it.
pub fn file(&self) -> Option<&str> {
self.file.as_deref()
}
/// Returns the 1-indexed source code line number this symbol was defined
/// on.
///
/// Note that this may not be present with malformed debug information, or
/// the debug information may not include it.
pub fn line(&self) -> Option<u32> {
self.line
}
/// Returns the 1-indexed source code column number this symbol was defined
/// on.
///
/// Note that this may not be present with malformed debug information, or
/// the debug information may not include it.
pub fn column(&self) -> Option<u32> {
self.column
}
}
#[test]
@@ -270,7 +375,7 @@ fn test_frame_info() -> Result<(), anyhow::Error> {
(ptr as usize, ptr as usize + len)
};
for pc in start..end {
let frame = info.lookup_frame_info(pc).unwrap();
let (frame, _) = info.lookup_frame_info(pc).unwrap();
assert!(frame.func_index() == i.as_u32());
}
}

2
crates/wasmtime/src/lib.rs
View File

@@ -253,7 +253,7 @@ mod values;
pub use crate::config::*;
pub use crate::engine::*;
pub use crate::externals::*;
pub use crate::frame_info::FrameInfo;
pub use crate::frame_info::{FrameInfo, FrameSymbol};
pub use crate::func::*;
pub use crate::instance::Instance;
pub use crate::linker::*;

71
crates/wasmtime/src/trap.rs
View File

@@ -122,6 +122,7 @@ struct TrapInner {
reason: TrapReason,
wasm_trace: Vec<FrameInfo>,
native_trace: Backtrace,
hint_wasm_backtrace_details_env: bool,
}
fn _assert_trap_is_sync_and_send(t: &Trap) -> (&dyn Sync, &dyn Send) {
@@ -214,6 +215,7 @@ impl Trap {
native_trace: Backtrace,
) -> Self {
let mut wasm_trace = Vec::new();
let mut hint_wasm_backtrace_details_env = false;
wasmtime_runtime::with_last_info(|last| {
// If the `store` passed in is `None` then we look at the `last`
// store configured to call wasm, and if that's a `Store` we use
@@ -236,9 +238,22 @@ impl Trap {
// want to lookup information for the previous instruction
// (the call instruction) so we subtract one as the lookup.
let pc_to_lookup = if Some(pc) == trap_pc { pc } else { pc - 1 };
if let Some(info) = store.frame_info().borrow().lookup_frame_info(pc_to_lookup)
if let Some((info, has_unparsed_debuginfo)) =
store.frame_info().borrow().lookup_frame_info(pc_to_lookup)
{
wasm_trace.push(info);
// If this frame has unparsed debug information and the
// store's configuration indicates that we were
// respecting the environment variable of whether to
// do this then we will print out a helpful note in
// `Display` to indicate that more detailed information
// in a trap may be available.
if has_unparsed_debuginfo
&& store.engine().config().wasm_backtrace_details_env_used
{
hint_wasm_backtrace_details_env = true;
}
}
}
}
@@ -248,6 +263,7 @@ impl Trap {
reason,
wasm_trace,
native_trace,
hint_wasm_backtrace_details_env,
}),
}
}
@@ -297,15 +313,52 @@ impl fmt::Display for Trap {
writeln!(f, "\nwasm backtrace:")?;
for (i, frame) in self.trace().iter().enumerate() {
let name = frame.module_name().unwrap_or("<unknown>");
write!(f, " {}: {:#6x} - {}!", i, frame.module_offset(), name)?;
match frame.func_name() {
Some(name) => match rustc_demangle::try_demangle(name) {
Ok(name) => write!(f, "{}", name)?,
Err(_) => write!(f, "{}", name)?,
},
None => write!(f, "<wasm function {}>", frame.func_index())?,
write!(f, " {:>3}: {:#6x} - ", i, frame.module_offset())?;
let demangle =
|f: &mut fmt::Formatter<'_>, name: &str| match rustc_demangle::try_demangle(name) {
Ok(name) => write!(f, "{}", name),
Err(_) => match cpp_demangle::Symbol::new(name) {
Ok(name) => write!(f, "{}", name),
Err(_) => write!(f, "{}", name),
},
};
let write_raw_func_name = |f: &mut fmt::Formatter<'_>| match frame.func_name() {
Some(name) => demangle(f, name),
None => write!(f, "<wasm function {}>", frame.func_index()),
};
if frame.symbols().is_empty() {
write!(f, "{}!", name)?;
write_raw_func_name(f)?;
writeln!(f, "")?;
} else {
for (i, symbol) in frame.symbols().iter().enumerate() {
if i > 0 {
write!(f, " - ")?;
} else {
// ...
}
match symbol.name() {
Some(name) => demangle(f, name)?,
None if i == 0 => write_raw_func_name(f)?,
None => write!(f, "<inlined function>")?,
}
writeln!(f, "")?;
if let Some(file) = symbol.file() {
write!(f, " at {}", file)?;
if let Some(line) = symbol.line() {
write!(f, ":{}", line)?;
if let Some(col) = symbol.column() {
write!(f, ":{}", col)?;
}
}
}
writeln!(f, "")?;
}
}
writeln!(f, "")?;
}
if self.inner.hint_wasm_backtrace_details_env {
writeln!(f, "note: run with `WASMTIME_BACKTRACE_DETAILS=1` environment variable to display more information")?;
}
Ok(())
}