Javascript V8 中的特殊性能

Javascript odd performance special in V8

今天写了几行JS,惊呆了。。。可能是漏掉了什么,但想不通。

情况如下。我有一个被调用两次(或更多次)的函数。函数的第一次执行比后面的执行快。

代码已在 Node 和 Chrome(V8 引擎)中测试 Firefox 每次都以固定速度执行代码,这比 V8 引擎慢得多。跨引擎的不同执行速度并不重要。问题是关于为什么函数第一次执行比 V8 中的其他函数快。

代码如下:(可以在chrome控制台中输入copy/pasted,你会看到结果)

var loop = 10000000;

function callable() {
    return Math.random();
}

function measureFunction(index) {
    var result = 0;
    var timer = new Date();
    var start = timer.getTime();
    for (var i = 0;  i < loop;  ++i)
        result += callable();

    res[index] = "RESULT FUNCTION: " + result + " FOR: " + (new Date().getTime() - start);
}

var res = new Array(2);

for (var i = 0  ;i < res.length;  ++i)
    measureFunction(i);

for (var i = 0;  i < res.length;  ++i)
    console.log(res[i]);

这段代码可能有很多错误。但是可能有两件事:

  1. V8 实际上有两个编译器和垃圾收集器。在第二个 运行 中,它可能决定进行完整编译或完成 GC。所以在高性能代码中调用构造函数可能不是一个好主意
  2. V8 根据大量规则优化或取消优化您的代码。当你 运行 node --trace-deopt main.js 时,肯定会发生 deopts。在第二个 运行 V8 决定你的代码 运行 出于某种原因变慢了。

请注意,如果您将代码拆分为两个单独的函数,第二个函数甚至会 运行 更快。

您可以使用 node --v8-flags 选项进行更多调查。

TL;DR:这是因为 GC。但是很复杂。

我已经在这个稍微修改过的 js 上用 V8 version 4.8.0 (candidate)(我手边那个)的调试版本重现了你的观察结果:

var loop = 10000000 * 10;

function callable() {
    return Math.random();
}

function measureFunction(index) {
    var result = 0;
    var timer = new Date();
    var start = timer.getTime();
    for (var i = 0;  i < loop;  ++i)
        result += callable();

    res[index] = "RESULT FUNCTION: " + result + " FOR: " + (new Date().getTime() - start) + " ms";
}

var res = new Array(3);

for (var i = 0  ;i < res.length;  ++i) {
    measureFunction(i);
    print (i + " COMPLETE"); // use console.log for node
}

for (var i = 0;  i < res.length;  ++i)
    print(res[i]); // ditto

它在我的机器上给出了以下输出:

0 COMPLETE
1 COMPLETE
2 COMPLETE
RESULT FUNCTION: 49997528.61602645 FOR: 649 ms
RESULT FUNCTION: 49996578.63860239 FOR: 1402 ms
RESULT FUNCTION: 49995279.39097646 FOR: 1400 ms

之后,我 运行 v8 shell 具有以下选项:d8 main.js --trace-opt --trace-deopt --trace-gc

它给出了以下输出(删节):

    ...
[marking 0xaaf9fce2a79 <JS Function measureFunction (SharedFunctionInfo 0xaaf9fce2501)> for recompilation..
[didn't find optimized code in optimized code map for 0xaaf9fce2501 <SharedFunctionInfo measureFunction>]
[compiling method 0xaaf9fce2a79 <JS Function measureFunction (SharedFunctionInfo 0xaaf9fce2501)> using Crankshaft OSR]
[optimizing 0xaaf9fce2a79 <JS Function measureFunction (SharedFunctionInfo 0xaaf9fce2501)> - took 1.092, 3.601, 2.595 ms]
[didn't find optimized code in optimized code map for 0xaaf9fce2501 <SharedFunctionInfo measureFunction>]
[optimizing 0xaaf9fcd2181 <JS Function random (SharedFunctionInfo 0xaaf9fc5c111)> - took 0.445, 2.367, 0.122 ms]
[completed optimizing 0xaaf9fcd2181 <JS Function random (SharedFunctionInfo 0xaaf9fc5c111)>]
[deoptimizing (DEOPT eager): begin 0xaaf9fce2a79 <JS Function measureFunction (SharedFunctionInfo 0xaaf9fce2501)> (opt #3) @14, FP to SP delta: 120]
            ;;; deoptimize at 298: wrong instance type
    ... 
[deoptimizing (eager): ... took 0.099 ms]
Materialization [0x7ffffae625a8] <- 0x25c6de07d439 ;  0x25c6de07d439 <Number: 5.00034e+07>
[removing optimized code for: measureFunction]
[evicting entry from optimizing code map (notify deoptimized) for 0xaaf9fce2501 <SharedFunctionInfo measureFunction> (osr ast id 71)]

0 COMPLETE

[marking 0xaaf9fce2a79 <JS Function measureFunction> for recompilation, reason: small function, ICs with typeinfo: 13/15 (86%)...]
[14386:0x49c5fb0]      657 ms: Scavenge 2.1 (37.1) -> 1.2 (37.1) MB, 1.2 / 0 ms [allocation failure].
[didn't find optimized code in optimized code map for 0xaaf9fce2501 <SharedFunctionInfo measureFunction>]
[compiling method 0xaaf9fce2a79 <JS Function measureFunction (SharedFunctionInfo 0xaaf9fce2501)> using Crankshaft OSR]
[optimizing 0xaaf9fce2a79 <JS Function measureFunction (SharedFunctionInfo 0xaaf9fce2501)> - took 1.232, 5.863, 0.621 ms]
[didn't find optimized code in optimized code map for 0xaaf9fce2501 <SharedFunctionInfo measureFunction>]
[14386:0x49c5fb0]      667 ms: Scavenge 2.1 (37.1) -> 1.2 (37.1) MB, 0.7 / 0 ms [allocation failure].
[14386:0x49c5fb0]      668 ms: Scavenge 2.2 (37.1) -> 1.2 (37.1) MB, 0.4 / 0 ms [allocation failure].
[14386:0x49c5fb0]      669 ms: Scavenge 2.2 (37.1) -> 1.2 (37.1) MB, 0.4 / 0 ms [allocation failure].
[14386:0x49c5fb0]      669 ms: Scavenge 2.2 (37.1) -> 1.2 (37.1) MB, 0.4 / 0 ms [allocation failure].
[14386:0x49c5fb0]      670 ms: Scavenge 2.2 (37.1) -> 1.2 (37.1) MB, 0.4 / 0 ms [allocation failure].
... and so on, 1550 times ...

1 COMPLETE

Same thing (only the scavenger messages) for 2.

如果我提供,例如 --gc-interval=1 到 v8,情况就会改变。在这种情况下,Scavenge 和 Mark-sweep GC 循环也在第一次调用期间发生,输出如下所示:

0 COMPLETE
1 COMPLETE
2 COMPLETE
RESULT FUNCTION: 50005046.56689139 FOR: 919 ms
RESULT FUNCTION: 50006871.86618896 FOR: 678 ms
RESULT FUNCTION: 49998279.72474023 FOR: 670 ms

UPD

事实证明 eljefedelrodeodeljefe 是部分正确的。

让我们看看会发生什么。

measureFunc 开始时未优化。它很快变热,因此 Crankshaft 对其进行优化并执行 OSR 条目(执行从它停止的地方继续——从循环的中间开始——但在新优化的机器代码版本上)。但由于某种原因,不久之后推测性假设被打破,导致紧急救援(OSR 退出未优化,'full' 代码)。

并且 V8 不会在第一次调用结束之前再次尝试重新编译 measureFunc。 可能是因为它已经将 OSRed 转化为优化函数并且推测性假设失败了,所以它认为急于重试没有意义(我想。我不知道究竟使用了什么启发式方法)。

所以大多数时候measureFucntion的第一次调用是在Full-compiler层执行的。这段完整的代码在 运行 循环时似乎不会触发 GC。不知道是故意的还是bug。有待进一步调查。

所以是的,第一个调用执行(大部分)未优化,后续执行已优化。但是 V8 并没有决定 运行 代码变慢。第一次执行恰好更快,因为未优化的代码不会停止触发 GC。它在这个例子中产生了真正的不同,因为代码实际上是 GC 密集型的(由于大量的堆编号分配具有较短的生命周期)。

我们不能让这个问题没有真正的答案就死掉!

问题在于 V8 不喜欢通过多态“+”运算符将 "result" 隐式转换为字符串。

如果您明确地将结果从数字转换为字符串,则会恢复预期的性能。

res[index] = "RESULT FUNCTION: " + result + " FOR:
// ===>
res[index] = "RESULT FUNCTION: " + Number.prototype.toString.apply(result) + " FOR: 

您可以通过查看 --trace-deopt 输出来判断。执行显式转换会将 deopt 从 "eager" 不可恢复的 deopt 更改为 "soft" 随着时间的推移可恢复的 deopt。

同样,您可以在 --trace-gc 中看到巨大的差异。原始代码会产生许多清除。使用显式转换只会产生一次清除。

最终结果是,如果您显式转换,将获得最佳性能。