Support long stacks

[jods4]

Aurelia dispatches a lot of things to its TaskQueue, in particular all the observed model changes. The drawback of this is that whenever some piece of code crashes, much of the callstack is lost.

In particular, in IE the callstack is completely lost, with just the TaskQueue present (since it rethrows in a task). In Cr, FF and Edge the situation is better because the .stack is created at new Error and not changed when rethrowing. Yet, finding what caused the task to be enqueued in the first place is nearly impossible.

Consider this example code:

let { TaskQueue } = require('./dist/commonjs/index.js');

let queue = new TaskQueue();
root();

function root() {
    queue.queueTask(nested);
}

function nested() {
    queue.queueMicroTask(frob);
}

function frob() {
    fail();
}

function fail() {
    throw new Error("Bar");
}

In IE the result is useless. In other browser the stack looks like this:

Error: Bar
    at fail (C:\Github\task-queue\demo.js:19:11)
    at frob (C:\Github\task-queue\demo.js:15:5)
    at TaskQueue.flushMicroTaskQueue (C:\Github\task-queue\dist\commonjs\aurelia-task-queue.js:142:14)
    at C:\Github\task-queue\dist\commonjs\aurelia-task-queue.js:78:22
    at Timeout.handleFlushTimer (C:\Github\task-queue\dist\commonjs\aurelia-task-queue.js:39:7)
    at tryOnTimeout (timers.js:228:11)
    at Timer.listOnTimeout (timers.js:202:5)

This is better but it is impossible to know why frob was called.

With my PR, the result looks like that instead:

Error: Bar
    at fail (C:\Github\task-queue\demo.js:19:11)
    at frob (C:\Github\task-queue\demo.js:15:5)
Enqueued in MicroTaskQueue by:
    at nested (C:\Github\task-queue\demo.js:11:11)
Enqueued in TaskQueue by:
    at root (C:\Github\task-queue\demo.js:7:11)
    at Object.<anonymous> (C:\Github\task-queue\demo.js:4:1)
    at Module._compile (module.js:541:32)
    at Object.Module._extensions..js (module.js:550:10)
    at Module.load (module.js:458:32)
    at tryModuleLoad (module.js:417:12)
    at Function.Module._load (module.js:409:3)

Which is awesome (I think). 😆

Note that this doesn't enable real long call stacks in the debugger (with evaluation in past contexts, etc), which is AFAIK not possible.

TODO: collecting the stacks on every task has a small perf impact, which is why I put the feature behind a flag longStacks at the top of the module. I leave it to you to decide how this flag should be enabled/disabled, I thought that maybe aurelia.use.developmentLogging() would be a good place for that.

[jdanyow]

awesome!!!

[stsje]

Lovely feature, very useful!

I'm just afraid there might be a performance impact. Especially the function captureStack looks troublesome. Throwing an error and catching it again for every task will take a lot of time. Building a stack trace has never been quick.

Would love some performance metrics, so we can judge if it's even a good idea for development.

[jods4]

@stsje That's why the whole thing is behind a longStacks flag. If it's too slow for you or you depend on call stacks for some reason, don't use it.

This PR doesn't say how/when the flag is manipulated, though, that is left to decide.

My idea is that it should be false by default and enabled by .use.developmentLogging(), maybe with an override .use.developmentLogging({ longStacks: false }).

[EisenbergEffect]

Definitely we want this behind a flag. We also would like to see if @jdanyow can do some perf benchmarking as well.

[EisenbergEffect]

Just dropping in to let you all we haven't forgotten about this. @jdanyow is working on getting a major update to validation out. I believe after that he's going to get our benchmarking suite updated and then we can test this change to see what we think.

[EisenbergEffect]

@jdanyow How is your workload? Do you have some time to update the benchmark suite so we can start looking at things like this PR?

[EisenbergEffect]

@jdanyow I assigned this to you as reminder to update the benchmark runner so we can investigate this :)

[jods4]

@EisenbergEffect @jdanyow After an Aurelia update on one of my projects I found myself having to debug infinite loops in binding changes... and really wishing I could have the full flow of information!

Can we merge this? If the only concern is about perf, we could merge this as a 100% opt-in feature. So no impact unless the dev actively asks for the feature: aurelia.use.developmentLogging({ longStacks: true }).

Or maybe a global switch that can be turned on and off at any point, even from the browser console?

> require('aurelia-task-queue').enableLongStacks = true;
// do some debugging

Real benchmarks would be interesting but it's been 4 months now... :(

