#![cfg(feature = "layer")]
use tracing::*;
use tracing_subscriber::{registry::Registry, Layer};
use tracing_timing::*;
#[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()));
sid.downcast(&d).unwrap();
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);
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"];
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"];
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| {
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");
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);
}
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);
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"));
assert!(hs["foo"].contains_key("baz_event"));
assert!(hs["bar"].contains_key("baz_event"));
assert!(hs["baz"].contains_key("baz_event"));
assert!(hs["foo"].contains_key("bar_event"));
assert!(hs["bar"].contains_key("bar_event"));
assert_eq!(hs["baz"].len(), 1);
assert!(hs["foo"].contains_key("foo_event"));
assert_eq!(hs["bar"].len(), 2);
assert_eq!(hs["foo"].len(), 3);
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);
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"));
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"));
assert!(hs["bar"].contains_key("bar_start"));
assert!(hs["bar"].contains_key("bar_end"));
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"));
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"));
assert!(hs["bar"].contains_key("bar_start"));
assert!(hs["bar"].contains_key("bar_end"));
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"));
assert!(hs["foo"].contains_key("foo_start"));
assert!(hs["foo"].contains_key("foo_end"));
assert!(hs["foo"].contains_key("close"));
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);
}
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());
})
});
});
});
}