V8 Stack Trace API

[enormouspenguin]

I was just playing around with V8 Stack Trace API and came up with the following stupid code:

var log = console.log;

log(process.versions);

Error.stackTraceLimit = Infinity;

Error.prepareStackTrace = function(err, stack) {

return stack;

};

function printST() {

var obj = {};

Error.captureStackTrace(obj, printST);

log('\tStack length: ' + obj.stack.length);

}

log('Initiation:');

printST();

function recur(n) {

if(n > 1) {

return recur(--n);

}

log('recur():');

printST();

}

for(var i = 1; i <= 10; i++) {

log(i + '/');

recur(1000);

}

Which prints:

{ http_parser: '2.2',

  node: '0.11.13',

  v8: '3.25.30',

  uv: '0.11.25',

  zlib: '1.2.3',

  modules: '14',

  openssl: '1.0.1g' }

Initiation:

        Stack length: 8

1/

recur():

        Stack length: 1008

2/

recur():

        Stack length: 1008

3/

recur():

        Stack length: 0

4/

recur():

        Stack length: 1008

5/

recur():

        Stack length: 0

6/

recur():

        Stack length: 1008

7/

recur():

        Stack length: 0

8/

recur():

        Stack length: 0

9/

recur():

        Stack length: 0

10/

recur():

        Stack length: 0

Is that expected behavior? And if so, could anyone please explain it? I think it involve some kind of optimization that V8 does because different versions of node print different outputs. For example:

{ http_parser: '1.0',

  node: '0.10.29',

  v8: '3.14.5.9',

  ares: '1.9.0-DEV',

  uv: '0.10.27',

  zlib: '1.2.3',

  modules: '11',

  openssl: '1.0.1h' }

Initiation:

        Stack length: 8

1/

recur():

        Stack length: 1008

2/

recur():

        Stack length: 0

3/

recur():

        Stack length: 0

4/

recur():

        Stack length: 0

5/

recur():

        Stack length: 0

6/

recur():

        Stack length: 0

7/

recur():

        Stack length: 0

8/

recur():

        Stack length: 0

9/

recur():

        Stack length: 0

10/

recur():

        Stack length: 0

[Ben Noordhuis]

On Tue, Sep 2, 2014 at 5:12 PM, enormouspenguin <kimkh...@gmail.com> wrote:
> I was just playing around with V8 Stack Trace API and came up with the
> following stupid code:
>

> [snip]

>
> Is that expected behavior? And if so, could anyone please explain it? I
> think it involve some kind of optimization that V8 does because different
> versions of node print different outputs.

It's a V8 bug, I've grappled with it before. And you're right, it's
an issue (sort of) with the optimizer.

The second argument to Error.captureStackTrace() is the "stack top"
function, the function whose stack frame capturing starts at.
Everything at or above the stack top frame is filtered, everything
below it is captured.

What happens in your test is that V8 misses the stack top when there
is an exit frame on the stack (a call into the C++ run-time) from
self-optimizing JS code. You can work around it in JS like this:

function printST(x) {
// Put another printST frame on the stack.
if (x !== 42) return printST(42);
// ...
}

I wrote a patch some time ago that adds raw_frame->is_exit() checks in
the right places but as I wasn't sure whether my approach was sound
and I didn't have time to go through multiple review rounds, I never
sent it upstream. You know what the score is now, you're welcome to
give it a try. :-)

[enormouspenguin]

Looks like I have just wandered myself far off into some pretty low level C++ stuff that I have little to no knowledge about. Sorry but I couldn't understand over half of your reply (only the "stack top" function explanation part that I think I do understand, the rest is some kind of mystery). A lot of naive questions pop up in my head:

_ Where should I insert that code snippet? Why the 42 check? Is 42 some kind of magic number?
_ Why pass x to printST() while it's main purpose is just simply print out stack length that needs no argument? If x is necessary then what is the value of x should I pass? Where should I call the new printST(x)?
_ What is self-optimizing JS code, isn't V8 responsible for optimization process of JS run-time? Should I do self-optimizing a lot?
_ Where is raw_frame located in C++ source files? How can an exit frame generated where I couldn't see any line of code I wrote that call a Node.js native C++ addon?
_ Is the call stack behavior different and unpredictable in live-optimized and interpreted languages like JS compare to pre-optimized and then compiled languages like C? If an exit frame wipe out entire current stack then how could Node.js profiling be accurate?

You are welcome to just ignore me because that is a lot of questions and I am in a totally different and extremely lower level than you (I have no experience in C/C++, although I did learn some in my university). I feel embarrassed to even ask the question in the first place. But still I want to learn more (university seem never enough) . So any direction pointing would be much appreciated. Thank you for your time.

[Ben Noordhuis]

On Wed, Sep 3, 2014 at 10:32 AM, enormouspenguin <kimkh...@gmail.com> wrote:
> Looks like I have just wandered myself far off into some pretty low level C++ stuff that I have little to no knowledge about. Sorry but I couldn't understand over half of your reply (only the "stack top" function explanation part that I think I do understand, the rest is some kind of mystery). A lot of naive questions pop up in my head:
>
> _ Where should I insert that code snippet? Why the 42 check? Is 42 some kind of magic number?
> _ Why pass x to printST() while it's main purpose is just simply print out stack length that needs no argument? If x is necessary then what is the value of x should I pass? Where should I call the new printST(x)?

42 is only a magic number insofar that it acts as a marker. Calling
printST() recursively once ensures that there are two printST stack
frames when the stack is captured. Because of a bug, V8 skips the
first one but then picks up the second one.

> _ What is self-optimizing JS code, isn't V8 responsible for optimization process of JS run-time? Should I do self-optimizing a lot?

Self-optimizing means that the generated native code for a JS function
keeps track of when it can be optimized.

For context, V8 consists of two compilers: the baseline and the
optimizing compiler. The baseline compiler generates slow code fast,
the optimizing compiler generates fast code slowly (to a first
approximation.)

Code generated by the baseline compiler contains heuristics like "how
often has this function been called?". It's those heuristics that
decide when to call the optimizing compiler. See [0] for a more
detailed explanation.

[0] http://wingolog.org/archives/2011/07/05/v8-a-tale-of-two-compilers

> _ Where is raw_frame located in C++ source files? How can an exit frame generated where I couldn't see any line of code I wrote that call a Node.js native C++ addon?

They're inserted into the generated code with the mechanism from the
previous paragraph. It's an implementation detail that you normally
wouldn't have to worry about. All the relevant code is in deps/v8/src
if you're curious.

> _ Is the call stack behavior different and unpredictable in live-optimized and interpreted languages like JS compare to pre-optimized and then compiled languages like C? If an exit frame wipe out entire current stack then how could Node.js profiling be accurate?

The exit frame (maybe "transition frame" is a better name but exit
frame is what V8 calls it) doesn't wipe out the stack but it puts it
in a configuration that V8 code elsewhere isn't quite able to cope
with.

By the way, the profiler (the --prof switch) is quite different from
the optimizer. It's a sampling profiler, it doesn't instrument native
code; it just collects samples of the program state at a fixed
interval.

> You are welcome to just ignore me because that is a lot of questions and I am in a totally different and extremely lower level than you (I have no experience in C/C++, although I did learn some in my university). I feel embarrassed to even ask the question in the first place. But still I want to learn more (university seem never enough) . So any direction pointing would be much appreciated. Thank you for your time.

No problem, happy to help. Let me know if things are still unclear.
V8 is pretty large and complex, there's a lot to take in.

[enormouspenguin]

Great explanation. Although, It took novice-me quite some time to dig in and digest. V8 is really "pretty large and complex" just as you said. The topic of V8 deserve full-time dedication in order to catch up. So, for now I am happy with the little bit of under the hood knowledge I just obtain. Just FYI, your fix for my code to mitigate the V8 bug works flawlessly. Just to check if my understanding of the 42 check is correct, I modify it a little bit (shorter, less typing):

function printST(x) {

if(!x) {

return printST(1);

}

var obj = {};

Error.captureStackTrace(obj, printST);

log('\tStack length: ' + obj.stack.length);

}

It also works just like your fix. Any chance the C++ fix (not the JS above) going to upstream Node.js, or better V8?

