Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

test: add (temporary) logging for unreliable test #26216

Closed
wants to merge 1 commit into from

Conversation

Trott
Copy link
Member

@Trott Trott commented Feb 20, 2019

Refs: #25984

Checklist
  • make -j4 test (UNIX), or vcbuild test (Windows) passes
  • commit message follows commit guidelines

@Trott Trott added the flaky-test Issues and PRs related to the tests with unstable failures on the CI. label Feb 20, 2019
@nodejs-github-bot nodejs-github-bot added the test Issues and PRs related to the tests. label Feb 20, 2019
@Trott
Copy link
Member Author

Trott commented Feb 20, 2019

@Trott
Copy link
Member Author

Trott commented Feb 20, 2019

Welp, that didn't help much...

08:06:06 not ok 4 pummel/test-crypto-timing-safe-equal-benchmarks
08:06:06   ---
08:06:06   duration_ms: 120.115
08:06:06   severity: fail
08:06:06   exitcode: -15
08:06:06   stack: |-
08:06:06     timeout
08:06:06   ...

@Trott
Copy link
Member Author

Trott commented Feb 20, 2019

Welp, that didn't help much...

Oh, that's because I accidentally ran the pummel tests against master and not against this PR. Time to try again...

Pummel CI: https://ci.nodejs.org/job/node-test-commit-custom-suites/882/

@Trott
Copy link
Member Author

Trott commented Feb 21, 2019

Pummel CI: https://ci.nodejs.org/job/node-test-commit-custom-suites/882/

More useful and less surprising output this time:

10:50:44 not ok 4 pummel/test-crypto-timing-safe-equal-benchmarks
10:50:44   ---
10:50:44   duration_ms: 120.157
10:50:44   severity: fail
10:50:44   exitcode: -15
10:50:44   stack: |-
10:50:44     timeout
10:50:44     timingSafeEqual
10:50:44     0
10:50:44     1000
10:50:44     2000
10:50:44     3000
10:50:44     4000
10:50:44     5000
10:50:44     6000
10:50:44     7000
10:50:44     8000
10:50:44     9000
10:50:44     10000
10:50:44     11000
10:50:44     12000
10:50:44     13000
10:50:44     14000
10:50:44     15000
10:50:44     16000
10:50:44     17000
10:50:44     18000
10:50:44     19000
10:50:44     20000
10:50:44     21000
10:50:44     22000
10:50:44     23000
10:50:44     24000
10:50:44     25000
10:50:44     26000
10:50:44     27000
10:50:44     28000
10:50:44     29000
10:50:44     30000
10:50:44     31000
10:50:44     32000
10:50:44     33000
10:50:44     34000
10:50:44     35000
10:50:44     36000
10:50:44     37000
10:50:44     38000
10:50:44     39000
10:50:44     40000
10:50:44     41000
10:50:44     42000
10:50:44     43000
10:50:44     44000
10:50:44     45000
10:50:44     46000
10:50:44     47000
10:50:44     48000
10:50:44     49000
10:50:44     50000
10:50:44     51000
10:50:44     52000
10:50:44     53000
10:50:44     54000
10:50:44     55000
10:50:44     56000
10:50:44     57000
10:50:44     58000
10:50:44     59000
10:50:44     60000
10:50:44     61000
10:50:44     62000
10:50:44     63000
10:50:44     64000
10:50:44     65000
10:50:44     66000
10:50:44     67000
10:50:44     68000
10:50:44     69000
10:50:44     70000
10:50:44     71000
10:50:44     72000
10:50:44     73000
10:50:44     74000
10:50:44     75000
10:50:44     76000
10:50:44     77000
10:50:44     78000
10:50:44     79000
10:50:44     80000
10:50:44     81000
10:50:44     82000
10:50:44     83000
10:50:44     84000
10:50:44     85000
10:50:44     86000
10:50:44     87000
10:50:44     88000
10:50:44     89000
10:50:44     90000
10:50:44     91000
10:50:44     92000
10:50:44     93000
10:50:44     94000
10:50:44     95000
10:50:44     96000
10:50:44     97000
10:50:44     98000
10:50:44     99000
10:50:44     unsafeCompare
10:50:44     0
10:50:44     1000
10:50:44     2000
10:50:44     3000
10:50:44     4000
10:50:44     5000
10:50:44     6000
10:50:44     7000
10:50:44     8000
10:50:44     9000
10:50:44     10000
10:50:44     11000
10:50:44     12000
10:50:44     13000
10:50:44     14000
10:50:44     15000
10:50:44     16000
10:50:44     17000
10:50:44     18000
10:50:44     19000
10:50:44     20000
10:50:44     21000
10:50:44     22000
10:50:44     23000
10:50:44     24000
10:50:44     25000
10:50:44     26000
10:50:44     27000
10:50:44     28000
10:50:44     29000
10:50:44     30000
10:50:44     31000
10:50:44     32000
10:50:44     33000
10:50:44     34000
10:50:44     35000
10:50:44     36000
10:50:44     37000
10:50:44     38000
10:50:44     39000
10:50:44     40000
10:50:44     41000
10:50:44     42000
10:50:44     43000
10:50:44     44000
10:50:44     45000
10:50:44     46000
10:50:44     47000
10:50:44     48000
10:50:44     49000
10:50:44     50000
10:50:44     51000
10:50:44     52000
10:50:44     53000
10:50:44     54000
10:50:44     55000
10:50:44     56000
10:50:44     57000
10:50:44     58000
10:50:44     59000
10:50:44     60000
10:50:44     61000
10:50:44     62000
10:50:44     63000
10:50:44     64000
10:50:44     65000
10:50:44     66000
10:50:44     67000
10:50:44     68000
10:50:44     69000
10:50:44     70000
10:50:44     71000
10:50:44     72000
10:50:44     73000
10:50:44     74000
10:50:44     75000
10:50:44     76000
10:50:44     77000
10:50:44     78000
10:50:44     79000
10:50:44     80000
10:50:44     81000
10:50:44     82000
10:50:44     83000
10:50:44     84000
10:50:44     85000
10:50:44     86000
10:50:44     87000
10:50:44     88000
10:50:44     89000
10:50:44     90000
10:50:44     91000
10:50:44   ...

