Speedup logging

[AlekSi]

Closes #23.

$ bin/benchstat old.txt new.txt
goos: darwin
goarch: arm64
pkg: github.com/FerretDB/wire/wirebson
cpu: Apple M1 Pro
                                            │   old.txt    │               new.txt               │
                                            │    sec/op    │   sec/op     vs base                │
Document/handshake1/LogMessageIndent-10        751.4n ± 0%   473.5n ± 0%  -36.99% (p=0.000 n=10)
Document/handshake1/LogMessage-10              701.2n ± 1%   473.5n ± 1%  -32.48% (p=0.000 n=10)
Document/handshake1/LogMessageIndentDeep-10    3.862µ ± 2%   2.172µ ± 0%  -43.77% (p=0.000 n=10)
Document/handshake1/LogMessageDeep-10          3.481µ ± 6%   2.033µ ± 1%  -41.60% (p=0.000 n=10)
Document/handshake2/LogMessageIndent-10        758.3n ± 1%   476.3n ± 1%  -37.19% (p=0.000 n=10)
Document/handshake2/LogMessage-10              701.3n ± 1%   473.1n ± 0%  -32.53% (p=0.000 n=10)
Document/handshake2/LogMessageIndentDeep-10    3.871µ ± 1%   2.177µ ± 1%  -43.77% (p=0.000 n=10)
Document/handshake2/LogMessageDeep-10          3.417µ ± 1%   2.034µ ± 1%  -40.47% (p=0.000 n=10)
Document/handshake3/LogMessageIndent-10        504.2n ± 0%   351.9n ± 1%  -30.21% (p=0.000 n=10)
Document/handshake3/LogMessage-10              473.1n ± 0%   307.9n ± 1%  -34.92% (p=0.000 n=10)
Document/handshake3/LogMessageIndentDeep-10    728.0n ± 1%   460.6n ± 0%  -36.73% (p=0.000 n=10)
Document/handshake3/LogMessageDeep-10          654.1n ± 3%   428.9n ± 0%  -34.44% (p=0.000 n=10)
Document/handshake4/LogMessageIndent-10        3.933µ ± 1%   2.087µ ± 1%  -46.94% (p=0.000 n=10)
Document/handshake4/LogMessage-10              3.701µ ± 1%   2.008µ ± 1%  -45.74% (p=0.000 n=10)
Document/handshake4/LogMessageIndentDeep-10    18.71µ ± 1%   10.92µ ± 1%  -41.61% (p=0.000 n=10)
Document/handshake4/LogMessageDeep-10          18.02µ ± 1%   10.69µ ± 0%  -40.69% (p=0.000 n=10)
Document/all/LogMessageIndent-10               2.601µ ± 1%   1.067µ ± 1%  -58.98% (p=0.000 n=10)
Document/all/LogMessage-10                     2.479µ ± 1%   1.030µ ± 1%  -58.44% (p=0.000 n=10)
Document/all/LogMessageIndentDeep-10           6.443µ ± 1%   2.417µ ± 2%  -62.49% (p=0.000 n=10)
Document/all/LogMessageDeep-10                 4.875µ ± 0%   1.958µ ± 2%  -59.84% (p=0.000 n=10)
Document/nested/LogMessageIndent-10            182.7n ± 0%   125.7n ± 1%  -31.21% (p=0.000 n=10)
Document/nested/LogMessage-10                  156.4n ± 0%   120.7n ± 2%  -22.86% (p=0.000 n=10)
Document/nested/LogMessageIndentDeep-10        4.920µ ± 2%   1.383µ ± 1%  -71.89% (p=0.000 n=10)
Document/nested/LogMessageDeep-10             1688.5n ± 1%   639.1n ± 1%  -62.15% (p=0.000 n=10)
geomean                                        1.800µ        986.4n       -45.19%

                                            │    old.txt    │               new.txt                │
                                            │     B/op      │     B/op      vs base                │
