test: strengthen test-worker-prof #26608

gireeshpunathil · 2019-03-12T12:29:54Z

Force main and worker to stay for some deterministic time
Add some more validation check around profile file generation

Checklist

make -j4 test (UNIX), or vcbuild test (Windows) passes
tests and/or benchmarks are included
documentation is changed or added
commit message follows commit guidelines

nodejs-github-bot · 2019-03-12T12:29:56Z

@gireeshpunathil build started: https://ci.nodejs.org/blue/organizations/jenkins/node-test-pull-request-lite-pipeline/detail/node-test-pull-request-lite-pipeline/2878/pipeline

test/parallel/test-worker-prof.js

Trott · 2019-03-14T04:24:36Z

test/parallel/test-worker-prof.js

+  });
+  w.postMessage(data);
+} else {
+  tmpdir.refresh();


An absolute micronit here but maybe add a comment above this (right below the else line) saying this is the parent process?

Trott · 2019-03-14T04:26:39Z

Looks good to me, but I'd want @addaleax's confirmed sign-off if at all possible first.

refack · 2019-03-14T21:30:38Z

I'm not confidant in my expertise to properly review this ¯\(ツ)/¯

gireeshpunathil · 2019-03-15T01:41:05Z

@refack - ack, np; and then I will critically depend on @addaleax's review on this.

In case if this explanation helps:
while the root cause of flakes (profile files missing, insufficient profile ticks) are not fully diagnosed, there is a reasonable and working explanation to that thus:

there was an issue in the worker in that it was creating isolate in the parent thread as opposed to worker thread itself
due to this the profile ticks were accounted against parent, not in the worker.
this test case is a regression test associated with the PR that fixed the issue.
the test makes use of a parent and a worker. Drive both to run equal amount of time, as much as possible.
collect the profile output. measure the tick counts from the profile file.
make sure that the tick counts are comparable.

The reason for the test failure in my assessment is due to unexpected interplay between the OS scheduler, thread execution order, and the program logic (tight loop until the time reaches a threshold) which could potentially result in the tight loop to exit prematurely without the thread really have consumed enough CPU - affecting either or both of the threads. (again, only theory, no real proof for it)

The new version attempts to run independent of time scale, instead in more deterministic manner , by shuttling some messages a predefined number of times, to get a right mix of CPU and IO. Scheduling and other environmental things should not affect the logic.

thanks!

test/parallel/test-worker-prof.js

gireeshpunathil · 2019-03-15T10:18:28Z

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

richardlau · 2019-03-15T12:25:08Z

test/parallel/test-worker-prof.js

+    { cwd: tmpdir.path });
+  assert.strictEqual(spawnResult.stderr.toString(), '');
+  assert.strictEqual(spawnResult.status, 0);
+  assert.strictEqual(spawnResult.signal, null);


Suggest swapping this line and the one above it so that the signal is checked first as that would be more useful to know if it is not null rather than the null exit code seen in #26401 (comment).

gireeshpunathil · 2019-03-15T12:47:24Z

just pushed a change to that effect: added debug data in all three assertions + reversed the signal and exit status check order.

Trott · 2019-03-15T13:38:09Z

test/parallel/test-worker-prof.js

+  assert.strictEqual(spawnResult.stderr.toString(), '',
+                     `child exited with an error: ${spawnResult}`);
+  assert.strictEqual(spawnResult.signal, null,
+                     `child exited with signal: ${spawnResult}`);


${spawnResult} will end up displaying [object Object] unfortunately. You might have to do something like ${util.inspect(spawnResult)} if you want something useful.

thanks. Is there any way to explode the internal arrays as well? with this change I get the primitive fields, but not the Buffers:

assert.strictEqual(spawnResult.status, 0, `child exited with non-zero status: ${util.inspect(spawnResult, {depth: 3})}`);

{ status: 1, signal: null, output: [ null, <Buffer >, <Buffer > ], pid: 72177, stdout: <Buffer >, stderr: <Buffer > }

How about passing encoding: 'utf8' option to spawnSync so that stdout and stdin are String objects instead of Buffer objects?

@richardlau - addressed your review comments, ptal.

gireeshpunathil · 2019-03-21T13:13:51Z

@refack @Trott - do you have any objections on landing this PR? I am asking this is in the light of reported crash in #26401 (comment) . In my opinion it is a container environment related; however, this test being a pure JS code cannot cause a crash in itself, so should be either native code in node, v8 or elsewhere - which is more of a reason this should land so that we can reproduce, investigate and fix at the source? please let me know!

Trott · 2019-03-21T20:24:51Z

do you have any objections on landing this PR?

I don't have any objections.

Trott · 2019-03-23T04:20:19Z

Is there anything stopping this up from landing at this point? Or should we land it?

Trott · 2019-03-23T04:21:08Z

I guess it needs a new CI run.

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

gireeshpunathil · 2019-03-23T04:58:13Z

@Trott - I was waiting to see if @refack has a say. At this point I think we should land this, when CI shows us green.

gireeshpunathil · 2019-03-23T05:09:08Z

Resume Build CI: https://ci.nodejs.org/job/node-test-pull-request/21825/

gireeshpunathil · 2019-03-23T07:51:16Z

the only failure parallel/test-async-hooks-http-parser-destroy is #26610

Trott · 2019-03-23T17:16:07Z

Resume Build CI: https://ci.nodejs.org/job/node-test-pull-request/21833/

Force main and worker to stay for some deterministic time Add some more validation check around profile file generation Fixes: nodejs#26401 PR-URL: nodejs#26608 Reviewed-By: James M Snell <[email protected]> Reviewed-By: Anna Henningsen <[email protected]> Reviewed-By: Richard Lau <[email protected]>

gireeshpunathil · 2019-03-24T01:40:01Z

landed as ed849f8

Force main and worker to stay for some deterministic time Add some more validation check around profile file generation Fixes: nodejs#26401 PR-URL: nodejs#26608 Reviewed-By: James M Snell <[email protected]> Reviewed-By: Anna Henningsen <[email protected]> Reviewed-By: Richard Lau <[email protected]>

Force main and worker to stay for some deterministic time Add some more validation check around profile file generation Fixes: #26401 PR-URL: #26608 Reviewed-By: James M Snell <[email protected]> Reviewed-By: Anna Henningsen <[email protected]> Reviewed-By: Richard Lau <[email protected]>

nodejs-github-bot added the test Issues and PRs related to the tests. label Mar 12, 2019

gireeshpunathil requested review from addaleax, refack and Trott March 12, 2019 12:30

addaleax approved these changes Mar 12, 2019

View reviewed changes

test/parallel/test-worker-prof.js Outdated Show resolved Hide resolved

Trott reviewed Mar 14, 2019

View reviewed changes

refack removed their request for review March 14, 2019 21:29

addaleax approved these changes Mar 15, 2019

View reviewed changes

test/parallel/test-worker-prof.js Outdated Show resolved Hide resolved

test/parallel/test-worker-prof.js Outdated Show resolved Hide resolved

Trott mentioned this pull request Mar 15, 2019

Investigate flaky test-worker-prof #26401

Closed

richardlau reviewed Mar 15, 2019

View reviewed changes

Trott reviewed Mar 15, 2019

View reviewed changes

jasnell approved these changes Mar 15, 2019

View reviewed changes

richardlau approved these changes Mar 21, 2019

View reviewed changes

gireeshpunathil added the author ready PRs that have at least one approval, no pending requests for changes, and a CI started. label Mar 23, 2019

gireeshpunathil force-pushed the worker_prof branch from 4c7fe07 to ed849f8 Compare March 24, 2019 01:39

gireeshpunathil removed the author ready PRs that have at least one approval, no pending requests for changes, and a CI started. label Mar 24, 2019

gireeshpunathil merged commit ed849f8 into nodejs:master Mar 24, 2019

targos mentioned this pull request Mar 27, 2019

v11.13.0 release proposal #26949

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

test: strengthen test-worker-prof #26608

test: strengthen test-worker-prof #26608

gireeshpunathil commented Mar 12, 2019

nodejs-github-bot commented Mar 12, 2019

Trott Mar 14, 2019

Trott commented Mar 14, 2019

refack commented Mar 14, 2019

gireeshpunathil commented Mar 15, 2019

gireeshpunathil commented Mar 15, 2019

richardlau Mar 15, 2019

gireeshpunathil commented Mar 15, 2019

Trott Mar 15, 2019

gireeshpunathil Mar 15, 2019

richardlau Mar 15, 2019

gireeshpunathil Mar 21, 2019

gireeshpunathil commented Mar 21, 2019

Trott commented Mar 21, 2019

Trott commented Mar 23, 2019

Trott commented Mar 23, 2019

gireeshpunathil commented Mar 23, 2019

gireeshpunathil commented Mar 23, 2019

gireeshpunathil commented Mar 23, 2019

Trott commented Mar 23, 2019

gireeshpunathil commented Mar 24, 2019

test: strengthen test-worker-prof #26608

test: strengthen test-worker-prof #26608

Conversation

gireeshpunathil commented Mar 12, 2019

Checklist

nodejs-github-bot commented Mar 12, 2019

Trott Mar 14, 2019

Choose a reason for hiding this comment

Trott commented Mar 14, 2019

refack commented Mar 14, 2019

gireeshpunathil commented Mar 15, 2019

gireeshpunathil commented Mar 15, 2019

richardlau Mar 15, 2019

Choose a reason for hiding this comment

gireeshpunathil commented Mar 15, 2019

Trott Mar 15, 2019

Choose a reason for hiding this comment

gireeshpunathil Mar 15, 2019

Choose a reason for hiding this comment

richardlau Mar 15, 2019

Choose a reason for hiding this comment

gireeshpunathil Mar 21, 2019

Choose a reason for hiding this comment

gireeshpunathil commented Mar 21, 2019

Trott commented Mar 21, 2019

Trott commented Mar 23, 2019

Trott commented Mar 23, 2019

gireeshpunathil commented Mar 23, 2019

gireeshpunathil commented Mar 23, 2019

gireeshpunathil commented Mar 23, 2019

Trott commented Mar 23, 2019

gireeshpunathil commented Mar 24, 2019