Multiple telemetry events when using dataloader

[akoutmos]

Environment

• Elixir version (elixir -v): 1.10.2
• Absinthe version (mix deps | grep absinthe): 1.5.0-rc.4
• Client Framework and version (Relay, Apollo, etc): Apollo

Expected behavior

When using a dataloader for a field, I would expect a single [:absinthe, :resolve, :field, :start] event and a single [:absinthe, :resolve, :field, :stop] event to be emitted via telemetry during the resolution of a field.

Actual behavior

I am currently getting 1 pair of start/stop telemetry events per reference of that field in a list of items even though I am only reaching out once to fetch the batch data.

I'll try and throw together a dummy project to repro the issue more clearly, but for now any assistance would be greatly appreciated. Thanks for all the hard work you've put into Absinthe!! Appreciate it :).

[akoutmos]

After digging through the code a bit, perhaps separate dataloader start/stop events should be emitted here: https://github.com/absinthe-graphql/dataloader/blob/master/lib/dataloader/kv.ex#L107. Thoughts?

[benwilson512]

Hi @akoutmos, the behaviour you are seeing is correct and expected. Batch style resolvers like dataloader group the resolution of many fields together.

Suppose you have this:

{
  posts {
    author { name
  }
}

and there are 3 posts, the author field uses dataloader. Each posts' author field starts resolving, but then suspends to wait on the results from dataloader. This means you get 3 start event in a row as each field adds its work to the dataloader batch. Then dataloader runs, and then each result is fed back into each field and you get 3 stop events.

Dataloader should definitely emit telemetry events though. Please feel free to open up an issue about that there.

[akoutmos]

Thanks for the detailed answer @benwilson512! That all makes sense. I'll get to work on adding telemetry to dataloader and will open up a PR. As a side note (mostly since I am new to Absinthe), how would I go about filtering out [:absinthe, :resolve, :field, :start] and [:absinthe, :resolve, :field, :stop] events to avoid misreporting metrics? Is there anything in the Absinthe.Resolutionstruct in themetadata` that could hint to me that a dataloader request can be ignored?

[benwilson512]

Can you elaborate on why you want to filter those out? The times are 100% valid, they're just happening concurrently.

[akoutmos]

My bad. I should have given some more context.

While the timings are 100% valid and accurate, I cannot reliably use those events to count how many times I have had to perform that batch resolution. For example, let's say I had a Prometheus counter set up inside the :stop event, I could get 3 increments for a field that I only had to resolve once (since all three are batched as one). Depending on the query that is taking place I could have an arbitrary number of increments....but still only 1 batch resolution. Currently I am looking at a whole bunch of [:absinthe, :resolve, :field, :stop] events that all have the same exact duration value in their measurements. Which I do plan on using in a Prom histogram...but I only want to report that once versus N times. Hopefully that all makes sense. Thanks again for the assistance @benwilson512!!