Fix: prevent race in slog text handler group handling #50451
Merged
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
rosstimothy
commented
Dec 19, 2024
There was a problem hiding this comment.
The contents of this file are not new, they were moved from slog_handler.go which was deleted.
rosstimothy
commented
Dec 19, 2024
There was a problem hiding this comment.
The contents of this file are not new, they were moved from slog_handler.go which was deleted.
|
This pull request is automatically being deployed by Amplify Hosting (learn more). |
rosstimothy
force-pushed
the
tross/slog_text_handler_groups
branch
6 times, most recently
from
91de9a4 to
74d744d
Compare
Closes #50450. This updates our custom slog text handler to take heavier inspiration from the slog.TextHandler. A variant of handleState used by the slog.TextHandler has been vendored and modified to produce the same output as our custom logrus formatter. Offloading formatting from the SlogTextHandler directly to handleState prevents the race caused in #50450. Additionally, some quality of life improvements were added by moving some code around to reduce file sizes and better define what belongs in a file. Benchmarks indicate that the changes here don't move the needle much. ``` goos: darwin goarch: arm64 pkg: github.com/gravitational/teleport/lib/utils/log cpu: Apple M2 Pro │ old.txt │ new.txt │ │ sec/op │ sec/op vs base │ Formatter/logrus/text-12 8.665µ ± 16% 8.187µ ± 9% ~ (p=0.280 n=10) Formatter/logrus/json-12 8.879µ ± 2% 8.820µ ± 1% ~ (p=0.089 n=10) Formatter/slog/default_text-12 3.936µ ± 3% 3.946µ ± 4% ~ (p=0.839 n=10) Formatter/slog/text-12 3.789µ ± 2% 3.431µ ± 1% -9.45% (p=0.000 n=10) Formatter/slog/default_json-12 3.005µ ± 4% 3.032µ ± 3% ~ (p=0.739 n=10) Formatter/slog/json-12 3.029µ ± 6% 3.022µ ± 1% ~ (p=0.381 n=10) geomean 4.675µ 4.557µ -2.52% │ old.txt │ new.txt │ │ B/op │ B/op vs base │ Formatter/logrus/text-12 5.936Ki ± 0% 5.936Ki ± 0% ~ (p=0.752 n=10) Formatter/logrus/json-12 6.212Ki ± 0% 6.211Ki ± 0% ~ (p=0.752 n=10) Formatter/slog/default_text-12 2.534Ki ± 0% 2.534Ki ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/text-12 2.144Ki ± 0% 2.167Ki ± 0% +1.09% (p=0.000 n=10) Formatter/slog/default_json-12 2.448Ki ± 0% 2.448Ki ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/json-12 2.318Ki ± 0% 2.318Ki ± 0% ~ (p=1.000 n=10) ¹ geomean 3.231Ki 3.236Ki +0.18% ¹ all samples are equal │ old.txt │ new.txt │ │ allocs/op │ allocs/op vs base │ Formatter/logrus/text-12 54.00 ± 0% 54.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/logrus/json-12 76.00 ± 0% 76.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/default_text-12 41.00 ± 0% 41.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/text-12 52.00 ± 0% 33.00 ± 0% -36.54% (p=0.000 n=10) Formatter/slog/default_json-12 41.00 ± 0% 41.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/json-12 42.00 ± 0% 42.00 ± 0% ~ (p=1.000 n=10) ¹ geomean 49.70 46.07 -7.30% ¹ all samples are equal ```
rosstimothy
force-pushed
the
tross/slog_text_handler_groups
branch
from
74d744d to
fffd058
Compare
rosstimothy
added
no-changelog
strideynet
approved these changes
Dec 20, 2024
marcoandredinis
approved these changes
Dec 20, 2024
public-teleport-github-review-bot
bot
removed the request for review
from zmb3
|
@rosstimothy See the table below for backport results.
|
rosstimothy
added a commit
that referenced
this pull request
Dec 20, 2024
Closes #50450. This updates our custom slog text handler to take heavier inspiration from the slog.TextHandler. A variant of handleState used by the slog.TextHandler has been vendored and modified to produce the same output as our custom logrus formatter. Offloading formatting from the SlogTextHandler directly to handleState prevents the race caused in #50450. Additionally, some quality of life improvements were added by moving some code around to reduce file sizes and better define what belongs in a file. Benchmarks indicate that the changes here don't move the needle much. ``` goos: darwin goarch: arm64 pkg: github.com/gravitational/teleport/lib/utils/log cpu: Apple M2 Pro │ old.txt │ new.txt │ │ sec/op │ sec/op vs base │ Formatter/logrus/text-12 8.665µ ± 16% 8.187µ ± 9% ~ (p=0.280 n=10) Formatter/logrus/json-12 8.879µ ± 2% 8.820µ ± 1% ~ (p=0.089 n=10) Formatter/slog/default_text-12 3.936µ ± 3% 3.946µ ± 4% ~ (p=0.839 n=10) Formatter/slog/text-12 3.789µ ± 2% 3.431µ ± 1% -9.45% (p=0.000 n=10) Formatter/slog/default_json-12 3.005µ ± 4% 3.032µ ± 3% ~ (p=0.739 n=10) Formatter/slog/json-12 3.029µ ± 6% 3.022µ ± 1% ~ (p=0.381 n=10) geomean 4.675µ 4.557µ -2.52% │ old.txt │ new.txt │ │ B/op │ B/op vs base │ Formatter/logrus/text-12 5.936Ki ± 0% 5.936Ki ± 0% ~ (p=0.752 n=10) Formatter/logrus/json-12 6.212Ki ± 0% 6.211Ki ± 0% ~ (p=0.752 n=10) Formatter/slog/default_text-12 2.534Ki ± 0% 2.534Ki ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/text-12 2.144Ki ± 0% 2.167Ki ± 0% +1.09% (p=0.000 n=10) Formatter/slog/default_json-12 2.448Ki ± 0% 2.448Ki ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/json-12 2.318Ki ± 0% 2.318Ki ± 0% ~ (p=1.000 n=10) ¹ geomean 3.231Ki 3.236Ki +0.18% ¹ all samples are equal │ old.txt │ new.txt │ │ allocs/op │ allocs/op vs base │ Formatter/logrus/text-12 54.00 ± 0% 54.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/logrus/json-12 76.00 ± 0% 76.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/default_text-12 41.00 ± 0% 41.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/text-12 52.00 ± 0% 33.00 ± 0% -36.54% (p=0.000 n=10) Formatter/slog/default_json-12 41.00 ± 0% 41.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/json-12 42.00 ± 0% 42.00 ± 0% ~ (p=1.000 n=10) ¹ geomean 49.70 46.07 -7.30% ¹ all samples are equal ```
rosstimothy
added a commit
that referenced
this pull request
Dec 20, 2024
Closes #50450. This updates our custom slog text handler to take heavier inspiration from the slog.TextHandler. A variant of handleState used by the slog.TextHandler has been vendored and modified to produce the same output as our custom logrus formatter. Offloading formatting from the SlogTextHandler directly to handleState prevents the race caused in #50450. Additionally, some quality of life improvements were added by moving some code around to reduce file sizes and better define what belongs in a file. Benchmarks indicate that the changes here don't move the needle much. ``` goos: darwin goarch: arm64 pkg: github.com/gravitational/teleport/lib/utils/log cpu: Apple M2 Pro │ old.txt │ new.txt │ │ sec/op │ sec/op vs base │ Formatter/logrus/text-12 8.665µ ± 16% 8.187µ ± 9% ~ (p=0.280 n=10) Formatter/logrus/json-12 8.879µ ± 2% 8.820µ ± 1% ~ (p=0.089 n=10) Formatter/slog/default_text-12 3.936µ ± 3% 3.946µ ± 4% ~ (p=0.839 n=10) Formatter/slog/text-12 3.789µ ± 2% 3.431µ ± 1% -9.45% (p=0.000 n=10) Formatter/slog/default_json-12 3.005µ ± 4% 3.032µ ± 3% ~ (p=0.739 n=10) Formatter/slog/json-12 3.029µ ± 6% 3.022µ ± 1% ~ (p=0.381 n=10) geomean 4.675µ 4.557µ -2.52% │ old.txt │ new.txt │ │ B/op │ B/op vs base │ Formatter/logrus/text-12 5.936Ki ± 0% 5.936Ki ± 0% ~ (p=0.752 n=10) Formatter/logrus/json-12 6.212Ki ± 0% 6.211Ki ± 0% ~ (p=0.752 n=10) Formatter/slog/default_text-12 2.534Ki ± 0% 2.534Ki ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/text-12 2.144Ki ± 0% 2.167Ki ± 0% +1.09% (p=0.000 n=10) Formatter/slog/default_json-12 2.448Ki ± 0% 2.448Ki ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/json-12 2.318Ki ± 0% 2.318Ki ± 0% ~ (p=1.000 n=10) ¹ geomean 3.231Ki 3.236Ki +0.18% ¹ all samples are equal │ old.txt │ new.txt │ │ allocs/op │ allocs/op vs base │ Formatter/logrus/text-12 54.00 ± 0% 54.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/logrus/json-12 76.00 ± 0% 76.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/default_text-12 41.00 ± 0% 41.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/text-12 52.00 ± 0% 33.00 ± 0% -36.54% (p=0.000 n=10) Formatter/slog/default_json-12 41.00 ± 0% 41.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/json-12 42.00 ± 0% 42.00 ± 0% ~ (p=1.000 n=10) ¹ geomean 49.70 46.07 -7.30% ¹ all samples are equal ```
rosstimothy
added a commit
that referenced
this pull request
Dec 20, 2024
Closes #50450. This updates our custom slog text handler to take heavier inspiration from the slog.TextHandler. A variant of handleState used by the slog.TextHandler has been vendored and modified to produce the same output as our custom logrus formatter. Offloading formatting from the SlogTextHandler directly to handleState prevents the race caused in #50450. Additionally, some quality of life improvements were added by moving some code around to reduce file sizes and better define what belongs in a file. Benchmarks indicate that the changes here don't move the needle much. ``` goos: darwin goarch: arm64 pkg: github.com/gravitational/teleport/lib/utils/log cpu: Apple M2 Pro │ old.txt │ new.txt │ │ sec/op │ sec/op vs base │ Formatter/logrus/text-12 8.665µ ± 16% 8.187µ ± 9% ~ (p=0.280 n=10) Formatter/logrus/json-12 8.879µ ± 2% 8.820µ ± 1% ~ (p=0.089 n=10) Formatter/slog/default_text-12 3.936µ ± 3% 3.946µ ± 4% ~ (p=0.839 n=10) Formatter/slog/text-12 3.789µ ± 2% 3.431µ ± 1% -9.45% (p=0.000 n=10) Formatter/slog/default_json-12 3.005µ ± 4% 3.032µ ± 3% ~ (p=0.739 n=10) Formatter/slog/json-12 3.029µ ± 6% 3.022µ ± 1% ~ (p=0.381 n=10) geomean 4.675µ 4.557µ -2.52% │ old.txt │ new.txt │ │ B/op │ B/op vs base │ Formatter/logrus/text-12 5.936Ki ± 0% 5.936Ki ± 0% ~ (p=0.752 n=10) Formatter/logrus/json-12 6.212Ki ± 0% 6.211Ki ± 0% ~ (p=0.752 n=10) Formatter/slog/default_text-12 2.534Ki ± 0% 2.534Ki ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/text-12 2.144Ki ± 0% 2.167Ki ± 0% +1.09% (p=0.000 n=10) Formatter/slog/default_json-12 2.448Ki ± 0% 2.448Ki ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/json-12 2.318Ki ± 0% 2.318Ki ± 0% ~ (p=1.000 n=10) ¹ geomean 3.231Ki 3.236Ki +0.18% ¹ all samples are equal │ old.txt │ new.txt │ │ allocs/op │ allocs/op vs base │ Formatter/logrus/text-12 54.00 ± 0% 54.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/logrus/json-12 76.00 ± 0% 76.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/default_text-12 41.00 ± 0% 41.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/text-12 52.00 ± 0% 33.00 ± 0% -36.54% (p=0.000 n=10) Formatter/slog/default_json-12 41.00 ± 0% 41.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/json-12 42.00 ± 0% 42.00 ± 0% ~ (p=1.000 n=10) ¹ geomean 49.70 46.07 -7.30% ¹ all samples are equal ```
rosstimothy
added a commit
that referenced
this pull request
Dec 20, 2024
Closes #50450. This updates our custom slog text handler to take heavier inspiration from the slog.TextHandler. A variant of handleState used by the slog.TextHandler has been vendored and modified to produce the same output as our custom logrus formatter. Offloading formatting from the SlogTextHandler directly to handleState prevents the race caused in #50450. Additionally, some quality of life improvements were added by moving some code around to reduce file sizes and better define what belongs in a file. Benchmarks indicate that the changes here don't move the needle much. ``` goos: darwin goarch: arm64 pkg: github.com/gravitational/teleport/lib/utils/log cpu: Apple M2 Pro │ old.txt │ new.txt │ │ sec/op │ sec/op vs base │ Formatter/logrus/text-12 8.665µ ± 16% 8.187µ ± 9% ~ (p=0.280 n=10) Formatter/logrus/json-12 8.879µ ± 2% 8.820µ ± 1% ~ (p=0.089 n=10) Formatter/slog/default_text-12 3.936µ ± 3% 3.946µ ± 4% ~ (p=0.839 n=10) Formatter/slog/text-12 3.789µ ± 2% 3.431µ ± 1% -9.45% (p=0.000 n=10) Formatter/slog/default_json-12 3.005µ ± 4% 3.032µ ± 3% ~ (p=0.739 n=10) Formatter/slog/json-12 3.029µ ± 6% 3.022µ ± 1% ~ (p=0.381 n=10) geomean 4.675µ 4.557µ -2.52% │ old.txt │ new.txt │ │ B/op │ B/op vs base │ Formatter/logrus/text-12 5.936Ki ± 0% 5.936Ki ± 0% ~ (p=0.752 n=10) Formatter/logrus/json-12 6.212Ki ± 0% 6.211Ki ± 0% ~ (p=0.752 n=10) Formatter/slog/default_text-12 2.534Ki ± 0% 2.534Ki ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/text-12 2.144Ki ± 0% 2.167Ki ± 0% +1.09% (p=0.000 n=10) Formatter/slog/default_json-12 2.448Ki ± 0% 2.448Ki ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/json-12 2.318Ki ± 0% 2.318Ki ± 0% ~ (p=1.000 n=10) ¹ geomean 3.231Ki 3.236Ki +0.18% ¹ all samples are equal │ old.txt │ new.txt │ │ allocs/op │ allocs/op vs base │ Formatter/logrus/text-12 54.00 ± 0% 54.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/logrus/json-12 76.00 ± 0% 76.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/default_text-12 41.00 ± 0% 41.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/text-12 52.00 ± 0% 33.00 ± 0% -36.54% (p=0.000 n=10) Formatter/slog/default_json-12 41.00 ± 0% 41.00 ± 0% ~ (p=1.000 n=10) ¹ Formatter/slog/json-12 42.00 ± 0% 42.00 ± 0% ~ (p=1.000 n=10) ¹ geomean 49.70 46.07 -7.30% ¹ all samples are equal ```
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Closes #50450.
This updates our custom slog text handler to take heavier inspiration from the slog.TextHandler. A variant of handleState used by the slog.TextHandler has been vendored and modified to produce the same output as our custom logrus formatter. Offloading formatting from the SlogTextHandler directly to handleState prevents the race caused in #50450.
Additionally, some quality of life improvements were added by moving some code around to reduce file sizes and better define what belongs in a file.
Benchmarks indicate that the changes here don't move the needle much.