trace-core: Dispatchers unset themselves

[hawkw]

This branch changes dispatcher::get_default to unset the thread's
current dispatcher while the reference to it is held by the closure.
This prevents infinite loops if the subscriber calls code paths which
emit events or construct spans.

Note that this also means that nested calls to get_default inside of a
get_default closure will recieve a None dispatcher rather than the
"actual" dispatcher. However, it was necessary to unset the default in
get_default rather than in dispatch methods such as Dispatch::enter,
as when those functions are called, the current state has already been
borrowed.

This introduces a little more overhead into span creation and events.

Before:

     Running target/release/deps/no_subscriber-09f0b39a00181a97

running 5 tests
test bench_1_atomic_load              ... bench:           0 ns/iter (+/- 0)
test bench_costly_field_no_subscriber ... bench:           2 ns/iter (+/- 0)
test bench_log_no_logger              ... bench:           0 ns/iter (+/- 0)
test bench_no_span_no_subscriber      ... bench:           0 ns/iter (+/- 0)
test bench_span_no_subscriber         ... bench:           2 ns/iter (+/- 0)

test result: ok. 0 passed; 0 failed; 0 ignored; 5 measured; 0 filtered out

     Running target/release/deps/subscriber-992535c5d1c348ad

running 5 tests
test enter_span              ... bench:           3 ns/iter (+/- 0)
test span_no_fields          ... bench:          38 ns/iter (+/- 8)
test span_repeatedly         ... bench:       4,560 ns/iter (+/- 663)
test span_with_fields        ... bench:          49 ns/iter (+/- 17)
test span_with_fields_record ... bench:         363 ns/iter (+/- 71)

After:

     Running target/release/deps/no_subscriber-09f0b39a00181a97

running 5 tests
test bench_1_atomic_load              ... bench:           0 ns/iter (+/- 0)
test bench_costly_field_no_subscriber ... bench:           2 ns/iter (+/- 0)
test bench_log_no_logger              ... bench:           0 ns/iter (+/- 0)
test bench_no_span_no_subscriber      ... bench:           0 ns/iter (+/- 0)
test bench_span_no_subscriber         ... bench:           2 ns/iter (+/- 0)

test result: ok. 0 passed; 0 failed; 0 ignored; 5 measured; 0 filtered out

     Running target/release/deps/subscriber-992535c5d1c348ad

running 5 tests
test enter_span              ... bench:           3 ns/iter (+/- 0)
test span_no_fields          ... bench:          48 ns/iter (+/- 9)
test span_repeatedly         ... bench:       5,274 ns/iter (+/- 596)
test span_with_fields        ... bench:          55 ns/iter (+/- 11)
test span_with_fields_record ... bench:         346 ns/iter (+/- 71)

Closes #1032

Signed-off-by: Eliza Weisman [email protected]

[carllerche]

Looking good 👍 I only skimmed it so far. I will review it in closer detail tomorrow.

Have you considered flagging the dispatcher as entered instead of swapping out then back? I wonder if that would make an impact in the benches you run.

Roughly, Dispatcher would have a bool entered. If that flag is set, then it does not forward any events to the subscriber.

[hawkw]

@carllerche We still need to store that bool as part of the thread-local state, rather than on Dispatch, since Dispatch needs to be Sync (precluding the use of a Cell) as it's a field on Span (which we are now asserting is Sync).

Using a flag stored in the thread-local state rather than replacing the dispatcher doesn't seem to result in a big performance improvement:

running 5 tests
test enter_span              ... bench:           3 ns/iter (+/- 0)
test span_no_fields          ... bench:          47 ns/iter (+/- 6)
test span_repeatedly         ... bench:       5,063 ns/iter (+/- 957)
test span_with_fields        ... bench:          57 ns/iter (+/- 6)
test span_with_fields_record ... bench:         361 ns/iter (+/- 37)

However, it does mean that calls to dispatcher::get_default can be nested, as long as calls to the functions on Dispatch that need to be guarded are not also nested. This at least lets us avoid a potentially surprising edge case...

[carllerche]

@hawkw looking at this, the version w/ the bool flag needs to add a lot of conditionals where the original one did not... I do wonder what made the original (Cell and swap) slower.

[hawkw]

@carllerche personally, I would prefer to move forward with the bool flag rather than Cell and swap, because it means that nested calls to get_default don't behave surprisingly --- in the bool flag approach, the dispatcher is only disabled when we're actually inside it.

[hawkw]

@carllerche commit b0c6b34 moves the check back into dispatcher::get_default, rather than guarding individual functions on the dispatcher.

This means that we don't have to access the TLS var twice, and we don't have to access it at all when entering a span handle that already exists. This pretty much entirely negates the performance hit caused by adding the check.

[hawkw]

Looks like the build failure is due to Azure Pipelines flaking out again; I restarted it.

[hawkw]

Benchmark results from b0c6b34:

Before:

test enter_span              ... bench:           3 ns/iter (+/- 0)
test span_no_fields          ... bench:          51 ns/iter (+/- 12)
test span_repeatedly         ... bench:       5,073 ns/iter (+/- 1,528)
test span_with_fields        ... bench:          56 ns/iter (+/- 49)
test span_with_fields_record ... bench:         363 ns/iter (+/- 61)

After:

test enter_span              ... bench:           3 ns/iter (+/- 0)
test span_no_fields          ... bench:          35 ns/iter (+/- 12)
test span_repeatedly         ... bench:       4,165 ns/iter (+/- 298)
test span_with_fields        ... bench:          48 ns/iter (+/- 12)
test span_with_fields_record ... bench:         363 ns/iter (+/- 91)

Note that the "after" benchmarks are pretty much in line with the perf on master before adding the check. :D

[hawkw]

FreeBSD CI is also failing due to an unrelated (and possibly transient?) failure in the threadpool tests:

failures:
---- blocking_thread_does_not_take_over_shutdown_worker_thread stdout ----
thread 'blocking_thread_does_not_take_over_shutdown_worker_thread' panicked at 'called `Result::unwrap()` on an `Err` value: RecvError', src/libcore/result.rs:997:5
failures:
    blocking_thread_does_not_take_over_shutdown_worker_thread
test result: FAILED. 6 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out

I restarted it.