440

I have a piece of JavaScript code that I am executing using the node.js interpreter.

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

How can I measure the time taken by these database 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.

6
  • 10
    Just read the start time before the db call, and the end time INSIDE the callback..
    – BFil
    May 16, 2012 at 10:59
  • There is a possibility that the time that the DB finishes the insert and the time the callback is executed is not the same and this would introduce an error in the measurement ? May 16, 2012 at 11:13
  • 1
    No, you shouldn't worry about it, if the db library code is well designed and doesn't handle any other operation before firing the callback, you should get a good measure. You can also profile the insertion by putting the timestamps inside the library code where the insert is actually performed, instead of your own, but, again, I wouldn't worry about it
    – BFil
    May 16, 2012 at 11:32
  • I would recommend trying NodeTime which seems to be a good fit for what you are trying to do. May 18, 2012 at 10:20
  • I wrote timerlog which is similar to console.time() but with additional features; github.com/brillout/timerlog
    – brillout
    Mar 1, 2017 at 13:10

12 Answers 12

935

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");
    }
};
7
  • 45
    Clean and built-in solution for node.
    – Behlül
    Sep 23, 2013 at 20:28
  • 53
    >I want to know how to measure the time taken by these db insert operations. --- console.timeEnd("dbsave") just outputs to console the timing. You can't use that further and is less flexible. If you need the actual timing value, like in original question, you cant use console.timeEnd("dbsave")
    – gogaman
    Aug 6, 2014 at 18:42
  • 6
    So what's the difference between console.time() and process.hrtime() in the below answer? Feb 20, 2015 at 14:43
  • 4
    Would be worth adding a note that the executing time is then printed out, just so that new users now.
    – Janko
    Nov 10, 2015 at 13:13
  • 1
    Just FYI the timer is killed by timeEnd, so you can't call it again afterward, it's a new bug fix that was once an accidental feature.
    – tbh__
    Jan 13, 2017 at 15:59
259

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
6
  • 4
    it that superior to the console.time solution in any way?
    – scravy
    Mar 31, 2015 at 17:29
  • 38
    Yep, it's a lot more precise and you can store the result in a variable Jul 1, 2015 at 6:17
  • 2
    Why do you call process.hrtime(start) twice? Is there a particular reason for it?
    – Sohail Si
    Feb 6, 2019 at 19:09
  • 2
    process.hrtime([time]), where time is an optional parameter that must be the result of a previous process.hrtime() call to diff with the current time. It gives the difference between the current call and the previous hrtime call. Nov 28, 2019 at 8:50
  • 1
    good solution but the last line ( start = process.hrtime(); // reset the timer ) doesn't make any sense Mar 9, 2020 at 13:55
157

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.

3
  • 2
    What does this add to the accepted answer? Jul 5, 2018 at 23:11
  • 14
    @DanDascalescu This is much more succinct, readable, and digestible than the accepted answer - which is littered with noisy "example" code. I personally much prefer this answer. Jan 4, 2022 at 9:40
  • You can also log the timer value at some points in code by using console.timeLog('label')
    – Janus
    Sep 19, 2022 at 6:41
44

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);
  // 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);
    }
})();
8
37

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;
}
17
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");
          }
    });
}
2
  • 5
    I had to look up the syntax '+new Date()' to figure out what that meant. According to comments on this answer (stackoverflow.com/a/221565/5114), it's not a good idea to use that form for performance reasons as well as readability. I prefer something a bit more verbose so it's clearer to the reader. Also see this answer: stackoverflow.com/a/5036460/5114
    – Mnebuerquo
    Jan 19, 2015 at 19:08
  • 4
    I often use var start = process.hrtime(); ... var end = process.hrtime(start); to get high resolution time (if I need to expect sub millisecond accuracy) Jan 20, 2015 at 5:57
10

Old question but for a simple API and light-weight solution; you can use perfy which uses high-resolution real time (process.hrtime) internally.

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

Note that each time perfy.end(label) is called, that instance is auto-destroyed.

Disclosure: Wrote this module, inspired by D.Deriso's answer. Docs here.

3

You could also try exectimer. It gives you feedback like:

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

[edit] There is an even simpler way now to use exectime. Your code could be wrapped like this:

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
2

You can use a wrapper function to easily report the execution time of any existing function.

A wrapper is a used to extend an existing function to do something before and after the existing function's execution - and is a convenient way to compose logic.

Here is an example of using the withDurationReporting wrapper:

// without duration reporting
const doSomethingThatMayTakeAWhile = async (someArg: string, anotherArg: number) => { 
  /** your logic goes here */
}

// with duration reporting
const doSomethingThatMayTakeAWhileWithReporting = withDurationReporting(
  'doSomethingThatMayTakeAWhile', 
  doSomethingThatMayTakeAWhile
);
// note: you can define the function with duration reporting directly, too
const doSomethingThatMayTakeAWhile = withDurationReporting(
  'doSomethingThatMayTakeAWhile', 
  async (someArg: string, anotherArg: number) => { 
    /** your logic goes here */
  }
)

And here is the wrapper itself:

import { hrtime } from 'process';

const roundToHundredths = (num: number) => Math.round(num * 100) / 100; // https://stackoverflow.com/a/14968691/3068233

/**
 * a wrapper which reports how long it took to execute a function, after the function completes
 */
export const withDurationReporting = <R extends any, T extends (...args: any[]) => Promise<R>>(
  title: string,
  logic: T,
  options: {
    reportingThresholdSeconds: number;
    logMethod: (message: string, metadata?: Record<string, any>) => void;
  } = {
    reportingThresholdSeconds: 1, // report on anything that takes more than 1 second, by default
    logMethod: console.log, // log with `console.log` by default
  }, 
) => {
  return (async (...args: Parameters<T>): Promise<R> => {
    const startTimeInNanoseconds = hrtime.bigint();
    const result = await logic(...args);
    const endTimeInNanoseconds = hrtime.bigint();
    const durationInNanoseconds = endTimeInNanoseconds - startTimeInNanoseconds;
    const durationInSeconds = roundToHundredths(Number(durationInNanoseconds) / 1e9); // https://stackoverflow.com/a/53970656/3068233
    if (durationInSeconds >= options.reportingThresholdSeconds)
      options.logMethod(`${title} took ${durationInSeconds} seconds to execute`, { title, durationInSeconds });
    return result;
  }) as T;
};
2

I designed a simple method for this, using console.time() & console.timeEnd():

measure function definition
function measureRunningTime(func,...args){
    const varToString = varObj => Object.keys(varObj)[0]
    const displayName = func.name || varToString({ func })
    console.time(displayName)
    func(...args)
    console.timeEnd(displayName)
}

To use it, pass a function without arguments, with arguments binded, or with arguments as the following parameters.

Examples:

let's say I want to check the running time of the simplest searching algorithm - SimpleSearch:
measured function definition (your code here)
const simpleSearch = (array = [1,2,3] ,item = 3) => {
    for(let i = 0; i< array.length; i++){
        if (array[i] === item) return i;
    }
    return -1
}

implementation without arguments
measureRunningTime(simpleSearch) 
//Prints something like that-> simpleSearch: 0.04ms
implementation with arguments using .bind()
const array = [1,2,3]
const item = 3
measureRunningTime(simpleSearch.bind(null, array, item))
//Prints something like that-> bound simpleSearch: 0.04ms
implementation with arguments without using .bind()
const array = [1,2,3]
const item = 3
measureRunningTime(simpleSearch, array, item)
//Prints something like that-> simpleSearch: 0.04ms

-> Take notice!! this implementation is far from perfect - for example there is no error handling - but it can be used to check the running times of simple algorithms, Moreover , I'm not an experienced programmer so take everything with a grain of salt 🧂 👌

1

I had same issue while moving from AWS to Azure

For express & aws, you can already use, existing time() and timeEnd()

For Azure, use this: https://github.com/manoharreddyporeddy/my-nodejs-notes/blob/master/performance_timers_helper_nodejs_azure_aws.js

These time() and timeEnd() use the existing hrtime() function, which give high-resolution real time.

Hope this helps.

0

I need this to be cumulative, and to measure different stuff.
Built these functions:

function startMeasuring(key) {
  measureTimers[key] = process.hrtime();
}

function stopMeasuring(key) {
  if (!measures[key]) {
    measures[key] = 0;
  }

  let hrtime = process.hrtime(measureTimers[key]);
  measures[key] += hrtime[0] + hrtime[1] / 1e9;
  measureTimers[key] = null;
}

Usage:

startMeasuring("first Promise");
startMeasuring("first and second Promises");
await new Promise((resolve) => {
  setTimeout(resolve, 1400);
});
stopMeasuring("first Promise");
stopMeasuring("first and second Promises");

startMeasuring("first and second Promises");
await new Promise((resolve) => {
  setTimeout(resolve, 600);
});
stopMeasuring("first and second Promises");

console.log("Measure Results", measures); 
/*
Measusre Results {
  setting: 0.00002375,
  'first Promise': 1.409392916,
  'first and second Promise': 2.015160376
}
*/

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.