Cache successfully parsed and validated documents for future requests.

[abernix]

This PR builds upon the housekeeping work done in #2107, #2108 and #2109 and implements an in-memory cache store for parsed and validated documents in an effort to increase server performance.

Upon receiving a request, one of the many steps Apollo Server must perform is the parsing and validation of the document via graphql-js's parse and validate functions. The parsing and the validation of the document results in a DocumentNode (an AST) which is used for the eventual execution (via graphql-js's execute);

For relatively small documents, this takes a small fraction of time, though with more complex documents, the computational sink is becomes larger and less predictable.

These performance characteristics aren't always predictable, but when processing the same operation over and over again we can avoid the expensive computation cost associated with parsing and validating again by storing the resulting DocumentNode rather than building what is ultimately a re-forged copy of an effectively identical DocumentNode.

This PR introduces that technique by utilizing the SHA-256 hex digest of the operation document itself as a key and storing identical DocumentNodes in an InMemoryLRUCache (powered under-the-hood by the excellent lru-cache package!).

When using GraphQL variables (rather than string/numeric literals within the GraphQL document itself), this means that repeat operations — even with dynamically changing variables — can still be ready to execute based on the parsing and validation of a similar, previous invocation and cut a substantial amount of time off the request time round-trip.

Some benchmarks might help demonstrate this better. For the purposes of demonstrating this, I'll utilize relatively flat GraphQL documents (and corresponding schemas) which I benchmarked locally using Apache JMeter. The resolvers involved in this test are all just so-called "default resolvers", as in, they do nothing but return null and should accurately demonstrate the "win" from this optimization technique:

Benchmarks

p99 = 99th percentile.

