Add tracing support for GraphQL objects, interfaces and subscriptions #972

ArsileLuci · 2021-07-23T07:24:48Z

Superseeds #720
Part of #953

This PR adds tracing support for GraphQL objects, interfaces and subscriptions.

Add #[tracing] attribute that should be used #[graphql_object], #[graphql_interface] attributes and derived GraphQL objects.
Add #[instrument] attribute on GraphQL fields, that can be used to tune how each field is traced
Impl tests for code related to tracing

Before review:

Ensure proper formatting
Run all tests
Update the CHANGELOG

This reverts commit 753c80f.

ArsileLuci · 2021-07-23T13:42:33Z

cc @tyranron

tyranron

@ArsileLuci thanks, quite raw and rough at the moment, needs more design polishing and some reconsiderations.

tyranron · 2021-07-23T14:49:20Z

juniper/src/lib.rs

+                    .iter()
+                    .map(|e| format!("{}", e))
+                    .collect::<Vec<_>>()
+                    .join("\n");


@ArsileLuci here the allocation is redundant. There are easier and more obvious way to strip the last newline.

tyranron · 2021-07-23T14:50:29Z

juniper/src/macros/tracing.rs

@@ -0,0 +1,130 @@
+// Macros to instrument future spans.


@ArsileLuci why not doc comment?

tyranron · 2021-07-23T15:05:14Z

juniper/src/lib.rs

+        &document, operation, root_node, variables, context,
+    );
+
+    __juniper_instrument_trace!(f, "execute_validated_query").await


@ArsileLuci seems that shoud be:

__juniper_instrument_trace!(f, "execute_validated_query_async").await

tyranron · 2021-07-23T15:07:18Z

juniper/src/util.rs

@@ -51,3 +51,22 @@ fn test_to_camel_case() {
    assert_eq!(&to_camel_case("a")[..], "a");
    assert_eq!(&to_camel_case("")[..], "");
 }
+
+#[cfg(feature = "tracing-futures")]


@ArsileLuci why "tracing-futures"? It will complicate looking for feature-gated stuff. It's better to gate everything under the single "tracing" feature, unless these two are going to be used separately, which is not our case.

tyranron · 2021-07-23T15:11:33Z

juniper/src/util.rs

+
+    /// Required to pass sanity tests when `Instrument` already imported.
+    pub trait InstrumentInternal {
+        fn __instrument(self, span: Span) -> Instrumented<Self>


@ArsileLuci still, seems to be quite redundant.

tyranron · 2021-07-23T15:47:16Z

juniper_codegen/src/util/mod.rs

@@ -1291,7 +1366,7 @@ impl GraphQLTypeDefiniton {
                                        Err(e) => Err(ex.new_error(e)),
                                    }
                                }
-                            });
+                            }) #trace_async;


and here it will be like

}); #trace_async

tyranron · 2021-07-23T15:48:43Z

juniper_codegen/src/util/mod.rs

@@ -4,6 +4,9 @@ pub mod duplicate;
 pub mod parse_impl;
 pub mod span_container;

+#[cfg(feature = "tracing")]
+pub mod tracing;


@ArsileLuci it's better to move it from util module to crate root and have a straight-forward tracing module.

tyranron · 2021-07-23T15:51:25Z

juniper_codegen/src/util/mod.rs