Document/handshake1/LogMessageIndent-10          952.0 ± 0%     328.0 ± 0%  -65.55% (p=0.000 n=10)
Document/handshake1/LogMessage-10                840.0 ± 0%     328.0 ± 0%  -60.95% (p=0.000 n=10)
Document/handshake1/LogMessageIndentDeep-10    7.836Ki ± 0%   1.469Ki ± 0%  -81.26% (p=0.000 n=10)
Document/handshake1/LogMessageDeep-10          6.039Ki ± 0%   1.469Ki ± 0%  -75.68% (p=0.000 n=10)
Document/handshake2/LogMessageIndent-10          952.0 ± 0%     328.0 ± 0%  -65.55% (p=0.000 n=10)
Document/handshake2/LogMessage-10                840.0 ± 0%     328.0 ± 0%  -60.95% (p=0.000 n=10)
Document/handshake2/LogMessageIndentDeep-10    7.836Ki ± 0%   1.469Ki ± 0%  -81.26% (p=0.000 n=10)
Document/handshake2/LogMessageDeep-10          6.039Ki ± 0%   1.469Ki ± 0%  -75.68% (p=0.000 n=10)
Document/handshake3/LogMessageIndent-10          520.0 ± 0%     296.0 ± 0%  -43.08% (p=0.000 n=10)
Document/handshake3/LogMessage-10                448.0 ± 0%     168.0 ± 0%  -62.50% (p=0.000 n=10)
Document/handshake3/LogMessageIndentDeep-10      936.0 ± 0%     360.0 ± 0%  -61.54% (p=0.000 n=10)
Document/handshake3/LogMessageDeep-10            792.0 ± 0%     360.0 ± 0%  -54.55% (p=0.000 n=10)
Document/handshake4/LogMessageIndent-10       10.602Ki ± 0%   1.445Ki ± 0%  -86.37% (p=0.000 n=10)
Document/handshake4/LogMessage-10              9.844Ki ± 0%   1.445Ki ± 0%  -85.32% (p=0.000 n=10)
Document/handshake4/LogMessageIndentDeep-10    63.69Ki ± 0%   10.70Ki ± 0%  -83.19% (p=0.000 n=10)
Document/handshake4/LogMessageDeep-10          60.98Ki ± 0%   10.70Ki ± 0%  -82.45% (p=0.000 n=10)
Document/all/LogMessageIndent-10               6.594Ki ± 0%   1.125Ki ± 0%  -82.94% (p=0.000 n=10)
Document/all/LogMessage-10                     5.961Ki ± 0%   1.125Ki ± 0%  -81.13% (p=0.000 n=10)
Document/all/LogMessageIndentDeep-10          16.430Ki ± 0%   2.266Ki ± 0%  -86.21% (p=0.000 n=10)
Document/all/LogMessageDeep-10                10.438Ki ± 0%   1.391Ki ± 0%  -86.68% (p=0.000 n=10)
Document/nested/LogMessageIndent-10             112.00 ± 0%     80.00 ± 0%  -28.57% (p=0.000 n=10)
Document/nested/LogMessage-10                    88.00 ± 0%     80.00 ± 0%   -9.09% (p=0.000 n=10)
Document/nested/LogMessageIndentDeep-10       27.109Ki ± 0%   3.398Ki ± 0%  -87.46% (p=0.000 n=10)
Document/nested/LogMessageDeep-10               2424.0 ± 0%     408.0 ± 0%  -83.17% (p=0.000 n=10)
geomean                                        3.022Ki          794.5       -74.33%

                                            │   old.txt   │              new.txt               │
                                            │  allocs/op  │ allocs/op   vs base                │
