-
Notifications
You must be signed in to change notification settings - Fork 29.6k
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: split test-cpu-prof.js #28170
test: split test-cpu-prof.js #28170
Conversation
Split test-cpu-prof.js into multiple files for different test cases so it's easier to find the problematic one if it flakes. Also move the split tests into parallel.
Sadly, an error occurred when I tried to trigger a build. :( |
Might be a good idea to fast-track this? Feel free to 👍 this comment to approve that. |
|
||
// This tests that --cpu-prof generates CPU profile when event | ||
// loop is drained. | ||
// TODO(joyeecheung): share the fixutres with v8 coverage tests |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
// TODO(joyeecheung): share the fixutres with v8 coverage tests | |
// TODO(joyeecheung): share the fixtures with v8 coverage tests |
There's a related CI test failure https://ci.nodejs.org/job/node-test-commit-freebsd/nodes=freebsd11-x64/26813/. If this isn't fixed before landing could it at least be marked flaky? |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
RSLGTM
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
RSLGTM
Nit, doesn't have to happen in this PR, but: There should be an entry added for the |
test-cpu-prof-dir-absolute and possibly others are flaky in $ tools/test.py -j 96 --repeat 96 test/parallel/test-cpu-prof-*
=== release test-cpu-prof-dir-absolute ===
Path: parallel/test-cpu-prof-dir-absolute
Dispatching message { "id": 1, "method": "Profiler.enable" }
Receive CPU profile message, ending = false
Dispatching message { "id": 2, "method": "Profiler.start" }
Receive CPU profile message, ending = false
Dispatching message { "id": 3, "method": "Profiler.setSamplingInterval", "params": { "interval": 50 } }
Receive CPU profile message, ending = false
EndStartedProfilers
Ending cpu profiling
Dispatching message { "id": 4, "method": "Profiler.stop" }
Receive CPU profile message, ending = true
Written result to /Users/trott/io.js/test/.tmp.23/prof/CPU.20190611.101157.31392.0.001.cpuprofile
[
{
id: 1,
callFrame: {
functionName: '(root)',
scriptId: '0',
url: '',
lineNumber: -1,
columnNumber: -1
},
hitCount: 0,
children: [ 2, 3, 5, 32 ]
},
{
id: 2,
callFrame: {
functionName: '(program)',
scriptId: '0',
url: '',
lineNumber: -1,
columnNumber: -1
},
hitCount: 2
},
{
id: 3,
callFrame: {
functionName: '',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 0,
columnNumber: 0
},
hitCount: 0,
children: [ 4 ]
},
{
id: 4,
callFrame: {
functionName: 'SafeSet',
scriptId: '4',
url: 'internal/per_context/primordials.js',
lineNumber: 71,
columnNumber: 2
},
hitCount: 1,
positionTicks: [ [Object] ]
},
{
id: 5,
callFrame: {
functionName: '',
scriptId: '8',
url: 'internal/bootstrap/node.js',
lineNumber: 0,
columnNumber: 0
},
hitCount: 1,
children: [ 6, 9, 10, 13, 21, 30 ],
positionTicks: [ [Object] ]
},
{
id: 6,
callFrame: {
functionName: 'setupPrepareStackTrace',
scriptId: '8',
url: 'internal/bootstrap/node.js',
lineNumber: 294,
columnNumber: 31
},
hitCount: 0,
children: [ 7 ]
},
{
id: 7,
callFrame: {
functionName: 'nativeModuleRequire',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 182,
columnNumber: 28
},
hitCount: 0,
children: [ 8 ]
},
{
id: 8,
callFrame: {
functionName: 'NativeModule.compile',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 286,
columnNumber: 41
},
hitCount: 1,
positionTicks: [ [Object] ]
},
{
id: 9,
callFrame: {
functionName: 'internalBinding',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 127,
columnNumber: 44
},
hitCount: 1,
positionTicks: [ [Object] ]
},
{
id: 10,
callFrame: {
functionName: 'nativeModuleRequire',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 182,
columnNumber: 28
},
hitCount: 0,
children: [ 11 ]
},
{
id: 11,
callFrame: {
functionName: 'NativeModule.compile',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 286,
columnNumber: 41
},
hitCount: 0,
children: [ 12, 27, 29, 33, 34 ]
},
{
id: 12,
callFrame: {
functionName: '',
scriptId: '10',
url: 'internal/util.js',
lineNumber: 0,
columnNumber: 0
},
hitCount: 1,
positionTicks: [ [Object] ]
},
{
id: 27,
callFrame: {
functionName: '',
scriptId: '21',
url: 'internal/async_hooks.js',
lineNumber: 0,
columnNumber: 0
},
hitCount: 0,
children: [ 28 ]
},
{
id: 28,
callFrame: {
functionName: 'emitHookFactory',
scriptId: '21',
url: 'internal/async_hooks.js',
lineNumber: 181,
columnNumber: 24
},
hitCount: 1,
positionTicks: [ [Object] ]
},
{
id: 29,
callFrame: {
functionName: '',
scriptId: '22',
url: 'internal/process/task_queues.js',
lineNumber: 0,
columnNumber: 0
},
hitCount: 1,
positionTicks: [ [Object] ]
},
{
id: 33,
callFrame: {
functionName: '',
scriptId: '28',
url: 'internal/url.js',
lineNumber: 0,
columnNumber: 0
},
hitCount: 1,
positionTicks: [ [Object] ]
},
{
id: 34,
callFrame: {
functionName: '',
scriptId: '33',
url: 'timers.js',
lineNumber: 0,
columnNumber: 0
},
hitCount: 0,
children: [ 35 ]
},
{
id: 35,
callFrame: {
functionName: 'nativeModuleRequire',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 182,
columnNumber: 28
},
hitCount: 0,
children: [ 36 ]
},
{
id: 36,
callFrame: {
functionName: 'NativeModule.compile',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 286,
columnNumber: 41
},
hitCount: 1,
positionTicks: [ [Object] ]
},
{
id: 13,
callFrame: {
functionName: 'setupProcessObject',
scriptId: '8',
url: 'internal/bootstrap/node.js',
lineNumber: 300,
columnNumber: 27
},
hitCount: 0,
children: [ 14 ]
},
{
id: 14,
callFrame: {
functionName: 'nativeModuleRequire',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 182,
columnNumber: 28
},
hitCount: 0,
children: [ 15 ]
},
{
id: 15,
callFrame: {
functionName: 'NativeModule.compile',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 286,
columnNumber: 41
},
hitCount: 0,
children: [ 16 ]
},
{
id: 16,
callFrame: {
functionName: '',
scriptId: '11',
url: 'events.js',
lineNumber: 0,
columnNumber: 0
},
hitCount: 0,
children: [ 17 ]
},
{
id: 17,
callFrame: {
functionName: 'nativeModuleRequire',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 182,
columnNumber: 28
},
hitCount: 0,
children: [ 18 ]
},
{
id: 18,
callFrame: {
functionName: 'NativeModule.compile',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 286,
columnNumber: 41
},
hitCount: 0,
children: [ 19 ]
},
{
id: 19,
callFrame: {
functionName: '',
scriptId: '12',
url: 'internal/util/inspect.js',
lineNumber: 0,
columnNumber: 0
},
hitCount: 0,
children: [ 20 ]
},
{
id: 20,
callFrame: {
functionName: '',
scriptId: '12',
url: 'internal/util/inspect.js',
lineNumber: 96,
columnNumber: 44
},
hitCount: 1,
positionTicks: [ [Object] ]
},
{
id: 21,
callFrame: {
functionName: 'setupBuffer',
scriptId: '8',
url: 'internal/bootstrap/node.js',
lineNumber: 384,
columnNumber: 20
},
hitCount: 0,
children: [ 22 ]
},
{
id: 22,
callFrame: {
functionName: 'nativeModuleRequire',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 182,
columnNumber: 28
},
hitCount: 0,
children: [ 23 ]
},
{
id: 23,
callFrame: {
functionName: 'NativeModule.compile',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 286,
columnNumber: 41
},
hitCount: 0,
children: [ 24 ]
},
{
id: 24,
callFrame: {
functionName: '',
scriptId: '15',
url: 'buffer.js',
lineNumber: 0,
columnNumber: 0
},
hitCount: 1,
children: [ 25 ],
positionTicks: [ [Object] ]
},
{
id: 25,
callFrame: {
functionName: 'nativeModuleRequire',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 182,
columnNumber: 28
},
hitCount: 0,
children: [ 26 ]
},
{
id: 26,
callFrame: {
functionName: 'NativeModule.compile',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 286,
columnNumber: 41
},
hitCount: 1,
positionTicks: [ [Object] ]
},
{
id: 30,
callFrame: {
functionName: 'createGlobalConsole',
scriptId: '8',
url: 'internal/bootstrap/node.js',
lineNumber: 401,
columnNumber: 28
},
hitCount: 0,
children: [ 31 ]
},
{
id: 31,
callFrame: {
functionName: 'wrapConsole',
scriptId: '27',
url: 'internal/util/inspector.js',
lineNumber: 36,
columnNumber: 20
},
hitCount: 1,
positionTicks: [ [Object] ]
},
{
id: 32,
callFrame: {
functionName: '(garbage collector)',
scriptId: '0',
url: '',
lineNumber: -1,
columnNumber: -1
},
hitCount: 2
}
]
assert.js:89
throw new AssertionError(obj);
^
AssertionError [ERR_ASSERTION]: Expected "actual" not to be strictly deep-equal to: []
at verifyFrames (/Users/trott/io.js/test/common/cpu-prof.js:34:10)
at Object.<anonymous> (/Users/trott/io.js/test/parallel/test-cpu-prof-dir-absolute.js:44:3)
at Module._compile (internal/modules/cjs/loader.js:777:30)
at Object.Module._extensions..js (internal/modules/cjs/loader.js:788:10)
at Module.load (internal/modules/cjs/loader.js:640:32)
at Function.Module._load (internal/modules/cjs/loader.js:555:12)
at Function.Module.runMain (internal/modules/cjs/loader.js:840:10)
at internal/main/run_main_module.js:17:11 {
generatedMessage: true,
code: 'ERR_ASSERTION',
actual: [],
expected: [],
operator: 'notDeepStrictEqual'
}
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cpu-prof-dir-absolute.js
=== release test-cpu-prof-dir-absolute ===
Path: parallel/test-cpu-prof-dir-absolute
Dispatching message { "id": 1, "method": "Profiler.enable" }
Receive CPU profile message, ending = false
Dispatching message { "id": 2, "method": "Profiler.start" }
Receive CPU profile message, ending = false
Dispatching message { "id": 3, "method": "Profiler.setSamplingInterval", "params": { "interval": 50 } }
Receive CPU profile message, ending = false
EndStartedProfilers
Ending cpu profiling
Dispatching message { "id": 4, "method": "Profiler.stop" }
Receive CPU profile message, ending = true
Written result to /Users/trott/io.js/test/.tmp.39/prof/CPU.20190611.101155.31321.0.001.cpuprofile
[
{
id: 1,
callFrame: {
functionName: '(root)',
scriptId: '0',
url: '',
lineNumber: -1,
columnNumber: -1
},
hitCount: 0,
children: [ 2, 3, 4, 23 ]
},
{
id: 2,
callFrame: {
functionName: '(program)',
scriptId: '0',
url: '',
lineNumber: -1,
columnNumber: -1
},
hitCount: 3
},
{
id: 3,
callFrame: {
functionName: '',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 0,
columnNumber: 0
},
hitCount: 1,
positionTicks: [ [Object] ]
},
{
id: 4,
callFrame: {
functionName: '',
scriptId: '8',
url: 'internal/bootstrap/node.js',
lineNumber: 0,
columnNumber: 0
},
hitCount: 2,
children: [ 5, 9, 13, 19 ],
positionTicks: [ [Object], [Object] ]
},
{
id: 5,
callFrame: {
functionName: 'setupPrepareStackTrace',
scriptId: '8',
url: 'internal/bootstrap/node.js',
lineNumber: 294,
columnNumber: 31
},
hitCount: 0,
children: [ 6 ]
},
{
id: 6,
callFrame: {
functionName: 'nativeModuleRequire',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 182,
columnNumber: 28
},
hitCount: 0,
children: [ 7 ]
},
{
id: 7,
callFrame: {
functionName: 'NativeModule.compile',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 286,
columnNumber: 41
},
hitCount: 0,
children: [ 8 ]
},
{
id: 8,
callFrame: {
functionName: '',
scriptId: '9',
url: 'internal/errors.js',
lineNumber: 0,
columnNumber: 0
},
hitCount: 1,
positionTicks: [ [Object] ]
},
{
id: 9,
callFrame: {
functionName: 'nativeModuleRequire',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 182,
columnNumber: 28
},
hitCount: 0,
children: [ 10 ]
},
{
id: 10,
callFrame: {
functionName: 'NativeModule.compile',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 286,
columnNumber: 41
},
hitCount: 1,
children: [ 11 ],
positionTicks: [ [Object] ]
},
{
id: 11,
callFrame: {
functionName: '',
scriptId: '10',
url: 'internal/util.js',
lineNumber: 0,
columnNumber: 0
},
hitCount: 0,
children: [ 12 ]
},
{
id: 12,
callFrame: {
functionName: 'internalBinding',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 127,
columnNumber: 44
},
hitCount: 1,
positionTicks: [ [Object] ]
},
{
id: 13,
callFrame: {
functionName: 'setupProcessObject',
scriptId: '8',
url: 'internal/bootstrap/node.js',
lineNumber: 300,
columnNumber: 27
},
hitCount: 0,
children: [ 14 ]
},
{
id: 14,
callFrame: {
functionName: 'nativeModuleRequire',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 182,
columnNumber: 28
},
hitCount: 0,
children: [ 15 ]
},
{
id: 15,
callFrame: {
functionName: 'NativeModule.compile',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 286,
columnNumber: 41
},
hitCount: 0,
children: [ 16 ]
},
{
id: 16,
callFrame: {
functionName: '',
scriptId: '11',
url: 'events.js',
lineNumber: 0,
columnNumber: 0
},
hitCount: 1,
children: [ 17 ],
positionTicks: [ [Object] ]
},
{
id: 17,
callFrame: {
functionName: 'nativeModuleRequire',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 182,
columnNumber: 28
},
hitCount: 0,
children: [ 18 ]
},
{
id: 18,
callFrame: {
functionName: 'NativeModule.compile',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 286,
columnNumber: 41
},
hitCount: 1,
positionTicks: [ [Object] ]
},
{
id: 19,
callFrame: {
functionName: 'setupBuffer',
scriptId: '8',
url: 'internal/bootstrap/node.js',
lineNumber: 384,
columnNumber: 20
},
hitCount: 0,
children: [ 20 ]
},
{
id: 20,
callFrame: {
functionName: 'nativeModuleRequire',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 182,
columnNumber: 28
},
hitCount: 0,
children: [ 21 ]
},
{
id: 21,
callFrame: {
functionName: 'NativeModule.compile',
scriptId: '7',
url: 'internal/bootstrap/loaders.js',
lineNumber: 286,
columnNumber: 41
},
hitCount: 0,
children: [ 22 ]
},
{
id: 22,
callFrame: {
functionName: '',
scriptId: '15',
url: 'buffer.js',
lineNumber: 0,
columnNumber: 0
},
hitCount: 1,
positionTicks: [ [Object] ]
},
{
id: 23,
callFrame: {
functionName: '(garbage collector)',
scriptId: '0',
url: '',
lineNumber: -1,
columnNumber: -1
},
hitCount: 2
}
]
assert.js:89
throw new AssertionError(obj);
^
AssertionError [ERR_ASSERTION]: Expected "actual" not to be strictly deep-equal to: []
at verifyFrames (/Users/trott/io.js/test/common/cpu-prof.js:34:10)
at Object.<anonymous> (/Users/trott/io.js/test/parallel/test-cpu-prof-dir-absolute.js:44:3)
at Module._compile (internal/modules/cjs/loader.js:777:30)
at Object.Module._extensions..js (internal/modules/cjs/loader.js:788:10)
at Module.load (internal/modules/cjs/loader.js:640:32)
at Function.Module._load (internal/modules/cjs/loader.js:555:12)
at Function.Module.runMain (internal/modules/cjs/loader.js:840:10)
at internal/main/run_main_module.js:17:11 {
generatedMessage: true,
code: 'ERR_ASSERTION',
actual: [],
expected: [],
operator: 'notDeepStrictEqual'
}
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cpu-prof-dir-absolute.js |
I'm getting results showing test-cpu-prof-dir-relative and test-cpu-prof-name flaky too with |
I’d prefer to mark the tasks as flaky over moving them to sequential, if there’s no other reason for them to end up in sequential… |
I would definitely prefer to have 11 reliable tests in sequential than 11 flaky tests in parallel. Moving them to sequential and running them all takes less than 2 seconds on my laptop (4 year-old MacBook Pro) so I don't expect a significant developer inconvenience for putting them in sequential. |
@Trott The thing is, the flakyness points to a bug in the test(s) or in Node.js, and I’d rather have reminders to get them fixed rather than solving them by modifying the circumstances under which they run… also, this is cumulative, and even if these tests run pretty fast, I’m pretty sure our history of moving tests to /sequential is one of the reasons why parallel/ runs in 1m30s for me and the rest of the test suite in 3m30s :) Anyway, no strong feelings about this PR in particular |
Generally, I agree with that but in this particular case, is it really a bug in the test? IIUC, the tests are doing CPU profiling so keeping other things off the CPU while they do their thing would seem to be a valid approach. (If they were Anyway, like you, I don't want to get too much in the weeds on this, and I'm fine if it lands as is. The tests can always be moved later if that's deemed the right thing to do.
I'd be interested to know how long sequential/ takes for you. Here's my results: parallel: 7:40 If your results are like mine, sequential just isn't a significant factor. Aside: It might be time for me to invest in a new laptop... |
I agree with @addaleax - moving them to sequential may make them more reliable, for now, but that's not where they are supposed to end up, at least I can't see why the tests have to be in sequential in nature. There are two kinds of flakes:
So we need to either improve the workload or find the bug. These tests are somewhat similar to GC stress tests so another solution may be to just make the assertions more lenient (i.e. just check that the file exists and contains some samples but don't look for the target function there). |
If there's a need to generate a specific workload with a target function, wouldn't that be a reason to keep the CPU free of other things it has to do? In other words, a reason to put the test in sequential? (Or am I just Not Understanding These Tests?) |
@Trott Keeping it in sequential might help keeping the samples more accurate - however the workload is supposed to run long enough so that this does not matter. We may know whether this matters after observing the type of failures after this PR. This is, I guess, also a valid use case of the CPU profiler - if you are profiling your applications, then it's probably already under heavy load or consuming significant amount of CPU time otherwise you would bother doing the profiling for optimizations. |
@Trott a few numbers from my machine which has 12 logical cores.
|
CI is green (not necessarily indicating the flake is gone but the flake is now split into different files) Landed in 8f98cf5 with the nit fixed. Let's observe and figure out what to do next. |
Split test-cpu-prof.js into multiple files for different test cases so it's easier to find the problematic one if it flakes. Also move the split tests into parallel. PR-URL: #28170 Refs: #27611 Reviewed-By: Gireesh Punathil <[email protected]> Reviewed-By: Anna Henningsen <[email protected]> Reviewed-By: Yongsheng Zhang <[email protected]> Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: Sam Roberts <[email protected]> Reviewed-By: Trivikram Kamat <[email protected]>
Split test-cpu-prof.js into multiple files for different test cases so it's easier to find the problematic one if it flakes. Also move the split tests into parallel. PR-URL: #28170 Refs: #27611 Reviewed-By: Gireesh Punathil <[email protected]> Reviewed-By: Anna Henningsen <[email protected]> Reviewed-By: Yongsheng Zhang <[email protected]> Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: Sam Roberts <[email protected]> Reviewed-By: Trivikram Kamat <[email protected]>
Split test-cpu-prof.js into multiple files for different
test cases so it's easier to find the problematic one if
it flakes.
Also move the split tests into parallel.
Refs: #27611
Checklist
make -j4 test
(UNIX), orvcbuild test
(Windows) passes