output is a bit confusing

[amitu]

For some code:

#[tracing::instrument(skip_all)]
async fn foo() {
    tokio::time::sleep(std::time::Duration::from_secs(3)).await;
}

#[tracing::instrument(skip_all)]
async fn test() -> fastn_core::Result<fastn_core::http::Response> {
    tokio::time::sleep(std::time::Duration::from_secs(2)).await;
    foo().await;
    Ok(actix_web::HttpResponse::Ok().finish())
}

The output I am getting with tracing-forest is:

INFO     route [ 1.25ms | 80.53% / 100.00% ]
INFO     ┝━ ｉ [info]:  | method: "GET" | uri: "/test/"
INFO     ┕━ test [ 243µs | 18.93% / 19.47% ]
INFO        ┕━ foo [ 6.71µs | 0.54% ]
[2023-07-14T10:27:26Z INFO ] "GET /test/ HTTP/1.1" 5.005786s 200 0 127.0.0.1 "-" "curl/7.88.1"

I found the output confusing. The time taken by route() was 5s, but tracing-forest reported 1.25ms. I have read the docs, and it kind of makes sense as per docs, but for my use case, where I wanted to quickly spot the most offending functions, I preferred seeing total times.

I have have modified this library for my use, https://github.com/fastn-stack/fastn/tree/main/fastn-observer, this is the output I get now:

INFO     23.7µs route [ 5.01s ] 
INFO     ┝━  | 407µs method: "GET" | 407µs uri: "/test/"
INFO     ┕━ 3.64ms test [ 5.01s ] 
INFO        ┕━ 2.00s foo [ 3.00s ] 

I have removed the inner and total times, and show only the time between span open to span closed. I am also reporting when the span or event was created with respect to the parent span, which gives some more timing information, eg the time between the first info!() call and the next, can tell us something between the two info calls should be investigated.

I am very happy with the work you have done, and want to thank you. I would love to contribute my changes back (maybe as a configuration option) and remove delete my library if you want to go in this direction.