Only set entry time when entry will be logged

[pjvds]

This pull request optimizes the Check scenario. It only sets the entry time after the decision has been made to log the entry or not. This improves performance in a disabled scenario by 63.55%.

benchmark                                           old ns/op     new ns/op     delta
BenchmarkDisabledAccumulatedContext/Zap.Check-4     20.3          7.40          -63.55%

[CLAassistant]

Thank you for your submission! We really appreciate it. Like many open source projects, we ask that you sign our Contributor License Agreement before we can accept your contribution.
_{You have signed the CLA already but the status is still pending? Let us recheck it.}

[codecov[bot]]

Codecov Report

Merging #664 into master will not change coverage. The diff coverage is 100%.

@@           Coverage Diff           @@
##           master     #664   +/-   ##
=======================================
  Coverage   97.38%   97.38%           
=======================================
  Files          40       40           
  Lines        2102     2102           
=======================================
  Hits         2047     2047           
  Misses         47       47           
  Partials        8        8

Impacted Files	Coverage Δ
logger.go	94.49% <100%> (ø)	:arrow_up:

---

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 67bc79d...dfdea27. Read the comment docs.

[fgrosse]

We also noticed that recording the time in high throughput scenarios was a bottleneck, basically because we had a lot of debug messages. However I'm afraid you cannot merge this change without breaking compatibility because cores such as the sampling core rely on the time information in order to check if the log entry should be printed or not. Additionally there might be other hooked cores which work in a similar way.

What we ended up doing was to wrap the debug log calls in a function which only checks the level and aborts early if possible. Of course that means that we cannot use any sampling based logging there.

[pjvds]

Is there a reason why we don't remove the sampling state to the sampling core itself, or make it not time depending but just a percentage of the logs with an atomic counter? This would mean you only pay the overhead for sampling support if the sampling core is enabled.