v2/log: check log level before using fmt.Sprint calls by ellemouton · Pull Request #19 · btcsuite/btclog

ellemouton · 2024-11-21T15:07:03Z

The Enabled call is also called later on in the slog.Logger's log call but by then we have already built the string with fmt.Sprint which can result in quite a big performance hit.

Thanks to @bitromortac for realising this!

EDIT: this has since been updated quite a bit. During review, you can use the new BenchmarkLogger and BenchmarkV1vsV2Loggers benchmark tests to evaluate each commits impact.

Note that this has also been expanded to add a WithPrefix method on the Logger so that we can get rid of the PrefixedLogger in LND

ellemouton · 2024-11-21T15:07:46Z

cc @Roasbeef

guggero

LGTM 🎉

bitromortac

Nice, thank you for the fix 🎉! LGTM ⚡

Roasbeef · 2024-11-22T01:51:25Z

Should we add some benchmarks here as a tool to catch regressions like this in the future?

Migth also be interesting to compare v1 to v2 w.r.t overhead.

Roasbeef · 2024-11-22T01:53:07Z

call but by then we have already built the string with fmt.Sprint which can result in quite a big performance hit.

Seems the log closure pattern is an alternative? So we'd only construct the string later down the call stack if we know the log level matches.

ellemouton · 2024-11-22T08:05:53Z

cool yeah great idea re benchmark and also having lazy compute values via closure. Currently implementing - will push up by EoD

ellemouton · 2024-11-22T10:21:43Z

accidental push soz. will ping when ready for re-review

ellemouton · 2024-11-25T10:19:21Z

Cool cool cool, this has been updated quite a bit. Please see the new benchmark tests which can be used to evaluate the effectiveness of each commit here. Note that the main thing this aims to do is to let the new f methods be as close to the performance of the old v1 f methods.

I've also added a new WithPrefix method on the Logger so that we can get rid of the Prefixed logger in LND

ellemouton · 2024-11-25T10:29:42Z

Some results:

Importantly, we can see from these results that in the case where a log line is skipped due to the
current log level, with this PR the performance matches that of the V1 logger for both the simple
log and complex log case.

V1 logger (baseline)

BenchmarkV1vsV2Loggers/btclog_v1_simple-10                     159.9   ns/op
BenchmarkV1vsV2Loggers/btclog_v1_skipped_simple-10               2.085 ns/op
BenchmarkV1vsV2Loggers/btclog_v1_complex-10                   1695     ns/op
BenchmarkV1vsV2Loggers/btclog_v1_skipped_complex-10            197.4   ns/op

V2 Logger (current master branch)

BenchmarkV1vsV2Loggers/btclog_v2_simple-10                     364.9  ns/op
BenchmarkV1vsV2Loggers/btclog_v2_skipped_simple-10              33.34 ns/op
BenchmarkV1vsV2Loggers/btclog_v2_complex-10                    1972   ns/op
BenchmarkV1vsV2Loggers/btclog_v2_skipped_complex-10            1611   ns/op

V2 Logger with this PR:

BenchmarkV1vsV2Loggers/btclog_v2_simple-10                     299.9   ns/op
BenchmarkV1vsV2Loggers/btclog_v2_skipped_simple-10               2.080 ns/op
BenchmarkV1vsV2Loggers/btclog_v2_complex-10                   1899     ns/op
BenchmarkV1vsV2Loggers/btclog_v2_skipped_complex-10            198.9   ns/op

guggero

Very nice performance tests and improvements 💯

v2/handler_test.go

guggero · 2024-11-25T12:52:13Z

v2/handler_test.go

+		level: LevelInfo,
+		logFunc: func(log Logger) {
+			ctx := context.Background()
+			log.InfoS(ctx, "msg", Hex("hex_val", []byte{0x01, 0x02}))


nit: Did you mean to call Hex6 here too?

No I wanted to test both :) But I'll change this one to have more than 6 bytes 👍

and I'll add a less-than-6-byte test for Hex6 👍

v2/attrs.go

v2/log_test.go

v2/log.go

ellemouton

Thanks for the speedy review @guggero!! 🎉 addressed all comments

ellemouton · 2024-11-25T13:14:41Z

v2/handler_test.go

