bench: Add logging benchmark #18815

maflcko · 2020-04-29T12:53:25Z

Might make finding performance bottlenecks or regressions (#17218) easier.

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

DrahtBot · 2020-04-29T16:24:30Z

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.

practicalswift · 2020-04-29T18:23:56Z

Concept ACK

practicalswift · 2020-04-29T19:05:57Z

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

    static TestingSetup setup{
        CBaseChainParams::REGTEST,
        {
            "-nodebuglogfile",
        },
    };

laanwj · 2020-04-30T08:11:17Z

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

maflcko · 2020-04-30T12:09:04Z

Jup, this is not primarily to encourage people to optimize this function, but rather to make finding performance bottlenecks (#18538 (comment)) or regressions (#17218) easier.

jb55 · 2020-05-02T10:07:05Z

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.

maflcko · 2020-05-02T11:57:55Z

The strings are written to disk unbuffered:

bitcoin/src/logging.cpp

Line 56 in 844d207

setbuf(m_fileout, nullptr); // unbuffered

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

jamesob

ACK fa22a52 (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.

Show platform data

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)

Show signature data

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA512

ACK fa22a52f2aae3d1962a386d973de192e0de8fd65 ([`jamesob/ackr/18815.1.MarcoFalke.bench_add_logging_benchm`](https://github.com/jamesob/bitcoin/tree/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.


<details><summary>Show platform data</summary>
<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)


</p></details>
-----BEGIN PGP SIGNATURE-----

iQIzBAEBCgAdFiEEpm2+LMqPsWj2rAwWyrywS1A+5mgFAl6xh6UACgkQyrywS1A+
5mjoJg//ZgjGIa7dmzkSwvbUHW0sg/u2ShTCsOrWWfx6cdZ7ApQlPOH5nDcjO7yb
Qr61POE/3uA3kUrcUvVvlwqStpbwbjqNNNR5g8OklGE/N2N4Q621ze1vtmWJOuU2
ik7APJT3MlU/fOEEqRGSdS9Jow2P45CqrPTSgCjJA0oPlhTn6lrtaCtDEgT/dFR3
TJlHO/Oe53zK2wpkzUVzKXswvNLsSSPYHIIp/hFYRNanfnnmFg16YTD73sr+CrSV
K6JGkTbIwtXEIHRuIglTHRMW46U3MoAMhg2/e1L4Ssdq1oUI0aCUNC7nww066zI6
1reKeu+fkfOVLAYNb+Ke18GqOrWwBdPUut+o8bTvK43nMYZHH2eRL/4orS/WKSWG
PGV1qSBDY8F7DdtLUeIXmvWxZbCFubFFpx/zl/Ur8S9+Hr96jWilt9l8t2FOhzbF
nzCV+LkfUYhpHYFgCxtXg3px6sKQ02S3A8NyyfWTkE/LIAMKrDcAG8JJxOeuAAMm
iay0gemRuqZKA4zGrhZTc85Js0Qjpu9LAnpWSNKraGEzwbxLCNIFN9J0LvogERhn
+4RbxIyJewk5P4Sb6k+lTuegmBu3CjfyohCndfuPEGdFI/++cd/ynIXlhDIjvDxq
CeeYGoBm8SjxtEMkeBCeuw4G+tZCfB2n8m8VccknjInX7t0lQSM=
=yVlS
-----END PGP SIGNATURE-----

elichai · 2020-05-18T14:58:10Z

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.

dergoegge · 2022-03-10T22:14:51Z

ACK fafe06c

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.

DrahtBot added the Build system label Apr 29, 2020

fanquake added Tests and removed Build system labels Apr 29, 2020

maflcko force-pushed the 2004-benchLog branch from fa25e36 to fa2f6ad Compare April 29, 2020 13:56

maflcko removed the Tests label Apr 29, 2020

DrahtBot added the Build system label Apr 29, 2020

maflcko removed the Build system label Apr 29, 2020

DrahtBot added Build system Tests labels Apr 29, 2020

maflcko removed the Build system label Apr 29, 2020

This was referenced Apr 29, 2020

util: Pass size to ParseHex to assist preallocation #18061

Closed

Avoid unnecessary signing provider copies on descriptor expansion #16116

Closed

Faster sigcache nonce #13204

Merged

maflcko added DrahtBot Guix build requested Needs gitian build labels May 2, 2020

DrahtBot removed DrahtBot Guix build requested Needs gitian build labels May 3, 2020

jamesob approved these changes May 5, 2020

View reviewed changes

DrahtBot added the Needs rebase label Jun 2, 2020

maflcko force-pushed the 2004-benchLog branch from fa22a52 to faf0302 Compare June 2, 2020 12:05

maflcko closed this Jun 2, 2020

maflcko reopened this Jun 2, 2020

DrahtBot removed the Needs rebase label Jun 2, 2020

DrahtBot mentioned this pull request Jun 13, 2020

Replace current benchmarking framework with nanobench #18011

Merged

bitcoin deleted a comment from DrahtBot Jun 18, 2020

DrahtBot mentioned this pull request Jun 25, 2020

bench: Add OrphanTxPool benchmark #19377

Closed

This was referenced Jul 7, 2020

multiprocess: Add bitcoin-gui -ipcconnect option #19461

Draft

multiprocess: Add bitcoin-wallet -ipcconnect option #19460

Draft

DrahtBot added the Needs rebase label Jul 30, 2020

MarcoFalke added 2 commits December 15, 2021 14:33

bench: Add logging benchmark

fa31dc9

bench: Sort bench_bench_bitcoin_SOURCES

fafe06c

maflcko force-pushed the 2004-benchLog branch from faf0302 to fafe06c Compare December 15, 2021 13:34

DrahtBot removed the Needs rebase label Dec 15, 2021

This was referenced Dec 16, 2021

Add allocator for node based containers #22702

Closed

util: improve FindByte() performance #19690

Merged

dergoegge mentioned this pull request Mar 10, 2022

log: Mitigate disk filling attacks by rate limiting LogPrintf #21603

Closed

maflcko merged commit e4d61d9 into bitcoin:master Mar 16, 2022

maflcko deleted the 2004-benchLog branch March 16, 2022 16:06

sidhujag pushed a commit to syscoin/syscoin that referenced this pull request Mar 16, 2022

Merge bitcoin#18815: bench: Add logging benchmark

0606f79

jonatack mentioned this pull request Jan 23, 2023

bench: update logging benchmarks #26957

Merged

bitcoin locked and limited conversation to collaborators Mar 16, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

bench: Add logging benchmark #18815

bench: Add logging benchmark #18815

Uh oh!

maflcko commented Apr 29, 2020 •

edited

Loading

Uh oh!

DrahtBot commented Apr 29, 2020 •

edited

Loading

Uh oh!

practicalswift commented Apr 29, 2020

Uh oh!

practicalswift commented Apr 29, 2020 •

edited

Loading

Uh oh!

laanwj commented Apr 30, 2020 •

edited

Loading

Uh oh!

maflcko commented Apr 30, 2020

Uh oh!

jb55 commented May 2, 2020 •

edited

Loading

Uh oh!

maflcko commented May 2, 2020

Uh oh!

jamesob left a comment •

edited

Loading

Uh oh!

elichai commented May 18, 2020

Uh oh!

dergoegge commented Mar 10, 2022

Uh oh!

Uh oh!

bench: Add logging benchmark #18815

bench: Add logging benchmark #18815

Uh oh!

Conversation

maflcko commented Apr 29, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

DrahtBot commented Apr 29, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Conflicts

Uh oh!

practicalswift commented Apr 29, 2020

Uh oh!

practicalswift commented Apr 29, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

laanwj commented Apr 30, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

maflcko commented Apr 30, 2020

Uh oh!

jb55 commented May 2, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

maflcko commented May 2, 2020

Uh oh!

jamesob left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

elichai commented May 18, 2020

Uh oh!

dergoegge commented Mar 10, 2022

Uh oh!

Uh oh!

maflcko commented Apr 29, 2020 •

edited

Loading

DrahtBot commented Apr 29, 2020 •

edited

Loading

practicalswift commented Apr 29, 2020 •

edited

Loading

laanwj commented Apr 30, 2020 •

edited

Loading

jb55 commented May 2, 2020 •

edited

Loading

jamesob left a comment •

edited

Loading