CPU Higher than expected in Node running in docker

Question

I have a vagrant machine running at 33% CPU on my Mac (10.9.5) when nothing is supposed to be happening. The VM machine is run by Kinematic. Looking inside one of the containers I see 2 node (v0.12.2) processes running at 3-4% CPU each.

root@49ab3ab54901:/usr/src# top -bc
top - 03:11:59 up  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 and runned a node --prof and processed the log with node-tick-processor. It looks like that 99.3% of CPU is used in the syscall : (for full output see http://pastebin.com/6qgFuFWK )

root@d6d78487e1ec:/usr/src# node-tick-processor isolate-0x26c0180-v8.log
...
Statistical profiling result from 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 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
  129736   99.3%  syscall


 [Top down (heavy) profile]:
  Note: callees occupying less than 0.1% are 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 the 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 I missing something? I wonder if it is VirtualBox's or Docker's layers consuming 4%.

When you have a few containers with 2 processes running at 4%, it adds up quickly.