Pool resources not being released in high load

[pkeuter]

Sorry for not using the schema as it's quite hard to follow that with this problem.

The issue that I have is that in rare cases, the pool connections are not being released. After some debugging I found that the problem is in the tarn.js library for which I made a PR. Unfortunately I have issues reproducing it in a small setup, but I was able to fix the issue.

This is a debug log of the situation:

2021-10-21T13:12:31.292Z mssql:base request(1317): created
2021-10-21T13:12:31.317Z mssql:tedi connection(32): borrowed to request #1317
2021-10-21T13:12:31.317Z mssql:tedi request(1317): query <query removed>
2021-10-21T13:12:31.364Z mssql:base connection(32): released
2021-10-21T13:12:31.364Z mssql:tedi request(1317): completed
2021-10-21T13:12:31.394Z mssql:base request(1318): created
2021-10-21T13:12:31.395Z mssql:base request(1319): created
2021-10-21T13:12:31.395Z mssql:base request(1320): created
2021-10-21T13:12:31.395Z mssql:base request(1321): created
2021-10-21T13:12:31.396Z mssql:base request(1322): created
2021-10-21T13:12:31.396Z mssql:base request(1323): created
2021-10-21T13:12:31.397Z mssql:base request(1324): created
2021-10-21T13:12:31.397Z mssql:base request(1325): created
2021-10-21T13:12:31.397Z mssql:base request(1326): created
2021-10-21T13:12:31.398Z mssql:base request(1327): created
2021-10-21T13:12:31.398Z mssql:base request(1328): created
2021-10-21T13:12:31.398Z mssql:base request(1329): created
2021-10-21T13:12:31.399Z mssql:base request(1330): created
2021-10-21T13:12:31.399Z mssql:base request(1331): created
2021-10-21T13:12:31.400Z mssql:base request(1332): created
2021-10-21T13:12:31.400Z mssql:base request(1333): created
2021-10-21T13:12:31.400Z mssql:base request(1334): created
2021-10-21T13:12:31.401Z mssql:base request(1335): created
2021-10-21T13:12:31.401Z mssql:base request(1336): created
2021-10-21T13:12:31.401Z mssql:base request(1337): created
2021-10-21T13:12:31.402Z mssql:base request(1338): created
2021-10-21T13:12:31.402Z mssql:base request(1339): created
2021-10-21T13:12:31.403Z mssql:base request(1340): created
2021-10-21T13:12:31.403Z mssql:base request(1341): created
2021-10-21T13:12:31.403Z mssql:base request(1342): created
2021-10-21T13:12:31.404Z mssql:base request(1343): created
2021-10-21T13:12:31.404Z mssql:base request(1344): created
2021-10-21T13:12:31.405Z mssql:base request(1345): created
2021-10-21T13:12:31.405Z mssql:base request(1346): created
2021-10-21T13:12:31.405Z mssql:base request(1347): created
2021-10-21T13:12:31.406Z mssql:base request(1348): created
2021-10-21T13:12:31.406Z mssql:base request(1349): created
2021-10-21T13:12:31.406Z mssql:base request(1350): created
2021-10-21T13:12:31.407Z mssql:base request(1351): created
2021-10-21T13:12:31.407Z mssql:base request(1352): created
2021-10-21T13:12:31.407Z mssql:base request(1353): created
2021-10-21T13:12:31.408Z mssql:base request(1354): created
2021-10-21T13:12:31.408Z mssql:base request(1355): created
2021-10-21T13:12:31.409Z mssql:base request(1356): created
2021-10-21T13:12:31.409Z mssql:base request(1357): created
2021-10-21T13:12:31.409Z mssql:base request(1358): created
2021-10-21T13:12:31.410Z mssql:base request(1359): created
2021-10-21T13:12:31.410Z mssql:base request(1360): created
2021-10-21T13:12:31.410Z mssql:base request(1361): created
2021-10-21T13:12:31.451Z mssql:tedi connection(32): borrowed to request #1318
2021-10-21T13:12:31.452Z mssql:tedi request(1318): query <query removed>
2021-10-21T13:12:31.483Z mssql:base connection(32): released
2021-10-21T13:12:31.489Z mssql:tedi request(1318): completed
2021-10-21T13:12:31.496Z mssql:base request(1362): created
2021-10-21T13:12:31.513Z mssql:tedi connection(32): borrowed to request #1319
2021-10-21T13:12:31.514Z mssql:tedi request(1319): query <query removed>
2021-10-21T13:12:31.612Z mssql:base connection(32): released
2021-10-21T13:12:31.616Z mssql:tedi request(1319): completed
2021-10-21T13:12:31.634Z mssql:base request(1363): created
2021-10-21T13:12:31.642Z mssql:tedi connection(32): destroying
2021-10-21T13:12:31.643Z mssql:tedi connection(32): destroyed
2021-10-21T13:12:31.646Z mssql:tedi pool(1): connection #33 created
2021-10-21T13:12:31.647Z mssql:tedi connection(33): establishing
2021-10-21T13:12:31.757Z mssql:tedi connection(33): established
2021-10-21T13:12:31.770Z mssql:tedi connection(33): destroying
2021-10-21T13:12:31.771Z mssql:tedi connection(33): destroyed
2021-10-21T13:12:32.124Z mssql:base request(1364): created
2021-10-21T13:12:32.126Z mssql:tedi pool(1): connection #34 created
2021-10-21T13:12:32.127Z mssql:tedi connection(34): establishing
2021-10-21T13:12:32.212Z mssql:tedi connection(34): established

--> I would expect request 1320 here, but instead, connection 34 is inside the "used" pool but no-one is using it <--

2021-10-21T13:12:32.788Z mssql:base request(1365): created
2021-10-21T13:12:33.437Z mssql:base request(1366): created

What I've found (although like I said it's hard to reproduce in a smaller setup) is that sometimes a pending request gets aborted before the validation ends. Normally tarn.js should immediately abort the validation process, but for some reason, it does not. In my PR I've built an extra check that validates if the pending request has already been aborted. If so, it will not resolve but it will release the connection. This fixes the issue, but I am not 100% certain there might be a different approach to this problem.

This is a pretty serious issue though, because it will eventually dehydrate the pool, causing all connections to stall. So if any of you have any idea on how we might be able to improve this, that will be greatly appreciated.

[dhensby]

So it looks like you've definitely found a genuine bug in tarn.js but I'm not clear on how this is materialising in this library. Are you aborting your request quickly?

In terms of testing load, we should be able to simulate large load fairly easy (it's been done before), do you know what kind of scale this is happening at?

[pkeuter]

Hi @dhensby. Thanks for your response! No, we are not aborting the requests quickly. I might have used incorrect wording here anyway since it's not really a "high load" situation in the sense that we're running a continuous high amount of queries. It's just that sometimes a lot of queries are executed simultaneously which gives us this issue.

What we are doing is shooting off multiple requests (like 20 or so) for multiple rows we got as a response from the database. This happens in a map so they are sent really quick after each other. So as you are able to see in the debug-log, while everything is still working, a bunch of requests come in, the first of those bunch of requests is trying to acquire a request from the pool, but here the pool will never respond, making one of our pool connections unusable.

We have quite some connections in our pool, so it's not immediately noticable, but after a few days the pool will have no connections left and everything comes to a stall.

I have responded in the PR as well: Vincit/tarn.js#67 (comment). As I mentioned there, I have a hard time reproducing it in a small setup. If we can eventually create a testable case, it would be easier to make a testcase in this library as well.

[dhensby]

I think it's pretty clear this is an issue coming from tarn and the patch you've authored looks to solve the problem (from what you've said).

I don't think we should provide a test in our library for this particular issue because it requires very close coupling to the internals of the pool. If we did write a test, what would we be testing beyond any test tarn should have?

I've created a test in the tarn library to cover the eventuality and also made a couple of improvements to make sure resources don't get orphaned.

Once it's merged and released I'll update the dependency in this library and mark the issue as closed.

[pkeuter]

Thanks @dhensby for your help and suggestions. Very much appreciated! I'll await the merge and release with updated version!