Stream: git-wasmtime

Topic: wasmtime / Issue #2758 Revert "Cranelift: remove logging ...

Wasmtime GitHub notifications bot (Mar 23 2021 at 19:26):

bnjbvr commented on Issue #2758:

Would it make sense to centralize all of our logging in our own macro that wraps log's APIs, but does the log_enabled check? Or checks some other global that we control? That's definitely taking on a responsibility that should be covered by the logging infra but maybe we can make it safer...?

Random (cute) idea: how about we add a log::debug statement at the top of wasmtime cranelift's entry point so that it warns users that compilation may be slower at this log filter level? This way, only people who did set up the log level too high will see the message, and that's something they can try to address on their side.

On the other hand, forcing users to not enable log::debug statements because it destroys performance in Cranelift is a bit of a sub-optimal developer experience.

Wasmtime GitHub notifications bot (Mar 23 2021 at 20:29):

cfallin commented on Issue #2758:

how about we add a log::debug statement at the top of wasmtime cranelift's entry point so that it warns users that compilation may be slower at this log filter level?

Interesting idea -- yes, that could definitely make sense. IIRC, though, wasn't the issue here that the logging level was high/max in some internal setting, but logs were not actually being written somewhere?

Wasmtime GitHub notifications bot (Mar 24 2021 at 10:04):

bnjbvr commented on Issue #2758:

Yeah, you're right.

Trying to get to the bottom of this, here's what's happening: the log crate provides three ways to control whether a message is "dispatched" or not:

• static Cargo features; they're not involved here, so let's not worry about them.
• a maximum filter level (e.g. debug or trace), that's set for the whole lib/bin.
• a final setting controlled by the log::Log implementation: for instance the log() method in particular can return early if the log's record metadata doesn't match what it's configured to show.

Now, the debug! et al. macros are only testing if the two first items from this list, that is, is this level statically enabled by Cargo features, and is it above the global maximum filter level or not. If that's the case, this means that the macro arguments will be evaluated, before being passed to the log::Log implementation where they can end up being ignored by the caller (if it returned early).

On the other hand, the log_enabled! macro will check for the first two items, and then call into the log::Log implementation of enabled, which must return true if the logger's impl cares about this particular level (and log target).

I don't have all the background for the log API design, but I wonder why all the macros don't check for enabled before evaluating the arguments (likely for performance reasons; that'd be an extra function call for every log message!). Overall, I think that if we'd actually take this PR, we'd force our users into setting the global log level (log::max_level) to any level below Debug (excluded) if they want to have the best performance. It would mean that our users have a binary choice between "allow any logging of levels Debug and above (== Trace)" versus "get good performance from Cranelift compilation". This actually sounds bad to me: one could care about getting debug! messages in some part of their application, while not caring about the debug! messages from Cranelift itself, and still wanting to get the best performance out of it. So it is unfortunate that we need to do this hack, but the current state without this PR allows both for 1. not blocking the maximum log level and 2. getting the maximum performance out of Cranelift. Hence I'd rather not take it.

What do you all think about it?

(Alternatives: make the vcode string rendering not so dramatically slow, use our own log macros that use log_enabled as suggested by @cfallin)

Wasmtime GitHub notifications bot (Mar 24 2021 at 14:10):

alexcrichton commented on Issue #2758:

Another possible alternative would be auditing to ensure that the argument evaluation itself is not expensive. There's not a great way to do this all the time but the theory is that you can avoid speeding things up by deferring actual formatting to when requested. (e.g. have one-off structs with Display impls that "do the thing" internally, although probably more ergonomically than is the default).

The separation was indeed for performance, where the Logger::enabled is expected to be called internally from Logger::log. The Logger::log method has the ability to also filter based on the message, e.g. "only log strings with foo in them". You're right, though, that the consequence of the current usage is that if debug is enabled anywhere then everything slows down in Cranelift since the argument evaluation is expensive.

Wasmtime GitHub notifications bot (Mar 24 2021 at 17:52):

cfallin commented on Issue #2758:

Wrapping everything in a struct (struct DeferredDebugOutput<'a, T: Debug>(t: &'a T) that just impls Display) might be a nice way to go about this. Then we could do something like log::debug!("expensive value is: {}", deferred(&slow_to_print_vcode));, maybe?

Alternately, I am OK with staying with the status quo ( == current main, without this PR) for now; it's certainly the simplest option!

Wasmtime GitHub notifications bot (Mar 24 2021 at 17:53):

cfallin edited a comment on Issue #2758:

Wrapping everything in a struct (struct DeferredDebugOutput<'a, T: Debug>(t: &'a T) that just impls Display) might be a nice way to go about this. Then we could do something like log::debug!("expensive value is: {}", deferred(&slow_to_print_vcode));, maybe? (edit to make clear: this is my understanding of @alexcrichton's idea -- did I get that right?)

Alternately, I am OK with staying with the status quo ( == current main, without this PR) for now; it's certainly the simplest option!

Wasmtime GitHub notifications bot (Mar 24 2021 at 17:57):

alexcrichton commented on Issue #2758:

To clarify, though, the exact struct would look more like:

struct DeferredDisplay<F>(F);

impl<F, R> fmt::Display for DeferredDisplay<F>
where
    F: Fn() -> R,
    R: fmt::Display,
{
    // ..
}

notably the closure would bake in "only run this when Display is requested" and would prevent anything from being executed until the log message is rendered.

Wasmtime GitHub notifications bot (Mar 25 2021 at 14:51):

bnjbvr commented on Issue #2758:

Fun idea, I've implemented it, thanks Alex! Care to have another look, please?

Last updated: Nov 22 2024 at 16:03 UTC