perf(logging): strip debug log messages at compile-time by andynog · Pull Request #4365 · cometbft/cometbft

andynog · 2024-10-29T20:36:10Z

partially close: #2847

Logging debug messages can lead to significant memory allocations, especially when outputting variable values. In Go, even if log_level is not set to debug, these allocations can still occur because the program evaluates the debug statements regardless of the log level.

To prevent unnecessary memory usage, you can strip out all debug-level code from the binary at compile time using build flags. This approach improves the performance of CometBFT by excluding debug messages entirely, even when log_level is set to debug. This technique is ideal for production environments that prioritize performance optimization over debug logging.

Note: Compiling CometBFT with this method will completely disable all debug messages. If you require debug output, avoid compiling the binary with these settings.

In order to build a binary stripping all debug log messages (e.g. log.Debug()) from the binary, use the nodebug tag:

COMETBFT_BUILD_OPTIONS=nodebug make install

once it's installed you can run a kvstore example with log_level = "debug" set in the config.toml and you will see that no debug messages are shown in the log.

cc: @ValarDragon

PR checklist

~~Tests written/updated~~
Changelog entry added in .changelog (we use unclog to manage our changelog)
Updated relevant documentation (docs/ or spec/) and code comments

melekes

Thanks @andynog ❤️

melekes · 2024-10-30T06:16:39Z

We're still incurring the cost of calculating arguments (if they are not Lazy), correct? Have you done any benchmarks? Curious about the results 🦊

ValarDragon · 2024-10-30T07:35:36Z

Is doing this at compile time best? feels hard to get operators to re-compile, vs having a global variable being set to off based on reading the config

If its at compile time, were anyways doing something global

andynog · 2024-10-30T12:42:16Z

We're still incurring the cost of calculating arguments (if they are not Lazy), correct? Have you done any benchmarks? Curious about the results 🦊

I will add more insights about this today before merging.

andynog · 2024-10-30T15:55:42Z

@melekes and @ValarDragon, to clarify the solution, it leverages a Go feature that removes dead code at compile time. Essentially, this strips out any Debug instructions from the final binary, ensuring zero allocations since these instructions don’t exist in the compiled output.

For example, here's the Debug func in the tm_logger.go file.

