logstats: do not allocate memory while logging

[vmg]

Description

This is the first PR in a series dedicated to taming the CPU and memory usage of vttablet instances. 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 logstats system. 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 vttablet in 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 logstats is 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 a vttablet is spent on temporary objects to compose these log messages.

The reduction in the "after" flamegraph is extremely significant.

Benchmark results

              │ benchold.txt │             benchnew.txt             │
              │  UserCPU/s   │ UserCPU/s   vs base                  │
OLTP/vtgate-4     4.230 ± 1%   4.160 ± 0%  -1.66% (p=0.000 n=13+14)
OLTP/tablet-4     1.427 ± 0%   1.373 ± 1%  -3.75% (n=52+56)
geomean           2.457        2.390       -2.71%

              │ benchold.txt │             benchnew.txt             │
              │  IdleCPU/s   │ IdleCPU/s   vs base                  │
OLTP/vtgate-4     27.20 ± 0%   27.27 ± 0%  +0.23% (p=0.002 n=13+14)
OLTP/tablet-4     30.45 ± 0%   30.51 ± 0%       ~ (p=0.057 n=52+56)
geomean           28.78        28.84       +0.23%

              │ benchold.txt │             benchnew.txt              │
              │   GCCPU/s    │   GCCPU/s    vs base                  │
OLTP/vtgate-4    565.8m ± 1%   562.5m ± 1%       ~ (p=0.488 n=13+14)
OLTP/tablet-4    134.0m ± 1%   120.6m ± 1%  -9.97% (n=52+56)
geomean          275.3m        260.5m       -5.39%

              │ benchold.txt │              benchnew.txt               │
              │     KB/s     │     KB/s      vs base                   │
OLTP/vtgate-4    315.9k ± 9%   257.4k ± 14%  -18.50% (p=0.011 n=13+14)
OLTP/tablet-4    82.75k ± 4%   60.09k ± 10%  -27.39% (p=0.000 n=52+56)
geomean          161.7k        124.4k        -23.07%

              │ benchold.txt │              benchnew.txt               │
              │   allocs/s   │   allocs/s    vs base                   │
OLTP/vtgate-4    5.629M ± 9%   4.442M ± 14%  -21.09% (p=0.003 n=13+14)
OLTP/tablet-4    1.569M ± 4%   1.027M ± 10%  -34.55% (n=52+56)
geomean          2.972M        2.136M        -28.14%

For this set of PRs, I've chosen to skip arewefastyet altogether 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 logstats logger 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. The logstats functionality 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

• "Backport to:" labels have been added if this change should be back-ported to release branches
• If this change is to be back-ported to previous releases, a justification is included in the PR description
• Tests were added or are not required
• Did the new or modified tests pass consistently locally and on CI?
• Documentation was added or is not required

Deployment Notes

[vitess-bot]

Review Checklist

Hello reviewers! 👋 Please follow this checklist when reviewing this Pull Request.

General

• Ensure that the Pull Request has a descriptive title.
• Ensure there is a link to an issue (except for internal cleanup and flaky test fixes), new features should have an RFC that documents use cases and test cases.

Tests

• Bug fixes should have at least one unit or end-to-end test, enhancement and new features should have a sufficient number of tests.

Documentation

• Apply the release notes (needs details) label if users need to know about this change.
• New features should be documented.
• There should be some code comments as to why things are implemented the way they are.
• There should be a comment at the top of each new or modified test to explain what the test does.

New flags

• Is this flag really necessary?
• Flag names must be clear and intuitive, use dashes (-), and have a clear help text.

If a workflow is added or modified:

• Each item in Jobs should be named in order to mark it as required.
• If the workflow needs to be marked as required, the maintainer team must be notified.

Backward compatibility

• Protobuf changes should be wire-compatible.
• Changes to _vt tables and RPCs need to be backward compatible.
• RPC changes should be compatible with vitess-operator
• If a flag is removed, then it should also be removed from vitess-operator and arewefastyet, if used there.
• vtctl command output order should be stable and awk-able.

[vitess-bot]

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]

Codecov Report

Attention: Patch coverage is 98.57820% with 3 lines in your changes are missing coverage. Please review.

Project coverage is 65.76%. Comparing base (696fe0e) to head (925744b).
Report is 147 commits behind head on main.

❗ Current head 925744b differs from pull request most recent head c52fee6. Consider uploading reports for the commit c52fee6 to get more accurate results

Files	Patch %	Lines
go/logstats/logger.go	97.19%	3 Missing ⚠️

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.
📢 Have feedback on the report? Share it here.

[mdlayher]

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.

[systay]

maybe a line or two with the raison d'etre for this logger?

[systay]

license

[deepthi]

@mdlayher there's an open PR for json-v2. We should review that.