tracing-calltree 0.1.2

Always-on hierarchical profiling for Rust tracing spans with rolling latency statistics.
Documentation 
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89

use std::future::Future;
use std::pin::Pin;
use std::task::{Context, Poll};
use std::time::Duration;
use tracing::Instrument;
use tracing_calltree::CallTree;
use tracing_subscriber::prelude::*;

#[tokio::test(flavor = "current_thread")]
async fn async_suspension_records_wall_greater_than_active() {
    let calltree = CallTree::builder().build();
    let subscriber = tracing_subscriber::registry().with(calltree.layer());
    let guard = tracing::subscriber::set_default(subscriber);

    async {
        tokio::task::yield_now().await;
        tokio::time::sleep(Duration::from_millis(10)).await;
    }
    .instrument(tracing::info_span!("database_query"))
    .await;

    drop(guard);

    let snapshot = calltree.snapshot();
    let node = &snapshot.roots[0];
    assert_eq!(node.total_calls, 1);
    assert!(node.wall.mean > node.active.mean);
    assert!(node.suspended.mean > Duration::ZERO);
}

#[tokio::test(flavor = "current_thread")]
async fn multiple_polls_produce_one_sample() {
    let calltree = CallTree::builder().build();
    let subscriber = tracing_subscriber::registry().with(calltree.layer());
    let guard = tracing::subscriber::set_default(subscriber);

    PollTwice { polls: 0 }
        .instrument(tracing::info_span!("poll_twice"))
        .await;

    drop(guard);

    let snapshot = calltree.snapshot();
    let node = &snapshot.roots[0];
    assert_eq!(node.total_calls, 1);
    assert_eq!(node.wall.samples, 1);
}

#[test]
fn nested_reentry_does_not_double_count_active_time() {
    let calltree = CallTree::builder().build();
    let subscriber = tracing_subscriber::registry().with(calltree.layer());

    tracing::subscriber::with_default(subscriber, || {
        let span = tracing::info_span!("reentrant");
        let outer = span.enter();
        std::thread::sleep(Duration::from_millis(2));
        {
            let inner = span.enter();
            std::thread::sleep(Duration::from_millis(2));
            drop(inner);
        }
        std::thread::sleep(Duration::from_millis(2));
        drop(outer);
    });

    let snapshot = calltree.snapshot();
    let node = &snapshot.roots[0];
    assert_eq!(node.wall.samples, 1);
    assert!(node.active.mean <= node.wall.mean);
}

struct PollTwice {
    polls: usize,
}

impl Future for PollTwice {
    type Output = ();

    fn poll(mut self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Self::Output> {
        if self.polls == 0 {
            self.polls += 1;
            cx.waker().wake_by_ref();
            Poll::Pending
        } else {
            Poll::Ready(())
        }
    }
}