Add trace functionality

[maurolacy]

Related to #746.

Useful for comparing wall time between contract code and blockchain code. This way the latency of the Go -> Rust and Rust -> Go bridges can be easily measured (and eventually improved).

Useful as well for general benchmarks of code and procedures. Elapsed time can be computed post-facto by subtracting calls to trace().

The performance of code between the native and wasm runtimes cannot be compared fairly, as the WebAssembly code is running inside the VM. But time measurements are useful as a relative reference for comparing different routines and implementations in contract code.

It could also be interesting to know how much faster native code is for particular tasks, compared to wasm code.

[ueco-jb]

What's the difference between debug and trace here?

[maurolacy]

What's the difference between debug and trace here?

The timestamp information. We can conflate the two things into one, but I think having two different calls makes sense / is more flexible.
debug can be used for printing the content of variables and stuff, whereas trace can be used for printing labels and timestamps. It's cleaner that way, both for reading and post-processing.

[maurolacy]

Are there plans to merge this? Any feedback on this?

[webmaster128]

Sorry, Mauro. I did not look into your two PRs yet.

I think the change makes sense in general. However, given how under-utilized debug is today, I am hesitant to add a new entry point.

What if we make the functionality available in the debug import implementation? I wanted to improve the flexibility of that already. Basically it would be cool if do_debug has a default implementation and also could be improved. println!("{}", msg); is not goo enough for most mid-level cases.

We can add microsecond timestamps in RFC-3339 format my default there:

println!("[2020-12-15T10:57:26.778923Z]: {}", msg);.

[maurolacy]

Sounds good. I'll do the proposed changes to debug.

Do you think this can be kept always on? The lack of default arguments in Rust makes it difficult to do this in a non-breaking way. In that sense, if we want to be able to enable / disable this functionality, a different entry point is better (less breaking) than adding a parameter to an existing one.

The same with the proposed consumed gas print functionality (#1643).

[maurolacy]

Perhaps we can implement a parametrised debug, and then provide some high level wrappers around it?

[webmaster128]

I'm thinking roughly of a solution like this is MockQuerier:

    /// A handler to handle custom queries. This is set to a dummy handler that
    /// always errors by default. Update it via `with_custom_handler`.
    ///
    /// Use box to avoid the need of another generic type
    custom_handler: Box<dyn for<'a> Fn(&'a C) -> MockQuerierCustomHandlerResult>, 

with a default value

            // strange argument notation suggested as a workaround here: https://github.com/rust-lang/rust/issues/41078#issuecomment-294296365
            custom_handler: Box::from(|_: &_| -> MockQuerierCustomHandlerResult {
                SystemResult::Err(SystemError::UnsupportedRequest {
                    kind: "custom".to_string(),
                })
            }),

that can be overriden:

    pub fn with_custom_handler<CH: 'static>(mut self, handler: CH) -> Self
    where
        CH: Fn(&C) -> MockQuerierCustomHandlerResult,
    {
        self.custom_handler = Box::from(handler);
        self
    }

If we have that available in Environment, we can call it.

With something like Rc instead of Box it should be possible to implement clone.

Ideally the function is optional. If print_debug is false (all production environments), no function is set and called in do_debug. If print_debug is true, we have a default implementation (maybe with the gas value and secod precision time stamps). And users have a way to override it to a custom debug implementation to e.g. write to STDERR instead of STDOUT, add more tracing data or write to file.

[maurolacy]

Not sure I understand. The original idea / proposal is having debug with timestamps and gas consumption, for real (non-mocked) environments. This allows you to print out timestamps and gas consumption in a node running with --trace. This is useful to measure the performance of wasm code in a real scenario.

Update: Oh, you mean like the custom querier impl, but for debug. Let's discuss in chat how to do this in detail.

[webmaster128]

Oh, yeah, the like is important here. See #1667

[maurolacy]

Closed in favour of #1667.