Query	Without DocumentNode caching	With DocumentNode caching
query Benchmark {   Field_1 }	Avg.: 19.96ms p99: 56.00ms Throughput: 925.45	Avg.: 18.85ms ⚡️ p99: 58.00ms Throughput: 979.08 ⚡️
query Benchmark {   Field_1   Field_2   # ...until...   Field_100 }	Avg.: 34.89ms p99: 74.00ms Throughput: 530.99	Avg.: 20.18ms ⚡️ p99: 55.99ms ⚡️ Throughput: 917.70 ⚡️
query Benchmark {   Field_1   Field_2   # ...until...   Field_5000 }	Avg.: 954.87ms p99: 1007.00ms Throughput: 19.22	Avg.: 310.07ms ⚡️ p99: 390.00ms ⚡️ Throughput: 59.64 ⚡️

The single field operations are a wash but there are substantial improvements as the query document's complexity increases! Looking at the middle of the road (and more reasonable request) for 100 fields, the 99th percentile (as in, 99% of requests returned within that timeframe) is showing that it's 132% faster!

It's worth pointing out that I had a 1000ms request/response timeouts configured on the test-runner so the results on the "5000 fields - Before" test aren't showing the true depth of the situation since 88.10% of the operations Read timed out! (Of course, requesting 5000 top-level fields probably has a number of concerns so if that metric piques your concern you I certainly encourage you to dive in more!). On the plus side, the parsed and validated document did not timeout at all and, based on the average response time performed 308% faster. 🏎💨🎠

For anyone interested in more details, I've posted the more complete results at https://abernix.github.io/documentStoreBenchmarks, in the form of JMeter reports. You can click through to them from the index page.

Of course, there's still a couple things to be figured out here, particularly in the realm of configuration surface area. Currently, this utilizes a 30MiB cache, which might be enough for many/most configurations, but I'd like to figure out exactly what the sensible defaults might be here — and what might need tuning — before opening it up for configuration. In fact, if we don't need to add configuration, that would be even better!

I'm excited to see how this performs for others!

Fixes #1566

[abernix]

For anyone interested in trying this out and providing feedback, this has been published under the apollo-server "next" tag as:

apollo-server@2.4.0-alpha.0

Integrations (e.g. express, hapi, koa) will also find their respective versions accordingly (e.g. apollo-server-express@2.4.0-alpha.0, apollo-server-hapi@2.4.0-alpha.0, apollo-server-koa@2.4.0-alpha.0, respectively; see 7697623 above for the full list).

[glasser]

Could there be any downsides for not calling parsingDidStart/DidEnd in this code path (and not providing some alternate callback to take its place)?

[abernix]

If someone has implemented critical parsingDidStart or parsingDidEnd functionality that didn't isolate its reach to that of the parsing phase, then they might find these callbacks are no longer invoked where they used to be.

Since we never documented or officially supported the graphql-extensions API and the request pipeline plugin hooks are new (though still undocumented. see #2008), I think the best we can do is stay true to the name of the methods and stand by the fact that parsing did not start or end; I don't think we should call parsingDidStart and parsingDidEnd if those behaviors did not actually happen.

Presumably, those who wanted behavior which occurred when execution started or ended would be using the executionDidStart or executionDidEnd hooks (and more generally, requestDidStart, requestDidEnd, willSendResponse, etc.).

I don't think there are any alternate callbacks that we can provide that will make this any easier, and I don't think such hooks would provide intrinsic value.

[mxstbr]

We have a bunch of really big queries for https://github.com/withspectrum/spectrum, so I'm excited about this change as it should provide a solid speedup for our use case!

Will see if we can get 2.4.0-alpha.0 into production and report back with some solid metrics 💯 EDIT: PRs open: withspectrum/spectrum#4533

[mxstbr]

Cross-posting from withspectrum/spectrum#4533: Reassessing after a couple days in prod, it seems to have helped @abernix!

p99 response time over:

• Three days before deploying this: 250.78ms
• Three days after deploying this: 230.65ms

👍

[abernix]

That's great news, @mxstbr!

I'm pretty close to merging this and iterating on this in subsequent follow-up work, but I think it's worth a last peak before doing so.

In particular, while those who have implemented this so far have had consistently improved response times to show for it, I've added an additional commit to this PR and cut another -alpha.1 release to gain some additional validation through data which will hopefully show that this cache store is sufficiently default-sized and that cache evictions are low.

Therefore, the versions indicated in the Publish commit above (33d1f82; e.g. apollo-server-express@2.4.0-alpha.1) will console.debug some statistics every 60 seconds which show the document store usage. e.g.:

[documentStore] 331408 / 31457280 (1%). Disposed of 0 documents this interval.

My intention is to remove this spammy-ness before merging, but I thought interested parties might want to take a look. So far, in our own dog-fooding on Apollo Engine, this seems to be working well as currently implemented.

[abernix]

As I mentioned I would in #2111 (comment), I've reverted 7a0d0e6 and published 2.4.0-alpha.2 without that commit.

I'm going to merge this PR into a release-2.4.0 branch which will be a staging grounds for anything else 2.4.0 related (#1971, I'm looking at you!).

[abernix]

This has been released in Apollo Server 2.4.0!

e.g.

• apollo-server-azure-functions@2.4.0
• apollo-server-cloud-functions@2.4.0
• apollo-server-cloudflare@2.4.0
• apollo-server-express@2.4.0
• apollo-server-hapi@2.4.0
• apollo-server-koa@2.4.0
• apollo-server-lambda@2.4.0
• apollo-server-micro@2.4.0
• apollo-server@2.4.0

[stephenh]

Just as an FYI to others that find this, we upgraded to apollo-server-express-2.4.0 and had to rollback due to OOMs; we usually run pretty lean on RAM, 600mb/container and use ~50% of it; with 2.4.0 (presumably b/c of this change) our RAM usage spiked to ~100%. Which is fine, we'll probably allocate more RAM to use this feature. Disclaimer we haven't taken heap dumps yet, so it could have been something else, but the apollo-server from ~2.2 to 2.4 was the only change in the release.

[glasser]

Huh, the intention is for this cache to take about 30MB. If you're seeing more, that sounds like a bug!

And also evidence that it's time to add the configurability @abernix alluded to, but more important to make sure there isn't just a bug in the size calculation or something...

[stephenh]

@glasser 30mb does sound much more reasonable. :-) I'll work on confirming the root cause but it probably won't be super quick just given current priorities.

[abernix]

@stephenh We've been running this in production ourselves for a while now and I haven't witnessed that problem, but I certainly wouldn't rule it out the possibility!

If you're able, I'm curious if you could try using 2.4.0-alpha.2, which as I eluded to in the comment above (#2111 (comment)) has hard-coded console.log-ging every 60 seconds which should expose the cache usage. The stability of that -alpha should be fine, but I'm also happy to cut you another release off the current master with that logging enabled if it's any use.

My hope in offering this suggestion is that it might be something you could quickly opt into, suffer the temporary consequences of the OOM and feed back that information to help identify if this is indeed at fault.

[stephenh]

@abernix sure, I can try 2.4.0-alpha.2, that sounds like a good idea. I'll have to jury rig a ~dark/canary type setup...likely manually register a machine into the ELB for a bit or something like that, so will take a bit to work on it in between other things.

[shackpank]

I'm experiencing the same issue here - seems like you may or may not encounter it based on client behaviour. In our case, there's a mutation like this, where the input will be different for every user, and the client is constructing the document with the input inline:

mutation {
  storeSomeId(id: "sajbfjkbdkfjbfk") { id }
}

Repeatedly running this mutation locally with a randomised input quickly fills the cache up; the debugging does indicate older documents are being dropped when the limit is reached, but the memory usage difference was more like 138 MB than 30 MB between an empty and full cache, and memory usage continues to rise (though more slowly; roughly 1MB per 2k requests - edit: comparing heapdumps suggests this is something internal to the lru-cache module and would likely need investigation over there) even after the cache is "full".

Assuming you control the client, the issue can be avoided (and much better use made of this cache) by rewriting the query like this to pass the input as a variable - this means the cache does not grow at all with additional requests:

mutation storeSomeId($id:String!) {
  storeSomeId(id:$id) { id }
}

[abernix]

@shackpank Thank you for sharing these helpful details and taking the time to look into this, particularly the follow-up edit which questions lru-cache's potential involvement. Super appreciated!

It sounds like there's two things:

• Cache limit exceedance : slower growth, past the cache limit. Potentially something we're doing incorrectly, but also potentially something in lru-cache.
• Cache misrepresentation: The "30MB" roughly-estimated cache limit (intention!), which mainly aims to facilitate ejection and prevent cache from becoming too full, may need to be re-analyzed. Measuring actual heap object size here would sure be nice, but JavaScript being JavaScript, we may just need another creative approach. This isn't configurable right now, and this lack of certainty of what the limit actually means in terms of memory usage is a good reason why. The overarching goal here is to just make sure that someone couldn't send so many unique documents to the server that it would fill up the cache.

I'm curious, when you say that the switching of string literals to variables:

means the cache does not grow at all with additional requests

...does this indicate that the cache limit exceedance also stopped? Or was it just no longer showing up on the radar? I'd expect this to be continuing regardless, if enough unique DocumentNodes (with or without variables) were being sent.

The lru-cache made a major bump to v5 in November via #2004. Maybe worth toggling that out with a v4 version? Is that something you could try? I somehow doubt this is something with that package — and more likely something we're doing — but worth digging around, I guess.

Since overall the cache is still bringing performance benefits even though it's exceeded it's intended size (read: in your case, 138MB) allotment, I'm actually mostly concerned about the slower growth, so hopefully we can get to the bottom of that. Still though, we'll need to adjust these expectations, and possible figure out another way to estimate AST sizes.

However, I'm glad you've discovered that string literals pose particular problems for cache benefits and that using GraphQL variables offers benefits in this department. The use of variables offers other benefits as well (e.g. aggregation purposes for metric reporting), so highly recommended!

[sebnow]

I can confirm the cache causes a memory leak. I wrote a script to generate random distinct queries and request them with wrk2. Taking a heap snapshot shows that it is retaining well above 30MB.

In a production environment I am noticing a ~30mb/hr increase in memory. After logging distinct queries, I have found that there are on average 4 unique queries (with literals) requested per second.

graphql-js: 14.2.1
apollo-server-core: 2.4.8
apollo-server-caching: 0.3.1