tracing-timing 0.6.0

Inter-event timing metrics on top of tracing.
Documentation
#![cfg(feature = "layer")]

use tracing::*;
use tracing_subscriber::{registry::Registry, Layer};
use tracing_timing::*;

// NOTE: leave this test first! it'll break if it moves
#[test]
fn by_name() {
    let s = Builder::default()
        .spans(group::ByName)
        .events(group::ByName)
        .layer(|| Histogram::new_with_max(200_000_000, 1).unwrap());
    let sid = s.downcaster();
    let d = Dispatch::new(s.with_subscriber(Registry::default()));
    sid.downcast(&d).unwrap().with_histograms(|_| {});
    let d2 = d.clone();
    std::thread::spawn(move || {
        dispatcher::with_default(&d2, || {
            trace_span!("foo").in_scope(|| {
                trace!("event");
            })
        });
    })
    .join()
    .unwrap();
    sid.downcast(&d).unwrap().with_histograms(|hs| {
        assert_eq!(hs.len(), 1);
        let hs = &hs["foo"];
        assert_eq!(hs.len(), 1);
        #[cfg(windows)]
        assert!(hs.contains_key("event tests\\layer.rs:21"));
        #[cfg(not(windows))]
        assert!(hs.contains_key("event tests/layer.rs:21"));
    })
}

#[test]
fn downcaster() {
    let s = Builder::default().layer(|| Histogram::new_with_max(200_000_000, 1).unwrap());
    let sid = s.downcaster();
    let sid2 = sid.clone();
    let d = Dispatch::new(s.with_subscriber(Registry::default()));

    // can downcast through a Downcaster
    sid.downcast(&d).unwrap();

    // can downcast through a cloned Downcaster
    sid2.downcast(&d).unwrap();
}

#[test]
fn by_target() {
    let s = Builder::default()
        .spans(group::ByTarget)
        .events(group::ByTarget)
        .layer(|| Histogram::new_with_max(200_000_000, 1).unwrap());
    let sid = s.downcaster();
    let d = Dispatch::new(s.with_subscriber(Registry::default()));
    let d2 = d.clone();
    std::thread::spawn(move || {
        dispatcher::with_default(&d2, || {
            trace_span!("foo").in_scope(|| {
                trace!(target: "e", "event");
            })
        })
    })
    .join()
    .unwrap();
    sid.downcast(&d).unwrap().with_histograms(|hs| {
        assert_eq!(hs.len(), 1);
        let hs = &hs["layer"];
        assert_eq!(hs.len(), 1);
        assert!(hs.contains_key("e"));
    })
}

#[test]
fn by_default() {
    let s = Builder::default().layer(|| Histogram::new_with_max(200_000_000, 1).unwrap());
    let sid = s.downcaster();
    let d = Dispatch::new(s.with_subscriber(Registry::default()));
    let d2 = d.clone();
    std::thread::spawn(move || {
        dispatcher::with_default(&d2, || {
            trace_span!("foo").in_scope(|| {
                trace!("fast");
                trace!("slow");
            })
        })
    })
    .join()
    .unwrap();
    sid.downcast(&d).unwrap().with_histograms(|hs| {
        assert_eq!(hs.len(), 1);
        let hs = &hs["foo"];
        assert_eq!(hs.len(), 2);
        assert!(hs.contains_key("fast"));
        assert!(hs.contains_key("slow"));
    })
}

#[test]
fn by_field() {
    let s = Builder::default()
        .spans(group::ByField::from("sf"))
        .events(group::ByField::from("ef"))
        .layer(|| Histogram::new_with_max(200_000_000, 1).unwrap());
    let sid = s.downcaster();
    let d = Dispatch::new(s.with_subscriber(Registry::default()));
    let d2 = d.clone();
    std::thread::spawn(move || {
        dispatcher::with_default(&d2, || {
            trace_span!("foo", sf = "span").in_scope(|| {
                trace!({ ef = "event1" }, "fast");
                trace!({ ef = "event2" }, "slow");
            })
        })
    })
    .join()
    .unwrap();
    sid.downcast(&d).unwrap().with_histograms(|hs| {
        assert_eq!(hs.len(), 1);
        let hs = &hs["span"];
        assert_eq!(hs.len(), 2);
        assert!(hs.contains_key("event1"));
        assert!(hs.contains_key("event2"));
    })
}

#[test]
fn custom_time() {
    let (time, mock) = quanta::Clock::mock();
    let s = Builder::default()
        .time(time)
        .layer(|| Histogram::new_with_bounds(1, 16, 3).unwrap());
    let sid = s.downcaster();
    let d = Dispatch::new(s.with_subscriber(Registry::default()));
    let d2 = d.clone();
    std::thread::spawn(move || {
        dispatcher::with_default(&d2, || {
            trace_span!("span").in_scope(|| {
                mock.increment(1);
                trace!("event1");
                mock.increment(2);
                trace!("event2");
                mock.decrement(1);
                trace!("event3");
            })
        })
    })
    .join()
    .unwrap();
    sid.downcast(&d).unwrap().force_synchronize();
    sid.downcast(&d).unwrap().with_histograms(|hs| {
        assert_eq!(hs.len(), 1);
        let hs = &hs["span"];
        assert_eq!(hs.len(), 3);
        assert!(hs.contains_key("event1"));
        assert!(hs.contains_key("event2"));
        assert_eq!(hs["event1"].max(), 1);
        assert_eq!(hs["event2"].max(), 2);
        // event3 "raced" with event2, and ended up recording "negative" time
        // in this case, event3's sample should be dropped.
        assert!(hs.contains_key("event3"));
        assert_eq!(hs["event3"].len(), 0);
    })
}

#[test]
fn event_order() {
    let s = Builder::default().layer(|| Histogram::new_with_max(200_000_000, 1).unwrap());
    let sid = s.downcaster();
    let d = Dispatch::new(s.with_subscriber(Registry::default()));
    let d2 = d.clone();
    std::thread::spawn(move || {
        dispatcher::with_default(&d2, || {
            trace_span!("span").in_scope(|| {
                trace!("first");
                trace!("second");
            })
        })
    })
    .join()
    .unwrap();
    sid.downcast(&d).unwrap().with_histograms(|hs| {
        assert_eq!(hs.len(), 1);
        let hs = &hs["span"];
        let mut it = hs.keys();
        assert_eq!(it.next().map(|s| &**s), Some("first"));
        assert_eq!(it.next().map(|s| &**s), Some("second"));
        assert_eq!(it.next(), None);
    })
}

#[test]
fn samples() {
    let s = Builder::default().layer(|| Histogram::new_with_max(1_000_000, 1).unwrap());
    let sid = s.downcaster();
    let d = Dispatch::new(s.with_subscriber(Registry::default()));
    let d2 = d.clone();
    let n = 100;
    std::thread::spawn(move || {
        dispatcher::with_default(&d2, || {
            for _ in 0..n {
                trace_span!("foo").in_scope(|| {
                    std::thread::sleep(std::time::Duration::from_millis(1));
                    trace!("fast");
                    std::thread::sleep(std::time::Duration::from_millis(5));
                    trace!("slow");
                })
            }
        })
    })
    .join()
    .unwrap();
    sid.downcast(&d).unwrap().force_synchronize();
    sid.downcast(&d).unwrap().with_histograms(|hs| {
        assert_eq!(hs.len(), 1);
        let hs = &hs["foo"];
        assert_eq!(hs.len(), 2);

        let h = &hs["fast"];
        // ~= 100µs
        assert_eq!(h.len(), n);
        assert!(h.value_at_quantile(0.5) > 200_000);
        assert!(h.value_at_quantile(0.5) < 5_000_000);

        let h = &hs["slow"];
        // ~= 500µs
        assert_eq!(h.len(), n);
        assert!(h.value_at_quantile(0.5) > 1_000_000);
        assert!(h.value_at_quantile(0.5) < 25_000_000);
    })
}

#[test]
fn dupe_span() {
    let s = Builder::default().layer(|| Histogram::new_with_max(200_000_000, 1).unwrap());
    let sid = s.downcaster();
    let d = Dispatch::new(s.with_subscriber(Registry::default()));
    let span = dispatcher::with_default(&d, || trace_span!("foo"));
    let d1 = d.clone();
    let span1 = span.clone();
    let jh1 = std::thread::spawn(move || {
        dispatcher::with_default(&d1, || {
            span1.in_scope(|| {
                trace!("thread1");
            })
        })
    });
    let span2 = span.clone();
    let d2 = d.clone();
    let jh2 = std::thread::spawn(move || {
        dispatcher::with_default(&d2, || {
            span2.in_scope(|| {
                trace!("thread2");
            })
        })
    });
    drop(span);
    jh1.join().unwrap();
    jh2.join().unwrap();
    sid.downcast(&d).unwrap().with_histograms(|hs| {
        assert_eq!(hs.len(), 1);
        let hs = &hs["foo"];
        assert_eq!(hs.len(), 2);
        assert!(hs.contains_key("thread1"));
        assert!(hs.contains_key("thread2"));
    })
}

#[test]
fn same_event_two_threads() {
    let s = Builder::default().layer(|| Histogram::new_with_max(200_000_000, 1).unwrap());
    let sid = s.downcaster();
    let d = Dispatch::new(s.with_subscriber(Registry::default()));
    let d1 = d.clone();
    let jh1 = std::thread::spawn(move || {
        dispatcher::with_default(&d1, || {
            trace_span!("span").in_scope(|| {
                trace!("event1");
                trace!("event2");
            })
        })
    });
    let d2 = d.clone();
    let jh2 = std::thread::spawn(move || {
        dispatcher::with_default(&d2, || {
            trace_span!("span").in_scope(|| {
                trace!("event1");
                trace!("event2");
            })
        })
    });
    jh1.join().unwrap();
    jh2.join().unwrap();
    sid.downcast(&d).unwrap().with_histograms(|hs| {
        assert_eq!(hs.len(), 1);
        let hs = &hs["span"];
        assert_eq!(hs.len(), 2);
        assert!(hs.contains_key("event1"));
        assert!(hs.contains_key("event2"));
    })
}

#[test]
fn by_field_typed() {
    let s = Builder::default()
        .events(group::ByField::from("f"))
        .layer(|| Histogram::new_with_max(200_000_000, 1).unwrap());
    let sid = s.downcaster();
    let d = Dispatch::new(s.with_subscriber(Registry::default()));
    let d2 = d.clone();
    std::thread::spawn(move || {
        dispatcher::with_default(&d2, || {
            trace_span!("foo").in_scope(|| {
                trace!({ f = 1u64 }, "");
                trace!({ f = true }, "");
                trace!({ f = -1i64 }, "");
            })
        })
    })
    .join()
    .unwrap();
    sid.downcast(&d).unwrap().with_histograms(|hs| {
        assert_eq!(hs.len(), 1);
        let hs = &hs["foo"];
        assert_eq!(hs.len(), 3);
        assert!(hs.contains_key("1"));
        assert!(hs.contains_key("true"));
        assert!(hs.contains_key("-1"));
    })
}

