Add GraphQL::Tracing

[rmosolgo]

GraphQL::Tracing wraps gem internals so that subscribers can receive the metadata.

TODO

• write a guide?
• Use only one . in the active support key

[rmosolgo]

cc @matsimitsu how does this ActiveSupport::Notification implementation look?

I didn't put a lot of metadata in the hash, but you can access anything from context, for example:

context = metadata[:context]
context.path # => ["field1", "field2", ... ]
context.query # => GraphQL::Query 
context.ast_node # => GraphQL::Language::Nodes::Field 
context.irep_node # => GraphQL::InternalRepresentation::Node 

[matsimitsu]

Awesome! The amount of instrumentation is really nice and should help debug any performance issues easily.

As discussed on the hackday yesterday there’s an issue with the way activesupport notifications are emitted that it’s difficult to see exactly what part of the query is causing the performance issues. This is because the graph tree is resolved breadth first. This means that the instrumentation does not follow the tree branches.

If we have the following (multiplexed) queries:

query {
  viewer {
    id
    username
    email
  }
}
query userPageQuery($username: String!) {
  user(username: $username) {
    id
    name
    isViewer
    username
    trips {
      id
      title
      subtitle
      viewerCanEdit
      header {
        ratio
        id
        url
      }
    }
  }
}

It looks something like this in a performance monitoring tool.

As you can see it’s very difficult to see what part of the query took the most time and looks very much like the second graph in @emilebosch ’s comment on issue #896 (comment)

In order to create a better visualisation this we can re-order our instrumentation back into a tree-like structure.

With the path method on the context that’s emitted with the notifications we can rebuild the tree by looping over the instrumentation and figuring out what the current path is.

This example middleware below will build a hash that should represent the query structure above, based on the path in the notification context.

class BetterInstrumentationMiddleware
  def initialize(app, options = {})
    @app = app
    @options = options
    @instrumentation = []
    ActiveSupport::Notifications.subscribe(/.*/) do |*args|
      @instrumentation << ActiveSupport::Notifications::Event.new(*args)
    end
  end

  def call(env)
    rack_result = @app.call(env)
    nested_instrumentation = {}
    current_path = []

    # Loop over the instrumentation and check if there's a path array
    # if there is one we can add it to our nested hash
    # if there isn't we can assume this event happened in the current path
    @instrumentation.each do |event|
      current_path = event.payload[:context].try(:path) || current_path

      # Set current branch to base
      current_branch = nested_instrumentation

      # Loop the paths and navigate to branch in our result hash
      # if the branch is new, create a new hash for that branch
      current_branch.each do |part|
        current_branch = current_branch[part] ||= {}
      end
      current_branch['events'] ||= []
      current_branch['events'].push(event)
    end

    @instrumentation = []

    # Send it off to 3rd party monitoring
    send_instrumentation(nested_instrumentation)
    return rack_result
  end
end

The resulting hash would look something like this:

{
  "viewer" => {
    "events"   => [(events that happened when viewer was computed)],
    "username" => {"events" => [(events that happened when viewer name was computed)]},
    "id"       => {"events" => [(events that happened when viewer id was computed)],
    "email"    => {"events" => [(events that happened when viewer email was computed)],
  },
  "user" => {
    "events" => [(events that happened when user was computed)],
    "id"     => {"events" => [(events that happened when user id was computed)],
    "name"   => {"events" => [(events that happened when user name was computed)],
    # and so on
  }
}

Adding this middleware, sending the nested_instrumentation and adding an event for each tree branch gives us the following event tree, as you can see it’s much easier to see where time is spent in the graphql query and it looks more like the first image in @emilebosch ’s comment on issue #896 (comment)

I’m not entirely sure if/how we should handle this in the gem. I don’t think it’s possible to create something that re-emits the instrumentation in the right order, as other tools might be subscribed and would get all events twice.

I think documenting these findings would be a good start, so anyone that wants to implement their own visualisation of the gem performance has an understanding of how to reproduce the tree.

Another option could be that we create a helper that emits the query with all nested instrumentation, something that @emilebosch has done with his rails engine https://github.com/emilebosch/graphql-metrics.

What do you think @rmosolgo

[emilebosch]

@rmosolgo @matsimitsu Awesome work. I'd love to incorporate this tracing in the dashboard. This looks very nice @matsimitsu. Now its a bunched of hacked stuff together, but with this i think i can get quite far and make it look super pretty.

Maybe its also cool to think about what we actually want to see:

• Slow fields (i.e. fields that need to be optimized)
• Slow queries (queries that are generally slow)
• Most used fields, most unused fields? (i.e. scary to refactor)

I'm also thinking about the graphs that you might want to see. What's the low hanging fruit?

[emilebosch]

@matsimitsu @rmosolgo Cant we emit a query end notification, that has a method to get the query back in the right order?

[rmosolgo]

Oops, this diff was added by mistake! I'll remove it.

[rmosolgo]

Yes, let me take a look at these events and make a few changes:

• Add some event which encloses the whole query execution.
• Change execute_field somehow:
  • Right now, it includes child field resolution in some cases (not for graphql-batch-based fields)
  • Maybe it should only include the resolve function call

[rmosolgo]

I added execute_multiplex which is the umbrella event for a call to Schema#execute or Schema#multiplex. When it finishes, you know everything is done!

[bdubaut]

@rmosolgo do you think it would be possible in the trace to highlight fields with a deprecation warning? Would be pretty useful IMO.

[emilebosch]

Great! So all i need to do now is order them? Couldnt be easier!

…

Sent from my iPhone

On 28 Aug 2017, at 21:58, Robert Mosolgo ***@***.***> wrote: I added execute_multiplex which is the umbrella event for a call to Schema#execute or Schema#multiplex. When it finishes, you know everything is done! — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.

[rmosolgo]

@bdubaut I think you can use http://www.rubydoc.info/gems/graphql/GraphQL/Analysis/FieldUsage for that!