node.js - CPU Higher than expected in Node running in docker -
i have vagrant machine running @ 33% cpu on mac (10.9.5) when nothing supposed happening. vm machine run kinematic. looking inside 1 of containers see 2 node (v0.12.2) processes running @ 3-4% cpu each.
root@49ab3ab54901:/usr/src# top -bc top - 03:11:59 8:31, 0 users, load average: 0.13, 0.18, 0.22 tasks: 7 total, 1 running, 6 sleeping, 0 stopped, 0 zombie %cpu(s): 0.2 us, 0.7 sy, 0.0 ni, 99.1 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st kib mem: 2051824 total, 1942836 used, 108988 free, 74572 buffers kib swap: 1466848 total, 18924 used, 1447924 free. 326644 cached mem pid user pr ni virt res shr s %cpu %mem time+ command 1 root 20 0 4332 672 656 s 0.0 0.0 0:00.10 /bin/sh -c node -e "require('./seed/seeder.js').seed().then(function (resp) { console.log('successfully seeded!'); pro+ 15 root 20 0 737320 81008 13452 s 0.0 3.9 0:32.57 node /usr/local/bin/nodemon app/api.js 33 root 20 0 4332 740 652 s 0.0 0.0 0:00.00 sh -c node app/api.js 34 root 20 0 865080 68952 14244 s 0.0 3.4 0:01.70 node app/api.js 83 root 20 0 20272 3288 2776 s 0.0 0.2 0:00.11 bash 18563 root 20 0 20248 3152 2840 s 0.0 0.2 0:00.11 bash 18575 root 20 0 21808 2308 2040 r 0.0 0.1 0:00.00 top -bc i went on , runned node --prof , processed log node-tick-processor. looks 99.3% of cpu used in syscall : (for full output see http://pastebin.com/6qgfufwk )
root@d6d78487e1ec:/usr/src# node-tick-processor isolate-0x26c0180-v8.log ... statistical profiling result isolate-0x26c0180-v8.log, (130664 ticks, 0 unaccounted, 0 excluded). ... [c++]: ticks total nonlib name 129736 99.3% 99.3% syscall 160 0.1% 0.1% node::contextifyscript::new(v8::functioncallbackinfo<v8::value> const&) 124 0.1% 0.1% __write 73 0.1% 0.1% __xstat 18 0.0% 0.0% v8::internal::heap::allocatefixedarray(int, v8::internal::pretenureflag) 18 0.0% 0.0% node::stat(v8::functioncallbackinfo<v8::value> const&) 17 0.0% 0.0% __lxstat 16 0.0% 0.0% node::read(v8::functioncallbackinfo<v8::value> const&) ... 1 0.0% 0.0% __fxstat 1 0.0% 0.0% _io_default_xsputn [gc]: ticks total nonlib name 22 0.0% [bottom (heavy) profile]: note: percentage shows share of particular caller in total amount of parent calls. callers occupying less 2.0% not shown. ticks parent name 129736 99.3% syscall [top down (heavy) profile]: note: callees occupying less 0.1% not shown. inclusive self name ticks total ticks total 129736 99.3% 129736 99.3% syscall 865 0.7% 0 0.0% function: ~<anonymous> node.js:27:10 864 0.7% 0 0.0% lazycompile: ~startup node.js:30:19 851 0.7% 0 0.0% lazycompile: ~module.runmain module.js:499:26 799 0.6% 0 0.0% lazycompile: module._load module.js:273:24 795 0.6% 0 0.0% lazycompile: ~module.load module.js:345:33 794 0.6% 0 0.0% lazycompile: ~module._extensions..js module.js:476:37 792 0.6% 0 0.0% lazycompile: ~module._compile module.js:378:37 791 0.6% 0 0.0% function: ~<anonymous> /usr/src/app/api.js:1:11 791 0.6% 0 0.0% lazycompile: ~require module.js:383:19 791 0.6% 0 0.0% lazycompile: ~module.require module.js:362:36 791 0.6% 0 0.0% lazycompile: module._load module.js:273:24 788 0.6% 0 0.0% lazycompile: ~module.load module.js:345:33 786 0.6% 0 0.0% lazycompile: ~module._extensions..js module.js:476:37 783 0.6% 0 0.0% lazycompile: ~module._compile module.js:378:37 644 0.5% 0 0.0% function: ~<anonymous> /usr/src/app/api.authentication.js:1:11 627 0.5% 0 0.0% ...
a strace resulted in nothing abnormal:
% time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 54.51 0.001681 76 22 clone 17.28 0.000533 4 132 epoll_ctl 16.80 0.000518 24 22 wait4 6.39 0.000197 2 110 66 stat 5.03 0.000155 1 176 close 0.00 0.000000 0 176 read 0.00 0.000000 0 88 write 0.00 0.000000 0 44 rt_sigaction 0.00 0.000000 0 88 rt_sigprocmask 0.00 0.000000 0 22 rt_sigreturn 0.00 0.000000 0 66 ioctl 0.00 0.000000 0 66 socketpair 0.00 0.000000 0 88 epoll_wait 0.00 0.000000 0 22 pipe2 ------ ----------- ----------- --------- --------- ---------------- 100.00 0.003084 1122 66 total and other node process:
% time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 0.00 0.000000 0 14 epoll_wait ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000000 14 total am missing something? wonder if virtualbox's or docker's layers consuming 4%.
when have few containers 2 processes running @ 4%, adds quickly.
Comments
Post a Comment