investigate flaky test-cpu-prof

[Trott]

https://ci.nodejs.org/job/node-test-commit-freebsd/26122/nodes=freebsd11-x64/console

test-digitalocean-freebsd11-x64-2

Details

00:15:35 not ok 2553 sequential/test-cpu-prof
00:15:35 ---
00:15:35 duration_ms: 2.101
00:15:35 severity: fail
00:15:35 exitcode: 1
00:15:35 stack: |-
00:15:35 Dispatching message { "id": 1, "method": "Profiler.enable" }
00:15:35 Receive CPU profile message, ending = false
00:15:35 Dispatching message { "id": 2, "method": "Profiler.start" }
00:15:35 Receive CPU profile message, ending = false
00:15:35 Dispatching message { "id": 3, "method": "Profiler.setSamplingInterval", "params": { "interval": 50 } }
00:15:35 Receive CPU profile message, ending = false
00:15:35 Dispatching message { "id": 1, "method": "Profiler.enable" }
00:15:35 Receive CPU profile message, ending = false
00:15:35 Dispatching message { "id": 2, "method": "Profiler.start" }
00:15:35 Receive CPU profile message, ending = false
00:15:35 Dispatching message { "id": 3, "method": "Profiler.setSamplingInterval", "params": { "interval": 50 } }
00:15:35 Receive CPU profile message, ending = false
00:15:35 EndStartedProfilers
00:15:35 Ending cpu profiling
00:15:35 Dispatching message { "id": 4, "method": "Profiler.stop" }
00:15:35 Receive CPU profile message, ending = true
00:15:35 Written result to prof/CPU.20190508.071535.5764.1.002.cpuprofile
00:15:35 EndStartedProfilers
00:15:35 Ending cpu profiling
00:15:35 Dispatching message { "id": 4, "method": "Profiler.stop" }
00:15:35 Receive CPU profile message, ending = true
00:15:35 Written result to prof/CPU.20190508.071535.5764.0.001.cpuprofile
00:15:35 
00:15:35 CPU path: /usr/home/iojs/node-tmp/.tmp.0/prof/CPU.20190508.071535.5764.0.001.cpuprofile
00:15:35 [
00:15:35 {
00:15:35 id: 1,
00:15:35 callFrame: {
00:15:35 functionName: '(root)',
00:15:35 scriptId: '0',
00:15:35 url: '',
00:15:35 lineNumber: -1,
00:15:35 columnNumber: -1
00:15:35 },
00:15:35 hitCount: 0,
00:15:35 children: [ 2, 3, 5, 25, 55, 58 ]
00:15:35 },
00:15:35 {
00:15:35 id: 2,
00:15:35 callFrame: {
00:15:35 functionName: '(program)',
00:15:35 scriptId: '0',
00:15:35 url: '',
00:15:35 lineNumber: -1,
00:15:35 columnNumber: -1
00:15:35 },
00:15:35 hitCount: 9
00:15:35 },
00:15:35 {
00:15:35 id: 3,
00:15:35 callFrame: {
00:15:35 functionName: '',
00:15:35 scriptId: '7',
00:15:35 url: 'internal/bootstrap/loaders.js',
00:15:35 lineNumber: 0,
00:15:35 columnNumber: 0
00:15:35 },
00:15:35 hitCount: 0,
00:15:35 children: [ 4 ]
00:15:35 },
00:15:35 {
00:15:35 id: 4,
00:15:35 callFrame: {
00:15:35 functionName: 'internalBinding',
00:15:35 scriptId: '7',
00:15:35 url: 'internal/bootstrap/loaders.js',
00:15:35 lineNumber: 127,
00:15:35 columnNumber: 44
00:15:35 },
00:15:35 hitCount: 1,
00:15:35 positionTicks: [ [Object] ]
00:15:35 },
00:15:35 {
00:15:35 id: 5,
00:15:35 callFrame: {
00:15:35 functionName: '',
00:15:35 scriptId: '8',
00:15:35 url: 'internal/bootstrap/node.js',
00:15:35 lineNumber: 0,
00:15:35 columnNumber: 0
00:15:35 },
00:15:35 hitCount: 4,
00:15:35 children: [ 6, 15, 23 ],
00:15:35 positionTicks: [ [Object], [Object], [Object], [Object] ]
00:15:35 },
00:15:35 {
00:15:35 id: 6,
00:15:35 callFrame: {
00:15:35 functionName: 'nativeModuleRequire',
00:15:35 scriptId: '7',
00:15:35 url: 'internal/bootstrap/loaders.js',
00:15:35 lineNumber: 182,
00:15:35 columnNumber: 28
00:15:35 },
00:15:35 hitCount: 0,
00:15:35 children: [ 7 ]
00:15:35 },
00:15:35 {
00:15:35 id: 7,
00:15:35 callFrame: {
00:15:35 functionName: 'NativeModule.compile',
00:15:35 scriptId: '7',
00:15:35 url: 'internal/bootstrap/loaders.js',
00:15:35 lineNumber: 286,
00:15:35 columnNumber: 41
00:15:35 },
00:15:35 hitCount: 3,
00:15:35 children: [ 8, 24 ],
00:15:35 positionTicks: [ [Object] ]
00:15:35 },
00:15:35 {
00:15:35 id: 8,
00:15:35 callFrame: {
00:15:35 functionName: '',
00:15:35 scriptId: '9',
00:15:35 url: 'internal/util.js',
00:15:35 lineNumber: 0,
00:15:35 columnNumber: 0
00:15:35 },
00:15:35 hitCount: 0,
00:15:35 children: [ 9, 14 ]
00:15:35 },
00:15:35 {
00:15:35 id: 9,
00:15:35 callFrame: {
00:15:35 functionName: 'nativeModuleRequire',
00:15:35 scriptId: '7',
00:15:35 url: 'internal/bootstrap/loaders.js',
00:15:35 lineNumber: 182,
00:15:35 columnNumber: 28
00:15:35 },
00:15:35 hitCount: 0,
00:15:35 children: [ 10 ]
00:15:35 },
00:15:35 {
00:15:35 id: 10,
00:15:35 callFrame: {
00:15:35 functionName: 'NativeModule.compile',
00:15:35 scriptId: '7',
00:15:35 url: 'internal/bootstrap/loaders.js',
00:15:35 lineNumber: 286,
00:15:35 columnNumber: 41
00:15:35 },
00:15:35 hitCount: 1,
00:15:35 children: [ 11 ],
00:15:35 positionTicks: [ [Object] ]
00:15:35 },
00:15:35 {
00:15:35 id: 11,
00:15:35 callFrame: {
00:15:35 functionName: '',
00:15:35 scriptId: '10',
00:15:35 url: 'internal/errors.js',
00:15:35 lineNumber: 0,
00:15:35 columnNumber: 0
00:15:35 },
00:15:35 hitCount: 0,
00:15:35 children: [ 12 ]
00:15:35 },
00:15:35 {
00:15:35 id: 12,
00:15:35 callFrame: {
00:15:35 functionName: 'E',
00:15:35 scriptId: '10',
00:15:35 url: 'internal/errors.js',
00:15:35 lineNumber: 250,
00:15:36 columnNumber: 10
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 children: [ 13 ],
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 13,
00:15:36 callFrame: {
00:15:36 functionName: 'makeNodeErrorWithCode',
00:15:36 scriptId: '10',
00:15:36 url: 'internal/errors.js',
00:15:36 lineNumber: 164,
00:15:36 columnNumber: 30
00:15:36 },
00:15:36 hitCount: 2,
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 14,
00:15:36 callFrame: {
00:15:36 functionName: 'internalBinding',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 127,
00:15:36 columnNumber: 44
00:15:36 },
00:15:36 hitCount: 2,
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 24,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '21',
00:15:36 url: 'internal/async_hooks.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 15,
00:15:36 callFrame: {
00:15:36 functionName: 'setupBuffer',
00:15:36 scriptId: '8',
00:15:36 url: 'internal/bootstrap/node.js',
00:15:36 lineNumber: 376,
00:15:36 columnNumber: 20
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 16 ]
00:15:36 },
00:15:36 {
00:15:36 id: 16,
00:15:36 callFrame: {
00:15:36 functionName: 'nativeModuleRequire',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 182,
00:15:36 columnNumber: 28
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 17 ]
00:15:36 },
00:15:36 {
00:15:36 id: 17,
00:15:36 callFrame: {
00:15:36 functionName: 'NativeModule.compile',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 286,
00:15:36 columnNumber: 41
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 18 ]
00:15:36 },
00:15:36 {
00:15:36 id: 18,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '12',
00:15:36 url: 'buffer.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 19, 22 ]
00:15:36 },
00:15:36 {
00:15:36 id: 19,
00:15:36 callFrame: {
00:15:36 functionName: 'nativeModuleRequire',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 182,
00:15:36 columnNumber: 28
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 20 ]
00:15:36 },
00:15:36 {
00:15:36 id: 20,
00:15:36 callFrame: {
00:15:36 functionName: 'NativeModule.compile',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 286,
00:15:36 columnNumber: 41
00:15:36 },
00:15:36 hitCount: 2,
00:15:36 children: [ 21 ],
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 21,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '14',
00:15:36 url: 'internal/util/inspect.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 22,
00:15:36 callFrame: {
00:15:36 functionName: 'createPool',
00:15:36 scriptId: '12',
00:15:36 url: 'buffer.js',
00:15:36 lineNumber: 120,
00:15:36 columnNumber: 19
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 23,
00:15:36 callFrame: {
00:15:36 functionName: 'wrapPosixCredentialSetters',
00:15:36 scriptId: '19',
00:15:36 url: 'internal/process/main_thread_only.js',
00:15:36 lineNumber: 53,
00:15:36 columnNumber: 35
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 25,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '40',
00:15:36 url: 'internal/main/run_main_module.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 26, 27 ]
00:15:36 },
00:15:36 {
00:15:36 id: 26,
00:15:36 callFrame: {
00:15:36 functionName: 'prepareMainThreadExecution',
00:15:36 scriptId: '41',
00:15:36 url: 'internal/bootstrap/pre_execution.js',
00:15:36 lineNumber: 7,
00:15:36 columnNumber: 35
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 27,
00:15:36 callFrame: {
00:15:36 functionName: 'Module.runMain',
00:15:36 scriptId: '44',
00:15:36 url: 'internal/modules/cjs/loader.js',
00:15:36 lineNumber: 807,
00:15:36 columnNumber: 25
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 28 ]
00:15:36 },
00:15:36 {
00:15:36 id: 28,
00:15:36 callFrame: {
00:15:36 functionName: 'Module._load',
00:15:36 scriptId: '44',
00:15:36 url: 'internal/modules/cjs/loader.js',
00:15:36 lineNumber: 506,
00:15:36 columnNumber: 23
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 29 ]
00:15:36 },
00:15:36 {
00:15:36 id: 29,
00:15:36 callFrame: {
00:15:36 functionName: 'Module.load',
00:15:36 scriptId: '44',
00:15:36 url: 'internal/modules/cjs/loader.js',
00:15:36 lineNumber: 619,
00:15:36 columnNumber: 32
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 30 ]
00:15:36 },
00:15:36 {
00:15:36 id: 30,
00:15:36 callFrame: {
00:15:36 functionName: 'Module._extensions..js',
00:15:36 scriptId: '44',
00:15:36 url: 'internal/modules/cjs/loader.js',
00:15:36 lineNumber: 767,
00:15:36 columnNumber: 36
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 31 ]
00:15:36 },
00:15:36 {
00:15:36 id: 31,
00:15:36 callFrame: {
00:15:36 functionName: 'Module._compile',
00:15:36 scriptId: '44',
00:15:36 url: 'internal/modules/cjs/loader.js',
00:15:36 lineNumber: 681,
00:15:36 columnNumber: 36
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 32 ]
00:15:36 },
00:15:36 {
00:15:36 id: 32,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '52',
00:15:36 url: 'file:///usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd11-x64/test/fixtures/workload/fibonacci-worker.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 33, 54 ]
00:15:36 },
00:15:36 {
00:15:36 id: 33,
00:15:36 callFrame: {
00:15:36 functionName: 'require',
00:15:36 scriptId: '49',
00:15:36 url: 'internal/modules/cjs/helpers.js',
00:15:36 lineNumber: 14,
00:15:36 columnNumber: 18
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 34 ]
00:15:36 },
00:15:36 {
00:15:36 id: 34,
00:15:36 callFrame: {
00:15:36 functionName: 'Module.require',
00:15:36 scriptId: '44',
00:15:36 url: 'internal/modules/cjs/loader.js',
00:15:36 lineNumber: 657,
00:15:36 columnNumber: 35
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 35 ]
00:15:36 },
00:15:36 {
00:15:36 id: 35,
00:15:36 callFrame: {
00:15:36 functionName: 'Module._load',
00:15:36 scriptId: '44',
00:15:36 url: 'internal/modules/cjs/loader.js',
00:15:36 lineNumber: 506,
00:15:36 columnNumber: 23
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 36 ]
00:15:36 },
00:15:36 {
00:15:36 id: 36,
00:15:36 callFrame: {
00:15:36 functionName: 'NativeModule.compileForPublicLoader',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 210,
00:15:36 columnNumber: 56
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 37 ]
00:15:36 },
00:15:36 {
00:15:36 id: 37,
00:15:36 callFrame: {
00:15:36 functionName: 'NativeModule.compile',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 286,
00:15:36 columnNumber: 41
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 38 ]
00:15:36 },
00:15:36 {
00:15:36 id: 38,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '53',
00:15:36 url: 'worker_threads.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 39 ]
00:15:36 },
00:15:36 {
00:15:36 id: 39,
00:15:36 callFrame: {
00:15:36 functionName: 'nativeModuleRequire',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 182,
00:15:36 columnNumber: 28
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 40 ]
00:15:36 },
00:15:36 {
00:15:36 id: 40,
00:15:36 callFrame: {
00:15:36 functionName: 'NativeModule.compile',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 286,
00:15:36 columnNumber: 41
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 41 ]
00:15:36 },
00:15:36 {
00:15:36 id: 41,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '54',
00:15:36 url: 'internal/worker.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 42 ]
00:15:36 },
00:15:36 {
00:15:36 id: 42,
00:15:36 callFrame: {
00:15:36 functionName: 'nativeModuleRequire',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 182,
00:15:36 columnNumber: 28
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 43 ]
00:15:36 },
00:15:36 {
00:15:36 id: 43,
00:15:36 callFrame: {
00:15:36 functionName: 'NativeModule.compile',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 286,
00:15:36 columnNumber: 41
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 44 ]
00:15:36 },
00:15:36 {
00:15:36 id: 44,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '55',
00:15:36 url: 'internal/worker/io.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 children: [ 45 ],
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 45,
00:15:36 callFrame: {
00:15:36 functionName: 'nativeModuleRequire',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 182,
00:15:36 columnNumber: 28
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 46 ]
00:15:36 },
00:15:36 {
00:15:36 id: 46,
00:15:36 callFrame: {
00:15:36 functionName: 'NativeModule.compile',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 286,
00:15:36 columnNumber: 41
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 47 ]
00:15:36 },
00:15:36 {
00:15:36 id: 47,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '56',
00:15:36 url: 'stream.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 48 ]
00:15:36 },
00:15:36 {
00:15:36 id: 48,
00:15:36 callFrame: {
00:15:36 functionName: 'nativeModuleRequire',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 182,
00:15:36 columnNumber: 28
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 49 ]
00:15:36 },
00:15:36 {
00:15:36 id: 49,
00:15:36 callFrame: {
00:15:36 functionName: 'NativeModule.compile',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 286,
00:15:36 columnNumber: 41
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 50, 53 ]
00:15:36 },
00:15:36 {
00:15:36 id: 50,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '60',
00:15:36 url: '_stream_readable.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 51 ]
00:15:36 },
00:15:36 {
00:15:36 id: 51,
00:15:36 callFrame: {
00:15:36 functionName: 'nativeModuleRequire',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 182,
00:15:36 columnNumber: 28
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 52 ]
00:15:36 },
00:15:36 {
00:15:36 id: 52,
00:15:36 callFrame: {
00:15:36 functionName: 'NativeModule.compile',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 286,
00:15:36 columnNumber: 41
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 53,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '64',
00:15:36 url: '_stream_writable.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 54,
00:15:36 callFrame: {
00:15:36 functionName: 'join',
00:15:36 scriptId: '31',
00:15:36 url: 'path.js',
00:15:36 lineNumber: 1030,
00:15:36 columnNumber: 6
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 55,
00:15:36 callFrame: {
00:15:36 functionName: 'processTicksAndRejections',
00:15:36 scriptId: '22',
00:15:36 url: 'internal/process/task_queues.js',
00:15:36 lineNumber: 61,
00:15:36 columnNumber: 34
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 56 ]
00:15:36 },
00:15:36 {
00:15:36 id: 56,
00:15:36 callFrame: {
00:15:36 functionName: 'resume_',
00:15:36 scriptId: '60',
00:15:36 url: '_stream_readable.js',
00:15:36 lineNumber: 932,
00:15:36 columnNumber: 16
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 57 ]
00:15:36 },
00:15:36 {
00:15:36 id: 57,
00:15:36 callFrame: {
00:15:36 functionName: 'Readable.read',
00:15:36 scriptId: '60',
00:15:36 url: '_stream_readable.js',
00:15:36 lineNumber: 376,
00:15:36 columnNumber: 34
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 58,
00:15:36 callFrame: {
00:15:36 functionName: 'onmessage',
00:15:36 scriptId: '55',
00:15:36 url: 'internal/worker/io.js',
00:15:36 lineNumber: 63,
00:15:36 columnNumber: 62
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 59 ]
00:15:36 },
00:15:36 {
00:15:36 id: 59,
00:15:36 callFrame: {
00:15:36 functionName: 'emit',
00:15:36 scriptId: '11',
00:15:36 url: 'events.js',
00:15:36 lineNumber: 144,
00:15:36 columnNumber: 43
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 60 ]
00:15:36 },
00:15:36 {
00:15:36 id: 60,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '54',
00:15:36 url: 'internal/worker.js',
00:15:36 lineNumber: 117,
00:15:36 columnNumber: 30
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 61 ]
00:15:36 },
00:15:36 {
00:15:36 id: 61,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '54',
00:15:36 url: 'internal/worker.js',
00:15:36 lineNumber: 178,
00:15:36 columnNumber: 14
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 62 ]
00:15:36 },
00:15:36 {
00:15:36 id: 62,
00:15:36 callFrame: {
00:15:36 functionName: 'Readable.push',
00:15:36 scriptId: '60',
00:15:36 url: '_stream_readable.js',
00:15:36 lineNumber: 208,
00:15:36 columnNumber: 34
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 63 ]
00:15:36 },
00:15:36 {
00:15:36 id: 63,
00:15:36 callFrame: {
00:15:36 functionName: 'readableAddChunk',
00:15:36 scriptId: '60',
00:15:36 url: '_stream_readable.js',
00:15:36 lineNumber: 233,
00:15:36 columnNumber: 25
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 64 ]
00:15:36 },
00:15:36 {
00:15:36 id: 64,
00:15:36 callFrame: {
00:15:36 functionName: 'addChunk',
00:15:36 scriptId: '60',
00:15:36 url: '_stream_readable.js',
00:15:36 lineNumber: 286,
00:15:36 columnNumber: 17
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 65 ]
00:15:36 },
00:15:36 {
00:15:36 id: 65,
00:15:36 callFrame: {
00:15:36 functionName: 'maybeReadMore',
00:15:36 scriptId: '60',
00:15:36 url: '_stream_readable.js',
00:15:36 lineNumber: 564,
00:15:36 columnNumber: 22
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 positionTicks: [ [Object] ]
00:15:36 }
00:15:36 ]
00:15:36 CPU path: /usr/home/iojs/node-tmp/.tmp.0/prof/CPU.20190508.071535.5764.1.002.cpuprofile
00:15:36 [
00:15:36 {
00:15:36 id: 1,
00:15:36 callFrame: {
00:15:36 functionName: '(root)',
00:15:36 scriptId: '0',
00:15:36 url: '',
00:15:36 lineNumber: -1,
00:15:36 columnNumber: -1
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 2, 3, 5, 37 ]
00:15:36 },
00:15:36 {
00:15:36 id: 2,
00:15:36 callFrame: {
00:15:36 functionName: '(program)',
00:15:36 scriptId: '0',
00:15:36 url: '',
00:15:36 lineNumber: -1,
00:15:36 columnNumber: -1
00:15:36 },
00:15:36 hitCount: 2
00:15:36 },
00:15:36 {
00:15:36 id: 3,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 children: [ 4 ],
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 4,
00:15:36 callFrame: {
00:15:36 functionName: 'NativeModule',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 148,
00:15:36 columnNumber: 21
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 5,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '8',
00:15:36 url: 'internal/bootstrap/node.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 children: [ 6, 14, 15, 16 ],
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 6,
00:15:36 callFrame: {
00:15:36 functionName: 'nativeModuleRequire',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 182,
00:15:36 columnNumber: 28
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 children: [ 7 ],
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 7,
00:15:36 callFrame: {
00:15:36 functionName: 'NativeModule.compile',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 286,
00:15:36 columnNumber: 41
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 children: [ 8, 25 ],
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 8,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '9',
00:15:36 url: 'internal/util.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 children: [ 9, 13 ],
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 9,
00:15:36 callFrame: {
00:15:36 functionName: 'nativeModuleRequire',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 182,
00:15:36 columnNumber: 28
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 10 ]
00:15:36 },
00:15:36 {
00:15:36 id: 10,
00:15:36 callFrame: {
00:15:36 functionName: 'NativeModule.compile',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 286,
00:15:36 columnNumber: 41
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 children: [ 11 ],
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 11,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '10',
00:15:36 url: 'internal/errors.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 children: [ 12 ],
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 12,
00:15:36 callFrame: {
00:15:36 functionName: 'E',
00:15:36 scriptId: '10',
00:15:36 url: 'internal/errors.js',
00:15:36 lineNumber: 250,
00:15:36 columnNumber: 10
00:15:36 },
00:15:36 hitCount: 2,
00:15:36 positionTicks: [ [Object], [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 13,
00:15:36 callFrame: {
00:15:36 functionName: 'internalBinding',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 127,
00:15:36 columnNumber: 44
00:15:36 },
00:15:36 hitCount: 2,
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 25,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '19',
00:15:36 url: 'internal/process/worker_thread_only.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 26 ]
00:15:36 },
00:15:36 {
00:15:36 id: 26,
00:15:36 callFrame: {
00:15:36 functionName: 'nativeModuleRequire',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 182,
00:15:36 columnNumber: 28
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 27 ]
00:15:36 },
00:15:36 {
00:15:36 id: 27,
00:15:36 callFrame: {
00:15:36 functionName: 'NativeModule.compile',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 286,
00:15:36 columnNumber: 41
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 28 ]
00:15:36 },
00:15:36 {
00:15:36 id: 28,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '20',
00:15:36 url: 'internal/worker/io.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 29 ]
00:15:36 },
00:15:36 {
00:15:36 id: 29,
00:15:36 callFrame: {
00:15:36 functionName: 'nativeModuleRequire',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 182,
00:15:36 columnNumber: 28
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 30 ]
00:15:36 },
00:15:36 {
00:15:36 id: 30,
00:15:36 callFrame: {
00:15:36 functionName: 'NativeModule.compile',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 286,
00:15:36 columnNumber: 41
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 31 ]
00:15:36 },
00:15:36 {
00:15:36 id: 31,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '21',
00:15:36 url: 'stream.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 32 ]
00:15:36 },
00:15:36 {
00:15:36 id: 32,
00:15:36 callFrame: {
00:15:36 functionName: 'nativeModuleRequire',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 182,
00:15:36 columnNumber: 28
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 33 ]
00:15:36 },
00:15:36 {
00:15:36 id: 33,
00:15:36 callFrame: {
00:15:36 functionName: 'NativeModule.compile',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 286,
00:15:36 columnNumber: 41
00:15:36 },
00:15:36 hitCount: 3,
00:15:36 children: [ 34 ],
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 34,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '25',
00:15:36 url: '_stream_readable.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 35 ]
00:15:36 },
00:15:36 {
00:15:36 id: 35,
00:15:36 callFrame: {
00:15:36 functionName: 'nativeModuleRequire',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 182,
00:15:36 columnNumber: 28
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 36 ]
00:15:36 },
00:15:36 {
00:15:36 id: 36,
00:15:36 callFrame: {
00:15:36 functionName: 'NativeModule.compile',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 286,
00:15:36 columnNumber: 41
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 14,
00:15:36 callFrame: {
00:15:36 functionName: 'setupProcessObject',
00:15:36 scriptId: '8',
00:15:36 url: 'internal/bootstrap/node.js',
00:15:36 lineNumber: 292,
00:15:36 columnNumber: 27
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 15,
00:15:36 callFrame: {
00:15:36 functionName: 'setupGlobalProxy',
00:15:36 scriptId: '8',
00:15:36 url: 'internal/bootstrap/node.js',
00:15:36 lineNumber: 337,
00:15:36 columnNumber: 25
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 16,
00:15:36 callFrame: {
00:15:36 functionName: 'setupBuffer',
00:15:36 scriptId: '8',
00:15:36 url: 'internal/bootstrap/node.js',
00:15:36 lineNumber: 376,
00:15:36 columnNumber: 20
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 17 ]
00:15:36 },
00:15:36 {
00:15:36 id: 17,
00:15:36 callFrame: {
00:15:36 functionName: 'nativeModuleRequire',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 182,
00:15:36 columnNumber: 28
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 18 ]
00:15:36 },
00:15:36 {
00:15:36 id: 18,
00:15:36 callFrame: {
00:15:36 functionName: 'NativeModule.compile',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 286,
00:15:36 columnNumber: 41
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 children: [ 19 ],
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 19,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '12',
00:15:36 url: 'buffer.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 20, 24 ]
00:15:36 },
00:15:36 {
00:15:36 id: 20,
00:15:36 callFrame: {
00:15:36 functionName: 'nativeModuleRequire',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 182,
00:15:36 columnNumber: 28
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 21 ]
00:15:36 },
00:15:36 {
00:15:36 id: 21,
00:15:36 callFrame: {
00:15:36 functionName: 'NativeModule.compile',
00:15:36 scriptId: '7',
00:15:36 url: 'internal/bootstrap/loaders.js',
00:15:36 lineNumber: 286,
00:15:36 columnNumber: 41
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 22, 23 ]
00:15:36 },
00:15:36 {
00:15:36 id: 22,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '14',
00:15:36 url: 'internal/util/inspect.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 3,
00:15:36 positionTicks: [ [Object], [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 23,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '17',
00:15:36 url: 'internal/buffer.js',
00:15:36 lineNumber: 0,
00:15:36 columnNumber: 0
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 24,
00:15:36 callFrame: {
00:15:36 functionName: 'createPool',
00:15:36 scriptId: '12',
00:15:36 url: 'buffer.js',
00:15:36 lineNumber: 120,
00:15:36 columnNumber: 19
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 positionTicks: [ [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 37,
00:15:36 callFrame: {
00:15:36 functionName: 'onmessage',
00:15:36 scriptId: '20',
00:15:36 url: 'internal/worker/io.js',
00:15:36 lineNumber: 63,
00:15:36 columnNumber: 62
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 38 ]
00:15:36 },
00:15:36 {
00:15:36 id: 38,
00:15:36 callFrame: {
00:15:36 functionName: 'emit',
00:15:36 scriptId: '11',
00:15:36 url: 'events.js',
00:15:36 lineNumber: 144,
00:15:36 columnNumber: 43
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 39 ]
00:15:36 },
00:15:36 {
00:15:36 id: 39,
00:15:36 callFrame: {
00:15:36 functionName: '',
00:15:36 scriptId: '52',
00:15:36 url: 'internal/main/worker_thread.js',
00:15:36 lineNumber: 89,
00:15:36 columnNumber: 19
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 40 ]
00:15:36 },
00:15:36 {
00:15:36 id: 40,
00:15:36 callFrame: {
00:15:36 functionName: 'Module.runMain',
00:15:36 scriptId: '61',
00:15:36 url: 'internal/modules/cjs/loader.js',
00:15:36 lineNumber: 807,
00:15:36 columnNumber: 25
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 41 ]
00:15:36 },
00:15:36 {
00:15:36 id: 41,
00:15:36 callFrame: {
00:15:36 functionName: 'Module._load',
00:15:36 scriptId: '61',
00:15:36 url: 'internal/modules/cjs/loader.js',
00:15:36 lineNumber: 506,
00:15:36 columnNumber: 23
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 42 ]
00:15:36 },
00:15:36 {
00:15:36 id: 42,
00:15:36 callFrame: {
00:15:36 functionName: 'Module.load',
00:15:36 scriptId: '61',
00:15:36 url: 'internal/modules/cjs/loader.js',
00:15:36 lineNumber: 619,
00:15:36 columnNumber: 32
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 43 ]
00:15:36 },
00:15:36 {
00:15:36 id: 43,
00:15:36 callFrame: {
00:15:36 functionName: 'Module._extensions..js',
00:15:36 scriptId: '61',
00:15:36 url: 'internal/modules/cjs/loader.js',
00:15:36 lineNumber: 767,
00:15:36 columnNumber: 36
00:15:36 },
00:15:36 hitCount: 0,
00:15:36 children: [ 44 ]
00:15:36 },
00:15:36 {
00:15:36 id: 44,
00:15:36 callFrame: {
00:15:36 functionName: 'readFileSync',
00:15:36 scriptId: '64',
00:15:36 url: 'fs.js',
00:15:36 lineNumber: 332,
00:15:36 columnNumber: 21
00:15:36 },
00:15:36 hitCount: 3,
00:15:36 children: [ 45 ],
00:15:36 positionTicks: [ [Object], [Object], [Object] ]
00:15:36 },
00:15:36 {
00:15:36 id: 45,
00:15:36 callFrame: {
00:15:36 functionName: 'tryReadSync',
00:15:36 scriptId: '64',
00:15:36 url: 'fs.js',
00:15:36 lineNumber: 320,
00:15:36 columnNumber: 20
00:15:36 },
00:15:36 hitCount: 1,
00:15:36 positionTicks: [ [Object] ]
00:15:36 }
00:15:36 ]
00:15:36 assert.js:362
00:15:36 throw err;
00:15:36 ^
00:15:36 
00:15:36 AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:
00:15:36 
00:15:36 assert(profile1.frames.length > 0 || profile2.frames.length > 0)
00:15:36 
00:15:36 at Object.<anonymous> (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd11-x64/test/sequential/test-cpu-prof.js:366:3)
00:15:36 at Module._compile (internal/modules/cjs/loader.js:759:30)
00:15:36 at Object.Module._extensions..js (internal/modules/cjs/loader.js:770:10)
00:15:36 at Module.load (internal/modules/cjs/loader.js:628:32)
00:15:36 at Function.Module._load (internal/modules/cjs/loader.js:555:12)
00:15:36 at Function.Module.runMain (internal/modules/cjs/loader.js:822:10)
00:15:36 at internal/main/run_main_module.js:17:11
00:15:36 ...

@joyeecheung

[joyeecheung]

I think this is caused by the function finishing too fast before it gets sampled in the profile. I have a rewritten version of the test here which may be more stable than the current one, though it runs longer (the current one takes < 1 sec on my laptop while the new one takes about 3 sec), because it intentionally keeps the function being profiled running for much longer than the sampling interval (1000x) to make sure it shows up in the profile.

I will see if https://ci.nodejs.org/job/node-test-commit/28455/ works before opening a PR.

[joyeecheung]

Although, on the other hand, another approach would be to not looking for a specific function in the profile at all but instead only make sure the profile exits and can be parsed. But this is kind of like the tick processor test - we want to make sure the generated profile actually can be analyzed by users and the functionality don't get broken randomly by V8.

[joyeecheung]

From https://ci.nodejs.org/job/node-test-commit/28459/ there is an alarming DCHECK:

See failures on test-digitalocean-ubuntu1604_sharedlibs_container-x64-7:

not ok 436 parallel/test-cpu-prof
 ---
 duration_ms: 1.978
 severity: fail
 exitcode: 1
 stack: |-
 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": 1000 } }
 Receive CPU profile message, ending = false
 
 
 #
 # Fatal error in ../deps/v8/src/profiler/profile-generator.cc, line 24
 # Debug check failed: line > 0 (0 vs. 0).
 #
 #
 #
 #FailureMessage Object: 0x7ffc07a223e0
 assert.js:89
 throw new AssertionError(obj);
 ^
 
 AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
 
 null !== 0
 
 at Object.<anonymous> (/home/iojs/build/workspace/node-test-commit-linux-containered/test/parallel/test-cpu-prof.js:78:10)
 at Module._compile (internal/modules/cjs/loader.js:759:30)
 at Object.Module._extensions..js (internal/modules/cjs/loader.js:770:10)
 at Module.load (internal/modules/cjs/loader.js:628:32)
 at Function.Module._load (internal/modules/cjs/loader.js:555:12)
 at Function.Module.runMain (internal/modules/cjs/loader.js:822:10)
 at internal/main/run_main_module.js:17:11
 ...

And from a glance I think test failures in release builds all have frames where lineNumber = -1 so it might be an upstream bug.

EDIT: it looks like the -1s are just for synthetic nodes which makes sense..

[Trott]

https://ci.nodejs.org/job/node-test-commit-linux-containered/13322/nodes=ubuntu1604_sharedlibs_debug_x64/console

10:18:23 not ok 2340 sequential/test-cpu-prof
10:18:23 ---
10:18:23 duration_ms: 480.79
10:18:23 severity: fail
10:18:23 exitcode: -15
10:18:23 stack: |-
10:18:23 timeout
10:18:23 ...

[Trott]

And again...I wondered if these particular failures are just because debug build is slow, but nope. On a successful run, this test takes 4 seconds or so on the debug build.

https://ci.nodejs.org/job/node-test-commit-linux-containered/13325/nodes=ubuntu1604_sharedlibs_debug_x64/console

10:57:29 not ok 2339 sequential/test-cpu-prof
10:57:29 ---
10:57:29 duration_ms: 480.70
10:57:29 severity: fail
10:57:29 exitcode: -15
10:57:29 stack: |-
10:57:29 timeout
10:57:29 ...

[Trott]

The test is failing consistently on debug builds in CI. Last success was about 36 hours ago.

/cc @joyeecheung @addaleax (based on git log...sorry if you're not the right folks to ping here)

[joyeecheung]

This takes 29 seconds to finish on a debug build for me locally..maybe we should split it into multiple tests instead.

[rvagg]

@Trott just a minor follow-up to your notes in IRC: all of the test-softlayer-ubuntu1604_sharedlibs_container-x64-? Jenkins nodes are all running on the same single host server, test-softlayer-ubuntu1604-docker-x64-1 (which you have access to if you're brave enough to try and debug locally). If it's true that you're only getting failures on test-softlayer-ubuntu1604_sharedlibs_container-x64-? machines and not the other sharedlibs machines then it could be a local problem. But, you mentioned test-softlayer-ubuntu1604_sharedlibs_container-x64-7 which isn't a thing, there's test-digitalocean-ubuntu1604_sharedlibs_container-x64-7 but that's on one of the two DigitalOcean hosts that run these containers (one has the even numbers and the other has the odd numbers). We also have one running on Joyent too so that may show up occasionally.
So, when looking for failure patterns with these container runs, pay attention to the provider name, in the case of SoftLayer and Joyent, they are all on the same base host. In the case of DO they span 2 hosts.

[joyeecheung]

I did a quick scan and it seems after #28170 the flake has only showed up on freebsd due to being unable to find the target function in the samples e.g. https://ci.nodejs.org/job/node-test-commit-freebsd/26826/nodes=freebsd11-x64/consoleFull