random acquire connection timeout and why new connection when freeConnections exist

[bolin-L]

In my app, I get a few acquire timeout every day, below is code and log

Code is:

  const mysqlPool = app.mysql.pool;

  mysqlPool.on('connection', connection => {
    app.logger.info(`mysql connection and pool detail: ${connection.threadId} - ${mysqlPoolConnection(mysqlPool)}`, { tid: app.tracerTraceId });
  });

  mysqlPool.on('acquire', connection => {
    app.logger.info(`mysql acquire and pool detail: ${connection.threadId} - ${mysqlPoolConnection(mysqlPool)}`, { tid: app.tracerTraceId });
  });

  mysqlPool.on('release', connection => {
    app.logger.info(`mysql release and pool detail: ${connection.threadId} - ${mysqlPoolConnection(mysqlPool)}`, { tid: app.tracerTraceId });
  });

  mysqlPool.on('enqueue', connection => {
    app.logger.info(`mysql enqueue and pool detail: ${connection.threadId} - ${mysqlPoolConnection(mysqlPool)}`, { tid: app.tracerTraceId });
  });

  function mysqlPoolConnection(pool) {
    return `_allConnections: ${pool._allConnections.length}[ ${getConnectionThreadIds(pool._allConnections)} ], _acquiringConnections: ${pool._acquiringConnections.length} [ ${getConnectionThreadIds(pool._acquiringConnections)} ], _freeConnections: ${pool._freeConnections.length} [ ${getConnectionThreadIds(pool._freeConnections)} ]`;
  }

  function getConnectionThreadIds(cons) {
    return cons.map(con => con.threadId).join(',');
  }

And config is

{
        host: 'xxx',
        port: xxx,
        user: 'xxx',
        password: 'xxx',
        database: 'xxx',
        connectionLimit: 10,
        connectTimeout: 3000,
        acquireTimeout: 4000
      }

Here is log:

[dougwilson]

The reason the free connection was not used is because it failed a PING. As in, in your screenshot, it shows 1 free connection available, but then when this module goes to use the connection, it will first run a PING command on the connection, and if it failed to return within acquireTimeout, it will discard that connection as dead and open a new connection, when then emits the 'connection' event on the pool.

[bolin-L]

@dougwilson Thank you for the timely response. I got your explanation, but I still have a few puzzles.

1. why the connection still returns a result after acquiring timeout, running continue in my app and return a result finally. I found you have removed the connection from all connections and destroyed it?

2. I used to changed "acquireTimeout" from 10 seconds to 4 seconds, and my request cost time has decreased accordingly. So I doubt it the ping timeout problem did not cause by mysql database(Mysql database no connect log). Maybe ping correctly and return to mysqljs but lost ok signal, then mysqljs release the connection after acquiring timeout? and then my app running continue?

[dougwilson]

Unfortunately unless you can provide me a way to reproduce the issue so I can debug it, I don't know the answer to those questions.

[bolin-L]

@dougwilson I understand but I can not provide a way to you to debug, because It is the company‘s project. I can reproduce the issue just a few times one day and it random. I will debug it on my Mac and get more log to offer to you. I hope if you have any suggestions or need the log, please let me know and I will do my best to do it.

log

debug in node_modules/mysql/lib/protocol/Protocol.js and get the log:

Protocol.prototype._dequeue = function(sequence) {
  sequence._timer.stop();

  // No point in advancing the queue, we are dead
  if (this._fatalError) {
    console.log(JSON.stringify(this._fatalError));
    return;
  }

log

{"code":"PROTOCOL_SEQUENCE_TIMEOUT","fatal":true,"timeout":4000}

I will debug for more detail log. Are you have any advice on where to debug for more timeout log

[dougwilson]

I've already explained why the connection was not used above. If you don't want to accept that answer, then I need more evidence to the contrary. What you just posted above re-enforce what I already said the issue was if that sequence timeout was on a PING sequence.

[bolin-L]

@dougwilson Yes, I accept your answer. But I want to know why it is timeout when pinging because it is so strange (Always appear in the first few requests of every day).

[dougwilson]

Gotcha. To determine why it has a timeout, you'll need to look out of your Node.js code and into either your network infrastructure or your MySQL server.

[bolin-L]

@dougwilson I think I found the question. the MySQL connection will be recycled when idle time over 8 hours (set by wait_timeout), but the client still holding on it in the connection pool.

My DBA colleague told me it did not send a signal to the client when the connection was recycled. their way is to check the connection on time to make the connection available by select 1, I do the same and it works to me

I found here is a pr it will suit for me.