Node: Strange deoptimzations in cycles

[vsemozhetbyt]

• Version: 7.1.0
• Platform: Windows 7 x64
• Subsystem: v8

The first iteration in cycles runs much faster than others:

[1, 2, 3, 4].forEach(() => {
  const func = () => {};
  const start = Date.now();
  for (let i = 0; i < 100000000; i++) func();
  console.log(Date.now() - start);
});

544
1297
1294
1301



md5-275f7d2a2b15909fa15d310b72bed0a9

577
1312
1314
1298

437
1501
1501
1493

It becomes more strange with `while` cycle added in the end (this cycle removes the difference in the previous cycle, but it almost doubles its run time besides):
```js
[1, 2, 3, 4].forEach(() => {
  const func = () => {};
  const start = Date.now();
  for (let i = 0; i < 100000000; i++) func();
  console.log(Date.now() - start);
});

console.log('');

for (let j = 1; j <= 4; j++) {
  const func = () => {};
  const start = Date.now();
  for (let i = 0; i < 100000000; i++) func();
  console.log(Date.now() - start);
}

console.log('');

let k = 4;
while (k--){
  const func = () => {};
  const start = Date.now();
  for (let i = 0; i < 100000000; i++) func();
  console.log(Date.now() - start);
}

566
1317
1333
1289

2221
2448
2448
2507

2147
2360
2332
2427

[vsemozhetbyt]

If the while cycle comes first, the difference remains in all the cycles and a run time is not doubled in any of them:

let k = 4;
while (k--){
  const func = () => {};
  const start = Date.now();
  for (let i = 0; i < 100000000; i++) func();
  console.log(Date.now() - start);
}

console.log('');

[1, 2, 3, 4].forEach(() => {
  const func = () => {};
  const start = Date.now();
  for (let i = 0; i < 100000000; i++) func();
  console.log(Date.now() - start);
});

console.log('');

for (let j = 1; j <= 4; j++) {
  const func = () => {};
  const start = Date.now();
  for (let i = 0; i < 100000000; i++) func();
  console.log(Date.now() - start);
}

492
1483
1482
1439

533
1293
1271
1300

440
1420
1423
1437

[vsemozhetbyt]

With non-empty functions that return different values, the difference remains (with less ratio, though):

let k = 4;
while (k--){
  const func = () => { return Math.random(); };
  const start = Date.now();
  for (let i = 0; i < 100000000; i++) func();
  console.log(Date.now() - start);
}

console.log('');

[1, 2, 3, 4].forEach(() => {
  const func = () => { return Math.random(); };
  const start = Date.now();
  for (let i = 0; i < 100000000; i++) func();
  console.log(Date.now() - start);
});

console.log('');

for (let j = 1; j <= 4; j++) {
  const func = () => { return Math.random(); };
  const start = Date.now();
  for (let i = 0; i < 100000000; i++) func();
  console.log(Date.now() - start);
}

1599
2844
2839
2838

1423
2688
2675
2690

1658
2832
2813
2829

[vsemozhetbyt]

However, if the function declaration is removed from cycles, the difference disappears:

const func = () => {};

let k = 4;
while (k--){
  const start = Date.now();
  for (let i = 0; i < 100000000; i++) func();
  console.log(Date.now() - start);
}

console.log('');

[1, 2, 3, 4].forEach(() => {
  const start = Date.now();
  for (let i = 0; i < 100000000; i++) func();
  console.log(Date.now() - start);
});

console.log('');

for (let j = 1; j <= 4; j++) {
  const start = Date.now();
  for (let i = 0; i < 100000000; i++) func();
  console.log(Date.now() - start);
}

483
455
436
455

452
438
448
430

465
455
436
448



md5-fb6f48788df48f801a9f75f0cbaf5701

482
446
444
451

2268
2285
2265
2339

2422
2544
2511
2489
```

[vsemozhetbyt]

And some more while cycle weirdness:

1. Even empty while cycle with one iteration has the described impact:

let k = 1;
while (k--){}

for (let j = 1; j <= 4; j++) {
  const func = () => {};
  const start = Date.now();
  for (let i = 0; i < 100000000; i++) func();
  console.log(Date.now() - start);
}

505
1438
1423
1407



md5-10bd726aee3934cdfca972bf72c145ee

2333
2512
2495
2506

2. The leading `while` overcomes the trailing one:
```js
let k = 1;
while (k--){}

for (let j = 1; j <= 4; j++) {
  const func = () => {};
  const start = Date.now();
  for (let i = 0; i < 100000000; i++) func();
  console.log(Date.now() - start);
}

k = 1;
while (k--){}

484
1453
1394
1409

[vsemozhetbyt]

In the ES5 code the difference ratio is bigger:

var func, start, j, i;

for (j = 1; j <= 4; j++) {
  func = function () {};
  start = Date.now();
  for (i = 0; i < 100000000; i++) func();
  console.log(Date.now() - start);
}

140
904
913
894



md5-f7d2a45f567262ea751ac09c0def74b9

139
915
925
904
```