The global switch in aurelia-task-queue would make it kind of a "hidden" feature, which has little impact and we can decide on a public API (useDevelopmentLogging) later after some initial feedback.

[EisenbergEffect]

@jdanyow It would be nice to have this. What do you think?

[jdanyow]

The PR looks great. I haven't had time to update the benchmark runner. I put together a quick gist that uses benchmark.js to compare the current task queue with the code in the PR with long stacks off and with long stacks on. Based on the results I'm confident this is safe to merge once the API for turning it on and off is ironed out.

In the gist I added a static setLongStacks(value: boolean) method to the TaskQueue class. There's big perf impact when you turn on long stacks so we probably shouldn't turn it on by default with developmentLogging.

Here's the benchmark and the results I saw on my Thinkpad X1 Carbon Touch. Please give it a try on your browsers/hardware and report back what you're seeing for perf.

https://gist.run/?id=558f4a479aa2acc0f444232af0d34d8d

Firefox:

running...
standard x 2,021 ops/sec ±23.96% (17 runs sampled)
long-stacks-off x 2,270 ops/sec ±20.10% (17 runs sampled)
long-stacks-on x 19.40 ops/sec ±9.83% (34 runs sampled)
Fastest is: long-stacks-off,standard

Chrome:

running...
standard x 1,854 ops/sec ±15.89% (12 runs sampled)
long-stacks-off x 2,079 ops/sec ±15.25% (22 runs sampled)
long-stacks-on x 11.47 ops/sec ±10.14% (26 runs sampled)
Fastest is: long-stacks-off,standard

[jods4]

The perf hit (when on) is a lot worse than I thought. Not sure if it's worth it but I have an idea to make it slightly faster...

Firefox 49 on Win10, Intel i5 (4 cores, 3.2 Ghz), 8 Go RAM

running...
standard x 1,813 ops/sec ±12.22% (19 runs sampled)
long-stacks-off x 2,018 ops/sec ±11.06% (37 runs sampled)
long-stacks-on x 29.48 ops/sec ±6.75% (38 runs sampled)
Fastest is: long-stacks-off

Too bad gist doesn't work in IE, because this is where the impact will be worse (it has to throw/catch to capture stack).

[EisenbergEffect]

We should have some api to turn it on/off with off being the default directly on the TaskQueue. I would want that to be on the instance.

Then we should surface an API on the FrameworkConfiguration object so that app devs can say:

aureila.use.longStackTraces();

Thoughts?

On January 15, 2017 at 12:43:39 PM, jods (notifications@github.com) wrote:

The perf hit (when on) is a lot worse than I thought. Not sure if it's worth it but I have an idea to make it slightly faster...

Firefox on Win10, Intel i5 (4 cores, 3.2 Ghz), 8 Go RAM

running... standard x 1,813 ops/sec ±12.22% (19 runs sampled) long-stacks-off x 2,018 ops/sec ±11.06% (37 runs sampled) long-stacks-on x 29.48 ops/sec ±6.75% (38 runs sampled) Fastest is: long-stacks-off

Too bad gist doesn't work in IE, because this is where the impact will be worse (it has to throw/catch to capture stack).

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/aurelia/task-queue/pull/15#issuecomment-272722328, or mute the thread https://github.com/notifications/unsubscribe-auth/AAIBnRZP9eGHg1DRUOO5BRp23ZG4C3WPks5rSoT7gaJpZM4JgntD .

[jods4]

This is fine by me. My primary use is to temporarily enable long stacks to debug bugs that are triggered by change detection.

[jdanyow]

Agree- don't worry about the perf hit when it's turned on. Just as long as there is zero perf hit when it's off (which is what we're seeing).

@jods4 can you amend the PR with a task queue instance method or prop to turn long stacks on? Then we can get this merged and look at adding some framework sugar later.

I think you can save the gist and open it with IE from the file system to test there.

[jdanyow]

Microsoft Edge:

running...
standard x 6,127 ops/sec ±6.72% (32 runs sampled)
long-stacks-off x 5,880 ops/sec ±6.33% (37 runs sampled)
long-stacks-on x 21.48 ops/sec ±2.12% (53 runs sampled)
Fastest is: standard,long-stacks-off

[EisenbergEffect]

@jods4 Where are we at with this?

[jods4]

I moved the global flag to a member field named longStacks, set to false in ctor. There's no central API to manipulate it atm, but in the debugger you can easily change its value in the watches and then get long stacks while figuring out a problem.

[EisenbergEffect]

That sounds good. @jdanyow Would you do one final review? If it's good I'll get it merged and into the next release.