Initial connection and first query is very slow

[Greensahil]

I am not sure what changed with the newer versions of node-sql but the initial connection as well as the first query to run is very slow. This is problematic mostly in my development where I have to restart the server several times to test my changes and have to wait more than 10 seconds for the database to connect.

Expected behaviour:

The database to connection to make milliseconds to a second like it did in the past

Actual behaviour:

This is more or less how I connect to the database. I am also using this for testing along with SQL Server Profiler to figure out why the initial connection is slow:

const sql = require('mssql');
const keys = require('./config/keys');
// const util = require('util')

// Need this package for windows authentication

let invDBConfig = {
  user: keys.db.dev_user,
  password: keys.db.dev_password,
  server: keys.db.dev_server, // You can use 'localhost\\instance' to connect to named instance
  database: keys.db.dev_database,

  pool: {
    max: 20,
    min: 1,
    idleTimeoutMillis: 30000,
  },
  options: {
    encrypt: false,
    instanceName: keys.db.dev_instanceName,
    enableArithAbort: false,
  },

};

// https://github.com/tediousjs/node-mssql/issues/1056
// the initial opening of a DB pool takes time because the pool does some probing
// of the SQL server to check connections are possible before resolving the pool.

// The flow is:

// const pool = new ConnectionPool(config)
// creates a pool object, no interaction with SQL server yet
// pool.connect()
// library creates a test connection to make sure the SQL server is up, config is correct, etc.
// this test connection is closed (and we wait for it to close)
// the internal pool logic is turned on and the pool is
// returned in a "connected" state - no connections will be open in the pool yet
// pool.query('SELECT 1')
// pool looks for a free connection; for a "cold" start there
// will be no connections in the pool so it will create one,
// this connection is then released from the pool and used to execute
// the query. it is then returned to the pool for re-use
// This means that if you call pool.connect() it will take some
// time (300ms perhaps) and if you then perform a query against the DB
//  it will create another new connection taking again 300ms
// (well, slightly less because we won't close this connection).
// This means that your benchmarking looks entirely as expected and
// as I stated in my above comment if you want to see the true performance
// you need a pool that already has a connection in it available for use.

const invDBConnection = new sql.ConnectionPool(invDBConfig).connect()
  .then((query) => query)
  .catch((error) => {
    if (error.code === 18456) {
      console.error('Invalid UserName');
    } else {
      console.error('Database Trouble!  ', error);
      console.log('Terminating Server');
      process.exit(1);
    }
  });

  GetSchemaVersion()

  async function GetSchemaVersion() {
    console.time("To get Inside GetSchemaVersion")
    console.timeEnd("To get Inside GetSchemaVersion")
    console.time("To await invDBConnection")
    const invDBPool =await invDBConnection

    console.timeEnd("To await invDBConnection")
    try {
       console.time("To get SchemaVer 1st time")
       let schVer = await invDBPool.query(`Select 'apple' `)
       console.timeEnd("To get SchemaVer 1st time")

       console.time("To get SchemaVer 2nd time")
       schVer = await invDBPool.query(`Select 'apple' `)
       console.timeEnd("To get SchemaVer 2nd time")

       console.time("To get SchemaVer 3rd time")
       schVer = await invDBPool.query(`Select 'apple' `)
       console.timeEnd("To get SchemaVer 3rd time")

       console.time("To get SchemaVer 4th time")
       schVer = await invDBPool.query(`Select 'apple' `)
       console.timeEnd("To get SchemaVer 4th time")

       console.log(schVer.recordset[0])
    } catch (err) {
        console.log(err)
    }
}

console.log('INV DB CONNECTION CONFIG:');
console.log(invDBConfig);

module.exports = { invDBConnection };

This is the output that I am getting in the console:

The database state is dev To get Inside GetSchemaVersion: 0.046ms INV DB CONNECTION CONFIG: { user: 'MyUser', password: 'MyPassword', server: 'LAPTOP-DELL-SAH', database: 'MY-INV', pool: { max: 20, min: 1, idleTimeoutMillis: 30000 }, options: { encrypt: false, instanceName: 'SQLEXPRESS', enableArithAbort: false } } To await invDBConnection: 5.098s To get SchemaVer 1st time: 5.129s To get SchemaVer 2nd time: 6.761ms To get SchemaVer 3rd time: 5.904ms To get SchemaVer 4th time: 6.185ms { '': 'apple' }

As you can see the intial connection takes 5 seconds and it takes 5 more seconds to run the very first query. After that all queries takes 1 0r 2 ms.

In the SQL Profiler:

You can see that once the audit logout completes in 3ms there seems to be a large gap before audit login fires.

