go-ethereum icon indicating copy to clipboard operation
go-ethereum copied to clipboard

log: allow --vmodule to downgrade the log level

Open MariusVanDerWijden opened this issue 8 months ago • 6 comments

This PR allows --vmodule to also downgrade the log level for packages. closes https://github.com/ethereum/go-ethereum/issues/30717

This does have some performance implications that I'm not sure about yet

Before

 ./build/bin/geth --dev --vmodule="*=1" console
WARN [04-01|12:38:38.561] The flag '--vmodule' is deprecated, please use '--log.vmodule' instead
INFO [04-01|12:38:38.569] Starting Geth in ephemeral dev mode...
WARN [04-01|12:38:38.569] You are running Geth in --dev mode. Please note the following:

  1. This mode is only intended for fast, iterative development without assumptions on
     security or persistence.
...

After

./build/bin/geth --dev --vmodule="*=1" console
ERROR[04-01|12:37:46.896] Head block is not reachable
Welcome to the Geth JavaScript console!

MariusVanDerWijden avatar Apr 01 '25 10:04 MariusVanDerWijden

Benchmark:

func BenchmarkGlog(b *testing.B) {
	out := new(bytes.Buffer)
	glog := NewGlogHandler(NewTerminalHandlerWithLevel(out, LevelTrace, false))
	glog.Verbosity(LevelCrit)
	logger := NewLogger(glog)
	logger.Warn("This should not be seen", "ignored", "true")
	//glog.Vmodule("logger_test.go=5")
	for i := 0; i < b.N; i++ {
		logger.Trace("a message", "foo", "bar")
	}
}

This PR:

With vmodule disabled: BenchmarkGlog-14 370532622 3.763 ns/op 0 B/op 0 allocs/op With vmodule enabled: BenchmarkGlog-14 2653554 406.2 ns/op 151 B/op 0 allocs/op

Master:

With vmodule disabled: BenchmarkGlog-14 307312317 3.775 ns/op 0 B/op 0 allocs/op With vmodule enabled: BenchmarkGlog-14 2882396 436.6 ns/op 279 B/op 0 allocs/op

So it seems there's almost no performance difference between this PR and master

MariusVanDerWijden avatar Apr 01 '25 10:04 MariusVanDerWijden

The size of the map will at max be 20.000 items, (rough count of every time we call log), so 20.000*64*2 = 2MB (if all logs we have in the code would be hit)

MariusVanDerWijden avatar Apr 01 '25 11:04 MariusVanDerWijden

I guess this works because the logger calls Enabled first to check for the fast path.

fjl avatar Apr 02 '25 11:04 fjl

BTW, any reason why we are not forwarding the context parameter into the sub-logger?

fjl avatar Apr 02 '25 11:04 fjl

use sync.Map

MariusVanDerWijden avatar May 29 '25 08:05 MariusVanDerWijden

Master:
BenchmarkVmodule-14    	 1413564	       960.7 ns/op	     569 B/op	       0 allocs/op
PR:
BenchmarkVmodule-14    	 1467424	       837.8 ns/op	     548 B/op	       0 allocs/op
func BenchmarkVmodule(b *testing.B) {
	out := new(bytes.Buffer)
	glog := NewGlogHandler(NewTerminalHandlerWithLevel(out, LevelTrace, false))
	glog.Verbosity(LevelCrit)
	logger := NewLogger(glog)
	glog.Vmodule("logger_test.go=5")
	for i := 0; i < b.N; i++ {
		logger.Warn("This should not be seen", "ignored", "true")
		logger.Trace("a message", "foo", "bar")
	}
}

MariusVanDerWijden avatar May 29 '25 09:05 MariusVanDerWijden