Nodejs Verzögerung/Interrupt in for Schleife

Question

Ich möchte einen Logger schreiben (bitte keine Kommentare warum und "verwenden ...") Aber ich bin verwirrt mit der Nodejs (Event?) Schleife/forEach.

Als Beispiel:

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

Ausgabe als: 1466021578453, 1466021578453, 1466021578469, 1466021578469

Fragen: Wo die Verzögerung von 16 ms kommt; Und wie kann ich das verhindern?

BEARBEITEN: Windows 7, x64; (Delay auf Ubuntu 15, max 2ms)

Answer 1

sudo ltrace -o outlog node myTest.js

Dies ist wahrscheinlich mehr als Sie wollen. Der Anruf Date.now() übersetzt in meine Maschine ist clock_gettime. Sie möchten zwischen den nachfolgenden Aufrufen an clock_gettime suchen. Sie schreiben auch auf STDOUT, jedes Mal, wenn Sie das tun, ist Overhead. Sie können den gesamten Prozess unter ltrace ausführen, um zu sehen, was passiert und eine Zusammenfassung mit -c erhalten.

Für mich läuft es in 3 ms, wenn es nicht unter ltrace läuft.

% 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 

Ich bin mir nicht sicher, warum es 31.690 memcpy's drin und 28544 memcmp gibt. Das scheint ein bisschen übertrieben, aber vielleicht nur die JIT-Startkosten, wie für die Laufzeitkosten, können Sie sehen, es gibt 512 Anrufe zu clock_gettime. Keine Ahnung, warum dort auch so viele Anrufe, aber man kann 106ms verloren in clock_gettime sehen. Viel Glück damit.