8

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
Alosyius
  • 8,771
  • 26
  • 76
  • 120

1 Answers1

2

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.

Maksym
  • 4,434
  • 4
  • 27
  • 46
  • I've updated my servers and will give it a try during the date. I'll post status here later when I know more. – Alosyius Nov 18 '14 at 07:03
  • thanks, this bug, really interesting and weird thing – Maksym Nov 18 '14 at 07:39
  • One of the instances started to go crazy again and hit 100 cpu. I've started another `strace -c node server.js` ill be back with the results as soon as it hits 100 again. – Alosyius Nov 18 '14 at 08:16
  • Im not sure if this could have to do with that I am using mysql and redis, the connections are shared amongst all sockets. – Alosyius Nov 18 '14 at 10:46
  • Yeah, it seems like your code issue then, see http://www.kennynet.co.uk/2014/07/07/nodejs-and-blocked-io/ . – Maksym Nov 18 '14 at 10:47
  • However here: http://stackoverflow.com/questions/8946915/redis-and-node-js-and-socket-io-questions it says one should use a single connection for a bunch of clients. Not sure what to believe :/ – Alosyius Nov 18 '14 at 10:49
  • Maybe the redis connection is fine with just a 2-3 connections. But that I should pool the mysql connection? – Alosyius Nov 18 '14 at 10:51
  • That's described ,why you have this issue only with around 50 concurrent connections. Seems like your thread getting blocked in this operations. – Maksym Nov 18 '14 at 10:51
  • So the problem is more likely to be with MySQL? – Alosyius Nov 18 '14 at 10:53
  • Yeah, seems like, but it's quite difficult to answer without your code. – Maksym Nov 18 '14 at 10:59