@Chris Fallin, @Benjamin Bouvier: I am surprised that https://github.com/bytecodealliance/wasmtime/pull/2755 is needed... I haven't looked at the implementation of debug!
but I assumed that the point of having such a macro is that the expressions passed to the logger are not evaluated _unless_ logging is enabled. Why do we have to have another check around that?!?
Indeed, I was surprised too -- will be curious to know more details about @Benjamin Bouvier 's environment (ie loggingg module setup)
if it is the case that args are always evaluated, or we can't rely on them not being so, then we should audit a bunch of hot paths!
(a lot of debug logging just prints primitive locals that exist anyway, so I imagine there's no overhead there aside from the do-I-log branch; but there may be other cases where we explicitly build a string in a call somewhere)
yes, exactly!
@Andrew Brown @Chris Fallin regardless of logging level the arguments to the logging macro are always evaluated
regardless of whichever logging crate you're using I believe
@Alex Crichton that is very much a TIL for me and I now know what I'm doing with high-ish priority. Thanks :-)
That seems broken, though... most of us expect logging to be lazily evaluated?
wait no, don't quote me on this
@Alex Crichton, is this something that could/should be fixed in log
? Or does it have to be this way?
the source disagrees with me
do you have the link?
@Chris Fallin no I am wrong
arguments are not evaluated
so this is probably the tokio bug and a crate that wasn't updated
@Andrew Brown I just checked locally and log::debug!("{:?}", println!(""));
doesn't print anything
so arguments aren't evaluated unless the log level is enabled
sorry I thought it was the other way around which is why I approved...
phew... my faith in log
is restored
Phew. Crisis averted.
but does that mean that @Benjamin Bouvier's PR was necessary?
Well, it's possible that others may be running with older (buggy) logging environments for which this is not true, I suppose
it means it shouldn't be necessary, no
yeah
Alex, what's the tokio bug?
https://github.com/tokio-rs/tracing/issues/1249
cool, thanks
oh really? i just spent some time looking at the log's code and concluded that it was necessary... let me back it up
I was equally surprised by this, the arguments are not evaluated if the max_level is correctly set
which could happen if the buggy version of tracing-subscriber is used, or if some incorrect code is used to set up the loggers
to make sure, I've added panics at the same places the PR changes things:
It might have been a red herring then: we're using tracing-subscriber, as well as another small log wrapper that might be doing something silly. I'll confirm, but then we can probably revert the change I've made.
Yep, that was it: we were using a default ctor of tracing_subscriber
which sets the max_level
to LevelFilter::Max
, by default -_-'
Good thing that the log macros are actually sane, and that we don't need to audit the full code base for other log uses!
its a bummer that the log ecosystem and tracing-subscriber dont work together perfectly well, but fastly uses tracing-subscriber in a lot of contexts and i expect many other users will as well, so its worthwhile to make sure we are optimized properly for using tracing-subscriber as well as the usual env_logger or equivelant
@Pat Hickey we have a nice solution now suggested by Alex in #2758 -- agreed that we want to avoid performance footguns like this lest we drive folks away thinking our backend is too slow
Last updated: Dec 23 2024 at 12:05 UTC