[ANN] long-stack-traces

[Tom Robinson]

"long-stack-traces" is an implementation of, well, "long stacktraces" that span multiple events (idea based on http://nodejs.org/illuminati0.pdf):

* Get the code: https://github.com/tlrobinson/long-stack-traces
* Install in Node: npm install long-stack-traces
* Enable upon startup (BEFORE any callbacks are registered): require("long-stack-traces")
* Try it out by running "node examples.js":

$ node examples.js
Uncaught Error: readFile
at Object.secondTimeout (/Users/tlrobinson/git/long-stack-traces/examples.js:7:15)
at Timer.callback (timers.js:62:39)
----------------------------------------
at Object.setTimeout
at initSecondTimeout (/Users/tlrobinson/git/long-stack-traces/examples.js:6:5)
at /Users/tlrobinson/git/long-stack-traces/examples.js:24:7
at [object Object].<anonymous> (fs.js:86:5)
at [object Object].emit (events.js:39:17)
at afterRead (fs.js:773:12)
----------------------------------------
at EventEmitter.on
at Object.readFile (fs.js:63:14)
at onload (/Users/tlrobinson/git/long-stack-traces/examples.js:22:8)
at Object.<anonymous> (/Users/tlrobinson/git/long-stack-traces/examples.js:28:1)
at Module._compile (node.js:423:30)
at Object..js (node.js:429:14)
at Module.load (node.js:355:35)
at Array.0 (node.js:443:26)
at EventEmitter._tickCallback (node.js:60:24)

Please give it a try and let me know what you think. It supports any APIs that use EventEmitter or setTimeout. File a ticket on GitHub (https://github.com/tlrobinson/long-stack-traces/issues) if it's missing stuff.

It's implemented in JavaScript (using a few, um, interesting tricks) so it can easily be enabled/disabled without recompiling Node. It also has the benefit of working in unmodified Chrome with setTimeout, addEventListener, and XMLHttpRequest.

One thing I would like to improve is making it even easier to enable/disable. A command-line argument or environment variable to enable it would be ideal.

AFAIK there's no way to automatically require a non-core module upon Node startup. Is something like that generally useful enough that it could be added to Node? Alternatively, is there some way I could hack it into Node using an npm install hook or something? With the user's permission, of course.

Thanks,

-tom

[Dominic Tarr]

wow! this looks super useful!

great work!

--
You received this message because you are subscribed to the Google Groups "nodejs" group.
To post to this group, send email to nod...@googlegroups.com.
To unsubscribe from this group, send email to nodejs+un...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/nodejs?hl=en.

[Ryan Dahl]

This is super cool - I can't believe you did it in "user space". Are
you finding this to be a useful debugging tool?

I can't think of any appropriate hooks to put this in before it loads
the program - but we can add one...

Ryan

[Jorge]

BTW, I proposed to do it exactly like that back (to you and Tim) in october 2010 : http://groups.google.com/group/nodejs/msg/722dc0862577a1bd
https://github.com/xk/nodeSnippets/blob/master/nodeErrorsHowTo.js

Just sayin'
--
Jorge.

[Tom Robinson]

To be honest I haven't actually used it beyond the examples in the repo, I just hacked it together in the last couple days, so I'd love to get feedback from heavy Node users.

> BTW, I proposed to do it exactly like that back (to you and Tim) in october 2010 : http://groups.google.com/group/nodejs/msg/722dc0862577a1bd
> https://github.com/xk/nodeSnippets/blob/master/nodeErrorsHowTo.js
>
> Just sayin'

Similar idea, but this is totally seamless. Just load the file before you register any callbacks and you get long stack traces automagically.

There are a few key parts:

1) Wrap async callback "registration functions" (addListener, setTimeout, etc) so that they saves the stack trace (in the closure) at time of callback registration.
2) Wrapped addListener/setTimeout then automatically wraps callbacks passed to the registration function in the same closure so the trace can be restored when it's executed.
3) A custom Error.prepareStackTrace method appends the currently restored stack trace (if any) to any newly formatted trace. https://code.google.com/p/v8/wiki/JavaScriptStackTraceApi (I have a feeling that wasn't the intended use but it happens to be just what we need)

This works recursively, so stack traces can span more than just 2 events.

-tom

[Jorge]

On 26/01/2011, at 19:54, Tom Robinson wrote:
> There are a few key parts:
>
> 1) Wrap async callback "registration functions" (addListener, setTimeout, etc) so that they saves the stack trace (in the closure) at time of callback registration.

Exactly, that was exactly the key idea: http://groups.google.com/group/nodejs/msg/722dc0862577a1bd

"As there's no way to go back in time to the point where the callback function was setup as a callback, istm, all that one could do is to save the stack trace at the point of setup so that it can be recovered later if needed (if it ever throws). "

You've done a good job.
--
Jorge.

[Mihai Călin Bazon]

Wouldn't this slow down considerably each and every listener registration?

> --
> You received this message because you are subscribed to the Google Groups "nodejs" group.
> To post to this group, send email to nod...@googlegroups.com.
> To unsubscribe from this group, send email to nodejs+un...@googlegroups.com.
> For more options, visit this group at http://groups.google.com/group/nodejs?hl=en.
>
>

--
Mihai Bazon,
http://mihai.bazon.net/blog

[Tom Robinson]

I haven't benchmarked it, so I can't say exactly, but I doubt the overhead is significant enough to inhibit development or debugging.

The nice thing is since it's implemented in JavaScript it can easily be enabled/disabled when necessary (it should probably always disabled in production)

-tom

[Jorge]

On 26/01/2011, at 22:48, Mihai Călin Bazon wrote:

> Wouldn't this slow down considerably each and every listener registration?

Yes...
--
Jorge.

[Marco Rogers]

This is awesome Tom.  I saw the stack trace api and was hoping someone would attempt something like this.  I'm going to try it out in my test suites. I've been doing crappy things in order to keep track of which tests throw which errors. This should be just the ticket.

Ry, how is this different from the eventsource implementation you were working on?

:Marco

[Tim Caswell]

Actually, if this is low enough overhead, you can leave it on in production and finally have a way to tie uncaught exceptions to specific http requests and send proper 500 responses.  /me will experiment...

--

[Tim Caswell]

https://gist.github.com/798121

I will release the code to the scoper middleware that makes this work after more testing and wrapping more kinds of async callbacks.  The good news is that there seems to be very little overhead.  I'm getting a solid 15k rps on my laptop (all catching the uncaught exception and sending the client a proper 500 response).  Without the addon and sending a HTTP 200 hello world response, I get the exact same speed (within statistical confidence).

One difference between this and long traces is that I'm only forwarding on a single payload object across stacks and not accumulating a longer and longer trace.  When the uncaught exception happens, it can look through the stack for the marker and call the appropriate error handler from the original middleware layer.

[Tom Robinson]

I've updated long-stack-traces (v0.1.1) to defer formatting the stack traces until absolutely necessary, which resulted in a 10X performance improvement on a "hello world" HTTP server. The overhead is still something like 33%, which isn't terrible (certainly better than before) but perhaps not production-worthy. A custom solution like yours is probably the right approach if is performance is paramount.

Here are my benchmarks (rps):

v0.1.0 enabled: 456.95

v0.1.1 enabled: 5117.23

disabled: 8211.28

Breaking it down:

wrap registration only: 8305.79

wrap registration and callback: 8069.70

wrap both + save new Error(): 5132.70

wrap both + save + restore: 5117.23

So it appears most of the remaining overhead comes from simply creating new Error objects.

-tom

[Ryan Dahl]

On Wed, Jan 26, 2011 at 8:06 PM, Marco Rogers <marco....@gmail.com> wrote:

> This is awesome Tom.  I saw the stack trace api and was hoping someone would
> attempt something like this.  I'm going to try it out in my test suites.
> I've been doing crappy things in order to keep track of which tests throw
> which errors. This should be just the ticket.
> Ry, how is this different from the eventsource implementation you were
> working on?

Mine saved/followed the stacks at the binding layer.

[Jorge]

On 27/01/2011, at 09:28, Tom Robinson wrote:

> I've updated long-stack-traces (v0.1.1) to defer formatting the stack traces until absolutely necessary, which resulted in a 10X performance improvement on a "hello world" HTTP server. The overhead is still something like 33%, which isn't terrible (certainly better than before) but perhaps not production-worthy. A custom solution like yours is probably the right approach if is performance is paramount.
>
> Here are my benchmarks (rps):
>
> v0.1.0 enabled: 456.95
> v0.1.1 enabled: 5117.23
> disabled: 8211.28
>
> Breaking it down:
>
> wrap registration only: 8305.79
> wrap registration and callback: 8069.70
> wrap both + save new Error(): 5132.70
> wrap both + save + restore: 5117.23
>
> So it appears most of the remaining overhead comes from simply creating new Error objects.

Yes, both the callback re-binding and the new Error() seem to be the most expensive parts of it:
http://jsperf.com/cost-of-trying
--
Jorge.

[Marco Rogers]

Apparently it is almost all due to the stack trace.  I updated the test.

http://jsperf.com/cost-of-trying/2

[Trindaz]

Why did this never make it into node? It's such a great feature

[Floby]

It's incredibly slow and thus unfit for production.

Also, the trycatch module has it.