[Feature] log Helper sprint, sprintf is executed before Filter Level, the performance consumption is very high

[sendya]

Please see the FAQ in our main README.md before submitting your issue.

What problem is the feature used to solve?

---

I try adding such a demo implementation, the CPU usage dropped to no more than 1%

func (h *Helper) CheckLevel(level Level) bool {
	l, ok := h.logger.(*Filter)
	return ok && level < l.level
}

// Debugf logs a message at debug level.
func (h *Helper) Debugf(format string, a ...interface{}) {
	if CheckLevel(LevelDebug) {
		return
	}
	_ = h.logger.Log(LevelDebug, h.msgKey, h.sprintf(format, a...))
}

Requirements description of the feature

References

[dosubot]

🤖

It's great to see that you've identified a potential performance improvement in the code! If you're able to propose a solution or a fix for this issue, we'd love to see a pull request from you. Your contribution could help improve the overall performance of the project. Thank you for considering to contribute!

About Dosu

This response is meant to be useful and save you time. It is not meant to be a precise solution, but rather a starting point for your own research.

Help me be more useful! Please leave a 👍 if this is helpful and 👎 if it is irrelevant.

If you want to continue the conversation, start your reply with @dosu-bot.

[Windfarer]

SGTM, could you submit a enhancement PR with benchmark codes?

[sendya]

@Windfarer

Please look at this sendya@d8eafb3

kratos/log on  main [!] via 🐹 v1.21.4 ❯ go test -benchmem -benchtime=10s -run=^\$ -bench=^BenchmarkHelperPrintfFilterLevel .
goos: linux
goarch: amd64
pkg: github.com/go-kratos/kratos/v2/log
cpu: AMD Ryzen 9 5900X 12-Core Processor
BenchmarkHelperPrintfFilterLevelInfoNoOptimize-24       100000000              119.0 ns/op            84 B/op          5 allocs/op
BenchmarkHelperPrintfFilterLevelInfoOptimized-24        592013310               20.29 ns/op           16 B/op          1 allocs/op
BenchmarkHelperPrintfFilterLevelDebugNoOptimize-24      60518269               197.4 ns/op            84 B/op          5 allocs/op
BenchmarkHelperPrintfFilterLevelDebugOptimized-24       60776246               197.3 ns/op            84 B/op          5 allocs/op
PASS
ok      github.com/go-kratos/kratos/v2/log      50.426s

kratos/log on  main [!] via 🐹 v1.21.4 took 50s ➜ go test -benchmem -benchtime=10s -run=^\$ -bench=^BenchmarkHelperPrintFilterLevel .
goos: linux
goarch: amd64
pkg: github.com/go-kratos/kratos/v2/log
cpu: AMD Ryzen 9 5900X 12-Core Processor
BenchmarkHelperPrintFilterLevelInfoNoOptimize-24        100000000              120.0 ns/op            84 B/op          5 allocs/op
BenchmarkHelperPrintFilterLevelInfoOptimized-24         597341275               20.09 ns/op           16 B/op          1 allocs/op
BenchmarkHelperPrintFilterLevelDebugNoOptimize-24       59979846               201.0 ns/op            84 B/op          5 allocs/op
BenchmarkHelperPrintFilterLevelDebugOptimized-24        53935786               219.3 ns/op           104 B/op          5 allocs/op
PASS
ok      github.com/go-kratos/kratos/v2/log      50.466s

Problem

log.NewHelper(log.NewFilter(log.DefaultLogger, log.FilterLevel(log.LevelInfo)))

log.Debuf("some data... key1: %s, key2: %s, key3: %s", 'value1', 'value2', 'value3')

 -->  log.Log(LevelDebug, h.msgKey, h.sprintf(format, a...) )

h.sprintf(format, a...)
This function first performs string concat, and then enters *log.Filter to judge the level and returns nil