Strange deoptimzations in cycles #9729

vsemozhetbyt · 2016-11-21T23:47:07Z

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

It renews in another cycle with a different ratio:

[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);
}

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):

[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);
}

The text was updated successfully, but these errors were encountered:

vsemozhetbyt · 2016-11-21T23:54:09Z

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

vsemozhetbyt · 2016-11-22T00:03:36Z

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

vsemozhetbyt · 2016-11-22T00:40:26Z

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

At the same time, the "while cycle at the last position increases own and previous run times" issue remains and gains strength:

const func = () => {};

[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);
}

console.log('');

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

vsemozhetbyt · 2016-11-22T01:31:18Z

And some more while cycle weirdness:

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

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

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

The leading while overcomes the trailing one:

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--){}

vsemozhetbyt · 2016-11-22T02:41:56Z

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

However, the while weirdness disappears:

var func, start, j, i, k;

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

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

vsemozhetbyt · 2016-11-22T03:22:17Z

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 · 2016-11-22T05:19:52Z

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

vsemozhetbyt · 2016-11-22T08:44:47Z

Reported.

bmeurer · 2016-11-22T10:35:08Z

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 · 2016-11-22T10:35:27Z

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 · 2016-11-22T16:57:23Z

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

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

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

vsemozhetbyt · 2016-11-22T17:18:53Z

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

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

var k = 1;

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

const k = 1;

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

let k = 1;

With non-empty cycle the ratio increases from 2 to 10:

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

var k = 1;

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

const k = 1;

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

vsemozhetbyt · 2016-11-23T11:53:23Z

Reported just in case.

bnoordhuis · 2016-11-23T12:15:32Z

@bmeurer Per #9729 (comment) - 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 · 2016-11-24T06:17:24Z

@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 · 2016-11-24T06:29:55Z

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.

Recognize Date.now() calls in the Typer and assign the proper integer type to them. See Node issue nodejs/node#9729 for more information. [email protected] BUG=v8:5267 Review-Url: https://codereview.chromium.org/2528853003 Cr-Commit-Position: refs/heads/master@{#41242}

bmeurer · 2016-11-24T08:41:32Z

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 · 2016-11-24T10:43:24Z

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 · 2016-11-24T10:59:07Z

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

Crankshaft has this highly unpredictable performance cliff around the "Unsupported phi use of const or let variable", which is due to the fact that Crankshaft refuses to do hole checks (for a couple of reasons). So ideally we should not even try to send any lexically bound variables to fullcodegen+Crankshaft, but instead give them to Ignition and TurboFan. This CL only adds the appropriate check to the AstNumbering, but doesn't remove the functionality from fullcodegen/Crankshaft yet. This would be step two in case this CL sticks. If you see any major performance regressions with this CL in the range, just revert it and ping me. See Node.js issue nodejs/node#9729 for additional information. BUG=v8:5666 [email protected], [email protected], [email protected] Review-Url: https://codereview.chromium.org/2525243002 Cr-Commit-Position: refs/heads/master@{#41445}

bmeurer · 2016-12-02T11:38:30Z

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).

vsemozhetbyt mentioned this issue Nov 21, 2016

Some strange deoptimization? nodejs/help#373

Closed

mscdex added question Issues that look for answers. v8 engine Issues and PRs related to the V8 dependency. labels Nov 22, 2016

vsemozhetbyt changed the title ~~The first iteration in cycles runs much faster than others~~ Strange deoptimzations in cycles Nov 22, 2016

vsemozhetbyt closed this as completed Nov 23, 2016

gibfahn added the performance Issues and PRs related to the performance of Node.js. label Nov 24, 2016

fhinkel mentioned this issue Dec 14, 2016

Benchmark var -> const before merging mass rewrites #8637

Closed

lpinca mentioned this issue Dec 14, 2016

Refactor WebSocket to use class syntax websockets/ws#930

Merged

vsemozhetbyt mentioned this issue Dec 29, 2016

const performance loss ? Node 6 vs Node 7 #10516

Closed

ZYSzys mentioned this issue Mar 10, 2019

various fix in lib #26562

Closed

2 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Strange deoptimzations in cycles #9729

Strange deoptimzations in cycles #9729

vsemozhetbyt commented Nov 21, 2016 •

edited

Loading

vsemozhetbyt commented Nov 21, 2016

vsemozhetbyt commented Nov 22, 2016 •

edited

Loading

vsemozhetbyt commented Nov 22, 2016 •

edited

Loading

vsemozhetbyt commented Nov 22, 2016 •

edited

Loading

vsemozhetbyt commented Nov 22, 2016

vsemozhetbyt commented Nov 22, 2016

sam-github commented Nov 22, 2016

vsemozhetbyt commented Nov 22, 2016

bmeurer commented Nov 22, 2016

bnoordhuis commented Nov 22, 2016

vsemozhetbyt commented Nov 22, 2016 •

edited

Loading

vsemozhetbyt commented Nov 22, 2016 •

edited

Loading

vsemozhetbyt commented Nov 23, 2016

bnoordhuis commented Nov 23, 2016

bmeurer commented Nov 24, 2016

bmeurer commented Nov 24, 2016

bmeurer commented Nov 24, 2016

bnoordhuis commented Nov 24, 2016

bmeurer commented Nov 24, 2016

bmeurer commented Dec 2, 2016

Strange deoptimzations in cycles #9729

Strange deoptimzations in cycles #9729

Comments

vsemozhetbyt commented Nov 21, 2016 • edited Loading

vsemozhetbyt commented Nov 21, 2016

vsemozhetbyt commented Nov 22, 2016 • edited Loading

vsemozhetbyt commented Nov 22, 2016 • edited Loading

vsemozhetbyt commented Nov 22, 2016 • edited Loading

vsemozhetbyt commented Nov 22, 2016

vsemozhetbyt commented Nov 22, 2016

sam-github commented Nov 22, 2016

vsemozhetbyt commented Nov 22, 2016

bmeurer commented Nov 22, 2016

bnoordhuis commented Nov 22, 2016

vsemozhetbyt commented Nov 22, 2016 • edited Loading

vsemozhetbyt commented Nov 22, 2016 • edited Loading

vsemozhetbyt commented Nov 23, 2016

bnoordhuis commented Nov 23, 2016

bmeurer commented Nov 24, 2016

bmeurer commented Nov 24, 2016

bmeurer commented Nov 24, 2016

bnoordhuis commented Nov 24, 2016

bmeurer commented Nov 24, 2016

bmeurer commented Dec 2, 2016

vsemozhetbyt commented Nov 21, 2016 •

edited

Loading

vsemozhetbyt commented Nov 22, 2016 •

edited

Loading

vsemozhetbyt commented Nov 22, 2016 •

edited

Loading

vsemozhetbyt commented Nov 22, 2016 •

edited

Loading

vsemozhetbyt commented Nov 22, 2016 •

edited

Loading

vsemozhetbyt commented Nov 22, 2016 •

edited

Loading