@@ -680,6 +706,9 @@ pub struct GraphQLTypeDefinitionField {
    pub is_async: bool,
    pub default: Option<TokenStream>,
    pub span: Span,
+
+    #[cfg(feature = "tracing")]
+    pub tracing: Option<tracing::Attr>,


@ArsileLuci also, as #[tracing] represent a separate attribute, it woud be nice to not embed it here, but rather parse separately and use directly.

@tyranron

parse separately and use directly.

You mean instead of expanding it within #[graphql_object]/#[graphql_interface] etc, we could just expand it separately for each field?

tyranron · 2021-07-23T15:56:00Z

juniper/src/tests/fixtures/tracing/schema.rs

+/// Derived GraphQL object marked with `trace = "complex"`.
+#[derive(GraphQLObject)]
+#[graphql(trace = "complex")]
+pub struct DerivedComplex {


@ArsileLuci I think we can use here #[tracing(complex)] too.

Also, let's check whether we can do that for #[graphql_object] macro, by looking up this attribute on a definition, parsing it and removing it. If not, it would be better to keep the similar to other cases format:

#[graphql_object(tracing(complex))]

This should also simplify the parsing, as we would have similar patterns everywhere.

tyranron · 2021-07-23T15:58:31Z

juniper_codegen/src/util/tracing.rs

+    name: Option<syn::LitStr>,
+
+    /// Overwritten `level` of span generated, if `None` `Level::INFO` should be used.
+    level: Option<syn::LitStr>,


@ArsileLuci also, why parse all the attribute arguments by ourselves? Cannot we piggyback everything to upstream (tracing crate)?

@tyranron span!(...) macro is pretty strict on argument order, and we need to cleanup arguments specific for juniper, so a little of extra work here will allow to forget about argument order.

tyranron · 2021-08-11T14:43:01Z

@ArsileLuci #971 is merged.

docs/book/content/tracing/index.md

ArsileLuci · 2021-08-15T11:28:50Z

@tyranron I want to discuss one feature in tracing that is currently risky to implement in Juniper. This is so called Empty fields, due to how we resolve fields we cannot use it in actual resolver (fn that's called within resolve_field and resolve_field_async to get value), we're limited to context of resolve_field or resolve_field_async.

It could be implemented by dirty modification of fns signature, but it's a little bit unfair, I guess.

Edit:

This also can be solved if user implicitly reference Span passed to fn, similarly to how Context and Executor passed, this variant more fair and clean than one suggested above.

Edit2:

The solution is much simpler. User could just use tracing::Span::current() to get access to current Span within resolver fn. So we don't need to bother about dealing with it.

mathroc · 2021-11-24T23:45:51Z

Hi!

Once this lands, I'd like to work on #953 and hope to be able to leverage this. My idea is to create a tracing collector and capture relevant span data to later be able to output the expected JSON. I'm wondering if there is enough already or if some tracing could be added (now or later):

    "tracing": {
      "version": 1,
      "startTime": <>, → that would be the "enter execute"
      "endTime": <>, → "close execute"
      "duration": <>, → the duration of the "execute" span
      "parsing": { → I don't think this is present at the moment
        "startOffset": <>, 
        "duration": <>,
      },
      "validation": {  -> there's "validate_document" & "validate_input_values" but I don't know if a duration can be extracted from simple spans. Should they be wrapped by a "start/close validation" span ?
        "startOffset": <>,
        "duration": <>,
      },
      "execution": {
        "resolvers": [ → They are traced. I would need to check if, 1: they can be identified easily, 2: everything below can be extracted from the span or could be added later
          {
            "path": [<>, ...],
            "parentType": <>,
            "fieldName": <>,
            "returnType": <>,
            "startOffset": <>,
            "duration": <>,
          },
          ...
        ]
      }

Do you think something like that would be possible?

LegNeato · 2021-11-25T08:11:26Z

What outstanding issues are we waiting on here?

ArsileLuci · 2021-11-25T08:25:25Z

Hi @mathroc

About this one:

"validation": { -> there's "validate_document" & "validate_input_values" but I don't know if a duration can be extracted from simple spans. Should they be wrapped by a "start/close validation"

Everything related to duration/time should be implemented on Subscriber side.

1: they can be identified easily, 2: everything below can be extracted from the span or could be added later

It's not so simple, probably the only way to identify whether this is field resolver or not is to add custom marker field in every resolver, something like juniper-resolver=true.
Let's walk through every field and check what we can do:

path: This will involve some work but all resolver spans follow one naming schema <TypeName>.<resolverName>. Combining it with custom marker field, mentioned above, you can walkthrough every single span and build resolver chain.
parentType: If I understand it right this is <TypeName> in span name so there should be no problems with it.
fieldName: Same to parentType but this is <resolverName>
returnType: This should be implemented, probably using late binding fields
startOffset and duration: also should be implemented manually

The biggest disadvantage I see so far is making a whole lot of custom fields. In process of working on this PR I've tested this with stack tracing -> tracing_opentelemetry -> opentelemetry_jaeger and all custom fields were sent to Jaeger. This resulted in Jaeger denying nearly half of my traces because "they are too large".

mathroc · 2021-11-25T08:42:05Z

thx @ArsileLuci for the feedback. Would you recommend doing something completely separate instead?

ArsileLuci · 2021-11-25T09:24:16Z

@mathroc

Would you recommend doing something completely separate instead?

If you need this exact feature, it could be implemented under feature flag either disabling or enabling it. The issue with Jaeger, could be simply solved, by just disabling this extra fields. Just explicitly mention it in the docs, and this should be enough.

@LegNeato

What outstanding issues are we waiting on here?

I don't think there's any, except this branch being a bit old (and forgotten).

tyranron · 2021-11-25T12:21:10Z

@LegNeato this branch requires some serious review. We (me, @ArsileLuci and @ilslv) have plans to revive it after merging #975

After this PR we will land some subsequent ones, hopefully to fully close the question about tracing in juniper.

mihai-dinculescu and others added 30 commits July 25, 2020 20:57

Add tracing support

e0f7eb5

Merge branch 'master' into add_tracing_support

419520d

Merge branch 'master' into add_tracing_support

c1f9e5f

Rocket can now compile on stable

753c80f

Remove boxed in favor of pin.

c599bae

Add tracing support example

b556934

Add some coarse execution tracing

0134da3

Remove old comment / docs

5c888a8

Merge branch 'master' into add_tracing_support

ef2da9b

Fix book tests

01b3453

fix up some imports

7ac7304

Add back subscriber Cargo.toml instructions

06687dd

Change trace errors to trace

697a743

Tracing unit tests

f2977d5

Tracing unit tests names

6c3654c

Revert "Rocket can now compile on stable"

7f746de

This reverts commit 753c80f.

Merge branch 'master' into add_tracing_support

64cad08

Merge branch 'master' into add_tracing_support

d7acba9

Fix tracing spans

88dc9c4

Do not include trailing newline on the last error

8a2f6ec

Standard tracing labels on snake_case

83fd44d

Add a validation error case to the tracing example

c92dd87

Use $crate everywhere

64d8e11

Add other levels to span macros

cdbc0ce

Merge branch 'master' into add_tracing_support

65ab688

Merge branch 'master' into add_tracing_support

6cf48d9

Merge branch 'master' into add_tracing_support

5f8a4ca

Merge branch 'master' into add_tracing_support

ae1054e

Use the released tracing crate

5938345

Fix email address

8bc07f6

Minor corrections [run ci]

b2a285a

ArsileLuci marked this pull request as ready for review July 23, 2021 13:41

tyranron requested changes Jul 23, 2021

View reviewed changes

tyranron and others added 4 commits July 23, 2021 18:59

Some corrections

33d6952

WIP

1af4115

Refactor

46c76bc

Book corrections

5dbdc94

ArsileLuci added 4 commits August 12, 2021 08:32

Fetch upstream

07bae4b

Restore tracing codegen

c256a2e

Book and docs correction

123a87b

fmt fix

3420e8f

mathroc reviewed Aug 14, 2021

View reviewed changes

docs/book/content/tracing/index.md Outdated Show resolved Hide resolved

ArsileLuci added 4 commits August 15, 2021 14:30

Impl sigils

7e31803

Impl field::Empty

ae02db7

Improve subscription tracing [run ci]

e69f261

Remove redundant code

c22ef43

ArsileLuci requested a review from tyranron August 17, 2021 11:01

ArsileLuci and others added 2 commits August 31, 2021 13:09

Merge branch 'graphql-rust:master' into tracing-support

a2e43fc

Small corrections [run-ci]

4861c24

tyranron marked this pull request as draft May 31, 2022 12:00

tyranron force-pushed the master branch from 875e399 to 2682ee1 Compare May 2, 2024 16:03

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add tracing support for GraphQL objects, interfaces and subscriptions #972

Add tracing support for GraphQL objects, interfaces and subscriptions #972

ArsileLuci commented Jul 23, 2021 •

edited

Loading

ArsileLuci commented Jul 23, 2021

tyranron left a comment

tyranron Jul 23, 2021

tyranron Jul 23, 2021

tyranron Jul 23, 2021

tyranron Jul 23, 2021

tyranron Jul 23, 2021

tyranron Jul 23, 2021

tyranron Jul 23, 2021

tyranron Jul 23, 2021

ArsileLuci Jul 23, 2021

tyranron Jul 23, 2021

tyranron Jul 23, 2021

ArsileLuci Jul 23, 2021

tyranron commented Aug 11, 2021

ArsileLuci commented Aug 15, 2021 •

edited

Loading

mathroc commented Nov 24, 2021

LegNeato commented Nov 25, 2021

ArsileLuci commented Nov 25, 2021 •

edited

Loading

mathroc commented Nov 25, 2021

ArsileLuci commented Nov 25, 2021

tyranron commented Nov 25, 2021

Add tracing support for GraphQL objects, interfaces and subscriptions #972

Are you sure you want to change the base?

Add tracing support for GraphQL objects, interfaces and subscriptions #972

Conversation

ArsileLuci commented Jul 23, 2021 • edited Loading

ArsileLuci commented Jul 23, 2021

tyranron 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

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

tyranron commented Aug 11, 2021

ArsileLuci commented Aug 15, 2021 • edited Loading

mathroc commented Nov 24, 2021

LegNeato commented Nov 25, 2021

ArsileLuci commented Nov 25, 2021 • edited Loading

mathroc commented Nov 25, 2021

ArsileLuci commented Nov 25, 2021

tyranron commented Nov 25, 2021

ArsileLuci commented Jul 23, 2021 •

edited

Loading

ArsileLuci commented Aug 15, 2021 •

edited

Loading

ArsileLuci commented Nov 25, 2021 •

edited

Loading