Logging takes quite some CPU time

[pepyakin]

Running polkadot under a profiler I've noticed that a big chunk of time is spent in logging. I lost the original trace, but here is the new one.

The steps I took to obtain the trace

• Launch polkadot --wasm-execution Compiled (the binary is compiled with --release flag)
• Attach Instruments to just launched process
• Let it run for a number of seconds (for the attached trace, it's 30 seconds of wall time)

Looking at the trace, focusing on the calls made by log::__private_api_log one can see, that polkadot spent 33.48s of CPU time out of 1.09m in logging.

Most of that time is spent in waiting for the rw lock it seems

macOS Big Sur 11.1
Polkadot: paritytech/polkadot@2495a6b0e
Instruments: Version 12.2 (12C33)

Polkadot Slow Log Trace.trace.zip

[dvdplm]

I can't seem to repeat this. Not an expert profile reader but afaict the trace looks alright.

I ran polkadot --wasm-execution Compiled like you; I'm on Catalina 10.15.7 and on commit 4e73c1d3bf (from yesterday) though, rustc at 1.51.0-nightly (158f8d034 2020-12-29). I started the profiler after some 10min of importing (a new DB, so major sync).

pd.trace.zip

Not sure what to make of this. You can repeat this every time right?

[dvdplm]

Unrelated to this problem perhaps but one thing that strikes me as odd is how the work in my trace seems to be skewed to a single thread. Your trace is hard to read for me here because symbols are missing

Yours look like this to me:

That spike ~8sec in looks weird – what is going on there you think?

[pepyakin]

The exact steps I did:

1. First, I disable "Call Tree → Separate By Thread"
2. Find this "log::__private_api_log"
3. Then right-click and "Focus on calls made by ..."

This gives you aggregation on all calls across all thread to this function.

It seem that your trace does exhibit the behavior, but to a smaller degree: 7 CPU seconds spent in under this function out of 2.16 CPU mins. Not as bad as my initial trace, but still too much IMO.

The spike at ~8 sec AFAICT is a rocksdb flush. FWIW, I can see the symbols from your trace ok.

Just retook a trace again, this time with the binary produced by the rust nightly you mentioned. Also, I've realized that my previous build was with "--features=real-overseer", whereas this one is not. The result is ~7 CPU secs spent under __private_api_log out of ~30 CPU secs.

[dvdplm]

Thank you so much for the detailed repro info, I see it now. And yes it's pretty bad.

tracing uses std locks for some random reason so that could be it. I had a PoC branch that uses parking_lot instead (see tokio-rs/tracing#1090) but didn't see any notable performance difference beyond the reloadable benchmark you see there in that PR. It could very well be that their benchmarks are too artificial to show the real difference in cases like ours.

I'll profile polkadot before #7474 (i.e. before paritytech/polkadot#1985) and see if that makes any difference.

[andresilva]

Even though we have recently migrated to use tracing we are still using the regular log macros. Not sure about tracing but at least for slog the macros are "lazily-evaluated", i.e. if something doesn't get printed (e.g. because the log level is too low) then it doesn't get formatted. IIRC it also supports moving the formatting/serialization to some background thread. We should investigate if any such solutions are available for tracing.

Edit: just read that the time is mostly spent waiting on a fat lock 😐

[bkchr]

Normal log is doing the same. They lazily evaluate in the macros as well.

[dvdplm]

Update from DM conversation with @pepyakin. It seems like the slowness can partly be explained by Cranelift kicking in when starting the chain (and --wasm-execution Compiled). The wasm functions are compiled in parallel with rayon and logs a fair bit, hence the lock contention.
We do spend a lot of time in logging and it's certainly worth investigating further but it's not as urgent as we thought at first. Something to check is how much we allocate when logging.

[dvdplm]

I'll profile polkadot before #7474 (i.e. before paritytech/polkadot#1985) and see if that makes any difference.

This is still on my TODO.

[notlesh]

This may or may not be relevant, but I did some profiling with valgrind and found that this log statement, even when disabled at runtime, was introducing a very significant amount of overhead:

https://github.com/rust-blockchain/evm/blob/5902295f6dd98e2b21c209171f0341054f5a40e5/src/executor/stack.rs#L930

Setting the feature max_level_debug (or for release mode only release_max_level_debug) on crate log was sufficient to remove this overhead; see:

moonbeam-foundation/moonbeam#168

[bkchr]

@notlesh Ty! You triggered something in my brain which lead to solving the underlying problem: #7851

I think that will also solve your problem in moonbeam!