trace_async broken for async_trait usage about minitrace-rust HOT 10 CLOSED

It appears that maybe in_new_span was renamed to in_local_span in this pr, but the usage on line 105 of crates/minitrace-macro/src/lib.rs was missed in the refactoring?

You are right.

I am new to Rust, so I don't know if there are any implications for fixing this beyond just changing the name to in_local_span, but I would be happy to help if I can.

Just to change the name then it will be fixed.

from minitrace-rust.

@zhongzc thanks for the answer. I have made the change and am operating off of my own fork, I am planning on making a PR when I can verify it is working as expected.

One question I have is that when I annotate an async function with the trace_async macro, I appear to end up with multiple traces for one function call. I think I might be ending up with a trace per poll, which I do see mentioned in the docbloc on in_local_span. Is this really expected, to have multiple traces per function call? Is there some way to combine these traces?

Here is an example of a span within Jaeger where there is a root span that calls an async service function, which itself calls a different async function, each annotated with trace_async. I suppose I would only expect to see three nested spans, one for root, one for mailbox_ack and one for datastore_ack_mailbox_public_key.

from minitrace-rust.

There isn't a good way to achieve your requirement with the current version.

[trace_async("mailbox_ack")] adds code for futures automatically as follow:

a_future.in_local_span("mailbox_ack").await;

Changing it to

a_future.in_span(Span::from_local_parent("mailbox_ack")).await;

will partially meet your requirement, but it's not easy as just adding an annotation [trace_async]. Besides, the parent-child relationship between mailbox_ack and datastore_ack_mailbox_public_key will be missed.

I'm not trying to convince you, but that outcome is really what I am hoping for as from that graph I can figure out that:

• When were futures suspended and when were they resumed
• How long was the real execution time and how long was the waiting time, not just the complete time

from minitrace-rust.

Thanks for the explanation. That makes sense, no sense in indicating that the code was actually doing anything when really it was just waiting on i/o. Also, I agree that the parent-child relationship is more important than these separated spans.

Is there anything that could be used to link/group those spans together (i.e. to indicate that a collection of spans were resulting from one function call, vs. multiple calls to the same function one after another, each resulting in multiple spans)?

from minitrace-rust.

Is there anything that could be used to link/group those spans together (i.e. to indicate that a collection of spans were resulting from one function call, vs. multiple calls to the same function one after another, each resulting in multiple spans)?

AFAIK, there is no such thing defined by opentracing spec. You can manually specify a parent span.

For example, we have a loop run some code multiple times; every time generates a span. Then we can group these spans by letting them have the same parent:

let _parent = LocalSpan::enter("a group of spans");

while running {
  let _child = LocalSpan::enter("some code");
  // some code
}

We will get finally:

[                            a group of spans                                 ]
 [ some code ]
                        [ some code ]
                                               ......
                                                                 [ some code ]

from minitrace-rust.

Thanks for the response again @zhongzc, you are very helpful, I really appreciate it.

I just put the fix for the async_trait usage in a PR here #65

I guess maybe as a feature request, in my mind it would make sense if there could be some way for there to be an automatically-generated parent span for the async polls that wouldn't involve adding code for the parent span around function calls (i.e. just adding the trace_async macro to a function would automatically lead to a parent span grouping the child polls). I don't know enough about how this might be architected, or how it would need to be designed to make sense in all situations (i.e. would each child span have a prefix of poll: or something?), but just thought I would put that out there in case it leads to something useful.

from minitrace-rust.

@zhongzc I've been thinking about trying to implement what is discussed here. I do see some value in having the traces signify each poll length when you have tracing for a cpu intensive area of code, but what I would think is more typical in a webservice is that 90% of the time you are yielding for network or db calls. In our system these traces get shipped to datadog and you end up with spans that are so short in duration, and so many of them, that it's hard to reason about what is actually happening. For this reason I see a lot of benefit in having the ability to have the spans include both polling and parked durations, IE make single spans look synchronous.

If this is something you agree with, do you have any advice on the architecture there and also should this be configurable so this library can operate in both of those modes?

from minitrace-rust.

@scirner22 #[trace] in the latest 0.2.0 traces the entire lifetime of async fn including polling and parking as the default behavior. The previous behavior of starting a new span on polling is enabled by a new macro attribute#[trace(event, enter_on_poll = true)].

from minitrace-rust.

Ah, just to mention,#[trace_async] is removed, and #[trace] will handle asyncness and async_trait automatically now.

from minitrace-rust.

That's awesome. Thanks!

from minitrace-rust.