Preface
This issue seems to only affect Chrome/V8, and may not be reproducible in Firefox or other browsers. In summary, the execution time of a function callback increases by an order of magnitude or more if the function is called with a new callback anywhere else.
Simplified Proof-of-Concept
Calling test(callback) arbitrarily many times works as expected, but once you call test(differentCallback), the execution time of the test function increases dramatically no matter what callback is provided (i.e., another call to test(callback) would suffer as well).
This example was updated to use arguments so as to not be optimized to an empty loop. Callback arguments a and b are summed and added to total, which is logged.
function test(callback) {
let start = performance.now(),
total = 0;
// add callback result to total
for (let i = 0; i < 1e6; i++)
total += callback(i, i + 1);
console.log(`took ${(performance.now() - start).toFixed(2)}ms | total: ${total}`);
}
let callback1 = (a, b) => a + b,
callback2 = (a, b) => a + b;
console.log('FIRST CALLBACK: FASTER');
for (let i = 1; i < 10; i++)
test(callback1);
console.log('\nNEW CALLBACK: SLOWER');
for (let i = 1; i < 10; i++)
test(callback2);Original post
I am developing a StateMachine class (source) for a library I'm writing and the logic works as expected, but in profiling it, I've run into an issue. I noticed that when I ran the profiling snippet (in global scope), it would only take about 8ms to finish, but if I ran it a second time, it would take up to 50ms and eventually balloon as high as 400ms. Typically, running the same named function over and over will cause its execution time to drop as the V8 engine optimizes it, but the opposite seems to be happening here.
I've been able to get rid of the problem by wrapping it in a closure, but then I noticed another weird side effect: Calling a different function that relies on the StateMachine class would break the performance for all code depending on the class.
The class is pretty simple - you give it an initial state in the constructor or init, and you can update the state with the update method, which you pass a callback that accepts this.state as an argument (and usually modifies it). transition is a method that is used to update the state until the transitionCondition is no longer met.
Two test functions are provided: red and blue, which are identical, and each will generate a StateMachine with an initial state of { test: 0 } and use the transition method to update the state while state.test < 1e6. The end state is { test: 1000000 }.
You can trigger the profile by clicking the red or blue button, which will run StateMachine.transition 50 times and log the average time the call took to complete. If you click the red or blue button repeatedly, you will see that it clocks in at less than 10ms without issue - but, once you click the other button and call the other version of the same function, everything breaks, and the execution time for both functions will increase by about an order of magnitude.
// two identical functions, red() and blue()
function red() {
let start = performance.now(),
stateMachine = new StateMachine({
test: 0
});
stateMachine.transition(
state => state.test++,
state => state.test < 1e6
);
if (stateMachine.state.test !== 1e6) throw 'ASSERT ERROR!';
else return performance.now() - start;
}
function blue() {
let start = performance.now(),
stateMachine = new StateMachine({
test: 0
});
stateMachine.transition(
state => state.test++,
state => state.test < 1e6
);
if (stateMachine.state.test !== 1e6) throw 'ASSERT ERROR!';
else return performance.now() - start;
}
// display execution time
const display = (time) => document.getElementById('results').textContent = `Avg: ${time.toFixed(2)}ms`;
// handy dandy Array.avg()
Array.prototype.avg = function() {
return this.reduce((a,b) => a+b) / this.length;
}
// bindings
document.getElementById('red').addEventListener('click', () => {
const times = [];
for (var i = 0; i < 50; i++)
times.push(red());
display(times.avg());
}),
document.getElementById('blue').addEventListener('click', () => {
const times = [];
for (var i = 0; i < 50; i++)
times.push(blue());
display(times.avg());
});<script src="https://cdn.jsdelivr.net/gh/TeleworkInc/state-machine@bd486a339dca1b3ad3157df20e832ec23c6eb00b/StateMachine.js"></script>
<h2 id="results">Waiting...</h2>
<button id="red">Red Pill</button>
<button id="blue">Blue Pill</button>
<style>
body{box-sizing:border-box;padding:0 4rem;text-align:center}button,h2,p{width:100%;margin:auto;text-align:center;font-family:-apple-system,BlinkMacSystemFont,"Segoe UI",Roboto,Helvetica,Arial,sans-serif,"Apple Color Emoji","Segoe UI Emoji","Segoe UI Symbol"}button{font-size:1rem;padding:.5rem;width:180px;margin:1rem 0;border-radius:20px;outline:none;}#red{background:rgba(255,0,0,.24)}#blue{background:rgba(0,0,255,.24)}
</style>Updates
Bug Report "Feature Request" filed (awaiting update) - See @jmrk's answers below for more details.
Ultimately, this behavior is unexpected and, IMO, qualifies as a nontrivial bug. The impact for me is significant - on Intel i7-4770 (8) @ 3.900GHz, my execution times in the example above go from an average of 2ms to 45ms (a 20x increase).
As for nontriviality, consider that any subsequent calls to StateMachine.transition after the first one will be unnecessarily slow, regardless of scope or location in the code. The fact that SpiderMonkey does not slow down subsequent calls to transition signals to me that there is room for improvement for this specific optimization logic in V8.
See below, where subsequent calls to StateMachine.transition are slowed:
// same source, several times
// 1
(function() {
let start = performance.now(),
stateMachine = new StateMachine({
test: 0
});
stateMachine.transition(state => state.test++, state => state.test < 1e6);
if (stateMachine.state.test !== 1e6) throw 'ASSERT ERROR!';
console.log(`took ${performance.now() - start}ms`);
})();
// 2
(function() {
let start = performance.now(),
stateMachine = new StateMachine({
test: 0
});
stateMachine.transition(state => state.test++, state => state.test < 1e6);
if (stateMachine.state.test !== 1e6) throw 'ASSERT ERROR!';
console.log(`took ${performance.now() - start}ms`);
})();
// 3
(function() {
let start = performance.now(),
stateMachine = new StateMachine({
test: 0
});
stateMachine.transition(state => state.test++, state => state.test < 1e6);
if (stateMachine.state.test !== 1e6) throw 'ASSERT ERROR!';
console.log(`took ${performance.now() - start}ms`);
})();<script src="https://cdn.jsdelivr.net/gh/TeleworkInc/state-machine@bd486a339dca1b3ad3157df20e832ec23c6eb00b/StateMachine.js"></script>This performance decrease can be avoided by wrapping the code in a named closure, where presumably the optimizer knows the callbacks will not change:
var test = (function() {
let start = performance.now(),
stateMachine = new StateMachine({
test: 0
});
stateMachine.transition(state => state.test++, state => state.test < 1e6);
if (stateMachine.state.test !== 1e6) throw 'ASSERT ERROR!';
console.log(`took ${performance.now() - start}ms`);
});
test();
test();
test();<script src="https://cdn.jsdelivr.net/gh/TeleworkInc/state-machine@bd486a339dca1b3ad3157df20e832ec23c6eb00b/StateMachine.js"></script>Platform Information
$ uname -a
Linux workspaces 5.4.0-39-generic #43-Ubuntu SMP Fri Jun 19 10:28:31 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
$ google-chrome --version
Google Chrome 83.0.4103.116
