fix: set span end time when it exits

[mladedav]

Closes #116

Motivation

Currently, the open telemetry span is considered to be running until the tracing span is dropped and closed. This can be an issue in cases where either the span is held onto in case the operation needs more processing which was not known beforehand or when a structure holds onto the span.

This is an issue especially if an instrumented task is spawned as tracing will hold onto all its ancestors. Therefore until the spawned task ends, the parent span will also be considered not closed.

Solution

The time is set every time a span is exited. This incurs a lookup in extensions during on_exit.

Open Questions

Start time is set during creation of the new span

It might also make sense to do it during the first on_enter call. I can't think of a scenario where someone creates spans beforehand and enters them only significantly later though (maybe that could happen for some instrumented asynchronous tasks with extremely high contention?)

[mladedav]

According to otel spec the start time should be set to the time when the span was created and it can be overridable (currently isn't but that's fine I guess).

End time should be set when the operation ends which I belive is during the last on_exit, not during on_close, hence the change.

[jtescher]

on_exit may happen many times as the span is entered and exited (e.g. polling a future) might be worth adding a benchmark to be sure?

[mladedav]

In the case when there's no tracked inactivity, this change is pretty bad. When inactivity is tracked, it's not so bad.

It is a regression, but I think it's worth pointing out that it's 1000 enters and exits on a span still under 100 us.

I'm not sure if there's a way to get the time faster.

otel_many_enters/spec_baseline
                        time:   [15.050 µs 15.144 µs 15.245 µs]
                        change: [-0.9582% -0.0820% +0.8010%] (p = 0.85 > 0.05)
                        No change in performance detected.
Found 6 outliers among 100 measurements (6.00%)
  6 (6.00%) high mild
otel_many_enters/no_data_baseline
                        time:   [49.619 µs 49.810 µs 50.014 µs]
                        change: [+1.8938% +2.5952% +3.2264%] (p = 0.00 < 0.05)
                        Performance has regressed.
Found 4 outliers among 100 measurements (4.00%)
  4 (4.00%) high mild
otel_many_enters/data_only_baseline
                        time:   [48.759 µs 49.022 µs 49.303 µs]
                        change: [+0.1691% +0.9060% +1.6963%] (p = 0.02 < 0.05)
                        Change within noise threshold.
Found 1 outliers among 100 measurements (1.00%)
  1 (1.00%) high mild
otel_many_enters/full_without_timings
                        time:   [97.830 µs 98.231 µs 98.663 µs]
                        change: [+88.418% +89.538% +90.647%] (p = 0.00 < 0.05)
                        Performance has regressed.
Found 3 outliers among 100 measurements (3.00%)
  3 (3.00%) high mild
otel_many_enters/full_with_timings
                        time:   [159.58 µs 160.31 µs 161.06 µs]
                        change: [+4.6524% +5.3605% +6.0557%] (p = 0.00 < 0.05)
                        Performance has regressed.
Found 3 outliers among 100 measurements (3.00%)
  3 (3.00%) high mild

[mladedav]

For the record, I do believe that all parents having an end time only after all their children have closed (except for inter-service boundaries) is a bug. I could also create an option on the subscriber for this that could skip this to avoid the overhead if the user doesn't mind the timing issue or is sure it doesn't matter for their workloads and the spans would be closed right after the last exit.

If you have any idea to make this faster though, I'd be happy to try it out.

Another option would be to add OpenTelemetrySpanExt::with_end_time . The performance there is even worse if I just call it unconditionally after each of the 1000 exits, but arguably it would have the same performance as the version before these changes if a user just called it once at the end. That however shifts the responsibility on the user to know to call this for any span that spawns instrumented long-running tasks.

[djc]

For the record, I do believe that all parents having an end time only after all their children have closed (except for inter-service boundaries) is a bug.

Why? It sounds intuitively reasonable.

[mladedav]

Because that behaviour is present only because that's how tracing works but OpenTelemetry seems to support this.

In their example span C is longer than its parent.

I personally had a scenario where a request spawns a long running background task where the former will be much shorter.

[Xuanwo]

Because that behaviour is present only because that's how tracing works but OpenTelemetry seems to support this.

Yep, spec said:

End MUST NOT have any effects on child spans. Those may still be running and can be ended later.

So child spans can be end after parent span ended.

[djc]

This looks good to me, thanks. I think I agree that the performance impact is acceptable.

[davidbarsky]

I'm a little worried about this change: I'd naively expect that the correct direction for "children outliving their parents" is follows_from, not changing how on_exit works.

[djc]

@davidbarsky how do you square that with the spec referenced above?

[mladedav]

Personally, I see follows_from as an equivalent of span links (as is already used by this library) and more general than the parent-span relationship. In the example of a request spawning a long-running task, I'd still rather model it as a parent-child relationship and have it in the same trace but not extending the request to the full duration of the spawned task.

I've never seen any proposed rules about what should be considered parent-child and what should be just linked causal relationship, but currently for us, mostly visualization capabilities dictate our usage. follows_from doesn't get visualized very well in the systems I've seen so that would not make it currently a viable option.

[neoeinstein]

Personally, I see follows_from as an equivalent of span links (as is already used by this library) and more general than the parent-span relationship. In the example of a request spawning a long-running task, I'd still rather model it as a parent-child relationship and have it in the same trace but not extending the request to the full duration of the spawned task.

I agree with this. My particular scenario is an incoming web request that then causes a message to be published to a queue. The publish happens asynchronously and may complete long after the web response is complete. However, there is a strong parent-child relationship here that should be maintained, that follows_from does not capture. I've been creative with a workaround involving creating a new span with an explicit none parent for tracing, and then using the set_parent OTel extension method in order to make OTel aware of the parent–child relationship without causing the duration of the web request to be unnaturally extended.

[davidbarsky]

@davidbarsky how do you square that with the spec referenced above?

Sorry for the delay. My stance is that, at least in this respect, tracing and the OpenTelemetry's specification disagree, but I don't know how to change tracing's behavior to make it agree with the OpenTelemetry's specification without completely revamping tracing's garbage/older span deallocation collection model.

If there's a solution, it'd be something that handles span links or making the approach that @neoeinstein took more ergonomic, such as through a detached_span! macro that does:

I've been creative with a workaround involving creating a new span with an explicit none parent for tracing, and then using the set_parent OTel extension method in order to make OTel aware of the parent–child relationship without causing the duration of the web request to be unnaturally extended.

(On an aside @neoeinstein, I appreciate the implication of what you're doing is necromancy!)

[mladedav]

We've been doing the same thing (and even created the macro you mentioned), but the main issue with that is that we lose the tracing-managed data of parents. When we emit (json) logs, we also include all parent spans and when we use this trick, we have to sacrifice that.

This change does not change the garbage collection at all (e.g. the request spans are still kept in the registry until the long running tasks finish), the only difference is the timestamp that is sent in the OpenTelemetry span as an end. Which is pretty much exactly the thing I would want it to do. The main drawback this has compared to detaching the child is that the OpenTelemetry spans are exported only after all the children have been closed (so the request spans are needlessly kept around).

I did also think about whether maybe on_close (or another method on Layer) could be called when all references to the span are dropped, except for the ones that are kept around by children to prevent early collection of parents, but I guess that's way out of scope here and it would just help us get our spans exported earlier, so I don't think I want to go into more detail about that here.

[Oliboy50]

// Assign end time

I think that the comment should have been updated too

[djc]

Oops! Want to send a PR?

[Oliboy50]

=> #148