Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

spanlogger: fix double logging of caller information #604

Merged
merged 9 commits into from
Oct 13, 2024

Conversation

charleskorn
Copy link
Contributor

@charleskorn charleskorn commented Oct 9, 2024

What this PR does:

This PR fixes an issue with the changes introduced in #547.

That PR added logging correct caller information for code that used SpanLogger, however, it would log both the correct caller as well as caller=spanlogger.go:xxx.

I incorrectly believed that github.com/go-kit/log would use the last value if multiple caller keys were logged for the same message. It turns out that is incorrect: if multiple duplicate keys are logged for the same message, both are included in the output.

The fix for this is to introduce a spanlogger.Caller that returns the correct caller information, ignoring any SpanLogger methods. It should be used in place of github.com/go-kit/log's Caller when creating the logger at application startup.

There is a small performance penalty (~1% additional latency for logging) when logging with spanlogger.Caller instead of Caller:

           │ SpanLoggerAwareCaller/with_go-kit's_Caller-10 │ SpanLoggerAwareCaller/with_dskit's_spanlogger.Caller-10 │
           │                    sec/op                     │              sec/op                vs base              │
output.txt                                     936.0n ± 1%                         945.1n ± 6%  +0.97% (p=0.015 n=6)

           │ SpanLoggerAwareCaller/with_go-kit's_Caller-10 │ SpanLoggerAwareCaller/with_dskit's_spanlogger.Caller-10 │
           │                     B/op                      │                  B/op                   vs base         │
output.txt                                      733.0 ± 1%                               735.0 ± 6%  ~ (p=0.143 n=6)

           │ SpanLoggerAwareCaller/with_go-kit's_Caller-10 │ SpanLoggerAwareCaller/with_dskit's_spanlogger.Caller-10 │
           │                   allocs/op                   │              allocs/op                vs base           │
output.txt                                      9.000 ± 0%                             9.000 ± 0%  ~ (p=1.000 n=6) ¹
¹ all samples are equal

This cost is only paid when a log line is actually logged, and not if the log line is filtered out (eg. if the log line is at debug level but the application is configured to emit info level and above, using spanlogger.Caller makes no difference).

This change also improves the performance of SpanLogger in general, as we no longer need to allocate a new spanLoggerAwareCaller for each instance. And the behaviour above when the log line is filtered also applies, which can be seen in the info_and_above_allowed/level.Debug benchmark below:

                                                               │ original.txt │             final.txt              │
                                                               │    sec/op    │   sec/op     vs base               │
SpanLoggerWithRealLogger/info_and_above_allowed/Log-10            1.941µ ± 1%   1.775µ ± 1%   -8.55% (p=0.002 n=6)
SpanLoggerWithRealLogger/info_and_above_allowed/level.Debug-10    570.3n ± 4%   161.8n ± 0%  -71.63% (p=0.002 n=6)
SpanLoggerWithRealLogger/info_and_above_allowed/DebugLog-10       2.865n ± 1%   2.911n ± 1%   +1.61% (p=0.006 n=6)
SpanLoggerWithRealLogger/all_levels_allowed/Log-10                1.941µ ± 2%   1.769µ ± 1%   -8.86% (p=0.002 n=6)
SpanLoggerWithRealLogger/all_levels_allowed/level.Debug-10        1.941µ ± 1%   2.656µ ± 3%  +36.84% (p=0.002 n=6)
SpanLoggerWithRealLogger/all_levels_allowed/DebugLog-10           2.231µ ± 1%   2.029µ ± 0%   -9.03% (p=0.002 n=6)
geomean                                                           546.5n        446.9n       -18.23%

                                                               │  original.txt   │               final.txt                │
                                                               │      B/op       │     B/op       vs base                 │
SpanLoggerWithRealLogger/info_and_above_allowed/Log-10            1072.0 ± 21%       952.0 ± 34%  -11.19% (p=0.013 n=6)
SpanLoggerWithRealLogger/info_and_above_allowed/level.Debug-10     720.0 ±  0%       400.0 ±  0%  -44.44% (p=0.002 n=6)
SpanLoggerWithRealLogger/info_and_above_allowed/DebugLog-10        0.000 ±  0%       0.000 ±  0%        ~ (p=1.000 n=6) ¹
SpanLoggerWithRealLogger/all_levels_allowed/Log-10                1072.0 ± 21%       952.0 ± 16%  -11.19% (p=0.011 n=6)
SpanLoggerWithRealLogger/all_levels_allowed/level.Debug-10       1.305Ki ±  0%     1.430Ki ±  0%   +9.58% (p=0.002 n=6)
SpanLoggerWithRealLogger/all_levels_allowed/DebugLog-10          1.312Ki ±  0%     1.133Ki ±  0%  -13.69% (p=0.002 n=6)
geomean                                                                        ²                  -13.66%               ²
¹ all samples are equal
² summaries must be >0 to compute geomean

                                                               │ original.txt  │              final.txt              │
                                                               │   allocs/op   │ allocs/op   vs base                 │
SpanLoggerWithRealLogger/info_and_above_allowed/Log-10            15.00 ± 0%     11.00 ± 0%  -26.67% (p=0.002 n=6)
SpanLoggerWithRealLogger/info_and_above_allowed/level.Debug-10   10.000 ± 0%     5.000 ± 0%  -50.00% (p=0.002 n=6)
SpanLoggerWithRealLogger/info_and_above_allowed/DebugLog-10       0.000 ± 0%     0.000 ± 0%        ~ (p=1.000 n=6) ¹
SpanLoggerWithRealLogger/all_levels_allowed/Log-10                15.00 ± 0%     11.00 ± 0%  -26.67% (p=0.002 n=6)
SpanLoggerWithRealLogger/all_levels_allowed/level.Debug-10        18.00 ± 0%     15.00 ± 0%  -16.67% (p=0.002 n=6)
SpanLoggerWithRealLogger/all_levels_allowed/DebugLog-10           17.00 ± 0%     13.00 ± 0%  -23.53% (p=0.002 n=6)
geomean                                                                      ²               -25.47%               ²
¹ all samples are equal
² summaries must be >0 to compute geomean

There is a regression in the all_levels_allowed/level.Debug benchmark, as now we need to read multiple stack frames for each log call. This is unavoidable, applications that are sensitive to this regression could use SpanLogger.DebugLog() rather than wrapping SpanLogger with level.Debug(...).

Which issue(s) this PR fixes:

(none)

Checklist

  • Tests updated
  • CHANGELOG.md updated - the order of entries should be [CHANGE], [FEATURE], [ENHANCEMENT], [BUGFIX]

@charleskorn
Copy link
Contributor Author

I'd like to investigate and understand the regression in the SpanLoggerWithRealLogger/all_levels_allowed/level.Debug benchmark, but I'm going to share this for feedback on the approach first.

…en SpanLogger

This makes the cost of spanlogger.Caller negligible for use outside of
SpanLogger:

                            │ SpanLoggerAwareCaller/with_go-kit's_Caller-10 │ SpanLoggerAwareCaller/with_dskit's_spanlogger.Caller-10 │
                            │                    sec/op                     │                 sec/op                  vs base         │
comparison-after-step-2.txt                                     927.5n ± 5%                              932.1n ± 2%  ~ (p=0.093 n=6)

                            │ SpanLoggerAwareCaller/with_go-kit's_Caller-10 │ SpanLoggerAwareCaller/with_dskit's_spanlogger.Caller-10 │
                            │                     B/op                      │                  B/op                   vs base         │
comparison-after-step-2.txt                                      732.5 ± 0%                               733.0 ± 0%  ~ (p=0.636 n=6)

                            │ SpanLoggerAwareCaller/with_go-kit's_Caller-10 │ SpanLoggerAwareCaller/with_dskit's_spanlogger.Caller-10 │
                            │                   allocs/op                   │              allocs/op                vs base           │
comparison-after-step-2.txt                                      9.000 ± 0%                             9.000 ± 0%  ~ (p=1.000 n=6) ¹
¹ all samples are equal
@charleskorn charleskorn marked this pull request as ready for review October 10, 2024 06:08
@charleskorn
Copy link
Contributor Author

I'd like to investigate and understand the regression in the SpanLoggerWithRealLogger/all_levels_allowed/level.Debug benchmark, but I'm going to share this for feedback on the approach first.

I've investigated this and addressed it in the main PR description. This PR is good to go now.

@aknuds1
Copy link
Collaborator

aknuds1 commented Oct 10, 2024

This is unavoidable, applications that are sensitive to this regression could use SpanLogger.DebugLog() rather than wrapping SpanLogger with level.Debug(...).

@charleskorn does this regression only apply to debug level?

Copy link
Collaborator

@aknuds1 aknuds1 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM, but please see suggestion about resizing the slice + my question about regression.

spanlogger/spanlogger.go Show resolved Hide resolved
spanlogger/spanlogger_test.go Outdated Show resolved Hide resolved
@charleskorn
Copy link
Contributor Author

This is unavoidable, applications that are sensitive to this regression could use SpanLogger.DebugLog() rather than wrapping SpanLogger with level.Debug(...).

@charleskorn does this regression only apply to debug level?

It applies to other levels too, if they are used when wrapping a SpanLogger.

However, at least in Mimir, it seems that the vast majority of logging to a SpanLogger is at the debug level, so that the logs appear only as events on trace spans and not in logs running at the default info level, so I don't think this regression is a big issue.

@aknuds1
Copy link
Collaborator

aknuds1 commented Oct 11, 2024

However, at least in Mimir, it seems that the vast majority of logging to a SpanLogger is at the debug level, so that the logs appear only as events on trace spans and not in logs running at the default info level, so I don't think this regression is a big issue.

Ah good point.

@charleskorn charleskorn merged commit 619c421 into main Oct 13, 2024
5 checks passed
@charleskorn charleskorn deleted the charleskorn/spanlogger-double-caller branch October 13, 2024 22:32
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants