14

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.

ehmicky
  • 1,915
  • 4
  • 20
  • 29
  • https://stackoverflow.com/questions/44158044/how-to-measure-the-execution-time-of-a-promise – jackarms Aug 18 '17 at 08:57
  • 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 Aug 18 '17 at 09:05

4 Answers4

6

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.

Bergi
  • 630,263
  • 148
  • 957
  • 1,375
  • 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. – ehmicky Aug 18 '17 at 09:24
  • 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. – Bergi Aug 18 '17 at 09:26
  • 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. – ehmicky Aug 18 '17 at 09:27
  • Then there's nothing wrong with your code that takes the time in the `then` callback. Notice that every `await` inside the `async function` is affected in exactly the same way by the task queue. – Bergi Aug 18 '17 at 09:29
  • The problem is that I want to know how long each individual middleware is taking. The current code takes into account the microtasks queued by other middleware, i.e. the reported time is wrong. When to comes to `async/await`, I used it for simplicity, but the problem is indeed the same with native promises. – ehmicky Aug 18 '17 at 09:31
  • I wouldn't call it "wrong" - it's a perfectly fine measurement *under load*. If you worry about comparability of the numbers, you might want to keep track of how many measurements are in flight concurrently with a counter, and report that together with the timespan to the dashboard. – Bergi Aug 18 '17 at 09:35
  • 1
    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 Aug 18 '17 at 09:37
  • Exactly, I only want to measure the synchronous parts. The way I do this is by instrumenting calls like `process.nextTick()` and `setTimeout()` so that they stop the counter of the current async function when the function yields, and restart it when the function re-enters. It turns out the web server currently has lots of both sync and async processing, so it's quite common that sync processing is happening, sometimes 100ms long, i.e. the task queue is not empty. – ehmicky Aug 18 '17 at 09:56
  • 1
    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 function`s (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. – Bergi Aug 18 '17 at 10:16
  • Thank you, that sounds very logical, and what I was afraid of. Instead of a full transpiler, I also considered doing it runtime, by using `function.toString()` and `new AsyncFunction()`, although this feels hacky. Thanks! I will wait to see if anyone has some other idea first, e.g. maybe using `async_hooks` Node.js core module? – ehmicky Aug 18 '17 at 10:19
5

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)
user943702
  • 956
  • 6
  • 12
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.

DivyaMaheswaran
  • 886
  • 1
  • 12
  • 16
  • 1
    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. – ehmicky Aug 18 '17 at 09:03
-2

you can use console.time('nameit') and console.timeEnd('nameit') check the example below.

console.time('init')

const asyncFunc = async function () {
};

const slowSyncFunc = function () {
  for (let i = 1; i < 10 ** 9; i++) {}
};
// let's slow down a bit.
slowSyncFunc()
console.time('async')
asyncFunc().then((data) => {
  console.timeEnd('async')  
});

console.timeEnd('init')
Necmttn
  • 1,137
  • 1
  • 9
  • 17
  • This does not solve this problem. You added a `setTimeout` statement in `asyncFunc`. Because of this, it will be run in a new macrotask, i.e. it will end after `aslowSyncFunc`. Try removing `setTimeout` and the problem appears again. – ehmicky Aug 18 '17 at 09:09
  • check it again ? `init: 1474.230ms - async: 3.345ms ` – Necmttn Aug 18 '17 at 09:17
  • You changed the example, but it still is different from my original example. `slowSyncFunc` is not run in a new microtask with `process.nextTick` anymore. I.e. it ends before `asyncFunc` even starts, so this will now work. Try adding `process.nextTick` and the problem appears again. – ehmicky Aug 18 '17 at 09:17