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

tst.postmortem_jsstack.js occasionally fails spuriously #38

Open
davepacheco opened this issue Oct 2, 2015 · 3 comments
Open

tst.postmortem_jsstack.js occasionally fails spuriously #38

davepacheco opened this issue Oct 2, 2015 · 3 comments
Labels

Comments

@davepacheco
Copy link
Contributor

While testing the fix for #32, I ran into an intermittent failure that I don't believe is a result of that change. I tested each combination of (v0.10.40, v0.12.7, v4.0.0) x (ia32, amd64). In two full runs of the test suite in each configuration, I saw this issue twice: once on v.10.40 ia32, and once on v4.0.0 amd64.

The failure looks like this:

$ cat /var/tmp/catest.95605/failure.0/README 
/home/dap/mdb_v8/test/standalone/tst.postmortem_jsstack.js failed: test returned 1

$ cat /var/tmp/catest.95605/failure.0/*.err

assert.js:89
  throw new assert.AssertionError({
  ^
AssertionError: unexpected frame where stalloogle was expected; core retained as /var/tmp/node.98845
    at ChildProcess.<anonymous> (/home/dap/mdb_v8/test/standalone/tst.postmortem_jsstack.js:110:11)
    at emitTwo (events.js:87:13)
    at ChildProcess.emit (events.js:172:7)
    at Process.ChildProcess._handle.onexit (internal/child_process.js:200:12)

and the core file looks like this:

$ mdb /var/tmp/node.98845
Loading modules: [ libumem.so.1 libc.so.1 ld.so.1 ]
> ::load build/amd64/mdb_v8.so
mdb_v8 version: 1.0.0 (dev)
V8 version: 4.5.103.30
Autoconfigured V8 support from target
C++ symbol demangling enabled

> ::jsstack
native: libc.so.1`__getloadavg+0xa
native: _ZN4node2osL10GetLoadAvgERKN2v820FunctionCallbackInfoINS1_5Value...
        (1 internal frame elided)
js:     <anonymous> (as doogle)
js:     listOnTimeout
        (1 internal frame elided)
        (1 internal frame elided)
native: v8::internal::Execution::Call+0x107
native: v8::Function::Call+0xff
native: v8::Function::Call+0x41
native: node::AsyncWrap::MakeCallback+0x10e
native: node::TimerWrap::OnTimeout+0x96
native: uv__run_timers+0x7d
native: uv_run+0x35a
native: node::Start+0x528
native: _start+0x6c
> 

I suspect (but haven't proved) that V8 is inlining some function calls.

@misterdjules
Copy link
Contributor

I suspect (but haven't proved) that V8 is inlining some function calls.

It seems this is definitely what's happening.

I collected the output of node --trace-opt --trace-deopt test/standalone/tst.postmortem_jsstack.js when it fails and when it passes.

We can see that when the test fails, the following optimizations are traced:

[marking 0xde4e09bf51 <JS Function stalloogle (SharedFunctionInfo 15d313b3fb71)> for recompilation, reason: small function, ICs with typeinfo: 2/2 (100%), generic ICs: 0/2 (0%)]
[optimizing 0xde4e00f431 <JS Function isEmpty (SharedFunctionInfo 1654520f6b99)> - took 0.036, 0.161, 0.026 ms]
[completed optimizing 0xde4e00f431 <JS Function isEmpty (SharedFunctionInfo 1654520f6b99)>]
[marking 0xde4e09bf99 <JS Function bagnoogle (SharedFunctionInfo 15d313b3fc19)> for recompilation, reason: small function, ICs with typeinfo: 4/4 (100%), generic ICs: 0/4 (0%)]
[marking 0xde4e09bfe1 <JS Function doogle (SharedFunctionInfo 15d313b3fcc1)> for recompilation, reason: small function, ICs with typeinfo: 4/4 (100%), generic ICs: 0/4 (0%)]
[optimizing 0xde4e00f3e9 <JS Function append (SharedFunctionInfo 1654520f6af1)> - took 0.123, 0.429, 0.252 ms]
[completed optimizing 0xde4e00f3e9 <JS Function append (SharedFunctionInfo 1654520f6af1)>]
[compiling method 0xde4e09bfe1 <JS Function doogle (SharedFunctionInfo 15d313b3fcc1)> using Crankshaft]
[compiling method 0xde4e09bf99 <JS Function bagnoogle (SharedFunctionInfo 15d313b3fc19)> using Crankshaft]
[compiling method 0xde4e09bf51 <JS Function stalloogle (SharedFunctionInfo 15d313b3fb71)> using Crankshaft]
[optimizing 0xde4e09bfe1 <JS Function doogle (SharedFunctionInfo 15d313b3fcc1)> - took 0.161, 0.158, 0.084 ms]
[completed optimizing 0xde4e09bfe1 <JS Function doogle (SharedFunctionInfo 15d313b3fcc1)>]
[optimizing 0xde4e09bf51 <JS Function stalloogle (SharedFunctionInfo 15d313b3fb71)> - took 0.028, 0.141, 0.061 ms]
[completed optimizing 0xde4e09bf51 <JS Function stalloogle (SharedFunctionInfo 15d313b3fb71)>]
[optimizing 0xde4e09bf99 <JS Function bagnoogle (SharedFunctionInfo 15d313b3fc19)> - took 0.058, 0.451, 0.552 ms]
[completed optimizing 0xde4e09bf99 <JS Function bagnoogle (SharedFunctionInfo 15d313b3fc19)>]

and there's no trace for any deoptimization of those functions. On the other hand, the output for when the test passes does not contain any trace of optimizations for any of the functions that this test wants to see on the stack.

V8 provides an intrinsic named NeverOptimizeFunction that allows to mark a function as not to ever optimize. It has to be called before any call to the function to mark. It seems we could use that to make tst.postmortem_jsstack.js run (and pass) consistently.

With the following changes to test/standalone/tst.postmortem_jsstack.js:

diff --git a/test/standalone/tst.postmortem_jsstack.js b/test/standalone/tst.postmortem_jsstack.js
index cc0f22d..48d56a3 100644
--- a/test/standalone/tst.postmortem_jsstack.js
+++ b/test/standalone/tst.postmortem_jsstack.js
@@ -38,6 +38,10 @@ var doogle = function () {
        bagnoogle('The bfs command', '(almost) like ed(1)');
 };
 
+%NeverOptimizeFunction(stalloogle);
+%NeverOptimizeFunction(bagnoogle);
+%NeverOptimizeFunction(doogle);
+
 var spawn = require('child_process').spawn;
 var prefix = '/var/tmp/node';
 var corefile = prefix + '.' + process.pid;

I'm able to consistently get that test to pass when running it with node --allow-natives-syntax, and the output I get from running that with --trace-deopt --trace-opt does not contain any mention of optimizing any of the three relevant functions in that test.

So here's the implementation I suggest in order to fix that test:

  1. Specify flags to pass to node to allow the use of V8 intrinsics as code comments in the test file (like // node-args: --allow-natives-syntax).

  2. Have tools/runtests_node parse these comments and pass the argument(s) to node by adding a -n command line option to catest. In the case of tst.postmortem_jsstack.js, tools/runtests_node would invoke catest as catest -a -n "--allow-natives-syntax".

  3. Call %NeverOptimizeFunction to mark the three relevant functions in tst.postmortem_jsstack.js as not optimizable.

How does that sound?

@misterdjules
Copy link
Contributor

Have tools/runtests_node parse these comments and pass the argument(s) to node by adding a -n command line option to catest. In the case of tst.postmortem_jsstack.js, tools/runtests_node would invoke catest as catest -a -n "--allow-natives-syntax".

I actually got confused, this is not how tools/runtests_node and catest work. So this would have to change to either catest parsing these comments that specify what arguments to pass to the node executable, or we could also have tools/runtests_node still do that and catest would run every JS test with the same set of command lin arguments.

I have a preference for the former, but I'm not sure if that's in scope of catest.

@davepacheco
Copy link
Contributor Author

catest is a general-purpose test-runner, and we shouldn't have local changes to it. We could create the idea of a catest configuration file that determines what commands are run based on file extension and use that in this project to change how it runs .js files.

I'm not sure whether we want to be testing with optimizations off or not. If mdb_v8 does the wrong thing with optimizations, that's pretty unfortunate. On the other hand, if that's only because this sequence of calls is so simple, and it's not that realistic a scenario, then maybe the test is just too simple. In that case, we could make it more realistic (in a way that wouldn't be inlined) or just make the proposed change (on the assumption that we're testing the more realistic case by doing that).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants