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

sendya commented 6 months ago

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[bot] commented 6 months ago

🤖

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 commented 6 months ago

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

sendya commented 6 months ago

@Windfarer

Please look at this https://github.com/sendya/kratos/commit/d8eafb336a70954eeaa141133c727c5c54086b0e

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

go-kratos / kratos