Comments (9)
Ah, I just noticed follows_from
. I'm guessing the intention is that each individual state transition is recorded with Span
(ie, the actual poll
calls), but they're linked together into a high-level operation via follows_from
. Is that correct?
from tracing.
I don't think follows_from
is the best fit in this case. A good example for follows_from
is a task sending a message to a worker and the worker does some work to process that message. The span representing the work to process that message has a parent that is the worker task but follows from the span that sent the message.
The case you describe does sound like a parent / child relationship. The work in the spawned task is entirely in service of the spawner. Being able to represent this as a parent / child was an original design goal. Thinking about it, I wonder if it was lost a bit over iterations.
IIRC, my thinking was that the spawner and the spawned task would get linked via a manual step. There would be an API to say that span A is a child of span B. However, parent / child was removed from -core. My thought was that it could be entirely handled by the subscriber by observing how spans are entered / exited.
Perhaps this isn't sufficient.
There are a few questions in my mind:
- How does the instrumentation side of tokio-trace say Span A is a child of Span B.
- Is observing parent/child via span enter / exit correct? I don't think not doing this is an option.
- What happens if a child span is nested in Span A, then it is moved and is re-rooted in Span B? I assume a span cannot have multiple parents? But how would this be handled?
from tracing.
@jsgf this is an excellent question, thanks!
The answer right now is that this is something that the core tokio-trace
libraries are unopinionated about. Since tracking the current span is something that can be done solely by a Subscriber
and isn't necessary to implement anything in tokio-trace-core
, we thought this was best left up to Subscriber
implementations to determine the correct behaviour for their particular use-case. This is why the docs mention a notion of a "current span" but don't actually define what this means (something which I think ought to be resolved by improving the documentation).
With that said, here are some of my thoughts that have fallen out of experimenting with subscriber implementations:
-
You're right that if a single global current span is tracked for the entire process, we can't really represent concurrently executing contexts on multiple threads.
I think that in most cases, subscribers which expect to be used in multithreaded contexts should track a separate current span per thread. In my subscriber implementations, I've used something like this:
thread_local! { static CURRENT_SPAN: RefCell<Vec<Span>> = RefCell::new(Vec::new()); } // This can be used for determining the parent of new spans, for determining // the current span for formatting events, etc... fn current_span() -> Option<Span> { CURRENT_SPAN.with(|stack| { stack.borrow().last().map(Span::clone) }) } impl Subscriber for MySubscriber { fn enter(&self, span: &Span) { CURRENT_SPAN.with(|stack| { stack.borrow_mut().push(span.clone()); }) } fn exit(&self, _span: &Span) { CURRENT_SPAN.with(|stack| { let _ = stack.borrow_mut().pop(); }) } // .... }
Eventually, I'd like to ship a library of composable utilities for writing subscribers, with code for things like "tracking the current span on a per-thread basis" to be used in subscriber implementations. That's something I'm still experimenting with, though.
-
Typically, I think of the "parent" of a span as being the span in which that span was created, meaning that in most cases, it's likely that there'll be both a stack of the spans the current thread has entered (as in the example above) and a tree of spans with parent-child relationships, but again, this is left up to the subscriber.
I've found that when printing events in a context, the context that makes the most logical sense to someone consuming logs is to print the thread's current span and all its parents. This means that (using the example of a Hyper server) we'll get logs that look like this:
INFO server{local=V4(127.0.0.1:3000)}: hyper_echo: listening... TRACE server{local=V4(127.0.0.1:3000)}:connection{remote=V4(127.0.0.1:50498)}: hyper_echo: accepted connection INFO server{local=V4(127.0.0.1:3000)}:connection{remote=V4(127.0.0.1:50498)}:request{method=POST uri=/echo/}: hyper_echo: received request TRACE server{local=V4(127.0.0.1:3000)}:connection{remote=V4(127.0.0.1:50500)}: hyper_echo: accepted connection INFO server{local=V4(127.0.0.1:3000)}:connection{remote=V4(127.0.0.1:50500)}:request{method=POST uri=/echo/reversed}: hyper_echo: received request DEBUG server{local=V4(127.0.0.1:3000)}:connection{remote=V4(127.0.0.1:50500)}:request{method=POST uri=/echo/reversed}:response{response_kind="reversed"}: hyper_echo: reversed request body chunk=Ok("hello world") body=Ok("dlrow olleh") TRACE server{local=V4(127.0.0.1:3000)}:connection{remote=V4(127.0.0.1:50500)}:request{method=POST uri=/echo/reversed}:response{response_kind="reversed"}: hyper_echo: response completed
even if the accepting task and the spawned request-handler futures are running on different threads in a threadpool. However, if we care about what individual worker threads are doing, we might also want to inspect the stack of spans that thread has entered as well.
In the use-case you described, representing the parent future with a span and having each spawned future correspond to a new span inside the spawning future's span definitely seems like what I would do.
I would probably do something like this (using the Future::instrument
combinator from the tokio-trace-futures
crate in the nursery):
use futures::future::{self, Future};
use tokio_trace_futures::Instrument;
fn parent_task(how_many: usize) -> impl Future<Item=(), Error=()> {
future::lazy(move || {
info!("spawning subtasks...");
let subtasks = (1..=how_many).map(|i| {
debug!(message = "creating subtask;", number = i);
subtask(i)
}).collect::<Vec<_>>();
future::join_all(subtasks)
})
.map(|result| {
debug!("all subtasks completed");
let sum: usize = result.into_iter().sum();
info!(sum = sum);
})
.instrument(span!("parent_task", subtasks = how_many))
}
fn subtask(number: usize) -> impl Future<Item=usize, Error=()> {
future::lazy(move || {
info!("polling subtask...");
Ok(number)
}).instrument(span!("subtask", number = number))
}
Running this as an example (using the tokio-trace-fmt
subscriber from the nursery) gets logs like this:
INFO parent_task{subtasks=10}: spawny_thing: spawning subtasks...
DEBUG parent_task{subtasks=10}: spawny_thing: creating subtask; number=1
DEBUG parent_task{subtasks=10}: spawny_thing: creating subtask; number=2
DEBUG parent_task{subtasks=10}: spawny_thing: creating subtask; number=3
DEBUG parent_task{subtasks=10}: spawny_thing: creating subtask; number=4
DEBUG parent_task{subtasks=10}: spawny_thing: creating subtask; number=5
DEBUG parent_task{subtasks=10}: spawny_thing: creating subtask; number=6
DEBUG parent_task{subtasks=10}: spawny_thing: creating subtask; number=7
DEBUG parent_task{subtasks=10}: spawny_thing: creating subtask; number=8
DEBUG parent_task{subtasks=10}: spawny_thing: creating subtask; number=9
DEBUG parent_task{subtasks=10}: spawny_thing: creating subtask; number=10
DEBUG parent_task{subtasks=10}:subtask{number=1}: spawny_thing: polling subtask...
DEBUG parent_task{subtasks=10}:subtask{number=2}: spawny_thing: polling subtask...
DEBUG parent_task{subtasks=10}:subtask{number=3}: spawny_thing: polling subtask...
DEBUG parent_task{subtasks=10}:subtask{number=4}: spawny_thing: polling subtask...
DEBUG parent_task{subtasks=10}:subtask{number=5}: spawny_thing: polling subtask...
DEBUG parent_task{subtasks=10}:subtask{number=6}: spawny_thing: polling subtask...
DEBUG parent_task{subtasks=10}:subtask{number=7}: spawny_thing: polling subtask...
DEBUG parent_task{subtasks=10}:subtask{number=8}: spawny_thing: polling subtask...
DEBUG parent_task{subtasks=10}:subtask{number=9}: spawny_thing: polling subtask...
DEBUG parent_task{subtasks=10}:subtask{number=10}: spawny_thing: polling subtask...
DEBUG parent_task{subtasks=10}: spawny_thing: all subtasks completed
INFO parent_task{subtasks=10}: spawny_thing: sum=55
which seems about like what I would expect to see from this code.
from tracing.
As a side note, sorry that the nursery crates I mentioned above are not currently very well documented or discoverable; they're still works in progress (is is what happens when one tries to materialize an entire library ecosystem from scratch. :P).
from tracing.
Thanks for your explanations. I think I have a clearer idea about how things fit together. Specifically the understanding I have now is:
- A
Span
corresponds to an instance of a Future (or Stream), withentry
periods corresponding to calls topoll
- Though Spans are more general and could be used to model similar things
- Sub-spans correspond to sub-Future/Streams for sub-parts of the overall job
Span
trees are scoped to aTask
- it doesn't make sense for aSpan
to reference one in another task (except byfollows_from
)- Tasks are always bound to a single thread at a time, so only one Span at a given level of the tree can be entered at a time
Does that sound about right?
from tracing.
My gut is that that using a thread local would be a good default for a subscriber to use if no parent / child relationship is specified, but there should be a way using the instrumentation API to explicitly create a parent / child relationship or to create an unrooted span.
I don't think we use span creation to determine parent / child given that spans are not entered when created. Subscribers probably have to observe the first time a span is entered and find the parent then.
from tracing.
there should be a way using the instrumentation API to explicitly create a parent / child relationship or to create an unrooted span.
I'm open to adding this.
I don't think we use span creation to determine parent / child given that spans are not entered when created. Subscribers probably have to observe the first time a span is entered and find the parent then.
I don't agree --- in my experience, considering the span in which a span was created to be its parent leads to behaviour more closely in line with the user's expectations. For example, consider code like
span!("span_1").enter(|| {
let fut = foo
.and_then(...)
// ...
.instrument(span!("span 2"));
tokio::spawn(fut);
});
Logically, I would expect span_1
to be the parent of span_2
. However, if we determine span parenthood based on the current span when a span is entered, then span_2
will likely be rootless*. In my experience, in order to get the nice trace trees we expect to see, where i.e. the task spawned to handle a request is a child of the task that accepts incoming connections, we probably want to determine parenthood based on the current span when a span is created.
But, regardless, this is behaviour that ought to be determined by the subscriber.
*Or, will be a child of whatever span the worker thread that began executing it was currently inside of when the future was polled for the first time, which could be very surprising indeed.
from tracing.
When would such a snippet ever happen? Spans are created in future constructors. In practice, it would be something like this:
TcpStream::connect(...)
.instrument(span!("child"))
.and_then(|...| {
})
.instrument(span!("parent"))
If the parent / child link happens at construction time, it will fail here.
from tracing.
I think we've put some work into fixing up the docs so that this is a little clearer. I'm closing this ticket for now.
from tracing.
Related Issues (20)
- Unqualified `line!` macro usage inside `info!` causes issues with `ratatui_macros` HOT 1
- How to modify EnvFilter instead of replace HOT 3
- RollingFileAppender `prune_old_logs()` relies on `metadata().created()` which is not available on all platforms HOT 1
- Make Layer::with_writer not truncate the file HOT 4
- When will the feature(`valuable` suport`) be merged into stable version? HOT 1
- error[E0609]: no field `free` on type `REGISTRY` HOT 3
- Add an option for outputting span IDs HOT 1
- RollingFileAppender: prefix and suffix custom separator
- `#instrument` attribute not making new spans HOT 2
- Execute custom code every time `error!` (etc) is called HOT 4
- Make path clickable HOT 2
- Lacking documentation of context propagation through channels HOT 2
- `fn subscriber` did exist in the main branch, but not in `tracing-subscriber-0.3.18` HOT 2
- Valuable: Enum Representations
- JSON: Field names should account for `r#` HOT 4
- Inconsistent behaviour in tracing_subscriber wrt tracing_log HOT 7
- Allow `Display` formatting of `Option`s in messages HOT 2
- `warn!` inside `unwrap_or(..)` argument body HOT 2
- Filter to detect/exclude events sourced from the `log` crate via `tracing-log` HOT 1
- Incorrect Documentation for `tracing_appender::rolling::daily`
Recommend Projects
-
React
A declarative, efficient, and flexible JavaScript library for building user interfaces.
-
Vue.js
🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
-
Typescript
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
-
TensorFlow
An Open Source Machine Learning Framework for Everyone
-
Django
The Web framework for perfectionists with deadlines.
-
Laravel
A PHP framework for web artisans
-
D3
Bring data to life with SVG, Canvas and HTML. 📊📈🎉
-
Recommend Topics
-
javascript
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
-
web
Some thing interesting about web. New door for the world.
-
server
A server is a program made to process requests and deliver data to clients.
-
Machine learning
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
-
Visualization
Some thing interesting about visualization, use data art
-
Game
Some thing interesting about game, make everyone happy.
Recommend Org
-
Facebook
We are working to build community through open source technology. NB: members must have two-factor auth.
-
Microsoft
Open source projects and samples from Microsoft.
-
Google
Google ❤️ Open Source for everyone.
-
Alibaba
Alibaba Open Source for everyone
-
D3
Data-Driven Documents codes.
-
Tencent
China tencent open source team.
from tracing.