clearTimeout blocks the process (100% CPU usage)

[morkai]

The following code should output TEST every 10s:

'use strict';

const timers = [];

function test()
{
  console.log(new Date().toISOString(), 'TEST');

  for (let i = 0; i < 1000; ++i)
  {
    timers.push(setTimeout(clearTimeouts, Math.round(Math.random() * 9000)));
  }

  setTimeout(test, 10000);
}

function clearTimeouts()
{
  for (let i = 0; i < timers.length; ++i)
  {
    if (timers[i] && Math.random() > 0.8)
    {
      clearTimeout(timers[i]);
      timers[i] = null;
    }
  }
}

test();

Version 11.0.0 hangs with 100% CPU usage (memory stays the same). v8.12.0 and v10.9.0 works. test.js was run for 60s in v8, v10 and v11:

λ node8 --version
v8.12.0
λ node8 test.js
2018-10-24T21:59:34.334Z TEST
2018-10-24T21:59:44.339Z TEST
2018-10-24T21:59:54.356Z TEST
2018-10-24T22:00:04.366Z TEST
2018-10-24T22:00:14.387Z TEST
2018-10-24T22:00:24.403Z TEST
^C

λ node10 --version
v10.9.0
λ node10 test.js
2018-10-24T22:01:49.382Z TEST
2018-10-24T22:01:59.388Z TEST
2018-10-24T22:02:09.403Z TEST
2018-10-24T22:02:19.419Z TEST
2018-10-24T22:02:29.433Z TEST
2018-10-24T22:02:39.442Z TEST
^C

λ node --version
v11.0.0
λ node test.js
2018-10-24T22:03:45.987Z TEST
^C

EDIT 1:
The following code hangs node v11 if N > 6 (sometimes TEST is printed twice):

'use strict';

const N = 10;

function noop() {}

function test()
{
  console.log(new Date().toISOString(), 'TEST');

  const timers = [];

  for (let i = 1; i <= N; ++i)
  {
    timers.push(setTimeout(noop, i * 1000));
  }

  setTimeout(() => timers.forEach(t => clearTimeout(t)), 5000);

  setTimeout(test, 10000);
}

test();

EDIT 2:
Just found out about NODE_DEBUG=timer:

λ node test.js
2018-10-24T22:39:02.837Z TEST
TIMER 13840: no 1000 list was found in insert, creating a new one
TIMER 13840: no 2000 list was found in insert, creating a new one
TIMER 13840: no 3000 list was found in insert, creating a new one
TIMER 13840: no 4000 list was found in insert, creating a new one
TIMER 13840: no 5000 list was found in insert, creating a new one
TIMER 13840: no 6000 list was found in insert, creating a new one
TIMER 13840: no 7000 list was found in insert, creating a new one
TIMER 13840: no 8000 list was found in insert, creating a new one
TIMER 13840: no 9000 list was found in insert, creating a new one
TIMER 13840: no 10000 list was found in insert, creating a new one
TIMER 13840: process timer lists 1055
TIMER 13840: timeout callback 1000
TIMER 13840: 1000 list empty
TIMER 13840: process timer lists 2060
TIMER 13840: timeout callback 2000
TIMER 13840: 2000 list empty
TIMER 13840: process timer lists 3059
TIMER 13840: timeout callback 3000
TIMER 13840: 3000 list empty
TIMER 13840: process timer lists 4058
TIMER 13840: timeout callback 4000
TIMER 13840: 4000 list empty
TIMER 13840: process timer lists 5059
TIMER 13840: timeout callback 5000
TIMER 13840: unenroll: list empty
TIMER 13840: unenroll: list empty
TIMER 13840: unenroll: list empty
TIMER 13840: unenroll: list empty
TIMER 13840: 5000 list empty
TIMER 13840: process timer lists 10060
TIMER 13840: timeout callback 10000
2018-10-24T22:39:12.846Z TEST
TIMER 13840: no 1000 list was found in insert, creating a new one
TIMER 13840: no 2000 list was found in insert, creating a new one
TIMER 13840: no 3000 list was found in insert, creating a new one
TIMER 13840: no 4000 list was found in insert, creating a new one
TIMER 13840: no 5000 list was found in insert, creating a new one
TIMER 13840: no 6000 list was found in insert, creating a new one
TIMER 13840: no 7000 list was found in insert, creating a new one
TIMER 13840: no 8000 list was found in insert, creating a new one
TIMER 13840: no 9000 list was found in insert, creating a new one
TIMER 13840: 10000 list wait because diff is -3
TIMER 13840: process timer lists 11063
TIMER 13840: timeout callback 1000
TIMER 13840: 1000 list empty
TIMER 13840: process timer lists 12065
TIMER 13840: timeout callback 2000
TIMER 13840: 2000 list empty
TIMER 13840: process timer lists 13064
TIMER 13840: timeout callback 3000
TIMER 13840: 3000 list empty
TIMER 13840: process timer lists 14064
TIMER 13840: timeout callback 4000
TIMER 13840: 4000 list empty
TIMER 13840: process timer lists 15064
TIMER 13840: timeout callback 5000
TIMER 13840: unenroll: list empty
TIMER 13840: unenroll: list empty
TIMER 13840: unenroll: list empty
TIMER 13840: unenroll: list empty
TIMER 13840: 5000 list empty
TIMER 13840: process timer lists 18065
TIMER 13840: timeout callback 8000
TIMER 13840: 8000 list empty
TIMER 13840: timeout callback 8000
TIMER 13840: 8000 list empty
TIMER 13840: timeout callback 8000
TIMER 13840: 8000 list empty
TIMER 13840: timeout callback 8000
TIMER 13840: 8000 list empty
TIMER 13840: timeout callback 8000
TIMER 13840: 8000 list empty
TIMER 13840: timeout callback 8000
TIMER 13840: 8000 list empty
...
TIMER 13840: 8000 list empty
TIMER 13840: timeout callback 8000
...

[Fishrock123]

@apapirovski Probably has a better idea as to the cause in the current codebase than I do, but I can look in a day or two otherwise.

[Fishrock123]

@morkai Can you try running with node --prof and then run node --prof-process isolate-whatever-it-calls-it.v8.log?

[apapirovski]

I can reproduce with the above but I can't make a reproduction that doesn't involve Math.random. Will dig in more tomorrow morning.

[morkai]

--prof-process results: https://gist.github.com/morkai/4c2b3bc3cec692dfb30076eaa4ae1ee8

--prof & --prof-process output and a CPU profile: node_issue_23860_clearTimeout.zip

[ChALkeR]

Reduced testcase:

function noop() {}

const timers = [];
timers.push(setTimeout(noop, 100));
timers.push(setTimeout(noop, 150));
timers.push(setTimeout(noop, 200));
timers.push(setTimeout(noop, 250));
timers.push(setTimeout(noop, 300));
setTimeout(() => {
  console.log('200 called');
}, 200);
setTimeout(() => {
  console.log('400 called');
}, 400);
setTimeout(() => {
  console.log('500 called');
}, 500);
timers.forEach(t => clearTimeout(t));

Reproducable here, I'm pretty sure this is confirmed.

[apapirovski]

Thanks @ChALkeR. Working on a PR.

Edit: Also I'm an idiot... 😞