async_wrap: when is callback ready to be called

[AndreasMadsen]

While developing dprof I came to realize that using beforeTimestamp (pre hook) - initTimestamp (init hook) as an async duration estimate is a bit misleading.

For example if user create a timeout of 100 ms and in the meanwhile have a cpu hungry calculation there takes 200 ms. The async operation only takes 100 ms but the beforeTimestamp - initTimestamp would indicate 200 ms.

A bit more likely, user could do fs.open which would finish quickly, but have so many other callbacks there needs calling first that it would take much longer time before the fs.open callback is called.

In both cases it would look like the async operation took much longer than it actually did. The user would ask questions like "why did my timeout take 200 ms, when I set it to 100 ms?" or "why is my filesystem so slow?".

I don't known if it is possible but I think a asyncReady event is missing. This would emit when the async operation is done. I'm guessing there is some interrupt causing a push the job queue that one could listen on, but I don't know. Emitting the event immediately would be problematic, as the javascript program would jump in a sync state. So I guess asyncReady it will just have to be executed right after the current callback is done. This would fix the fs.open example, but not the setTimeout example.

[Qard]

When the thread is done and when it can get inserted back into the main thread are two different things. If some sync code continues to block past when the async thing is done, there'd be no way for it to enter the suggested "ready" callback.

fs.readFile(file, function (err, data) {
  console.log('data is', data)
})

var now = Date.now()
var then = now + 1000
while (Date.now() < then) {
  // Main thread is still busy in here when readFile is done.
  // Therefore, it can not trigger some async_wrap callback.
}

[AndreasMadsen]

Yeah, that is the timeout example, that I don't think can be solved.

But if you have:

for (var i = 0; i < 1000; i++) {
  fs.open(file[i], 'r', function (err, fd) {
    var now = Date.now()
    var then = now + 10
    while (Date.now() < then);
  })
}

setTimeout(function () {
  // May first emit after 1000 x 10 ms
}, 20);

then it should be possible to emit a asyncReady event after two fs.open callbacks (20 ms), as the main thread is not in a blocking state. But the actual setTImeout callback may first be called after a while (1000 x 10 ms).

[hayes]

I have been thinking a lot about this specific issue. A simple alternative
would be to pass along a timestamp when the before hook is called. It
would probably be relatively easy to capture a timestamp when async tasks
complete. Injecting new things into the queue of things to run sounds like
a much bigger challenge
On Mar 23, 2015 1:39 PM, "Andreas Madsen" [email protected] wrote:

Yeah, that is the timeout example, that I don't think can be solved.

But if you have:

for (var i = 0; i < 1000; i++) {
fs.open(file[i], 'r', function (err, fd) {
var now = Date.now()
var then = now + 10
while (Date.now() < then);
})
}
setTimeout(function () {
// May first emit after 1000 x 10 ms
}, 20);

then it should be possible to emit a asyncReady event after two fs.open
callbacks (20 ms), as the main thread is not in a blocking state. But the
actual setTImeout callback may first be called after a while (1000 x 10
ms).

—
Reply to this email directly or view it on GitHub
#11 (comment).

[AndreasMadsen]

Yeah, that would be fine too. I think it would need some kind of async_wrap flag, as getting timestamps can be a bit expensive.

[trevnorris]

Don't forget that the _asyncQueue object property should be attached to the this in init. So you can check each individually. e.g.

function init() {
  this._asyncQueue = { init: process.hrtime() };
}

function before() {
  this._asyncQueue.before = process.hrtime();
  // capture time between init and when before was able to run
}

function after() {
  // capture time between before and when after was able to run
}

And if all you want to do is get past the synchronous execution stack then use process.nextTick(). Will only be an exact measurement if it's the first call on the nextTickQueue, but we could work around that in the future. e.g.

function before() {
  var t = process.hrtime();
  process.nextTick(function() {
    // print time difference
  });
}

[trevnorris]

Now as far as knowing when the call has actually completed, well you're SOL. Receiving the response from the kernel will be blocked until the sync script is done running, so the only way to get around that would be to accept completed requests from another thread so sync execution wouldn't disrupt the time. But because on Windows the port it tied to the handle it's impossible to do this. Sorry, but unless I'm missing some black magic that's never going to happen.

[AndreasMadsen]

@trevnorris Maybe I don't understand the effect of the before + process.nextTick that you are suggesting. But I think you just didn't understand me. Let me try again:

The this._asyncQueue queue trick is how I'm doing it now. It is what I'm referring to when I write beforeTimestamp - initTimestamp. But it is a miss leading number.

To not get misleading numbers, one would need something earlier than before. This early event doesn't have to emit immediately when the non-blocking operation is done, because that is likely impossible. But if there is something in between immediately and before then that it much a much better approximation.

If I understand correctly the order of execution for a event loop turn is:

before[1], callback[1], after[1], before[2], callback[2], after[2], idle

What I'm suggesting is that maybe there is a way to do:

early[1], early[2], before[1], callback[1], after[1], before[2], callback[2], after[2], idle

This will not be a perfect approximation, but it will be a better approximation if callback[1] and callback[2] takes a long time to execute.

To get the same effect using exciting API, one could perhaps use a recursive loop of setImmediate to get the time and then use this time in before[i]. But it would be ridiculous inefficient.

[trevnorris]

@AndreasMadsen I got you, and that's what my second comment above addresses (about being SOL). The completed requests are queued by the kernel and wait patiently for the event loop to retrieve them. Since the event loop is too busy to retrieve these completed requests from the internal queue, it's also too busy to notify you that the request has been completed. You can only be notified of exactly how long a request took if your script is ready to accept the request from the internal queue the moment it's queued. But in that case it'll call the before callback anyway.

[AndreasMadsen]

@trevnorris Okay, that makes sense. I though the callback queue was maintained by v8. This makes things a bit more difficult :)

[trevnorris]

@AndreasMadsen The only way I know of to get around this, to know the exact time of a request, is to perform the request on another thread. Unfortunately that's impossible for a few reasons. If you have any good ideas, let me know, but right now I can't see any way around it.

[joshgav]

closing old AsyncWrap issues, please start a new thread if appropriate