open-telemetry
[Bug]: trace BatchSpanProcessor::force_flush can deadlock
What happened?
I have an application which uses a multi-threaded tokio runtime. Calling trace_provider.force_flush() in our pre-shutdown routine consistently deadlocks the application (since the call never returns).
I suspect the internal usage of futures_executor::block_on is the culprit. My hypothesis is that calling force_flush from an async task blocks the runtime thread and prevents actual progress if the scheduler cannot cope with other tasks assigned to that thread. This hypothesis is further supported by the observation that starting an opentelemetry_otlp pipeline from a dedicated, single-threaded tokio runtime no longer exhibits the deadlocking scenario when trace_provider.force_flush() is called (notably because there's a separate thread available to handle the internal export tasks while the caller is blocked)
https://github.com/open-telemetry/opentelemetry-rust/blob/073f7a6b6a69c823e2debcc7e424677a3aa4a19f/opentelemetry-sdk/src/trace/span_processor.rs#L290-L292
API Version
Not sure, using the opentelemetry-collector with Jaeger, so likely the latest API version
SDK Version
opentelemetry 0.21.0 opentelmetry-otlp 0.14.0 opentelemetry_sdk 0.21.1
What Exporters are you seeing the problem on?
OTLP
Relevant log output
No useful log output. I did some println debugging of the opentelemetry-sdk internals (with a local fork) which showed that once force_flush was called, the internal methods of the BatchSpanProcessor stopped processing messages
I think one way to resolve the tension of issues with an async-sync-async sandwich, without forcing callers to use an async API, is to change the force_flush APIs to take a callback that resolves when the flush completes, while the actual force_sync call itself becomes non-blocking. This would allow callers to effectively await the flush's completion however they would like (e.g. write to a channel, hold an async lock, etc.)
~~This would also allow for more consistent behavior across Simple and Batch processors. For example, SimpleSpanProcessor::force_flush enqueues a flush but does not actually block until it's done: https://github.com/open-telemetry/opentelemetry-rust/blob/073f7a6b6a69c823e2debcc7e424677a3aa4a19f/opentelemetry-sdk/src/trace/span_processor.rs#L173-L177~~
~~But the BatchSpanProcessor does try to block until the flush completes which can result in unexpected surprises when switching the implementation~~
An alternative proposal would be to expose a force_flush_async equivalent which might be simpler to use at the expense of a larger API surface.
I'd be interested in working on implementing this if there is interest in pursuing either of these proposals!
Thanks for the detail report! I believe this is the same issue as https://github.com/open-telemetry/opentelemetry-rust/issues/868.
I think there is a scanrio that force flush will block the runtime but I haven't be able to reproduce it. So if you have an minimal exmaple could you share it?
For example, SimpleSpanProcessor::force_flush enqueues a flush but does not actually block until it's done
It actually does, if you look at singal, it employes a zero side channel and block on it until it receives the response from worker tasks. But it's a noop on worker tasks as there is no buffer in SimpleSpanProcessor
Hi @TommyCpp thanks for the quick response!
It actually does, if you look at singal, it employes a zero side channel and block on it until it receives the response from worker tasks. But it's a noop on worker tasks as there is no buffer in SimpleSpanProcessor
Ah my mistake, I should have looked at the implementation more closely!
I think there is a scanrio that force flush will block the runtime but I haven't be able to reproduce it. So if you have an minimal exmaple could you share it?
Yes! I did manage to boil it down to a minimal reproduction below:
# Cargo.toml
[package]
name = "otel-bug"
version = "0.1.0"
edition = "2021"
[dependencies]
opentelemetry = { version = "0.21", default-features = false, features = ["trace"] }
opentelemetry_sdk = { version = "0.21", default-features = false, features = ["rt-tokio", "trace"] }
opentelemetry-otlp = { version = "0.14", default-features = false, features = ["grpc-tonic", "trace"] }
tracing-opentelemetry = "0.22"
tracing = "0.1"
tracing-subscriber = { version = "0.3", features = [ "env-filter" ] }
tokio = { version = "1", features = ["rt", "rt-multi-thread"] }
// src/main.rs
use opentelemetry::KeyValue;
use opentelemetry_sdk::{
trace::{BatchConfig, RandomIdGenerator, Sampler},
Resource,
};
use std::time::Duration;
use tracing_subscriber::{layer::SubscriberExt, EnvFilter};
#[tokio::main]
async fn main() {
let tracer = opentelemetry_otlp::new_pipeline()
.tracing()
.with_exporter(opentelemetry_otlp::new_exporter().tonic())
.with_batch_config(
BatchConfig::default()
.with_max_concurrent_exports(4)
// shorten the delay between when spans are flushed, default is 5s,
.with_scheduled_delay(Duration::from_secs(2)),
)
.with_trace_config(
opentelemetry_sdk::trace::config()
.with_sampler(Sampler::AlwaysOn)
.with_id_generator(RandomIdGenerator::default())
.with_resource(Resource::new(vec![KeyValue::new(
"service.name",
"FooService",
)])),
)
.install_batch(opentelemetry_sdk::runtime::Tokio)
.unwrap();
let tracer_provider = tracer.provider().unwrap();
let _ = tracing::subscriber::set_global_default(
tracing_subscriber::registry()
.with(tracing_opentelemetry::layer().with_tracer(tracer))
.with(EnvFilter::new("debug")),
);
// NB: This spawn is load bearing
let _ = tokio::spawn(async move {
// Do some work
let _ = foo().await;
// Attempt to flush traces
println!("start trace_provider flush");
for r in tracer_provider.force_flush() {
if let Err(e) = r {
println!("unable to fully flush traces: {e}");
}
}
println!("finished trace_provider flush");
})
.await;
}
#[tracing::instrument(ret)]
async fn foo() -> usize {
let mut sum = 0;
for _ in 0..10 {
sum += bar().await
}
sum
}
#[tracing::instrument]
async fn bar() -> usize {
tokio::time::sleep(Duration::from_millis(100)).await;
42
}
# This file is automatically @generated by Cargo. # It is not intended for manual editing. version = 3[[package]] name = "addr2line" version = "0.20.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "f4fa78e18c64fce05e902adecd7a5eed15a5e0a3439f7b0e169f0252214865e3" dependencies = [ "gimli", ]
[[package]] name = "adler" version = "1.0.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "f26201604c87b1e01bd3d98f8d5d9a8fcbb815e8cedb41ffccbeb4bf593a35fe"
[[package]] name = "anyhow" version = "1.0.72" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "3b13c32d80ecc7ab747b80c3784bce54ee8a7a0cc4fbda9bf4cda2cf6fe90854"
[[package]] name = "async-trait" version = "0.1.74" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "a66537f1bb974b254c98ed142ff995236e81b9d0fe4db0575f46612cb15eb0f9" dependencies = [ "proc-macro2", "quote", "syn 2.0.28", ]
[[package]] name = "autocfg" version = "1.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "d468802bab17cbc0cc575e9b053f41e72aa36bfa6b7f55e3529ffa43161b97fa"
[[package]] name = "axum" version = "0.6.20" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "3b829e4e32b91e643de6eafe82b1d90675f5874230191a4ffbc1b336dec4d6bf" dependencies = [ "async-trait", "axum-core", "bitflags", "bytes", "futures-util", "http", "http-body", "hyper", "itoa", "matchit", "memchr", "mime", "percent-encoding", "pin-project-lite", "rustversion", "serde", "sync_wrapper", "tower", "tower-layer", "tower-service", ]
[[package]] name = "axum-core" version = "0.3.4" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "759fa577a247914fd3f7f76d62972792636412fbfd634cd452f6a385a74d2d2c" dependencies = [ "async-trait", "bytes", "futures-util", "http", "http-body", "mime", "rustversion", "tower-layer", "tower-service", ]
[[package]] name = "backtrace" version = "0.3.68" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "4319208da049c43661739c5fade2ba182f09d1dc2299b32298d3a31692b17e12" dependencies = [ "addr2line", "cc", "cfg-if", "libc", "miniz_oxide", "object", "rustc-demangle", ]
[[package]] name = "base64" version = "0.21.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "a4a4ddaa51a5bc52a6948f74c06d20aaaddb71924eab79b8c97a8c556e942d6a"
[[package]] name = "bitflags" version = "1.3.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "bef38d45163c2f1dde094a7dfd33ccf595c92905c8f8f4fdc18d06fb1037718a"
[[package]] name = "bumpalo" version = "3.11.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "572f695136211188308f16ad2ca5c851a712c464060ae6974944458eb83880ba"
[[package]] name = "byteorder" version = "1.4.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "14c189c53d098945499cdfa7ecc63567cf3886b3332b312a5b4585d8d3a6a610"
[[package]] name = "bytes" version = "1.0.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b700ce4376041dcd0a327fd0097c41095743c4c8af8887265942faf1100bd040"
[[package]] name = "cc" version = "1.0.79" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "50d30906286121d95be3d479533b458f87493b30a4b5f79a607db8f5d11aa91f"
[[package]] name = "cfg-if" version = "1.0.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "baf1de4339761588bc0619e3cbc0120ee582ebb74b53b4efbf79117bd2da40fd"
[[package]] name = "crossbeam-channel" version = "0.5.8" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "a33c2bf77f2df06183c3aa30d1e96c0695a313d4f9c453cc3762a6db39f99200" dependencies = [ "cfg-if", "crossbeam-utils", ]
[[package]] name = "crossbeam-utils" version = "0.8.7" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b5e5bed1f1c269533fa816a0a5492b3545209a205ca1a54842be180eb63a16a6" dependencies = [ "cfg-if", "lazy_static", ]
[[package]] name = "either" version = "1.6.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e78d4f1cc4ae33bbfc157ed5d5a5ef3bc29227303d595861deb238fcec4e9457"
[[package]] name = "equivalent" version = "1.0.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "5443807d6dff69373d433ab9ef5378ad8df50ca6298caf15de6e52e24aaf54d5"
[[package]] name = "fnv" version = "1.0.7" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "3f9eec918d3f24069decb9af1554cad7c880e2da24a9afd88aca000531ab82c1"
[[package]] name = "futures-channel" version = "0.3.26" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "2e5317663a9089767a1ec00a487df42e0ca174b61b4483213ac24448e4664df5" dependencies = [ "futures-core", ]
[[package]] name = "futures-core" version = "0.3.26" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ec90ff4d0fe1f57d600049061dc6bb68ed03c7d2fbd697274c41805dcb3f8608"
[[package]] name = "futures-executor" version = "0.3.14" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "10f6cb7042eda00f0049b1d2080aa4b93442997ee507eb3828e8bd7577f94c9d" dependencies = [ "futures-core", "futures-task", "futures-util", ]
[[package]] name = "futures-macro" version = "0.3.26" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "95a73af87da33b5acf53acfebdc339fe592ecf5357ac7c0a7734ab9d8c876a70" dependencies = [ "proc-macro2", "quote", "syn 1.0.107", ]
[[package]] name = "futures-sink" version = "0.3.26" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "f310820bb3e8cfd46c80db4d7fb8353e15dfff853a127158425f31e0be6c8364"
[[package]] name = "futures-task" version = "0.3.26" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "dcf79a1bf610b10f42aea489289c5a2c478a786509693b80cd39c44ccd936366"
[[package]] name = "futures-util" version = "0.3.26" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "9c1d6de3acfef38d2be4b1f543f553131788603495be83da675e180c8d6b7bd1" dependencies = [ "futures-core", "futures-macro", "futures-sink", "futures-task", "pin-project-lite", "pin-utils", "slab", ]
[[package]] name = "getrandom" version = "0.2.7" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "4eb1a864a501629691edf6c15a593b7a51eebaa1e8468e9ddc623de7c9b58ec6" dependencies = [ "cfg-if", "libc", "wasi", ]
[[package]] name = "gimli" version = "0.27.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b6c80984affa11d98d1b88b66ac8853f143217b399d3c74116778ff8fdb4ed2e"
[[package]] name = "glob" version = "0.3.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "d2fabcfbdc87f4758337ca535fb41a6d701b65693ce38287d856d1674551ec9b"
[[package]] name = "h2" version = "0.3.18" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "17f8a914c2987b688368b5138aa05321db91f4090cf26118185672ad588bce21" dependencies = [ "bytes", "fnv", "futures-core", "futures-sink", "futures-util", "http", "indexmap 1.9.3", "slab", "tokio", "tokio-util", "tracing", ]
[[package]] name = "hashbrown" version = "0.12.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "8a9ee70c43aaf417c914396645a0fa852624801b24ebb7ae78fe8272889ac888"
[[package]] name = "hashbrown" version = "0.14.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "2c6201b9ff9fd90a5a3bac2e56a830d0caa509576f0e503818ee82c181b3437a"
[[package]] name = "hermit-abi" version = "0.2.6" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ee512640fe35acbfb4bb779db6f0d80704c2cacfa2e39b601ef3e3f47d1ae4c7" dependencies = [ "libc", ]
[[package]] name = "http" version = "0.2.9" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "bd6effc99afb63425aff9b05836f029929e345a6148a14b7ecd5ab67af944482" dependencies = [ "bytes", "fnv", "itoa", ]
[[package]] name = "http-body" version = "0.4.5" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "d5f38f16d184e36f2408a55281cd658ecbd3ca05cce6d6510a176eca393e26d1" dependencies = [ "bytes", "http", "pin-project-lite", ]
[[package]] name = "httparse" version = "1.8.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "d897f394bad6a705d5f4104762e116a75639e470d80901eed05a860a95cb1904"
[[package]] name = "httpdate" version = "1.0.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "05842d0d43232b23ccb7060ecb0f0626922c21f30012e97b767b30afd4a5d4b9"
[[package]] name = "hyper" version = "0.14.27" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ffb1cfd654a8219eaef89881fdb3bb3b1cdc5fa75ded05d6933b2b382e395468" dependencies = [ "bytes", "futures-channel", "futures-core", "futures-util", "h2", "http", "http-body", "httparse", "httpdate", "itoa", "pin-project-lite", "socket2", "tokio", "tower-service", "tracing", "want", ]
[[package]] name = "hyper-timeout" version = "0.4.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "bbb958482e8c7be4bc3cf272a766a2b0bf1a6755e7a6ae777f017a31d11b13b1" dependencies = [ "hyper", "pin-project-lite", "tokio", "tokio-io-timeout", ]
[[package]] name = "indexmap" version = "1.9.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "bd070e393353796e801d209ad339e89596eb4c8d430d18ede6a1cced8fafbd99" dependencies = [ "autocfg", "hashbrown 0.12.3", ]
[[package]] name = "indexmap" version = "2.0.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "d5477fe2230a79769d8dc68e0eabf5437907c0457a5614a9e8dddb67f65eb65d" dependencies = [ "equivalent", "hashbrown 0.14.0", ]
[[package]] name = "itertools" version = "0.10.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "a9a9d19fa1e79b6215ff29b9d6880b706147f16e9b1dbb1e4e5947b5b02bc5e3" dependencies = [ "either", ]
[[package]] name = "itoa" version = "1.0.9" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "af150ab688ff2122fcef229be89cb50dd66af9e01a4ff320cc137eecc9bacc38"
[[package]] name = "js-sys" version = "0.3.65" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "54c0c35952f67de54bb584e9fd912b3023117cbafc0a77d8f3dee1fb5f572fe8" dependencies = [ "wasm-bindgen", ]
[[package]] name = "lazy_static" version = "1.4.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e2abad23fbc42b3700f2f279844dc832adb2b2eb069b2df918f455c4e18cc646"
[[package]] name = "libc" version = "0.2.147" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b4668fb0ea861c1df094127ac5f1da3409a82116a4ba74fca2e58ef927159bb3"
[[package]] name = "log" version = "0.4.17" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "abb12e687cfb44aa40f41fc3978ef76448f9b6038cad6aef4259d3c095a2382e" dependencies = [ "cfg-if", ]
[[package]] name = "matchers" version = "0.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558" dependencies = [ "regex-automata", ]
[[package]] name = "matchit" version = "0.7.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "0e7465ac9959cc2b1404e8e2367b43684a6d13790fe23056cc8c6c5a6b7bcb94"
[[package]] name = "memchr" version = "2.5.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "2dffe52ecf27772e601905b7522cb4ef790d2cc203488bbd0e2fe85fcb74566d"
[[package]] name = "mime" version = "0.3.16" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "2a60c7ce501c71e03a9c9c0d35b861413ae925bd979cc7a4e30d060069aaac8d"
[[package]] name = "miniz_oxide" version = "0.7.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e7810e0be55b428ada41041c41f32c9f1a42817901b4ccf45fa3d4b6561e74c7" dependencies = [ "adler", ]
[[package]] name = "mio" version = "0.8.8" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "927a765cd3fc26206e66b296465fa9d3e5ab003e651c1b3c060e7956d96b19d2" dependencies = [ "libc", "wasi", "windows-sys", ]
[[package]] name = "nu-ansi-term" version = "0.46.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84" dependencies = [ "overload", "winapi", ]
[[package]] name = "num-traits" version = "0.2.16" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "f30b0abd723be7e2ffca1272140fac1a2f084c77ec3e123c192b66af1ee9e6c2" dependencies = [ "autocfg", ]
[[package]] name = "num_cpus" version = "1.15.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "0fac9e2da13b5eb447a6ce3d392f23a29d8694bff781bf03a16cd9ac8697593b" dependencies = [ "hermit-abi", "libc", ]
[[package]] name = "object" version = "0.31.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "8bda667d9f2b5051b8833f59f3bf748b28ef54f850f4fcb389a252aa383866d1" dependencies = [ "memchr", ]
[[package]] name = "once_cell" version = "1.17.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b7e5500299e16ebb147ae15a00a942af264cf3688f47923b8fc2cd5858f23ad3"
[[package]] name = "opentelemetry" version = "0.21.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "1e32339a5dc40459130b3bd269e9892439f55b33e772d2a9d402a789baaf4e8a" dependencies = [ "futures-core", "futures-sink", "indexmap 2.0.0", "js-sys", "once_cell", "pin-project-lite", "thiserror", "urlencoding", ]
[[package]] name = "opentelemetry-otlp" version = "0.14.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "f24cda83b20ed2433c68241f918d0f6fdec8b1d43b7a9590ab4420c5095ca930" dependencies = [ "async-trait", "futures-core", "http", "opentelemetry", "opentelemetry-proto", "opentelemetry-semantic-conventions", "opentelemetry_sdk", "prost", "thiserror", "tokio", "tonic", ]
[[package]] name = "opentelemetry-proto" version = "0.4.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "a2e155ce5cc812ea3d1dffbd1539aed653de4bf4882d60e6e04dcf0901d674e1" dependencies = [ "opentelemetry", "opentelemetry_sdk", "prost", "tonic", ]
[[package]] name = "opentelemetry-semantic-conventions" version = "0.13.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "f5774f1ef1f982ef2a447f6ee04ec383981a3ab99c8e77a1a7b30182e65bbc84" dependencies = [ "opentelemetry", ]
[[package]] name = "opentelemetry_sdk" version = "0.21.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "968ba3f2ca03e90e5187f5e4f46c791ef7f2c163ae87789c8ce5f5ca3b7b7de5" dependencies = [ "async-trait", "crossbeam-channel", "futures-channel", "futures-executor", "futures-util", "glob", "once_cell", "opentelemetry", "ordered-float", "percent-encoding", "rand", "thiserror", "tokio", "tokio-stream", ]
[[package]] name = "ordered-float" version = "4.1.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "536900a8093134cf9ccf00a27deb3532421099e958d9dd431135d0c7543ca1e8" dependencies = [ "num-traits", ]
[[package]] name = "otel-bug" version = "0.1.0" dependencies = [ "opentelemetry", "opentelemetry-otlp", "opentelemetry_sdk", "tokio", "tracing", "tracing-opentelemetry", "tracing-subscriber", ]
[[package]] name = "overload" version = "0.1.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39"
[[package]] name = "percent-encoding" version = "2.2.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "478c572c3d73181ff3c2539045f6eb99e5491218eae919370993b890cdbdd98e"
[[package]] name = "pin-project" version = "1.1.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "fda4ed1c6c173e3fc7a83629421152e01d7b1f9b7f65fb301e490e8cfc656422" dependencies = [ "pin-project-internal", ]
[[package]] name = "pin-project-internal" version = "1.1.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "4359fd9c9171ec6e8c62926d6faaf553a8dc3f64e1507e76da7911b4f6a04405" dependencies = [ "proc-macro2", "quote", "syn 2.0.28", ]
[[package]] name = "pin-project-lite" version = "0.2.9" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e0a7ae3ac2f1173085d398531c705756c94a4c56843785df85a60c1a0afac116"
[[package]] name = "pin-utils" version = "0.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "8b870d8c151b6f2fb93e84a13146138f05d02ed11c7e7c54f8826aaaf7c9f184"
[[package]] name = "ppv-lite86" version = "0.2.10" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ac74c624d6b2d21f425f752262f42188365d7b8ff1aff74c82e45136510a4857"
[[package]] name = "proc-macro2" version = "1.0.66" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "18fb31db3f9bddb2ea821cde30a9f70117e3f119938b5ee630b7403aa6e2ead9" dependencies = [ "unicode-ident", ]
[[package]] name = "prost" version = "0.11.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "399c3c31cdec40583bb68f0b18403400d01ec4289c383aa047560439952c4dd7" dependencies = [ "bytes", "prost-derive", ]
[[package]] name = "prost-derive" version = "0.11.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7345d5f0e08c0536d7ac7229952590239e77abf0a0100a1b1d890add6ea96364" dependencies = [ "anyhow", "itertools", "proc-macro2", "quote", "syn 1.0.107", ]
[[package]] name = "quote" version = "1.0.32" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "50f3b39ccfb720540debaa0164757101c08ecb8d326b15358ce76a62c7e85965" dependencies = [ "proc-macro2", ]
[[package]] name = "rand" version = "0.8.5" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "34af8d1a0e25924bc5b7c43c079c942339d8f0a8b57c39049bef581b46327404" dependencies = [ "libc", "rand_chacha", "rand_core", ]
[[package]] name = "rand_chacha" version = "0.3.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e12735cf05c9e10bf21534da50a147b924d555dc7a547c42e6bb2d5b6017ae0d" dependencies = [ "ppv-lite86", "rand_core", ]
[[package]] name = "rand_core" version = "0.6.4" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ec0be4795e2f6a28069bec0b5ff3e2ac9bafc99e6a9a7dc3547996c5c816922c" dependencies = [ "getrandom", ]
[[package]] name = "regex" version = "1.7.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "48aaa5748ba571fb95cd2c85c09f629215d3a6ece942baa100950af03a34f733" dependencies = [ "regex-syntax", ]
[[package]] name = "regex-automata" version = "0.1.9" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ae1ded71d66a4a97f5e961fd0cb25a5f366a42a41570d16a763a69c092c26ae4" dependencies = [ "byteorder", "regex-syntax", ]
[[package]] name = "regex-syntax" version = "0.6.28" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "456c603be3e8d448b072f410900c09faf164fbce2d480456f50eea6e25f9c848"
[[package]] name = "rustc-demangle" version = "0.1.19" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "410f7acf3cb3a44527c5d9546bad4bf4e6c460915d5f9f2fc524498bfe8f70ce"
[[package]] name = "rustversion" version = "1.0.14" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7ffc183a10b4478d04cbbbfc96d0873219d962dd5accaff2ffbd4ceb7df837f4"
[[package]] name = "serde" version = "1.0.192" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "bca2a08484b285dcb282d0f67b26cadc0df8b19f8c12502c13d966bf9482f001" dependencies = [ "serde_derive", ]
[[package]] name = "serde_derive" version = "1.0.192" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "d6c7207fbec9faa48073f3e3074cbe553af6ea512d7c21ba46e434e70ea9fbc1" dependencies = [ "proc-macro2", "quote", "syn 2.0.28", ]
[[package]] name = "sharded-slab" version = "0.1.4" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "900fba806f70c630b0a382d0d825e17a0f19fcd059a2ade1ff237bcddf446b31" dependencies = [ "lazy_static", ]
[[package]] name = "slab" version = "0.4.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "f173ac3d1a7e3b28003f40de0b5ce7fe2710f9b9dc3fc38664cebee46b3b6527"
[[package]] name = "smallvec" version = "1.10.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "a507befe795404456341dfab10cef66ead4c041f62b8b11bbb92bffe5d0953e0"
[[package]] name = "socket2" version = "0.4.9" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "64a4a911eed85daf18834cfaa86a79b7d266ff93ff5ba14005426219480ed662" dependencies = [ "libc", "winapi", ]
[[package]] name = "syn" version = "1.0.107" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "1f4064b5b16e03ae50984a5a8ed5d4f8803e6bc1fd170a3cda91a1be4b18e3f5" dependencies = [ "proc-macro2", "quote", "unicode-ident", ]
[[package]] name = "syn" version = "2.0.28" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "04361975b3f5e348b2189d8dc55bc942f278b2d482a6a0365de5bdd62d351567" dependencies = [ "proc-macro2", "quote", "unicode-ident", ]
[[package]] name = "sync_wrapper" version = "0.1.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "20518fe4a4c9acf048008599e464deb21beeae3d3578418951a189c235a7a9a8"
[[package]] name = "thiserror" version = "1.0.40" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "978c9a314bd8dc99be594bc3c175faaa9794be04a5a5e153caba6915336cebac" dependencies = [ "thiserror-impl", ]
[[package]] name = "thiserror-impl" version = "1.0.40" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "f9456a42c5b0d803c8cd86e73dd7cc9edd429499f37a3550d286d5e86720569f" dependencies = [ "proc-macro2", "quote", "syn 2.0.28", ]
[[package]] name = "thread_local" version = "1.1.4" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "5516c27b78311c50bf42c071425c560ac799b11c30b31f87e3081965fe5e0180" dependencies = [ "once_cell", ]
[[package]] name = "tokio" version = "1.29.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "532826ff75199d5833b9d2c5fe410f29235e25704ee5f0ef599fb51c21f4a4da" dependencies = [ "autocfg", "backtrace", "bytes", "libc", "mio", "num_cpus", "pin-project-lite", "socket2", "tokio-macros", "windows-sys", ]
[[package]] name = "tokio-io-timeout" version = "1.2.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "30b74022ada614a1b4834de765f9bb43877f910cc8ce4be40e89042c9223a8bf" dependencies = [ "pin-project-lite", "tokio", ]
[[package]] name = "tokio-macros" version = "2.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "630bdcf245f78637c13ec01ffae6187cca34625e8c63150d424b59e55af2675e" dependencies = [ "proc-macro2", "quote", "syn 2.0.28", ]
[[package]] name = "tokio-stream" version = "0.1.11" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "d660770404473ccd7bc9f8b28494a811bc18542b915c0855c51e8f419d5223ce" dependencies = [ "futures-core", "pin-project-lite", "tokio", ]
[[package]] name = "tokio-util" version = "0.7.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "cc463cd8deddc3770d20f9852143d50bf6094e640b485cb2e189a2099085ff45" dependencies = [ "bytes", "futures-core", "futures-sink", "pin-project-lite", "tokio", "tracing", ]
[[package]] name = "tonic" version = "0.9.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "3082666a3a6433f7f511c7192923fa1fe07c69332d3c6a2e6bb040b569199d5a" dependencies = [ "async-trait", "axum", "base64", "bytes", "futures-core", "futures-util", "h2", "http", "http-body", "hyper", "hyper-timeout", "percent-encoding", "pin-project", "prost", "tokio", "tokio-stream", "tower", "tower-layer", "tower-service", "tracing", ]
[[package]] name = "tower" version = "0.4.13" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b8fa9be0de6cf49e536ce1851f987bd21a43b771b09473c3549a6c853db37c1c" dependencies = [ "futures-core", "futures-util", "indexmap 1.9.3", "pin-project", "pin-project-lite", "rand", "slab", "tokio", "tokio-util", "tower-layer", "tower-service", "tracing", ]
[[package]] name = "tower-layer" version = "0.3.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c20c8dbed6283a09604c3e69b4b7eeb54e298b8a600d4d5ecb5ad39de609f1d0"
[[package]] name = "tower-service" version = "0.3.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "360dfd1d6d30e05fda32ace2c8c70e9c0a9da713275777f5a4dbb8a1893930c6"
[[package]] name = "tracing" version = "0.1.40" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c3523ab5a71916ccf420eebdf5521fcef02141234bbc0b8a49f2fdc4544364ef" dependencies = [ "pin-project-lite", "tracing-attributes", "tracing-core", ]
[[package]] name = "tracing-attributes" version = "0.1.27" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "34704c8d6ebcbc939824180af020566b01a7c01f80641264eba0999f6c2b6be7" dependencies = [ "proc-macro2", "quote", "syn 2.0.28", ]
[[package]] name = "tracing-core" version = "0.1.32" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c06d3da6113f116aaee68e4d601191614c9053067f9ab7f6edbcb161237daa54" dependencies = [ "once_cell", "valuable", ]
[[package]] name = "tracing-log" version = "0.1.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "78ddad33d2d10b1ed7eb9d1f518a5674713876e97e5bb9b7345a7984fbb4f922" dependencies = [ "lazy_static", "log", "tracing-core", ]
[[package]] name = "tracing-log" version = "0.2.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" dependencies = [ "log", "once_cell", "tracing-core", ]
[[package]] name = "tracing-opentelemetry" version = "0.22.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c67ac25c5407e7b961fafc6f7e9aa5958fd297aada2d20fa2ae1737357e55596" dependencies = [ "js-sys", "once_cell", "opentelemetry", "opentelemetry_sdk", "smallvec", "tracing", "tracing-core", "tracing-log 0.2.0", "tracing-subscriber", "web-time", ]
[[package]] name = "tracing-subscriber" version = "0.3.17" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "30a651bc37f915e81f087d86e62a18eec5f79550c7faff886f7090b4ea757c77" dependencies = [ "matchers", "nu-ansi-term", "once_cell", "regex", "sharded-slab", "smallvec", "thread_local", "tracing", "tracing-core", "tracing-log 0.1.3", ]
[[package]] name = "try-lock" version = "0.2.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "59547bce71d9c38b83d9c0e92b6066c4253371f15005def0c30d9657f50c7642"
[[package]] name = "unicode-ident" version = "1.0.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "5bd2fe26506023ed7b5e1e315add59d6f584c621d037f9368fea9cfb988f368c"
[[package]] name = "urlencoding" version = "2.1.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "daf8dba3b7eb870caf1ddeed7bc9d2a049f3cfdfae7cb521b087cc33ae4c49da"
[[package]] name = "valuable" version = "0.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d"
[[package]] name = "want" version = "0.3.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "1ce8a968cb1cd110d136ff8b819a556d6fb6d919363c61534f6860c7eb172ba0" dependencies = [ "log", "try-lock", ]
[[package]] name = "wasi" version = "0.11.0+wasi-snapshot-preview1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "9c8d87e72b64a3b4db28d11ce29237c246188f4f51057d65a7eab63b7987e423"
[[package]] name = "wasm-bindgen" version = "0.2.88" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7daec296f25a1bae309c0cd5c29c4b260e510e6d813c286b19eaadf409d40fce" dependencies = [ "cfg-if", "wasm-bindgen-macro", ]
[[package]] name = "wasm-bindgen-backend" version = "0.2.88" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e397f4664c0e4e428e8313a469aaa58310d302159845980fd23b0f22a847f217" dependencies = [ "bumpalo", "log", "once_cell", "proc-macro2", "quote", "syn 2.0.28", "wasm-bindgen-shared", ]
[[package]] name = "wasm-bindgen-macro" version = "0.2.88" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "5961017b3b08ad5f3fe39f1e79877f8ee7c23c5e5fd5eb80de95abc41f1f16b2" dependencies = [ "quote", "wasm-bindgen-macro-support", ]
[[package]] name = "wasm-bindgen-macro-support" version = "0.2.88" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c5353b8dab669f5e10f5bd76df26a9360c748f054f862ff5f3f8aae0c7fb3907" dependencies = [ "proc-macro2", "quote", "syn 2.0.28", "wasm-bindgen-backend", "wasm-bindgen-shared", ]
[[package]] name = "wasm-bindgen-shared" version = "0.2.88" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "0d046c5d029ba91a1ed14da14dca44b68bf2f124cfbaf741c54151fdb3e0750b"
[[package]] name = "web-time" version = "0.2.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "57099a701fb3a8043f993e8228dc24229c7b942e2b009a1b962e54489ba1d3bf" dependencies = [ "js-sys", "wasm-bindgen", ]
[[package]] name = "winapi" version = "0.3.9" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "5c839a674fcd7a98952e593242ea400abe93992746761e38641405d28b00f419" dependencies = [ "winapi-i686-pc-windows-gnu", "winapi-x86_64-pc-windows-gnu", ]
[[package]] name = "winapi-i686-pc-windows-gnu" version = "0.4.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ac3b87c63620426dd9b991e5ce0329eff545bccbbb34f3be09ff6fb6ab51b7b6"
[[package]] name = "winapi-x86_64-pc-windows-gnu" version = "0.4.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "712e227841d057c1ee1cd2fb22fa7e5a5461ae8e48fa2ca79ec42cfc1931183f"
[[package]] name = "windows-sys" version = "0.48.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "677d2418bec65e3338edb076e806bc1ec15693c5d0104683f2efe857f61056a9" dependencies = [ "windows-targets", ]
[[package]] name = "windows-targets" version = "0.48.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "05d4b17490f70499f20b9e791dcf6a299785ce8af4d709018206dc5b4953e95f" dependencies = [ "windows_aarch64_gnullvm", "windows_aarch64_msvc", "windows_i686_gnu", "windows_i686_msvc", "windows_x86_64_gnu", "windows_x86_64_gnullvm", "windows_x86_64_msvc", ]
[[package]] name = "windows_aarch64_gnullvm" version = "0.48.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "91ae572e1b79dba883e0d315474df7305d12f569b400fcf90581b06062f7e1bc"
[[package]] name = "windows_aarch64_msvc" version = "0.48.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b2ef27e0d7bdfcfc7b868b317c1d32c641a6fe4629c171b8928c7b08d98d7cf3"
[[package]] name = "windows_i686_gnu" version = "0.48.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "622a1962a7db830d6fd0a69683c80a18fda201879f0f447f065a3b7467daa241"
[[package]] name = "windows_i686_msvc" version = "0.48.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "4542c6e364ce21bf45d69fdd2a8e455fa38d316158cfd43b3ac1c5b1b19f8e00"
[[package]] name = "windows_x86_64_gnu" version = "0.48.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "ca2b8a661f7628cbd23440e50b05d705db3686f894fc9580820623656af974b1"
[[package]] name = "windows_x86_64_gnullvm" version = "0.48.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7896dbc1f41e08872e9d5e8f8baa8fdd2677f29468c4e156210174edc7f7b953"
[[package]] name = "windows_x86_64_msvc" version = "0.48.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "1a515f5799fe4961cb532f983ce2b23082366b898e52ffbce459c86f67c8378a"
Any known workarounds?
A quick workaround would be place the tracer_provider.force_flush() inside a blocking task. Something like
let handle = tokio::task::spawn_blocking(move || {
println!("start trace_provider flush");
for r in tracer_provider.force_flush() {
if let Err(e) = r {
println!("unable to fully flush traces: {e}");
}
}
println!("finished trace_provider flush");
});
handle.await
Background
The root cause for those issues is we want run a blocking operation in an async context, which can block the async scheduler from moving forward forever.
Consider the following example
#[tokio::main(flavor = "multi_thread", worker_threads = 10)]
async fn main() {
// setup a tracer provider w/ batch span processor
// when starting a batch span processor we also spawn a task to handle all message, including force flush and shutdown
// we will call it the batch span processing tasks
let _ = tokio::spawn(async move {
let _ = tracer_provider.force_flush() {
}).await;
}
Runnnig the example you will observe two tasks
- The batch span procssing task, which can receive a force flush message and respond to it.
- The force push task, which sends a mesasge to batch span procssing task and block on it's response
The two tasks can deadlock when the force push task takes priority. Since force push task never yield the resource to other tasks. The batch span procsssing task never gets a chance to run and respond to force push task.
Possible Solutions
1. separate resource pool The general idea is to separate the two tasks mentioned above. Consider the following resource pool available in an async setup:
- Async task pool. Spawn from
tokio::spawn. Tasks use this pool must not block otherwise the whole pool can deadlock - Blocking task pool. Spawn from
tokio::tasks::spawn_blocking. For any tasks that blocks this should be their resource pool - Dedicate thread. Spawn a dedicated thread with
std::thread::spawn.
We should spawn the force push task to background threads and allow users to await on them. This benifits the overall performance in following ways:
- The batch span procssing task can stay on the async task pool. Thus, it can take the benifit of coop schduling and stay idle when there is no spans
- The
force_pushis a most likely expensive operation because of the network IO involves.
Based on the idea above we can add a force_push_async function like this
pub fn force_push_async(&self) -> tokio::task::JoinHandle<Vec<TraceResult<()>>> {
let inner = self.inner.clone();
tokio::task::spawn_blocking(move || {
inner.processors
.iter()
.map(|processor| processor.force_flush())
.collect()
})
}
// once user has the handle they can await on it in an async context
force_push_async().await;
Reference
- Tokio recommendation on how to handle blocking tasks link
Any known workarounds?
A quick workaround would be place the
tracer_provider.force_flush()inside a blocking task. Something likelet handle = tokio::task::spawn_blocking(move || { println!("start trace_provider flush"); for r in tracer_provider.force_flush() { if let Err(e) = r { println!("unable to fully flush traces: {e}"); } } println!("finished trace_provider flush"); }); handle.await
Thanks, I think I'm seeing a combination of this issue, as well as the fact that the timeouts for the exporter and tracer are high by default and in the case where tracing is enabled but no collector is running, it takes a full 10 minutes by default for the timeouts to expire!
This made is so that when I was debugging deadlocks, I didn't realize if I fixed it because I didn't wait 10 minutes lol
@TommyCpp Can I just ask for clarification, how does it block the runtime? I thought that since the multi-threaded runtime uses several threads (in your example 10), then the blocking flush call would just block one of the threads but the background task doing the actual flushing would continue on any of the other threads?
@TommyCpp Can I just ask for clarification, how does it block the runtime? I thought that since the multi-threaded runtime uses several threads (in your example 10), then the blocking flush call would just block one of the threads but the background task doing the actual flushing would continue on any of the other threads?
My understanding is that if you flush from the main function, that doesn't run on a worker thread and can block the runtime.
I'm writing a small helper around OpenTelemetry, and I would love to be able to rely on the Drop trait to force_flush/shutdown the providers, instead of asking for the helper users to think about calling my_helper.shutdown().await themselves at the end of the main() function.
I though that it would be easy to use the Drop trait in my helper to flush/shutdown everything automatically, since the opentelemetry APIs are not async...
impl Drop for MyHelper {
fn drop(&mut self) {
for r in tracer_provider.force_flush() {
if let Err(e) = r {
println!("Failed to flush OpenTelemetry tracing: {e}");
};
}
opentelemetry::global::shutdown_tracer_provider();
}
}
However, by relying on the Drop trait (in an async fn main() context), now I see 1 or 2 error message like this one, printed in stdout when I stop my program using CTRL+C:
OpenTelemetry trace error occurred. cannot send message to batch processor as the channel is closed
Is this related to the explanation of TommyCpp and therefore my_helper.shutdown().await will have to stay?
