optionally disable verbose logging to improve performance

[JakkuSakura]

Currently the logging is too verbose. As seen from the flamegraph, half of the time is spent on logging. This PR adds a feature no-verbose-logging that disables these annoying loggings.

[JakkuSakura]

Not sure if it's better to disable verbose logging by default, by using verbose-logging as the feature.
async-tungstenite suggests so

[daniel-abramov]

Hm, interesting. I would imagine that logging may take a decent amount of time in case the trace level logs (quite low level) are enabled and displayed on the screen / redirected to the file.

But if I got your point right, even if you just normally use the library without getting any trace logs, you still observe the picture above with the distribution of time tungstenite-rs spends on logging? If so, then I would actually agree with you and make it the default.

[JakkuSakura]

I got the above flamegraph when disabling trace logging in tungstenite. I think part of the problem is the filtering in tracing, but I prefer only enable trace logging in my crate. Not enabling any logger would definitely decrease the time for logging somehow(who would do that?).

[daniel-abramov]

I got the above flamegraph when disabling trace logging in tungstenite.

So after you applied the changes suggested in the PR you got the posted flamegraph, right?

I think part of the problem is the filtering in tracing, but I prefer only enable trace logging in my crate.

Ok, so what I meant with my comment is that normally trace!() logs should not be a big issue since if logging is not configured, nothing is done. Checking the source code for the trace!() macro reveals that it barely calls generic log!() macro which in turn does not seem to have lot of things going on apart from the if and passing the result to the function (that is initialized in the crate and depends on the logging facility used in the target application).

I.e. I expect that if you don't have any logging enabled in your crate, no tungstenite's logs will appear and the performance burden will not be huge. I might be wrong though. But if I am wrong, then I think the solution should be using the compile time filter for log that allows to statically disable e.g. trace!() logging. Does it make any sense?

[JakkuSakura]

So after you applied the changes suggested in the PR you got the posted flamegraph, right?

I got the posted flamegraph without the PR.

does not seem to have lot of things going on

The logging implementation may be complex, and the filtering may be rather expensive in a performance targeted program.

I expect that if you don't have any logging enabled in your crate, no tungstenite's logs will appear and the performance burden will not be huge

It seems right, and I'l do a test later today.

This is what it looks like after removing all loggings.

solution should be using the compile time filter for log that allows to statically disable e.g. trace!() logging

It is a viable solution, but in some cases I prefer a per-crate configuration, i.e. trace logging in main crate, debug/info in dependencies.

[daniel-abramov]

It seems right, and I'l do a test later today.
This is what it looks like after removing all loggings.

By "removing all loggings" you mean applying the changes in this PR, right? (just so that we're on the same page)

It is a viable solution, but in some cases I prefer a per-crate configuration, i.e. trace logging in main crate, debug/info in dependencies.

Makes sense, but what about this: we do introduce a new feature flag for disabling trace logging, however instead of adding the conditional to enable/disable certain parts of the code depending on the feature, we just use the above mentioned strategy (passing a feature flags to the log) so that these are disabled automatically for tungstenite-rs?

[JakkuSakura]

By "removing all loggings" you mean applying the changes in this PR, right? (just so that we're on the same page)

Yes

we just use the above mentioned strategy (passing a feature flags to the log) so that these are disabled automatically for tungstenite-rs

It does not work. features are enabled globally. I.e. log/max_level_debug will disable all trace in current program.

Maybe we can do this:
we define a new macro called tung_trace!() that forwards all args to trace!() if verbose-log is enabled, otherwise drops all arguments

#[cfg(feature = "verbose-log")]
macro_rules! tung_trace {
    ($($arg:expr),*) => { log::trace!($($arg),*); };
}


#[cfg(not(feature = "verbose-log"))]
macro_rules! tung_trace {
    ($level:ident, $($arg:expr),*) => {{ $( let _ = $arg; )* }}
}

[daniel-abramov]

Another possibility that I thought about is to remove the trace!() logs. It seems like they were primarily used in the early stages of the development as sort of a debugging tool, but not particularly helpful in the modern version of the library (in fact I can't remember any single case us relying on the trace!() logs to debug anything within the last 4 years).

@jxs, what do you think?

[daniel-abramov]

There was no response from @jxs, so if no-one objects, then I think the best way would be just removing traces there. I don't remember us using it after the first production-ready version. Seems like they are not much of a use. It does not seem like introducing a whole feature for that is worth it 🙂

[daniel-abramov]

There have been no updates on this for almost half a year, so we decided to close it. Feel free to re-open in case any changes are desired :)