@Trott
Copy link
Member Author

Trott commented Feb 21, 2019

I logged onto the host and went to run the test and it's just slow. Took 2 minutes and 7 seconds. The test can't be shortened because it needs this many runs to be statistically significant (and, in fact, it is expected to fail about once every 10K runs as is).

At the same time, this is new. The test used to run more than twice as fast on the host. @nodejs/build

@Trott
Copy link
Member Author

Trott commented Feb 21, 2019

I'm going to mark the host offline long enough for another host to pick up the job and see if another host is any faster....

Pummel CI on -2 rather than -1: https://ci.nodejs.org/job/node-test-commit-custom-suites/883/

@Trott
Copy link
Member Author

Trott commented Feb 21, 2019

Pummel CI on -2 rather than -1: https://ci.nodejs.org/job/node-test-commit-custom-suites/883/

Timed out there too in about the same way.

I'm now wondering if something landed in the last day or two that has made one or more of the crypto functions much slower.

@Trott
Copy link
Member Author

Trott commented Feb 21, 2019

@nodejs/crypto

@Trott
Copy link
Member Author

Trott commented Feb 21, 2019

Locally, I compiled master (85df2c4) and a993160 and compared their speed running this test. The latter (the earlier commit) is more than twice as fast. Bisecting to find where the performance hit happened...

@Trott
Copy link
Member Author

Trott commented Feb 21, 2019

git bisect indicates the performance regression occurred in d345b0d #21573.

@Trott
Copy link
Member Author

Trott commented Feb 21, 2019

(Looks like the regression is in module loading and not in crypto stuff. Sorry for the ping, crypto team.)

@Trott
Copy link
Member Author

Trott commented Feb 21, 2019

Going to close this as the problem isn't in the test. Opened #26229 instead.

@Trott Trott closed this Feb 21, 2019
@Trott Trott deleted the add-logging-for-flaky-test branch January 13, 2022 22:51
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
flaky-test Issues and PRs related to the tests with unstable failures on the CI. test Issues and PRs related to the tests.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants