sdk/log: Optimize BatchProcessor

[pellared]

Benchmarks: https://github.com/pellared/spanevents-vs-logs

Batch processing in Logs SDK seems like a bottleneck.

Reproduction:

git clone https://github.com/pellared/spanevents-vs-logs.git
cd spanevents-vs-logs
make up

wait some time to make sure OTel Collector is ready

go test -run=^$ -bench=BenchmarkLogs/OTLP -cpuprofile profile.out.txt
make down

profile.out.txt

[pellared]

Output from benchmarks that emit a single log record vs span.

goos: linux
goarch: amd64
pkg: github.com/pellared/spanevents-vs-logs
cpu: 13th Gen Intel(R) Core(TM) i7-13800H
BenchmarkSpan/OTLP-20            1592239               731.4 ns/op           978 B/op          3 allocs/op
BenchmarkSpan/STDOUT-20          1000000              1270 ns/op            1051 B/op          5 allocs/op
BenchmarkSpan/NOOP-20            4216621               258.7 ns/op           240 B/op          3 allocs/op
BenchmarkLog/OTLP-20              621262             12069 ns/op            1267 B/op          6 allocs/op
BenchmarkLog/STDOUT-20            186285              7985 ns/op            2324 B/op         33 allocs/op
BenchmarkLog/NOOP-20            100000000               11.13 ns/op            0 B/op          0 allocs/op

go test -run=^$ -bench=BenchmarkLog/OTLP -cpuprofile profile-log.out.txt

profile-log.out.txt

[sreenath-tm]

Hi @pellared , I would like to contribute to the issue. This is my first time contributing to Otel so what would be a good starting point to approach this issue?

[pellared]

Hi @sreenath-tm,

This issue is most probably very difficult to solve.
I am mostly concerned about BenchmarkSpan/OTLP-20 vs BenchmarkLog/OTLP-20.

what would be a good starting point to approach this issue?

I am not sure what exactly you have in mind given I have provided the repro steps.
How to improve the performance? I do not know. There are whole books on improving performance in Go.

[wmdanor]

Hey, I see that someone already left the comment about picking it up, I cloned the repo and started occasionally trying things out without big hopes around 2 weeks ago, so did not see it, so it might not be needed anymore, but I think I was able to achieve significant improvement.

I noticed that huge amount of perf was lost because of log record copying as they are passed by values instead of pointers (while spans are passed by ptrs), even though OnEmit in processor accepts record pointer. So I refactored everything downstream to use records pointers, hence it also changed the API for log Exporter, so not sure if this is acceptable change. It improved performance, but not by much (less than 2 times).

Then, I saw that sdklog.ring which was used for queue in batch processor was eating noticeable amount of time, so I thought I could try to refactor it to cyclical array queue. At first it did not work (worked, but it was ~10% improvement), and the TryDequeue was still the problem. But today I just tried using builtin.copy instead of copying everything to provided buffer manually in a loop and the result was great. Now otlp logs bench was just ~3 times slower (base ~67 times) per op than span events. And also allocated less memory.

I have created draft PR in my fork, @pellared can you please take a look and tell if something like this can be acceptable solution or not? Note: it really is a draft with some unnecessary commented code and left out unneeded code fragments remaining from my work. I will clean all this up and create PR in this repo, if at least the concept will be accepted.

Benchmarks (OTLP)

Base

go tool benchstat spanevents.out logs.out
goos: linux
goarch: amd64
pkg: github.com/pellared/spanevents-vs-logs
cpu: AMD Ryzen 9 7900X 12-Core Processor
         │ spanevents.out │                 logs.out                 │
         │     sec/op     │     sec/op      vs base                  │
/OTLP-24      43.58µ ± 6%   2977.49µ ± 10%  +6731.84% (p=0.000 n=10)

         │ spanevents.out │               logs.out                │
         │      B/op      │     B/op       vs base                │
/OTLP-24     99.47Ki ± 5%   193.25Ki ± 1%  +94.29% (p=0.000 n=10)

         │ spanevents.out │               logs.out               │
         │   allocs/op    │  allocs/op   vs base                 │
/OTLP-24      710.0 ± 12%   1861.0 ± 2%  +162.11% (p=0.000 n=10)

Pointer

go tool benchstat spanevents.out logs.out
goos: linux
goarch: amd64
pkg: github.com/pellared/spanevents-vs-logs
cpu: AMD Ryzen 9 7900X 12-Core Processor
         │ spanevents.out │                 logs.out                 │
         │     sec/op     │     sec/op      vs base                  │
/OTLP-24      43.58µ ± 6%   1617.18µ ± 25%  +3610.63% (p=0.000 n=10)

         │ spanevents.out │                logs.out                │
         │      B/op      │      B/op       vs base                │
/OTLP-24     99.47Ki ± 5%   148.22Ki ± 28%  +49.01% (p=0.002 n=10)

         │ spanevents.out │               logs.out               │
         │   allocs/op    │  allocs/op    vs base                │
/OTLP-24      710.0 ± 12%   1196.5 ± 56%  +68.52% (p=0.023 n=10)

Pointer Array Queue (manual copy in dequeue)

go tool benchstat spanevents.out logs.out
goos: linux
goarch: amd64
pkg: github.com/pellared/spanevents-vs-logs
cpu: AMD Ryzen 9 7900X 12-Core Processor
         │ spanevents.out │                logs.out                 │
         │     sec/op     │    sec/op      vs base                  │
/OTLP-24      43.58µ ± 6%   1315.50µ ± 4%  +2918.42% (p=0.000 n=10)

         │ spanevents.out │               logs.out                │
         │      B/op      │     B/op       vs base                │
/OTLP-24     99.47Ki ± 5%   139.32Ki ± 2%  +40.07% (p=0.000 n=10)

         │ spanevents.out │              logs.out               │
         │   allocs/op    │  allocs/op   vs base                │
/OTLP-24      710.0 ± 12%   1056.0 ± 3%  +48.73% (p=0.000 n=10)

Pointer Array Queue

go tool benchstat spanevents.out logs.out
goos: linux
goarch: amd64
pkg: github.com/pellared/spanevents-vs-logs
cpu: AMD Ryzen 9 7900X 12-Core Processor
         │ spanevents.out │               logs.out                │
         │     sec/op     │    sec/op     vs base                 │
/OTLP-24      42.44µ ± 7%   178.70µ ± 4%  +321.08% (p=0.000 n=10)

         │ spanevents.out │            logs.out            │
         │      B/op      │     B/op      vs base          │
/OTLP-24     99.34Ki ± 3%   98.13Ki ± 3%  ~ (p=0.280 n=10)

         │ spanevents.out │              logs.out               │
         │   allocs/op    │  allocs/op   vs base                │
/OTLP-24       707.0 ± 7%   400.0 ± 11%  -43.42% (p=0.000 n=10)

Bench (all)

go test -run=^$ -bench=. -benchmem
goos: linux
goarch: amd64
pkg: github.com/pellared/spanevents-vs-logs
cpu: AMD Ryzen 9 7900X 12-Core Processor
BenchmarkSpan/OTLP-24            2366409               495.5 ns/op           962 B/op          3 allocs/op
BenchmarkSpan/STDOUT-24          2176042               527.2 ns/op          1059 B/op          5 allocs/op
BenchmarkSpan/NOOP-24           11895832                88.96 ns/op          240 B/op          3 allocs/op
BenchmarkLog/OTLP-24             1917961               611.8 ns/op           942 B/op          3 allocs/op
BenchmarkLog/STDOUT-24           1647330               716.3 ns/op          1090 B/op          6 allocs/op
BenchmarkLog/NOOP-24            136179979                8.803 ns/op           0 B/op          0 allocs/op
BenchmarkSpanEvents/OTLP-24                27658             42702 ns/op          109553 B/op        854 allocs/op
BenchmarkSpanEvents/STDOUT-24              30069             39874 ns/op           93007 B/op        641 allocs/op
BenchmarkSpanEvents/NOOP-24                82713             14019 ns/op           29840 B/op        303 allocs/op
BenchmarkLogs/OTLP-24                       6744            176597 ns/op           97971 B/op        360 allocs/op
BenchmarkLogs/STDOUT-24                     5911            215967 ns/op          154461 B/op       1697 allocs/op
BenchmarkLogs/NOOP-24                     265395              4382 ns/op             240 B/op          3 allocs/op
PASS
ok      github.com/pellared/spanevents-vs-logs  30.732s

go tool benchstat spanevents.out logs.out
goos: linux
goarch: amd64
pkg: github.com/pellared/spanevents-vs-logs
cpu: AMD Ryzen 9 7900X 12-Core Processor
           │ spanevents.out │               logs.out                │
           │     sec/op     │    sec/op     vs base                 │
/OTLP-24        44.22µ ± 3%   187.59µ ± 4%  +324.19% (p=0.000 n=10)
/STDOUT-24      40.65µ ± 3%   186.79µ ± 4%  +359.53% (p=0.000 n=10)
/NOOP-24       13.825µ ± 3%    4.346µ ± 1%   -68.57% (p=0.000 n=10)
geomean         29.18µ         53.40µ        +82.99%

           │ spanevents.out │               logs.out                │
           │      B/op      │     B/op       vs base                │
/OTLP-24       99.72Ki ± 7%    97.90Ki ± 1%   -1.82% (p=0.000 n=10)
/STDOUT-24     91.00Ki ± 0%   145.70Ki ± 1%  +60.12% (p=0.000 n=10)
/NOOP-24       29840.0 ± 0%      240.0 ± 0%  -99.20% (p=0.000 n=10)
geomean        64.19Ki         14.95Ki       -76.70%

           │ spanevents.out │               logs.out               │
           │   allocs/op    │  allocs/op   vs base                 │
/OTLP-24        714.5 ± 19%    396.5 ± 3%   -44.51% (p=0.000 n=10)
/STDOUT-24      647.5 ±  1%   1581.0 ± 2%  +144.17% (p=0.000 n=10)
/NOOP-24      303.000 ±  0%    3.000 ± 0%   -99.01% (p=0.000 n=10)
geomean         519.5          123.4        -76.24%

[pellared]

@wmdanor , first of all thanks a lot for looking at it and providing that much information.

I just made a quick look and the changes look good. I propose to split it into multiple PRs (one for each performance improvement). Each PR should provide have in it's description a benchstat of existing benchmarks or new ones if existing are not enough to show the improvements. Doing it in many steps (PRs) would make it easier to review and discuss each improvement separately.

Side note: I suspected that using pointers would improve the performance. However, the "reimplementation" of ring buffer (cqueue) is amazing.

CC @MrAlias

[wmdanor]

@pellared thanks for the quick feedback, I will start cleaning up the code and splitting it into few PRs then.

[pellared]

@pellared thanks for the quick feedback, I will start cleaning up the code and splitting it into few PRs then.

Thanks! Having this draft PR cleaned up and used as a reference (prior art) will also help in reviews.