logstats: do not allocate memory while logging #15539
Conversation
Review ChecklistHello reviewers! 👋 Please follow this checklist when reviewing this Pull Request. General
Tests
Documentation
New flags
If a workflow is added or modified:
Backward compatibility
|
vitess-bot
bot
added
NeedsBackportReason
vmg
added
Component: Query Serving
Type: Performance
Benchmark me
|
Hello! 👋 This Pull Request is now handled by arewefastyet. The current HEAD and future commits will be benchmarked. You can find the performance comparison on the arewefastyet website. |
Codecov ReportAttention: Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## main #15539 +/- ##
==========================================
- Coverage 67.41% 65.76% -1.66%
==========================================
Files 1560 1561 +1
Lines 192752 194710 +1958
==========================================
- Hits 129952 128057 -1895
- Misses 62800 66653 +3853 ☔ View full report in Codecov by Sentry. |
vmg
requested review from
harshit-gangal,
systay,
shlomi-noach,
rohit-nayak-ps,
frouioui,
GuptaManan100 and
deepthi
as code owners
There was a problem hiding this comment.
LGTM, well done.
For JSON there is the experimental json/v2 under development at https://github.com/go-json-experiment/json which may make some of the JSON token construction easier.
But since logic supports both JSON and some kind of plaintext format, I have no objections to keeping it as is.
| BVar *querypb.BindVariable | ||
| } | ||
|
|
||
| type Logger struct { |
There was a problem hiding this comment.
maybe a line or two with the raison d'etre for this logger?
| @@ -0,0 +1,130 @@ | |||
| package dml | |||
Signed-off-by: Vicent Marti <vmg@strn.cat>
Signed-off-by: Vicent Marti <vmg@strn.cat> Signed-off-by: Vilius Okockis <vilius.okockis@vinted.com>
Description
This is the first PR in a series dedicated to taming the CPU and memory usage of
vttabletinstances. The effort here is based off profiling and behavior data from PlanetScale customers that run particularly large and busy Vitess clusters. Many of these results do not reproduce in synthetic benchmarks.For this first low hanging fruit, I've noticed that a disproportionate amount of CPU time and allocations is spent logging queries as part of the
logstatssystem. Let's start from the finish line and look at before/after graphs and metrics.Flame graph for CPU usage (before vs after)
These are CPU flame graphs for the
vttabletin synthetic stress benchmark. This result reproduces very well regardless of the QPS/throughput of the Vitess cluster. The amount of time spent logging is always disproportionate.The time spent in
logstatsis marked with a red square in both graphs. Important detail: although the CPU usage for the subsystem was disproportionate, I've only highlighted in this flamegraph the direct CPU impact of logging. The indirect impact caused by the extreme amount of small allocations cannot be clearly highlighted here but it'll become apparent in the metrics.Flame graph for object allocation count (before vs after)
Here we display the object allocation count for the
vttablet(before and after). I've skipped the total memory allocated flamegraph because it looks very similar. As you can see, this one is particularly disproportionate: up to one third of all object allocations during normal execution of avttabletis spent on temporary objects to compose these log messages.The reduction in the "after" flamegraph is extremely significant.
Benchmark results
For this set of PRs, I've chosen to skip
arewefastyetaltogether and instead use a custom harness instead. There's several reasons for this: First and foremost, we're having significant replication issues with the platform which @frouioui is actively working on fixing. Also, the OLTP and TPCC benchmarks that currently run in the platform do not model particularly well the traffic of the busiest Vitess clusters we've seen in production. Lastly, the platform right now does not measure some of the metrics which we're interested in, such as total CPU time spent in GC.Anyway, onto the results analysis: it looks very good. The key metrics here are the reduction in memory allocations per second and object allocations per second in both the tablets and the gates (up to -35% fewer objects allocated per second after this change). The other key result is reduction in CPU seconds spent in GC for the tablets, which is down 10%. There's also a corresponding and very nice reduction in CPU time spent in user code because the new
logstatslogger is plain faster, but I think the major and significant impact here is GC time.The new implementation
To accomplish these results, I've implemented a new zero-allocation logger for
logstats. Thelogstatsfunctionality is currently used in both the gates and the tablets (whilst tracking slightly different metrics), but the performance impact appears to be much more significant in the tablets. Regardless, I've unified the two implementations, which is why the benchmark metrics also show improvements on the tablets.For the new logger interface, I've tried to balance ergonomics and performance, although this is code that won't change often. I think the new implementation is frankly more readable than the old one! I've also paid special attention to backwards compatibility to ensure the logging results are equivalent.
There's only one exception to this: the printing of bind variables in the logstats. For the textual logstats output, the bind variables were printed in a very peculiar way:
fmt.Sprintf("%v", bvars). The resulting syntax of this print expression is neither stable nor parseable, so it seemed futile to try to replicate it. Instead, I've chosen to print the bind variables as JSON in both textual and JSON logstat output, because this is a stable format that can always be parsed. I've also fixed a bug in the previous version of the JSON bind-variable printer, where the variables were not consistently sorted when printing.Lastly, as part of the unified logger path, I'm storing the loggers in a sync pool which is not exposed directly via the public interface but which allows for transparently re-using the logging buffer between logging calls.
Related Issue(s)
Checklist
Deployment Notes