Optimize encoder #12

fyrchik · 2023-10-12T12:57:41Z

fyrchik commented

2023-10-12 12:57:41 +00:00

Reduce time overhead for encoding log from ~300% to ~30%
Reduce allocations by infinity.

Also, fix a bug where SYSLOG_ fields were duplicated both in user message and in journald fields.

Here we try a bit different approach by providing encoder and sink, but using standard core.
Most of the optimizations are possible even with the current approach, let's discuss.
We are using zap, so I believe having 0 allocations is worth the effort.

goos: linux
goarch: amd64
pkg: git.frostfs.info/TrueCloudLab/zapjournald
cpu: 11th Gen Intel(R) Core(TM) i5-1135G7 @ 2.40GHz
                   │     out     │
                   │   sec/op    │
Log/standard-8       427.5n ± 1%
Log/journald-8       1.980µ ± 1%
Log/journald_new-8   554.6n ± 0%
geomean              777.1n

                   │      out       │
                   │      B/op      │
Log/standard-8         0.000 ± 0%
Log/journald-8       2.211Ki ± 0%
Log/journald_new-8     0.000 ± 0%
geomean                           ¹
¹ summaries must be >0 to compute geomean

                   │     out      │
                   │  allocs/op   │
Log/standard-8       0.000 ± 0%
Log/journald-8       31.00 ± 0%
Log/journald_new-8   0.000 ± 0%
geomean                         ¹
¹ summaries must be >0 to compute geomean

Reduce time overhead for encoding log from ~300% to ~30% Reduce allocations by infinity. Also, fix a bug where `SYSLOG_` fields were duplicated both in user message and in journald fields. Here we try a bit different approach by providing encoder and sink, but using standard core. Most of the optimizations are possible even with the current approach, let's discuss. We are using zap, so I believe having 0 allocations is worth the effort. ``` goos: linux goarch: amd64 pkg: git.frostfs.info/TrueCloudLab/zapjournald cpu: 11th Gen Intel(R) Core(TM) i5-1135G7 @ 2.40GHz │ out │ │ sec/op │ Log/standard-8 427.5n ± 1% Log/journald-8 1.980µ ± 1% Log/journald_new-8 554.6n ± 0% geomean 777.1n │ out │ │ B/op │ Log/standard-8 0.000 ± 0% Log/journald-8 2.211Ki ± 0% Log/journald_new-8 0.000 ± 0% geomean ¹ ¹ summaries must be >0 to compute geomean │ out │ │ allocs/op │ Log/standard-8 0.000 ± 0% Log/journald-8 31.00 ± 0% Log/journald_new-8 0.000 ± 0% geomean ¹ ¹ summaries must be >0 to compute geomean ```

fyrchik requested review from storage-core-developers 2023-10-12 12:57:52 +00:00

fyrchik requested review from storage-core-committers 2023-10-12 12:57:52 +00:00

fyrchik requested review from storage-services-committers 2023-10-12 12:57:52 +00:00

fyrchik requested review from storage-services-developers 2023-10-12 12:57:53 +00:00

fyrchik requested review from AlekseySVTN 2023-10-12 13:00:36 +00:00

dstepanov-yadro reviewed 2023-10-12 14:58:13 +00:00

encoder.go Outdated

					
				@ -0,0 +45,4 @@

				}

				func (e *journaldEncoder) Clone() zapcore.Encoder {

					return &journaldEncoder{Encoder: e.Encoder.Clone()}

dstepanov-yadro commented

2023-10-12 14:54:42 +00:00

Please explain why only the encoder is cloned? Why aren't the other fields (fields and buf) cloned?

👍 1

fyrchik commented

2023-10-13 07:27:12 +00:00

Because I wrote this like before adding buffers, will fix

fyrchik commented

2023-10-18 08:31:10 +00:00

removed this

fyrchik marked this conversation as resolved

vdomnich-yadro approved these changes 2023-10-12 16:19:25 +00:00

vdomnich-yadro left a comment

That's awesome stuff!

encoder.go Outdated

					
				@ -0,0 +32,4 @@

				var pool = buffer.NewPool()

				func newEncoder(cfg zapcore.EncoderConfig, fields ...field) *journaldEncoder {

					// FIXME (@fyrchik): We would like to accept any encoder here, but to prevent acidentally passing journald encoder.

vdomnich-yadro commented

2023-10-12 16:01:34 +00:00

acidentally -> accidentally

fyrchik commented

2023-10-18 08:30:54 +00:00

removed this

fyrchik marked this conversation as resolved

encoder.go Outdated

					
				@ -0,0 +73,4 @@

					}

				}

				func writeFieldBytes(w *buffer.Buffer, name string, value []byte) {

vdomnich-yadro commented

2023-10-12 16:05:42 +00:00

Let's probably stick with buf for buffer parameter name (as on line 68).

Let's probably stick with `buf` for buffer parameter name (as on line 68).

👍 1

fyrchik marked this conversation as resolved

encoder.go Outdated

					
				@ -0,0 +98,4 @@

						w.Write([]byte{'\n'})

						// 1 allocation here.

						// binary.Write(w, binary.LittleEndian, uint64(len(value)))

vdomnich-yadro commented

2023-10-12 16:06:35 +00:00

Let's remove commented code.

fyrchik commented

2023-10-13 13:50:19 +00:00

I wanted to keep the code from journal library for easier verification.

I wanted to keep the code from `journal` library for easier verification.

fyrchik force-pushed optimize-encoder from ca8f766274 to 2821b2e8f9

2023-10-13 07:07:29 +00:00

Compare

fyrchik force-pushed optimize-encoder from 2821b2e8f9 to ad30ad03a0

2023-10-13 08:36:13 +00:00

Compare

fyrchik force-pushed optimize-encoder from ad30ad03a0 to 7db0bb250b

2023-10-13 13:45:16 +00:00

Compare

fyrchik commented

2023-10-13 14:10:14 +00:00

Skip fields allow to optimize, but it looks hacky: we could always have Interface , but it is +1 allocation. Another option is to have ObjectMarshaler field set, should try this too.

`Skip` fields allow to optimize, but it looks hacky: we could always have `Interface` , but it is +1 allocation. Another option is to have `ObjectMarshaler` field set, should try this too.

fyrchik commented

2023-10-13 14:10:41 +00:00

Actual benchmark results:

goos: linux
goarch: amd64
pkg: git.frostfs.info/TrueCloudLab/zapjournald
cpu: 11th Gen Intel(R) Core(TM) i5-1135G7 @ 2.40GHz
                                     │     old      │                  3                  │
                                     │    sec/op    │   sec/op     vs base                │
Logger/standard/no_fields-8             435.9n ± 4%   441.9n ± 1%        ~ (p=0.436 n=10)
Logger/standard/application_fields-8    629.0n ± 8%   592.4n ± 1%   -5.83% (p=0.000 n=10)
Logger/standard/journald_fields-8       626.8n ± 5%   494.2n ± 1%  -21.16% (p=0.000 n=10)
Logger/journald/no_fields-8            2097.0n ± 3%   508.5n ± 1%  -75.75% (p=0.000 n=10)
Logger/journald/application_fields-8   2348.0n ± 5%   677.2n ± 0%  -71.16% (p=0.000 n=10)
Logger/journald/journald_fields-8      2395.5n ± 4%   634.6n ± 7%  -73.51% (p=0.000 n=10)
geomean                                 1.125µ        551.9n       -50.94%

                                     │      old       │                     3                      │
                                     │      B/op      │     B/op       vs base                     │
Logger/standard/no_fields-8              0.000 ± 0%       0.000 ±  0%         ~ (p=1.000 n=10) ¹
Logger/standard/application_fields-8     128.0 ± 0%       128.0 ±  0%         ~ (p=1.000 n=10) ¹
Logger/standard/journald_fields-8        64.00 ± 0%       64.00 ±  0%         ~ (p=1.000 n=10) ¹
Logger/journald/no_fields-8            2.210Ki ± 0%     0.000Ki ±  0%  -100.00% (p=0.000 n=10)
Logger/journald/application_fields-8    2551.0 ± 0%       128.0 ±  0%   -94.98% (p=0.000 n=10)
Logger/journald/journald_fields-8       2535.0 ± 0%       287.5 ± 78%   -88.66% (p=0.000 n=10)
geomean                                             ²                  ?                       ² ³
¹ all samples are equal
² summaries must be >0 to compute geomean
³ ratios must be >0 to compute geomean

                                     │      old      │                    3                    │
                                     │   allocs/op   │ allocs/op   vs base                     │
Logger/standard/no_fields-8             0.000 ± 0%     0.000 ± 0%         ~ (p=1.000 n=10) ¹
Logger/standard/application_fields-8    1.000 ± 0%     1.000 ± 0%         ~ (p=1.000 n=10) ¹
Logger/standard/journald_fields-8       1.000 ± 0%     1.000 ± 0%         ~ (p=1.000 n=10) ¹
Logger/journald/no_fields-8             31.00 ± 0%      0.00 ± 0%  -100.00% (p=0.000 n=10)
Logger/journald/application_fields-8   32.000 ± 0%     1.000 ± 0%   -96.88% (p=0.000 n=10)
Logger/journald/journald_fields-8      33.000 ± 0%     1.000 ± 0%   -96.97% (p=0.000 n=10)
geomean                                            ²               ?                       ² ³
¹ all samples are equal
² summaries must be >0 to compute geomean
³ ratios must be >0 to compute geomean

Actual benchmark results: ``` goos: linux goarch: amd64 pkg: git.frostfs.info/TrueCloudLab/zapjournald cpu: 11th Gen Intel(R) Core(TM) i5-1135G7 @ 2.40GHz │ old │ 3 │ │ sec/op │ sec/op vs base │ Logger/standard/no_fields-8 435.9n ± 4% 441.9n ± 1% ~ (p=0.436 n=10) Logger/standard/application_fields-8 629.0n ± 8% 592.4n ± 1% -5.83% (p=0.000 n=10) Logger/standard/journald_fields-8 626.8n ± 5% 494.2n ± 1% -21.16% (p=0.000 n=10) Logger/journald/no_fields-8 2097.0n ± 3% 508.5n ± 1% -75.75% (p=0.000 n=10) Logger/journald/application_fields-8 2348.0n ± 5% 677.2n ± 0% -71.16% (p=0.000 n=10) Logger/journald/journald_fields-8 2395.5n ± 4% 634.6n ± 7% -73.51% (p=0.000 n=10) geomean 1.125µ 551.9n -50.94% │ old │ 3 │ │ B/op │ B/op vs base │ Logger/standard/no_fields-8 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ Logger/standard/application_fields-8 128.0 ± 0% 128.0 ± 0% ~ (p=1.000 n=10) ¹ Logger/standard/journald_fields-8 64.00 ± 0% 64.00 ± 0% ~ (p=1.000 n=10) ¹ Logger/journald/no_fields-8 2.210Ki ± 0% 0.000Ki ± 0% -100.00% (p=0.000 n=10) Logger/journald/application_fields-8 2551.0 ± 0% 128.0 ± 0% -94.98% (p=0.000 n=10) Logger/journald/journald_fields-8 2535.0 ± 0% 287.5 ± 78% -88.66% (p=0.000 n=10) geomean ² ? ² ³ ¹ all samples are equal ² summaries must be >0 to compute geomean ³ ratios must be >0 to compute geomean │ old │ 3 │ │ allocs/op │ allocs/op vs base │ Logger/standard/no_fields-8 0.000 ± 0% 0.000 ± 0% ~ (p=1.000 n=10) ¹ Logger/standard/application_fields-8 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ Logger/standard/journald_fields-8 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ Logger/journald/no_fields-8 31.00 ± 0% 0.00 ± 0% -100.00% (p=0.000 n=10) Logger/journald/application_fields-8 32.000 ± 0% 1.000 ± 0% -96.88% (p=0.000 n=10) Logger/journald/journald_fields-8 33.000 ± 0% 1.000 ± 0% -96.97% (p=0.000 n=10) geomean ² ? ² ³ ¹ all samples are equal ² summaries must be >0 to compute geomean ³ ratios must be >0 to compute geomean ```

dstepanov-yadro approved these changes 2023-10-13 14:10:48 +00:00

fyrchik force-pushed optimize-encoder from 7db0bb250b to 028c873de4

2023-10-13 14:29:26 +00:00

Compare

fyrchik force-pushed optimize-encoder from 028c873de4 to 1eb6e99148

2023-10-13 17:43:19 +00:00

Compare

fyrchik force-pushed optimize-encoder from 1eb6e99148 to 8c785a966e

2023-10-13 18:11:45 +00:00

Compare

acid-ant approved these changes 2023-10-17 15:12:05 +00:00

fyrchik force-pushed optimize-encoder from 8c785a966e to a9e1aa74f7

2023-10-18 08:19:51 +00:00

Compare

fyrchik referenced this pull request

2023-10-18 08:25:15 +00:00

Think about more optimal field processing #14

fyrchik commented

2023-10-18 08:26:22 +00:00

With my scheme we cannot currently support all requirements. So let's make this PR do the first 80% of the optimizations and have some correctness fixes. Let's discuss the other 20% in #14

With my scheme we cannot currently support all requirements. So let's make this PR do the first 80% of the optimizations and have some correctness fixes. Let's discuss the other 20% in https://git.frostfs.info/TrueCloudLab/zapjournald/issues/14

fyrchik force-pushed optimize-encoder from a9e1aa74f7 to 2b6d84de9a

2023-10-18 08:30:33 +00:00

Compare

alexvanin approved these changes 2023-10-19 06:26:55 +00:00

aarifullin approved these changes 2023-10-19 12:20:37 +00:00

fyrchik merged commit 2b6d84de9a into master

2023-10-19 15:33:29 +00:00

fyrchik deleted branch optimize-encoder

2023-10-19 15:33:30 +00:00

fyrchik referenced this pull request from a commit

2023-10-19 15:33:31 +00:00

[#12] Add benchmarks