Skip to content

Conversation

@seh
Copy link

@seh seh commented Oct 2, 2016

As a foil to #357, demonstrate an alternate approach to the "level" package offered via the "github.com/go-kit/kit/log/experimental_package" import path, allowing use of either a global log event level filtering threshold or local filtering via instances of the level.Leveler interface.

Features not accommodated here for now:

  • Returning an error from log.Log when squelching an event
  • Returning an error from log.Log for events that lack a level
    (This feature doesn't make much sense with this approach.)
  • Squelching events that lack a level
    (This feature doesn't make much sense with this approach.)
  • Concurrent-safe adjustment of the global level threshold
    (Note the "alternately" comments in file global.go for one proposed solution.)
  • Documentation
    (We could adapt much of this from the sibling package.)

See the commit message for then benchstat comparison.

This is a proof of concept. If others like this approach, we could refine whether to handle global configuration changes more safely (whether via atomic.Value, or guarding it with a sync.RWMutex), and whether to accommodate returning an error from log.Log, which wouldn't be too hard, whether via a singular sentinel error instance or with a caller-supplied error instance captured at configuration time.

Accommodating adjustment of the global level threshold safely imposes a performance tax on every subsequent event-recording call. I'd prefer to just document that callers should only change the threshold in an init function.

@seh seh mentioned this pull request Oct 2, 2016
Demonstrate an alternate approach to the "level" package offered via the
"github.com/go-kit/kit/log/experimental_level" import path, allowing
use of either a global log event level filtering threshold or local
filtering via instances of the level.Leveler interface.

Features not accommodated here for now:
- Returning an error from log.Log when squelching an event
- Returning an error from log.Log for events that lack a level
- Squelching events that lack a level
- Concurrent-safe adjustment of the global level threshold
  (Note the "alternately" comments in file global.go.)
- Documentation

Benchmarks demonstrate both run time and allocation reduction for the
disallowed/squelching cases compared to the "experimental_level"
alternate:

	name                     old time/op    new time/op    delta
	NopBaseline-4               737ns ± 0%     197ns ± 0%  -73.27%
	NopDisallowedLevel-4        805ns ± 0%     189ns ± 0%  -76.52%
	NopAllowedLevel-4           800ns ± 0%     754ns ± 0%   -5.75%
	JSONBaseline-4             4.00µs ± 0%    4.08µs ± 0%   +1.95%
	JSONDisallowedLevel-4       778ns ± 0%     193ns ± 0%  -75.19%
	JSONAllowedLevel-4         4.24µs ± 0%    4.00µs ± 0%   -5.57%
	LogfmtBaseline-4           1.50µs ± 0%    1.59µs ± 0%   +6.28%
	LogfmtDisallowedLevel-4     795ns ± 0%     186ns ± 0%  -76.60%
	LogfmtAllowedLevel-4       1.63µs ± 0%    1.59µs ± 0%   -2.27%

	name                     old alloc/op   new alloc/op   delta
	NopBaseline-4                288B ± 0%       64B ± 0%  -77.78%
	NopDisallowedLevel-4         288B ± 0%       64B ± 0%  -77.78%
	NopAllowedLevel-4            288B ± 0%      288B ± 0%   +0.00%
	JSONBaseline-4               968B ± 0%      968B ± 0%   +0.00%
	JSONDisallowedLevel-4        288B ± 0%       64B ± 0%  -77.78%
	JSONAllowedLevel-4           968B ± 0%      968B ± 0%   +0.00%
	LogfmtBaseline-4             288B ± 0%      288B ± 0%   +0.00%
	LogfmtDisallowedLevel-4      288B ± 0%       64B ± 0%  -77.78%
	LogfmtAllowedLevel-4         288B ± 0%      288B ± 0%   +0.00%

	name                     old allocs/op  new allocs/op  delta
	NopBaseline-4                9.00 ± 0%      3.00 ± 0%  -66.67%
	NopDisallowedLevel-4         9.00 ± 0%      3.00 ± 0%  -66.67%
	NopAllowedLevel-4            9.00 ± 0%      9.00 ± 0%   +0.00%
	JSONBaseline-4               22.0 ± 0%      22.0 ± 0%   +0.00%
	JSONDisallowedLevel-4        9.00 ± 0%      3.00 ± 0%  -66.67%
	JSONAllowedLevel-4           22.0 ± 0%      22.0 ± 0%   +0.00%
	LogfmtBaseline-4             9.00 ± 0%      9.00 ± 0%   +0.00%
	LogfmtDisallowedLevel-4      9.00 ± 0%      3.00 ± 0%  -66.67%
	LogfmtAllowedLevel-4         9.00 ± 0%      9.00 ± 0%   +0.00%
@seh seh force-pushed the leveled-log-exp branch from 25e6f92 to 23a96fd Compare October 3, 2016 00:17
seh added 2 commits October 3, 2016 08:12
Since these values are only used in one place each, don't bother
declaring manifest constants for them.
@seh
Copy link
Author

seh commented Oct 3, 2016

Also worth considering: functions to check whether a given level is currently allowed. This allows callers to decide whether to avoid running some costly operation to produce log values if the event won't be recorded anyway.

These would look something like the following, both on the level.Leveler interface and available globally (though those are vulnerable to check-then-act mistakes):

  • DebugIsAllowed() bool
  • InfoIsAllowed() bool
  • WarnIsAllowed() bool
  • ErrorIsAllowed() bool

That's eight more identifiers that we'd export from the package.

Another idea—though easy enough for callers to implement—is a narrowing Leveler decorator that takes a Leveler and restricts it further, if necessary. That is, something like a family of these:

  • AllowingErrorOnly(Leveler) Leveler

or, turning it around,

  • SquelchingWarnAndBelow(Leveler) Leveler

@ChrisHines
Copy link
Member

@seh Thanks for submitting your ideas. This way of handling leveled logging is certainly an interesting alternative to other approaches we've tried.

I have similar concerns with this variation as with the experiment in #357. Specifically the use of global state, although convenient, seems to almost always end with regret in the long run for widely reusable components.

@seh
Copy link
Author

seh commented Oct 14, 2016

@ChrisHines Using the global functions here is optional, much like the flag package. It's a convenience, but if you can't afford that convenience, you're left with a second stateful thing to carry around (here, a Leveler), as opposed to hiding that state in a Logger like the "experimental_level" one does. In my applications I'd use that global access option.

@peterbourgon, I'd like to hear your thoughts as well. Is it worth proceeding with documentation?

@peterbourgon
Copy link
Member

peterbourgon commented Oct 14, 2016

Unfortunately, I am pretty categorically opposed to package-global state.

@peterbourgon
Copy link
Member

What's the chief difference or advantage to this approach over the existing one in your view, @seh? Performance, friendlier API, both, something else?

@seh
Copy link
Author

seh commented Oct 26, 2016

The main advantage is CPU efficiency, avoiding inspecting log records to figure out whether their level is allowed to pass through, and avoiding collecting of records (their key/value pairs) that will get filtered due to their level.

Providing the global functions turned out to be a distraction here. I have (yet) another approach that I'd like to try, which will fall somewhere in between what I proposed here (minus the global functions) and your "experimental_level" package. I was out on vacation for a week, but now that I'm back I'll endeavor to flesh out the idea this week.

@peterbourgon
Copy link
Member

Looking forward to it.

@peterbourgon
Copy link
Member

@seh So I'd like to cut a Go kit 1.0.0 in the next few days, and I'd like for the current package experimental_level to be promoted to package level. I've been using it in anger on a couple of projects, and I'm happy with the experience. But if you have something cooking, I'd like to give that proper consideration first. Any update?

Also, @ChrisHines, would you have any objection to the above?

@ChrisHines
Copy link
Member

@peterbourgon I don't object to promoting experimental_level. I do suggest that you create an issue or milestone for doing a 1.0.0. It would be good to give contributors a chance to coordinate with you and prompt people like me to submit any work they have been procrastinating.

@seh
Copy link
Author

seh commented Jan 20, 2017

Please see a related proposal in #444, which removes the global state and embeds the level threshold in a logger.Logger instance, rather than in a companion level.Leveler instance as we did here.

@seh seh closed this Jan 20, 2017
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants