investigate flaky sequential/test-benchmark-child-process on Windows

[Trott]

• Version: v8.0.0-pre
• Platform: win2008r2
• Subsystem: test

sequential/test-benchmark-child-process is still failing sometimes flaky on Windows in CI. I'll open a PR to mark it as flaky. This issue is for trying to locate the problem and a solution.

When the test succeeds, it seems to take just a few seconds.

https://ci.nodejs.org/job/node-test-binary-windows/RUN_SUBSET=3,VS_VERSION=vs2015,label=win2008r2/7865/console

ok 356 sequential/test-benchmark-child-process
  ---
  duration_ms: 1.764

When it fails, it's a timeout.

https://ci.nodejs.org/job/node-test-binary-windows/7867/RUN_SUBSET=3,VS_VERSION=vs2015,label=win2008r2/console

not ok 356 sequential/test-benchmark-child-process
  ---
  duration_ms: 60.70
  severity: fail
  stack: |-
    timeout

This would suggest a race condition or something else causing a child process to hang or something. And that might be the cause. But...

Interestingly, a stress test where the five benchmarks that this test calls were all split out into individual tests, succeeded but each test took around 30 seconds to run. Wha??!! I know! (Only other change in those tests is the dur option for the benchmarks was increased from 0 to 0.1. Well, that, and that this test was run on win2016 so maybe the results are completely irrelevant? I don't know.)

https://ci.nodejs.org/job/node-stress-single-test/1161/nodes=win2016/console:

ok 1 sequential/test-benchmark-child-process-exec-stdout
  ---
  duration_ms: 3.158
  ...
ok 2 sequential/test-benchmark-child-process-params
  ---
  duration_ms: 36.735
  ...
ok 3 sequential/test-benchmark-child-process-read-ipc
  ---
  duration_ms: 30.116
  ...
ok 4 sequential/test-benchmark-child-process-read
  ---
  duration_ms: 31.844
  ...
ok 5 sequential/test-benchmark-child-process-spawn-echo
  ---
  duration_ms: 31.661

So I'm not sure what's going on here. Maybe it can be worked out by someone more comfortable testing and debugging on Windows or someone more deeply familiar with child_process and/or our benchmarking code. @nodejs/platform-windows @nodejs/benchmarking @mscdex @cjihrig @bnoordhuis @nodejs/testing

[Trott]

Guess it may be useful to loop in @nodejs/build too in case there's something relevant to know about the win2008r2 hosts....

[joaocgreis]

Looking at https://ci.nodejs.org/computer/test-azure_msft-win2016-x64-6/builds , the job that run right after it killed a left-over yes.exe process: https://ci.nodejs.org/job/node-test-binary-windows/RUN_SUBSET=2,VS_VERSION=vs2015,label=win2016/7860/consoleFull

c:\workspace\node-test-binary-windows\RUN_SUBSET\2\VS_VERSION\vs2015\label\win2016>TASKKILL /F /IM yes.exe /T   || TRUE
SUCCESS: The process with PID 6256 (child process of PID 6652) has been terminated.

Could that first test be leaving a yes.exe behind draining CPU?

[refack]

I'm looking as well.

[Trott]

Could that first test be leaving a yes.exe behind draining CPU?

Sounds about right since the benchmarks use yes.exe. I'm not sure why yes.exe isn't terminating reliably, of course....

[Trott]

@joaocgreis @refack Thanks for looking at this, by the way! I'm very grateful for that.

[Trott]

So, we need a way to make sure yes.exe is reliably terminated after the benchmarks that use it are done. Has anyone else looked into this and gotten further than that? Just that info we already have is hugely helpful, but if there's more info to work with, I certainly want it. :-D

[bzoz]

child_process/child-process-exec-stdout benchmark uses exec('yes', ..) which will spawn yes inside a shell. Killing the shell does not always kill yes, so we get a leftover yes from time to time.

We can try using

require('child_process').execSync(`taskkill /f /t /pid ${child.pid}`)

instead of child.kill(). The /t switch is for terminating entire process tree. From my tests it works, but I haven gone to testing if this solves test-benchmark-child-process flakiness.

[Trott]

@bzoz Thanks! Awesome. I'll test that out using the Jenkins stress test job and we'll see how it does....

[Trott]

Fixed in #12658, I believe.