Nodejs delay/interrupt in for loop

Question

I want to write a logger (please no comments why and "use ...") But I am confused with the nodejs (event?) loop/forEach.

As example:

for(var i = 0; i<100; i++){
  process.stdout.write(Date.now().toString() + "\n", "utf8");
};

output as: 1466021578453, 1466021578453, 1466021578469, 1466021578469

Questions: Where comes the Delay from 16ms; And how can I prevent that?

EDIT: Windows 7, x64; (Delay on Ubuntu 15, max 2ms)

Answer 1

sudo ltrace -o outlog node myTest.js

This is likely more than you want. The call Date.now() translates into on my machine is clock_gettime. You want to look at the stuff between subsequent calls to clock_gettime. You're also writing out to STDOUT, each time you do that there is overhead. You can run the whole process under ltrace to see what's happening and get a summary with -c.

For me, it runs in 3 ms when not running it under ltrace.

% time     seconds  usecs/call     calls      function
------ ----------- ----------- --------- --------------------
 28.45    6.629315         209     31690 memcpy
 26.69    6.219529         217     28544 memcmp
 16.78    3.910686         217     17990 free
  9.73    2.266705         214     10590 malloc
  2.92    0.679971         220      3083 _Znam
  2.86    0.666421         216      3082 _ZdaPv
  2.55    0.593798         206      2880 _ZdlPv
  2.16    0.502644         211      2378 _Znwm
  1.09    0.255114         213      1196 strlen
  0.69    0.161741         215       750 pthread_getspecific
  0.67    0.155609         209       744 memmove
  0.57    0.133857         212       631 _ZNSo6sentryC1ERSo
  0.57    0.133344         226       589 pthread_mutex_lock
  0.52    0.121342         206       589 pthread_mutex_unlock
  0.46    0.106343         207       512 clock_gettime
  0.40    0.093022         204       454 memset
  0.39    0.089857         216       416 _ZNSt9basic_iosIcSt11char_traitsIcEE4initEPSt15basic_streambufIcS1_E
  0.22    0.050741         195       259 strcmp
  0.20    0.047454         228       208 _ZNSt8ios_baseC2Ev
  0.20    0.047236         227       208 floor
  0.19    0.044603         214       208 _ZNSt6localeC1Ev
  0.19    0.044536         212       210 _ZNSs4_Rep10_M_destroyERKSaIcE
  0.19    0.044200         212       208 _ZNSt8ios_baseD2Ev

I'm not sure why there are 31,690 memcpy's in there and 28544 memcmp. That seems a bit excessive but perhaps that just the JIT start up cost, as for the runtime cost, you can see there are 512 calls to clock_gettime. No idea why there at that many calls either, but you can see 106ms lost in clock_gettime. Good luck with it.