subscriber: fix incorrect filter selection + improve filter performan…

…ce (#583)

## Motivation

The benchmarks added in #581 indicate that `tracing-subscriber`'s 
`EnvFilter` has significant overhead when filtering events generated
from `log` records that is not present when filtering native `tracing` 
events.

Additionally, the behavior of `EnvFilter` differs from the `env_logger`
crate it emulates: when a less specific filter is more verbose than a
more specific filter, the more verbose filter is used. For example:

```
RUST_LOG=debug,tokio_postgres=info,hyper::server::response=info
```

* With `env_logger` - treat all targets as DEBUG *except* for 
  `tokio_postgres` and `hyper::server::response`

* With `EnvFilter::from_default_env()` - treat all targets as DEBUG.
  This then overrides the explicit setting of INFO for the other two,
  so they are DEBUG as well.

(see #512)

## Solution

This branch makes some performance optimizations to filtering, to
improve performance with `log` events significantly. In particular, it
makes the following changes:

* Code was previously added to record the maximum level enabled by
  the static and dynamic directive sets. This would allow a fast path
  for skipping events that no directive will ever enable. However, this
  currently is never actually checked, so we always have to check an
  event against every directive. I've fixed that.

* If there are no dynamic directives that would require looking at the
  dynamic span state (a TLS value), we now avoid looking at TLS.

* Finally, I've fixed #512, by changing `enabled` to select the _most_
  specific static filter, rather than by checking _every_ filter until
  it finds something that enables the span. In addition to making the
  behaviour correct, this also improves performance: it means we only 
  iterate over the statics until we find something that cares about an
  event, and then return. In the previous implementation (of incorrect 
  behavior), we would break the iteration if the event was enabled, but
  never break iteration if it was disabled. Now, we can return early.
  This should improve performance significantly with a large number of 
  filters.

## Benchmark Results

Performance in the `filter_log` benchmark is significantly improved in
most cases, while performance in the `filter` benchmark (for filtering
`tracing` events) is about the same as master, but significantly better
than `filter_log` across the board. This is expected, since the
`tracing` events in `filter` benchmark can (in most cases) participate
in the callsite cache, while the `log` events cannot. Therefore, the
`filter` benchmarks with static filters are measuring the overhead of a
single filter hit + multiple callsite cache loads, while the
`filter_log` benchmarks are always measuring an actual filter hit.


<details>
<summary>Benchmark results (vs master):</summary>

```console
eliza@ares:~/tracing$ cargo bench -p tracing-subscriber --bench filter --bench filter_log
   Compiling tracing-subscriber v0.2.0 (/home/eliza/tracing/tracing-subscriber)
    Finished bench [optimized] target(s) in 9.86s
     Running target/release/deps/filter-b804f035b8022c0d
static/baseline_single_threaded
                        time:   [109.11 ns 109.21 ns 109.32 ns]
                        change: [-6.3289% -4.9555% -3.6799%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 11 outliers among 100 measurements (11.00%)
  2 (2.00%) high mild
  9 (9.00%) high severe
static/single_threaded  time:   [62.942 ns 63.023 ns 63.150 ns]
                        change: [-0.1370% +0.0191% +0.2011%] (p = 0.83 > 0.05)
                        No change in performance detected.
Found 15 outliers among 100 measurements (15.00%)
  1 (1.00%) low mild
  6 (6.00%) high mild
  8 (8.00%) high severe
static/enabled_one      time:   [28.745 ns 28.764 ns 28.789 ns]
                        change: [-0.2144% -0.0862% +0.0283%] (p = 0.18 > 0.05)
                        No change in performance detected.
Found 13 outliers among 100 measurements (13.00%)
  1 (1.00%) low mild
  4 (4.00%) high mild
  8 (8.00%) high severe
static/enabled_many     time:   [28.765 ns 28.827 ns 28.912 ns]
                        change: [-0.0864% +0.2092% +0.5574%] (p = 0.25 > 0.05)
                        No change in performance detected.
Found 16 outliers among 100 measurements (16.00%)
  5 (5.00%) high mild
  11 (11.00%) high severe
static/disabled_level_one
                        time:   [4.1104 ns 4.1134 ns 4.1170 ns]
                        change: [+0.0402% +0.1317% +0.2300%] (p = 0.01 < 0.05)
                        Change within noise threshold.
Found 13 outliers among 100 measurements (13.00%)
  5 (5.00%) high mild
  8 (8.00%) high severe
static/disabled_level_many
                        time:   [3.6496 ns 3.6530 ns 3.6573 ns]
                        change: [-0.2017% -0.0164% +0.1271%] (p = 0.86 > 0.05)
                        No change in performance detected.
Found 15 outliers among 100 measurements (15.00%)
  1 (1.00%) low mild
  1 (1.00%) high mild
  13 (13.00%) high severe
static/disabled_one     time:   [3.6496 ns 3.6517 ns 3.6543 ns]
                        change: [-0.1254% +0.1413% +0.5468%] (p = 0.52 > 0.05)
                        No change in performance detected.
Found 14 outliers among 100 measurements (14.00%)
  1 (1.00%) low mild
  1 (1.00%) high mild
  12 (12.00%) high severe
static/disabled_many    time:   [3.6501 ns 3.6518 ns 3.6538 ns]
                        change: [-0.0351% +0.0331% +0.1054%] (p = 0.35 > 0.05)
                        No change in performance detected.
Found 15 outliers among 100 measurements (15.00%)
  2 (2.00%) low mild
  2 (2.00%) high mild
  11 (11.00%) high severe
static/baseline_multithreaded
                        time:   [7.6316 us 7.8421 us 8.0892 us]
                        change: [-1.1385% +2.9646% +7.3036%] (p = 0.18 > 0.05)
                        No change in performance detected.
Found 7 outliers among 100 measurements (7.00%)
  5 (5.00%) high mild
  2 (2.00%) high severe
static/multithreaded    time:   [7.5579 us 7.7286 us 7.9126 us]
                        change: [+0.2480% +3.6935% +7.1400%] (p = 0.04 < 0.05)
                        Change within noise threshold.
Found 4 outliers among 100 measurements (4.00%)
  3 (3.00%) high mild
  1 (1.00%) high severe

dynamic/baseline_single_threaded
                        time:   [245.73 ns 246.12 ns 246.67 ns]
                        change: [-2.6694% -2.3670% -2.0569%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 20 outliers among 100 measurements (20.00%)
  7 (7.00%) low mild
  2 (2.00%) high mild
  11 (11.00%) high severe
dynamic/single_threaded time:   [1.1532 us 1.1550 us 1.1568 us]
                        change: [+0.2317% +0.4117% +0.5707%] (p = 0.00 < 0.05)
                        Change within noise threshold.
Found 3 outliers among 100 measurements (3.00%)
  2 (2.00%) high mild
  1 (1.00%) high severe
dynamic/baseline_multithreaded
                        time:   [7.6121 us 7.7931 us 7.9882 us]
                        change: [-4.3847% +0.2323% +4.8431%] (p = 0.92 > 0.05)
                        No change in performance detected.
Found 3 outliers among 100 measurements (3.00%)
  1 (1.00%) low mild
  1 (1.00%) high mild
  1 (1.00%) high severe
dynamic/multithreaded   time:   [8.0848 us 8.2926 us 8.5161 us]
                        change: [-2.0820% +1.4262% +4.9321%] (p = 0.42 > 0.05)
                        No change in performance detected.
Found 5 outliers among 100 measurements (5.00%)
  1 (1.00%) low mild
  4 (4.00%) high mild

mixed/disabled          time:   [67.544 ns 67.623 ns 67.716 ns]
                        change: [+4.0220% +4.3608% +4.6472%] (p = 0.00 < 0.05)
                        Performance has regressed.
Found 12 outliers among 100 measurements (12.00%)
  1 (1.00%) low mild
  1 (1.00%) high mild
  10 (10.00%) high severe
mixed/disabled_by_level time:   [26.704 ns 26.743 ns 26.785 ns]
                        change: [-51.833% -51.737% -51.632%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 4 outliers among 100 measurements (4.00%)
  1 (1.00%) low mild
  2 (2.00%) high mild
  1 (1.00%) high severe

     Running target/release/deps/filter_log-b8cedd42cccfa727
log/static/baseline_single_threaded
                        time:   [459.87 ns 460.05 ns 460.28 ns]
                        change: [-4.4236% -4.3735% -4.3170%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 13 outliers among 100 measurements (13.00%)
  1 (1.00%) low severe
  4 (4.00%) low mild
  1 (1.00%) high mild
  7 (7.00%) high severe
log/static/single_threaded
                        time:   [469.18 ns 470.12 ns 471.08 ns]
                        change: [-12.406% -12.037% -11.759%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 1 outliers among 100 measurements (1.00%)
  1 (1.00%) high severe
log/static/enabled_one  time:   [154.79 ns 155.08 ns 155.54 ns]
                        change: [-10.717% -10.585% -10.436%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 11 outliers among 100 measurements (11.00%)
  1 (1.00%) low mild
  4 (4.00%) high mild
  6 (6.00%) high severe
log/static/enabled_many time:   [229.55 ns 229.69 ns 229.86 ns]
                        change: [-11.433% -11.076% -10.828%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 4 outliers among 100 measurements (4.00%)
  3 (3.00%) high mild
  1 (1.00%) high severe
log/static/disabled_level_one
                        time:   [57.489 ns 57.518 ns 57.557 ns]
                        change: [-20.363% -20.247% -20.155%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 7 outliers among 100 measurements (7.00%)
  2 (2.00%) high mild
  5 (5.00%) high severe
log/static/disabled_level_many
                        time:   [57.486 ns 57.515 ns 57.554 ns]
                        change: [-48.696% -48.652% -48.610%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 6 outliers among 100 measurements (6.00%)
  1 (1.00%) high mild
  5 (5.00%) high severe
log/static/disabled_one time:   [68.872 ns 68.902 ns 68.941 ns]
                        change: [-4.0195% -3.8865% -3.7487%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 10 outliers among 100 measurements (10.00%)
  2 (2.00%) low mild
  8 (8.00%) high severe
log/static/disabled_many
                        time:   [103.10 ns 103.38 ns 103.72 ns]
                        change: [-5.8728% -5.6128% -5.3436%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 6 outliers among 100 measurements (6.00%)
  3 (3.00%) high mild
  3 (3.00%) high severe
log/static/baseline_multithreaded
                        time:   [7.5054 us 7.7234 us 7.9713 us]
                        change: [-4.8650% -1.5881% +2.0839%] (p = 0.37 > 0.05)
                        No change in performance detected.
Found 4 outliers among 100 measurements (4.00%)
  3 (3.00%) high mild
  1 (1.00%) high severe
log/static/multithreaded
                        time:   [7.6285 us 7.7574 us 7.8967 us]
                        change: [-4.5998% -2.0115% +0.5929%] (p = 0.14 > 0.05)
                        No change in performance detected.
Found 1 outliers among 100 measurements (1.00%)
  1 (1.00%) high mild

log/dynamic/baseline_single_threaded
                        time:   [603.16 ns 603.55 ns 603.96 ns]
                        change: [-6.9548% -6.7858% -6.6651%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 20 outliers among 100 measurements (20.00%)
  3 (3.00%) high mild
  17 (17.00%) high severe
log/dynamic/single_threaded
                        time:   [1.4624 us 1.4645 us 1.4669 us]
                        change: [+4.2866% +4.4193% +4.5763%] (p = 0.00 < 0.05)
                        Performance has regressed.
Found 4 outliers among 100 measurements (4.00%)
  1 (1.00%) high mild
  3 (3.00%) high severe
log/dynamic/baseline_multithreaded
                        time:   [7.6292 us 7.8527 us 8.1103 us]
                        change: [-6.4268% -2.6258% +0.8495%] (p = 0.17 > 0.05)
                        No change in performance detected.
Found 9 outliers among 100 measurements (9.00%)
  1 (1.00%) low mild
  8 (8.00%) high mild
log/dynamic/multithreaded
                        time:   [8.0253 us 8.2673 us 8.5647 us]
                        change: [-3.4243% +0.5838% +5.0749%] (p = 0.79 > 0.05)
                        No change in performance detected.
Found 6 outliers among 100 measurements (6.00%)
  2 (2.00%) low mild
  1 (1.00%) high mild
  3 (3.00%) high severe

log/mixed/disabled      time:   [94.775 ns 94.825 ns 94.884 ns]
                        change: [-0.0623% +0.0665% +0.1997%] (p = 0.33 > 0.05)
                        No change in performance detected.
Found 11 outliers among 100 measurements (11.00%)
  2 (2.00%) low mild
  1 (1.00%) high mild
  8 (8.00%) high severe
log/mixed/disabled_by_level
                        time:   [59.763 ns 59.809 ns 59.873 ns]
                        change: [-26.225% -26.054% -25.852%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 12 outliers among 100 measurements (12.00%)
  1 (1.00%) low mild
  2 (2.00%) high mild
  9 (9.00%) high severe

```

</details>

<details>

<summary>Benchmark environment:</summary>

```console
eliza@ares:~/tracing$ uname -a
Linux ares 4.9.0-11-amd64 #1 SMP Debian 4.9.189-3+deb9u2 (2019-11-11) x86_64 GNU/Linux
eliza@ares:~/tracing$ rustc --version
rustc 1.41.0 (5e1a79984 2020-01-27)
eliza@ares:~/tracing$ lscpu
Architecture:          x86_64
CPU op-mode(s):        32-bit, 64-bit
Byte Order:            Little Endian
CPU(s):                40
On-line CPU(s) list:   0-39
Thread(s) per core:    2
Core(s) per socket:    10
Socket(s):             2
NUMA node(s):          2
Vendor ID:             GenuineIntel
CPU family:            6
Model:                 79
Model name:            Intel(R) Xeon(R) CPU E5-2630 v4 @ 2.20GHz
Stepping:              1
CPU MHz:               1879.077
CPU max MHz:           2200.0000
CPU min MHz:           1200.0000
BogoMIPS:              4390.06
Virtualization:        VT-x
L1d cache:             32K
L1i cache:             32K
L2 cache:              256K
L3 cache:              25600K
NUMA node0 CPU(s):     0-9,20-29
NUMA node1 CPU(s):     10-19,30-39
Flags:                 fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf pni pclmulqdq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch epb invpcid_single kaiser tpr_shadow vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 hle avx2 smep bmi2 erms invpcid rtm cqm rdseed adx smap intel_pt xsaveopt cqm_llc cqm_occup_llc cqm_mbm_total cqm_mbm_local dtherm arat pln pts
eliza@ares:~/tracing$
```

</details>

Fixes #512

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

tracing-subscriber/src/filter/env/directive.rs

@@ -39,7 +39,7 @@ pub(crate) type Statics = DirectiveSet<StaticDirective>;
 #[derive(Debug, PartialEq)]
 pub(crate) struct DirectiveSet<T> {
  directives: Vec<T>,
- max_level: LevelFilter,
+ pub(crate) max_level: LevelFilter,
 }
 
 pub(crate) type CallsiteMatcher = MatchSet<field::CallsiteMatch>;
@@ -406,6 +406,7 @@ impl<T: Match + Ord> DirectiveSet<T> {
  self.directives
  .iter()
  .filter(move |d| d.cares_about(metadata))
+ .rev()
  }
 
  pub(crate) fn add(&mut self, directive: T) {
@@ -482,7 +483,10 @@ impl Dynamics {
 impl Statics {
  pub(crate) fn enabled(&self, meta: &Metadata<'_>) -> bool {
  let level = meta.level();
- self.directives_for(meta).any(|d| d.level >= *level)
+ match self.directives_for(meta).next() {
+ Some(d) => d.level >= *level,
+ None => false,
+ }
  }
 }
 

tracing-subscriber/src/filter/env/mod.rs

@@ -96,7 +96,7 @@ use tracing_core::{
 pub struct EnvFilter {
  statics: directive::Statics,
  dynamics: directive::Dynamics,
-
+ has_dynamics: bool,
  by_id: RwLock<HashMap<span::Id, directive::SpanMatcher>>,
  by_cs: RwLock<HashMap<callsite::Identifier, directive::CallsiteMatcher>>,
 }
@@ -219,21 +219,24 @@ impl EnvFilter {
  if let Some(stat) = directive.to_static() {
  self.statics.add(stat)
  } else {
+ self.has_dynamics = true;
  self.dynamics.add(directive);
  }
  self
  }
 
  fn from_directives(directives: impl IntoIterator<Item = Directive>) -> Self {
  let (dynamics, mut statics) = Directive::make_tables(directives);
+ let has_dynamics = !dynamics.is_empty();
 
- if statics.is_empty() && dynamics.is_empty() {
+ if statics.is_empty() && !has_dynamics {
  statics.add(directive::StaticDirective::default());
  }
 
  Self {
  statics,
  dynamics,
+ has_dynamics,
  by_id: RwLock::new(HashMap::new()),
  by_cs: RwLock::new(HashMap::new()),
  }
@@ -245,17 +248,17 @@ impl EnvFilter {
  }
 
  fn base_interest(&self) -> Interest {
- if self.dynamics.is_empty() {
- Interest::never()
- } else {
+ if self.has_dynamics {
  Interest::sometimes()
+ } else {
+ Interest::never()
  }
  }
 }
 
 impl<S: Subscriber> Layer<S> for EnvFilter {
  fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest {
- if metadata.is_span() {
+ if self.has_dynamics && metadata.is_span() {
  // If this metadata describes a span, first, check if there is a
  // dynamic filter that should be constructed for it. If so, it
  // should always be enabled, since it influences filtering.
@@ -276,20 +279,35 @@ impl<S: Subscriber> Layer<S> for EnvFilter {
 
  fn enabled(&self, metadata: &Metadata<'_>, _: Context<'_, S>) -> bool {
  let level = metadata.level();
- SCOPE.with(|scope| {
- for filter in scope.borrow().iter() {
- if filter >= level {
- return true;
+
+ // is it possible for a dynamic filter directive to enable this event?
+ // if not, we can avoid the thread local access + iterating over the
+ // spans in the current scope.
+ if self.has_dynamics && self.dynamics.max_level >= *level {
+ let enabled_by_scope = SCOPE.with(|scope| {
+ for filter in scope.borrow().iter() {
+ if filter >= level {
+ return true;
+ }
  }
+ false
+ });
+ if enabled_by_scope {
+ return true;
  }
+ }
 
+ // is it possible for a static filter directive to enable this event?
+ if self.statics.max_level >= *level {
  // Otherwise, fall back to checking if the callsite is
  // statically enabled.
  // TODO(eliza): we *might* want to check this only if the `log`
  // feature is enabled, since if this is a `tracing` event with a
  // real callsite, it would already have been statically enabled...
- self.statics.enabled(metadata)
- })
+ return self.statics.enabled(metadata);
+ }
+
+ false
  }
 
  fn new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, _: Context<'_, S>) {