AuroraMiddleware/v8
1
0
Fork 0
Code Issues 2 Pull Requests Releases Wiki Activity

[wasm] Add more output to console-profile-wasm test

Browse Source 
The test occasionally times out, and it's unclear why.
This CL adds an explicit timeout to the test (30 seconds), and prints
all seen profiles after that. This makes it easier to see which frame is
missing from the profiles.

As a drive-by refactoring, we now also use
{InspectorTest.runAsyncTestSuite} instead of the hand-written sequential
execution of the asynchronous test functions.

R=thibaudm@chromium.org

Bug: v8:13370
Change-Id: I67f53a819706c8e5971bf32dc925d90b21c96243
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/3956976
Commit-Queue: Clemens Backes <clemensb@chromium.org>
Reviewed-by: Thibaud Michaud <thibaudm@chromium.org>
Cr-Commit-Position: refs/heads/main@{#83748}
This commit is contained in:
Clemens Backes 2022-10-14 19:14:57 +02:00 committed by V8 LUCI CQ
parent 9b3a177b16
commit e69505242f
2 changed files with 79 additions and 62 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

12
test/inspector/cpu-profiler/console-profile-wasm-expected.txt
View File

@ -1,26 +1,30 @@
Test that console profiles contain wasm function names.
testEnableProfilerEarly
Running test: testEnableProfilerEarly
Compiling wasm.
Building wasm module with sentinel 1.
Running fib with increasing input until it shows up in the profile.
Found expected functions in profile.
Wasm script id is set.
Wasm position: wasm://wasm/6b211e7e@0:47
testEnableProfilerLate
Running test: testEnableProfilerLate
Compiling wasm.
Building wasm module with sentinel 2.
Running fib with increasing input until it shows up in the profile.
Found expected functions in profile.
Wasm script id is set.
Wasm position: wasm://wasm/d6029ed6@0:47
testEnableProfilerAfterDebugger
Running test: testEnableProfilerAfterDebugger
Compiling wasm.
Building wasm module with sentinel 3.
Running fib with increasing input until it shows up in the profile.
Found expected functions in profile.
Wasm script id is set.
Wasm position: wasm://wasm/6df1c11a@0:47
testEnableProfilerBeforeDebugger
Running test: testEnableProfilerBeforeDebugger
Compiling wasm.
Building wasm module with sentinel 4.
Running fib with increasing input until it shows up in the profile.

129
test/inspector/cpu-profiler/console-profile-wasm.js
View File

@ -63,12 +63,28 @@ let found_good_profile = false;
let found_wasm_script_id;
let wasm_position;
let finished_profiles = 0;
// Remember which sequences of functions we have seen in profiles so far. This
// is printed in the error case to aid debugging.
let seen_profiles = [];
function addSeenProfile(function_names) {
let arrays_equal = (a, b) =>
a.length == b.length && a.every((val, index) => val == b[index]);
if (seen_profiles.some(a => arrays_equal(a, function_names))) return false;
seen_profiles.push(function_names.slice());
return true;
}
function resetGlobalData() {
found_good_profile = false;
finished_profiles = 0;
seen_profiles = [];
}
Protocol.Profiler.onConsoleProfileFinished(e => {
++finished_profiles;
let nodes = e.params.profile.nodes;
let function_names = nodes.map(n => n.callFrame.functionName);
// Enable this line for debugging:
// InspectorTest.log(function_names.join(', '));
// Check for at least one full cycle of
// fib -> wasm-to-js -> imp -> js-to-wasm -> fib.
// There are two different kinds of js-to-wasm-wrappers, so there are two
@ -77,6 +93,7 @@ Protocol.Profiler.onConsoleProfileFinished(e => {
['fib'], ['wasm-to-js:i:i'], ['imp'],
['GenericJSToWasmWrapper', 'js-to-wasm:i:i'], ['fib']
];
if (!addSeenProfile(function_names)) return;
for (let i = 0; i <= function_names.length - expected.length; ++i) {
if (expected.every((val, idx) => val.includes(function_names[i + idx]))) {
found_good_profile = true;
@ -91,25 +108,35 @@ Protocol.Profiler.onConsoleProfileFinished(e => {
async function runFibUntilProfileFound() {
InspectorTest.log(
'Running fib with increasing input until it shows up in the profile.');
found_good_profile = false;
finished_profiles = 0;
resetGlobalData();
const start = Date.now();
const kTimeoutMs = 30000;
for (let i = 1; !found_good_profile; ++i) {
checkError(await Protocol.Runtime.evaluate(
{expression: 'console.profile(\'profile\');'}));
{expression: `console.profile('profile');`}));
checkError(await Protocol.Runtime.evaluate(
{expression: 'globalThis.instance.exports.fib(' + i + ');'}));
{expression: `globalThis.instance.exports.fib(${i});`}));
checkError(await Protocol.Runtime.evaluate(
{expression: 'console.profileEnd(\'profile\');'}));
{expression: `console.profileEnd('profile');`}));
if (finished_profiles != i) {
InspectorTest.log(
'Missing consoleProfileFinished message (expected ' + i + ', got ' +
finished_profiles + ')');
`Missing consoleProfileFinished message (expected ${i}, got ` +
`${finished_profiles})`);
}
if (Date.now() - start > kTimeoutMs) {
InspectorTest.log('Seen profiles so far:');
for (let profile of seen_profiles) {
InspectorTest.log(' - ' + profile.join(" -> "));
}
throw new Error(
`fib did not show up in the profile within ` +
`${kTimeoutMs}ms (after ${i} executions)`);
}
}
InspectorTest.log('Found expected functions in profile.');
InspectorTest.log(
'Wasm script id is ' + (found_wasm_script_id ? 'set.' : 'NOT SET.'));
InspectorTest.log('Wasm position: ' + wasm_position);
`Wasm script id is ${found_wasm_script_id ? 'set.' : 'NOT SET.'}`);
InspectorTest.log(`Wasm position: ${wasm_position}`);
}
async function compileWasm() {
@ -120,54 +147,40 @@ async function compileWasm() {
}));
}
async function testEnableProfilerEarly() {
InspectorTest.log(arguments.callee.name);
checkError(await Protocol.Profiler.enable());
checkError(await Protocol.Profiler.start());
await compileWasm();
await runFibUntilProfileFound();
checkError(await Protocol.Profiler.disable());
}
InspectorTest.runAsyncTestSuite([
async function testEnableProfilerEarly() {
checkError(await Protocol.Profiler.enable());
checkError(await Protocol.Profiler.start());
await compileWasm();
await runFibUntilProfileFound();
checkError(await Protocol.Profiler.disable());
},
async function testEnableProfilerLate() {
InspectorTest.log(arguments.callee.name);
await compileWasm();
checkError(await Protocol.Profiler.enable());
checkError(await Protocol.Profiler.start());
await runFibUntilProfileFound();
checkError(await Protocol.Profiler.disable());
}
async function testEnableProfilerLate() {
await compileWasm();
checkError(await Protocol.Profiler.enable());
checkError(await Protocol.Profiler.start());
await runFibUntilProfileFound();
checkError(await Protocol.Profiler.disable());
},
async function testEnableProfilerAfterDebugger() {
InspectorTest.log(arguments.callee.name);
checkError(await Protocol.Debugger.enable());
await compileWasm();
checkError(await Protocol.Profiler.enable());
checkError(await Protocol.Profiler.start());
await runFibUntilProfileFound();
checkError(await Protocol.Profiler.disable());
checkError(await Protocol.Debugger.disable());
}
async function testEnableProfilerAfterDebugger() {
checkError(await Protocol.Debugger.enable());
await compileWasm();
checkError(await Protocol.Profiler.enable());
checkError(await Protocol.Profiler.start());
await runFibUntilProfileFound();
checkError(await Protocol.Profiler.disable());
checkError(await Protocol.Debugger.disable());
},
async function testEnableProfilerBeforeDebugger() {
InspectorTest.log(arguments.callee.name);
await compileWasm();
await Protocol.Profiler.enable();
await Protocol.Debugger.enable();
checkError(await Protocol.Profiler.start());
await runFibUntilProfileFound();
await Protocol.Debugger.disable();
await Protocol.Profiler.disable();
}
(async function test() {
try {
await testEnableProfilerEarly();
await testEnableProfilerLate();
await testEnableProfilerAfterDebugger();
await testEnableProfilerBeforeDebugger();
} catch (e) {
InspectorTest.log('caught: ' + e);
async function testEnableProfilerBeforeDebugger() {
await compileWasm();
await Protocol.Profiler.enable();
await Protocol.Debugger.enable();
checkError(await Protocol.Profiler.start());
await runFibUntilProfileFound();
await Protocol.Debugger.disable();
await Protocol.Profiler.disable();
}
})().catch(e => InspectorTest.log('caught: ' + e))
.finally(InspectorTest.completeTest);
]);