[vsemozhetbyt]

Issue distribution:

| Node.js v. | v0.10.48 | v0.12.17 | v4.6.2 | v5.12.0 | v6.9.1 | v8.0.0-nightly-20161121 | v7.0.0-nightly-20161121 chakracore |
|-----------------|----------|----------|----------|----------|---------------------|-------------------------|------------------------------------|
| JavaScript v. | ES5 | ES5 | ES6 | ES6 | ES6 | ES6 | ES6 |
| Iteration 1 | 1328 | 109 | 437 | 437 | 531 | 453 | 204 |
| Iteration 2 | 1326 | 749 | 1295 | 1295 | 1518 | 1450 | 205 |
| Iteration 3 | 639 | 717 | 1283 | 1310 | 1500 | 1451 | 200 |
| Iteration 4 | 640 | 734 | 1279 | 1311 | 1482 | 1466 | 199 |
| while weirdness | – | – | + | + | 1406 2215 1280 1279 | + | – |

[sam-github]

This is a pure V8 question, or possibly bug report, should be reported upstream to theml

[vsemozhetbyt]

Reported.

[bmeurer]

This is expected. We first need warm-up and only tier-up once we have a couple of cycles in the relevant function. Also note that there's only one deoptimization in forEach, and that doesn't really affect the outcome.

[bnoordhuis]

In your first example, the console.log(Date.now() - start) triggers a deopt because apparently V8 doesn't infer the return type of Date.now() correctly ("Insufficient type feedback for LHS of binary operation.")

When you remove it, it then deopts because of the const func = () => {} statement. If you move that out of the function, it stays optimized. I don't understand why that should be the case, though.

The let in for (let i = ...) slows it down quite a bit. If you replace it with var, it's about 4x faster.

Here is a revised version that has stable performance characteristics.

let start;
function before() { start = Date.now(); }
function after() { console.log(Date.now() - start); }

const func = () => {};
[1, 2, 3, 4].forEach(() => {
  before();
  for (var i = 0; i < 1e8; i++) func();
  after();
});

[vsemozhetbyt]

@bmeurer, @bnoordhuis Thank you!

However, how would you explain this remaining while weirdness:

const func = () => {};
const start = Date.now();

for (var j = 1; j <= 4; j++) {
  for (var i = 0; i < 1e8; i++) func();
}

console.log(Date.now() - start);

490



md5-b181d0f4c1d52ba0650177d161a13d6f

5550
```

[vsemozhetbyt]

Oops. This is not the while. It is the let or const!

const start = Date.now();
for (var i = 0; i < 1e9; i++) ;
console.log(Date.now() - start);

1251



md5-2f69daf8192defe0e618902c7c886ec2

1252

```js
const start = Date.now();
for (var i = 0; i < 1e9; i++) ;
console.log(Date.now() - start);

const k = 1;

2974



md5-a68c5b0a9c33538d6a109b66988ec448

3002

With non-empty cycle the ratio increases from 2 to 10:
```js
const func = () => {};
const start = Date.now();
for (var i = 0; i < 1e9; i++) func ();
console.log(Date.now() - start);

var k = 1;

 1249



md5-93440de6b5a462e65b4e0d354a4c41f2

12556
```
Is this also intended or should I post a separate bug upstream?

[vsemozhetbyt]

Reported just in case.

[bnoordhuis]

@bmeurer Per https://github.com/nodejs/node/issues/9729#issuecomment-262205508 - in particular, moving func out of the function and Date.now()'s return type not being inferred - do you still feel that's expected behavior?

Date.now() seems like a missed optimization opportunity. The func thing I can't explain and I couldn't piece it together from reading V8's source code. I would appreciate it if you can provide insight.

[bmeurer]

@bnoordhuis The Date.now() deopt seems a bit stupid, indeed. Fixed that for TurboFan in crrev.com/2528853003.

I'll have a look at the func thing.

[bmeurer]

Ah, the func is easy to explain: Currently we can only inline at a call site when there was exactly one closure, which is why the first iteration is super fast, but as soon as we see more than one closure we have to emit a call. I'm working on that, see crbug.com/v8/2206.

[bmeurer]

And finally, the let/const vs var issue: It's because Crankshaft permanently disables optimizations for the function when it sees a hole (for let/const TDZ), which is exactly what happens when you wrap the code above in a closure (as explained by @ofrobots on the relevant V8 bug report). One way to fix this would be consistently use only Ignition+TurboFan for let/const.

[bnoordhuis]

Interesting, thanks. I had a more-or-less accurate mental image of the let-vs-var issue but I was looking in completely the wrong place for the func deopt.

[bmeurer]

You're welcome. I'll see if I can push a bit harder for the inlining fixes.

[bmeurer]

And finally with crrev.com/2525243002 let and const now go to TurboFan+Ignition only, so the performance cliff is gone, and let/const are safe to use for you (with next LTS; this is not really back-mergable unfortunately).