Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

NodeJS 100% cpu usage - epoll_wait

Tags:

node.js

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
like image 632
Alosyius Avatar asked Nov 17 '14 14:11

Alosyius


Video Answer


1 Answers

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.

like image 99
Maksym Avatar answered Sep 17 '22 14:09

Maksym