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.

The answers of this question do not solve my problem. The top answer is basically another formulation of my first example. It does not address the problem about the event loop, i.e. promises are always run in a new microtask, and other pending microtasks will be run first. — ehmicky
– ehmicky, Commented Aug 18, 2017 at 9:05

Bergi · Accepted Answer · 2017-08-18 09:21:35Z

7

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.

answered Aug 18, 2017 at 9:21

Bergi

671k162 gold badges1k silver badges1.5k bronze badges

Sign up to request clarification or add additional context in comments.

10 Comments

ehmicky Over a year ago

The problem is that this is happening on a web server where many microtasks are fired from every direction, so I cannot force the task queue to be empty when asyncFunc stops executing.

Bergi Over a year ago

I don't see the problem with that. Either you want to do your measurements in a real world environment or not. Which is it? Btw, if you make sure that no task is slow and blocking, this shouldn't make much of a difference anyway.

ehmicky Over a year ago

I want to do measurements in a real world environment (production). The stats are sent to performance monitoring dashboards. My web server fires a pipeline of 70+ async middleware functions, fired one after another, sometimes in parallel for the same request. Many microtasks and macrotasks are running in parallel. I want to know how long each async middleware function is taking, without having to modify each of them.

Bergi Over a year ago

Also, the most microtasks run while your current middleware is doing its background processing asynchronous stuff. So the task queue should be empty most of the time and not affect your measurement heavily - and if at all, then by a constant factor at most. Or are you actually looking to measure the synchronous task parts only?

Bergi Over a year ago

I'm afraid then it is not possible. Unlike nextTick or setTimeout that take a callback which you can instrument, there is no way to hook into native async functions (except maybe for some debugging API). I guess your best bet would be using a transpiler to inject the stop-and-start code around every await operator.

|

user943702 · Accepted Answer · 2017-08-20 14:37:27Z

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)

DivyaMaheswaran · Accepted Answer · 2017-08-18 08:57:35Z

0

Consider using perfrmance.now() API

var time_0 = performance.now();
function();
var time_1 = performance.now();
console.log("Call to function took " + (time_1 - time_0) + " milliseconds.")

As performance.now() is the bare-bones version of console.time , it provide more accurate timings.

answered Aug 18, 2017 at 8:57

DivyaMaheswaran

9341 gold badge12 silver badges16 bronze badges

1 Comment

ehmicky Over a year ago

This does not solve this problem. Try running my second example by replacing Date.now() by performance.now(), and you will find the same problem. The problem is about promises callbacks being run in a new microtask. Any already queued microtask will be run first, whether you use performance.now or something else.

Collectives™ on Stack Overflow

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

3 Answers 3

10 Comments

Comments

1 Comment

Your Answer

Linked

Hot Network Questions

Collectives™ on Stack Overflow

3 Answers 3

10 Comments

Comments

1 Comment

Your Answer

Sign up or log in

Post as a guest

Linked

Related