itsscb/tracing
1
0
Fork 0
mirror of https://github.com/tokio-rs/tracing.git synced 2025-10-02 15:24:47 +00:00
Code Issues Packages Projects Releases Wiki Activity

core: add faster fast path for level filtering (#853)

Browse Source 
## Motivation

Tracing currently stores cached filter evaluations in a per-callsite
cache. Once filters have been evaluated, this allows us to skip disabled
callsites with a single load and compare, which is a nice fast path for
skipping. However, determining the value to store in the callsite cache
is expensive: it requires acquiring a lock to register the callsite, and
asking the subscriber for an `Interest` value to cache.

In long-running applications, such as servers, daemons, and interactive
applications that are used for a long period of time, this cost is not
very visible; it's amortized over the rest of the application's
lifetime. However, in batch-oriented programs and CLI tools that run to
completion, the cost of building the initial cached value has a much
bigger impact. If a given callsite is hit twice over the thirty seconds
that a CLI tool runs for (for example), the cost of the initial
evaluation is _much_ more meaningful than if the same callsite is hit
hundreds of thousands of times by a server that runs for several weeks
before its restarted. Even in a long running application, though, it
could lead to a surprising latency hit if a given callsite is only hit
after a long period of operation.

Per-callsite caching allows high performance for more granular filters,
since it tracks the state of _every_ callsite; we still get a fast path
for skipping a `trace` event in the `foo::bar` module if the `trace`
level is only enabled for the `baz` module. Because of this, we didn't
initially believe that a global maximum level fast path was necessary.
However, in `rustc`, it turns out that the cost of just building the
callsite cache for the first time has a noticeable impact on
performance. See here for details:
https://github.com/rust-lang/rust/pull/74726#issuecomment-664181180

## Solution

This branch adds a faster fast path for skipping callsites whose level
is higher than the highest level enabled for _any_ target/metadata
combination, similar to the `log` crate's `max_level`.

Unlike the `log` crate, which only ever has a single global logger,
`tracing` allows multiple `Subscriber`s to coexist in the same process.
Therefore, our implementation is somewhat different than `log`'s. We
can't simply provide a `set_max_level` function call, because _another_
subscriber may have already set a lower max level, and just overwriting
the max level with ours may result in diagnostics being skipped that
another subscriber wants to collect.

Instead, we've added a `max_level_hint` method to the `Subscriber`
trait, returning an `Option<LevelFilter>`. By default, this returns
`None`, for backwards compatibility. However, if it returns `Some`, the
resulting `LevelFilter` is stored in a global `MAX_LEVEL` atomic. This
method is called by the `register_dispatch` function, which handles the
creation of a new `Dispatch`. This allows us to compare the max level
from a new subscriber with those of all other currently active
subscribers. Similarly, when cached interests are invalidated (such as
by changing a filter, or when a `Subscriber` is dropped), we can
reevaluate the max level.

The path for _checking_ the max level (e.g. in the macros) should be
very efficient. We load the atomic, convert the `usize` value into a
`LevelFilter`, and compare it to the callsite's level. With help from
@eddyb, I was able to implement the conversion such that it should
hopefully be an identity conversion in release mode, rather than
requiring rustc to generate a LUT. The macros have been updated to check
the max level before anything requiring hitting the callsite cache _or_
the subscriber TLS var.

Also, I've updated `tracing` and `tracing-subscriber` to reexport the
`LevelFilter` type from `tracing-core` rather than defining their own.
The API should be a superset of those crates' versions.

Thanks to @oli-obk for uncovering this issue when adding `tracing` to
`rustc`, and for doing a lot of the preliminary analysis of the cause!

So far, there doesn't appear to be a significant change in any of `tracing`'s
internal benchmarks on this branch. However, my guess is that this is
because of `criterion`'s outlier elimination: since the cache is constructed
only on the first iteration, it's pretty likely that `criterion` considers this an
outlier and throws it out entirely, so the benchmark results on master don't
include the cost of evaluating the filter for the initial time.

Incidentally, this PR also fixes a bug in the `tracing` crate's version
of `LevelFilter`, where the `OFF` level actually enabled *everything*,
rather than *nothing*. Oopsie!

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
This commit is contained in:
Eliza Weisman 2020-07-30 16:20:26 -07:00 committed by GitHub
parent b22fd87ad4
commit 61b08decf4
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
16 changed files with 639 additions and 285 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

9
tracing-core/CHANGELOG.md
View File

@ -1,3 +1,12 @@
# 0.1.12 (UNRELEASED)
## Added
- `LevelFilter` type and `LevelFilter::current()` for returning the highest level
that any subscriber will enable (#853)
- `Subscriber::max_level_hint` optional trait method, for setting the value
returned by `LevelFilter::current()` (#853)
# 0.1.11 (June 8, 2020)
## Changed

2
tracing-core/Cargo.toml
View File

@ -8,7 +8,7 @@ name = "tracing-core"
# - README.md
# - Update CHANGELOG.md.
# - Create "v0.1.x" git tag.
version = "0.1.11"
version = "0.1.12"
authors = ["Tokio Contributors <team@tokio.rs>"]
license = "MIT"
readme = "README.md"

25
tracing-core/src/callsite.rs
View File

@ -7,9 +7,9 @@ use crate::stdlib::{
vec::Vec,
};
use crate::{
dispatcher::{self, Dispatch, Registrar},
dispatcher::{self, Dispatch},
metadata::{LevelFilter, Metadata},
subscriber::Interest,
Metadata,
};
lazy_static! {
@ -40,11 +40,24 @@ impl Registry {
}
fn rebuild_interest(&mut self) {
self.dispatchers.retain(Registrar::is_alive);
let mut max_level = LevelFilter::TRACE;
self.dispatchers.retain(|registrar| {
if let Some(dispatch) = registrar.upgrade() {
if let Some(level) = dispatch.max_level_hint() {
if level > max_level {
max_level = level;
}
}
true
} else {
false
}
});
self.callsites.iter().for_each(|&callsite| {
self.rebuild_callsite_interest(callsite);
});
LevelFilter::set_max(max_level);
}
}
@ -91,6 +104,12 @@ pub struct Identifier(
/// reconfiguration of filters always return [`Interest::sometimes()`] so that
/// [`enabled`] is evaluated for every event.
///
/// This function will also re-compute the global maximum level as determined by
/// the [`Subscriber::max_level_hint`] method. If a [`Subscriber`]
/// implementation changes the value returned by its `max_level_hint`
/// implementation at runtime, then it **must** call this function after that
/// value changes, in order for the change to be reflected.
///
/// [`Callsite`]: ../callsite/trait.Callsite.html
/// [`enabled`]: ../subscriber/trait.Subscriber.html#tymethod.enabled
/// [`Interest::sometimes()`]: ../subscriber/struct.Interest.html#method.sometimes

22
tracing-core/src/dispatcher.rs
View File

@ -135,7 +135,7 @@
use crate::{
callsite, span,
subscriber::{self, Subscriber},
Event, Metadata,
Event, LevelFilter, Metadata,
};
use crate::stdlib::{
@ -427,6 +427,22 @@ impl Dispatch {
self.subscriber.register_callsite(metadata)
}
/// Returns the highest [verbosity level][level] that this [`Subscriber`] will
/// enable, or `None`, if the subscriber does not implement level-based
/// filtering or chooses not to implement this method.
///
/// This calls the [`max_level_hint`] function on the [`Subscriber`]
/// that this `Dispatch` forwards to.
///
/// [level]: ../struct.Level.html
/// [`Subscriber`]: ../subscriber/trait.Subscriber.html
/// [`register_callsite`]: ../subscriber/trait.Subscriber.html#method.max_level_hint
// TODO(eliza): consider making this a public API?
#[inline]
pub(crate) fn max_level_hint(&self) -> Option<LevelFilter> {
self.subscriber.max_level_hint()
}
/// Record the construction of a new span, returning a new [ID] for the
/// span being constructed.
///
@ -670,8 +686,8 @@ impl Registrar {
self.0.upgrade().map(|s| s.register_callsite(metadata))
}
pub(crate) fn is_alive(&self) -> bool {
self.0.upgrade().is_some()
pub(crate) fn upgrade(&self) -> Option<Dispatch> {
self.0.upgrade().map(|subscriber| Dispatch { subscriber })
}
}

2
tracing-core/src/lib.rs
View File

@ -251,7 +251,7 @@ pub use self::{
dispatcher::Dispatch,
event::Event,
field::Field,
metadata::{Level, Metadata},
metadata::{Level, LevelFilter, Metadata},
subscriber::Subscriber,
};

537
tracing-core/src/metadata.rs
View File

@ -1,6 +1,10 @@
//! Metadata describing trace data.
use super::{callsite, field};
use crate::stdlib::{fmt, str::FromStr};
use crate::stdlib::{
cmp, fmt,
str::FromStr,
sync::atomic::{AtomicUsize, Ordering},
};
/// Metadata describing a [span] or [event].
///
@ -90,9 +94,28 @@ pub struct Metadata<'a> {
pub struct Kind(KindInner);
/// Describes the level of verbosity of a span or event.
#[derive(Clone, Debug, Eq, PartialEq, Ord, PartialOrd)]
#[derive(Clone, Debug, PartialEq, Eq)]
pub struct Level(LevelInner);
/// A filter comparable to a verbosity `Level`.
///
/// If a `Level` is considered less than a `LevelFilter`, it should be
/// considered disabled; if greater than or equal to the `LevelFilter`, that
/// level is enabled.
///
/// Note that this is essentially identical to the `Level` type, but with the
/// addition of an `OFF` level that completely disables all trace
/// instrumentation.
#[repr(transparent)]
#[derive(Clone, Eq, PartialEq)]
pub struct LevelFilter(Option<Level>);
/// Indicates that a string could not be parsed to a valid level.
#[derive(Clone, Debug)]
pub struct ParseLevelFilterError(());
static MAX_LEVEL: AtomicUsize = AtomicUsize::new(LevelFilter::OFF_USIZE);
// ===== impl Metadata =====
impl<'a> Metadata<'a> {
@ -309,28 +332,223 @@ impl FromStr for Level {
}
#[repr(usize)]
#[derive(Copy, Clone, Debug, Eq, PartialEq, Hash, Ord, PartialOrd)]
#[derive(Copy, Clone, Debug, Hash, Eq, PartialEq)]
enum LevelInner {
/// The "error" level.
///
/// Designates very serious errors.
Error = 1,
/// The "warn" level.
///
/// Designates hazardous situations.
Warn,
/// The "info" level.
///
/// Designates useful information.
Info,
/// The "debug" level.
///
/// Designates lower priority information.
Debug,
/// The "trace" level.
///
/// Designates very low priority, often extremely verbose, information.
Trace,
Trace = 0,
/// The "debug" level.
///
/// Designates lower priority information.
Debug = 1,
/// The "info" level.
///
/// Designates useful information.
Info = 2,
/// The "warn" level.
///
/// Designates hazardous situations.
Warn = 3,
/// The "error" level.
///
/// Designates very serious errors.
Error = 4,
}
// === impl LevelFilter ===
impl From<Level> for LevelFilter {
#[inline]
fn from(level: Level) -> Self {
Self::from_level(level)
}
}
impl Into<Option<Level>> for LevelFilter {
#[inline]
fn into(self) -> Option<Level> {
self.into_level()
}
}
impl LevelFilter {
/// The "off" level.
///
/// Designates that trace instrumentation should be completely disabled.
pub const OFF: LevelFilter = LevelFilter(None);
/// The "error" level.
///
/// Designates very serious errors.
pub const ERROR: LevelFilter = LevelFilter::from_level(Level::ERROR);
/// The "warn" level.
///
/// Designates hazardous situations.
pub const WARN: LevelFilter = LevelFilter::from_level(Level::WARN);
/// The "info" level.
///
/// Designates useful information.
pub const INFO: LevelFilter = LevelFilter::from_level(Level::INFO);
/// The "debug" level.
///
/// Designates lower priority information.
pub const DEBUG: LevelFilter = LevelFilter::from_level(Level::DEBUG);
/// The "trace" level.
///
/// Designates very low priority, often extremely verbose, information.
pub const TRACE: LevelFilter = LevelFilter(Some(Level::TRACE));
/// Returns a `LevelFilter` that enables spans and events with verbosity up
/// to and including `level`.
pub const fn from_level(level: Level) -> Self {
Self(Some(level))
}
/// Returns the most verbose [`Level`] that this filter accepts, or `None`
/// if it is [`OFF`].
///
/// [`Level`]: ../struct.Level.html
/// [`OFF`]: #associatedconstant.OFF
pub const fn into_level(self) -> Option<Level> {
self.0
}
// These consts are necessary because `as` casts are not allowed as
// match patterns.
const ERROR_USIZE: usize = LevelInner::Error as usize;
const WARN_USIZE: usize = LevelInner::Warn as usize;
const INFO_USIZE: usize = LevelInner::Info as usize;
const DEBUG_USIZE: usize = LevelInner::Debug as usize;
const TRACE_USIZE: usize = LevelInner::Trace as usize;
// Using the value of the last variant + 1 ensures that we match the value
// for `Option::None` as selected by the niche optimization for
// `LevelFilter`. If this is the case, converting a `usize` value into a
// `LevelFilter` (in `LevelFilter::current`) will be an identity conversion,
// rather than generating a lookup table.
const OFF_USIZE: usize = LevelInner::Error as usize + 1;
/// Returns a `LevelFilter` that matches the most verbose [`Level`] that any
/// currently active [`Subscriber`] will enable.
///
/// User code should treat this as a *hint*. If a given span or event has a
/// level *higher* than the returned `LevelFilter`, it will not be enabled.
/// However, if the level is less than or equal to this value, the span or
/// event is *not* guaranteed to be enabled; the subscriber will still
/// filter each callsite individually.
///
/// Therefore, comparing a given span or event's level to the returned
/// `LevelFilter` **can** be used for determining if something is
/// *disabled*, but **should not** be used for determining if something is
/// *enabled*.`
///
/// [`Level`]: ../struct.Level.html
/// [`Subscriber`]: ../../trait.Subscriber.html
#[inline(always)]
pub fn current() -> Self {
match MAX_LEVEL.load(Ordering::Relaxed) {
Self::ERROR_USIZE => Self::ERROR,
Self::WARN_USIZE => Self::WARN,
Self::INFO_USIZE => Self::INFO,
Self::DEBUG_USIZE => Self::DEBUG,
Self::TRACE_USIZE => Self::TRACE,
Self::OFF_USIZE => Self::OFF,
#[cfg(debug_assertions)]
unknown => unreachable!(
"/!\\ `LevelFilter` representation seems to have changed! /!\\ \n\
This is a bug (and it's pretty bad). Please contact the `tracing` \
maintainers. Thank you and I'm sorry.\n \
The offending repr was: {:?}",
unknown,
),
#[cfg(not(debug_assertions))]
_ => unsafe {
// Using `unreachable_unchecked` here (rather than
// `unreachable!()`) is necessary to ensure that rustc generates
// an identity conversion from integer -> discriminant, rather
// than generating a lookup table. We want to ensure this
// function is a single `mov` instruction (on x86) if at all
// possible, because it is called *every* time a span/event
// callsite is hit; and it is (potentially) the only code in the
// hottest path for skipping a majority of callsites when level
// filtering is in use.
//
// safety: This branch is only truly unreachable if we guarantee
// that no values other than the possible enum discriminants
// will *ever* be present. The `AtomicUsize` is initialized to
// the `OFF` value. It is only set by the `set_max` function,
// which takes a `LevelFilter` as a parameter. This restricts
// the inputs to `set_max` to the set of valid discriminants.
// Therefore, **as long as `MAX_VALUE` is only ever set by
// `set_max`**, this is safe.
crate::stdlib::hint::unreachable_unchecked()
},
}
}
pub(crate) fn set_max(LevelFilter(level): LevelFilter) {
let val = match level {
Some(Level(level)) => level as usize,
None => Self::OFF_USIZE,
};
// using an AcqRel swap ensures an ordered relationship of writes to the
// max level.
MAX_LEVEL.swap(val, Ordering::AcqRel);
}
}
impl fmt::Display for LevelFilter {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
match *self {
LevelFilter::OFF => f.pad("off"),
LevelFilter::ERROR => f.pad("error"),
LevelFilter::WARN => f.pad("warn"),
LevelFilter::INFO => f.pad("info"),
LevelFilter::DEBUG => f.pad("debug"),
LevelFilter::TRACE => f.pad("trace"),
}
}
}
impl fmt::Debug for LevelFilter {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
match *self {
LevelFilter::OFF => f.pad("LevelFilter::OFF"),
LevelFilter::ERROR => f.pad("LevelFilter::ERROR"),
LevelFilter::WARN => f.pad("LevelFilter::WARN"),
LevelFilter::INFO => f.pad("LevelFilter::INFO"),
LevelFilter::DEBUG => f.pad("LevelFilter::DEBUG"),
LevelFilter::TRACE => f.pad("LevelFilter::TRACE"),
}
}
}
impl FromStr for LevelFilter {
type Err = ParseLevelFilterError;
fn from_str(from: &str) -> Result<Self, Self::Err> {
from.parse::<usize>()
.ok()
.and_then(|num| match num {
0 => Some(LevelFilter::OFF),
1 => Some(LevelFilter::ERROR),
2 => Some(LevelFilter::WARN),
3 => Some(LevelFilter::INFO),
4 => Some(LevelFilter::DEBUG),
5 => Some(LevelFilter::TRACE),
_ => None,
})
.or_else(|| match from {
"" => Some(LevelFilter::ERROR),
s if s.eq_ignore_ascii_case("error") => Some(LevelFilter::ERROR),
s if s.eq_ignore_ascii_case("warn") => Some(LevelFilter::WARN),
s if s.eq_ignore_ascii_case("info") => Some(LevelFilter::INFO),
s if s.eq_ignore_ascii_case("debug") => Some(LevelFilter::DEBUG),
s if s.eq_ignore_ascii_case("trace") => Some(LevelFilter::TRACE),
s if s.eq_ignore_ascii_case("off") => Some(LevelFilter::OFF),
_ => None,
})
.ok_or_else(|| ParseLevelFilterError(()))
}
}
/// Returned if parsing a `Level` fails.
@ -348,9 +566,239 @@ impl fmt::Display for ParseLevelError {
}
}
impl fmt::Display for ParseLevelFilterError {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
f.pad(
"error parsing level filter: expected one of \"off\", \"error\", \
\"warn\", \"info\", \"debug\", \"trace\", or a number 0-5",
)
}
}
#[cfg(feature = "std")]
impl std::error::Error for ParseLevelFilterError {}
// ==== Level and LevelFilter comparisons ====
// /!\ BIG, IMPORTANT WARNING /!\
// Do NOT mess with these implementations! They are hand-written for a reason!
//
// Since comparing `Level`s and `LevelFilter`s happens in a *very* hot path
// (potentially, every time a span or event macro is hit, regardless of whether
// or not is enabled), we *need* to ensure that these comparisons are as fast as
// possible. Therefore, we have some requirements:
//
// 1. We want to do our best to ensure that rustc will generate integer-integer
// comparisons wherever possible.
//
// The derived `Ord`/`PartialOrd` impls for `LevelFilter` will not do this,
// because `LevelFilter`s are represented by `Option<Level>`, rather than as
// a separate `#[repr(usize)]` enum. This was (unfortunately) necessary for
// backwards-compatibility reasons, as the `tracing` crate's original
// version of `LevelFilter` defined `const fn` conversions between `Level`s
// and `LevelFilter`, so we're stuck with the `Option<Level>` repr.
// Therefore, we need hand-written `PartialOrd` impls that cast both sides of
// the comparison to `usize`s, to force the compiler to generate integer
// compares.
//
// 2. The hottest `Level`/`LevelFilter` comparison, the one that happens every
// time a callsite is hit, occurs *within the `tracing` crate's macros*.
// This means that the comparison is happening *inside* a crate that
// *depends* on `tracing-core`, not in `tracing-core` itself. The compiler
// will only inline function calls across crate boundaries if the called
// function is annotated with an `#[inline]` attribute, and we *definitely*
// want the comparison functions to be inlined: as previously mentioned, they
// should compile down to a single integer comparison on release builds, and
// it seems really sad to push an entire stack frame to call a function
// consisting of one `cmp` instruction!
//
// Therefore, we need to ensure that all the comparison methods have
// `#[inline]` or `#[inline(always)]` attributes. It's not sufficient to just
// add the attribute to `partial_cmp` in a manual implementation of the
// trait, since it's the comparison operators (`lt`, `le`, `gt`, and `ge`)
// that will actually be *used*, and the default implementation of *those*
// methods, which calls `partial_cmp`, does not have an inline annotation.
//
// 3. We need the comparisons to be inverted. The discriminants for the
// `LevelInner` enum are assigned in "backwards" order, with `TRACE` having
// the *lowest* value. However, we want `TRACE` to compare greater-than all
// other levels.
//
// Why are the numeric values inverted? In order to ensure that `LevelFilter`
// (which, as previously mentioned, *has* to be internally represented by an
// `Option<Level>`) compiles down to a single integer value. This is
// necessary for storing the global max in an `AtomicUsize`, and for ensuring
// that we use fast integer-integer comparisons, as mentioned previously. In
// order to ensure this, we exploit the niche optimization. The niche
// optimization for `Option<{enum with a numeric repr}>` will choose
// `(HIGHEST_DISCRIMINANT_VALUE + 1)` as the representation for `None`.
// Therefore, the integer representation of `LevelFilter::OFF` (which is
// `None`) will be the number 5. `OFF` must compare higher than every other
// level in order for it to filter as expected. Since we want to use a single
// `cmp` instruction, we can't special-case the integer value of `OFF` to
// compare higher, as that will generate more code. Instead, we need it to be
// on one end of the enum, with `ERROR` on the opposite end, so we assign the
// value 0 to `ERROR`.
//
// This *does* mean that when parsing `LevelFilter`s or `Level`s from
// `String`s, the integer values are inverted, but that doesn't happen in a
// hot path.
//
// Note that we manually invert the comparisons by swapping the left-hand and
// right-hand side. Using `Ordering::reverse` generates significantly worse
// code (per Matt Godbolt's Compiler Explorer).
//
// Anyway, that's a brief history of why this code is the way it is. Don't
// change it unless you know what you're doing.
impl PartialEq<LevelFilter> for Level {
#[inline(always)]
fn eq(&self, other: &LevelFilter) -> bool {
self.0 as usize == filter_as_usize(&other.0)
}
}
impl PartialOrd for Level {
#[inline(always)]
fn partial_cmp(&self, other: &Level) -> Option<cmp::Ordering> {
Some(self.cmp(other))
}
#[inline(always)]
fn lt(&self, other: &Level) -> bool {
(other.0 as usize) < (self.0 as usize)
}
#[inline(always)]
fn le(&self, other: &Level) -> bool {
(other.0 as usize) <= (self.0 as usize)
}
#[inline(always)]
fn gt(&self, other: &Level) -> bool {
(other.0 as usize) > (self.0 as usize)
}
#[inline(always)]
fn ge(&self, other: &Level) -> bool {
(other.0 as usize) >= (self.0 as usize)
}
}
impl Ord for Level {
#[inline(always)]
fn cmp(&self, other: &Self) -> cmp::Ordering {
(other.0 as usize).cmp(&(self.0 as usize))
}
}
impl PartialOrd<LevelFilter> for Level {
#[inline(always)]
fn partial_cmp(&self, other: &LevelFilter) -> Option<cmp::Ordering> {
Some(filter_as_usize(&other.0).cmp(&(self.0 as usize)))
}
#[inline(always)]
fn lt(&self, other: &LevelFilter) -> bool {
filter_as_usize(&other.0) < (self.0 as usize)
}
#[inline(always)]
fn le(&self, other: &LevelFilter) -> bool {
filter_as_usize(&other.0) <= (self.0 as usize)
}
#[inline(always)]
fn gt(&self, other: &LevelFilter) -> bool {
filter_as_usize(&other.0) > (self.0 as usize)
}
#[inline(always)]
fn ge(&self, other: &LevelFilter) -> bool {
filter_as_usize(&other.0) >= (self.0 as usize)
}
}
#[inline(always)]
fn filter_as_usize(x: &Option<Level>) -> usize {
match x {
Some(Level(f)) => *f as usize,
None => LevelFilter::OFF_USIZE,
}
}
impl PartialEq<Level> for LevelFilter {
#[inline(always)]
fn eq(&self, other: &Level) -> bool {
filter_as_usize(&self.0) == other.0 as usize
}
}
impl PartialOrd for LevelFilter {
#[inline(always)]
fn partial_cmp(&self, other: &LevelFilter) -> Option<cmp::Ordering> {
Some(self.cmp(other))
}
#[inline(always)]
fn lt(&self, other: &LevelFilter) -> bool {
filter_as_usize(&other.0) < filter_as_usize(&self.0)
}
#[inline(always)]
fn le(&self, other: &LevelFilter) -> bool {
filter_as_usize(&other.0) <= filter_as_usize(&self.0)
}
#[inline(always)]
fn gt(&self, other: &LevelFilter) -> bool {
filter_as_usize(&other.0) > filter_as_usize(&self.0)
}
#[inline(always)]
fn ge(&self, other: &LevelFilter) -> bool {
filter_as_usize(&other.0) >= filter_as_usize(&self.0)
}
}
impl Ord for LevelFilter {
#[inline(always)]
fn cmp(&self, other: &Self) -> cmp::Ordering {
filter_as_usize(&other.0).cmp(&filter_as_usize(&self.0))
}
}
impl PartialOrd<Level> for LevelFilter {
#[inline(always)]
fn partial_cmp(&self, other: &Level) -> Option<cmp::Ordering> {
Some((other.0 as usize).cmp(&filter_as_usize(&self.0)))
}
#[inline(always)]
fn lt(&self, other: &Level) -> bool {
(other.0 as usize) < filter_as_usize(&self.0)
}
#[inline(always)]
fn le(&self, other: &Level) -> bool {
(other.0 as usize) <= filter_as_usize(&self.0)
}
#[inline(always)]
fn gt(&self, other: &Level) -> bool {
(other.0 as usize) > filter_as_usize(&self.0)
}
#[inline(always)]
fn ge(&self, other: &Level) -> bool {
(other.0 as usize) >= filter_as_usize(&self.0)
}
}
#[cfg(test)]
mod tests {
use super::*;
use crate::stdlib::mem;
#[test]
fn level_from_str() {
@ -358,4 +806,53 @@ mod tests {
assert_eq!("4".parse::<Level>().unwrap(), Level::DEBUG);
assert!("0".parse::<Level>().is_err())
}
#[test]
fn filter_level_conversion() {
let mapping = [
(LevelFilter::OFF, None),
(LevelFilter::ERROR, Some(Level::ERROR)),
(LevelFilter::WARN, Some(Level::WARN)),
(LevelFilter::INFO, Some(Level::INFO)),
(LevelFilter::DEBUG, Some(Level::DEBUG)),
(LevelFilter::TRACE, Some(Level::TRACE)),
];
for (filter, level) in mapping.iter() {
assert_eq!(filter.clone().into_level(), *level);
if let Some(level) = level {
assert_eq!(LevelFilter::from_level(level.clone()), *filter);
}
}
}
#[test]
fn level_filter_is_usize_sized() {
assert_eq!(
mem::size_of::<LevelFilter>(),
mem::size_of::<usize>(),
"`LevelFilter` is no longer `usize`-sized! global MAX_LEVEL may now be invalid!"
)
}
#[test]
fn level_filter_reprs() {
let mapping = [
(LevelFilter::OFF, LevelInner::Error as usize + 1),
(LevelFilter::ERROR, LevelInner::Error as usize),
(LevelFilter::WARN, LevelInner::Warn as usize),
(LevelFilter::INFO, LevelInner::Info as usize),
(LevelFilter::DEBUG, LevelInner::Debug as usize),
(LevelFilter::TRACE, LevelInner::Trace as usize),
];
for &(ref filter, expected) in &mapping {
let repr = unsafe {
// safety: The entire purpose of this test is to assert that the
// actual repr matches what we expect it to be --- we're testing
// that *other* unsafe code is sound using the transmuted value.
// We're not going to do anything with it that might be unsound.
mem::transmute::<_, usize>(filter.clone())
};
assert_eq!(expected, repr, "repr changed for {:?}", filter)
}
}
}

29
tracing-core/src/subscriber.rs
View File

@ -1,5 +1,5 @@
//! Subscribers collect and record trace data.
use crate::{span, Event, Metadata};
use crate::{span, Event, LevelFilter, Metadata};
use crate::stdlib::any::{Any, TypeId};
@ -167,6 +167,33 @@ pub trait Subscriber: 'static {
/// [`register_callsite`]: #method.register_callsite
fn enabled(&self, metadata: &Metadata<'_>) -> bool;
/// Returns the highest [verbosity level][level] that this `Subscriber` will
/// enable, or `None`, if the subscriber does not implement level-based
/// filtering or chooses not to implement this method.
///
/// If this method returns a [`Level`][level], it will be used as a hint to
/// determine the most verbose level that will be enabled. This will allow
/// spans and events which are more verbose than that level to be skipped
/// more efficiently. Subscribers which perform filtering are strongly
/// encouraged to provide an implementation of this method.
///
/// If the maximum level the subscriber will enable can change over the
/// course of its lifetime, it is free to return a different value from
/// multiple invocations of this method. However, note that changes in the
/// maximum level will **only** be reflected after the callsite [`Interest`]
/// cache is rebuilt, by calling the [`callsite::rebuild_interest_cache`][rebuild]
/// function. Therefore, if the subscriber will change the value returned by
/// this method, it is responsible for ensuring that
/// [`rebuild_interest_cache`][rebuild] is called after the value of the max
/// level changes.
///
/// [level]: ../struct.Level.html
/// [`Interest`]: struct.Interest.html
/// [rebuild]: ../callsite/fn.rebuild_interest_cache.html
fn max_level_hint(&self) -> Option<LevelFilter> {
None
}
/// Visit the construction of a new span, returning a new [span ID] for the
/// span being constructed.
///

2
tracing-subscriber/Cargo.toml
View File

@ -31,7 +31,7 @@ registry = ["sharded-slab"]
json = ["tracing-serde", "serde", "serde_json"]
[dependencies]
tracing-core = { path = "../tracing-core", version = "0.1.2" }
tracing-core = { path = "../tracing-core", version = "0.1.12" }
# only required by the filter feature
matchers = { optional = true, version = "0.0.1" }

7
tracing-subscriber/src/filter/env/mod.rs vendored
View File

@ -277,6 +277,13 @@ impl<S: Subscriber> Layer<S> for EnvFilter {
}
}
fn max_level_hint(&self) -> Option<LevelFilter> {
std::cmp::max(
self.statics.max_level.clone().into(),
self.dynamics.max_level.clone().into(),
)
}
fn enabled(&self, metadata: &Metadata<'_>, _: Context<'_, S>) -> bool {
let level = metadata.level();

151
tracing-subscriber/src/filter/level.rs
View File

@ -1,52 +1,13 @@
use std::{cmp::Ordering, fmt, str::FromStr};
use tracing_core::{
subscriber::{Interest, Subscriber},
Level, Metadata,
Metadata,
};
/// A filter which is enabled for a given verbosity level and below.
#[derive(Clone, Eq, PartialEq, Ord, PartialOrd)]
pub struct LevelFilter(Inner);
#[derive(Clone, Eq, PartialEq, Ord, PartialOrd)]
enum Inner {
Off,
Level(Level),
}
/// Indicates that a string could not be parsed to a valid level.
#[derive(Clone, Debug)]
pub struct ParseError(());
#[allow(unreachable_pub)] // https://github.com/rust-lang/rust/issues/57411
pub use tracing_core::metadata::{LevelFilter, ParseLevelFilterError as ParseError};
// === impl LevelFilter ===
impl LevelFilter {
/// The "off" level.
///
/// Designates that trace instrumentation should be completely disabled.
pub const OFF: LevelFilter = LevelFilter(Inner::Off);
/// The "error" level.
///
/// Designates very serious errors.
pub const ERROR: LevelFilter = LevelFilter(Inner::Level(Level::ERROR));
/// The "warn" level.
///
/// Designates hazardous situations.
pub const WARN: LevelFilter = LevelFilter(Inner::Level(Level::WARN));
/// The "info" level.
///
/// Designates useful information.
pub const INFO: LevelFilter = LevelFilter(Inner::Level(Level::INFO));
/// The "debug" level.
///
/// Designates lower priority information.
pub const DEBUG: LevelFilter = LevelFilter(Inner::Level(Level::DEBUG));
/// The "trace" level.
///
/// Designates very low priority, often extremely verbose, information.
pub const TRACE: LevelFilter = LevelFilter(Inner::Level(Level::TRACE));
}
impl<S: Subscriber> crate::Layer<S> for LevelFilter {
fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest {
if self >= metadata.level() {
@ -59,110 +20,8 @@ impl<S: Subscriber> crate::Layer<S> for LevelFilter {
fn enabled(&self, metadata: &Metadata<'_>, _: crate::layer::Context<'_, S>) -> bool {
self >= metadata.level()
}
}
impl PartialEq<Level> for LevelFilter {
fn eq(&self, other: &Level) -> bool {
match self.0 {
Inner::Off => false,
Inner::Level(ref level) => level == other,
}
fn max_level_hint(&self) -> Option<LevelFilter> {
self.clone().into()
}
}
impl PartialOrd<Level> for LevelFilter {
fn partial_cmp(&self, other: &Level) -> Option<Ordering> {
match self.0 {
Inner::Off => Some(Ordering::Less),
Inner::Level(ref level) => level.partial_cmp(other),
}
}
}
impl fmt::Display for LevelFilter {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
match self.0 {
Inner::Off => f.pad("off"),
Inner::Level(Level::ERROR) => f.pad("error"),
Inner::Level(Level::WARN) => f.pad("warn"),
Inner::Level(Level::INFO) => f.pad("info"),
Inner::Level(Level::DEBUG) => f.pad("debug"),
Inner::Level(Level::TRACE) => f.pad("trace"),
}
}
}
impl fmt::Debug for LevelFilter {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
match self.0 {
Inner::Off => f.pad("LevelFilter::OFF"),
Inner::Level(Level::ERROR) => f.pad("LevelFilter::ERROR"),
Inner::Level(Level::WARN) => f.pad("LevelFilter::WARN"),
Inner::Level(Level::INFO) => f.pad("LevelFilter::INFO"),
Inner::Level(Level::DEBUG) => f.pad("LevelFilter::DEBUG"),
Inner::Level(Level::TRACE) => f.pad("LevelFilter::TRACE"),
}
}
}
impl FromStr for LevelFilter {
type Err = ParseError;
fn from_str(from: &str) -> Result<Self, Self::Err> {
from.parse::<usize>()
.ok()
.and_then(|num| match num {
0 => Some(LevelFilter::OFF),
1 => Some(LevelFilter::ERROR),
2 => Some(LevelFilter::WARN),
3 => Some(LevelFilter::INFO),
4 => Some(LevelFilter::DEBUG),
5 => Some(LevelFilter::TRACE),
_ => None,
})
.or_else(|| match from {
"" => Some(LevelFilter::ERROR),
s if s.eq_ignore_ascii_case("error") => Some(LevelFilter::ERROR),
s if s.eq_ignore_ascii_case("warn") => Some(LevelFilter::WARN),
s if s.eq_ignore_ascii_case("info") => Some(LevelFilter::INFO),
s if s.eq_ignore_ascii_case("debug") => Some(LevelFilter::DEBUG),
s if s.eq_ignore_ascii_case("trace") => Some(LevelFilter::TRACE),
s if s.eq_ignore_ascii_case("off") => Some(LevelFilter::OFF),
_ => None,
})
.ok_or_else(|| ParseError(()))
}
}
impl Into<Option<Level>> for LevelFilter {
fn into(self) -> Option<Level> {
match self.0 {
Inner::Off => None,
Inner::Level(l) => Some(l),
}
}
}
impl From<Option<Level>> for LevelFilter {
fn from(level: Option<Level>) -> Self {
match level {
Some(level) => LevelFilter(Inner::Level(level)),
None => LevelFilter(Inner::Off),
}
}
}
impl From<Level> for LevelFilter {
fn from(level: Level) -> Self {
LevelFilter(Inner::Level(level))
}
}
// === impl ParseError ===
impl fmt::Display for ParseError {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
write!(f, "invalid level`")
}
}
impl std::error::Error for ParseError {}

14
tracing-subscriber/src/layer.rs
View File

@ -3,7 +3,7 @@ use tracing_core::{
metadata::Metadata,
span,
subscriber::{Interest, Subscriber},
Event,
Event, LevelFilter,
};
#[cfg(feature = "registry")]
@ -305,6 +305,14 @@ where
let _ = (attrs, id, ctx);
}
// TODO(eliza): do we want this to be a public API? If we end up moving
// filtering layers to a separate trait, we may no longer want `Layer`s to
// be able to participate in max level hinting...
#[doc(hidden)]
fn max_level_hint(&self) -> Option<LevelFilter> {
None
}
/// Notifies this layer that a span with the given `Id` recorded the given
/// `values`.
// Note: it's unclear to me why we'd need the current span in `record` (the
@ -618,6 +626,10 @@ where
}
}
fn max_level_hint(&self) -> Option<LevelFilter> {
std::cmp::max(self.layer.max_level_hint(), self.inner.max_level_hint())
}
fn new_span(&self, span: &span::Attributes<'_>) -> span::Id {
let id = self.inner.new_span(span);
self.layer.new_span(span, &id, self.ctx());

7
tracing/CHANGELOG.md
View File

@ -1,3 +1,10 @@
# 0.1.18 (UNRELEASED)
### Fixed
- Fixed a bug where `LevelFilter::OFF` (and thus also the `static_max_level_off`
feature flag) would enable *all* traces, rather than *none* (#853)
# 0.1.17 (July 22, 2020)
### Changed

2
tracing/Cargo.toml
View File

@ -27,7 +27,7 @@ keywords = ["logging", "tracing", "metrics", "async"]
edition = "2018"
[dependencies]
tracing-core = { path = "../tracing-core", version = "0.1.11", default-features = false }
tracing-core = { path = "../tracing-core", version = "0.1.12", default-features = false }
log = { version = "0.4", optional = true }
tracing-attributes = { path = "../tracing-attributes", version = "0.1.9", optional = true }
cfg-if = "0.1.10"

105
tracing/src/level_filters.rs
View File

@ -37,87 +37,7 @@
//! *Compiler support: requires rustc 1.39+*
//!
//! [`log` crate]: https://docs.rs/log/0.4.6/log/#compile-time-filters
use crate::stdlib::cmp::Ordering;
use tracing_core::Level;
/// A filter comparable to trace verbosity `Level`.
///
/// If a `Level` is considered less than a `LevelFilter`, it should be
/// considered disabled; if greater than or equal to the `LevelFilter`, that
/// level is enabled.
///
/// Note that this is essentially identical to the `Level` type, but with the
/// addition of an `OFF` level that completely disables all trace
/// instrumentation.
#[derive(Clone, Debug, Eq, PartialEq, Ord, PartialOrd)]
pub struct LevelFilter(Option<Level>);
impl From<Level> for LevelFilter {
#[inline]
fn from(level: Level) -> Self {
Self::from_level(level)
}
}
impl LevelFilter {
/// The "off" level.
///
/// Designates that trace instrumentation should be completely disabled.
pub const OFF: LevelFilter = LevelFilter(None);
/// The "error" level.
///
/// Designates very serious errors.
pub const ERROR: LevelFilter = LevelFilter::from_level(Level::ERROR);
/// The "warn" level.
///
/// Designates hazardous situations.
pub const WARN: LevelFilter = LevelFilter::from_level(Level::WARN);
/// The "info" level.
///
/// Designates useful information.
pub const INFO: LevelFilter = LevelFilter::from_level(Level::INFO);
/// The "debug" level.
///
/// Designates lower priority information.
pub const DEBUG: LevelFilter = LevelFilter::from_level(Level::DEBUG);
/// The "trace" level.
///
/// Designates very low priority, often extremely verbose, information.
pub const TRACE: LevelFilter = LevelFilter(Some(Level::TRACE));
/// Returns a `LevelFilter` that enables spans and events with verbosity up
/// to and including `level`.
pub const fn from_level(level: Level) -> Self {
Self(Some(level))
}
/// Returns the most verbose [`Level`] that this filter accepts, or `None`
/// if it is [`OFF`].
///
/// [`Level`]: ../struct.Level.html
/// [`OFF`]: #associatedconstant.OFF
pub const fn into_level(self) -> Option<Level> {
self.0
}
}
impl PartialEq<LevelFilter> for Level {
fn eq(&self, other: &LevelFilter) -> bool {
match other.0 {
None => false,
Some(ref level) => self.eq(level),
}
}
}
impl PartialOrd<LevelFilter> for Level {
fn partial_cmp(&self, other: &LevelFilter) -> Option<Ordering> {
match other.0 {
None => Some(Ordering::Less),
Some(ref level) => self.partial_cmp(level),
}
}
}
pub use tracing_core::{metadata::ParseLevelFilterError, LevelFilter};
/// The statically configured maximum trace level.
///
@ -159,26 +79,3 @@ cfg_if! {
const MAX_LEVEL: LevelFilter = LevelFilter::TRACE;
}
}
#[cfg(test)]
mod tests {
use super::*;
#[test]
fn filter_level_conversion() {
let mapping = [
(LevelFilter::OFF, None),
(LevelFilter::ERROR, Some(Level::ERROR)),
(LevelFilter::WARN, Some(Level::WARN)),
(LevelFilter::INFO, Some(Level::INFO)),
(LevelFilter::DEBUG, Some(Level::DEBUG)),
(LevelFilter::TRACE, Some(Level::TRACE)),
];
for (filter, level) in mapping.iter() {
assert_eq!(filter.clone().into_level(), *level);
if let Some(level) = level {
assert_eq!(LevelFilter::from_level(level.clone()), *filter);
}
}
}
}

8
tracing/src/macros.rs
View File

@ -1840,11 +1840,15 @@ macro_rules! callsite {
}
#[macro_export]
// TODO: determine if this ought to be public API?
// TODO: determine if this ought to be public API?`
// TODO(eliza): is the `has_been_set` check still necessary? the max
// level check should be equivalent...
#[doc(hidden)]
macro_rules! level_enabled {
($lvl:expr) => {
$crate::dispatcher::has_been_set() && $lvl <= $crate::level_filters::STATIC_MAX_LEVEL
$crate::dispatcher::has_been_set()
&& $lvl <= $crate::level_filters::STATIC_MAX_LEVEL
&& $lvl <= $crate::level_filters::LevelFilter::current()
};
}

2
tracing/test_static_max_level_features/tests/test.rs
View File

@ -33,7 +33,7 @@ impl Subscriber for TestSubscriber {
fn exit(&self, _span: &Id) {}
}
#[cfg(test)]
#[test]
fn test_static_max_level_features() {
let me = Arc::new(State {
last_level: Mutex::new(None),