Im trying to track down why my nodejs app all a sudden uses 100% cpu. The app has around 50 concurrent connections and is running on a ec2 micro instance.
Below is the output of: strace -c node server.js
^C% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
87.32 0.924373 8 111657 epoll_wait
6.85 0.072558 3 22762 pread
2.55 0.026965 0 146179 write
0.92 0.009733 0 108434 1 futex
0.44 0.004661 0 82010 7 read
0.44 0.004608 0 223317 clock_gettime
0.31 0.003244 0 172467 gettimeofday
0.31 0.003241 35 93 brk
0.20 0.002075 0 75233 3 epoll_ctl
0.19 0.002052 0 23850 11925 accept4
0.19 0.001997 0 12302 close
0.19 0.001973 7 295 mmap
0.06 0.000617 4 143 munmap
And here is the output of: node-tick-processor
[Top down (heavy) profile]:
Note: callees occupying less than 0.1% are not shown.
inclusive self name
ticks total ticks total
669160 97.4% 669160 97.4% /lib/x86_64-linux-gnu/libc-2.15.so
4834 0.7% 28 0.0% LazyCompile: *Readable.push _stream_readable.js:116
4750 0.7% 10 0.0% LazyCompile: *emitReadable _stream_readable.js:392
4737 0.7% 19 0.0% LazyCompile: *emitReadable_ _stream_readable.js:407
1751 0.3% 7 0.0% LazyCompile: ~EventEmitter.emit events.js:53
1081 0.2% 2 0.0% LazyCompile: ~<anonymous> _stream_readable.js:741
1045 0.2% 1 0.0% LazyCompile: ~EventEmitter.emit events.js:53
960 0.1% 1 0.0% LazyCompile: *<anonymous> /home/ubuntu/node/node_modules/redis/index.js:101
948 0.1% 11 0.0% LazyCompile: RedisClient.on_data /home/ubuntu/node/node_modules/redis/index.js:541
This is my first time debugging a node app. Are there any conclusions that can be drawn from the above debug output? Where could the error be?
Edit
My node version: v0.10.25
Edit 2
After updating node to: v0.10.33
Here is the output
^C% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
91.81 1.894522 8 225505 45 epoll_wait
3.58 0.073830 1 51193 pread
1.59 0.032874 0 235054 2 write
0.98 0.020144 0 1101789 clock_gettime
0.71 0.014658 0 192494 1 futex
0.57 0.011764 0 166704 21 read
Seems like Node JS v0.10.25 bug with event loop, look here.
Note, from this github pull request:
If the same file description is open in two different processes, then closing the file descriptor is not sufficient to deregister it from the epoll instance (as described in epoll(7)), resulting in spurious events that cause the event loop to spin repeatedly. So always explicitly deregister it.
So as solution you can try update your OS or update Node JS.
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With