Follow promises across resolve

[jbunton-atlassian]

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 f34d0957e78258166fa19f33304bef63048831b9)

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]

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 https://github.com/AndreasMadsen/trace/issues/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]

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]

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.