Session Pool Leaks & Investigation

[walshie4]

Environment details

• OS: CoreOS
• Node.js version: v8.9.6
• npm version: v6.0.0
• @google-cloud/spanner version: v1.4.1 (kinda - see below)

The issue

As I've mentioned in my other issues (#183, #177) we're (@honeyscience) attempting to apply a fairly large amount of load to our new Spanner backed APIs but are running into a slew of session pooling issues. The main issues are:

• Time spent waiting for a session is too high
• Session pool grows seemingly without bound (Session pool max not respected #177)
• When the session max is hit you either need to spin up even more nodes ($$$) or wait ~an hour for sessions to be deleted by the server

As per our previous issue (#134) & PR (#135) into the session pooling code the module is setup in such a way which makes it quite prone to race conditions. On top of that the session pool management responsibilities are not 100% contained within the session pool module itself which has made understanding it a larger challenge. Without knowing exactly what the authors were aiming for, and not sure we’d be able to confidently ensure no leaks with the current architecture, we decided to replace it rather than try to fix it.

Our first attempt at replacing it was simply a rudimentary create-upon-request and destroy after 60 seconds setup. You can see this here (https://github.com/honeyscience/nodejs-spanner/commit/c76df11457e3b72fa0c1f32088af780f9e64e730#diff-0c4114554752f1c79d35d17a91563062R292).

Although this setup suffered from some write failures and increased latency overall it worked amazingly. We were able to run the API overnight with 120 replicas of the API in total never consuming more than 100 Spanner sessions.

This is of course non-optimal as you can see from the following chart where the purple line is session destruction and the blue line is session creation:

The impact of this approach is increased latency and some occasional failures. However as a proof of concept we were more than pleased with the results.

We then decided we’d try to implement our own pool implementation leveraging this library for the main pool management functionality: https://github.com/coopernurse/node-pool

The code for this is available here https://github.com/honeyscience/nodejs-spanner/blob/869871e45a034af2ba9158466912dc4f17e8e32b/src/session-pool.js

It still has some issues (particularly with write sessions) but so far it has been doing fairly well.

The main issue we’ve seen with our current setup is everything seems to be only using write sessions which are sometimes slow to create or be released back into the pool. We suspect there is still a location not releasing back to the pool because with the new setup the pool properly enforces the max session count but all are marked borrowed so everything is queued and thus times out.

Session count chart:

Spanner API requests for the same period:

When the limit for sessions was much higher we saw failed writes causes spikes in session create requests (upwards of a few thousand per second - see screenshot) but does not solve write failures, they still timeout. Which seems like a similar issue if not the same one.

Looking around we found this PR which addressed an issue with write sessions googleapis/google-cloud-node#2561. Could be relevant to the write session speed issue.

We're currently looking into if this change f5897d6 will resolve the issue with sessions getting stuck in the borrowed state.

If there is any other information you can give us on how sessions work which could be relevant to our efforts we're all ears.

We’re still digging at this from our side and will report back with any more findings. We're more than happy to work with anyone on your side to get a speedy and solid resolution to this.

[walshie4]

Also any news on the session pool stress tests for this library?

#134 (comment)

[callmehiphop]

@walshie4 its definitely on my radar, I think its something I might try to tackle this week.

[walshie4]

The main issue we’ve seen with our current setup is everything seems to be only using write sessions

Lowered the size of the read pool to test this theory and saw requests queue up for the read pool, so that statement above is not correct.

[walshie4]

With our most recent commit fixing a leak we had https://github.com/honeyscience/nodejs-spanner/commit/39044f318198cad0ae6d54b1b56f29bdb1cf83ac we've seen some very strong results so far with this code in production. We'll continue to monitor this and report back in a few hours.

[anupbaldawa]

We have reimplemented the session pool logic and deployed in our prod environment. It has been running overnight and we haven't noticed any session leaks in our code. Based on the load, the sessions will be added and eventually, the sessions get terminated if there is not enough load.
This is the link to the code:

https://github.com/honeyscience/nodejs-spanner/blob/master/src/session-pool.js

Let us know if you are okay creating a PR with this new session pool code.

[vkedia]

Firstly @anup-honey and @walshie4 thanks a lot for taking the time to dig into this and reimplenting the logic. We really appreciate that.
@stephenplusplus @callmehiphop I am ok with replacing the current session pool code with this if it does fix the issues with the current code. But I have not taken a look at the code. Can you guys review this code?
Since this is the second time we will be replacing the session pool code I think we should also implement the stress test.

cc @danoscarmike @snehashah16

[anupbaldawa]

@vkedia Thanks for the response. I will prepare the code for a PR and create one by the end of the day.

[callmehiphop]

Thanks @anup-honey @walshie4! I'd be happy to review

Side note: @vkedia could we possibly get a one pager outlining what a session pool stress test should look like? I can probably figure it out from the java/go code but I think it would take considerably longer than if a document was made available. This would have the added benefit of being sharable with all teams as well.

[anupbaldawa]

I have created a PR
#194

I have tried to stick to the same unit test case format. The documentation needs to be updated and it is going to be a major change.

[PacciniBruno]

Off topic but I would love to know how you set up those charts (especially the session count & session creation/deletion ones), or if it's accessible somewhere on GCP, where @walshie4 :)

[walshie4]

@PacciniBruno I created them in stackdriver using the available system Spanner metrics. If you're on a dashboard and click the Add Chart button and type spanner into the resource input box you should see them available. Sessions is exactly what you'd think (note it appears to only update at a 10min interval), while API requests will show you the createSession and other request volume.

[PacciniBruno]

Oh that's great :) I had no idea we could do that. Thanks!