Awesome. Do note that once OTP 24 is released we’ve seen significant improvements from the JIT as well, so we expect the overhead to drop a further ~60% from that alone.

One key thing to check on is what your scalars are doing. Scalars are serialized in the result phase, which happens entirely after the resolution phase. In the past, poorly optimized serialization functions have lead to lengthy post-resolution times.

To dig in further, some additional metrics would be handy. Can you provide an example query document? How large is the result JSON in bytes? How large is the schema (approximated by MyAppWeb.Schema.__absinthe_types__ |> map_size)?

Hi @derekbrown I still need some sense of the size of the returned document. This will help diagnose time spent after the resolution phase constructing the actual JSON result.

While

I recommend using Telemetry to provide a few more data points, specifically the [:operation, :start] event would be very helpful because right now although it is likely that Absinthe starts work immediately after the context is set, in theory there could be other plugs or issues within Absinthe.Plug that are introducing delay. See https://hexdocs.pm/absinthe/telemetry.html#content for details.

The document is relatively small, so processing on the document should happen pretty quickly. I’m going to take that document and create a project with a similar schema to see if we can reproduce the observed performance issues.

Update: I’ve been able to add Absinthe Telemetry events to the tracer, per reply above from @benwilson512 . Below are some observations and pretty pictures. I’ve tried to keep the same query here from the original post, for some apples-to-apples comparison. Hope this all helps.

• You’ll notice there’s a significant reduction in speed. The query document remains the same, along with the response size, more or less (if anything, the response is likely bigger). Part of this is attributed to some logic/DB work we’ve been doing underneath the query, and some of it is directly attributed to the .uniq issue I mentioned earlier. Hope that helps anyone else with looking to increase performance.

Overall shape of the query. The first flame of spans is the context loading, followed by the operation.start event, followed by the first resolution.start event. We’ll zoom in subsequent screenshots, but there’s a significant gap between those two events, and after the operation.stop event.

Screenshot 2020-05-25 12.35.392282×482 39.6 KB

Context to Operation Start. There’s a miniscule gap (≈300µs) between context being added and the operation starting, but not significant enough for us to blink.

Screenshot 2020-05-25 12.36.48880×396 30 KB

Operation Start. The span on the right of the screenshot is the first resolution.start event, which is followed by the fetch_messages query in the overall screenshot above. Would we expect there to be a ≈6ms delay or so between operation start and resolution start?

Screenshot 2020-05-25 12.36.323248×358 42.3 KB

Operation Stop. There’s a ≈10ms gap after operation.stop that’s unaccounted for. I’ll dig into what could be happening there (perhaps other plugs?). I don’t assume so there’s any cleanup or anything that Absinthe would be doing after the operation, is there?

Screenshot 2020-05-25 12.37.193292×410 53.1 KB

Edits

1. Maybe a clue, or could be a rabbit trail: it seems that the delay to context matters whether or not it’s a query or mutation. The gap from trace start to context being added is much less for mutations.
2. The above is a rabbit trail. Doesn’t seem to be anything deterministic causing the delay before Context gets called.

The offer to investigate any runnable example stands! Do make sure to check out the persistent_term backend Absinthe.Schema.PersistentTerm — absinthe v1.6.4 which we’re promoting out of the Experimental namespace in the next release. It has proven to be both faster and easier to work with.

I’m seeing the original post was on Absinthe 1.5.0, and we definitely fixed an N^2 regression in our variable handling somewhere in a release between that and latest. Hopefully you’ve updated since!