Add the possibity to track a time execution of async functions

[antoniomuso]

What do you think of trackAsyncCbTime function to trace async function resolve's time?

async function asyncFunction(a, b, c) {
    await doSomething(a, b, c);
    return doSomething2(a, b, c);
}

const asyncFunctionOutput = await fastify.trackAsyncCbTime(
    { scope: 'something', label: 'test' },
    asyncFunction,
    a,
    b,
    c
);

WDYT?

[dnlup]

Yes that is useful 😉

[simonecorsi]

I've missed a point in this that I haven't thought before and there is only one thing to keep in mind, this will never be a 100% correct timing.

Because of how underlying queueing work, then's callback (here is async/await but that's syntactical sugar) is queued in the next microtaskQueue that may or may not (probably has) already multiple callback queued up and those will count toward our computation.

There is no way around this because that how async jobs works.

If we're ok with it I'm fine but we should at least warn the users!

[antoniomuso]

It's ok for me to add a warn in the docs.

[dnlup]

I've missed a point in this that I haven't thought before and there is only one thing to keep in mind, this will never be a 100% correct timing.

Because of how underlying queueing work, then's callback (here is async/await but that's syntactical sugar) is queued in the next microtaskQueue that may or may not (probably has) already multiple callback queued up and those will count toward our computation.

There is no way around this because that how async jobs works.

If we're ok with it I'm fine but we should at least warn the users!

That would be the same if you timed a Promise without the utility functions want to provide (if I understand correctly). I don't think we need a warning for that.

[simonecorsi]

If your callback ends up down in the queue you would have all the overhead in timing of the others, it's something I would want to know if it can make my metrics somehow not what I expect

[dnlup]

A couple of thoughts:

1. maybe it could be useful to expose this also for sync functions
2. if the function that we want to time is attached to a Fastify instance we could have context issues

[antoniomuso]

The first point it's ok for me, for the second I don't understand the possible problem, can you give an example?

[dnlup]

Sure, imagine we have to time something like:

fastify.decorate('someFn', function (arg1, arg2) {
  this.log.info(arg1,arg2)
})
fastify.timeAsync(fastify.someFn, arg1, arg2)

I think we would lose the this context in the decorated function.

[dnlup]

Finally found this:

https://nodejs.org/dist/latest-v16.x/docs/api/perf_hooks.html#performancetimerifyfn-options

We could provide a wrapper of this in the plugin, but I think it's also pretty straightforward to use as it is. I think it's a much cleaner approach.

[antoniomuso]

I like it; we should test if this function has overheads. It uses the PerformanceObserver that can add performance overhead.

[dnlup]

I have used it to track GC activity in the past with no perf issues, but I'll test it again for sure.

[dnlup]

I am removing this one from the milestone. I would prefer not blocking a new release waiting for this feature.