node.js - Hur mäter jag exekveringstiden för JavaScript-kod med callbacks?

Jag har en bit JavaScript-kod som jag kör med node.js-tolken.

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");
    }
  });
}

Hur kan jag mäta tiden som dessa databasinläggningsoperationer tar? Jag skulle kunna beräkna skillnaden mellan datumvärdena efter och före den här koddelen, men det skulle vara fel på grund av kodens asynkrona natur.

Svar #1

Använd Node.js console.time() och 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");
    }
};

Svar #2

Det finns en metod som är utformad för detta. Kolla in process.hrtime();.

Så, jag placerade i princip detta högst upp i min app.

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
}

Då använder jag det för att se hur lång tid funktioner tar. Här är ett grundläggande exempel som skriver ut innehållet i en textfil som heter "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);

Här är ett snabbt test som du kan köra i en terminal (BASH-skal):

for i in {1..100}; do echo $i; curl http://localhost:8080/; done

Svar #3

Att anropa console.time('label') kommer att registrera den aktuella tiden i millisekunder, och sedan kommer ett senare anrop till console.timeEnd('label') att visa varaktigheten från den tidpunkten.

Tiden i millisekunder kommer automatiskt att skrivas ut tillsammans med etiketten, så du behöver inte göra ett separat anrop till console.log för att skriva ut en etikett:

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

För mer information, se Mozillas utvecklardokumentation om console.time.

Svar #4

Förvånad över att ingen ännu har nämnt de nya inbyggda biblioteken:

Tillgänglig i Node >= 8.5, och bör finnas i moderna webbläsare

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

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

Nod 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);
  // apparently you should clean up...
  performance.clearMarks();
  performance.clearMeasures();         
  // Prints the number of milliseconds between Mark 'A' and Mark 'B'
})();

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

Node 12.x

https://nodejs.org/docs/latest-v12.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);
      // apparently you should clean up...
      performance.clearMarks();
      // performance.clearMeasures(); // Not a function in Node.js 12
});
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);
    }
})();

Svar #5

För alla som vill få värdet på förfluten tid istället för konsolutskrift:

använd process.hrtime() enligt @D.Deriso:s förslag, nedan är mitt enklare tillvägagångssätt :

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;
}

Svar #6

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");
          }
    });
}

Svar #7

Gammal fråga men för ett enkelt API och en lättviktslösning; du kan använda perfy som använder högupplöst realtid (process.hrtime) internt.

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));
}

Observera att varje gång perfy.end(label) kallas, förstörs den instansen automatiskt.

Upplysning: Skrev denna modul, inspirerad av D.Derisos svar. Dokumentation här.

Svar #8

Big Brain-metoden som använder performance.now():

let stime = performance.now();     // started time
executeSomething()                      
let ftime = performance.now();     // finished time

let elapsed_time = ftime - stime;  
console.log(`Execution time: ${elapsed_time} ms`);

performance.now-metoden returnerar en tidsstämpel från tidsursprunget (i millisekunder).

Genom att subtrahera starttiden från sluttiden kan du enkelt få den förflutna tiden och, viktigast av allt, ha den lagrad i en variabel.

Relaterade artiklar