V8 中 Javascript 的奇怪性能

Question

今天我写了几行JS，我惊呆了......也许我错过了一些东西，但无法弄清楚。

情况如下。我有一个被调用两次(甚至多次)的函数。函数的第一次执行比后续执行要快。

代码在 Node 和 Chrome(V8 引擎)中进行了测试 Firefox 每次都以固定的速度执行代码，这比 V8 引擎慢得多。引擎之间的执行速度有什么不同并不重要。问题是为什么 V8 中函数的首次执行比其他函数更快。

这是代码:(可以将其复制/粘贴到 Chrome 控制台中，您将看到结果)

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]);

Answer 1

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

我在这个稍微修改过的 js 上使用 V8 版本 4.8.0(候选)(我已经方便使用的版本)的调试版本重现了您的观察结果:

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.

如果我向 v8 提供 --gc-interval=1，情况就会发生变化。在这种情况下，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 退出到未优化的“完整”代码)。

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

所以大多数时候，measureFucntion 的第一次调用是在完整编译器层上执行的。而且这段完整的代码在循环中运行时似乎没有触发 GC。不知道是故意的还是bug。这有待进一步调查。

所以，是的，第一次调用执行(大部分)未优化，后续执行已优化。但 V8 并没有决定减慢代码的运行速度。第一次执行恰好更快，因为未优化的代码不会停止触发 GC。在这个示例中，它确实有所不同，因为代码实际上是 GC 密集型的(由于大量的堆号分配，且生命周期很短)。