benchmark: readStart only after completion

[refack]

fix #11972
On windows apparently it's meaningful to call readStart only after connection completion.
(makes sense on POSIX as well, and causes no regressions)

Checklist

• tests and/or benchmarks are included
• commit message follows [commit guidelines]

Affected core subsystem(s)

benchmarks

[refack]

@indutny might be related to #6404
/cc @yosuke-furukawa , @bnoordhuis

[bzoz]

CI: https://ci.nodejs.org/job/node-test-pull-request/7247/

[vsemozhetbyt]

@refack It is strange: test-benchmark-net.js is OK with it. But with normal run this benchmark hangs after all tests:

J:\temp\_git\node-fork\benchmark\net>set NODEJS_BENCHMARK_ZERO_ALLOWED=1

J:\temp\_git\node-fork\benchmark\net>tcp-raw-pipe.js dur=0
net\tcp-raw-pipe.js dur=0 type="utf" len=102400: 0
net\tcp-raw-pipe.js dur=0 type="asc" len=102400: 0
net\tcp-raw-pipe.js dur=0 type="buf" len=102400: 0
net\tcp-raw-pipe.js dur=0 type="utf" len=16777216: 0
net\tcp-raw-pipe.js dur=0 type="asc" len=16777216: 0
net\tcp-raw-pipe.js dur=0 type="buf" len=16777216: 0

J:\temp\_git\node-fork\benchmark\net> // OK

J:\temp\_git\node-fork\benchmark\net>set NODEJS_BENCHMARK_ZERO_ALLOWED=

J:\temp\_git\node-fork\benchmark\net>tcp-raw-pipe.js
net\tcp-raw-pipe.js dur=5 type="utf" len=102400: 1.297886419487734
net\tcp-raw-pipe.js dur=5 type="asc" len=102400: 1.0694375760443917
net\tcp-raw-pipe.js dur=5 type="buf" len=102400: 1.2243643596337568
net\tcp-raw-pipe.js dur=5 type="utf" len=16777216: 1.0074100180585681
net\tcp-raw-pipe.js dur=5 type="asc" len=16777216: 1.2771849558116457
net\tcp-raw-pipe.js dur=5 type="buf" len=16777216: 1.1929763144473262
// HUNG! Needs CTRL+C to abort

Windows 7 x64.

[refack]

failure was because the #12261 issue/fix
IMHO can be considered green 😜

[refack]

But with normal run this benchmark hangs after all tests:

which node version?

[vsemozhetbyt]

@refack I have flaky results with almost all versions:

4.8.2: OK / hung after all tests
6.10.2: OK / hung after dur=5 type="asc" len=16777216 / hung after all tests
7.8.0: OK
8.0.0: OK / hung after dur=5 type="utf" len=16777216: / hung after all tests

When it hangs, there are 2 node processes. When I type Ctrl+c, one process is aborted. second remains and I can't even kill it via process manager (Access Denied). I've run recently almost all Node benchmarks and had no such problem with any. Can anybody reproduce?

[refack]

Can anybody reproduce?

Windows 7 SP1 x64?

[vsemozhetbyt]

Windows 7 SP1 x64

Yep.

[refack]

@vsemozhetbyt try this trick: rename the node.exe you're testing, then see if the hung node.exe is the tested node or the one run by autocannon
(always good to use procmon run as administrator, will also give you the command line a process was run with)

[vsemozhetbyt]

@refack Yes, I've already have a set of renamed Nodes and do usualy use procmon)

1: Total Commander with nodes.
2: cmd.exe with one succesful and one hung run.
3: procmon: a tooltip for the second process. Ctrl+c abort the first process, the second remains hung and unkillable.

[refack]

@vsemozhetbyt ups for the setup 🙆

I can't repro...
The "unkillable" issue makes me think you should check the unholy trinity "MpsSvc, WSearch, WinDefend" or any other firewall/vpn/anti-virus

[vsemozhetbyt]

"MpsSvc, WSearch, WinDefend" — not found / disabled)

Well, I think we can ignore this my issue as too flaky. Thank you again for fixing!

[refack]

I think we can ignore this my issue as too flaky. Thank you again for fixing!

Maybe a good restart...
Anyway, have a nice one!

[mcollina]

LGTM

[refack]

Landed in 16073c083e
Landed in: fbe946b

[vsemozhetbyt]

@refack Please, don't forget about commit message guidelines :)

[watilde]

This command may support you when you want to check the commit message :)

• https://github.com/evanlucas/core-validate-commit

[refack]

This command may support you when you want to check the commit message :)

https://github.com/evanlucas/core-validate-commit

I'll need to find a way to hook it into git for myself, in just the right conditions.

[gibfahn]

Landed fbe946b on v6.x, LMK if this is incorrect.

[refack]

🤔 it's a bug fix in /benchmark/ so it makes sense to except it from the "no automatic benchmarking porting" rule.

[amark]

@refack do you by chance know what is going on here? readStart 23 seconds to complete, blocking all other NodeJS operations. IDK if I should open an issue, tho this is v12.14.1 so I wouldn't until I test against latest stable & 14.

Here's a screenshot of the time-ordered flamegraph as rendered by speedscope:

It caused a in-production server to peg past 100% CPU utilization & drop 17K concurrent websocket connections (I presume from timeout). It regularly seems to occur at ~17.4K+ concurrency, not randomly, in low memory with otherwise ~27% CPU usage.

Thanks, just looking for pointers or if anybody has seen something similar.