Configuration:

I am using a Dell Laptop with Windows 11 Pro. Also using SQL Server Express.

Software versions

• NodeJS: 15.8.0
• node-mssql: 9.1.1
• SQL Server: 15.0.2000.5

[Greensahil]

I would also like to add that I understand that initiating connection and pooling it is the most resource and time consuming part and will always take more time than to just using a connection from the pool. I have left some comment made by the developer of this package in the code snippet above where he says that the initial connection and first query might take around 300 ms each. I feel like 10 second wait time is a lot and I am not sure if there is something wrong with my configuration.

I just miss the good old days hitting ctrls + s with nodemon and the server starting instantly when using this library :)

[dhensby]

Thanks for opening the issue and providing the replication code.

I've run it locally against a docker image on my M2 MacBook Air and I get the following output:

To get Inside GetSchemaVersion: 0.036ms
INV DB CONNECTION CONFIG:
{
  user: 'sa',
  password: 'yourStrong(!)Password',
  server: 'localhost',
  database: 'master',
  debug: true,
  pool: { max: 20, min: 1, idleTimeoutMillis: 30000 },
  options: { encrypt: false, enableArithAbort: false }
}
To await invDBConnection: 21.101ms
To get SchemaVer 1st time: 20.091ms
To get SchemaVer 2nd time: 3.366ms
To get SchemaVer 3rd time: 4.095ms
To get SchemaVer 4th time: 3.566ms
{ '': 'apple' }

As with other reports of slowness, I'm not able to replicate. Maybe this is something to do with SQL Express?

If you run this with DEBUG=* env var set, what kind of information are you getting about where the delays are? I suspect they are all just within the tedious library. If that's the case, then really this issue needs to be opened with tedious as it's just their internals dealing with it.

Just to point out, it seems like it's taking you 5 seconds to establish a connection, all your subsequent queries (after the connection + first query) are just using a pooled connection, so that's why they are "quick", but if you run some parallel queries, you'll force the pool to create new connections and I suspect you'll see the same 5s latency.

I wonder if Tedious is performing a whole host of authentication attempts before finally logging in with username/password. I had a problem with microsoft auth on some other libraries trying to login using system assigned identities and it hanging for ages - do you have any environment variables that could be confusing the auth layer, such as CLIENT_ID?

---

Edit: Also, you say it's "newer versions" - do you know which versions (and corresponding versions of tedious) don't have this problem for you?

[Greensahil]

Thank you for the response. I updated my start script to SET DEBUG=mssql:* & nodemon database.js and this is the output:

The database state is dev mssql:base pool(1): created +0ms mssql:base pool(1): connecting +1ms mssql:tedi pool(1): connection #1 created +0ms mssql:tedi connection(1): establishing +0ms To get Inside GetSchemaVersion: 0.048ms INV DB CONNECTION CONFIG: { user: 'MyUser', password: 'MyPassword', server: 'LAPTOP-DELL-SAH', database: 'MY-INV', debugger: true, pool: { max: 20, min: 1, idleTimeoutMillis: 30000 }, options: { encrypt: false, instanceName: 'SQLEXPRESS', enableArithAbort: false } } mssql:tedi connection(1): established +5s mssql:base pool(1): connected +5s mssql:tedi connection(1): destroying +1ms mssql:tedi connection(1): destroyed +1ms To await invDBConnection: 5.088s mssql:base request(1): created +0ms mssql:tedi pool(1): connection #2 created +2ms mssql:tedi connection(2): establishing +1ms mssql:tedi connection(2): established +5s mssql:tedi connection(2): borrowed to request #1 +0ms mssql:tedi request(1): query Select 'apple' +0ms mssql:base connection(2): released +5s mssql:tedi request(1): completed +8ms To get SchemaVer 1st time: 5.135s mssql:base request(2): created +5s mssql:tedi connection(2): borrowed to request #2 +2ms mssql:tedi request(2): query Select 'apple' +1ms mssql:base connection(2): released +5ms mssql:tedi request(2): completed +1ms To get SchemaVer 2nd time: 3.739ms mssql:base request(3): created +4ms mssql:tedi connection(2): borrowed to request #3 +2ms mssql:tedi request(3): query Select 'apple' +0ms mssql:base connection(2): released +3ms mssql:tedi request(3): completed +2ms To get SchemaVer 3rd time: 3.349ms mssql:base request(4): created +3ms mssql:tedi connection(2): borrowed to request #4 +1ms mssql:tedi request(4): query Select 'apple' +1ms mssql:base connection(2): released +3ms mssql:tedi request(4): completed +1ms To get SchemaVer 4th time: 2.572ms { '': 'apple' }

