bench: Add logging benchmark

MarcoFalke commented at 12:53 pm on April 29, 2020: member

Might make finding performance bottlenecks or regressions (https://github.com/bitcoin/bitcoin/pull/17218) easier.

For example, fuzzing relies on disabled logging to be as fast as possible.

DrahtBot added the label Build system on Apr 29, 2020

fanquake removed the label Build system on Apr 29, 2020

fanquake added the label Tests on Apr 29, 2020

MarcoFalke force-pushed on Apr 29, 2020

DrahtBot commented at 4:24 pm on April 29, 2020: member

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Conflicts

Reviewers, this pull request conflicts with the following ones:

#22702 (Add allocator for node based containers by martinus)

If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

MarcoFalke removed the label Tests on Apr 29, 2020

DrahtBot added the label Build system on Apr 29, 2020

MarcoFalke removed the label Build system on Apr 29, 2020

DrahtBot added the label Build system on Apr 29, 2020

DrahtBot added the label Tests on Apr 29, 2020

MarcoFalke removed the label Build system on Apr 29, 2020

practicalswift commented at 6:23 pm on April 29, 2020: contributor

Concept ACK

practicalswift commented at 7:05 pm on April 29, 2020: contributor

Would it make sense to also benchmark the logging setup we use in the fuzz tests to avoid logging to disk?

0    static TestingSetup setup{
1        CBaseChainParams::REGTEST,
2        {
3            "-nodebuglogfile",
4        },
5    };

laanwj commented at 8:11 am on April 30, 2020: member

To be honest, I think the idea of logging being performance critical is a bit scary. It was never meant like this. We shouldn’t log in inner loops and such. Sure, debug flags are enabled it’s different but one can expect a performance hit in that case. It’s not really something to optimize for IMO.

(not opposed to adding a benchmark, but I just think it’s not a very high priority thing to optimize and a benchmark encourages this)

Edit: I understand it now in the context of #18678

MarcoFalke commented at 12:09 pm on April 30, 2020: member

Jup, this is not primarily to encourage people to optimize this function, but rather to make finding performance bottlenecks (https://github.com/bitcoin/bitcoin/issues/18538#issuecomment-614898713) or regressions (#17218) easier.

jb55 commented at 10:07 am on May 2, 2020: member

I think a big issue with the logging is that it does a bunch of string concatenation and allocation for formatting, instead of format strings+printf. When you do this in a tight loop/IBD, I’m not surprised that you would see performance issues.

My guess for the thread_local issue is just the fact that it has to allocate and concatenate even more when it formats threads names into the log.

MarcoFalke commented at 11:57 am on May 2, 2020: member

The strings are written to disk unbuffered:

https://github.com/bitcoin/bitcoin/blob/844d2070a2c0106bb7a54be5cad7d4da4d9cd55e/src/logging.cpp#L56

If I had to guess, even with SSD this might be the dominant factor, and not memory allocation for strings.

MarcoFalke added the label Needs Guix build on May 2, 2020

MarcoFalke added the label Needs gitian build on May 2, 2020

DrahtBot removed the label Needs Guix build on May 3, 2020

DrahtBot removed the label Needs gitian build on May 4, 2020

jamesob approved

jamesob commented at 3:35 pm on May 5, 2020: member

ACK fa22a52f2aae3d1962a386d973de192e0de8fd65 (jamesob/ackr/18815.1.MarcoFalke.bench_add_logging_benchm)

Built and tested with ./src/bench/bench_bitcoin -filter='.*Logging.*'.

Seems like a no-brainer to have this benchmark data on hand to avoid embarrassing regressions due to some quirk in the logging system.

Worth noting that some effort was made previously to move logging to a separate thread (#13200), though I think that implementation did do string interpolation inline (synchronously). I had tried to move interpolation to the logging thread, but the difficulty of __VA_ARGS__ and getting the right function signatures deterred me; may be doable though.

0Tested on Linux-5.3.0-51-generic-x86_64-with-Ubuntu-18.04-bionic
1
2Configured with ./configure LDFLAGS=-L/home/james/src/bitcoin/db4/lib/ CPPFLAGS=-I/home/james/src/bitcoin/db4/include/ CXXFLAGS=-std=c++11 -Werror=thread-safety-analysis --enable-wallet --enable-debug --with-daemon CXX=/usr/bin/clang++-4.0 CC=/usr/bin/clang-4.0 PYTHONPATH= --disable-shared --with-pic --enable-benchmark=no --with-bignum=no --enable-module-recovery --disable-jni --disable-shared --with-pic --enable-benchmark=no --with-bignum=no --enable-module-recovery --disable-jni --no-create --no-recursion
3
4Compiled with /usr/bin/ccache /usr/bin/clang++-4.0 -std=c++11 -mavx -mavx2 -std=c++11 -Werror=thread-safety-analysis -O0 -g3 -ftrapv  -Wstack-protector -fstack-protector-all -msse4 -msha -msse4.1 -msse4.2  i
5
6Compiler version: clang version 4.0.1-10 (tags/RELEASE_401/final)

 0-----BEGIN PGP SIGNED MESSAGE-----
 1Hash: SHA512
 2
 3ACK fa22a52f2aae3d1962a386d973de192e0de8fd65 ([`jamesob/ackr/18815.1.MarcoFalke.bench_add_logging_benchm`](https://github.com/jamesob/bitcoin/tree/ackr/18815.1.MarcoFalke.bench_add_logging_benchm))
 4
 5Built and tested with `./src/bench/bench_bitcoin -filter='.*Logging.*'`. 
 6
 7Seems like a no-brainer to have this benchmark data on hand to avoid embarrassing 
 8regressions due to some quirk in the logging system.
 9
10Worth noting that some effort was made previously to move logging to a separate
11thread (#13200), though I think that implementation did do string interpolation
12inline (synchronously). I had tried to move interpolation to the logging
13thread, but the difficulty of `__VA_ARGS__` and getting the right function
14signatures deterred me; may be doable though.
15
16
17<details><summary>Show platform data</summary>
18<p>

Tested on Linux-5.3.0-51-generic-x86_64-with-Ubuntu-18.04-bionic

Configured with ./configure LDFLAGS=-L/home/james/src/bitcoin/db4/lib/ CPPFLAGS=-I/home/james/src/bitcoin/db4/include/ CXXFLAGS=-std=c++11 -Werror=thread-safety-analysis –enable-wallet –enable-debug –with-daemon CXX=/usr/bin/clang++-4.0 CC=/usr/bin/clang-4.0 PYTHONPATH= –disable-shared –with-pic –enable-benchmark=no –with-bignum=no –enable-module-recovery –disable-jni –disable-shared –with-pic –enable-benchmark=no –with-bignum=no –enable-module-recovery –disable-jni –no-create –no-recursion

Compiled with /usr/bin/ccache /usr/bin/clang++-4.0 -std=c++11 -mavx -mavx2 -std=c++11 -Werror=thread-safety-analysis -O0 -g3 -ftrapv -Wstack-protector -fstack-protector-all -msse4 -msha -msse4.1 -msse4.2 i

Compiler version: clang version 4.0.1-10 (tags/RELEASE_401/final)

 0
 1</p></details>
 2-----BEGIN PGP SIGNATURE-----
 3
 4iQIzBAEBCgAdFiEEpm2+LMqPsWj2rAwWyrywS1A+5mgFAl6xh6UACgkQyrywS1A+
 55mjoJg//ZgjGIa7dmzkSwvbUHW0sg/u2ShTCsOrWWfx6cdZ7ApQlPOH5nDcjO7yb
 6Qr61POE/3uA3kUrcUvVvlwqStpbwbjqNNNR5g8OklGE/N2N4Q621ze1vtmWJOuU2
 7ik7APJT3MlU/fOEEqRGSdS9Jow2P45CqrPTSgCjJA0oPlhTn6lrtaCtDEgT/dFR3
 8TJlHO/Oe53zK2wpkzUVzKXswvNLsSSPYHIIp/hFYRNanfnnmFg16YTD73sr+CrSV
 9K6JGkTbIwtXEIHRuIglTHRMW46U3MoAMhg2/e1L4Ssdq1oUI0aCUNC7nww066zI6
101reKeu+fkfOVLAYNb+Ke18GqOrWwBdPUut+o8bTvK43nMYZHH2eRL/4orS/WKSWG
11PGV1qSBDY8F7DdtLUeIXmvWxZbCFubFFpx/zl/Ur8S9+Hr96jWilt9l8t2FOhzbF
12nzCV+LkfUYhpHYFgCxtXg3px6sKQ02S3A8NyyfWTkE/LIAMKrDcAG8JJxOeuAAMm
13iay0gemRuqZKA4zGrhZTc85Js0Qjpu9LAnpWSNKraGEzwbxLCNIFN9J0LvogERhn
14+4RbxIyJewk5P4Sb6k+lTuegmBu3CjfyohCndfuPEGdFI/++cd/ynIXlhDIjvDxq
15CeeYGoBm8SjxtEMkeBCeuw4G+tZCfB2n8m8VccknjInX7t0lQSM=
16=yVlS
17-----END PGP SIGNATURE-----

elichai commented at 2:58 pm on May 18, 2020: contributor

Worth noting that some effort was made previously to move logging to a separate thread (#13200), though I think that implementation did do string interpolation inline (synchronously). I had tried to move interpolation to the logging thread, but the difficulty of VA_ARGS and getting the right function signatures deterred me; may be doable though.

Is it? because LogPrintf accepts the inputs as references, so if you pass those to a thread and run tfm::format in that thread you might have a dangling reference or a data race here.

DrahtBot added the label Needs rebase on Jun 2, 2020

MarcoFalke force-pushed on Jun 2, 2020

MarcoFalke closed this on Jun 2, 2020

MarcoFalke reopened this on Jun 2, 2020

DrahtBot removed the label Needs rebase on Jun 2, 2020

MarcoFalke deleted a comment on Jun 18, 2020

DrahtBot added the label Needs rebase on Jul 30, 2020

bench: Add logging benchmark fa31dc9b71

bench: Sort bench_bench_bitcoin_SOURCES fafe06c379

MarcoFalke force-pushed on Dec 15, 2021

DrahtBot removed the label Needs rebase on Dec 15, 2021

dergoegge commented at 10:14 pm on March 10, 2022: member

ACK fafe06c379316f165e88b8de7300a716cef25d0a

Tested with ./src/bench/bench_bitcoin -filter="Logging.*"

These benchmarks were helpful to me in answering this review comment on my log rate limting PR.

MarcoFalke merged this on Mar 16, 2022

MarcoFalke closed this on Mar 16, 2022

MarcoFalke deleted the branch on Mar 16, 2022

sidhujag referenced this in commit 0606f79a2e on Mar 16, 2022

DrahtBot locked this on Mar 16, 2023

bench: Add logging benchmark #18815

Conflicts