Jak zmierzyć czas wykonania kodu JavaScript za pomocą wywołań zwrotnych?

319

Mam kawałek kodu JavaScript, który wykonuję za pomocą node.jsinterpretera.

for(var i = 1; i < LIMIT; i++) {
  var user = {
    id: i,
    name: "MongoUser [" + i + "]"
  };
  db.users.save(user, function(err, saved) {
    if(err || !saved) {
      console.log("Error");
    } else {
      console.log("Saved");
    }
  });
}

Jak mogę zmierzyć czas potrzebny na operacje wstawiania bazy danych? Mógłbym obliczyć różnicę wartości dat przed i przed tym fragmentem kodu, ale byłoby to niepoprawne z powodu asynchronicznej natury kodu.

Stormshadow
źródło
8
Wystarczy przeczytać godzinę rozpoczęcia przed wywołaniem db oraz godzinę zakończenia WEWNĄTRZ wywołania zwrotnego.
BFil
Istnieje możliwość, że czas, w którym DB kończy wstawianie i czas wywołania zwrotnego, nie jest taki sam, a to spowodowałoby błąd w pomiarze?
Stormshadow
1
Nie, nie powinieneś się tym przejmować, jeśli kod biblioteki db jest dobrze zaprojektowany i nie obsługuje żadnych innych operacji przed uruchomieniem wywołania zwrotnego, powinieneś uzyskać dobrą miarę. Możesz także profilować wstawienie, umieszczając znaczniki czasu w kodzie biblioteki, w którym wstawianie jest faktycznie wykonywane, zamiast własnego, ale znowu nie martwię się o to
BFil
Poleciłbym wypróbowanie NodeTime, który wydaje się być odpowiedni do tego, co próbujesz zrobić.
Julian Knight
Napisałem, timerlogktóry jest podobny, console.time()ale z dodatkowymi funkcjami; github.com/brillout/timerlog
brillout

Odpowiedzi:

718

Użyj Node.js console.time()i console.timeEnd():

var i;
console.time("dbsave");

for(i = 1; i < LIMIT; i++){
    db.users.save({id : i, name : "MongoUser [" + i + "]"}, end);
}

end = function(err, saved) {
    console.log(( err || !saved )?"Error":"Saved");
    if(--i === 1){console.timeEnd("dbsave");}
};
użytkownik2362662
źródło
31
Czyste i wbudowane rozwiązanie dla węzła.
Behlül Uçar,
45
> Chcę wiedzieć, jak zmierzyć czas potrzebny na te operacje wstawiania db. --- console.timeEnd („dbsave”) po prostu wyświetla dane wyjściowe do konsolidacji taktowania. Nie możesz tego dalej używać i jest mniej elastyczny. Jeśli potrzebujesz rzeczywistej wartości taktowania, jak w pierwotnym pytaniu, nie możesz użyć console.timeEnd ("dbsave")
gogaman
@ gogaman jest to dobry punkt, ponieważ nie można przechwycić danych wyjściowych z console.timeEnd (). Być może przydatne może być przesłanie danych wyjściowych do pliku i wykorzystanie ich stamtąd?
Doug Molineux,
5
Jaka jest zatem różnica między console.time () i process.hrtime () w poniższej odpowiedzi?
żółty święty
3
Warto dodać notatkę, że czas wykonania jest następnie drukowany, tak aby teraz nowi użytkownicy.
janko-m
208

Jest do tego zaprojektowana metoda. Sprawdź process.hrtime (); .

Zasadniczo umieszczam to na górze mojej aplikacji.

var start = process.hrtime();

var elapsed_time = function(note){
    var precision = 3; // 3 decimal places
    var elapsed = process.hrtime(start)[1] / 1000000; // divide by a million to get nano to milli
    console.log(process.hrtime(start)[0] + " s, " + elapsed.toFixed(precision) + " ms - " + note); // print message + time
    start = process.hrtime(); // reset the timer
}

Następnie używam go, aby zobaczyć, jak długo zajmują funkcje. Oto podstawowy przykład, który drukuje zawartość pliku tekstowego o nazwie „output.txt”:

var debug = true;
http.createServer(function(request, response) {

    if(debug) console.log("----------------------------------");
    if(debug) elapsed_time("recieved request");

    var send_html = function(err, contents) {
        if(debug) elapsed_time("start send_html()");
        response.writeHead(200, {'Content-Type': 'text/html' } );
        response.end(contents);
        if(debug) elapsed_time("end send_html()");
    }

    if(debug) elapsed_time("start readFile()");
    fs.readFile('output.txt', send_html);
    if(debug) elapsed_time("end readFile()");

}).listen(8080);

Oto szybki test, który można uruchomić w terminalu (powłoka BASH):

for i in {1..100}; do echo $i; curl http://localhost:8080/; done
D.Deriso
źródło
3
czy w jakikolwiek sposób przewyższa to rozwiązanie console.time?
scravy
31
Tak, jest o wiele bardziej precyzyjny i możesz zapisać wynik w zmiennej
Dallas Clark
Ten działa dla mnie, ponieważ chciałem kilka razy zadzwonić do timera
tbh__
2
Dlaczego dzwonisz process.hrtime(start)dwa razy? Czy ma to jakiś szczególny powód?
Sohail Si
1
process.hrtime ([time]), gdzie time jest parametrem opcjonalnym, który musi być wynikiem poprzedniego wywołania process.hrtime (), aby różnić się od bieżącego czasu. Daje różnicę między bieżącym połączeniem a poprzednim połączeniem hrtime.
Nilesh Jain
72

Wywołanie console.time('label')spowoduje zapisanie aktualnego czasu w milisekundach, a później wywołanie console.timeEnd('label')wyświetli czas od tego momentu.

Czas w milisekundach zostanie automatycznie wydrukowany obok etykiety, więc nie musisz wykonywać osobnego połączenia z plikiem console.log, aby wydrukować etykietę:

console.time('test');
//some code
console.timeEnd('test'); //Prints something like that-> test: 11374.004ms

Aby uzyskać więcej informacji, zobacz dokumentację programistów Mozilli naconsole.time .

jfcorugedo
źródło
Co to dodaje do zaakceptowanej odpowiedzi ?
Dan Dascalescu
1
Zaakceptowana odpowiedź została zmodyfikowana po mojej odpowiedzi na użycie mojego kodu
jfcorugedo
24

Zaskoczony, nikt jeszcze nie wspomniał o nowych wbudowanych bibliotekach:

Dostępne w Węzle> = 8,5 i powinny być w Modern Browers

https://developer.mozilla.org/en-US/docs/Web/API/Performance

https://nodejs.org/docs/latest-v8.x/api/perf_hooks.html#

Węzeł 8.5 ~ 9.x (Firefox, Chrome)

// const { performance } = require('perf_hooks'); // enable for node
const delay = time => new Promise(res=>setTimeout(res,time))
async function doSomeLongRunningProcess(){
  await delay(1000);
}
performance.mark('A');
(async ()=>{
  await doSomeLongRunningProcess();
  performance.mark('B');
  performance.measure('A to B', 'A', 'B');
  const measure = performance.getEntriesByName('A to B')[0];
  // firefox appears to only show second precision.
  console.log(measure.duration);
  performance.clearMeasures(); // apparently you should remove entries...
  // Prints the number of milliseconds between Mark 'A' and Mark 'B'
})();

https://repl.it/@CodyGeisler/NodeJsPerformanceHooks

Węzeł 10.x

https://nodejs.org/docs/latest-v10.x/api/perf_hooks.html

const { PerformanceObserver, performance } = require('perf_hooks');
const delay = time => new Promise(res => setTimeout(res, time))
async function doSomeLongRunningProcess() {
    await delay(1000);
}
const obs = new PerformanceObserver((items) => {
    console.log('PerformanceObserver A to B',items.getEntries()[0].duration);
    performance.clearMarks();
});
obs.observe({ entryTypes: ['measure'] });

performance.mark('A');

(async function main(){
    try{
        await performance.timerify(doSomeLongRunningProcess)();
        performance.mark('B');
        performance.measure('A to B', 'A', 'B');
    }catch(e){
        console.log('main() error',e);
    }
})();
Cody G
źródło
Daje mi TypeError: performance.getEntriesByName is not a functionw węźle 10.4.1
Jeremy Thille
Zrobiłem przykład, abyś mógł uruchomić go online. Jest to Węzeł 9.7.1. Jeśli to nie działa w wersji 10.4.1, zastanawiam się, co może się zmienić!
Cody G
1
Stability: 1 - Experimentalmoże? :) nodejs.org/docs/latest-v8.x/api/…
Jeremy Thille
Tak, na pewno to się zmieniło. W wersji 10 pojawił się nowy obserwator . Dokumenty można zobaczyć na stronie nodejs.org/docs/latest-v10.x/api/documentation.html . Będę aktualizować, kiedy będę mieć szansę!
Cody G
19

Dla każdego, kto chce uzyskać upływ czasu zamiast wyniku konsoli:

użyj process.hrtime () jako sugestii @ D.Deriso, poniżej jest moje prostsze podejście:

function functionToBeMeasured() {
    var startTime = process.hrtime();
    // do some task...
    // ......
    var elapsedSeconds = parseHrtimeToSeconds(process.hrtime(startTime));
    console.log('It takes ' + elapsedSeconds + 'seconds');
}

function parseHrtimeToSeconds(hrtime) {
    var seconds = (hrtime[0] + (hrtime[1] / 1e9)).toFixed(3);
    return seconds;
}
Śpiewać
źródło
16
var start = +new Date();
var counter = 0;
for(var i = 1; i < LIMIT; i++){
    ++counter;
    db.users.save({id : i, name : "MongoUser [" + i + "]"}, function(err, saved) {
          if( err || !saved ) console.log("Error");
          else console.log("Saved");
          if (--counter === 0) 
          {
              var end = +new Date();
              console.log("all users saved in " + (end-start) + " milliseconds");
          }
    });
}
Andrey Sidorov
źródło
5
Musiałem sprawdzić składnię „+ new Date ()”, aby dowiedzieć się, co to znaczy. Zgodnie z komentarzami do tej odpowiedzi ( stackoverflow.com/a/221565/5114 ) używanie tego formularza ze względu na wydajność i czytelność nie jest dobrym pomysłem. Wolę coś bardziej szczegółowego, aby czytelnik był bardziej zrozumiały. Zobacz także tę odpowiedź: stackoverflow.com/a/5036460/5114
Mnebuerquo
3
Często używam, var start = process.hrtime(); ... var end = process.hrtime(start);aby uzyskać wysoką rozdzielczość (jeśli muszę spodziewać się dokładności poniżej milisekundy)
Andrey Sidorov,
9

Stare pytanie, ale dla prostego API i lekkiego rozwiązania; możesz użyć perfy, który korzysta wewnętrznie z wysokiej rozdzielczości w czasie rzeczywistym ( process.hrtime).

var perfy = require('perfy');

function end(label) {
    return function (err, saved) {
        console.log(err ? 'Error' : 'Saved'); 
        console.log( perfy.end(label).time ); // <——— result: seconds.milliseconds
    };
}

for (var i = 1; i < LIMIT; i++) {
    var label = 'db-save-' + i;
    perfy.start(label); // <——— start and mark time
    db.users.save({ id: i, name: 'MongoUser [' + i + ']' }, end(label));
}

Zauważ, że przy każdym perfy.end(label)wywołaniu instancja ta jest automatycznie niszczona.

Ujawnienie: Napisałem ten moduł, zainspirowany odpowiedzią D.Deriso . Dokumenty tutaj .

Onur Yıldırım
źródło
2

Możesz spróbować Benchmark.js . Obsługuje wiele platform, w tym także node.js.

jsbeckr
źródło
11
Byłoby dobrze, gdybyś mógł dodać przykład użycia benchmark.js w tym przypadku użycia.
Petah
2

Możesz także wypróbować exectimer . Daje ci informacje zwrotne takie jak:

var t = require("exectimer");

var myFunction() {
   var tick = new t.tick("myFunction");
   tick.start();
   // do some processing and end this tick
   tick.stop();
}

// Display the results
console.log(t.timers.myFunction.duration()); // total duration of all ticks
console.log(t.timers.myFunction.min()); // minimal tick duration
console.log(t.timers.myFunction.max()); // maximal tick duration
console.log(t.timers.myFunction.mean()); // mean tick duration
console.log(t.timers.myFunction.median()); // median tick duration

[edytuj] Istnieje jeszcze prostszy sposób korzystania z exectimer, ponieważ teraz może on zawijać kod do pomiaru. Twój kod może być zawinięty w następujący sposób:

var t = require('exectimer'),
Tick = t.Tick;

for(var i = 1; i < LIMIT; i++){
    Tick.wrap(function saveUsers(done) {
        db.users.save({id : i, name : "MongoUser [" + i + "]"}, function(err, saved) {
            if( err || !saved ) console.log("Error");
            else console.log("Saved");
            done();
        });
    });
}

// Display the results
console.log(t.timers.myFunction.duration()); // total duration of all ticks
console.log(t.timers.saveUsers.min()); // minimal tick duration
console.log(t.timers.saveUsers.max()); // maximal tick duration
console.log(t.timers.saveUsers.mean()); // mean tick duration
console.log(t.timers.saveUsers.median()); // median tick duration
Alexandru Savin
źródło
1

Miałem ten sam problem podczas przenoszenia z AWS na Azure

W przypadku ekspresów i aws możesz już użyć istniejącego time () i timeEnd ()

W przypadku platformy Azure użyj tego: https://github.com/manoharreddyporeddy/my-nodejs-notes/blob/master/performance_timers_helper_nodejs_azure_aws.js

Te time () i timeEnd () używają istniejącej funkcji hrtime (), która daje czas rzeczywisty wysokiej rozdzielczości.

Mam nadzieję że to pomoże.

Manohar Reddy Poreddy
źródło
0

Inną opcją jest użycie narzędzia do debugowania ekspresowego :

express-debug to narzędzie programistyczne dla express. To proste oprogramowanie pośrednie, które wstrzykuje użyteczne dane do debugowania do html, w sposób nie przeszkadzający.

Dogodnie oferuje panel profilujący:

całkowity czas przetwarzania zapotrzebowania. czasy pośrednie, parametry i trasy.

Również. aby dodać do powyższych odpowiedzi, możesz sprawdzić tę odpowiedź, aby włączyć dowolny kod profilujący tylko dla środowiska programistycznego.

Wtower
źródło