search

Shopify / graphql-metrics

Extract as much much detail as you want from GraphQL queries, served up from your Ruby app and the graphql gem.
MIT License
169 stars 13 forks source link

Metrics for multiplexes are a bit broken/inaccurate. #45

Open chrisbutcher opened 3 years ago

chrisbutcher commented 3 years ago

Edit: Problems #1 and #2 appear to be non-problems. See below.

As demonstrated in this PR, and in the below multiplex scenario walkthrough, timings for parsing, lexing and query duration are wrong when executing multiplexes.

There are last-write wins problems in lexing/parsing timings in the Tracer, and query durations are inaccurate because we wait until Instrumentation.after_query to calculate them.

The queries being executed in the throwaway PR are:

test 'multiplex test' do
    queries = [
    {
      query: 'query QueryOne { post(id: "42") { id title } }',
      operation_name: 'QueryOne',
    },
    {
      query: 'query QueryTwo { post(id: "42") { body } }',
      operation_name: 'QueryTwo',
    },
  ]

  SchemaWithFullMetrics.multiplex(queries)
# ...
chrisbutcher commented 3 years ago

cc: @eapache @RobertWSaunders

eapache commented 3 years ago

This explanation makes sense to me, though it raises one other question: I consistently see execute_multiplex running after lex and parse, and you seem to consistently see it running before. What's going on here?

chrisbutcher commented 3 years ago

@eapache In those instances, are you passing .multiplex an already-parsed GraphQL::Query or a document string? This is my best guess as to why the order might differ.

eapache commented 3 years ago

This is in core, which instantiates a GraphQL::Query instance with the string, and then calls .result on it. AFAICT this intentionally lexes/parses before it enters the multiplexer: https://github.com/rmosolgo/graphql-ruby/blob/5c3a8ec6f45319f40cb59f2ffb5961bb1071aa80/lib/graphql/query.rb#L198-L200

This may be a genuine inconsistency within the graphql-ruby gem depending on the entrypoint you use?

Yes: https://github.com/rmosolgo/graphql-ruby/issues/3393

chrisbutcher commented 3 years ago

On second thought: Problems 1 and 2 might not actually be problems?

While it's true that the pre_context is not aware of mulitplexes (and multiple queries, contexts), we do run parse, lex and validate in that order, each time we run validate, we're using the values for parsing and lexing time that we last stored.

So long as graphql-ruby never runs something like parse (query 1), lex (query 1), parse (query 2), lex (query 2), validate (query 1), validate (query 2), and always does parse 1, lex 1, validate 1, parse n, lex n, validate n; we're ok?

Maybe the real problem is that if you pass a multiplex an unparsed document string and an already parsed query object (as one of our existing tests does), you don't always get a validate event that is preceded by a parse/lex events for the same query.

If that's true, maybe we just need to clear the pre_context after validate makes use of any values within?

tldr after sync: