AndreasMadsen / async-hook

Inspect the life of handle objects in node
MIT License
36 stars 14 forks source link

patch native promises #2

Closed omsmith closed 8 years ago

omsmith commented 8 years ago

Was just playing around, seems to work the way I would expect though.

Thoughts?

AndreasMadsen commented 8 years ago

@watson what was that tracing project that also had a Promise wrapper? It was much more complicated than this.

AndreasMadsen commented 8 years ago

@omsmith Looks good. I have a few things I need to check, I'm still not super familiar with the details of promises and how they fit into the tick/turn look.

Also I don't think the try/finally is necessary, but I will have to check.

watson commented 8 years ago

@AndreasMadsen Thinking of this one? https://github.com/othiym23/async-listener

AndreasMadsen commented 8 years ago

@watson Yes that was it. Thanks.

omsmith commented 8 years ago

I could be wrong, but it doesn't seem like this needs to be quite as complicated as async-listener is.

I was overwriting the constructor at first, but that ended up not making a whole ton of sense, since a Promise executor executes immediately/synchronously anyway, so it seemed about equivalent to just letting that be, and letting anything in the new Promise executor be tracked to the parent handle.

This could also be more complicated if you felt the context should propogate with the Promise itself. For instance I've seen some monkey-patching where then calls are associated to the context the original Promise was created in (which, in an APM, meant shared promises between transactions would mis-associate the reported work). It makes much more sense to me for work/handles created by calling then to be associated with the active handle at the time it was called.

async-listener also overwrites chain for completeness sake - though I'm not positive that's remaining in V8?

