tracing improvments and separation of runtime/services traces #1903

muhamadazmy · 2024-08-28T10:00:46Z

tracing improvments and separation of runtime/services traces

Stack created with Sapling. Best reviewed with ReviewStack.

muhamadazmy · 2024-08-28T13:30:28Z

https://www.notion.so/restatedev/Tracing-1b471c273ba640549df331810ab21743

muhamadazmy · 2024-08-28T13:37:13Z

crates/types/src/config/common.rs

+#[cfg_attr(feature = "schemars", derive(schemars::JsonSchema))]
+#[cfg_attr(feature = "schemars", schemars(default))]
+#[serde(rename_all = "kebab-case")]
+pub struct TracingOptions {


Seem that me and @tillrohrmann decided to create TracingOptions at the same time. So i merged the headers attribute into my strcuture

tillrohrmann

Thanks a lot for adding support for separating service traces and runtime traces @muhamadazmy. I like the approach of emitting spans with a special target that get filtered, well done :-) I left a few minor comments and questions which we could address.

tillrohrmann · 2024-08-28T17:22:14Z

crates/invoker-impl/src/invocation_task/mod.rs

+        fields(rpc.system = "restate",
+        rpc.service = %self.invocation_target.service_name(),


nit: Formatting seems inconsistent

nit: The formatting seems still to be off. Not a deal breaker, though.

tillrohrmann · 2024-08-28T20:02:04Z

crates/tracing-instrumentation/src/lib.rs

+            .with_version(env!("CARGO_PKG_VERSION"))
+            .build(),
+    );
+    // let _ = opentelemetry::global::set_tracer_provider(provider);


Can this be removed?

yeah, definitely

crates/tracing-instrumentation/src/lib.rs

tillrohrmann · 2024-08-28T20:04:58Z

crates/tracing-instrumentation/src/lib.rs

 use tracing_subscriber::fmt::time::SystemTime;
 use tracing_subscriber::fmt::writer::MakeWriterExt;
 use tracing_subscriber::layer::SubscriberExt;
 use tracing_subscriber::reload::Handle;
 use tracing_subscriber::util::SubscriberInitExt;
 use tracing_subscriber::{EnvFilter, Layer, Registry};

+pub const DEPLOYMENT_TARGET: &str = "::deployment.target";


Is this the deployment target == service target?

It's the tracing target i use for services yes. Maybe SERVICES_TARGET is a better name.

crates/tracing-instrumentation/src/lib.rs

tillrohrmann · 2024-08-28T20:56:06Z

