Investigate flaky test - sequential/test-performance-eventloopdelay

Test

sequential/test-performance-eventloopdelay

Platform

linuxone

Console output

node:assert:399
    throw err;
    ^

AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:

  assert(histogram.min > 0)

    at Timeout.spinAWhile [as _onTimeout] (/home/iojs/build/workspace/node-test-commit-linuxone/test/sequential/test-performance-eventloopdelay.js:65:7)
    at listOnTimeout (node:internal/timers:568:17)
    at processTimers (node:internal/timers:510:7) {
  generatedMessage: true,
  code: 'ERR_ASSERTION',
  actual: false,
  expected: true,
  operator: '=='
}

Node.js v18.0.0-pre

Build links

https://ci.nodejs.org/job/node-test-commit-linuxone/30015/

Additional information

No response

According to https://github.com/nodejs/reliability/issues?q=is%3Aissue+test-performance-eventloopdelay this first showed up on 22 December 2021.

Walking backwards from commits landed on 22 December 2021, I've started two stress runs around 23637e9:

665b404: https://ci.nodejs.org/view/Stress/job/node-stress-single-test/306/nodes=rhel7-s390x/ (✔️ no failures in 1000 runs)
23637e9: https://ci.nodejs.org/view/Stress/job/node-stress-single-test/307/nodes=rhel7-s390x/ (❌ 100 failures in 1000 runs)

I've added some debug to the test

diff --git a/test/sequential/test-performance-eventloopdelay.js b/test/sequential/test-performance-eventloopdelay.js
index f262e9de3f..eddc9348fa 100644
--- a/test/sequential/test-performance-eventloopdelay.js
+++ b/test/sequential/test-performance-eventloopdelay.js
@@ -62,7 +62,7 @@ const { sleep } = require('internal/util');
       histogram.disable();
       // The values are non-deterministic, so we just check that a value is
       // present, as opposed to a specific value.
-      assert(histogram.min > 0);
+      assert(histogram.min > 0, `histogram.min (${histogram.min}) > 0`);
       assert(histogram.max > 0);
       assert(histogram.stddev > 0);
       assert(histogram.mean > 0);

and kicked off another stress run (based on current master branch): https://ci.nodejs.org/view/Stress/job/node-stress-single-test/309/nodes=rhel7-s390x/console
and it looks like in the failure case histogram.min is 0:
e.g.

18:00:25 + /usr/bin/python3.6 tools/test.py -p tap --logfile test20.tap --mode=release sequential/test-performance-eventloopdelay
18:00:25 TAP version 13
18:00:25 1..1
18:00:32 not ok 1 sequential/test-performance-eventloopdelay
18:00:32   ---
18:00:32   duration_ms: 7.169
18:00:32   severity: fail
18:00:32   exitcode: 1
18:00:32   stack: |-
18:00:32     node:assert:399
18:00:32         throw err;
18:00:32         ^
18:00:32     
18:00:32     AssertionError [ERR_ASSERTION]: histogram.min (0) > 0
18:00:32         at Timeout.spinAWhile [as _onTimeout] (/home/iojs/build/workspace/node-stress-single-test/nodes/rhel7-s390x/test/sequential/test-performance-eventloopdelay.js:65:7)
18:00:32         at listOnTimeout (node:internal/timers:559:17)
18:00:32         at processTimers (node:internal/timers:502:7) {
18:00:32       generatedMessage: false,
18:00:32       code: 'ERR_ASSERTION',
18:00:32       actual: false,
18:00:32       expected: true,
18:00:32       operator: '=='
18:00:32     }
18:00:32     
18:00:32     Node.js v18.0.0-pre

test: mark test-performance-eventloopdelay flaky

