node-mssql is not truly concurrent on queries

[luca-moser]

Hi Patrik.

I have some code which should have simultaneous queries running. I am using a global connection pool by instantiating a new let sqlConn = new sql.Connection(dbconfig) with a pool of max 15 connections.

Using that single connection pool called sqlConn, I am not able to run multiple sqlConn.request() queries concurrently. It always queues requests up and runs them sequentially, instead of executing all called query() functions. Is there a way to stop the queuing?

What is the reason requests are queued if the purpose of NodeJS is to run code concurrently? Problem is that this design stalls every other query in the program. From my understanding, atleast queries which have stream = true should allow other streamed queries to run concurrently, so that node-mssql is between those two functions concurrently instead of using all power to fininsh one and then executing the other. Sequentially running queries should explicitly be written in code by nesting callbacks or using thenable Promises and not by the library doing it automatically for me.

---

Here is an example:

The connection pool:

let dbConfig = {
    user: 'root',
    password: 'obviouslyfake',
    server: 'localhost',
    database: 'test',
    requestTimeout: 60000,
    connectionTimeout: 3000,
    options: {
        tdsVersion: '7_3_B'
    },
    pool: {
        max: 15,
        min: 10,
        idleTimeoutMillis: 3000
    }
};

// instantiate new connection pool
let sqlConn = new sql.Connection(dbConfig);

Now using that connection pool, we run 3 Promises concurrently, in this example, we load data from the sql server into a cache, all at the same time:

    return Promise.all([
        CustomerRetriever.preloadCache(report),
        ContractRetriever.preloadCache(report),
        CustomerDeviceRetriever.preloadCache(report)
    ]);

Each of this preloadCache functions does the same, but when the program is executed, only one of them is returning query results back at a time. The 3 preloadCache functions are called immediately, they don't wait for the one before to be finished. (The word entities is replaced with the actual entity which is cached in the original code)

static preloadCache(report){
        return new Promise((resolve, reject) => {

            // check count
            let amountOfEntities = 0;
            let onePercent = 0;
            let psCount = sqlConn.request();
            let cacheKeyPrefix = 'entity:';

            logger.debug(`get amount of entites for preloading`);

            psCount.stream = true;
            psCount.query('SELECT COUNT(*) AS count FROM entities');
            psCount.on('row', (row) => {
                // set count
                amountOfEntities = row.count;
                onePercent = amountOfEntities / 100;
            });

            psCount.on('error', (err) => reject(err));

            psCount.on('done', () => {

                mainLogger.info(`preloading ${amountOfEntities} entities`);

                // query entities
                let done = 0;
                let req = sqlConn.request();
                req.stream = true;
                req.query(`
                    SELECT * FROM entities
                `);

                req.on('row', row => {
                    let entityNumber = row.entityNumber; 
                    let entity = this.build(row);
                    redis.set(`${cacheKeyPrefix}${entityNumber}`, JSON.stringify(entity));
                    done++;

                    report(onePercent, done, 'entity');
                });

                req.on('done', () => {
                    resolve();
                });

                req.on('error', err => reject(err));

            });

        });
    }

What really happens is, that in the console you might or might no see two mainLogger.info('preloading ${amountOfEntities} entities'); messages and then you can see how only one of the streamed queries is returning data at a time because the report(onePercent, done, 'entity'); function never gets called from the other queries as only one is ran at a time.

Is this a bug? If I have 15 connections in a pool, in my opinion, I should be able to run 15 streamed queries simlultaneously. Here we see, that only one is executed.

Changing sqlConn.request() to new sql.Request(sqlConn) has no effect.

The documentation does not comply with what is actually happening:
"Internally, each Connection instance is a separate pool of TDS connections. Once you create a new Request/Transaction/Prepared Statement, a new TDS connection is acquired from the pool and reserved for desired action (So one executing query handled by one connection from the pool?). Once the action is complete, connection is released back to the pool. Connection health check is built-in so once the dead connection is discovered, it is immediately replaced with a new one."

[patriksimek]

There is no queue for requests outside transaction. You can try it yourself:

var sql = require('mssql'); 

var config = {
    user: "...",
    password: "...",
    server: "localhost",
    port: 1433,
    database: "...",
    pool: {
        max: 3,
        min: 1
    }
}

var connection = new sql.Connection(config, function(err) {
    console.log("connected");

    var request1 = new sql.Request(connection);
    request1.stream = true
    request1.query('waitfor delay \'00:00:03\'');
    request1.on('done', function() {
        console.log("done 1");
    });

    var request2 = new sql.Request(connection);
    request2.stream = true
    request2.query('waitfor delay \'00:00:02\'');
    request2.on('done', function() {
        console.log("done 2");
    });

    var request3 = new sql.Request(connection);
    request3.stream = true
    request3.query('waitfor delay \'00:00:01\'');
    request3.on('done', function() {
        console.log("done 3");
    });
});

Result:

connected
done 3
done 2
done 1

Result after changing pool.max to 1:

connected
done 1
done 2
done 3

[luca-moser]

@patriksimek
Your example works, but it is missing nested queries.

Here is your example extended to correspond with my original code. What I want to happen is to get console.log('got row on inner request X') from all 3 requests concurrently. We have nested streamed queries in each of the first COUNT(*) queries. But I only see console.log('got row on inner request 1') from innerRequest1. request3 is actually stalled until innerReqest1 and innerReqest2are finished. The streamed inner requests are queued/run sequentially. If I move the inner requests to the done event of the outer request, the result is the same.

/*jshint esnext: true */
/*jslint node: true */
/* global -Promise */
'use strict';

// check execution environment
let dev = process.env.NODE_ENV === 'development' ? true : false;
let fs = require('fs');
let sql = require('mssql');
let Promise = require('bluebird');

// config
let config;
try {
    config = JSON.parse(fs.readFileSync('../../config/server.json', 'utf-8'));
} catch (err) {
    throw Error('unable to read config file.');
}

sql.Promise = Promise;
let successConfig = config.database.success;
let dbConfig = {
    user: successConfig.user,
    password: successConfig.pw,
    server: successConfig.host,
    database: successConfig.name,
    requestTimeout: successConfig.requestTimeout,
    connectionTimeout: successConfig.connectionTimeout,
    options: {
        tdsVersion: '7_3_B'
    },
    pool: {
        max: 15,
        min: 5,
        idleTimeoutMillis: successConfig.pool.idleTimeoutMillis
    }
};

// instantiate new connection pool and run queries
let connectionPool = new sql.Connection(dbConfig, (err) => {
    if(err){
        throw Error(err);
    }

    console.log('connected to database');

    var request1 = new sql.Request(connectionPool);
    request1.stream = true;
    request1.query('SELECT COUNT(*) FROM KUNDEN');
    request1.on('row', (row) => {
        var innerRequest1 = new sql.Request(connectionPool);
        innerRequest1.stream = true;
        innerRequest1.query('SELECT * FROM KUNDEN');
        innerRequest1.on('row', (row) => console.log('got row on inner request 1'));
        innerRequest1.on('done', () => console.log('inner request 1 done'));
    });
    request1.on('done', function() {
        console.log("done 1");
    });

    var request2 = new sql.Request(connectionPool);
    request2.stream = true;
    request2.query('SELECT COUNT(*) FROM TA_LUMO_Karbon_Vertrag_Ziel');
    request2.on('row', (row) => {
        var innerRequest2 = new sql.Request(connectionPool);
        innerRequest2.stream = true;
        innerRequest2.query('SELECT * FROM TA_LUMO_Karbon_Vertrag_Ziel OPTION(RECOMPILE)');
        innerRequest2.on('row', (row) => console.log('got row on inner request 2'));
        innerRequest2.on('done', () => console.log('inner request 2 done'));        
    }); 
    request2.on('done', function() {
        console.log("done 2");
    });

    var request3 = new sql.Request(connectionPool);
    request3.stream = true;
    request3.query('SELECT COUNT(*) FROM TA_LUMO_Karbon_Kundengeraete OPTION(RECOMPILE)');
    request3.on('row', (row) => {
        var innerRequest3 = new sql.Request(connectionPool);
        innerRequest3.stream = true;
        innerRequest3.query('SELECT * FROM TA_LUMO_Karbon_Kundengeraete OPTION(RECOMPILE)');
        innerRequest3.on('row', (row) => console.log('got row on inner request 3'));
        innerRequest3.on('done', () => console.log('inner request 3 done'));                
    });         
    request3.on('done', function() {
        console.log("done 3");
    });
});

output 1:

> node Test.js
connected to database
done 1
done 2
got row on inner request 1
got row on inner request 1
got row on inner request 1
got row on inner request 1
........afer some time........
inner request 1 done
got row on inner request 2
got row on inner request 2
got row on inner request 2
got row on inner request 2
got row on inner request 2
........afer some time........
inner request 2 done
done 3
got row on inner request 3
got row on inner request 3
got row on inner request 3
got row on inner request 3
got row on inner request 3
got row on inner request 3
........afer some time........
inner request 3 done

If I use your example with the waitfor delay it works:

let connectionPool = new sql.Connection(dbConfig, (err) => {
    if(err){
        throw Error(err);
    }

    console.log('connected to database');

    var reqTime1 = new Date();
    var request1 = new sql.Request(connectionPool);
    request1.stream = true;
    request1.query('waitfor delay \'00:00:03\'');
    request1.on('row', (row) => {
    });
    request1.on('done', function() {

        console.log(`done 1 ${new Date() - reqTime1}ms`);

        var inReqTime1 = new Date();
        var innerRequest1 = new sql.Request(connectionPool);
        innerRequest1.stream = true;
        innerRequest1.query('waitfor delay \'00:00:06\'');
        innerRequest1.on('row', (row) => {});
        innerRequest1.on('done', () => console.log(`inner request 1 done ${new Date() - inReqTime1}ms`));                           
    });

    var reqTime2 = new Date();
    var request2 = new sql.Request(connectionPool);
    request2.stream = true;
    request2.query('waitfor delay \'00:00:02\'');
    request2.on('row', (row) => {
    }); 
    request2.on('done', function() {

        console.log(`done 2 ${new Date() - reqTime2}ms`);

        var inReqTime2 = new Date();        
        var innerRequest2 = new sql.Request(connectionPool);
        innerRequest2.stream = true;
        innerRequest2.query('waitfor delay \'00:00:02\'');
        innerRequest2.on('row', (row) => {});
        innerRequest2.on('done', () => console.log(`inner request 2 done ${new Date() - inReqTime2}ms`));                   
    });

    var reqTime3 = new Date();
    var request3 = new sql.Request(connectionPool);
    request3.stream = true;
    request3.query('waitfor delay \'00:00:01\'');
    request3.on('row', (row) => {
    });         
    request3.on('done', function() {

        console.log(`done 3 ${new Date() - reqTime3}ms`);

        var inReqTime3 = new Date();
        var innerRequest3 = new sql.Request(connectionPool);
        innerRequest3.stream = true;
        innerRequest3.query('waitfor delay \'00:00:01\'');
        innerRequest3.on('row', (row) => {});
        innerRequest3.on('done', () => console.log(`inner request 3 done ${new Date() - inReqTime3}ms`));               
    });
});

output 2:

connected to database
done 3 1108ms
done 2 2110ms
inner request 3 done 1056ms
done 1 3031ms
inner request 2 done 2069ms
inner request 1 done 6020ms

Now without any inner requests but directly querying 3 different tables with stream enabled:

// instantiate new connection pool and run queries
let connectionPool = new sql.Connection(dbConfig, (err) => {
    if(err){
        throw Error(err);
    }

    console.log('connected to database');


    var req1 = new sql.Request(connectionPool);
    req1.stream = true;
    req1.query('SELECT * FROM KUNDEN');
    req1.on('row', (row) => console.log('got row on request 1'));
    req1.on('done', () => console.log('request 1 done'));

    var req2 = new sql.Request(connectionPool);
    req2.stream = true;
    req2.query('SELECT * FROM TA_LUMO_Karbon_Vertrag_Ziel OPTION(RECOMPILE)');
    req2.on('row', (row) => console.log('got row on request 2'));
    req2.on('done', () => console.log('request 2 done'));       

    var req3 = new sql.Request(connectionPool);
    req3.stream = true;
    req3.query('SELECT * FROM TA_LUMO_Karbon_Kundengeraete OPTION(RECOMPILE)');
    req3.on('row', (row) => console.log('got row on request 3'));
    req3.on('done', () => console.log('request 3 done'));               

});

Gives the same result as output1, the queries are running sequentially.

using 3 pools for each query also runs the queries sequentially:

let connectionPool = new sql.Connection(dbConfig, (err) => {
    if(err){
        throw Error(err);
    }

    console.log('connected to database with pool 1');


    var req1 = new sql.Request(connectionPool);
    req1.stream = true;
    req1.query('SELECT * FROM KUNDEN');
    req1.on('row', (row) => console.log('got row on request 1'));
    req1.on('done', () => console.log('request 1 done'));           

});

let connectionPool2 = new sql.Connection(dbConfig, (err) => {
    if(err){
        throw Error(err);
    }

    console.log('connected to database with pool 2');

    var req2 = new sql.Request(connectionPool2);
    req2.stream = true;
    req2.query('SELECT * FROM TA_LUMO_Karbon_Vertrag_Ziel');
    req2.on('row', (row) => console.log('got row on request 2'));
    req2.on('done', () => console.log('request 2 done'));                   

});

let connectionPool3 = new sql.Connection(dbConfig, (err) => {
    if(err){
        throw Error(err);
    }

    console.log('connected to database with pool 3');

    var req2 = new sql.Request(connectionPool3);
    req2.stream = true;
    req2.query('SELECT * FROM TA_LUMO_Karbon_Vertrag_Ziel');
    req2.on('row', (row) => console.log('got row on request 2'));
    req2.on('done', () => console.log('request 2 done'));                   

});

Does the query parser somehow block subsequent requests if there are rows returned? Yes, it does work with waitfor delay but not when actually processing rows.

[patriksimek]

Discussion moved to tediousjs/tedious#319

[audiolion]

This is unfortunate because it is the main driver node-mssql relies upon, I am not sure if the other drives fair any better. Maybe the windows native msnodesql driver doesn't have this issue.