I am interested in call stack (also stack trace API) because I am writing a module (for my private project) that organize and execute a arbitrary long sequence of functions, using next() callback to signal completion at each one, inspired by Connect pipeline. But my module encourage both sync and async style of continuation. Therefore, I want to find a way to mitigate call stack growth potential problem when doing sync. And also a way to correctly test it if I could figure out a solution (It's a work in progress though).

I thought of using nextTick() as a fast and reliable built-in trampoline (to eliminate tail-call). But what I think I need is a way to insert a function to the head of the queue (like stack), not the back as nextTick() does. The queue output direction remains the same. The rationale is that I want to ensure the next function will always be executed right after the current one, but before everything else. Do you have any advice on this?

Lastly, a tiny problem, any ideas why my code kept not being highlighted although I used the "Highlight code syntax" button before entering it? It annoys and also embarrasses me to post my code for others to see but have no highlight.

[Ben Noordhuis]

Sorry, missed your reply. Replies inline.

On Fri, Sep 5, 2014 at 5:37 PM, enormouspenguin <kimkh...@gmail.com> wrote:
> Great explanation. Although, It took novice-me quite some time to dig in and
> digest. V8 is really "pretty large and complex" just as you said. The topic
> of V8 deserve full-time dedication in order to catch up. So, for now I am
> happy with the little bit of under the hood knowledge I just obtain. Just
> FYI, your fix for my code to mitigate the V8 bug works flawlessly. Just to
> check if my understanding of the 42 check is correct, I modify it a little
> bit (shorter, less typing):
>
> function printST(x) {
> if(!x) {
> return printST(1);
> }
> var obj = {};
> Error.captureStackTrace(obj, printST);
> log('\tStack length: ' + obj.stack.length);
> }
>
> It also works just like your fix. Any chance the C++ fix (not the JS above)
> going to upstream Node.js, or better V8?

I don't think I have time to work on it myself but if someone wants to
take a stab, I'll be happy to review their work.

> I am interested in call stack (also stack trace API) because I am writing a
> module (for my private project) that organize and execute a arbitrary long
> sequence of functions, using next() callback to signal completion at each
> one, inspired by Connect pipeline. But my module encourage both sync and
> async style of continuation. Therefore, I want to find a way to mitigate
> call stack growth potential problem when doing sync. And also a way to
> correctly test it if I could figure out a solution (It's a work in progress
> though).
>
> I thought of using nextTick() as a fast and reliable built-in trampoline (to
> eliminate tail-call). But what I think I need is a way to insert a function
> to the head of the queue (like stack), not the back as nextTick() does. The
> queue output direction remains the same. The rationale is that I want to
> ensure the next function will always be executed right after the current
> one, but before everything else. Do you have any advice on this?

I'm not quite sure what "before everything else" means here but what I
think you are asking is whether callbacks / continuations should run
in FIFO or LIFO order? That's up to you, really, but if
process.nextTick()'s FIFO order doesn't work for you, you can always
implement LIFO on top of that. E.g.:

var fs = [];
function cont(f) {
if (fs.unshift(f) === 1) process.nextTick(function() {
fs.splice(0, fs.length).forEach(function(f) { f(); });
});
}

Aside, ES6 will have proper tail recursion optimization (TCO) but I
don't think that has been implemented in V8 so far.

> Lastly, a tiny problem, any ideas why my code kept not being highlighted
> although I used the "Highlight code syntax" button before entering it? It
> annoys and also embarrasses me to post my code for others to see but have no
> highlight.

I don't know, I don't use the web interface. I wouldn't worry about it, though.

[enormouspenguin]

Your responses clear up many problems that I struggled for a long time. I think I have had enough info to move on now. It has been a great pleasure and eyes opening talking to you. Thank you very much.

[enormouspenguin]

Hi again, if you are still interested, I found another hacky fix in JS. Instead of having to call the printST() twice, I could just use arguments.callee to pass to Error.captureStackTrace(). The printST() now become as simple as this:

function printST(bl) {

var obj = {};

Error.captureStackTrace(obj, arguments.callee);

log('\tStack length: ' + obj.stack.length);

}

I don't know how it works, but my theory is that there are some special internal variables attached to arguments that makes it work. I checked, printST === arguments.callee is true but some how using arguments.callee instead of direct function name make a whole lot difference.

Another side detail, that fix didn't just come out of the sky, I saw it in callsite module of TJ Holowaychuk. I thought I should give it a try, and it magically works. Somehow he had thought it through and come up with the beautiful solution. My hat's off to him. This bug also affect stack-trace module of Felix Geisendörfer but I don't have enough confidence to send him a PR. May be I will just send him an Issue.

You don't need to answer this. I just found something interesting and I thought maybe you would want to know.

[Yang Guo]

Is this still an issue with the newest V8? I can't reproduce this on 3.31.

[enormouspenguin]

Really, that's great to know that V8 team fixed it (but I couldn't test and confirm it by my self right now). Though, node.js still haven't upgraded yet. Node v0.11.14 still goes with V8 v3.26. Also node v0.10.33 goes with V8 v3.14. I guess I will just have to wait for future node releases because I don't want to mess too much with compatibility stuffs between the two.

[Axel Kittenberger]

Maybe I miss something, but so I always just did:

"(new Error()).stack.split('\n');"

to get a backtrace, when needed for debugging.

Futher autmatic string processing if needed. These stacktraces from a pseudo Error are correct for me in the original example.

--
Job board: http://jobs.nodejs.org/
New group rules: https://gist.github.com/othiym23/9886289#file-moderation-policy-md
Old group rules: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
---
You received this message because you are subscribed to the Google Groups "nodejs" group.
To unsubscribe from this group and stop receiving emails from it, send an email to nodejs+un...@googlegroups.com.
To post to this group, send email to nod...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/nodejs/0e95c1fa-9b9a-46c4-9536-6a160cdb977c%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[enormouspenguin]

But then, you will have to correctly parse it to get useful information. It's not much, but parsing still cost some processing time. Not to mention the amount of information you get is less than using native CallSite object. The situation I am in is not just only for simple manual on-screen debugging, but also getting as much as possible info out for some other personal purposes without incurring much performance penalty. Why letting V8 stringify it and then we have to parse it later to get even less amount of data than before the stringify while we could prevent all that from happening in the first place?