grafana
Improve `*deduplicatingSlice.ingest` performance
As in #4033 in the past hackathon I checked optimizations on Pyroscope ingester, and found a couple low hanging fruits that could speed up *deduplicatingSlice.ingest method.
The first thing I did was adding a benchmark for *PartitionWriter.WriteProfileSymbols which was showing as one of the methods consuming most CPU and memory. Armed with this, I eventually found out that *deduplicatingSlice.ingest stand out as one of the methods that could be improved in a relatively easy way.
The first was creating the rewritingMap with the most capacity it could hold. This already showed some gains in ~7% CPU and ~8% bytes/op reduction.
benchstat bench.pw-writeprofilesymbols-refactorbench.log bench.pw-writeprofilesymbols-rewritemapinitcap.log
goos: darwin
goarch: arm64
pkg: github.com/grafana/pyroscope/pkg/phlaredb/symdb
cpu: Apple M1 Pro
│ bench.pw-writeprofilesymbols-refactorbench.log │ bench.pw-writeprofilesymbols-rewritemapinitcap.log │
│ sec/op │ sec/op vs base │
PartitionWriter_WriteProfileSymbols-10 548.2µ ± 1% 509.8µ ± 1% -7.01% (p=0.000 n=20)
│ bench.pw-writeprofilesymbols-refactorbench.log │ bench.pw-writeprofilesymbols-rewritemapinitcap.log │
│ B/op │ B/op vs base │
PartitionWriter_WriteProfileSymbols-10 706.2Ki ± 0% 650.5Ki ± 0% -7.88% (p=0.000 n=20)
│ bench.pw-writeprofilesymbols-refactorbench.log │ bench.pw-writeprofilesymbols-rewritemapinitcap.log │
│ allocs/op │ allocs/op vs base │
PartitionWriter_WriteProfileSymbols-10 2.241k ± 0% 2.202k ± 0% -1.76% (p=0.000 n=20)
Next thing I did was noticing that when iterating over missing elements we were calling append on s.slice every time there was an element to add. By creating a temporary slice with an initial capacity of len(missing) and size 0 and appending to that one, the runtime doesn't have to regrow the slice (if needed) on every iteration, and it only checks capacity and regrows s.slice if needed outside the loop. This results in additional CPU and memory savings:
$ benchstat bench.pw-writeprofilesymbols-rewritemapinitcap.log bench.pw-writeprofilesymbols-misslice.log
goos: darwin
goarch: arm64
pkg: github.com/grafana/pyroscope/pkg/phlaredb/symdb
cpu: Apple M1 Pro
│ bench.pw-writeprofilesymbols-rewritemapinitcap.log │ bench.pw-writeprofilesymbols-misslice.log │
│ sec/op │ sec/op vs base │
PartitionWriter_WriteProfileSymbols-10 569.9µ ± 15% 545.6µ ± 1% -4.28% (p=0.013 n=20)
│ bench.pw-writeprofilesymbols-rewritemapinitcap.log │ bench.pw-writeprofilesymbols-misslice.log │
│ B/op │ B/op vs base │
PartitionWriter_WriteProfileSymbols-10 650.6Ki ± 0% 600.9Ki ± 0% -7.64% (p=0.000 n=20)
│ bench.pw-writeprofilesymbols-rewritemapinitcap.log │ bench.pw-writeprofilesymbols-misslice.log │
│ allocs/op │ allocs/op vs base │
PartitionWriter_WriteProfileSymbols-10 2.202k ± 0% 2.176k ± 0% -1.18% (p=0.000 n=20)
Overall, with all these changes applied, the benchmark comparison is close to 20% CPU and 15% memory:
$ benchstat bench.pw-writeprofilesymbols.log bench.pw-writeprofilesymbols-misslice.log
goos: darwin
goarch: arm64
pkg: github.com/grafana/pyroscope/pkg/phlaredb/symdb
cpu: Apple M1 Pro
│ bench.pw-writeprofilesymbols.log │ bench.pw-writeprofilesymbols-misslice.log │
│ sec/op │ sec/op vs base │
PartitionWriter_WriteProfileSymbols-10 629.1µ ± 9% 504.0µ ± 1% -19.89% (p=0.000 n=20)
│ bench.pw-writeprofilesymbols.log │ bench.pw-writeprofilesymbols-misslice.log │
│ B/op │ B/op vs base │
PartitionWriter_WriteProfileSymbols-10 706.2Ki ± 0% 600.8Ki ± 0% -14.92% (p=0.000 n=20)
│ bench.pw-writeprofilesymbols.log │ bench.pw-writeprofilesymbols-misslice.log │
│ allocs/op │ allocs/op vs base │
PartitionWriter_WriteProfileSymbols-10 2.241k ± 0% 2.176k ± 0% -2.90% (p=0.000 n=20)
Not too sure if you are aware, but using
-memprofile, you can also generate a profile of your micro benchmark to see how it performs line by line: (left is before this PR right is after)
Ah, yes! I used it locally and that's how I arrived to the ingest method.
I think the best benchmark test would, be to run pyroscope for 30 min with ingestion real profiles and compare its memory profiles before and after.
Ooh this would definitely be The Dream™. I'm going to apply your suggestion for refactoring the benchmark and then see how it affects the results I have.
Thanks for the review so far! 🫶
@simonswine applying your changes to the benchmark it runs ~13% faster with the original code, so I'm going to reorder the commits and run the benchmarks again to get more realistic results. I'll update the PR accordingly. Thanks!
I've found another thing that could be pre-initialized with a size that greatly affects the performance, and is the *deduplicatingSlice.lookup map (see here), however, that one is trickier to address because each usage of *deduplicatingSlice benefits better from different initial sizes of the lookup map, so I'm leaving out. Nevertheless, I thought it was worth mentioning.
🤔 there's a failing test on CI, IIUC due to a context cancelled. I've run make go/test locally and it's working, maybe it needs to re-run?
maybe it needs to re-run?
Yes some tests are flaky right now, sorry about that
@simonswine 👋🏽 any updates that I need to make to this? Last time CI failed because there were some flaky tests.
Thank you for the review and suggestions!! And I'll definitely be looking at those graphs 😬