Document/handshake1/LogMessageIndent-10        20.00 ± 0%   10.00 ± 0%  -50.00% (p=0.000 n=10)
Document/handshake1/LogMessage-10              19.00 ± 0%   10.00 ± 0%  -47.37% (p=0.000 n=10)
Document/handshake1/LogMessageIndentDeep-10    88.00 ± 0%   34.00 ± 0%  -61.36% (p=0.000 n=10)
Document/handshake1/LogMessageDeep-10          82.00 ± 0%   34.00 ± 0%  -58.54% (p=0.000 n=10)
Document/handshake2/LogMessageIndent-10        20.00 ± 0%   10.00 ± 0%  -50.00% (p=0.000 n=10)
Document/handshake2/LogMessage-10              19.00 ± 0%   10.00 ± 0%  -47.37% (p=0.000 n=10)
Document/handshake2/LogMessageIndentDeep-10    88.00 ± 0%   34.00 ± 0%  -61.36% (p=0.000 n=10)
Document/handshake2/LogMessageDeep-10          82.00 ± 0%   34.00 ± 0%  -58.54% (p=0.000 n=10)
Document/handshake3/LogMessageIndent-10        17.00 ± 0%   10.00 ± 0%  -41.18% (p=0.000 n=10)
Document/handshake3/LogMessage-10             16.000 ± 0%   9.000 ± 0%  -43.75% (p=0.000 n=10)
Document/handshake3/LogMessageIndentDeep-10    25.00 ± 0%   14.00 ± 0%  -44.00% (p=0.000 n=10)
Document/handshake3/LogMessageDeep-10          23.00 ± 0%   14.00 ± 0%  -39.13% (p=0.000 n=10)
Document/handshake4/LogMessageIndent-10        77.00 ± 0%   32.00 ± 0%  -58.44% (p=0.000 n=10)
Document/handshake4/LogMessage-10              76.00 ± 0%   32.00 ± 0%  -57.89% (p=0.000 n=10)
Document/handshake4/LogMessageIndentDeep-10   169.00 ± 0%   69.00 ± 0%  -59.17% (p=0.000 n=10)
Document/handshake4/LogMessageDeep-10         164.00 ± 0%   69.00 ± 0%  -57.93% (p=0.000 n=10)
Document/all/LogMessageIndent-10               61.00 ± 0%   19.00 ± 0%  -68.85% (p=0.000 n=10)
Document/all/LogMessage-10                     60.00 ± 0%   19.00 ± 0%  -68.33% (p=0.000 n=10)
Document/all/LogMessageIndentDeep-10          158.00 ± 0%   41.00 ± 0%  -74.05% (p=0.000 n=10)
Document/all/LogMessageDeep-10                141.00 ± 0%   40.00 ± 0%  -71.63% (p=0.000 n=10)
Document/nested/LogMessageIndent-10            8.000 ± 0%   6.000 ± 0%  -25.00% (p=0.000 n=10)
Document/nested/LogMessage-10                  7.000 ± 0%   6.000 ± 0%  -14.29% (p=0.000 n=10)
Document/nested/LogMessageIndentDeep-10        90.00 ± 0%   29.00 ± 0%  -67.78% (p=0.000 n=10)
Document/nested/LogMessageDeep-10              70.00 ± 0%   25.00 ± 0%  -64.29% (p=0.000 n=10)
geomean                                        45.27        20.05       -55.72%

[codecov-commenter]

Codecov Report

Attention: Patch coverage is 97.64706% with 2 lines in your changes missing coverage. Please review.

Project coverage is 65.73%. Comparing base (2df20a8) to head (5d834ad).

Files with missing lines	Patch %	Lines
wirebson/logging.go	97.64%	2 Missing :warning:

Additional details and impacted files

[](https://app.codecov.io/gh/FerretDB/wire/pull/42?src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=FerretDB) ```diff @@ Coverage Diff @@ ## main #42 +/- ## ========================================== + Coverage 65.08% 65.73% +0.64% ========================================== Files 41 41 Lines 1753 1789 +36 ========================================== + Hits 1141 1176 +35 - Misses 442 443 +1 Partials 170 170 ``` | [Files with missing lines](https://app.codecov.io/gh/FerretDB/wire/pull/42?dropdown=coverage&src=pr&el=tree&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=FerretDB) | Coverage Δ | | |---|---|---| | [wirebson/logging.go](https://app.codecov.io/gh/FerretDB/wire/pull/42?src=pr&el=tree&filepath=wirebson%2Flogging.go&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=FerretDB#diff-d2lyZWJzb24vbG9nZ2luZy5nbw==) | `93.22% <97.64%> (+0.92%)` | :arrow_up: | | [Flag](https://app.codecov.io/gh/FerretDB/wire/pull/42/flags?src=pr&el=flags&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=FerretDB) | Coverage Δ | | |---|---|---| | [test](https://app.codecov.io/gh/FerretDB/wire/pull/42/flags?src=pr&el=flag&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=FerretDB) | `65.73% <97.64%> (+0.64%)` | :arrow_up: | Flags with carried forward coverage won't be shown. [Click here](https://docs.codecov.io/docs/carryforward-flags?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=FerretDB#carryforward-flags-in-the-pull-request-comment) to find out more.