TypeError: Cannot call method 'end' of undefined

[mogongzi]

Hi all,

I used connection pool for my app for inserting records concurrently. There is the very strange issue when I use JMeter for simulating concurrency. If the threads less than 400, the app works fine. However, if I set thread to 1000, I got the following err:
[2013-06-18 15:27:52.628] [ERROR] syslog - SQL error: Error: connect EMFILE
[2013-06-18 15:27:52.629] [ERROR] syslog - SQL source: INSERT INTO CellDataTemp (Type, MCC, MNC, LAC, Ci, RSSI, GPS_Lat, GPS_Lon, GPS_Uncert, Source) VALUES (1,),(1, 460, 0, 6339, 41169, -75, 31.24599429, 121.60113167, 15, 1

[2013-06-18 15:27:52.628] [ERROR] syslog - SQL error: Error: connect EMFILE
[2013-06-18 15:27:52.629] [ERROR] syslog - SQL source: INSERT INTO DataTemp (ID, ID1, ID2, ID3, ID4, ID5, ID6, ID7, ID8, ID9) VALUES (1,),(1, 460, 0, 6339, 41169, -75, 31.24599429, 121.60113167, 15, 1

TypeError: Cannot call method 'end' of undefined
at /home/usr/nodeapps/agps/collectorhttpserver.js:55:24
at Handshake._callback (/home/usr/node_modules/mysql/lib/Pool.js:35:9)
at Handshake.Sequence.end (/home/usr/node_modules/mysql/lib/protocol/sequences/Sequence.js:66:24)
at Protocol.handleNetworkError (/home/usr/node_modules/mysql/lib/protocol/Protocol.js:238:14)
at Connection._handleNetworkError (/home/usr/node_modules/mysql/lib/Connection.js:157:18)
at Socket.EventEmitter.emit (events.js:117:20)
at net.js:426:14
at process._tickCallback (node.js:415:13)

My code is like below:
pool.getConnection(function(err, connection) {
connection.query( 'insert into table(x,x,x) values(x,x,x)', function(err, rows) {
connection.end();
});
});

It seems when the connection.end executed, it actually not created. I don’t know whether the issue caused by some optimized skills by V8 itself. Could anyone give me some helps?

[kai-koch]

Your SQL-Query is wrong, therefor an error is given, which you do not catch or handle.

INSERT INTO CellDataTemp (Type, MCC, MNC, LAC, Ci, RSSI, GPS_Lat, GPS_Lon, GPS_Uncert, Source)
 VALUES (1,),(1, 460, 0, 6339, 41169, -75, 31.24599429, 121.60113167, 15, 1

The first row (1,) in the VALUES Part of the query does not match the field count.

[mogongzi]

Hi Kai,

Thanks for your reply! I think the sql statement recorded here is not correct. I had the correct sql but still got the same problem. I think the issue is related to EMFILE error of MySQL. I'm trying to figure out the root cause.

Ryan

[mogongzi]

I changed the log information, please see the detail below:

[2013-06-19 09:33:52.863] [ERROR] syslog - SQL error code Level 1:EMFILE
[2013-06-19 09:33:52.864] [ERROR] syslog - { [Error: connect EMFILE]
code: 'EMFILE',
errno: 'EMFILE',
syscall: 'connect',
fatal: true }
Error: connect EMFILE
at errnoException (net.js:884:11)
at connect (net.js:747:19)
at net.js:825:9
at dns.js:72:18
at process._tickCallback (node.js:415:13)
--------------------
at Handshake.Sequence (/home/usr/node_modules/mysql/lib/protocol/sequences/Sequence.js:15:20)
at new Handshake (/home/usr/node_modules/mysql/lib/protocol/sequences/Handshake.js:9:12)
at Protocol.handshake (/home/usr/node_modules/mysql/lib/protocol/Protocol.js:42:50)
at Connection.connect (/home/usr/node_modules/mysql/lib/Connection.js:73:18)
at Pool.getConnection (/home/usr/node_modules/mysql/lib/Pool.js:30:16)
at collectCELLData (/home/usr/nodeapps/agps/collectorhttpserver.js:51:10)
at IncomingMessage. (/home/usr/nodeapps/agps/collectorhttpserver.js:131:25)
at IncomingMessage.EventEmitter.emit (events.js:92:17)
at _stream_readable.js:910:16
at process._tickCallback (node.js:415:13)
[2013-06-19 09:33:52.875] [ERROR] syslog - SQL source: INSERT INTO TempTable (ID1, ID2, ID3, ID4, ID5, ID6, ID7, ID8, ID9, ID10) VALUES (1, a, 0, b, 41859, -75, 31.24635325, 121.60232342, 15, 1 ),(1, a, 0, b, 41859, -75, 31.24635325, 121.60232342, 15, 1 ),(1, a, 0, b, 41859, -75, 31.24628641, 121.60211745, 15, 1 ),(1, a, 0, b, 41859, -75, 31.24628641, 121.60211745, 15, 1 ),(1, a, 0, b, 41859, -75, 31.24623195, 121.60190694, 15, 1 ),(1, a, 0, b, 41859, -75, 31.24623195, 121.60190694, 15, 1 ),(1, a, 0, b, 41859, -75, 31.24617604, 121.60170804, 15, 1 ),(1, a, 0, b, 41859, -75, 31.24617604, 121.60170804, 15, 1 ),(1, a, 0, b, 41169, -75, 31.24617604, 121.60170804, 15, 1 ),(1, a, 0, b, 41169, -75, 31.24617604, 121.60170804, 15, 1 ),(1, a, 0, b, 41169, -67, 31.24617604, 121.60170804, 15, 1 ),(1, a, 0, b, 41169, -67, 31.24617604, 121.60170804, 15, 1 ),(1, a, 0, b, 41169, -67, 31.24611360, 121.60149859, 15, 1 ),(1, a, 0, b, 41169, -67, 31.24611360, 121.60149859, 15, 1 ),(1, a, 0, b, 41169, -75, 31.24611360, 121.60149859, 15, 1 ),(1, a, 0, b, 41169, -75, 31.24611360, 121.60149859, 15, 1 ),(1, a, 0, b, 41169, -75, 31.2a5325, 121.60131145, 15, 1 ),(1, a, 0, b, 41169, -75, 31.2a5325, 121.60131145, 15, 1 ),(1, a, 0, b, 41169, -75, 31.24599429, 121.60113167, 15, 1 ),(1, a, 0, b, 41169, -75, 31.24599429, 121.60113167, 15, 1
)

[mogongzi]

I changed the MySQL configuration open files from 1024 to 16384. However, sometimes the issue still happened when the concurrency level bigger than 1000 on JMeter:

mysql@testmachine:~$ ulimit -a
core file size (blocks, -c) 0
data seg size (kbytes, -d) unlimited
scheduling priority (-e) 0
file size (blocks, -f) unlimited
pending signals (-i) 14480
max locked memory (kbytes, -l) 64
max memory size (kbytes, -m) unlimited
open files (-n) 16384
pipe size (512 bytes, -p) 8
POSIX message queues (bytes, -q) 819200
real-time priority (-r) 0
stack size (kbytes, -s) 8192
cpu time (seconds, -t) unlimited
max user processes (-u) 14480
virtual memory (kbytes, -v) unlimited
file locks (-x) unlimited

[kai-koch]

I am not sure this is a mysql problem.
Please check, if http://stackoverflow.com/questions/10355501/connect-emfile-error-in-node-js and http://stackoverflow.com/questions/34588/how-do-i-change-the-number-of-open-files-limit-in-linux can help you with your problem.
My guess is that simply raising the open file limit in mysql won't do, when the OS does not allow more open files for the process that runs mysql.

[dresende]

Yes, changing on mysql probably won't do. If you're not changing the limit globally (and rebooting after it), don't forget that changing limit in a shell won't change in the system. If you're on a Linux machine, you should be able to do command below when you see problems with the process and see how many open files there are:

ls /proc/PID_OF_MYSQL/fd | wc -l

------- edited --------
The PID should be of the process that's having the problem, whether it's mysql or a node program..

[mogongzi]

Hi dresende,

Thanks for your help! I used the command for monitoring what was really happened when the error occurred. It seems the root cause is the limitation is caused by the node program. Because MySQL and my node program on the different machine, I only changed the limitation on MySQL machine. So, after I changed the value on node program one, the issue fixed.

Also thanks kai-koch's help!

Thanks you guys!

Regards,

Ryan