+		level: LevelInfo,
+		logFunc: func(log Logger) {
+			ctx := context.Background()
+			log.InfoS(ctx, "msg", Hex("hex_val", []byte{0x01, 0x02}))


No I wanted to test both :) But I'll change this one to have more than 6 bytes 👍

ellemouton · 2024-11-25T13:16:17Z

v2/handler_test.go

+		level: LevelInfo,
+		logFunc: func(log Logger) {
+			ctx := context.Background()
+			log.InfoS(ctx, "msg", Hex("hex_val", []byte{0x01, 0x02}))


and I'll add a less-than-6-byte test for Hex6 👍

v2/attrs.go

v2/log_test.go

v2/log.go

bitromortac

Nice improvements 🔥! I've also done some pathfinding benchmarks with lnd (500 random payments, no mission control data). The first benchmark is lnd with v2 logging before this PR, the second one is with v1 logging, and the last one is with this PR. So I think practially, there shouldn't be a noticable difference now 🎉.

v2/attrs.go

v2/closure.go

v2/handler_test.go

v2/attrs.go

v2/handler.go

v2/interface.go

v2/attrs.go

Roasbeef · 2024-11-26T02:34:40Z

Looking good to land, only blocker is this failing test:

=== RUN   TestDefaultHandler/Basic_calls_and_levels
    handler_test.go:33: Log result mismatch. Expected
        "1970-01-01 02:01:40.000 [INF]: Test Basic Log
        1970-01-01 02:01:40.000 [DBG]: Test basic log with format
        ", got
        "1969-12-31 18:01:40.000 [INF]: Test Basic Log
        1969-12-31 18:01:40.000 [DBG]: Test basic log with format
        "

Move the test cases to the bottom of the file so that we can add more tests without the results (line number) of the call-site test changing.

Like the Hex helper, this helper prints a byte array in hex form but this one prints a maximum of 6 bytes.

Along with helpers to convert closures into slog Attributes.

This commit adds two benchmark tests: 1) BenchmarkLogger tests the new V2 logger under various scenarios. 2) BenchmarkV1vsV2Loggers tests the performance of the V2 logger against that of the V1 logger. As of this commit, the biggest issue is the time it takes for the new v2 logger to perform a log action that actually gets skipped due to the current log level. This is due to a bug that builds the log string using fmt.Sprintf _before_ the logger's Enabled check is run against the current log level. This will be improved upon in the upcoming commits. The BenchmarkLogger test will also help to assess the various improvements that will be make in the upcoming commits. We ideally want BenchmarkV2vsV2Loggers to show that the performance between the same methods on the two loggers does not change much. This will be improved upon in upcoming commits.

Instead of a fresh context per call to the old interface methods.

In this commit, we start checking the log level of the logger's handler before we do any more evaluation. This does not change behaviour since the level is checked by the slog library itself later on but by then we have performed some evaluation which impacts performance. In the benchmark tests, the biggest differences should be noticeable in the "skipped" tests.

The default styled options use `fmt.Sprintf` calls. This commit removes these defaults which improves the performance of the V2 logger for the cases when styled options are not provided.

To prioritise performance of the logger, we opt for code duplication instead of adding an extra code jump to the call-stack.

In this commit, instead of depending on the Handler for Level handling, we add a level object to the logger itself. This makes checking the log level before computing any expensive checks much faster. The handler still needs to carry its own level member so that it can properly implement the `Enabled` method of the Handler interface. This means that for the cases where a log line is skipped due to log level not being met, the performance will be faster. However, in the cases where the log line will be printed, execution will be slightly slower due to the fact that the level will in essence be checked twice.

So that a sub-system logger can be derived directly from a logger rather than needing to first create a new handler.

Which can be used to derive a new prefixed logger which will prefix a provided string to any message printed by the logger.

ellemouton

Thanks so much for the thorough testing @bitromortac! 🙏 addressed all comments

v2/handler_test.go

v2/attrs.go

v2/interface.go

ellemouton · 2024-11-26T19:58:17Z

think this is g2g now @Roasbeef 🙏

Roasbeef

LGTM 🐦‍🔥

ellemouton force-pushed the checkLevel branch from 5da5eff to e3d3184 Compare November 21, 2024 15:08

ellemouton mentioned this pull request Nov 21, 2024

