Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Follow promises across resolve #40

Open
wants to merge 12 commits into
base: master
Choose a base branch
from

Conversation

jbunton-atlassian
Copy link

@jbunton-atlassian jbunton-atlassian commented Feb 6, 2018

Edited 2018-02-20 after rebasing.
Edited 2018-02-23 after fixing memory leak and rebasing.

There are four distinct changes in this PR. I'm happy to reraise them as separate PRs if that's more convenient.

This is ready for review, but still early days. I intend to try this out on some of our real services for a while. I'll let you know how that goes.

I've been running this in production for about a week now. The only serious issue was a memory leak which has been fixed.

Thanks for looking :)

Add .editorconfig and .eslintrc

EditorConfig is awesome: http://EditorConfig.org

Fix tests on newer Node.js

The tests didn't pass for me on Node.js 9.5.0. I've modified test.js to strip all Node.js lines from the stack frames. This isn't ideal because it throws away some useful data. However the tests do now pass on Node 8 and 9 :)

Fix memory leak

Unfortunately keeping references to CallSite objects causes a huge memory leak. I copy the interesting fields into a new object to work around this.

Specifically if we keep a CallSite which refers to a promise then we have created a cyclic dependency. Node will not call asyncDestroy for the promise until it is garbage collect. Because we are referencing the promise through the traces map through a CallSite we have a leak.

Follow promises across resolve

To fix issue #34 I've refactored trace.js to store trace data in a Trace object and only join stack frames when the stack is being printed.

A Trace object is created for each init callback and saved in a global map. This is linked to the trace object created for the triggerAsyncId. For non-promises this results in a linked list of objects which joins to an equivalent list of stack frames.

For promises we make use of the promiseResolve callback to link Trace objects. This results in a graph structure. By the time the stack trace is being printed we have a lot more stack frames.

Benchmark

On master

baseline: 1013.4939 ± 12300.6550 ns/tick
trace: 22190.8859 ± 89508.4342 ns/tick
done

With the copying of CallSites to fix the memory leak (commit f34d095)

baseline: 1057.6367 ± 7583.1083 ns/tick
trace: 50453.5197 ± 153317.9060 ns/tick
done

With all the new code

baseline: 1015.0815 ± 7003.2737 ns/tick
trace: 53601.3450 ± 307510.1723 ns/tick
done

With only the new promise tracking code (CallSite copying disabled)

baseline: 984.9927 ± 12584.2651 ns/tick
trace: 27590.7374 ± 125900.8123 ns/tick
done

@AndreasMadsen
Copy link
Owner

AndreasMadsen commented Feb 17, 2018

I will try and get this reviewed soon. My immediate thoughts are:

  • This makes it almost twice as slow (lower benchmark numbers are better)
  • This can't solve The dreaded "throwing after await" #34, only a new Error() hook can do that. (I talked to the V8 team and they are willing to provide that).

In any case, I have been thinking about using the promiseResolve for something so I'm interrested in seeing what this does. However, the large amount of refactors making it rather timeconsuming to understand the behavioual change from the code change.

If you could split it up that would help a lot.

@jbunton-atlassian
Copy link
Author

jbunton-atlassian commented Feb 20, 2018

Hi, thanks for taking a look :)

Yep, it's definitely slower right now. However for my use case the improved debug info is more than worth it. Most of the slowness seems to be in keeping the stackMap up to date. I tested this by setting MAX_STACKS_TO_JOIN = 1 and then becomes only 5-10% slower. If we get to the point where performance is the only objection to the PR I'll be happy to put some time into optimising that :)

It definitely does solve #34. I've tested the example from the async-test repository with an increased stackTraceLimit. I also added my own similar test case to my fork.

I've just written some pretty printing logic which should help to demonstrate what's happening if you run it. I'll also try to split it up into a few more commits.

Do you want separate PRs for the editorconfig and test.js commits?

@jbunton-atlassian jbunton-atlassian force-pushed the follow-promise-resolve branch 2 times, most recently from e44c237 to 47108d5 Compare February 20, 2018 02:14
@jbunton-atlassian
Copy link
Author

Hi again!

I've pushed up some new changes.

Fix a memory leak that exists on master

Unfortunately keeping references to CallSite objects causes a huge memory leak. I copy the interesting fields into a new object to work around this.

Specifically if we keep a CallSite which refers to a promise then we have created a cyclic dependency. Node will not call asyncDestroy for the promise until it is garbage collect. Because we are referencing the promise through the traces map through a CallSite we have a leak.

Unfortunately this naive solution makes it about 2.5x slower.

Significantly more efficient tracking of async context / promiseResolve graph

The new code for tracking Trace objects now only adds about a 25% speed penalty on its own.

Rebased everything again to try to make a comprehensible and reviewable list of commits.

Please let me know when you start reviewing this. At that point I'll stop rebasing so you can track any additions separately.

…original

This stops a memory leak. The CallSite keeps a reference to Promise
objects. This stops the Promise from being garbage collected, which
stops asyncDestroy from being called.
- For each non-destroyed async context we store a `Trace` object in
  the global `traces` map.
- A trace object contains an array of `NamedStack` objects. This is
  simply a pair of `asyncId` and `frames`.
- Whenever a new async context is created we ask the trigger Trace
  to copy its `stacks` into the newly created Trace.
- The final long stack trace is assembled only if needed. This means
  tracking `executionScopeInits` is not necessary because we can do
  the stack trace deduplication later.
- Moved `equalCallSites` next to its caller, `extendFrames`
- `equalCallSites` treats anonymous stack frames as equal
Whenever a promise resolves we copy the trigger `Trace.stacks` into
the current async context's `Trace`. We also recursively copy it into
all related Traces.

This means any Error stacks that are extended from this point on will
contain the new frames.

Note this leaks lots of memory, see the next commit for some limits.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants