Node-oracledb: Unable to get new connections from DB, even max pool is not reached.

[mrizwanyaqub]

Unable to get connection from pool in following scenario.

• update a record in multiple transactions, without committing or rolling back transactions.
• get new connection from pool, no connection or error is returned.
• even neither the max pool is reached in application nor in DB server.

Files to reproduce the scenario are attached.

Pool statistics:
...total up time (milliseconds): 195558
...total connection requests: 110
...total requests enqueued: 0
...total requests dequeued: 0
...total requests failed: 0
...total request timeouts: 0
...max queue length: 0
...sum of time in queue (milliseconds): 0
...min time in queue (milliseconds): 0
...max time in queue (milliseconds): 0
...avg time in queue (milliseconds): 0
...pool connections in use: 99
...pool connections open: 99
Related pool attributes:
...poolAlias: default
...queueRequests: true
...queueTimeout (milliseconds): 60000
...poolMin: 2
...poolMax: 120
...poolIncrement: 5
...poolTimeout (seconds): 30
...stmtCacheSize: 30
Related environment variables:
...process.env.UV_THREADPOOL_SIZE: 125

Envirnoments:

• Node.js version: v4.5.0
• oracledb node module version: 1.11.0
• CentOS 6.6
• Oracle Client 12.1
• Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production

Unable to upload zip file, don't know why. So uploaded files individually.

dbAssist.js.txt
main.js.txt
package.json.txt
sql.txt

[cjbj]

update a record in multiple transactions, without committing or rolling back transactions.

Could be a table deadlock.

[dmcghan]

@muhammadrizwanyaqub

process.env.UV_THREADPOOL_SIZE = threadPool;

In dbAssist.js, you're setting the value of UV_THREADPOOL_SIZE after you've made an async call that relies on the thread pool (call to oracledb.createPool). This means you've actually locked in the default of 4.

You'll need to either set the value prior to starting the Node.js process or ensure that the value is set (as you're doing) prior to any async call that uses the thread pool. Let us know how that works for you.

[cjbj]

@dmcghan that bit about when to set UV_THREADPOOL_SIZE could be added to our doc (yet more duplication, but useful I think).

The big question is: is there a way for logStats() to print the actual number of threads created?

@muhammadrizwanyaqub you may be interested in this doc snippet that will be in the next doc push to GitHub:

The Oracle Real-World Performance Group's general recommendation for client connection pools is for the minimum and maximum number of connections to be the same. This avoids connection storms which can decrease throughput. They also recommend sizing connection pools so that the sum of all connections from all applications accessing a database gives 1-10 connections per database server CPU core. See About Optimizing Real-World Performance with Static Connection Pools.

[dmcghan]

@cjbj I don't know of any API that would allow that. :( Though looking with fresh eyes at the stats, it seems we are missing "current requests enqueued" - for when people are monitoring the queue while running.

Maybe "avg service time" could be useful too. That would measure the average time from when a connection is obtained to when it's released.

[cjbj]

@dmcghan IIRC we were trying to make the stats 'fast' and not do too much calculation

[dmcghan]

@cjbj I remember we had that issue with a median calculation, but I think these could be implemented efficiently. Current requests enqueued would be a simple counter.

For average service time, we would call Date.now() and put the ms on the connection object. Then, as part of the release call, we'd call Date.now() again to get the total ms spent "working". We'd add that value to a new variable that tracks the total ms spent servicing all connections. Then, when logStats is called we would just divide that by the total connections dequeued.

Let me know if you're ever interested in adding these.

[cjbj]

If it helps users, and doesn't slow down connecting when no queueing is performed, any stat can be added.

Brainstorming here: Is an average really useful - what would an admin do with the data? Is the fact there was queuing already enough? Would it be average for successful/unsuccessful/total connections? logStats() already has the sum of the time in the queue and the numbers of requests.

[mrizwanyaqub]

update a record in multiple transactions, without committing or rolling back transactions.
Could be a table deadlock.

@cjbj Yes, we are aware of this. But the issue is, why new connections are not being made? Even neither the max pool is reached in application nor in DB server.

[mrizwanyaqub]

You'll need to either set the value of UV_THREADPOOL_SIZE prior to starting the Node.js process or ensure that the value is set (as you're doing) prior to any async call that uses the thread pool. Let us know how that works for you.

@dmcghan I set it in my main.js file just after requiring modules, but still it didn't help.

[sagiegurari]

any reason not to set it before running the nodejs process?

[cjbj]

Try reducing the problem. Add some logging code. Make sure connections are being closed in all code paths. Set poolMin and poolMax to smaller values, say each to 10.

[mrizwanyaqub]

@sagiegurari Things did not change even after setting the value from terminal.

[mrizwanyaqub]

@cjbj We are aware of the open connections. And they will remain open until transaction is completed. In our case some of the accounts are frequently updated in multiple transaction. Because of lock on one record other transactions wait for it to be free. When this wait goes on and dependent transaction or connection increase gradually, then there comes a time when pool stops to give more connection for other operations even max pool size is not reached.

[mrizwanyaqub]

Set poolMin and poolMax to smaller values, say each to 10.

@cjbj setting min, max to 10 and pool increment to any value from 0 to 10 returns following error:

Unable to create new pool connection error: ORA-24413: Invalid number of sessions specified
unable to connect to db, err: Oracle db stack error: [ORA-24413: Invalid number of sessions specified

[dmcghan]

@muhammadrizwanyaqub Maybe this will help clarify what's happening...

Given the following table:

create table t (
  c number 
);

insert into t (c) values (1);

commit;

And assuming the default thread pool size of 4.

var oracledb = require('oracledb');
var config = require('./dbConfig.js');

config.poolMax = 10;
config.poolMin = 0;
config.poolIncrement = 10;

oracledb.createPool(config, function(err, pool) {
  if (err) {
    throw err;
  }

  console.log('Pool created successfully', pool);

  lockTheRow();
});

function lockTheRow() {
    console.log('Getting the first connection.');

    oracledb.getConnection(function(err, conn) {
      if (err) {
        throw err;
      }

      console.log('Got a connection. Proceeding to lock the row.');

      conn.execute(
        'update t set c = 1',
        [], // no binds
        {
          autoCommit: false
        },
        function(err, result) {
          if (err) {
            throw err;
          }

          console.log('Row is locked. The connection will not be released.');
          console.log('However, because we made it here, the thread the connection was using is now free.');

          runMoreUpdates();
        }
      );
    });
}

function runMoreUpdates() {
  var updatesToRun = 4;
  var idx;

  for (idx = 0; idx < updatesToRun; idx += 1) {
    console.log('About to request another connection.');

    oracledb.getConnection(function(err, conn) {
      if (err) {
        throw err;
      }

      console.log('Got a connection. Proceeding to update (even though the row is locked).');
      console.log('In this case, the connection will wait and thus the thread will be locked too.');

      conn.execute(
        'update t set c = 1',
        [], // no binds
        {
          autoCommit: false
        },
        function(err, result) {
          if (err) {
            throw err;
          }

          console.log('This will never run because the connections are waiting on the locked row.');
        }
      );
    });
  }

  setTimeout(tryToGetAnotherConnection, 3000);
}

function tryToGetAnotherConnection() {
    console.log('Now that all threads are locked, let\'s try to get another connection');

    oracledb.getConnection(function(err, conn) {
      if (err) {
        throw err;
      }

      console.log('This does not run because there are no avaialble threads to run it.');
    });
}

[dmcghan]

@cjbj You're probably right. What's already logged in the poolStats is probably sufficient for most folks.

[cjbj]

@dmcghan that's a great anti-pattern example

[dmcghan]

Thanks. I need to turn this into a blog post! :)

[cjbj]

@dmcghan or node-oracledb doc...

[dmcghan]

@cjbj Or both! 👍