go.mod: bump btclog dep lightningnetwork/lnd#9295

Merged

guggero approved these changes Nov 21, 2024

View reviewed changes

bitromortac approved these changes Nov 21, 2024

View reviewed changes

ellemouton force-pushed the checkLevel branch from e3d3184 to 84cd56b Compare November 22, 2024 10:16

ellemouton force-pushed the checkLevel branch 3 times, most recently from 965a07b to 913b97d Compare November 25, 2024 09:54

ellemouton requested review from bitromortac and guggero November 25, 2024 10:16

guggero approved these changes Nov 25, 2024

View reviewed changes

ellemouton force-pushed the checkLevel branch from 41945e1 to ba4eabe Compare November 25, 2024 13:34

ellemouton commented Nov 25, 2024

View reviewed changes

bitromortac approved these changes Nov 25, 2024

View reviewed changes

ellemouton added 8 commits November 26, 2024 09:19

handler_test: restructure test

21ac472

Move the test cases to the bottom of the file so that we can add more tests without the results (line number) of the call-site test changing.

attrs: add Hex6 helper

c9d039d

Like the Hex helper, this helper prints a byte array in hex form but this one prints a maximum of 6 bytes.

attrs+closure: add Closure methods

8efaf8e

Along with helpers to convert closures into slog Attributes.

log: one context per logger

02ac0c5

Instead of a fresh context per call to the old interface methods.

handler: only use fmt.Sprintf in styled outputs when specified

8722008

The default styled options use `fmt.Sprintf` calls. This commit removes these defaults which improves the performance of the V2 logger for the cases when styled options are not provided.

log: remove the toSlog* helpers

054acdb

To prioritise performance of the logger, we opt for code duplication instead of adding an extra code jump to the call-stack.

ellemouton added 4 commits November 26, 2024 09:20

log: add SubSystem method to Logger interface

e669d22

So that a sub-system logger can be derived directly from a logger rather than needing to first create a new handler.

log: add WithPrefix method

875edf9

Which can be used to derive a new prefixed logger which will prefix a provided string to any message printed by the logger.

handler: export default skip depth

e0b4906

ellemouton force-pushed the checkLevel branch from ba4eabe to e0b4906 Compare November 26, 2024 07:28

ellemouton commented Nov 26, 2024

View reviewed changes

v2/handler_test.go Outdated Show resolved Hide resolved

v2/attrs.go Outdated Show resolved Hide resolved

v2/attrs.go Show resolved Hide resolved

v2/interface.go Outdated Show resolved Hide resolved

Roasbeef approved these changes Nov 27, 2024

View reviewed changes

Roasbeef merged commit e4cba5d into btcsuite:master Nov 27, 2024

ellemouton deleted the checkLevel branch November 27, 2024 03:06

Conversation

ellemouton commented Nov 21, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

ellemouton commented Nov 21, 2024

Uh oh!

guggero left a comment

Choose a reason for hiding this comment

Uh oh!

bitromortac left a comment

Choose a reason for hiding this comment

Uh oh!

Roasbeef commented Nov 22, 2024

Uh oh!

Roasbeef commented Nov 22, 2024

Uh oh!

ellemouton commented Nov 22, 2024

Uh oh!

ellemouton commented Nov 22, 2024

Uh oh!

ellemouton commented Nov 25, 2024

Uh oh!

ellemouton commented Nov 25, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

V1 logger (baseline)

V2 Logger (current master branch)

V2 Logger with this PR:

Uh oh!

guggero left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

guggero Nov 25, 2024

Choose a reason for hiding this comment

Uh oh!

ellemouton Nov 25, 2024

Choose a reason for hiding this comment

Uh oh!

ellemouton Nov 25, 2024

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

ellemouton left a comment

Choose a reason for hiding this comment

Uh oh!

ellemouton Nov 25, 2024

Choose a reason for hiding this comment

Uh oh!

ellemouton Nov 25, 2024

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

bitromortac left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Roasbeef commented Nov 26, 2024

Uh oh!

ellemouton left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

ellemouton commented Nov 26, 2024

Uh oh!

ellemouton commented Nov 21, 2024 •

edited

Loading

ellemouton commented Nov 25, 2024 •

edited

Loading

bitromortac left a comment •

edited

Loading