Timing asynchronous functions in JavaScript ES6

In this post I’ll present a reusable function for timing async operations in JavaScript.

calc is an async function that we like to profile. By convention its last argument is a callback. We use calc like this:

calc(arg, (err, res) => console.log(err || res))

Perhaps the easiest way of profiling a function like calc is adding the timing logic wherever we need it:

const t0 = Date.now()
calc(arg, (err, res) => {
 const t1 = Date.now() 
 console.log(`Log: time: ${t1 = t0}`)
 console.log(err || res)
})

But this is not a reusable solution. Every time that we want to time a function we have to introduce a t⁰ at the outer scope and change the callback to measure and log the time.

Ideally I’d like to be able to time any async function by just wrapping it:

timeIt(calc)(arg, (err, res) => console.log(err || res))

timeIt should take care of profiling and logging the execution time for every async function.

Note that timeIt(calc) has the same signature as our original calc. It takes the same arguments and produces the same result. It just adds a feature to calc (the feature being logging the time).

calc and timeIt(calc) are replaceable with each other every time.

timeIt itself is a higher order function, because it takes a function and returns a function. In our example, it takes calc async function and returns a function that has the same signature as calc.

This is how we can implement the timeIt function:

I am using the amazing Ramda library. You can run this snippet in Ramda REPL.

This implementation of timeIt takes two input parameters:

• report: a function that will be called with the profiling result
• f: the async function that we’re profiling

timeIt1 is a handy utility function that just logs the time measure using console.log. It is defined by filling in the reporter argument in the more general timeIt function.

We achieved our goal, now we can time calc by just wrapping it inside timeIt1:

timeIt1(calc)(18, 7, 3, (err, res) => console.log(err || res))

The more general timeIt function takes a report callback and an async function and returns a new async function with the same signature as the original’s. We can use it like this:

timeIt(
   (time, ...result) => // report callback: log the time
 , asyncFunc
)(
  parameters…, 
  (...result) => // result of the async function
)

Now let’s dig into the implementation of timeIt. We can easily make a utility like timeIt1 because timeIt is curried using R.curry.

I am not going to discuss currying in this post but this snippet shows the gist of it:

const f = R.curry((x, y) => x + y)
f(1, 10)  // == 11
f(1)(10)  // == 11
const plus1 = f(1)
plus1(10) // == 11

On the other hand, there are a couple of problems with this part of timeIt implementation:

(...args) => {
  const t1 = Date.now()
  callback(...args)
  report(t1 — t0, ...args)
}

This is the anonymous function (aka lambda, callback) that is being called at the end of the original async operation. The main problem is that this function has no error handling mechanism. If callback throws an exception then report is never being called.

We can add a try / catch block to this lambda, but the root of the problem is that callback and report are two void functions that are not linked together. timeIt has two continuations (report and callback). This is fine if we just log the execution time in the console or if we make sure that neither report nor callback will be throwing an exception. But if we want to take some action depending on the profiling result (let’s say scaling up automatically) then we need to enforce and clarify the sequence of continuations in our program.

We will discuss a solution using Promises in a later post.