Note that it is on line 63. If we compile a binary that includes the debug messages (e.g. don't compile with the nodebug tag), you can see from the objdump that these instructions are part of the binary

(cometbft) > go tool objdump ./build/cometbft | grep tm_logger.go:63
  tm_logger.go:63                       0x100278570             f9400b90                MOVD 16(R28), R16                                       
  tm_logger.go:63                       0x100278574             d10083f1                SUB $32, RSP, R17                                       
  tm_logger.go:63                       0x100278578             eb10023f                CMP R16, R17                                            
  tm_logger.go:63                       0x10027857c             54001209                BLS 144(PC)                                             
  tm_logger.go:63                       0x100278580             f8160ffe                MOVD.W R30, -160(RSP)                                   
  tm_logger.go:63                       0x100278584             f81f83fd                MOVD R29, -8(RSP)                                       
  tm_logger.go:63                       0x100278588             d10023fd                SUB $8, RSP, R29                                        
  tm_logger.go:63                       0x1002787bc             f90007e0                MOVD R0, 8(RSP)                                         
  tm_logger.go:63                       0x1002787c0             f9000be1                MOVD R1, 16(RSP)                                        
  tm_logger.go:63                       0x1002787c4             f9000fe2                MOVD R2, 24(RSP)                                        
  tm_logger.go:63                       0x1002787c8             f90013e3                MOVD R3, 32(RSP)                                        
  tm_logger.go:63                       0x1002787cc             f90017e4                MOVD R4, 40(RSP)                                        
  tm_logger.go:63                       0x1002787d0             f9001be5                MOVD R5, 48(RSP)                                        
  tm_logger.go:63                       0x1002787d4             aa1e03e3                MOVD R30, R3                                            
  tm_logger.go:63                       0x1002787d8             97f8157a                CALL -518790(PC)                                        
  tm_logger.go:63                       0x1002787dc             f94007e0                MOVD 8(RSP), R0                                         
  tm_logger.go:63                       0x1002787e0             f9400be1                MOVD 16(RSP), R1                                        
  tm_logger.go:63                       0x1002787e4             f9400fe2                MOVD 24(RSP), R2                                        
  tm_logger.go:63                       0x1002787e8             f94013e3                MOVD 32(RSP), R3                                        
  tm_logger.go:63                       0x1002787ec             f94017e4                MOVD 40(RSP), R4                                        
  tm_logger.go:63                       0x1002787f0             f9401be5                MOVD 48(RSP), R5                                        
  tm_logger.go:63                       0x1002787f4             17ffff5f                JMP -161(PC)                                            
  tm_logger.go:63                       0x1002787f8             00000000                ?                                                       
  tm_logger.go:63                       0x1002787fc             00000000                ?

If you compile a binary with the nodebug tag, it will strip out all the instructions for Debug:

(cometbft) > COMETBFT_BUILD_OPTIONS=nodebug make build              
CGO_ENABLED=1 go build -mod=readonly -ldflags "-X github.com/cometbft/cometbft/version.CMTGitCommitHash=980d8a315  -s -w" -trimpath -tags 'cometbft nodebug' -o /Users/andynogueira/Development/Go/src/github.com/cometbft/cometbft/build/cometbft ./cmd/cometbft/
(cometbft) > go tool objdump ./build/cometbft | grep tm_logger.go:63
(cometbft) >

I recognize that, from an operator's perspective, re-compiling a binary may not initially seem ideal. However, this approach is the safest and most effective way to eliminate any risk of extra allocations from debug messages, ultimately boosting performance for operators. Given these benefits, I believe re-compilation will be a reasonable step for them.

Alternatively, we could explore a solution based on conditional statements (if checks), though this would involve a significant refactor and still might not fully eliminate allocations. If needed, I can add additional tests to validate these outcomes and ensure reliability. Might be a good idea to add benchmarks too.

melekes · 2024-10-30T17:54:45Z

compile time is the way 👍

cason · 2024-10-31T08:29:09Z

The question for me now is whether the official binaries should have debug level enabled or not.

I agree with @ValarDragon that changing the executed binary when we want to debug something is not really the best way to go.

At the same time, this is another (apparently very efficient) option to reduce the cost of debug log calls, when debugging is disabled.

andynog · 2024-10-31T13:00:03Z

We agreed this is a good use case for operators looking for optimal performance. However, there might be alternatives that would require more refactoring but would allow a granular and configurable approach to the problem. I will merge this and say it partially closes the issue. In the future, I can submit another PR that implements the other approach, too, so this way, we will cater to multiple operators.

@ValarDragon

partially close: #2847 Logging debug messages can lead to significant memory allocations, especially when outputting variable values. In Go, even if log_level is not set to debug, these allocations can still occur because the program evaluates the debug statements regardless of the log level. To prevent unnecessary memory usage, you can strip out all debug-level code from the binary at compile time using build flags. This approach improves the performance of CometBFT by excluding debug messages entirely, even when `log_level` is set to `debug`. This technique is ideal for production environments that prioritize performance optimization over debug logging. > Note: Compiling CometBFT with this method will completely disable all debug messages. If you require debug output, avoid compiling the binary with these settings. In order to build a binary stripping all debug log messages (e.g. `log.Debug()`) from the binary, use the `nodebug` tag: ``` COMETBFT_BUILD_OPTIONS=nodebug make install ``` once it's installed you can run a `kvstore` example with `log_level = "debug"` set in the `config.toml` and you will see that no debug messages are shown in the log. cc: @ValarDragon #### PR checklist - [ ] ~~Tests written/updated~~ - [X] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [X] Updated relevant documentation (`docs/` or `spec/`) and code comments --------- Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com> (cherry picked from commit 51e9948)

@ValarDragon

…) (#4375) partially close: #2847 Logging debug messages can lead to significant memory allocations, especially when outputting variable values. In Go, even if log_level is not set to debug, these allocations can still occur because the program evaluates the debug statements regardless of the log level. To prevent unnecessary memory usage, you can strip out all debug-level code from the binary at compile time using build flags. This approach improves the performance of CometBFT by excluding debug messages entirely, even when `log_level` is set to `debug`. This technique is ideal for production environments that prioritize performance optimization over debug logging. > Note: Compiling CometBFT with this method will completely disable all debug messages. If you require debug output, avoid compiling the binary with these settings. In order to build a binary stripping all debug log messages (e.g. `log.Debug()`) from the binary, use the `nodebug` tag: ``` COMETBFT_BUILD_OPTIONS=nodebug make install ``` once it's installed you can run a `kvstore` example with `log_level = "debug"` set in the `config.toml` and you will see that no debug messages are shown in the log. cc: @ValarDragon #### PR checklist - [ ] ~~Tests written/updated~~ - [X] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [X] Updated relevant documentation (`docs/` or `spec/`) and code comments <hr>This is an automatic backport of pull request #4365 done by [Mergify](https://mergify.com). Co-authored-by: Andy Nogueira <me@andynogueira.dev>

@ValarDragon

partially close: #2847 Logging debug messages can lead to significant memory allocations, especially when outputting variable values. In Go, even if log_level is not set to debug, these allocations can still occur because the program evaluates the debug statements regardless of the log level. To prevent unnecessary memory usage, you can strip out all debug-level code from the binary at compile time using build flags. This approach improves the performance of CometBFT by excluding debug messages entirely, even when `log_level` is set to `debug`. This technique is ideal for production environments that prioritize performance optimization over debug logging. > Note: Compiling CometBFT with this method will completely disable all debug messages. If you require debug output, avoid compiling the binary with these settings. In order to build a binary stripping all debug log messages (e.g. `log.Debug()`) from the binary, use the `nodebug` tag: ``` COMETBFT_BUILD_OPTIONS=nodebug make install ``` once it's installed you can run a `kvstore` example with `log_level = "debug"` set in the `config.toml` and you will see that no debug messages are shown in the log. cc: @ValarDragon - [ ] ~~Tests written/updated~~ - [X] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [X] Updated relevant documentation (`docs/` or `spec/`) and code comments --------- Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com>

@ValarDragon

partially close: #2847 Logging debug messages can lead to significant memory allocations, especially when outputting variable values. In Go, even if log_level is not set to debug, these allocations can still occur because the program evaluates the debug statements regardless of the log level. To prevent unnecessary memory usage, you can strip out all debug-level code from the binary at compile time using build flags. This approach improves the performance of CometBFT by excluding debug messages entirely, even when `log_level` is set to `debug`. This technique is ideal for production environments that prioritize performance optimization over debug logging. > Note: Compiling CometBFT with this method will completely disable all debug messages. If you require debug output, avoid compiling the binary with these settings. In order to build a binary stripping all debug log messages (e.g. `log.Debug()`) from the binary, use the `nodebug` tag: ``` COMETBFT_BUILD_OPTIONS=nodebug make install ``` once it's installed you can run a `kvstore` example with `log_level = "debug"` set in the `config.toml` and you will see that no debug messages are shown in the log. cc: @ValarDragon - [ ] ~~Tests written/updated~~ - [X] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [X] Updated relevant documentation (`docs/` or `spec/`) and code comments --------- Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com>

@ValarDragon

partially close: #2847 Logging debug messages can lead to significant memory allocations, especially when outputting variable values. In Go, even if log_level is not set to debug, these allocations can still occur because the program evaluates the debug statements regardless of the log level. To prevent unnecessary memory usage, you can strip out all debug-level code from the binary at compile time using build flags. This approach improves the performance of CometBFT by excluding debug messages entirely, even when `log_level` is set to `debug`. This technique is ideal for production environments that prioritize performance optimization over debug logging. > Note: Compiling CometBFT with this method will completely disable all debug messages. If you require debug output, avoid compiling the binary with these settings. In order to build a binary stripping all debug log messages (e.g. `log.Debug()`) from the binary, use the `nodebug` tag: ``` COMETBFT_BUILD_OPTIONS=nodebug make install ``` once it's installed you can run a `kvstore` example with `log_level = "debug"` set in the `config.toml` and you will see that no debug messages are shown in the log. cc: @ValarDragon - [ ] ~~Tests written/updated~~ - [X] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [X] Updated relevant documentation (`docs/` or `spec/`) and code comments --------- Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com>

@ValarDragon

partially close: #2847 Logging debug messages can lead to significant memory allocations, especially when outputting variable values. In Go, even if log_level is not set to debug, these allocations can still occur because the program evaluates the debug statements regardless of the log level. To prevent unnecessary memory usage, you can strip out all debug-level code from the binary at compile time using build flags. This approach improves the performance of CometBFT by excluding debug messages entirely, even when `log_level` is set to `debug`. This technique is ideal for production environments that prioritize performance optimization over debug logging. > Note: Compiling CometBFT with this method will completely disable all debug messages. If you require debug output, avoid compiling the binary with these settings. In order to build a binary stripping all debug log messages (e.g. `log.Debug()`) from the binary, use the `nodebug` tag: ``` COMETBFT_BUILD_OPTIONS=nodebug make install ``` once it's installed you can run a `kvstore` example with `log_level = "debug"` set in the `config.toml` and you will see that no debug messages are shown in the log. cc: @ValarDragon - [ ] ~~Tests written/updated~~ - [X] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [X] Updated relevant documentation (`docs/` or `spec/`) and code comments --------- Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com>

@ValarDragon

partially close: #2847 Logging debug messages can lead to significant memory allocations, especially when outputting variable values. In Go, even if log_level is not set to debug, these allocations can still occur because the program evaluates the debug statements regardless of the log level. To prevent unnecessary memory usage, you can strip out all debug-level code from the binary at compile time using build flags. This approach improves the performance of CometBFT by excluding debug messages entirely, even when `log_level` is set to `debug`. This technique is ideal for production environments that prioritize performance optimization over debug logging. > Note: Compiling CometBFT with this method will completely disable all debug messages. If you require debug output, avoid compiling the binary with these settings. In order to build a binary stripping all debug log messages (e.g. `log.Debug()`) from the binary, use the `nodebug` tag: ``` COMETBFT_BUILD_OPTIONS=nodebug make install ``` once it's installed you can run a `kvstore` example with `log_level = "debug"` set in the `config.toml` and you will see that no debug messages are shown in the log. cc: @ValarDragon - [ ] ~~Tests written/updated~~ - [X] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [X] Updated relevant documentation (`docs/` or `spec/`) and code comments --------- Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com>

andynog added 2 commits October 29, 2024 16:19

logic to strip debug log messages at compile-time (#2847)

d1597ef

add changelog entry (#2847)

980d8a3

andynog added P:operator-experience Priority: Improve experience for operators logs Anything relating to logging labels Oct 29, 2024

andynog added this to the 2024-Q4 milestone Oct 29, 2024

andynog self-assigned this Oct 29, 2024

andynog requested a review from a team as a code owner October 29, 2024 20:36

andynog requested a review from a team October 29, 2024 20:36

andynog added the backport-to-v1.x label Oct 29, 2024

melekes approved these changes Oct 30, 2024

View reviewed changes

Merge branch 'main' into andy/compile-time-debug-strip

b5c7e3b

mergify bot added 4 commits October 31, 2024 06:25

Merge branch 'main' into andy/compile-time-debug-strip

0adfbfa

Merge branch 'main' into andy/compile-time-debug-strip

7fe40f5

Merge branch 'main' into andy/compile-time-debug-strip

5ca6a91

Merge branch 'main' into andy/compile-time-debug-strip

a62d021

andynog added this pull request to the merge queue Oct 31, 2024

Merged via the queue into main with commit 51e9948 Oct 31, 2024

andynog deleted the andy/compile-time-debug-strip branch October 31, 2024 13:08

mergify bot mentioned this pull request Oct 31, 2024

perf(logging): strip debug log messages at compile-time (backport #4365) #4375

Merged

3 tasks

andynog mentioned this pull request Dec 12, 2024

Don't pay vote Debug logging cost in normal operation #2847

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

perf(logging): strip debug log messages at compile-time#4365

perf(logging): strip debug log messages at compile-time#4365
andynog merged 7 commits intomainfrom
andy/compile-time-debug-strip

andynog commented Oct 29, 2024 •

edited

Loading

Uh oh!

melekes left a comment

Uh oh!

melekes commented Oct 30, 2024

Uh oh!

ValarDragon commented Oct 30, 2024 •

edited

Loading

Uh oh!

andynog commented Oct 30, 2024

Uh oh!

andynog commented Oct 30, 2024 •

edited

Loading

Uh oh!

melekes commented Oct 30, 2024

Uh oh!

cason commented Oct 31, 2024

Uh oh!

andynog commented Oct 31, 2024

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

Conversation

andynog commented Oct 29, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

PR checklist

Uh oh!

melekes left a comment

Choose a reason for hiding this comment

Uh oh!

melekes commented Oct 30, 2024

Uh oh!

ValarDragon commented Oct 30, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

andynog commented Oct 30, 2024

Uh oh!

andynog commented Oct 30, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

melekes commented Oct 30, 2024

Uh oh!

cason commented Oct 31, 2024

Uh oh!

andynog commented Oct 31, 2024

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

andynog commented Oct 29, 2024 •

edited

Loading

ValarDragon commented Oct 30, 2024 •

edited

Loading

andynog commented Oct 30, 2024 •

edited

Loading