[Greensahil]

About the previous version. I probably should not have said that because I had lost my laptop and I had to start everything fresh. There was an upgrade on SQL Version, my laptop model, this library etc. Since you cannot replicate this issue with my config the problem is somewhere else.

[Greensahil]

Okay, I finally decided to install the SQL Server Developer edition and sure enough there was no delay in connection. I was not able to use the server name as LAPTOP-DELL-SAH as it did not work. So I had to use localhost instead. So I tried to connect again using SQL Server Express but this time with server name localhost and the connection is almost instant. 5s is down to 26ms!!

So here is the output while using SQL Server Express edition. First while using my laptop name "LAPTOP-DELL-SAH" as server name:

The database state is dev mssql:base pool(1): created +0ms mssql:base pool(1): connecting +0ms mssql:tedi pool(1): connection #1 created +0ms mssql:tedi connection(1): establishing +0ms To get Inside GetSchemaVersion: 0.052ms INV DB CONNECTION CONFIG: { user: 'MyUser', password: 'MyPassword', server: 'LAPTOP-DELL-SAH', database: 'MY-INV', pool: { max: 20, min: 1, idleTimeoutMillis: 30000 }, options: { encrypt: false, instanceName: 'SQLEXPRESS', enableArithAbort: false } } mssql:tedi connection(1): established +5s mssql:base pool(1): connected +5s mssql:tedi connection(1): destroying +1ms mssql:tedi connection(1): destroyed +1ms To await invDBConnection: 5.109s mssql:base request(1): created +0ms mssql:tedi pool(1): connection #2 created +2ms mssql:tedi connection(2): establishing +1ms

And here is the output with everything the same except the laptop name replaced with localhost:

The database state is dev mssql:base pool(1): created +0ms mssql:base pool(1): connecting +1ms mssql:tedi pool(1): connection #1 created +0ms mssql:tedi connection(1): establishing +1ms To get Inside GetSchemaVersion: 0.045ms INV DB CONNECTION CONFIG: { user: 'MyUser', password: 'MyPassword', server: 'localhost', database: 'MY-INV', pool: { max: 20, min: 1, idleTimeoutMillis: 30000 }, options: { encrypt: false, instanceName: 'SQLEXPRESS', enableArithAbort: false } } mssql:tedi connection(1): established +20ms mssql:base pool(1): connected +25ms mssql:tedi connection(1): destroying +1ms mssql:tedi connection(1): destroyed +1ms To await invDBConnection: 21.85ms mssql:base request(1): created +0ms mssql:tedi pool(1): connection #2 created +2ms mssql:tedi connection(2): establishing +0ms mssql:tedi connection(2): established +7ms mssql:tedi connection(2): borrowed to request #1 +0ms mssql:tedi request(1): query Select 'apple' +1ms mssql:base connection(2): released +22ms mssql:tedi request(1): completed +7ms To get SchemaVer 1st time: 21.176ms mssql:base request(2): created +21ms mssql:tedi connection(2): borrowed to request #2 +2ms mssql:tedi request(2): query Select 'apple' +0ms mssql:base connection(2): released +4ms mssql:tedi request(2): completed +2ms To get SchemaVer 2nd time: 3.115ms mssql:base request(3): created +3ms mssql:tedi connection(2): borrowed to request #3 +2ms mssql:tedi request(3): query Select 'apple' +0ms mssql:base connection(2): released +3ms mssql:tedi request(3): completed +1ms To get SchemaVer 3rd time: 2.752ms mssql:base request(4): created +3ms mssql:tedi connection(2): borrowed to request #4 +1ms mssql:tedi request(4): query Select 'apple' +0ms mssql:base connection(2): released +2ms mssql:tedi request(4): completed +2ms To get SchemaVer 4th time: 2.575ms { '': 'apple' }

Just to rule out the possibility that this has anything to do with my test MY-INV database, I also used master database and got the same result. Do you think, I should create this same thread over at the tedious repository? I would love to hear your thoughts on this.

[dhensby]

I think it would be useful to open an issue in the tedious driver about slow connections to named instances / SQL Express

[dhensby]

I'm going to close this as an issue with the underlying driver. Thanks for taking the time to report the issue and investigate it.

[erSitzt]

Old issue i know.. but if this is still a thing and as i did not see an issue in the tedious repo.

When connecting to instances of an sql server, remember there is a UDP request first on port 1434 (SQL Server Browser) to query the instance port. This might have some overhead.

Have a look here : https://github.com/search?q=repo%3Atediousjs%2Ftedious%20udp&type=code