Query Execution Time increases when increasing pool size

[SinghBhisham]

Node version: 14
Node-oracledb version: 5.1
Oracle DB version: 12.2

When i use pool size of 1 (static pool) all my queries are executed within 1ms. But when i increase the pool size to say 20, same queries start taking more than 5-10ms. I am also increasing UV_THREADPOOL_SIZE when increasing pool size.

Below is a sample code to illustrate my problem

const uuid = require('uuid').v4;
oracledb.autoCommit = false;
process.env.ORA_SDTZ = 'UTC';
const poolSize = 1;
async function init(){
        await oracledb.createPool({ // no need to store the returned pool
            user: 'XXXXX',
            password: 'XXXXX',  // mypw contains the hr schema password
            connectString: 'XXXXX/XXX',
            poolAlias:  'dev',
            poolIncrement: 0,
            poolMax: poolSize,
            poolMin: poolSize
        });
}
async function executeQuery(query, binds = {}, opts = {}) {
    let connection;
    try {
        const tagName = `<------${uuid()}----->`;
        const pool = await oracledb.getPool('dev')
        connection = await pool.getConnection();
        console.time(tagName);
        console.log("Connections in USE:  ", pool.connectionsInUse);
        const result = await connection.execute(query, binds, opts);
        console.timeEnd(tagName);
        return result;
    } catch (err) {
        console.error(' err', err, query, opts);
    } finally {
        if (connection) {
            try {
                await connection.close(); // Put the connection back in the pool
            } catch (err) {
                console.error('Error :: ', err);
            }
        }
    }
}


async function  test(v) {
    console.log("UV_THREADPOOL_SIZE: ", process.env.UV_THREADPOOL_SIZE)
    console.log("POOLSIZE: ", poolSize)
    await init();
    const query = `SELECT  * FROM "Customers" WHERE "crmId"=:crmId`
    for (let i = 0; i < v; i++) {
        try {
            let p = executeQuery(query, { crmId: 'refactor_5656'}, { fetchArraySize: 1 })
            
        } catch(e) {
            console.log(e)
        }
        
    }
}

test(500)

PS: there is an index on crmId.
I am simulating parallel queries here. Basically as the connections in use increases connection.execute start taking more time to complete

[cjbj]

This is likely a problem with threads. Your code (thanks for making it runnable!) shows a per-execution time increase if I increase the pool size but haven't bumped up UV_THREADPOOL_SIZE. Times are stable if I do increase UV_THREADPOOL_SIZE.

Give details about how you are setting UV_THREADPOOL_SIZE, and where. Remember on Windows it needs to be set in the environment before Node.js runs.

You wouldn't want to make a pool too big - there will always be overheads of accessing a shared resource, not to mention DB limitiations. Check the doc Connection Pool Sizing.

And can you answer the issue template questions? Thanks.

My results for test(20) are:

$ node issue1354.js 
UV_THREADPOOL_SIZE is:  4
poolSize is: 10
Connection pool started
<------76629650-99bc-469b-a5cd-cce7440f316d----->: 87.834ms
<------21a52902-856b-4dc7-9991-af67123c4c7a----->: 88.145ms
<------1ac28ea0-8873-43d8-bc78-5c1431705139----->: 88.541ms
<------a6faaae8-6c43-4fad-b568-67af1ed714b7----->: 88.189ms
<------1dc5d10c-cf33-4e7e-8e49-a6423d8039fa----->: 88.395ms
<------f436a15f-1df3-41f0-8f47-249b1cd46b97----->: 88.626ms
<------b219de9a-8cda-4810-892f-08e3d1588fc3----->: 88.612ms
<------7cb9b1bd-a283-4fe5-adc9-9d6b53d5a408----->: 88.76ms
<------c19ac982-5e05-4b57-ae01-17d0022c5ea8----->: 173.407ms
<------263c6fc6-4c99-4f97-8224-be897fdaf27f----->: 84.543ms
<------607aaba7-0044-40b8-b0a2-2738a1b6edf7----->: 84.734ms
<------f9390ead-1946-4dff-b103-242e71d4321b----->: 84.821ms
<------c6524fb3-2d58-404d-ad6f-cc9167c87bab----->: 174.236ms
<------21223899-c6f1-455e-882a-a4b8d3e80510----->: 84.87ms
<------e4e00151-826b-4524-a997-06d2161f668e----->: 85.085ms
<------4af0d7fa-0d04-417c-9d97-5774b53b0456----->: 85.476ms
<------b90d731f-b861-4156-ac9e-d9dfd4107617----->: 122.015ms
<------024f2cc0-bbbd-4bfe-8ad3-1e3030283ee7----->: 122.698ms
<------6bbff080-e47d-4c93-a0fe-66a68648cc37----->: 40.277ms
<------b3fc6d45-2224-4bcd-947e-ccc3b19a64f7----->: 40.804ms


$ node issue1354.js 
UV_THREADPOOL_SIZE is:  10
poolSize is: 10
Connection pool started
<------4423358d-e60a-4cd1-9c5e-9d06d7dbfa43----->: 46.017ms
<------9985b733-bb3c-44db-aaba-5959a89ec2b4----->: 46.521ms
<------364d1845-5054-4ec1-b1d0-4b791c0e0f04----->: 46.443ms
<------122251de-55cc-4c2f-bbec-93bb7f053733----->: 46.519ms
<------d3457f76-da86-49a5-a845-fd3fe7a80341----->: 46.807ms
<------60bc4918-a23a-4e4a-b2dc-124e59cd06b4----->: 46.799ms
<------41e45b92-5e08-45ac-a873-69fc7feb4415----->: 47.955ms
<------77cf17da-3c0d-4e6f-8c24-da2f122b4bce----->: 47.805ms
<------307eff18-7988-4e77-8381-eb29924b3a60----->: 47.987ms
<------a7af0585-d8c6-4427-ad6c-3b881066d826----->: 48.128ms
<------87dd650a-2359-4d9f-af28-59bc0bc9eae1----->: 44.51ms
<------dd57b7ef-bcda-4226-a5f3-d391ef58a43d----->: 45.196ms
<------064d916d-4a26-4ace-a23c-262bba0f79bc----->: 45.978ms
<------8b69d849-62f9-4be2-88e7-31ddd1bae998----->: 46.693ms
<------61680cc5-9c16-4910-aafc-6dcc474c5362----->: 47.177ms
<------b4a72399-78d3-458b-ae01-ed8605cd6a49----->: 46.95ms
<------efa91461-4fe8-43cb-9b54-ef54b91d537c----->: 47.678ms
<------55b0367c-fa9c-40ea-83bd-960938d0c97c----->: 48.461ms
<------10573674-0e4a-414a-95d6-e9d321ae7c9d----->: 49.046ms
<------217fbe87-a0d3-4dc5-ac32-2e34626f1c03----->: 48.607ms

[SinghBhisham]

@cjbj Thanks for quick reply. I am running this on kubernetes using base image of oraclelinux. I am setting UV_THREADPOOL_SIZE from environment variables.
I can see relation between connection in use and response time. As the connections in use grow, response time increases.
NOTE: Also we have allocated resources 1000m CPU and 1G memory in kubernetes deployement file

UV_THREADPOOL_SIZE 30
POOLSIZE: 1
<------1fa23feb-f687-46f1-b415-0939062c0df1----->: 0.552ms
Connections in USE:   1
<------e275d0a2-c7fb-4f7f-85b5-59d2844e7b5d----->: 0.877ms
Connections in USE:   1
<------7089f36a-b864-45c0-81f1-4236f5b649bf----->: 0.609ms
Connections in USE:   1
<------78ecb1a4-bcf1-4eb3-b871-f17163428acd----->: 0.628ms
Connections in USE:   1
<------78f5d4f2-31dd-4d7f-86de-4a52c8c3ad9c----->: 0.565ms
Connections in USE:   1
<------730a3af1-7f27-45e8-9ccb-9beeb2533e95----->: 0.570ms
Connections in USE:   1
<------3d24b569-9b06-4e32-9535-a88f566ef6ab----->: 0.504ms
Connections in USE:   1
<------0da15b46-5d52-46d5-b63d-8e868acb24f0----->: 0.512ms
Connections in USE:   1
<------4f54e575-fda9-4293-af40-addb4e86ed6e----->: 0.622ms
Connections in USE:   1
<------e9d81bd9-ea31-46ee-8bd7-2e42e7b2d3bf----->: 0.647ms



UV_THREADPOOL_SIZE:  30
POOLSIZE:  20
Connections in USE:   1
<------1069e159-0844-4e01-9bcd-9323a8167d7a----->: 11.417ms
Connections in USE:   7
<------c57efeda-4eab-4c6b-9032-94b1917c7a2a----->: 2.782ms
Connections in USE:   6
<------256e0f38-9491-4760-910a-09b26d395584----->: 2.589ms
Connections in USE:   7
Connections in USE:   7
Connections in USE:   7
Connections in USE:   7
<------60491d1e-9094-4a23-9a47-c26a567dd295----->: 63.268ms
<------d0582404-3164-4f26-8e91-a311b1474bfb----->: 63.515ms
<------459e9406-cf6e-484b-b251-d27668a8cfa7----->: 63.413ms
<------b940cc95-ba0a-4a70-904d-e3cc94afd2cc----->: 63.277ms
<------301dd1a6-b656-4563-b72d-5e5446a0b620----->: 1.103ms
Connections in USE:   2
Connections in USE:   3
<------c23a4cf9-1c86-48ad-b104-a40e80228a66----->: 1.115ms
<------63ab4de4-be61-46ec-baad-c26dacac5626----->: 0.928ms
<------b65d7038-e687-4d83-80ef-82522d1db5c1----->: 0.775ms
Connections in USE:   3
Connections in USE:   3
Connections in USE:   3
<------78aa9f71-92f0-4b6d-9ca1-29002d89d500----->: 49.112ms
<------6cfc3306-a952-4d41-bf13-fc89ca065b51----->: 0.951ms
<------8c2ee9be-c9c8-418f-9b77-62db14cf2743----->: 0.856ms
Connections in USE:   3
Connections in USE:   3
Connections in USE:   3
<------d3f87344-8ca9-44b8-8061-dbae297fbc79----->: 1.138ms
<------4e4c6a44-47c1-43b3-a0bb-7886e08be756----->: 0.913ms
Connections in USE:   3
<------c7390531-bdcc-4451-a62e-ee48233d63b0----->: 1.282ms
Connections in USE:   2
Connections in USE:   3
<------e6733138-6587-406e-8e0e-a5d2ae3f2b2b----->: 1.205ms
<------219e0c47-9715-4324-bc96-4adf7586d2c7----->: 0.848ms
<------788087e4-7558-4b33-95de-d07b5a8e3b0e----->: 0.869ms
Connections in USE:   2
Connections in USE:   3
Connections in USE:   3
<------5d0400be-77e1-4858-a4fe-f6977062942f----->: 0.809ms

Connections in USE:   7
<------700f3928-154a-46e8-a25b-c5252ed79ab5----->: 63.671ms
<------1aa5fd84-676c-429e-beed-aefd86a9075c----->: 63.544ms
Connections in USE:   7
Connections in USE:   7
<------162f5131-8aab-4ddb-acac-9d70a657c125----->: 63.865ms
Connections in USE:   7
Connections in USE:   7
Connections in USE:   7

[SinghBhisham]

@cjbj
process.platform : linux
process.version: v10.24.0
process.arch: x64
require('oracledb').versionString: 5.1.0
require('oracledb').oracleClientVersionString: 21.1.0.0.0

[cjbj]

UV_THREADPOOL_SIZE from environment variables

Prove it :)

[SinghBhisham]

@cjbj HAHA. I have logging process.env.UV_THREADPOOL_SIZE in the test function.
In the logs shared above me you can see in the starting it's getting log.

[SinghBhisham]

@cjbj ??

[cjbj]

The way to prove the thread pool sizing was set OK is to run something like pstack on the running process. The number of threads should be your desired number + some more.

You could also see if there is different between using 4 & 5 connections, since the default number of worker threads is 4.

Check there isn't some system resource restriction that I don't know about.

For maximum throughput, your test(500) parameter will need to be (should be) no more than the number of connections in the pool, which should be no more than the number of worker threads.

A more natural way to test would be to take examples/webapp.js and throw some parallel load with 'ab' or 'siege' or similar at it. This can be clearer to work with than worrying about what is and isn't async in a single test script.

[SinghBhisham]

For maximum throughput, your test(500) parameter will need to be (should be) no more than the number of connections in the pool, which should be no more than the number of worker threads.

Does this mean, if i have an express app and connection pool of 10, i will be able to handle 10 requests in my express app?

Actually we have an express app and tested it using jmeter when i observed this behaviour of increasing response time as connections in use increases.

I prepared this code for simplification.
I will try to modify code with adding a REST route and checking with ab.

[cjbj]

Does this mean, if i have an express app and connection pool of 10, i will be able to handle 10 requests in my express app?

If you have a connection pool with poolMax=10, then only 10 express requests can be doing DB work. The rest can be doing non-DB work, or will be queued up in the node-oracledb pool queue waiting to get a connection.

Since setting UV_THREADPOOL_SIZE is the potential issue, you might want to share the code that is setting it.

[SinghBhisham]

NEW CODE

const oracledb = require('oracledb');
const express = require("express")
const uuid = require('uuid').v4;
oracledb.dbObjectAsPojo = true;
oracledb.autoCommit = false;
process.env.ORA_SDTZ = 'UTC';
const config = require("./config/deployment.json");
const app =express();
const poolSize = parseInt(process.env.POOLSIZE) || 4;
async function init(){
    await oracledb.createPool({ // no need to store the returned pool
        user: config.oracledb.user,
        password: config.oracledb.password,  // mypw contains the hr schema password
        connectString: config.oracledb.connectString,
        poolIncrement: 0,
        poolMax: poolSize,
        poolMin: poolSize
    });
}
async function executeQuery(query, binds = {}, opts = {}) {
    let connection;
    try {
        const tagName = `<------${uuid()}----->`;
        const pool = await oracledb.getPool()
        connection = await pool.getConnection();
        console.time(tagName);
        console.log("Connections in USE:  ", pool.connectionsInUse);
        const result = await connection.execute(query, binds, opts);
        console.timeEnd(tagName);
        return result;
    } catch (err) {
        console.error(' err', err, query, opts);
    } finally {
        if (connection) {
            try {
                await connection.close(); // Put the connection back in the pool
            } catch (err) {
                console.error('Error :: ', err);
            }
        }
    }
}

app.get("/", async function(req, res){
    const query = `SELECT  * FROM "Customers" WHERE "crmId"=:crmId`
    try {
        await executeQuery(query, { crmId: 'refactor_5656' }, { fetchArraySize: 1 })
        res.send("Success")
    } catch (e) {
        console.log(e)
        res.status(500);
    }

});
console.log("UV_THREADPOOL_SIZE: ", process.env.UV_THREADPOOL_SIZE)
console.log("POOLSIZE: ", poolSize)
console.log('process.version', process.version);
console.log('process.arch', process.arch);
console.log('oracledb.versionString', oracledb.versionString);
console.log('oracledb.oracleClientVersionString', oracledb.oracleClientVersionString);
init().then(()=>{
    app.listen(3000, function(){
        console.log('listening on 3000')
    })
})
async function closePoolAndExit() {
    console.log('\nTerminating Oracle connection pool');
    try {
        const pool = oracledb.getPool();
        await pool.close(10);
        process.exit(0);
    } catch (err) {
        console.error(err.message);
        process.exit(1);
    }
}

// Close the pool cleanly if Node.js is interrupted
process
    .once('SIGTERM', closePoolAndExit)
    .once('SIGINT', closePoolAndExit);

[SinghBhisham]

Running as

sudo docker run -it --net='host' test sh
sh-4.4# UV_THREADPOOL_SIZE=15 POOLSIZE=10 node test.js 
UV_THREADPOOL_SIZE:  15
POOLSIZE:  10
process.version v14.16.0
process.arch x64
oracledb.versionString 5.1.0
oracledb.oracleClientVersionString 21.1.0.0.0
listening on 3000

Also output of ps -efL from docker container to ensure worker threads are being created

sh-4.4# ps -efL | grep node
root         6     1     6  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1     7  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1     8  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1     9  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1    10  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1    11  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1    12  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1    13  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1    14  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1    15  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1    16  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1    17  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1    18  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1    19  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1    20  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1    21  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1    22  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1    23  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1    24  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1    25  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1    26  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1    27  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1    28  0   24 08:22 pts/0    00:00:00 node test.js
root         6     1    29  0   24 08:22 pts/0    00:00:00 node test.js
root        36    30    36  0    1 08:27 pts/1    00:00:00 grep node
sh-4.4# ps -efL | grep node | wc -l
25

[SinghBhisham]

@cjbj Now when i run ab with concurrency of 1

ab -n 100 -c 1 http://localhost:3000/

I see

              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:     1    1   0.6      1       7
Waiting:        1    1   0.6      1       7
Total:          1    1   0.6      1       7

Percentage of the requests served within a certain time (ms)
  50%      1
  66%      1
  75%      1
  80%      2
  90%      2
  95%      2
  98%      3
  99%      7
 100%      7 (longest request)
 

But when i increase concurrent to 10

 ab -n 100 -c 10 http://localhost:3000/

I get following

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:     6    9   1.0      9      11
Waiting:        5    7   1.0      8      10
Total:          6    9   1.0      9      12
WARNING: The median and mean for the waiting time are not within a normal deviation
        These results are probably not that reliable.

Percentage of the requests served within a certain time (ms)
  50%      9
  66%      9
  75%     10
  80%     10
  90%     10
  95%     10
  98%     11
  99%     12
 100%     12 (longest request)

Also from app logs i can see response times going beyond 5ms with connections in use reaches 10. But when connection in use is 1 the response times are 0.5ms.

[SinghBhisham]

@cjbj ?

[cjbj]

@SinghBhisham I wonder whether you're seeing the latching overheads of accessing a shared resource (the pool - which you do to get the stats and to get a connection) on a fast machine, where the SQL query cost is tiny?

A more practical real-world example would be to compare the -c 10 case using the pool vs opening & closing 10 standalone connections. And use a query that is more significant! In apps when you need to do multiple SQL statements for each user request, retain the connection and execute all the SQL sequentially without putting the connection back into the pool in between.

[stale]

This issue has been automatically marked as inactive because it has not been updated recently. It will be closed if no further activity occurs. Thank you for your contributions.

[stale]

This issue has been automatically closed because it has not been updated for a month.