How to measure execution time of javascript code with callbacks

How to measure execution time of javascript code with callbacks

I have a piece of javascript code that I am executing using the node.js interpreter.
for(var i = 1; i < LIMIT; i++){ db.users.save({id : i, name : "MongoUser [" + i + "]"}, function(err, saved) { if( err || !saved ) console.log("Error"); else console.log("Saved"); }); } I want to know how to measure the time taken by these db insert operations. I could compute the difference of Date values after and before this piece of code but that would be incorrect because of the asynchronous nature of the code.

Solutions/Answers:

Solution 1:

Use the Node.js console.time() and 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");}
};

Solution 2:

There is a method that is designed for this. Check out process.hrtime(); .

So, I basically put this at the top of my 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
}

Then I use it to see how long functions take. Here’s a basic example that prints the contents of a text file called “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);

Here’s a quick test you can run in a terminal (BASH shell):

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

Solution 3:

Invoking console.time('label') will record the current time in milliseconds, then later calling console.timeEnd('label') will display the duration from that point.

The time in milliseconds will be automatically printed alongside the label, so you don’t have to make a separate call to console.log to print a label:

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

For more information, see Mozilla’s developer docs on console.time.

Solution 4:

For anyone want to get time elapsed value instead of console output :

use process.hrtime() as @D.Deriso suggestion, below is my simpler approach :

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

Solution 5:

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

Solution 6:

Surprised no one had mentioned yet the new built in libraries:

Available in Node >= 8.5, and should be in Modern Browers

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

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

Node 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

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