#[test]
fn informed_histogram_constructor() {
    let s = Builder::default().layer_informed(|s: &_, e: &_| {
        assert_eq!(*s, "span");
        assert_eq!(e, "event");
        Histogram::new_with_max(200_000_000, 1).unwrap()
    });
    let sid = s.downcaster();
    let d = Dispatch::new(s.with_subscriber(Registry::default()));
    let d2 = d.clone();
    std::thread::spawn(move || {
        dispatcher::with_default(&d2, || {
            trace_span!("span").in_scope(|| {
                trace!("event");
            })
        })
    })
    .join()
    .unwrap();
    sid.downcast(&d).unwrap().with_histograms(|hs| {
        assert_eq!(hs.len(), 1);
        let hs = &hs["span"];
        assert_eq!(hs.len(), 1);
        assert!(hs.contains_key("event"));
    })
}

#[test]
fn by_closure() {
    let s = Builder::default()
        .spans(|_: &span::Attributes| ())
        .events(|_: &Event| ())
        .layer(|| Histogram::new_with_max(200_000_000, 1).unwrap());
    let sid = s.downcaster();
    let d = Dispatch::new(s.with_subscriber(Registry::default()));
    let d2 = d.clone();
    std::thread::spawn(move || {
        dispatcher::with_default(&d2, || {
            trace_span!("foo").in_scope(|| {
                trace!({ f = 1u64 }, "");
                trace!("foo");
            })
        })
    })
    .join()
    .unwrap();
    sid.downcast(&d).unwrap().with_histograms(|hs| {
        assert_eq!(hs.len(), 1);
        let hs = &hs[&()];
        assert_eq!(hs.len(), 1);
        assert!(hs.contains_key(&()));
    })
}

#[test]
fn free_standing_event() {
    let s = Builder::default().layer(|| Histogram::new_with_max(200_000_000, 1).unwrap());
    let sid = s.downcaster();
    let d = Dispatch::new(s.with_subscriber(Registry::default()));
    let d2 = d.clone();
    std::thread::spawn(move || {
        dispatcher::with_default(&d2, || {
            trace!("event");
        })
    })
    .join()
    .unwrap();
    sid.downcast(&d).unwrap().with_histograms(|hs| {
        // free-standing events should not be recorded
        assert_eq!(hs.len(), 0);
    })
}

#[test]
fn nested() {
    let s = Builder::default().layer(|| Histogram::new_with_max(200_000_000, 1).unwrap());
    let sid = s.downcaster();
    let d = Dispatch::new(s.with_subscriber(Registry::default()));
    let d2 = d.clone();
    std::thread::spawn(move || {
        dispatcher::with_default(&d2, || {
            trace_span!("foo").in_scope(|| {
                std::thread::sleep(std::time::Duration::from_millis(1));
                trace_span!("bar").in_scope(|| {
                    std::thread::sleep(std::time::Duration::from_millis(1));
                    trace_span!("baz").in_scope(|| {
                        std::thread::sleep(std::time::Duration::from_millis(1));
                        trace!("event1");
                        std::thread::sleep(std::time::Duration::from_millis(1));
                        trace!("event2");
                        // now do an event twice so we check the re-use path
                        trace!("event3");
                        trace!("event3");
                    })
                })
            })
        })
    })
    .join()
    .unwrap();
    sid.downcast(&d).unwrap().force_synchronize();
    sid.downcast(&d).unwrap().with_histograms(|hs| {
        assert_eq!(hs.len(), 3);
        for &s in &["baz", "bar", "foo"] {
            assert!(hs.contains_key(s));
            assert!(hs[s].contains_key("event1"));
            assert!(hs[s].contains_key("event2"));
            assert_eq!(hs[s].len(), 3);
            for &e in &["event1", "event2"] {
                assert_eq!(hs[s][e].len(), 1);
            }
            assert_eq!(hs[s]["event3"].len(), 2);
        }

        // timing should differ between the different spans for event1
        // since it is measured relative to span start time
        let foo_e1 = &hs["foo"]["event1"].max();
        let bar_e1 = &hs["bar"]["event1"].max();
        let baz_e1 = &hs["baz"]["event1"].max();
        assert!(foo_e1 > bar_e1);
        assert!(bar_e1 > baz_e1);
        // for event2 however, they should all be relative to event1
        // note, however, that event1.end is _later_ for foo than for bar/baz
        // because events are recorded for spans in reverse span order
        let foo_e2 = &hs["foo"]["event2"].max();
        let bar_e2 = &hs["bar"]["event2"].max();
        let baz_e2 = &hs["baz"]["event2"].max();
        assert!(foo_e2 <= bar_e2);
        assert!(foo_e2 <= baz_e2);
        assert!(bar_e2 <= baz_e2);
    })
}

#[test]
fn nested_diff() {
    let s = Builder::default().layer(|| Histogram::new_with_max(200_000_000, 1).unwrap());
    let sid = s.downcaster();
    let d = Dispatch::new(s.with_subscriber(Registry::default()));
    let d2 = d.clone();
    std::thread::spawn(move || {
        dispatcher::with_default(&d2, || {
            trace_span!("foo").in_scope(|| {
                trace!("foo_event");
                std::thread::sleep(std::time::Duration::from_millis(1));
                trace_span!("bar").in_scope(|| {
                    std::thread::sleep(std::time::Duration::from_millis(1));
                    trace!("bar_event");
                    std::thread::sleep(std::time::Duration::from_millis(1));
                    trace_span!("baz").in_scope(|| {
                        std::thread::sleep(std::time::Duration::from_millis(1));
                        trace!("baz_event");
                    })
                })
            })
        })
    })
    .join()
    .unwrap();
    sid.downcast(&d).unwrap().force_synchronize();
    sid.downcast(&d).unwrap().with_histograms(|hs| {
        assert_eq!(hs.len(), 3);
        assert!(hs.contains_key("foo"));
        assert!(hs.contains_key("bar"));
        assert!(hs.contains_key("baz"));

        // all spans see baz_event
        assert!(hs["foo"].contains_key("baz_event"));
        assert!(hs["bar"].contains_key("baz_event"));
        assert!(hs["baz"].contains_key("baz_event"));
        // baz does not see any the other events, but the others do
        assert!(hs["foo"].contains_key("bar_event"));
        assert!(hs["bar"].contains_key("bar_event"));
        assert_eq!(hs["baz"].len(), 1);
        // bar does not see foo_event, but foo does
        assert!(hs["foo"].contains_key("foo_event"));
        assert_eq!(hs["bar"].len(), 2);
        // foo doesn't somehow see any other events
        assert_eq!(hs["foo"].len(), 3);

        // in foo, bar_event should be measured relative to foo_event
        // in bar, bar_event should be measured relative to the start of bar
        // therefore, bar should see a lower time for bar_event than foo should
        let foo_bar_e = &hs["foo"]["bar_event"].max();
        let bar_bar_e = &hs["bar"]["bar_event"].max();
        assert!(foo_bar_e > bar_bar_e);

        // in both foo and bar, baz_event should be measured relative to bar_event
        // in baz, baz_event should be measured relative to the start of baz
        // therefore, baz should see a lower time for baz_event than foo or bar
        // and foo and bar should see the _same_ time.
        // note, however, that bar_event.end is _later_ for foo than for bar
        // because events are recorded for spans in reverse span order, so
        // baz will appear to have happened _sooner_ to foo.
        let foo_baz_e = &hs["foo"]["baz_event"].max();
        let bar_baz_e = &hs["bar"]["baz_event"].max();
        let baz_baz_e = &hs["baz"]["baz_event"].max();
        assert!(foo_baz_e <= bar_baz_e);
        assert!(foo_baz_e > baz_baz_e);
    })
}

