ddtrace/tracer: Remove log.Debug from hot path (-2 allocs; -5% CPU) #1186
Conversation
The log.Debug function takes a ...interface{} argument which must be
heap allocated. This is done even if debug logging is disabled, which
is the common case. Add a log.DebugEnabled() function to check if it
is enabled, and skip allocating this slice in the common case. The
benchstat output from my laptop shows this saves about 5% CPU and
2 allocs/call for the BenchmarkStartSpan microbenchmark.
Normally, I do not like this sort of ugly log level check. However,
given that StartSpan is widely called, and sometimes from hot code
paths, this may be worthit.
name old time/op new time/op delta
StartSpan-8 1.63µs ± 5% 1.55µs ±10% -5.00% (p=0.003 n=9+9)
name old alloc/op new alloc/op delta
StartSpan-8 1.55kB ± 0% 1.52kB ± 0% -2.08% (p=0.000 n=10+8)
name old allocs/op new allocs/op delta
StartSpan-8 19.0 ± 0% 17.0 ± 0% -10.53% (p=0.000 n=10+10)
There was a problem hiding this comment.
LGTM – I played around with this a bit to see if the same result can be achieved by getting the compiler to inline the log.Debug() call. But unfortunately I wasn't able to get the cost of the Debug function below the threshold of 80 (only got it to 122 from 228 by applying my NIT suggestion).
Anyway, since this is all internal and only a single call-site needs the explicit log.DebugEnabled() check, I think this is a fine tradeoff.
internal/log/log.go
Outdated
| mu.RUnlock() | ||
| return lvl == LevelDebug | ||
| } | ||
|
|
||
| // Debug prints the given message if the level is LevelDebug. | ||
| func Debug(fmt string, a ...interface{}) { | ||
| mu.RLock() |
There was a problem hiding this comment.
NIT: Remove code duplication by calling DebugEnabled() here?
There was a problem hiding this comment.
Oops excellent suggestion; fixed
|
I think it is tricky to eliminate the slice allocation, since the arguments eventually get passed to fmt.Printf? I'm not entirely sure if inlining could do this, since it would need to rearrange when the argument slice gets allocated with the check. Uber's zap logging library provides a very clever but ugly API to avoid needing to check if a level is enabled more than once. This seems like overkill for this internal use: https://pkg.go.dev/go.uber.org/zap#Logger.Check Also: having poked around some profiles yesterday, there may be ONE more place where this check might be useful. However, I'll wait until we get this merged before I look again. |
The log.Debug function takes a ...interface{} argument which must be
heap allocated. This is done even if debug logging is disabled, which
is the common case. Add a log.DebugEnabled() function to check if it
is enabled, and skip allocating this slice in the common case. The
benchstat output from my laptop shows this saves about 5% CPU and
2 allocs/call for the BenchmarkStartSpan microbenchmark.
Normally, I do not like this sort of ugly log level check. However,
given that StartSpan is widely called, and sometimes from hot code
paths, this may be worthit.