Node API taking 100% CPU, node-tick-processor output looks cryptic
Problem
I have a node API which normally handles traffic quite well. However, in our peak times, it gets into this state where it starts using 100% CPU and needs to be restarted. After restarting, it returns to a regular state for the next few days.
Using a load testing site, I have been able to reproduce this issue. The request I am load testing is extremely simple, so I fear the problem is in a third-party library I'm using.
I'm new to debugging node and I'm not sure what to make of the following output from node-tick-processor. Can anyone decipher this?
Update: I'm running node v0.10.4
[Unknown]:
ticks total nonlib name
5 0.0%
[Shared libraries]:
ticks total nonlib name
11943 49.1% 0.0% /lib64/libc-2.12.so
10754 44.2% 0.0% /usr/local/bin/node
314 1.3% 0.0% /lib64/libpthread-2.12.so
50 0.2% 0.0% 7fff318b4000-7fff318b5000
5 0.0% 0.0% /lib64/libm-2.12.so
3 0.0% 0.0% /usr/lib64/libstdc++.so.6.0.17
[JavaScript]:
ticks total nonlib name
40 0.2% 3.2% LazyCompile: ~read tls.js:397
36 0.1% 2.8% LazyCompile: *EventEmitter.addListener events.js:126
29 0.1% 2.3% LazyCompile: *Readable.read _stream_readable.js:226
[Bottom up (heavy) profile]:
Note: percentage shows a share of a particular caller in the total
amount of its parent calls.
Callers occupying less than 2.0% are not shown.
ticks parent name
11943 49.1% /lib64/libc-2.12.so
10754 44.2% /usr/local/bin/node
8270 76.9% LazyCompile: *use tls.js:222
5162 62.4% LazyCompile: ~read tls.js:397
5074 98.3% LazyCompile: *Readable.read _stream_readable.js:226
3396 66.9% LazyCompile: ~write tls.js:315
3396 100.0% LazyCompile: *Writable.write _stream_writable.js:155
1063 20.9% LazyCompile: *write tls.js:315
1063 100.0% LazyCompile: *Writable.write _stream_writable.js:155
370 7.3% LazyCompile: *Writable.write _stream_writable.js:155
370 100.0% LazyCompile: ~write _stream_readable.js:546
186 3.7% LazyCompile: ~callback tls.js:753
180 96.8% LazyCompile: *onclienthello tls.js:748
6 3.2% LazyCompile: ~onclienthello tls.js:748
2417 29.2% LazyCompile: *read tls.js:397
2417 100.0% LazyCompile: *Readable.read _stream_readable.js:226
2320 96.0% LazyCompile: *Writable.write _stream_writable.js:155
2315 99.8% LazyCompile: ~write _stream_readable.js:546
57 2.4% LazyCompile: ~callback tls.js:753
57 100.0% LazyCompile: *onclienthello tls.js:748
691 8.4% LazyCompile: *Readable.read _stream_readable.js:226
675 97.7% LazyCompile: *write tls.js:315
675 100.0% LazyCompile: *Writable.write _stream_writable.js:155
674 99.9% LazyCompile: ~write _stream_readable.js:546
Solution
For those still coming here, this was caused somewhere in the SSL-handling code in a system node module. I re-configured my stack to do SSL termination at nginx, and use basic HTTP handling at the node level, and this problem went away entirely.
Discussion
View additional discussion.