Repository navigation
Investigate flaky sequential/test-performance #23291
Description
https://ci.nodejs.org/job/node-test-binary-arm/3710/RUN_SUBSET=4,label=pi1-docker/console
00:40:41 not ok 330 sequential/test-performance
00:40:41 ---
00:40:41 duration_ms: 5.141
00:40:41 severity: fail
00:40:41 exitcode: 1
00:40:41 stack: |-
00:40:41 { name: 'node',
00:40:41 entryType: 'node',
00:40:41 startTime: 0,
00:40:41 duration: { around: 4609.206676006317 },
00:40:41 nodeStart: { around: 0 },
00:40:41 v8Start: { around: 0 },
00:40:41 bootstrapComplete: { around: 4517.247398018837 },
00:40:41 environment: { around: 0 },
00:40:41 loopStart: -1,
00:40:41 loopExit: -1 }
00:40:41 assert.js:349
00:40:41 throw err;
00:40:41 ^
00:40:41
00:40:41 AssertionError [ERR_ASSERTION]: bootstrapComplete: 1233.9948890209198 >= 1111
00:40:41 at checkNodeTiming (/home/iojs/build/workspace/node-test-binary-arm/test/sequential/test-performance.js:92:7)
00:40:41 at Object.<anonymous> (/home/iojs/build/workspace/node-test-binary-arm/test/sequential/test-performance.js:104:1)
00:40:41 at Module._compile (internal/modules/cjs/loader.js:703:30)
00:40:41 at Object.Module._extensions..js (internal/modules/cjs/loader.js:714:10)
00:40:41 at Module.load (internal/modules/cjs/loader.js:613:32)
00:40:41 at tryModuleLoad (internal/modules/cjs/loader.js:552:12)
00:40:41 at Function.Module._load (internal/modules/cjs/loader.js:544:3)
00:40:41 at Function.Module.runMain (internal/modules/cjs/loader.js:756:12)
00:40:41 at startup (internal/bootstrap/node.js:303:19)
00:40:41 at bootstrapNodeJSCore (internal/bootstrap/node.js:865:3)
00:40:41 ...Looks like a case of testing elapsed time (as a proxy for performance?). Is this a case of the test being unreliable or is it a case of the test flagging something we care about? Test doesn't have a comment explaining itself but it was added in 67269fd / #14680 and there's context there.
/ping @jasnell
Activity
Trott commentedon Oct 6, 2018
@nodejs/testing @nodejs/performance
joyeecheung commentedon Oct 6, 2018
(The performance team is for changes related to
/benchmark, not the perf hooks)Trott commentedon Nov 4, 2018
https://ci.nodejs.org/job/node-test-commit-smartos/21373/nodes=smartos17-64/console
Trott commentedon Nov 16, 2018
I want to run a stress test on smartos 17 but it doesn't look like it's in a choice in our stress test job on CI. Can someone add it? @nodejs/build
Fishrock123 commentedon Jan 23, 2019
Happened again in #25656
https://ci.nodejs.org/job/node-test-binary-arm/5663/RUN_SUBSET=2,label=pi1-docker/testReport/(root)/test/sequential_test_performance/
Failed on a Raspberry PI 1 I think:
richardlau commentedon Jan 23, 2019
@Trott Not sure if still required, since this was from a few months back, but I've just added it (seemed like a reasonable thing to have there): https://ci.nodejs.org/view/Stress/job/node-stress-single-test/jobConfigHistory/showDiffFiles?timestamp1=2018-12-07_11-55-34×tamp2=2019-01-23_14-21-08
Fishrock123 commentedon Jan 23, 2019
For some reason this has affected all three runs of #25656 - does this just always happen on master right now?
Fishrock123 commentedon Jan 24, 2019
Failing on my other rebased PR too.
Trott commentedon Jan 24, 2019
Looks like it's barely-but-relatively-consistently failing due to arbitrary-ish timing constraints. The test lacks a comment explaining its purpose which is unfortunate, given it's bland name open to multiple interpretations. I guess it's testing perf_hooks generally?
What is this
deltaanddelaystuff? Should this usecommon.platformTimeout()to adjust some values on slower machines? I mean, that's a band-aid and not a fix, but I'll certainly take it. Another workaround-but-not-a-solution-but-whatever-close-enough might be "change 1000 to 2000" or "change 1000 to 500". ¯\(ツ)/¯pinging folks who have authored lines in the test: @BridgeAR @jasnell @TimothyGu @apapirovski @addaleax
Trott commentedon Jan 24, 2019
Happened for the first time on node-daily-master today so something seems to have happened in the last 24 hours to cause this to be perma-red (or perma-ish-red) on Pi 1, it would seem.
@nodejs/testing
https://ci.nodejs.org/job/node-test-binary-arm/5673/RUN_SUBSET=3,label=pi1-docker/console
test-requireio_continuationlabs-debian9-armv6l_pi1p-1
Failed by just 2ms or so?
Trott commentedon Jan 24, 2019
This gets weird. https://ci.nodejs.org/job/node-test-binary-arm/5610/ was green. Hooray? But looking at the fanned jobs for Pi1, nowhere was sequential/test-performance run. And the PR (#25612) doesn't remove it or anything. The test is still in master and that PR is against master. ?????!!!!!! @nodejs/build
joyeecheung commentedon Jan 24, 2019
I am not entirely sure about what the test is actually doing but I guess it was failing because:
node/test/sequential/test-performance.js
Line 17 in d40ed71
Is too far away from the bootstrap complete milestone? Then there could be two remedies:
commonis required ascommonis not exactly small6 remaining items
Trott commentedon Jan 25, 2019
I guess I also don't feel like using Pi 1 as our performance canary is a great approach. I'm inclined to treat this as a "bare functionality of
perf_hooks" test rather than a "watch performance in Node.js" test.This is supported IMO by the fact that the test was added with the initial implementation of
perf_hooksin 67269fd7f33 and not added after implementation as a performance test. We should probably rename ittest-perf-hooksor something like that to avoid this confusion. @jasnellmhdawson commentedon Jan 25, 2019
@Trott I don't know about it passing as its failed twice in attempts for me today.
sam-github commentedon Jan 25, 2019
Fwiw, I also got 2 failures in a row for #25688 as well, and going through the build history, @ofrobots and @danbev have also gotten failures on it today.
test: fix sequential/test-performance delay
Trott commentedon Jan 26, 2019
Fixed by d1d357d
gireeshpunathil commentedon Jan 26, 2019
ok, now that #25695 is landed and this one closed it makes little difference to raise my opinion; but raising it anyways.
these points:
Piare slow machines with little ram and a slow chipwould have been considerations at the time when the test was introduced IMO. Now that it showed us
somethingwhich is indicative of a change in timing in terms of latency in the boot sequences. So the question is:designedto test,or
we have many instances where unrelated tests threw light on serious issues in the code; issues associated in #25007 are latest examples - none of those were meant to catch race conditions; yet those tests were used to reproduce issues, troubleshoot, fix and finally validate the correctness of the fix.
my summary is that the test threw something to us - by design or by chance; amending the code block that suppresses the issue without looking at the root cause of the failure may be like silently ignoring an error.
Trott commentedon Jan 26, 2019
I guess ideally we'd do both. I don't want to leave it broken, causing people to either not be able to land valid changes or else get into the habit of ignoring failing test suites.
But as you are suggesting, I also want to understand why the test started failing so a determination can be made if it is a sign of a larger problem.
I think the issue this brought up is probably more appropriate for a benchmark than a test. (And maybe there already is a benchmark in
benchmark/misc/startup.js?) Perhaps we can, at some point, introduce nightly performance benchmarks that will fail if things fall below a certain threshold or if there is a drop in performance larger than a certain percentage. (I'd like to see something like that for coverage stats too.)Trott commentedon Jan 26, 2019
Perhaps the thing to do is to open a new issue about the slower startup. Because I guess we are talking about two different things anyway. One issue is that a test is failing when it should not be failing. That's this issue. It's about fixing the test. But the second issue, which this one uncovered, is why is startup slower than it used to be? These questions are related, but they can (and probably should?) be considered separately? Like, it's possible (as we've done here) to fix the first issue without successfully addressing the second.
test: fix sequential/test-performance delay
test: fix sequential/test-performance delay
test: fix sequential/test-performance delay
test: fix sequential/test-performance delay