Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

logger: Check level before creating entry #771

Merged
merged 1 commit into from
Dec 18, 2019
Merged

logger: Check level before creating entry #771

merged 1 commit into from
Dec 18, 2019

Conversation

prashantv
Copy link
Collaborator

@prashantv prashantv commented Dec 10, 2019

Calling time.Now() and creating an entry is unnecessary
if the underlying core has the specified level disabled.

To reduce the cost of logs at disabled levels, skip entry
creation if the log level is disabled in the core.

This special logic does not apply to DPanic or higher logs as
they may need to panic/exit even if the entry does not cause
any log to be emitted.

On my machine, disabled debugging logs are 6x (~60ns to ~10ns)
based on the example in the issue.

benchcmp:

benchmark                                                 old ns/op     new ns/op     delta
BenchmarkDisabledWithoutFields/Zap-12                     8.42          1.59          -81.12%
BenchmarkDisabledWithoutFields/Zap.Check-12               8.01          1.32          -83.52%
BenchmarkDisabledWithoutFields/Zap.Sugar-12               12.4          11.4          -8.06%
BenchmarkDisabledWithoutFields/Zap.SugarFormatting-12     117           102           -12.82%

Fixes #770.

Calling `time.Now()` and creating an entry is unnecessary
if the underlying core has the specified level disabled.

To reduce the cost of logs at disabled levels, skip entry
creation if the log level is disabled in the core.

This special logic does not apply to DPanic or higher logs as
they may need to panic/exit even if the entry does not cause
any log to be emitted.

On my machine, disabled debugging logs are 6x (~60ns to ~10ns).

Fixes #770.
@codecov
Copy link

codecov bot commented Dec 10, 2019

Codecov Report

Merging #771 into master will increase coverage by <.01%.
The diff coverage is 100%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master     #771      +/-   ##
==========================================
+ Coverage   98.19%   98.19%   +<.01%     
==========================================
  Files          42       42              
  Lines        2269     2271       +2     
==========================================
+ Hits         2228     2230       +2     
  Misses         33       33              
  Partials        8        8
Impacted Files Coverage Δ
logger.go 94.59% <100%> (+0.09%) ⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 33e58d4...18e55c5. Read the comment docs.

Copy link
Collaborator

@abhinav abhinav left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nice

@alxn
Copy link
Member

alxn commented Dec 10, 2019

new test?

@prashantv
Copy link
Collaborator Author

new test?

Since this is an optimization, it doesn't have any impact to the functional tests, just a performance improvement.

While it is possible to write a test to check for this (we can verify at the core which methods are called), it seems like we're breaking the abstraction.

@abhinav
Copy link
Collaborator

abhinav commented Dec 11, 2019

Perhaps not a test, but perhaps we should add a benchmark for messages being discarded if we don't already have one.

@prashantv
Copy link
Collaborator Author

We do have existing benchmarks for this,

benchmark                                                 old ns/op     new ns/op     delta
BenchmarkDisabledWithoutFields/Zap-12                     8.42          1.59          -81.12%
BenchmarkDisabledWithoutFields/Zap.Check-12               8.01          1.32          -83.52%
BenchmarkDisabledWithoutFields/Zap.Sugar-12               12.4          11.4          -8.06%
BenchmarkDisabledWithoutFields/Zap.SugarFormatting-12     117           102           -12.82%

Will update the summary as well.

@prashantv prashantv merged commit 66bdb5b into master Dec 18, 2019
@prashantv prashantv deleted the logger_check branch December 18, 2019 01:52
sykesm added a commit to sykesm/fabric that referenced this pull request Mar 16, 2020
This picks up uber-go/zap#771.

Change-Id: Ic55f3fd29b0d600a3b1c87bd117f7e0a2e0fce04
Signed-off-by: Matthew Sykes <sykesmat@us.ibm.com>
sykesm added a commit to hyperledger/fabric that referenced this pull request Mar 16, 2020
This picks up uber-go/zap#771.

Change-Id: Ic55f3fd29b0d600a3b1c87bd117f7e0a2e0fce04
Signed-off-by: Matthew Sykes <sykesmat@us.ibm.com>
cgxxv pushed a commit to cgxxv/zap that referenced this pull request Mar 25, 2022
Calling `time.Now()` and creating an entry is unnecessary
if the underlying core has the specified level disabled.

To reduce the cost of logs at disabled levels, skip entry
creation if the log level is disabled in the core.

This special logic does not apply to DPanic or higher logs as
they may need to panic/exit even if the entry does not cause
any log to be emitted.

On my machine, disabled debugging logs are 6x (~60ns to ~10ns)
based on the example in the issue.

benchcmp:
```
benchmark                                                 old ns/op     new ns/op     delta
BenchmarkDisabledWithoutFields/Zap-12                     8.42          1.59          -81.12%
BenchmarkDisabledWithoutFields/Zap.Check-12               8.01          1.32          -83.52%
BenchmarkDisabledWithoutFields/Zap.Sugar-12               12.4          11.4          -8.06%
BenchmarkDisabledWithoutFields/Zap.SugarFormatting-12     117           102           -12.82%
```

Fixes uber-go#770.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

Successfully merging this pull request may close these issues.

Calling Debug or Check on a Production Logger is slow
3 participants