Extensive trace logging is expensive even when disabled

[thaarok]

While running performance benchmarks of ethereum code, I have discovered a significant amount of time is consumed by trace logging, even when the trace logging is not enabled.

By cpuprofile, 2% of my runtime is consumed by:

log.Trace
log.write
stack.Caller

In the source:
https://github.com/ethereum/go-ethereum/blob/v1.12.2/log/logger.go#L185

Actual behaviour

The ethereum logging generates expensive stacktraces on every log.Trace() call, even when the trace logging is disabled.

Expected behaviour

The stacktrace should be generated only when the log is not going to be dropped.

System information

Commit hash : 25733a4

[holiman]

Why did you close this? Seems like you have a point, no?

[holiman]

A benchmark:

func BenchmarkTraceLogging(b *testing.B) {
	Root().SetHandler(LvlFilterHandler(LvlInfo, StreamHandler(os.Stderr, TerminalFormat(true))))
	b.ResetTimer()
	for i := 0; i < b.N; i++ {
		Trace("a message", "v", i)
	}
}

Results, for commenting out the line Call: stack.Caller(skip),:

[user@work go-ethereum]$ benchstat before.txt after.txt 
name            old time/op    new time/op    delta
TraceLogging-8    2.84µs ± 8%    0.97µs ±11%  -65.80%  (p=0.008 n=5+5)

name            old alloc/op   new alloc/op   delta
TraceLogging-8      511B ± 0%      263B ± 0%  -48.53%  (p=0.000 n=5+4)

name            old allocs/op  new allocs/op  delta
TraceLogging-8      4.00 ± 0%      2.00 ± 0%  -50.00%  (p=0.008 n=5+5)