Problem while doing stress testing on TCP server

[seallee]

Hi all,
We are using node.js(version 0.6.11) on CentOS(version 6.0) to build a TCP server. While I doing the stress testing, I found a problem:

The CPU usage of node.js deamon is only about 5~6% when less than 1150 connection established. But it rises to 100%
rapidly when only a few more connection established.

Does anyone know why it works like that? Is it a bug in node.js?

Here is the demo code:

var net = require("net");
var server = net.createServer(function(socket)
{
    socket.setEncoding("utf8");
    socket.on('close',
        function()
        {
            console.log('close');
        });
    socket.on('disconnect',
        function()
        {
            console.log('disconnect');
        });
    socket.on("data", function(data)
        {
//          console.log("recv");            
        });
});

server.listen(8080, "192.168.2.105");
console.log("Server on 8080");

[bnoordhuis]

I can think of a couple of reasons. Can you post the output of uname -a and ulimit -a? Have you tried tracing your app with time and strace -c? It might give some insight in where your application is spending its CPU time, user or kernel mode and (for kernel mode) in what syscalls.

[seallee]

Ok, here is the information.

[root@itools-master ~]# uname -a
Linux itools-master.local 2.6.32-71.el6.x86_64 #1 SMP Fri May 20 03:51:51 BST 2011 x86_64 x86_64 x86_64 GNU/Linux

[root@itools-master ~]# 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) 15941
max locked memory (kbytes, -l) 64
max memory size (kbytes, -m) unlimited
open files (-n) 1024
pipe size (512 bytes, -p) 8
POSIX message queues (bytes, -q) 819200
real-time priority (-r) 0
stack size (kbytes, -s) 10240
cpu time (seconds, -t) unlimited
max user processes (-u) 1024
virtual memory (kbytes, -v) unlimited
file locks (-x) unlimited

[seallee]

1000 connection for time and strace -c:

real 1m30.174s
user 0m0.864s
sys 0m0.743s

time seconds usecs/call calls errors syscall

---

89.67 0.350389 13 27082 epoll_wait
3.88 0.015151 1 20995 2 futex
3.69 0.014429 0 31028 read
1.48 0.005794 0 54167 clock_gettime
0.59 0.002310 2 1025 close
0.46 0.001815 1 1974 974 accept4
0.06 0.000240 0 1002 epoll_ctl
0.06 0.000231 0 1001 setsockopt
0.05 0.000189 0 1001 write
0.03 0.000112 2 47 22 open
0.01 0.000046 1 34 brk
0.01 0.000034 3 12 munmap
0.00 0.000000 0 5 3 stat
0.00 0.000000 0 24 fstat
0.00 0.000000 0 4 lstat
0.00 0.000000 0 128 mmap
0.00 0.000000 0 39 mprotect
0.00 0.000000 0 7 rt_sigaction
0.00 0.000000 0 1 rt_sigprocmask
0.00 0.000000 0 2 1 ioctl
0.00 0.000000 0 1 1 access
0.00 0.000000 0 1 socket
0.00 0.000000 0 1 bind
0.00 0.000000 0 1 listen
0.00 0.000000 0 1 clone
0.00 0.000000 0 1 execve
0.00 0.000000 0 4 fcntl
0.00 0.000000 0 2 getcwd
0.00 0.000000 0 1 readlink
0.00 0.000000 0 2 getrlimit
0.00 0.000000 0 1 getuid
0.00 0.000000 0 1 getgid
0.00 0.000000 0 1 geteuid
0.00 0.000000 0 1 getegid
0.00 0.000000 0 1 statfs
0.00 0.000000 0 1 arch_prctl
0.00 0.000000 0 1 gettid
0.00 0.000000 0 1 set_tid_address
0.00 0.000000 0 1 set_robust_list
0.00 0.000000 0 1 eventfd2
0.00 0.000000 0 1 epoll_create1

---

100.00 0.390740 139604 1003 total

[seallee]

1200 connection :

real 1m26.742s
user 0m10.045s
sys 0m25.180s

time seconds usecs/call calls errors syscall

---

58.11 0.138323 0 597602 epoll_wait
18.48 0.043980 0 588392 587192 accept4
14.64 0.034838 0 1195207 clock_gettime
4.36 0.010380 0 21067 2 futex
3.01 0.007168 0 34018 read
0.69 0.001642 1 1223 close
0.35 0.000843 1 1199 write
0.25 0.000601 1 1202 epoll_ctl
0.07 0.000163 0 1201 setsockopt
0.04 0.000090 2 39 mprotect
0.00 0.000000 0 47 22 open
0.00 0.000000 0 5 3 stat
0.00 0.000000 0 24 fstat
0.00 0.000000 0 4 lstat
0.00 0.000000 0 116 mmap
0.00 0.000000 0 12 munmap
0.00 0.000000 0 31 brk
0.00 0.000000 0 7 rt_sigaction
0.00 0.000000 0 1 rt_sigprocmask
0.00 0.000000 0 2 1 ioctl
0.00 0.000000 0 1 1 access
0.00 0.000000 0 1 socket
0.00 0.000000 0 1 bind
0.00 0.000000 0 1 listen
0.00 0.000000 0 1 clone
0.00 0.000000 0 1 execve
0.00 0.000000 0 4 fcntl
0.00 0.000000 0 2 getcwd
0.00 0.000000 0 1 readlink
0.00 0.000000 0 2 getrlimit
0.00 0.000000 0 1 getuid
0.00 0.000000 0 1 getgid
0.00 0.000000 0 1 geteuid
0.00 0.000000 0 1 getegid
0.00 0.000000 0 1 statfs
0.00 0.000000 0 1 arch_prctl
0.00 0.000000 0 1 gettid
0.00 0.000000 0 1 set_tid_address
0.00 0.000000 0 1 set_robust_list
0.00 0.000000 0 1 eventfd2
0.00 0.000000 0 1 epoll_create1

---

100.00 0.238028 2441425 587221 total

[bnoordhuis]

With how many concurrent connections are you testing it? According to the output of uname -a, the number of open files is capped at 1024. What happens if you set e.g. uname -n 16384?

[seallee]

I found that I have made a silly mistake, I am sorry that I ignored to ulimit the number of open files. I will try it later.

[bnoordhuis]

No problem. Does that mean I can close the issue?

[seallee]

Yeah, thank you for your help. I will close it.