Support for logs and spans in execution trace

[anorth]

It is currently very difficult to analyse the gas consumption of most regions of actor code because the execution trace does not include items delimiting Rust calls, scopes etc. It does delimit sends between different actors, but nothing more fine-grained.

This issue is for discussion of how we might add better instrumentation support here, especially for:

• logs: arbitrary instrumentation messages posted by an actor
• spans: defined begin/end boundaries around regions of code

Spans can be implemented in terms of logs by encoding structure span information into log messages, but we may wish to support some notion of a span more directly, both for efficiency and ease of analysis.

[anorth]

One annoyance I discovered is that the log syscall charges gas, even though the implementation does nothing when debugging is not enabled. It does still invoke the overhead of making the syscall into the VM before determining this. It's unfortunate to discourage the committing of log/trace information in this way.

Perhaps we could find a way to propagate the is-debugging-enabled property of the VM into WASM-land just once for each call, so that we can short-circuit actor side (without invoking a syscall to determine if debugging is enabled each time).

[Stebalien]

ref-fvm/sdk/src/debug.rs

Lines 60 to 62 in a4ae7e8

	if enabled() {
	log(format!("[{}] {}", record.level(), record.args()));
	}

[anorth]

@Stebalien I'm not quite sure of the context there, but I'm looking for logs that are part of execution traces, so they can be programmatically analysed (e.g. in a benchmark).

[Stebalien]

Sorry, I was responding to:

One annoyance I discovered is that the log syscall charges gas, even though the implementation does nothing when debugging is not enabled. It does still invoke the overhead of making the syscall into the VM before determining this. It's unfortunate to discourage the committing of log/trace information in this way.

The SDK currently does check if logging is enabled before making a syscall, if you use the logging framework (https://crates.io/crates/log). That way we can skip formatting as well.

On the other hand, there's no reason we can't check within the log function as well.

[Stebalien]

I.e., if you call log::trace!("some message: {}", thing), we'll skip the syscall, message formatting, etc. if logging is disabled.

[anorth]

Ah, so an insight I was missing for filecoin-project/builtin-actors#999 is that (you expect that) logging via the standard Rust logging mechanisms should invoke the syscall. I agree that this will more or less resolve the issues about charging gas for debug logging.

However, I cannot get this to work. My manual syscall works fine and produces a Log event in the execution trace, but nothing I've tried will get a debug!("hi") from an actor to also do the same.

Note that I'm on release/v2 because I'm attempting to instrument the built-in actors. And I am working on a patched local version of ref-fvm because I'm adding this instrumentation.

What did you mean by

Well, now you can just call fvm_sdk::initialize() to setup a panic handler and logging.

What's now? Was this only introduced recently (is it not in v2, or broken there?). Did this commit change things?

In one of my many runs attempting this, I did see:

warning: patch for fvm_sdk uses the features mechanism. default-features and features will not take effect because the patch dependency does not support this mechanism

Does this suggest to you that it's not going to work because there's no way for me to set the debug feature?

[anorth]

Closing this in favour of #1566 which specifies a concrete implementation of trace spans.