(Sorry for rambling - on my phone, would've given examples otherwise)

AndreasMadsen commented 8 years ago

(Sorry for rambling - on my phone, would've given examples otherwise)

Don't sweat it. I have exams tomorrow, so I won't be able to look at this before saturday (UTC +1)

AndreasMadsen commented 8 years ago

Some specific feedback:

omsmith commented 8 years ago

Sure thing. Thanks for taking the time to look.

omsmith commented 8 years ago

Added follow-up commits to address your specific feedback - could probably still add a test or two and then I'll squash them.

AndreasMadsen commented 8 years ago

@omsmith yeah, the execution order for the two tests I mentioned will definitely have to be tested more. You can just use the hook name together with the uid.

['init#1', 'init#2', 'pre#1', 'post#1', 'destroy#1', 'pre#2', 'post#2', 'destroy#2']

should be the execution order for both of them. Though the correctness of that order is in the second case something I have to think about.

omsmith commented 8 years ago

Added tests and a fix for a case I thought of, where a then of only onFulfilled or only onRejected isn't destroyed because the opposite path went through.

So I think that order is the best we can get, without tapping in to GC - otherwise we'll never be able to call destroy, as this is perfectly valid:

const p = Promise.resolve().then(() => { throw new Error('rejected!'); });
setTimeout(() => p.catch(console.error), 10000000000);`
omsmith commented 8 years ago

We ~can do something about this order though, which we may want to change:

Promise
  .resolve()
  .then(function a() {
    return thingWhichReturnsPromise()
      .then(function b(_) { return _; });
  })
  .then(function c(_) {
    console.log(c);
  });

Currently this would look like: 'initA', 'initC', 'preA', <snip>, 'initB', 'postA', 'destroyA', 'preB', 'postB', 'destroyB', 'preC', 'postC', 'destroyC'

It would arguably be better as: 'initA', 'initC', 'preA', <snip>, 'initB', 'postA', 'preB', 'postB', 'destroyB', 'destroyA', 'preC', 'postC', 'destroyC'

Which we could possibly do via something like:

return function wrappedHandler() {
  hooks.pre.call(handle);

  let asyncDestroy = false;
  function destroy() { hooks.destroy.call(null, uid); }
  try {
    const result = fn.apply(this, arguments);
    if (result instanceof Promise) {
      asyncDestroy = true;
      asyncHook.disable();
      result.then(destroy, destroy);
      asyncHook.enable();
    }
    return result;
  } finally {
    hooks.post.call(handle);
    if (!asyncDestroy) destroy();
  }
};
AndreasMadsen commented 8 years ago

Added tests and a fix for a case I thought of, where a then of only onFulfilled or only onRejected isn't destroyed because the opposite path went through.

Good catch.

We ~can do something about this order though, which we may want to change:

It is not the destroy timing that bothers me, it is the init timing. Consider:

new Promise(function (s, r) {
  setTimeout(s, 100); // 1
})
.then(function (v) {
  return new Promise((s, r) => setTimeout(s, 100)); // 2
})
.then();

The timing between init and pre, is such that it looks like [1] took 100 ms (fine) and [2] took 200 ms (misleading). I think it should be be:

['init#1', 'pre#1', 'init#2', 'post#1', 'destroy#1', 'pre#2', 'post#2', 'destroy#2']
omsmith commented 8 years ago

Can test, but I'm pretty sure, without changes both of the timeouts look like they take 100ms:

new Promise((s, r) => { // no handle because this is synchronous
  setTimeout(s, 100); // 1
})
.then(v => { // 2
  return new Promise((s, r) => { // no handle because this is synchronous
    setTimeout(s, 100); // 3
  });
})
.then(() => { /* 4 */ });
['initT1', 'initP2', 'initP4']
// 100ms
['preT1', 'postT1', 'destroyT1']
// tick
['preP2', 'initT3', 'postP2', 'destroyP2']
// 100ms
['preT3', 'postT3', 'destroyT3']
// tick
['preP4', 'postP4', 'destroyP4']
AndreasMadsen commented 8 years ago

@omsmith I'm talking about the time between initP4 and preP4 which as you state is 200 ms. But in my head the promise from [4] was first created when the handle / callback from [2] was called. But I could be wrong, however it will definitely appear to take 200 ms.

drof dump:

skaermbillede 2016-01-25 kl 18 14 19

edit: yeah I'm definitely wrong. Because the [2] .then callback is called in another tick, thus an proxy Promise has to be created.

omsmith commented 8 years ago

Oh okay yeah - get what you're going for now, thought you were talking about the time between pre and post and something.

I'm thinking the behaviour dprof is showing makes a lot of sense / is accurate - you could say calling .then creates an "awaiter", the wait time from creation to activation would be 200ms.

omsmith commented 8 years ago

(P.S. hope your exams went well on Friday!)

omsmith commented 8 years ago

Also, the behaviour you're describing would occur by laying out the calls differently. They're quite similar, in that they'd have the same effect overall, but the semantics are obviously ever so slightly different, in terms of "ownership" or whathaveyou.

new Promise((s, r) => { // no handle because this is synchronous
  setTimeout(s, 100); // 1
})
.then(v => { // 2
  return new Promise((s, r) => { // no handle because this is synchronous
    setTimeout(s, 100); // 3
  })
  .then(() => { /* 4 */ });
});
AndreasMadsen commented 8 years ago

I'm thinking the behaviour dprof is showing makes a lot of sense / is accurate - you could say calling .then creates an "awaiter", the wait time from creation to activation would be 200ms.

I hard for me to say what makes sense. I know about Promises but I don't use them, and in my mind I just construct the callback equivalent. When considering the callback equivalent the current init hook timing doesn't make sense, but maybe considering the callback isn't a good strategy. Promises attempt to make async code look sync, because of this design it might be correct to let the init calls come from the same stack / frame. This was also requested in https://github.com/AndreasMadsen/trace/issues/6.

Another thing that bothers, is that there is no attachment between the setTimeout callback being called and the .then handler being called. This also what appears in the dprof plot. I definitely don't consider this ideal, but I also think it is a limitation of Promises and thus not something async-hook should take care of.

If you will add tests for the hook timings, then I'm happy about this PR. Thanks for taking care of this.

P.S. hope your exams went well on Friday!

Got top grade :)

omsmith commented 8 years ago

I hard for me to say what makes sense.

Hard for anybody to I guess. There's definitely two ways you could go about it.

Consider a Promise P1 and a ~handle A, creating another Promise P2

const P1 = Promise.resolve().then(() => 'cats');
process.nextTick(function () { // A
  const P2 = P1.then(str => str + 'dogs');
});

P2 is created by A, from P1. So, which is the parent, the by or the from?

What makes most sense to me (and what is implemented by giving a null parent) is that by is the parent. But I know at least one implementation of "context tracking" has opted for from.

Using from as the parent probably maps a little bit better to the callback analogy.

Another thing that bothers, is that there is no attachment between the setTimeout callback being called and the .then handler being called.

I think that could be achieved by tracking things a little differently, creating a handle when a Promise resolves (e.g. the timeout fires and calls accept) - and doing a pre/post around each "PromiseReaction" (to use language from the spec). In this way, destroy would never happen/would have to be tied to GC.

But this goes back to the question of which way makes "sense".

If you will add tests for the hook timings, then I'm happy about this PR. Thanks for taking care of this.

Will try to work on that soon. Thanks for working through it with me.

Got top grade :)

Good to hear!

AndreasMadsen commented 8 years ago

P2 is created by A, from P1. So, which is the parent, the by or the from?

Can you explain the by and from terminology?

AndreasMadsen commented 8 years ago

In this way, destroy would never happen/would have to be tied to GC.

Yes. We will leave c++ out of this for now. When node core gets native support for Promises in async_wrap we (node Tracing WG) will reconsider the strategy.

omsmith commented 8 years ago

@AndreasMadsen sorry for letting this sit idle, had a busy couple of weeks.

Will try to get this wrapped up in the next few days

AndreasMadsen commented 8 years ago

Added the timing test myself.