Race in slog text handler #50450
Assignees
Labels
Comments
rosstimothy
added a commit
that referenced
this issue
Dec 19, 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 issue
Dec 19, 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 issue
Dec 19, 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 issue
Dec 19, 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 issue
Dec 19, 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 issue
Dec 19, 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 issue
Dec 19, 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 issue
Dec 19, 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 issue
Dec 19, 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 ```
github-merge-queue bot
pushed a commit
that referenced
this issue
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 issue
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 issue
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 issue
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 issue
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
CI caught a race in the slog text handlers group handling:
https://github.com/gravitational/teleport/actions/runs/12410421297/job/34646019797?pr=50429
The text was updated successfully, but these errors were encountered: