3

If the do work function was performing some operation, say, picking an item from queue and performing some operation. How would I get the execution times for doWork function over time. I want to find out how much time doWork takes to complete at an average.

Sample Code

function doWork () {
  return Promise.resolve({first: 'Tony', last: 'Starks'})
}

async function wrapper () {
  console.time('wrapper')
  const response = await doWork()
  console.timeEnd('wrapper')
  return response
}

Promise.all([
  wrapper(),
  wrapper(),
  wrapper()
]).then((result) => console.info(result))

Output

wrapper: 0.388ms
[ { first: 'Tony', last: 'Starks' },
  { first: 'Tony', last: 'Starks' },
  { first: 'Tony', last: 'Starks' } ]
(node:2749) Warning: No such label 'wrapper' for console.timeEnd()
(node:2749) Warning: No such label 'wrapper' for console.timeEnd()
Perpetualcoder
  • 13,501
  • 9
  • 64
  • 99
  • It might be prudent to run the tests of your function end-to-end, otherwise each invocation will be "fighting" all the others for limited CPU time. It would make more sense to do performance testing one at a time, and stress testing the way you're doing now. – Patrick Roberts Jun 27 '17 at 03:38
  • You are basically doing `console.time('wrapper')` thrice, then doing `console.timeEnd('wrapper')` thrice. Make the measurement of the parallel executing tasks by manually subtracting timestamps. – Bergi Jun 27 '17 at 03:39
  • possible duplicate of [How to measure the execution time of a promise?](https://stackoverflow.com/q/44158044/1048572), unless your question specifically is why the `console.time` approach didn't work (please [edit] to make that clearer). – Bergi Jun 27 '17 at 03:41
  • @PatrickRoberts Not sure I understand what you are trying to say. – Perpetualcoder Jun 27 '17 at 04:04
  • @Bergi The code I posted is an over simplification of the actual code. I have built an offline process that performs a bunch of tasks. We are not sure how long each of the task takes. Ideally each of these tasks can be an AWS Lambda but without knowing how long it is taking we dont want to go the lambda way. – Perpetualcoder Jun 27 '17 at 04:07
  • JavaScript is single-threaded. You're initializing 3 asynchronous functions in the same tick. They end up competing for CPU time on each asynchronous callback. Look at [my answer](https://stackoverflow.com/a/44771968/1541563) and compare the times for parallel vs. series, the series will be an order of magnitude faster because they are initialized one-after-the-other and do not compete for CPU time. – Patrick Roberts Jun 27 '17 at 04:08
  • @PatrickRoberts - They don't really compete for CPU time. Actual async operations run outside of the JS thread (in native code) and most don't use much CPU (usually, they are I/O or timer related). The completion callback itself will be scheduled via the event queue and only one callback can run at a time. I don't see how this is "competing for CPU time". – jfriend00 Jun 27 '17 at 05:04
  • @jfriend00 well I, as you did, interpreted the question a little more literally than that. These are not "actual" async functions, and do in fact compete for CPU time. – Patrick Roberts Jun 27 '17 at 06:19

3 Answers3

2

If you're just trying to get your console.time() and console.end() calls to work around your async function, you can generate a unique label each time you call console.time() and console.end() so that the measurement will still work when there are multiple calls in flight at the same time (since each call will then be using its own label):

let wrapperCntr = 0;

async function wrapper () {
  let cnt = wrapperCntr++;
  console.time('wrapper' + cnt);
  const response = await doWork();
  console.timeEnd('wrapper' + cnt);
  return response;
}
jfriend00
  • 683,504
  • 96
  • 985
  • 979
  • Updated question with your suggestion. – Perpetualcoder Jun 27 '17 at 04:13
  • @Perpetualcoder - Why would you update your question with my answer? That's not how things are supposed to work here. You can do several things with my answer such as upvote it, downvote it, comment on it, accept it, but copying it into your question is not one of them. Your question should stay what it originally was (with any needed clarification). Questions are questions, answers are answers and the two should not be merged here on stack overflow. Questions are NOT meant to be a running commentary on your latest thinking, incorporating what you've learned from answers. – jfriend00 Jun 27 '17 at 05:07
  • Ok. Removed the updates. There was no reason to downvote. I had already upvoted it. However, it was not producing the results quite the way I wanted. But your solution got over the initial problem of the warnings thrown for labels going out of context. – Perpetualcoder Jun 27 '17 at 05:16
  • 1
    @Perpetualcoder - What is the "results the way you wanted"? I had a hard time figuring out what you're really asking for beyond this. – jfriend00 Jun 27 '17 at 05:29
  • I would like to know how much time (assuming the function was called 3 times), each call took. This method isolates each call because of the wrapperCntr but.. first call takes 0.6ms then it takes 2.6ms etc. I dont think this is the right behavior. – Perpetualcoder Jun 27 '17 at 05:33
  • Why don't you think that's the right behavior. You are calling `Promise.resolve()` multiple times in a row. That will schedule several things to run on next tick, but with JS being single threaded and everything running through a single event queue, they can't all run as soon as they are ready so the first one runs first, the others have to wait until that first one is done running before their turn comes.That's just the ramifications of a single event queue and single threaded JS. The activity doesn't actually take that much CPU, it just has to be scheduled for after other things are running. – jfriend00 Jun 27 '17 at 05:45
  • @Perpetualcoder - If you want to know how long one takes all by itself when it's not competing with other things, then run just one of them and time it when nothing else is going through the event queue. That will be how long it takes. – jfriend00 Jun 27 '17 at 05:49
1

If you're hard-set on testing them in parallel, I recommend this approach:

function doWork () {
  return Promise.resolve({ first: 'Tony', last: 'Stank' })
}

async function wrapper (index) {
  console.time(index)
  const response = await doWork()
  console.timeEnd(index)
  return response
}

Promise.all(
  Array(3) // some big number
    .fill(wrapper)
    .map((wrapper, index) => wrapper(index))
).then((results) => console.info(results))

However, JavaScript is single-threaded. You're initializing 3 asynchronous functions in the same tick. They end up competing for CPU time on each asynchronous callback, which as you observed, causes undue timing delays.

Compare the times for above and below; below will be an order of magnitude faster because they are initialized in series and do not compete for CPU time:

function doWork () {
  return Promise.resolve({ first: 'Tony', last: 'Stank' })
}

async function wrapper ({ index, responses }) {
  console.time(index)
  responses.push(await doWork())
  console.timeEnd(index)
  return { index: ++index, responses }
}

Array(3) // some big number
  .fill(wrapper)
  .reduce(
    (promise, wrapper) => promise.then(wrapper),
    Promise.resolve({ index: 0, responses: [] })
  )
  .then(({ responses: results }) => console.info(results))
Patrick Roberts
  • 49,224
  • 10
  • 102
  • 153
1

Related Question

Why not use the built-in performance package, which is available in node and the browser by default.

The following will work for multiple calls too...

async function timePromise(promiseFunction) {
  try {
    const begin = performance.now();
    await promiseFunction();
    const end = performance.now();
    const timeTaken_ms = end - begin;
    return timeTaken_ms;
  } catch (error) {
    console.error(error);
  }
}
Ben Winding
  • 10,208
  • 4
  • 80
  • 67