Summary

Apps that emit many info events may filter them out, either through processor interest or with an event sampler. This adds the observed_benchmarks/emit_filtering group, which measures what one emit! of an info event (SimpleLogEvent) costs when no processor receives it, what an event sampler adds to an emit, and what the same filtering costs with tracing.

observed, filtered out (emit_filtered_out):

• Processors not interested: the sink has no sampler, and every processor's is_interested returns false. Runs with 1 and 3 processors.
• Processors not interested, sampler keeps: the same with 1 processor, plus a sampler that returns EventSamplingDecision::Continue.
• Sampler drops: every processor wants the event, but the sink's sampler returns EventSamplingDecision::Drop. Runs with 1 and 3 processors.

observed, delivered (emit_delivered) to one processor whose process does nothing, so only observed's own delivery work is measured:

• Interested processor, without and with a sampler that keeps the event.

tracing (tracing_filtered_out, tracing_delivered): the same info log with tracing::info!. Each processor is a layer that does nothing, behind a per-layer filter that tracing asks on every event, as observed asks its processors. tracing has no event sampler, so only the setups without one are compared. One extra case, level_filtered_one_processor, uses LevelFilter::WARN, tracing's built-in filter by level. Each case installs its subscriber as the thread's scoped default, because the process-wide default can be set only once.

Comparing each "sampler keeps" case with the same setup without a sampler gives the sampler's overhead. The sink calls its sampler once per emit, before asking any processor (SingleSinkState::sample_and_ask_processors in crates/observed/src/sink/core.rs). Without a sampler, or when the sampler keeps the event, the sink asks every processor; a dropping sampler stops before any processor is asked. The 3-processor cases show that difference.

Results

Apple M3 Max, macOS 27.0.1, rustc 1.97.1. Time per emit is the median of four Criterion runs of the same build. The runs differed by up to 3.6 ns for observed's delivered cases, 1.5 ns for the tracing cases and 0.8 ns for observed's filtered-out cases. In earlier builds, adding or removing other benchmarks also moved identical cases by up to 0.5 ns. Small differences between cases are therefore not reliable.

"—" means the setup does not exist in that library: tracing has no sampler, and observed has no level filter. No case allocates. Delivered events go to a processor or layer that does nothing with them.

For reference, existing benchmarks of the same event from the same runs:

Findings

• observed never builds an event that is filtered out; a throwaway run with call counters confirmed this.
• A sampler that keeps the event adds about 0.5 ns: in each of the four runs, the two filtered-out cases with and without it differed by 0.44 to 0.51 ns. The two delivered cases differed by 0.4 to 1.8 ns, but they also varied by up to 3.6 ns between runs. This is what observed spends calling the sampler; a real sampler's own decision logic adds to it.
• tracing's level filter drops an info event in 1.10 ns, because tracing::info! first compares the event's level with the highest level any subscriber wants, before asking any filter. observed has no such check; it asks the sampler or every processor on each emit.

Why delivery costs more in observed

For every delivered event, observed records the current time: SingleSinkState::dispatch (crates/observed/src/sink/core.rs) calls self.clock.system_time(), which with the default clock is SystemTime::now() (SimpleClock::system_time in crates/tick/src/simple_clock.rs). tracing reads no clock while delivering an event; that is left to the layer, and the layer in these benchmarks does nothing.

Two throwaway builds, not part of this PR, measured each library with and without one SystemTime::now() per event. The first added a tracing case whose layer calls SystemTime::now() for every event; the second also replaced observed's clock read with a fixed time. Each number is the average of two runs; observed without a clock read comes from the second build, the other three from the first. These runs are separate from the table above, so their numbers differ slightly from it.

Doing the same work, the two cost the same: they differ by under 1 ns, less than these cases vary between runs. A real tracing log layer pays this cost too: by default, tracing-subscriber's fmt layer calls SystemTime::now() for every event (impl FormatTime for SystemTime in tracing-subscriber's src/fmt/time/mod.rs).

Validation

• just anvil-clippy, just anvil-fmt, just anvil-spellcheck
• cargo bench -p observed --features test-util --bench observed_benchmarks -- --test
• cargo bench -p observed --features test-util --bench observed_benchmarks -- --criterion --criterion-arg 'emit_filtering|emit_to_noop_sink|emit_pipeline/simple_log_2_fields' --no-output --no-baseline (four runs)
• cargo bench -p observed --features test-util --bench observed_benchmarks -- --allocations --criterion-arg 'emit_filtering|emit_to_noop_sink|emit_pipeline/simple_log_2_fields' --no-output --no-baseline

Notes

• The new group pushed criterion_benchmarks past Clippy's 100-line limit, so it now has #[expect(clippy::too_many_lines, ...)], as other bench registration functions in the repo do.
• tracing and tracing-subscriber become dev-dependencies of observed. Both were already workspace dependencies, so Cargo.lock only gains the two edges.
• The tracing cases use a scoped subscriber. In a separate program with a process-wide subscriber, tracing measured 8.6 ns with the processor declining and 9.4 ns delivered, which leads to the same conclusions.
• Gungraun instruction counts were not collected; Gungraun runs only on Linux.