spanlogger: fix double logging of caller information

[charleskorn]

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]

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.

[charleskorn]

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]

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?

[aknuds1]

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

[charleskorn]

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]

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.