Grafast not reusing operation plans from previous requests?

Summary

This is a question we have about the expectations of grafast and optimizations during operation plan creation.

We noticed that most of the time (close to 50%) in our node server was spent in these two functions/files in grafast:

grafastPrepare (prepare.js)
establishOperationPlanFromEvent

When reading the documentation for grafast, under "Getting the operation plan", it seems like operation plans should be saved for future use and optimizations.

When an operation is seen a future time, Grafast looks for an existing operation plan whose constraints fit the request. If there is one then this operation plan can be executed, otherwise a new operation plan is created (see previous paragraph).

However, after profiling what the cpu does for each request, it seems like the operation plans are only reuse when the operation body AND variables are exactly the same. Is this expected?

Additional context

How to replicate:

Run a small postgraphile/grafast server

Issue a small request with variables:


query GetPost($id: ID!) {
post(id: $id) { title }
}

{ "id": 1 }

3. Issue the same request, with different variables:
```graphql
query GetPost($id: ID!) {
  post(id: $id) { title }
}

{ "id": 2 }

All steps for preparation of operation plans (prepare.js) are performed, all over again

If in step 3, we send { "id": 1 } again as variables, then the prepare.js is skipped, and it jumps to execute.js directly.

I'm happy to provide even more additional context if necessary, but this is easy to replicate with any small server that can run postgraphile with PG.

Versions used

# postgraphile / grafast
"postgraphile": "^5.0.0-beta.25",
"grafast": "^0.1.1-beta.10",
"grafserv": "^0.1.1-beta.12",
"graphile": "^5.0.0-beta.25",
"graphile-build": "^5.0.0-beta.20",
"graphile-build-pg": "^5.0.0-beta.24",
"graphile-config": "^0.0.1-beta.8",
"graphile-migrate": "^1.4.1",
"graphile-utils": "^5.0.0-beta.24",
"@graphile-contrib/pg-omit-archived": "^4.0.0-beta.3",
"@graphile-contrib/pg-simplify-inflector": "^6.1.0",
"@graphile/simplify-inflection": "^8.0.0-beta.5",

# pg
"pg-sql2": "^5.0.0-beta.6",
"pg": "^8.12.0",

Screenshots of profiling

Request 1

request 1

Request 2

request 2

Command used:

node --cpu-prof --use-strict app.js

I cannot reproduce the issue you describe (I have not broken out the profiling tools to check that way, just added logs)

Specifically here's my schema:

create table users (id serial primary key, username text not null unique);
insert into users (username) values ('Benjie'), ('Jem');

And my query:

query User($id:ID!) {
  user(id:$id) {
    id
    username
  }
}

And I run it with the variables:

{ "id": "WyJ1c2VycyIsMV0=" }
{ "id": "WyJ1c2VycyIsMl0=" }

I've added log messages around this section of establishOperationPlan:

https://github.com/graphile/crystal/blob/47098fc69468726f4d212fcf1782fbdad880adea/grafast/grafast/src/establishOperationPlan.ts#L177-L186

like so:

and the output I get for running one id after the other is exactly what I'd expect (I've added extra newlines to make it easier to parse):

Server listening on port 5678 at http://[::]:5678/graphql
NO CACHE! IntrospectionQuery
NEW PLAN! IntrospectionQuery

REUSING OPERATION PLAN IntrospectionQuery

NO CACHE! User
NEW PLAN! User

REUSING OPERATION PLAN User

The first User request had no cache, so required a new plan. The second User request used the other value for id, but was happy reusing the plan.

Please create a minimal reproduction on https://github.com/benjie/ouch-my-finger/

graphile / crystal