crates/tracing-instrumentation/src/lib.rs


    Ok(Some(
        tracing_opentelemetry::layer()
            .with_location(false)
            .with_threads(false)
            .with_tracked_inactivity(false)
            .with_tracer(tracer)
-            .with_filter(EnvFilter::try_new(&common_opts.tracing.tracing_filter)?),
+            .with_filter(EnvFilter::try_new(&opts.filter)?)
+            .with_filter(filter_fn(|meta| meta.target() != DEPLOYMENT_TARGET))


Out of curiosity: Is it more performant to only have a single tracer if runtime and service tracing is the same? In that case, I guess one would only need to not set this filter here.

services tracer still also inlcudes the SpanModifyingTracer and ResourceModifyingSpanExporter which is not used by the runtime tracer.

I have already tried to remove this filter before from the runtime so the same span is recorded in both but this caused a panic on start up

2024-08-29T14:17:44.853716Z ERROR tracing_panic A panic occurred panic.payload: "assertion failed: self.replace(val).is_none()" panic.location: "/home/azmy/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-subscriber-0.3.18/src/registry/extensions.rs:88:9" panic.backtrace: 0: tracing_panic::panic_hook at /home/azmy/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-panic-0.1.2/src/lib.rs:74:25 1: restate_server::main::{{closure}}::{{closure}} at ./server/src/main.rs:176:17 2: <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/alloc/src/boxed.rs:2036:9 3: std::panicking::rust_panic_with_hook at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:799:13 4: std::panicking::begin_panic_handler::{{closure}} at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:656:13 ...

The panic of course includes many more line. The panic is originated from the tracing subscriber crate i tried to reconfigure the layers in a way that doesn't cause this with no luck, my only solution was to not process the services spans by the runtime tracer

crates/invoker-impl/src/invocation_task/mod.rs

tillrohrmann · 2024-08-29T07:12:54Z

crates/tracing-instrumentation/src/lib.rs

+    let resource = opentelemetry_sdk::Resource::new(vec![
+        KeyValue::new(
+            opentelemetry_semantic_conventions::resource::SERVICE_NAME,
+            service_name.clone(),


Is it possible to update this value once we have the NodeId obtained? Then we could distinguish the traces originating from different Restate nodes.

there is already another key "SERVICES_INSTANCE_ID" below for that specific reason. But I will look into this as well

tillrohrmann · 2024-08-29T07:48:54Z

crates/worker/src/partition/state_machine/mod.rs

-            .span_context
-            .as_parent()
-            .attach_to_span(&Span::current());
+        Span::current().set_relation(service_invocation.span_context.as_parent());


I think that this will cause some internal spans to have an invalid parent span configured when separating the services and runtime tracing to two different jaeger endpoints. As a result those internal spans lose their context.

I think it would be a great state if we can send the runtime and services traces to separate jaeger endpoints and the traces on each of the endpoints are consistent and helpful. Whether they link together when shown on the same endpoint, is probably not so important because the services traces do only present a make-belief reality anyway.

tillrohrmann · 2024-08-29T07:56:56Z

crates/worker/src/partition/state_machine/mod.rs

+            instrumentation::info_invocation_span!(
+                prefix = "suspend",
+                id = invocation_id,
+                target = metadata.invocation_target,


What happens with this target? Will it be overwritten by DEPLOYMENT_TARGET?

This is our custom invocation_span, and this target is the invocation_target, not the tracing target. Same way id here is the invocation_id

slinkydeveloper · 2024-08-29T12:09:01Z

I like the approach of emitting spans with a special target that get filtered, well done :-) I left a few minor comments and questions which we could address.

Will it be possible with this approach to:

Avoid mixing parent spans between user span/runtime span
Have different severity levels
Have different sampling ratio/configuration

Plus another thing we should check is whether this PR breaks tracing propagation in the SDK (essentially what happens here https://github.com/restatedev/restate/pull/1903/files#diff-4de20bc15971f83cf8f16a1a858cdaf6cbc58122f211a477e77cfefc17f2fc64R129 needs to generate the correct headers to let otel on the service side to correctly relate with the parent user span). I know @jackkleeman was working on this topic specifically.

tillrohrmann

Thanks for updating the PR @muhamadazmy. The changes look good to me.

The one thing which I would like to discuss is whether the internal runtime spans should or should not be linked to the services traces. Right now, I believe we do link them (at least sporadically). The result is that we see a couple of orphaned spans when separating the runtime and services traces, I believe.

I am wondering whether the services traces should be completely separate of the runtime traces and we only report them if the user has configured services_tracing? In this world, the runtime traces would also contain information about service calls but in a form as the runtime executes them (no artificial span modifying to make users believe that service invocations happen continuously, etc.).

tillrohrmann · 2024-08-29T16:29:21Z

crates/invoker-impl/src/invocation_task/mod.rs

+        fields(rpc.system = "restate",
+        rpc.service = %self.invocation_target.service_name(),


nit: The formatting seems still to be off. Not a deal breaker, though.

crates/invoker-impl/src/invocation_task/mod.rs

tillrohrmann · 2024-08-29T16:33:28Z

crates/invoker-impl/src/invocation_task/service_protocol_runner.rs

-        let invocation_task_span = Span::current();
-        journal_metadata
-            .span_context
-            .as_parent()
-            .attach_to_span(&invocation_task_span);
+        Span::current().set_relation(journal_metadata.span_context.as_parent());


I am wondering whether these internal spans should really be associated with the services trace. Maybe it is simplest if we keep the services and runtime traces separate because then there is no problem if we send them to two different jaeger endpoints.

tillrohrmann · 2024-08-29T16:36:52Z

crates/tracing-instrumentation/src/lib.rs

+    if let Some(path) = &opts.json_path {
        let exporter = JaegerJsonExporter::new(
            path.into(),
            "trace".to_string(),
-            service_name,
+            SERVICE_NAME.into(),


Did we come to a conclusion whether there is a problem with two exporters writing to the same output file? If we didn't default to the tracing runtime settings, then people wouldn't run into this problem (assuming it is a problem) so easily.

tillrohrmann · 2024-08-29T16:37:32Z

crates/tracing-instrumentation/src/lib.rs

+    // the following logic is based on `opentelemetry_otlp::span::build_batch_with_exporter`
+    // but also injecting ResourceModifyingSpanExporter around the SpanExporter


This comment seems outdated.

tillrohrmann · 2024-08-29T16:38:01Z

crates/tracing-instrumentation/src/lib.rs

@@ -207,10 +294,13 @@ pub fn init_tracing_and_logging(
    #[cfg(feature = "console-subscriber")]
    let layers = layers.with(console_subscriber::spawn());

-    // Tracing layer
-    let layers = layers.with(build_tracing_layer(
+    // Deployments Tracing layer


Suggested change

// Deployments Tracing layer

// Services Tracing layer

crates/tracing-instrumentation/src/lib.rs

tillrohrmann · 2024-08-29T16:39:15Z

crates/tracing-instrumentation/src/lib.rs

+}
+
+#[macro_export]
+macro_rules! info_invocation_span {


Same here with the Rustdoc.

tillrohrmann · 2024-08-29T16:41:05Z

crates/worker/src/partition/state_machine/mod.rs

-            journal_metadata
-                .span_context
-                .as_parent()
-                .attach_to_span(&Span::current());
+            Span::current().set_relation(journal_metadata.span_context.as_parent());


I am a bit unsure about linking internal spans to the services trace. The problem I see is that we will end up with orphaned spans if the runtime and services tracing spans end up on different jaeger endpoints.

This is handled during Export of spans (by the RuntimeServicesExporter) to separate (and alter) services spans.

The exporter will make sure to emit all spans to the 2 endpoints, it will also derive new traces and span ids for services spans so they maintain their relationship if they are reported to the same or different endpoint

tillrohrmann · 2024-08-29T16:43:39Z

crates/worker/src/partition/state_machine/mod.rs

-            .span_context
-            .as_parent()
-            .attach_to_span(&Span::current());
+        Span::current().set_relation(service_invocation.span_context.as_parent());


I think it would be a great state if we can send the runtime and services traces to separate jaeger endpoints and the traces on each of the endpoints are consistent and helpful. Whether they link together when shown on the same endpoint, is probably not so important because the services traces do only present a make-belief reality anyway.

muhamadazmy · 2024-09-09T08:27:42Z

superseded by #1922

muhamadazmy mentioned this pull request Aug 28, 2024

Tracing improvements #1904

Closed

muhamadazmy force-pushed the pr1903 branch 2 times, most recently from 7a0828b to 777e13e Compare August 28, 2024 12:59

muhamadazmy changed the title ~~improving deployment invocation tracing~~ tracing improvments and separation of runtime/services traces Aug 28, 2024

muhamadazmy force-pushed the pr1903 branch from 777e13e to 8092344 Compare August 28, 2024 13:09

muhamadazmy force-pushed the pr1903 branch from 8092344 to f0d9758 Compare August 28, 2024 13:35

muhamadazmy commented Aug 28, 2024

View reviewed changes

muhamadazmy requested review from AhmedSoliman and tillrohrmann August 28, 2024 13:37

muhamadazmy force-pushed the pr1903 branch from f0d9758 to a6e689b Compare August 28, 2024 14:49

tillrohrmann reviewed Aug 29, 2024

View reviewed changes

muhamadazmy force-pushed the pr1903 branch from a6e689b to 5e15737 Compare August 29, 2024 13:56

tillrohrmann reviewed Aug 29, 2024

View reviewed changes

muhamadazmy force-pushed the pr1903 branch 3 times, most recently from d996b2a to b101ca6 Compare September 3, 2024 09:05

tracing improvments and separation of runtime/services traces

56d6c6e

muhamadazmy force-pushed the pr1903 branch from b101ca6 to 56d6c6e Compare September 3, 2024 12:01

muhamadazmy mentioned this pull request Sep 5, 2024

use opentelemetry to separate services from runtime traces #1922

Merged

muhamadazmy closed this Sep 9, 2024

muhamadazmy deleted the pr1903 branch September 9, 2024 08:27

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

tracing improvments and separation of runtime/services traces #1903

tracing improvments and separation of runtime/services traces #1903

muhamadazmy commented Aug 28, 2024 •

edited

Loading

muhamadazmy commented Aug 28, 2024

muhamadazmy Aug 28, 2024

tillrohrmann left a comment

tillrohrmann Aug 28, 2024

tillrohrmann Aug 29, 2024

tillrohrmann Aug 28, 2024

muhamadazmy Aug 29, 2024

tillrohrmann Aug 28, 2024

muhamadazmy Aug 29, 2024

tillrohrmann Aug 28, 2024

muhamadazmy Aug 29, 2024 •

edited

Loading

tillrohrmann Aug 29, 2024

muhamadazmy Aug 29, 2024

tillrohrmann Aug 29, 2024

tillrohrmann Aug 29, 2024

tillrohrmann Aug 29, 2024

muhamadazmy Aug 30, 2024

slinkydeveloper commented Aug 29, 2024 •

edited

Loading

tillrohrmann left a comment •

edited

Loading

tillrohrmann Aug 29, 2024

tillrohrmann Aug 29, 2024

tillrohrmann Aug 29, 2024

tillrohrmann Aug 29, 2024

tillrohrmann Aug 29, 2024

tillrohrmann Aug 29, 2024

tillrohrmann Aug 29, 2024

muhamadazmy Sep 3, 2024

tillrohrmann Aug 29, 2024

muhamadazmy commented Sep 9, 2024

		fields(rpc.system = "restate",
		rpc.service = %self.invocation_target.service_name(),

		// the following logic is based on `opentelemetry_otlp::span::build_batch_with_exporter`
		// but also injecting ResourceModifyingSpanExporter around the SpanExporter

tracing improvments and separation of runtime/services traces #1903

tracing improvments and separation of runtime/services traces #1903

Conversation

muhamadazmy commented Aug 28, 2024 • edited Loading

muhamadazmy commented Aug 28, 2024

Choose a reason for hiding this comment

tillrohrmann left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

muhamadazmy Aug 29, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

slinkydeveloper commented Aug 29, 2024 • edited Loading

tillrohrmann left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

muhamadazmy commented Sep 9, 2024

muhamadazmy commented Aug 28, 2024 •

edited

Loading

muhamadazmy Aug 29, 2024 •

edited

Loading

slinkydeveloper commented Aug 29, 2024 •

edited

Loading

tillrohrmann left a comment •

edited

Loading