Plugin telemetry events

[akoutmos]

This PR addresses some of my thoughts that I raised in #892 and emits start+stop events for dataloader events where there are pending_batches to process. Those two additional Telemetry events are:
[:absinthe, :dataloader, :resolve, :start] when a dataloader with pending batches starts
[:absinthe, :dataloader, :resolve, :stop] when a dataloader with pending batches finishes

This is just an initial stab at the problem, so feel free to comment. Thanks :)!

[benwilson512]

Hey @akoutmos thanks for taking a stab at this!

Here's the challenge we need to solve: Dataloader is an optional dependency within Absinthe. I don't think it's appropriate for Absinthe to emit dataloader specific events. I do think that the resolution phase should emit events for when a plugin callback has started, and when a plugin callback has ended though, and the plugin module would be part of the event emitted.

For Dataloader specific events, I think we need to have those fire within Dataloader itself.

[benwilson512]

Specifically, I think we should move these start and end events into https://github.com/absinthe-graphql/absinthe/blob/master/lib/absinthe/phase/document/execution/resolution.ex#L78 and it would be something like:

  defp run_callbacks(plugins, callback, acc, true) do
    Enum.reduce(plugins, acc, fn plugin, acc ->
      start_time = System.monotonic_time()
              :telemetry.execute(
          [:absinthe, :plugin, callback, :start]
          %{start_time: start_time},
          %{plugin: plugin, acc: acc}
        )
      acc = apply(plugin, callback, [acc])
      # stop event
     acc
    end)
  end

[akoutmos]

@benwilson512 I think my latest commits address the comments that you brought up. I really like this approach compared to my original solution as it is more general purpose now and covers all the plugins. On that same note, is a dataloader specific event even needed? You can match on

{
  :telemetry_event, 
  [:absinthe, :plugin, :callback, :start], 
  %{start_time: _}, 
  %{loader:Absinthe.Middleware.Dataloader}
}

to get your dataloader (or any plugin for that matter) specific events. Thoughts?

[benwilson512]

Nice improvements!

[benwilson512]

Very close! So, callback here is either the atom :before_resolution or :after_resolution, and I was thinking we could use that to dispatch more finely tuned events. Specifically this would get us:

[:absinthe, :plugin, :before_resolution, :start]
[:absinthe, :plugin, :before_resolution, :stop]
[:absinthe, :plugin, :after_resolution, :start]
[:absinthe, :plugin, :after_resolution, :stop]

[benwilson512]

The loader variable here is I think the plugin right? We probably want to call it plugin: plugin

[akoutmos]

My bad. I read your callback line as an atom and not the function variable. Third time is a charm I think I addressed all your feedback :D. Thoughts on the separate dataloader telemetry events? Thanks again!!

[benwilson512]

Changes look good to me!

Thoughts on the separate dataloader telemetry events?

Let's do these within the Dataloader project itself: https://github.com/absinthe-graphql/dataloader. PR welcome. We probably want to emit events for each run_batch call basically.

@binaryseed you did the original telemetry stuff, this look good to you?

[binaryseed]

My only concern would be how frequently these will happen. With field-level events, we made sure that the telemetry only triggered when a resolver function was explicitly called. We need to make sure that this instrumentation won't cause there to be a huge increase in calls to execute, since they are not free (an ETS lookup so cheap, but not free)

[binaryseed]

I'm unclear why the reduce is needed, the other telemetry tests managed to work just fine with assert_receive...

absinthe/test/absinthe/integration/execution/telemetry_test.exs

Line 62 in 7821d27

assert_receive {[:absinthe, :execute, :operation, :start], _, %{id: id}, _config}

[akoutmos]

The reason for the reduce is so that I can count only the specific events that I want to fetch. Since the telemetry events emit on all plugins, I was also getting Async and Batch events. But only wanted to assert on the Dataloader specific events.

[binaryseed]

Also, we have a pattern of sticking an id on each event to correlate the start & stop...

absinthe/lib/absinthe/middleware/telemetry.ex

Line 12 in 7821d27

id = :erlang.unique_integer()

[benwilson512]

Is this ready for re-review?

[akoutmos]

I think I addressed everything on my end. The only open question from what I gather is the number of events being generated...but I defer to you guys on that one.

[binaryseed]

So, I looked into this locally on my API, and the problem is real.

We've got a few plugins installed for standard stuff like auth & monitoring, and this addition calls execute 2 times for every plugin for every phase of resolution.

That means when using stuff like Async / Batch, every new phase added by any plugin re-triggers a whole new set of telemetry events for every plugin.

For example, I tried it out with a really simple query, and there were 6 resolution phases. Each phase added 14 calls to execute (we have 7 plugins). That means a total of 84 additional calls to telemetry.execute - 84 more ETS lookups. And that's as a no-op, if there's a handler attached, then it's going to get called 84 times.

I'm a little worried about this... It's pretty unlikely that the raw data here is going to be leveraged, and that's a good bit of work to do for something that's rarely going to be used.

I"m wondering if directly instrumenting Dataloader would be a better way to go about this vs instrumenting every single plugin interaction?

[benwilson512]

@binaryseed This is a good point, I didn't think about the fact that this will run N*M times, where N is the number of plugins, and M is the number of resolution phases that happen (roughly proportional to the depth of the GraphQL query). :ets is pretty fast, but I agree that there isn't a lot of point to firing events about plugins that don't execute.

Perhaps an alternative strategy would be to emit events only within the functions within the batch and dataloader plugins that actually execute user code so that you can track how long a given batch or run_batch call takes if any are queued up without firing events at all if none are present. I realize this is closer to what you had originally @akoutmos and I apologize for the back and forth here. In this proposal to be clear, we would move the event hooks to here: https://github.com/absinthe-graphql/absinthe/blob/master/lib/absinthe/middleware/batch.ex#L156 and within Dataloader itself. @binaryseed does that seem more reasonable?

[akoutmos]

No worries at all @benwilson512! That sounds good to me in regards to moving the telemetry events to the plugins directly. If that sounds good to you as well @binaryseed then I can get going on this approach and update this PR + open up a new one for the dataloader repo.

[binaryseed]

Instrumenting call_batch_fun sounds pretty good!

[benwilson512]

@akoutmos do note the naming conventions mentioned here: #901 (review)

[akoutmos]

Working on cleaning up this PR to reflect the conversation that we had. But managed to wrap up the Dataloader changes: absinthe-graphql/dataloader#89

Will update this PR over the weekend. Thanks!

[akoutmos]

I think I addressed everything that we discussed and also updated the documentation.

Question for you guys. Should I remove the telemetry tests in the test/absinthe/middleware/dataloader_test.exs file? The emitting of telemetry events is covered in the Dataloader PR that I made...but it would also be nice to ensure that those events are captured in an integration style test within Absinthe. On the flip side, the tests in Absinthe will fail until a newer version of Dataloader is published and the deps are updated in Absinthe. Thoughts?

[binaryseed]

Yeah, I'd much rather we keep the tests for dataloader telemetry events inside the library itself...

[akoutmos]

I went ahead and removed the test @binaryseed

[binaryseed]

Thanks! I'm going to merge this and followup with a small commit to move the telemetry.execute call in the start case to execute after the task is spawned so that handlers don't impact the timing!

[binaryseed]

Here it is: 38016db

[akoutmos]

Thanks @binaryseed! Let me know what you think of the dataloader changes and if you require any changes there absinthe-graphql/dataloader#89.