How to calculate the execution time of an async function in JavaScript?

Question

I would like to calculate how long an async function (async/await) is taking in JavaScript.

One could do:

const asyncFunc = async function () {};

const before = Date.now();
asyncFunc().then(() => {
  const after = Date.now();
  console.log(after - before);
});

However, this does not work, because promises callbacks are run in a new microtask. I.e. between the end of asyncFunc() and the beginning of then(() => {}), any already queued microtask will be fired first, and their execution time will be taken into account.

E.g.:

const asyncFunc = async function () {};

const slowSyncFunc = function () {
  for (let i = 1; i < 10 ** 9; i++) {}
};

process.nextTick(slowSyncFunc);

const before = Date.now();
asyncFunc().then(() => {
  const after = Date.now();
  console.log(after - before);
});

This prints 1739 on my machine, i.e. almost 2 seconds, because it waits for slowSyncFunc() to complete, which is wrong.

Note that I do not want to modify the body of asyncFunc, as I need to instrument many async functions without the burden of modifying each of them. Otherwise I could just add a Date.now() statement at the beginning and the end of asyncFunc.

Note also that the problem is not about how the performance counter is being retrieved. Using Date.now(), console.time(), process.hrtime() (Node.js only) or performance (browser only) will not change the base of this problem. The problem is about the fact that promise callbacks are run in a new microtask. If you add statements like setTimeout or process.nextTick to the original example, you are modifying the problem.

Answer 1

The problem we have

process.nextTick(() => {/* hang 100ms */})
const asyncFunc = async () => {/* hang 10ms */}
const t0 = /* timestamp */
asyncFunc().then(() => {
  const t1 = /* timestamp */
  const timeUsed = t1 - t0 /* 110ms because of nextTick */
  /* WANTED: timeUsed = 10ms */
})

A solution (idea)

const AH = require('async_hooks')
const hook = /* AH.createHook for
   1. Find async scopes that asycnFunc involves ... SCOPES
      (by handling 'init' hook)
   2. Record time spending on these SCOPES ... RECORDS 
      (by handling 'before' & 'after' hook) */
hook.enable()
asyncFunc().then(() => {
  hook.disable()
  const timeUsed = /* process RECORDS */
})

But this wont capture the very first sync operation; i.e. Suppose asyncFunc as below, $1$ wont add to SCOPES(as it is sync op, async_hooks wont init new async scope) and then never add time record to RECORDS

hook.enable()
/* A */
(async function asyncFunc () { /* B */
  /* hang 10ms; usually for init contants etc ... $1$ */ 
  /* from async_hooks POV, scope A === scope B) */
  await /* async scope */
}).then(..)

To record those sync ops, a simple solution is to force them to run in a new ascyn scope, by wrapping into a setTimeout. This extra stuff does take time to run, ignore it because the value is very small

hook.enable()
/* force async_hook to 'init' new async scope */
setTimeout(() => { 
   const t0 = /* timestamp */
   asyncFunc()
    .then(()=>{hook.disable()})
    .then(()=>{
      const timeUsed = /* process RECORDS */
    })
   const t1 = /* timestamp */
   t1 - t0 /* ~0; note that 2 `then` callbacks will not run for now */ 
}, 1)

Note that the solution is to 'measure time spent on sync ops which the async function involves', the async ops e.g. timeout idle will not count, e.g.

async () => {
  /* hang 10ms; count*/
  await new Promise(resolve => {
    setTimeout(() => {
      /* hang 10ms; count */
      resolve()
    }, 800/* NOT count*/)
  }
  /* hang 10ms; count*/
}
// measurement takes 800ms to run
// timeUsed for asynFunc is 30ms

---

Last, I think it maybe possible to measure async function in a way that includes both sync & async ops(e.g. 800ms can be determined) because async_hooks does provide detail of scheduling, e.g. setTimeout(f, ms), async_hooks will init an async scope of "Timeout" type, the scheduling detail, ms, can be found in resource._idleTimeout at init(,,,resource) hook

---

Demo(tested on nodejs v8.4.0)

// measure.js
const { writeSync } = require('fs')
const { createHook } = require('async_hooks')

class Stack {
  constructor() {
    this._array = []
  }
  push(x) { return this._array.push(x) }
  peek() { return this._array[this._array.length - 1] }
  pop() { return this._array.pop() }
  get is_not_empty() { return this._array.length > 0 }
}

class Timer {
  constructor() {
    this._records = new Map/* of {start:number, end:number} */
  }
  starts(scope) {
    const detail =
      this._records.set(scope, {
        start: this.timestamp(),
        end: -1,
      })
  }
  ends(scope) {
    this._records.get(scope).end = this.timestamp()
  }
  timestamp() {
    return Date.now()
  }
  timediff(t0, t1) {
    return Math.abs(t0 - t1)
  }
  report(scopes, detail) {
    let tSyncOnly = 0
    let tSyncAsync = 0
    for (const [scope, { start, end }] of this._records)
      if (scopes.has(scope))
        if (~end) {
          tSyncOnly += end - start
          tSyncAsync += end - start
          const { type, offset } = detail.get(scope)
          if (type === "Timeout")
            tSyncAsync += offset
          writeSync(1, `async scope ${scope} \t... ${end - start}ms \n`)
        }
    return { tSyncOnly, tSyncAsync }
  }
}

async function measure(asyncFn) {
  const stack = new Stack
  const scopes = new Set
  const timer = new Timer
  const detail = new Map
  const hook = createHook({
    init(scope, type, parent, resource) {
      if (type === 'TIMERWRAP') return
      scopes.add(scope)
      detail.set(scope, {
        type: type,
        offset: type === 'Timeout' ? resource._idleTimeout : 0
      })
    },
    before(scope) {
      if (stack.is_not_empty) timer.ends(stack.peek())
      stack.push(scope)
      timer.starts(scope)
    },
    after() {
      timer.ends(stack.pop())
    }
  })

  // Force to create a new async scope by wrapping asyncFn in setTimeout,
  // st sync part of asyncFn() is a async op from async_hooks POV.
  // The extra async scope also take time to run which should not be count
  return await new Promise(r => {
    hook.enable()
    setTimeout(() => {
      asyncFn()
        .then(() => hook.disable())
        .then(() => r(timer.report(scopes, detail)))
        .catch(console.error)
    }, 1)
  })
}

Test

// arrange
const hang = (ms) => {
  const t0 = Date.now()
  while (Date.now() - t0 < ms) { }
}
const asyncFunc = async () => {
  hang(16)                           // 16
  try {
    await new Promise(r => {
      hang(16)                       // 16
      setTimeout(() => {
        hang(16)                     // 16
        r()
      }, 100)                        // 100
    })
    hang(16)                         // 16
  } catch (e) { }
  hang(16)                           // 16
}
// act
process.nextTick(() => hang(100))    // 100
measure(asyncFunc).then(report => {
  // inspect
  const { tSyncOnly, tSyncAsync } = report
  console.log(`
  ∑ Sync Ops       = ${tSyncOnly}ms \t (expected=${16 * 5})
  ∑ Sync&Async Ops = ${tSyncAsync}ms \t (expected=${16 * 5 + 100})
  `)
}).catch(e => {
  console.error(e)
})

Result

async scope 3   ... 38ms
async scope 14  ... 16ms
async scope 24  ... 0ms
async scope 17  ... 32ms

  ∑ Sync Ops       = 86ms       (expected=80)
  ∑ Sync&Async Ops = 187ms      (expected=180)

Answer 2

Any already queued microtask will be fired first, and their execution time will be taken into account.

Yes, and there's no way around that. If you don't want to have other tasks contribute to your measurement, don't queue any. That's the only solution.

This is not a problem of promises (or async functions) or of the microtask queue specifically, it's a problem shared by all asynchronous things which run callbacks on a task queue.