log: Unexport Context

[ChrisHines]

Implement #474.

The first commit makes the API change in the simplest way possible and patches dependent packages within this repository to account for the change.

Work remaining:

• Update documentation.
• Check for benchmark regressions.
• Justify breaking change.

[ChrisHines]

name                      old time/op    new time/op    delta
JSONLoggerSimple-8          1.95µs ± 8%    1.93µs ± 8%     ~     (p=0.841 n=5+5)
JSONLoggerContextual-8      2.61µs ± 4%    2.76µs ± 8%     ~     (p=0.151 n=5+5)
Discard-8                    106ns ± 9%     102ns ± 1%     ~     (p=0.175 n=5+5)
OneWith-8                    170ns ± 9%     192ns ± 6%  +13.18%  (p=0.016 n=5+5)
TwoWith-8                    165ns ± 1%     194ns ± 2%  +17.72%  (p=0.008 n=5+5)
TenWith-8                    287ns ± 1%     320ns ± 5%  +11.65%  (p=0.008 n=5+5)
LogfmtLoggerSimple-8         659ns ± 1%     651ns ± 0%     ~     (p=0.063 n=5+5)
LogfmtLoggerContextual-8     931ns ± 5%     968ns ± 3%     ~     (p=0.095 n=5+5)
NopLoggerSimple-8            220ns ±21%     194ns ± 6%     ~     (p=0.222 n=5+5)
NopLoggerContextual-8        377ns ± 4%     408ns ± 5%   +8.28%  (p=0.008 n=5+5)
ValueBindingTimestamp-8      599ns ± 4%     628ns ± 3%   +4.87%  (p=0.048 n=5+5)
ValueBindingCaller-8         825ns ± 1%     863ns ± 1%   +4.68%  (p=0.008 n=5+5)

name                      old alloc/op   new alloc/op   delta
JSONLoggerSimple-8            904B ± 0%      904B ± 0%     ~     (all equal)
JSONLoggerContextual-8      1.20kB ± 0%    1.23kB ± 0%   +2.67%  (p=0.008 n=5+5)
Discard-8                    64.0B ± 0%     64.0B ± 0%     ~     (all equal)
OneWith-8                    96.0B ± 0%    128.0B ± 0%  +33.33%  (p=0.008 n=5+5)
TwoWith-8                     160B ± 0%      192B ± 0%  +20.00%  (p=0.008 n=5+5)
TenWith-8                     672B ± 0%      704B ± 0%   +4.76%  (p=0.008 n=5+5)
LogfmtLoggerSimple-8          128B ± 0%      128B ± 0%     ~     (all equal)
LogfmtLoggerContextual-8      304B ± 0%      336B ± 0%  +10.53%  (p=0.008 n=5+5)
NopLoggerSimple-8             128B ± 0%      128B ± 0%     ~     (all equal)
NopLoggerContextual-8         304B ± 0%      336B ± 0%  +10.53%  (p=0.008 n=5+5)
ValueBindingTimestamp-8       158B ± 0%      190B ± 0%  +20.25%  (p=0.008 n=5+5)
ValueBindingCaller-8          112B ± 0%      144B ± 0%  +28.57%  (p=0.008 n=5+5)

name                      old allocs/op  new allocs/op  delta
JSONLoggerSimple-8            19.0 ± 0%      19.0 ± 0%     ~     (all equal)
JSONLoggerContextual-8        25.0 ± 0%      26.0 ± 0%   +4.00%  (p=0.008 n=5+5)
Discard-8                     3.00 ± 0%      3.00 ± 0%     ~     (all equal)
OneWith-8                     3.00 ± 0%      4.00 ± 0%  +33.33%  (p=0.008 n=5+5)
TwoWith-8                     3.00 ± 0%      4.00 ± 0%  +33.33%  (p=0.008 n=5+5)
TenWith-8                     3.00 ± 0%      4.00 ± 0%  +33.33%  (p=0.008 n=5+5)
LogfmtLoggerSimple-8          4.00 ± 0%      4.00 ± 0%     ~     (all equal)
LogfmtLoggerContextual-8      7.00 ± 0%      8.00 ± 0%  +14.29%  (p=0.008 n=5+5)
NopLoggerSimple-8             4.00 ± 0%      4.00 ± 0%     ~     (all equal)
NopLoggerContextual-8         7.00 ± 0%      8.00 ± 0%  +14.29%  (p=0.008 n=5+5)
ValueBindingTimestamp-8       5.00 ± 0%      6.00 ± 0%  +20.00%  (p=0.008 n=5+5)
ValueBindingCaller-8          4.00 ± 0%      5.00 ± 0%  +25.00%  (p=0.008 n=5+5)

At first glace the benchmark changes look like a regression, but after investigating the increase in allocations I have determined that the benchmarks on master are flawed.

The flaw is explained in the comments below.

func BenchmarkOneWith(b *testing.B) {
	logger := log.NewNopLogger()
        // The old code returned a concrete *log.Context to lc.
	// lc := log.NewContext(logger).With("k", "v")
        
        // The new code returns a log.Logger interface value to lc.
        // That prevents escape analysis from eliminating the allocation
        // of the keyvals slice passed to Log.
        // I think most client code will be using variables of type
        // log.Logger to hold the context, so the old benchmark
        // was measuring an atypical use case.
	lc := log.With(logger, "k", "v")
	b.ReportAllocs()
	b.ResetTimer()
	for i := 0; i < b.N; i++ {
		lc.Log("k", "v")
	}
}

[willfaught]

That prevents escape analysis from eliminating the allocation of the keyvals slice passed to Log.

Interesting. I'd like to understand this better. How did you know escape analysis was the culprit? Why is the slice allocated for Log on an interface instead of Log on a struct?

[ChrisHines]

I inferred that from a couple pieces of information.

• Looking at the generated assembly from both master and this branch it was clear that the extra allocation was happening in the benchmark code prior to calling Log on the interface value, but not on the concrete *Context value.
• I had a conversation with Brad Fitzpatrick at one of the recent GopherCon's in which he pointed out that one of the benefits of the stdlib Logger being a concrete type is that the compiler knows statically which methods are getting called and that this allows better escape analysis for the method arguments.

[peterbourgon]

This looks good to me. I'm happy to take the breaking change.

[ChrisHines]

@peterbourgon What do you think of my revised language in the documentation in doc.go and log.go?

[peterbourgon]

Yes, it's great. I like that the previously floating comment about stack frame details now has a home on the unexported context type.

[ChrisHines]

OK. Merging.