Mysql: Query taking forever when using nodejs, but less than 1s with other apps.

[caio-porto]

This specific query becomes really slow and then it gets back to normal as new data is inserted. It keeps oscillating. To make sure that I would be able to reproduce it constantly, I created a backup DB exactly when it got slow. I can give access to the database if required to run some tests.
When I execute the following query using NodeJS it takes at least 1 minute, while using any other application it usually takes less than 1 second.
I monitored the MySQL and I could see that the query stays in Sending data state for the whole time until it finishes.
I can provide additional information and access to this database if required. I really need to fix this problem.

MySQL Server: 5.7.10-log
NodeJS MySQL: 2.11.1
NodeJS: 6.2.2
IISNode: 0.2.21
IIS: 7.5+
Windows Server 2012 and Windows 7

NodeJS code:

var http = require('http'),
    express = require('express'),
    bodyParser = require('body-parser'),
    cors = require('cors');

var app = express();

mysql = require('mysql');

app.use(bodyParser.urlencoded({
  extended: true
}));
app.use(bodyParser.json());
app.use(bodyParser.text());
app.use(cors());


app.post('/test', function(req,res){
    var conn  = mysql.createConnection({
        host     : '10.1.1.3',
        user     : 'test',
        password : 'Test1234',
        database : 'test',
        debug: ['HandshakeInitializationPacket','ClientAuthenticationPacket','OkPacket', 'ComQueryPacket', 'ResultSetHeaderPacket']
    });

    conn.connect(function(err) {
        if (err) {
            console.error('error connecting: ' + err.stack);
            return;
        }
        console.log('connected as id ' + conn.threadId);

        conn.query('SELECT s.* FROM can_status s INNER JOIN (account_company_symbol acs) ON s.canid = acs.canid WHERE company = '+conn.escape(req.body.company)+' AND idvehicle = '+conn.escape(req.body.idvehicle)+' AND time >= DATE_SUB((select max(time) from can_status WHERE idvehicle = '+conn.escape(req.body.idvehicle)+'), INTERVAL '+conn.escape(req.body.time)+' MINUTE) ORDER BY time DESC', function(error, results, fields){         
            if(error !== undefined && error !== null){
                console.log(error);
                conn.end()
                res.send(error);
            }
            conn.end()
            res.send(results);

        });

    });
});

app.listen(process.env.PORT, function () {
  console.log('Example app listening on port'+process.env.PORT);
});

NodeJS Log:

Example app listening on port\\.\pipe\87c13d28-d1fe-4c3a-afa2-df979d56db0a
<-- HandshakeInitializationPacket
HandshakeInitializationPacket {
  protocolVersion: 10,
  serverVersion: '5.7.10-log',
  threadId: 26514,
  scrambleBuff1: <Buffer 6e 23 25 06 03 13 0d 34>,
  filler1: <Buffer 00>,
  serverCapabilities1: 63487,
  serverLanguage: 33,
  serverStatus: 2,
  serverCapabilities2: 33279,
  scrambleLength: 21,
  filler2: <Buffer 00 00 00 00 00 00 00 00 00 00>,
  scrambleBuff2: <Buffer 3e 4a 6b 37 79 2a 25 72 20 4f 27 59>,
  filler3: <Buffer 00>,
  pluginData: 'mysql_native_password',
  protocol41: true }

--> ClientAuthenticationPacket
ClientAuthenticationPacket {
  clientFlags: 455631,
  maxPacketSize: 0,
  charsetNumber: 33,
  filler: undefined,
  user: 'test',
  scrambleBuff: <Buffer e2 56 b0 51 5f 27 ac 8a 45 55 50 37 bc b3 04 0e 98 25 72 c5>,
  database: 'test',
  protocol41: true }

<-- OkPacket
OkPacket {
  fieldCount: 0,
  affectedRows: 0,
  insertId: 0,
  serverStatus: 2,
  warningCount: 0,
  message: '',
  protocol41: true,
  changedRows: 0 }

connected as id 26514
--> ComQueryPacket
ComQueryPacket {
  command: 3,
  sql: 'SELECT s.* FROM can_status s INNER JOIN (account_company_symbol acs) ON s.canid = acs.canid WHERE company = \'Efficient Drivetrains Inc.\' AND idvehicle = \'4\' AND time >= DATE_SUB((select max(time) from can_status WHERE idvehicle = \'4\'), INTERVAL \'5\' MINUTE) ORDER BY time DESC' }

<-- ResultSetHeaderPacket
ResultSetHeaderPacket { fieldCount: 5, extra: undefined }

Thank you very much!

[sidorares]

does it connect immediately, but spend a lot of time between .query() and query callback?

[caio-porto]

Yes, exactly. And I can see using the MySQL Workbench that the Query has state "Sending data".

[sidorares]

any suspects in between client and server ( firewall etc )? Do you have MySQL Workbench running on the same host as node-mysql client?

[caio-porto]

Nothing between them. I ran the Workbench, a C# application and the node-mysql on the same machine, but only the node-mysql is having problem. Tried to query from different computers, including the host itself, same result.

[sidorares]

can you try to connect with node-mysql2 and see if issue persist?

[caio-porto]

Just tried and same thing, still very slow.

[sidorares]

to me this indicates that the reason is outside of node-mysql ( network issues, dns resolution etc etc ). Strange though that other clients work fine

[caio-porto]

Not only other clients, but also all the other queries, that's why I'm sure it's not an outside problem.

[dougwilson]

Hi @caio-porto, I don't think I've ever heard of this issue before (and I even use this module on Windows servers in production). One of my first questions, to get it out of the way: how are you making your timing measurements? For example, what specific event are you using to start that timer and what even to end the timer? I only ask because your example does not include any code that would be performing time measurements, so I really just want to make sure that we're measuring the SQL time here and not the entire HTTP request cycle time.

[ZJONSSON]

Two suggestions:

Number of records returned

Is it possible this has to do with number of records returned, i.e. workbench has a default limit of 1000. If you add limit 1000 to your query does it perform better?

indices are type sensitive

If you are using indices you need to make sure that any terms in the query are the same type as the field itself as defined in the table. For example if idvehicle is a defined as numeric variable in the table but you search as string (i.e. put the search term in quotes), or idvehicle is a string in the DB but you search with a integer (i.e. unquoted number) then in both cases the index for idvehicle will not be used and a full tablescan will be performed.

[caio-porto]

@ZJONSSON You were right about the limit, that was very stupid, I didn't notice that using the workbench it was always returning the limit of 1000. I already knew about the limit, but it was really stupid to not see that the results were always 1000 rows. I also didn't notice that using the C# application, it was actually hanging after 2412 rows, I thought it had already finished.
Thank you everybody for the help, I really appreciate it. Sorry for the stupidity.

[dougwilson]

Hi @caio-porto, I'm glad to hear you figured it out :)!