Happened again today (and I'm sure many, many other days, but since it's marked as flaky, people probably don't log it).

Details

https://ci.nodejs.org/job/node-test-commit-linuxone/nodes=rhel8-s390x/31271/console

00:16:18 not ok 3582 sequential/test-performance-eventloopdelay # TODO : Fix flaky test
00:16:25   ---
00:16:25   duration_ms: 7.211
00:16:25   severity: flaky
00:16:25   exitcode: 1
00:16:25   stack: |-
00:16:25     node:assert:399
00:16:25         throw err;
00:16:25         ^
00:16:25     
00:16:25     AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:
00:16:25     
00:16:25       assert(histogram.min > 0)
00:16:25     
00:16:25         at Timeout.spinAWhile [as _onTimeout] (/home/iojs/build/workspace/node-test-commit-linuxone/test/sequential/test-performance-eventloopdelay.js:65:7)
00:16:25         at listOnTimeout (node:internal/timers:559:17)
00:16:25         at processTimers (node:internal/timers:502:7) {
00:16:25       generatedMessage: true,
00:16:25       code: 'ERR_ASSERTION',
00:16:25       actual: false,
00:16:25       expected: true,
00:16:25       operator: '=='
00:16:25     }
00:16:25     
00:16:25     Node.js v18.0.0-pre
00:16:25   ...

@jasnell

Is this a bug in the test and the docs? Is it possible for the minimum recorded event loop delay to be 0 (or rather, to round to 0) on a sufficiently fast machine? @jasnell

Most likely test bug. I'll be able to look tomorrow

@jasnell

@jasnell any chance you are goin to be able to take a look at this soon?

test: increase spin for eventloop test on s390

I'm not sure if I should rather open a new issue or continue posting in this old one, but I can confirm that this test is flaky on my build system that has 32 cores @ 5.7 ghz with exactly the same test failure as reported here.

It happens relatively regularly (my estimate: 25% of the time) if my system is not doing a lot of other things at the time of testing.

This is a bog-standard x86_64 GNU/Linux system, fwiw.
EDIT:
This is still the case for v22.12.0

@jellelicht

@jellelicht can you confirm you have the commit for 96a3804 in where you see the failure?

@jellelicht

@jellelicht I guess nevermind since I only 96a3804 only modified the time for s390x.

It would be usefull if you could check if a similar change on your system reduces the flakiness. I'm guessing its a similar issue.

test: increase spin for eventloop test on s390

@jellelicht I guess nevermind since I only 96a3804 only modified the time for s390x.

It would be usefull if you could check if a similar change on your system reduces the flakiness. I'm guessing its a similar issue.

This notification slipped throught the cracks. I've just tested; even increasing spin by huge amounts (x4) does not entirely prevent the issue, so I've simply disabled the test locally as it's quite flaky according to CI logs I've found floating around

This is flaking up the CI again (and has been significantly flaky for a few months), it might be time to mark it as flaky at least https://github.com/nodejs/reliability/blob/main/reports/2025-09-04.md

I was looking at this, but I think the test is wrong, tbh — it should check min >= 0.
monitorEventLoopDelay configures the histogram with lowest_discernible_value = 1000 ns. hdr_min() returns the lower bound of the bucket the smallest sample landed in, and for that config the first bucket is [0, 512) ns — lower bound 0.

So min === 0 just means the smallest sample fell into the first bucket.
In other words, seems to me that the assert is wrong, and min === 0 is legit

Here a PR: #63100

This issue has been marked as stale due to 90 days of inactivity.
It will be automatically closed in 30 days if no further activity occurs. If this is still relevant, please leave a comment or update it to keep it open.

This issue slipped through the cracks because our previous stale bot only tracked issues and couldn't catch all the issues.
Our new stale bot flagged this, and would have closed it shortly after RenderATL, but I'm just doing it a bit early so
maintainer's can focus on new code-and-learn PRs during the event.

If this is still relevant, feel free to reopen it or leave a comment with additional details so we can continue the discussion.

Navigation Menu

Repository navigation

Investigate flaky test - sequential/test-performance-eventloopdelay #41286

Test

Platform

Console output

Build links

Additional information

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Investigate flaky test - sequential/test-performance-eventloopdelay #41286

Description

Test

Platform

Console output

Build links

Additional information

Activity

richardlau commented on Jan 4, 2022

richardlau commented on Jan 4, 2022

richardlau commented on Jan 4, 2022

Trott commented on Mar 19, 2022

Trott commented on Mar 19, 2022

jasnell commented on Mar 19, 2022

mhdawson commented on Jun 15, 2022

jellelicht commented on Jan 6, 2025

mhdawson commented on Jan 6, 2025

mhdawson commented on Jan 6, 2025

jellelicht commented on May 30, 2025

joyeecheung commented on Sep 4, 2025

marcopiraccini commented on May 3, 2026

github-actions commented on Aug 2, 2026

avivkeller commented on Aug 9, 2026

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions