Confusing --trace_opt --trace_deopt output

[vsemozhetbyt]

• Node.js Version: 8.0.0-pre (v8 5.6.326.55)
• OS: Windows 7 x64
• Scope: v8

Checking different opt/deopt cases, I often stumble on this scheme (the function name is just a one example):

[marking 0000011AAAC5ACA9 <JS Function fs.readFile (SharedFunctionInfo 0000011AAAC31C29)> for optimized recompilation, reason: hot and stable, ICs with typeinfo: 25/39 (64%), generic ICs: 0/39 (0%)]
[compiling method 0000011AAAC5ACA9 <JS Function fs.readFile (SharedFunctionInfo 0000011AAAC31C29)> using Crankshaft]
[optimizing 0000011AAAC5ACA9 <JS Function fs.readFile (SharedFunctionInfo 0000011AAAC31C29)> - took 1.120, 2.973, 0.862 ms]
[completed optimizing 0000011AAAC5ACA9 <JS Function fs.readFile (SharedFunctionInfo 0000011AAAC31C29)>]

...

[deoptimizer unlinked: fs.readFile / 11aaac5aca9]
[evicting entry from optimizing code map (deoptimized code) for 0000011AAAC31C29 <SharedFunctionInfo fs.readFile>]

That's all, just these 6 messages concerning the tested function.

Do the last two messages mean the function is deoptimized? If so, how can we detect the cause? If not, what do they mean?

// cc @nodejs/v8

[bnoordhuis]

Yes, it's been deoptimized but it's hard to say why without the full output. You may also have to add --trace_allocation_site_pretenuring, --trace_osr and --trace_stub_failures.

[vsemozhetbyt]

@bnoordhuis

--trace_allocation_site_pretenuring

Throws bad option: --trace_allocation_site_pretenuring with master.
I could only see these similar options in node --v8-options:
--allocation_site_pretenuring
--trace_pretenuring
--trace_pretenuring_statistics
Which of them should I use?

[bnoordhuis]

Ah, sorry. Yes, either (or both) should work.

[vsemozhetbyt]

@bnoordhuis Thank you, I've added all the three) Unfortunately, I get only the same 6 mentions of the fs.readFile() function. Here is some context, could it be helpful?

[optimizing 0000014C822DACA9 <JS Function fs.readFile (SharedFunctionInfo 0000014C822B1C29)> - took 1.013, 1.670, 0.487 ms]
[completed optimizing 0000014C822DACA9 <JS Function fs.readFile (SharedFunctionInfo 0000014C822B1C29)>]
[optimizing 0000027824FCAB29 <JS Function resolve (SharedFunctionInfo 0000014C822A46B1)> - took 1.045, 2.731, 0.403 ms]
[completed optimizing 0000027824FCAB29 <JS Function resolve (SharedFunctionInfo 0000014C822A46B1)>]
[marking dependent code 0x10371449ba1 (opt #4) for deoptimization, reason: transition]
[marking dependent code 0x1037144dec1 (opt #7) for deoptimization, reason: transition]
[deoptimize marked code in all contexts]
[deoptimizer unlinked: fs.readFile / 14c822daca9]
[deoptimizer unlinked: ReadFileContext / 2717350d911]
[evicting entry from optimizing code map (deoptimized code) for 0000014C822B1C29 <SharedFunctionInfo fs.readFile>]
[evicting entry from optimizing code map (deoptimized code) for 0000014C822B00D1 <SharedFunctionInfo ReadFileContext>]

[bnoordhuis]

I half-expected to see "reason: transition" log lines in there. What is probably happening is that some external invariant that fs.readFile() depends on has changed, not fs.readFile() itself; likewise for ReadFileContext.

Unfortunately, it's very hard to track down such issues. Sometimes --trace_ic gives a hint, sometimes not. --trace_maps can be useful too but needs a custom build ('v8_trace_maps%': 1 in common.gypi or config.gypi.)

If you have a short test case, I can help look into it.

[vsemozhetbyt]

@bnoordhuis I've found out something strange.

Prehistory:

1. I've tried to eliminate some deopts in the fs.readFile() connected with using arguments. So I've replaced using arguments with some if-else blocks. The previous deopts disappear, but the abovementioned one appears.
2. I've added %GetOptimizationStatus(fn) to the test code cycle and this showed that deopt happens only after the last function call when (before or after) the cycle is ended.

So this code causes deopt:

const readFile = require('fs').readFile;
const cb = () => {};
for (let i = 0; i < 1e3; i++) {
  readFile(__filename, cb);
}

And this one does not causes deopt:

const readFile = require('fs').readFile;
const cb = () => {};
for (let i = 0; i < 1e3; i++) {
  readFile(__filename, cb);
  if (i === 999) process.exit();
}

[vsemozhetbyt]

You can test this with master if you temporarily require() an external .fs.js with replacing this line:

  callback = maybeCallback(arguments[arguments.length - 1]);

with something like this:

  callback = maybeCallback(callback || options);

or this:

  if (callback)
    callback = maybeCallback(callback);
  else
    callback = maybeCallback(options);

I've tested with rebuilt internal module as well.