#[test]
fn nested_no_bubble() {
    let s = Builder::default()
        .no_span_recursion()
        .layer(|| Histogram::new_with_max(200_000_000, 1).unwrap());
    let sid = s.downcaster();
    let d = Dispatch::new(s.with_subscriber(Registry::default()));
    let d2 = d.clone();
    std::thread::spawn(move || {
        dispatcher::with_default(&d2, || {
            trace_span!("foo").in_scope(|| {
                trace!("foo_start");
                std::thread::sleep(std::time::Duration::from_millis(1));
                trace_span!("bar").in_scope(|| {
                    trace!("bar_start");
                    std::thread::sleep(std::time::Duration::from_millis(1));
                    trace!("bar_end");
                });
                trace!("foo_end");
            })
        })
    })
    .join()
    .unwrap();
    sid.downcast(&d).unwrap().force_synchronize();
    sid.downcast(&d).unwrap().with_histograms(|hs| {
        assert_eq!(hs.len(), 2);
        assert!(hs.contains_key("foo"));
        assert!(hs.contains_key("bar"));

        // foo membership
        assert!(hs["foo"].contains_key("foo_start"));
        assert!(hs["foo"].contains_key("foo_end"));
        assert!(!hs["foo"].contains_key("bar_start"));
        assert!(!hs["foo"].contains_key("bar_end"));

        // bar membership
        assert!(hs["bar"].contains_key("bar_start"));
        assert!(hs["bar"].contains_key("bar_end"));

        // because of no_span_recursion(), bar_end - bar_start < foo_end - foo_start
        let bar_t = hs["bar"]["bar_end"].max();
        let foo_t = hs["foo"]["foo_end"].max();
        assert!(foo_t > bar_t);
    })
}

#[test]
fn nested_bubble() {
    let s = Builder::default().layer(|| Histogram::new_with_max(200_000_000, 1).unwrap());
    let sid = s.downcaster();
    let d = Dispatch::new(s.with_subscriber(Registry::default()));
    let d2 = d.clone();
    std::thread::spawn(move || {
        dispatcher::with_default(&d2, || {
            trace_span!("foo").in_scope(|| {
                trace!("foo_start");
                std::thread::sleep(std::time::Duration::from_millis(1));
                trace_span!("bar").in_scope(|| {
                    trace!("bar_start");
                    std::thread::sleep(std::time::Duration::from_millis(1));
                    trace!("bar_end");
                });
                trace!("foo_end");
            })
        })
    })
    .join()
    .unwrap();
    sid.downcast(&d).unwrap().force_synchronize();
    sid.downcast(&d).unwrap().with_histograms(|hs| {
        assert_eq!(hs.len(), 2);
        assert!(hs.contains_key("foo"));
        assert!(hs.contains_key("bar"));

        // foo membership
        assert!(hs["foo"].contains_key("foo_start"));
        assert!(hs["foo"].contains_key("foo_end"));
        // foo span additionally contains bar events because of no no_span_recursion()
        assert!(hs["foo"].contains_key("bar_start"));
        assert!(hs["foo"].contains_key("bar_end"));

        // bar membership
        assert!(hs["bar"].contains_key("bar_start"));
        assert!(hs["bar"].contains_key("bar_end"));

        // because of no no_span_recursion(), bar_end - bar_start < foo_end - foo_start
        let bar_t = hs["bar"]["bar_end"].max();
        let foo_t = hs["foo"]["foo_end"].max();
        assert!(foo_t < bar_t);
    })
}

#[test]
fn span_close_event() {
    let s = Builder::default()
        .span_close_events()
        .layer(|| Histogram::new_with_max(200_000_000, 1).unwrap());
    let sid = s.downcaster();
    let d = Dispatch::new(s.with_subscriber(Registry::default()));
    let d2 = d.clone();
    std::thread::spawn(move || {
        dispatcher::with_default(&d2, || {
            trace_span!("foo").in_scope(|| {
                std::thread::sleep(std::time::Duration::from_millis(1));
                trace!("foo_start");
                trace_span!("bar").in_scope(|| {
                    trace!("bar_end");
                    std::thread::sleep(std::time::Duration::from_millis(1));
                });
                trace!("foo_end");
            })
        })
    })
    .join()
    .unwrap();
    sid.downcast(&d).unwrap().force_synchronize();
    sid.downcast(&d).unwrap().with_histograms(|hs| {
        assert_eq!(hs.len(), 2);
        assert!(hs.contains_key("foo"));
        assert!(hs.contains_key("bar"));

        // foo membership
        assert!(hs["foo"].contains_key("foo_start"));
        assert!(hs["foo"].contains_key("foo_end"));
        assert!(hs["foo"].contains_key("close"));

        // bar membership
        assert!(hs["bar"].contains_key("bar_end"));
        assert!(hs["bar"].contains_key("close"));

        let foo_start = hs["foo"]["foo_start"].max();
        let bar_end = hs["bar"]["bar_end"].max();
        assert!(foo_start > bar_end);

        let foo_end = hs["foo"]["foo_end"].max();
        let bar_close = hs["bar"]["close"].max();
        assert!(bar_close > foo_end);
    })
}

#[test]
fn explicit_span_parent() {
    let s = Builder::default().layer(|| Histogram::new_with_max(200_000_000, 1).unwrap());
    let sid = s.downcaster();
    let d = Dispatch::new(s.with_subscriber(Registry::default()));
    let d2 = d.clone();
    std::thread::spawn(move || {
        dispatcher::with_default(&d2, || {
            let s1 = trace_span!("foo");
            std::thread::sleep(std::time::Duration::from_millis(1));
            trace_span!(parent: &s1, "bar").in_scope(|| {
                trace!("event");
            })
        })
    })
    .join()
    .unwrap();
    sid.downcast(&d).unwrap().force_synchronize();
    sid.downcast(&d).unwrap().with_histograms(|hs| {
        assert_eq!(hs.len(), 2);
        for &s in &["bar", "foo"] {
            assert!(hs.contains_key(s));
            assert!(hs[s].contains_key("event"));
            assert_eq!(hs[s].len(), 1);
            assert_eq!(hs[s]["event"].len(), 1);
        }

        // timing should differ between the different spans for event
        // since it is measured relative to span start time
        let foo_e = &hs["foo"]["event"].max();
        let bar_e = &hs["bar"]["event"].max();
        assert!(foo_e > bar_e);
    })
}

#[test]
fn explicit_event_parent() {
    let s = Builder::default().layer(|| Histogram::new_with_max(200_000_000, 1).unwrap());
    let sid = s.downcaster();
    let d = Dispatch::new(s.with_subscriber(Registry::default()));
    let d2 = d.clone();
    std::thread::spawn(move || {
        dispatcher::with_default(&d2, || {
            let span = trace_span!("foo");
            trace!(parent: &span, "event");
        })
    })
    .join()
    .unwrap();
    sid.downcast(&d).unwrap().with_histograms(|hs| {
        assert_eq!(hs.len(), 1);
        assert!(hs.contains_key("foo"));
        assert!(hs["foo"].contains_key("event"));
        assert_eq!(hs["foo"].len(), 1);
    })
}

#[test]
fn tracks_current_span() {
    let d = Dispatch::new(
        Builder::default()
            .layer(|| Histogram::new_with_max(200_000_000, 1).unwrap())
            .with_subscriber(Registry::default()),
    );
    dispatcher::with_default(&d, || {
        let span = trace_span!("span");
        span.in_scope(|| {
            assert_eq!(span, Span::current());
        })
    });
}

#[test]
fn tracks_current_span_deep() {
    let d = Dispatch::new(
        Builder::default()
            .layer(|| Histogram::new_with_max(200_000_000, 1).unwrap())
            .with_subscriber(Registry::default()),
    );
    dispatcher::with_default(&d, || {
        trace_span!("span1").in_scope(|| {
            trace_span!("span2").in_scope(|| {
                let span = trace_span!("span3");
                span.in_scope(|| {
                    assert_eq!(span, Span::current());
                })
            });
        });
    });
}