Bug 1559798 - Begin polling for the results (runner.js) only after the pageload.js code has been invoked in the test page content r=acreskey,tarek

Differential Revision: https://phabricator.services.mozilla.com/D35261

--HG--
extra : moz-landing-system : lando
This commit is contained in:
Rob Wood 2019-06-19 20:56:16 +00:00
parent 4e5bca5dc2
commit a5885f4602
5 changed files with 141 additions and 76 deletions

View File

@ -10,3 +10,8 @@ user_pref("geckoview.console.enabled", true);
// required to prevent non-local access to push.services.mozilla.com
user_pref("dom.push.connection.enabled", false);
// get the console logging out of the webext into the stdout
user_pref("browser.dom.window.dump.enabled", true);
user_pref("devtools.console.stdout.chrome", true);
user_pref("devtools.console.stdout.content", true);

View File

@ -191,16 +191,30 @@ class Raptor(object):
raise NotImplementedError()
def wait_for_test_finish(self, test, timeout):
# this is a 'back-stop' i.e. if for some reason Raptor doesn't finish for some
# serious problem; i.e. the test was unable to send a 'page-timeout' to the control
# server, etc. Therefore since this is a 'back-stop' we want to be generous here;
# we don't want this timeout occurring unless abosultely necessary
# convert timeout to seconds and account for page cycles
timeout = int(timeout / 1000) * int(test.get('page_cycles', 1))
# account for the pause the raptor webext runner takes after browser startup
# and the time an exception is propagated through the framework
timeout += (int(self.post_startup_delay / 1000) + 10)
# for page-load tests we don't start the page-timeout timer until the pageload.js content
# is successfully injected and invoked; which differs per site being tested; therefore we
# need to be generous here - let's add 10 seconds extra per page-cycle
if test.get('type') == "pageload":
timeout += (10 * int(test.get('page_cycles', 1)))
# if geckoProfile enabled, give browser more time for profiling
if self.config['gecko_profile'] is True:
timeout += 5 * 60
# we also need to give time for results processing, not just page/browser cycles!
timeout += 60
elapsed_time = 0
while not self.control_server._finished:
if self.config['enable_control_server_wait']:

View File

@ -5,8 +5,8 @@
// receives result from benchmark and relays onto our background runner
function receiveMessage(event) {
console.log("raptor benchmark received message");
console.log(event.data);
raptorLog("raptor benchmark received message");
raptorLog(event.data);
// raptor benchmark message data [0] is raptor tag, [1] is benchmark
// name, and the rest is actual benchmark results that we want to fw
if (event.data[0] == "raptor-benchmark") {
@ -16,11 +16,15 @@ function receiveMessage(event) {
function sendResult(_type, _value) {
// send result back to background runner script
console.log(`sending result back to runner: ${_type} ${_value}`);
raptorLog(`sending result back to runner: ${_type} ${_value}`);
chrome.runtime.sendMessage({"type": _type, "value": _value}, function(response) {
console.log(response.text);
raptorLog(response.text);
});
}
console.log("raptor benchmark content loaded");
function raptorLog(logText) {
console.log(`[raptor-benchmarkjs] ${logText}`);
}
raptorLog("raptor benchmark content loaded");
window.addEventListener("message", receiveMessage);

View File

@ -52,6 +52,10 @@ var getLoadTime = false;
var startMeasure = "fetchStart";
function raptorContentHandler() {
raptorLog("pageloadjs raptorContentHandler!");
// let the main raptor runner know that we (pageloadjs) is ready!
sendPageloadReady();
// retrieve test settings from local ext storage
if (typeof(browser) !== "undefined") {
// firefox, returns promise
@ -66,20 +70,30 @@ function raptorContentHandler() {
}
}
function sendPageloadReady() {
// send message to runnerjs indicating pageloadjs is ready to start getting measures
raptorLog("sending pageloadjs-ready message to runnerjs");
chrome.runtime.sendMessage({"type": "pageloadjs-ready"}, function(response) {
if (response !== undefined) {
raptorLog(`${response.text}`);
}
});
}
function setup(settings) {
if (settings.type != TEST_PAGE_LOAD) {
return;
}
if (settings.measure == undefined) {
console.log("abort: 'measure' key not found in test settings");
raptorLog("abort: 'measure' key not found in test settings");
return;
}
if (settings.measure.fnbpaint !== undefined) {
getFNBPaint = settings.measure.fnbpaint;
if (getFNBPaint) {
console.log("will be measuring fnbpaint");
raptorLog("will be measuring fnbpaint");
measureFNBPaint();
}
}
@ -87,7 +101,7 @@ function setup(settings) {
if (settings.measure.dcf !== undefined) {
getDCF = settings.measure.dcf;
if (getDCF) {
console.log("will be measuring dcf");
raptorLog("will be measuring dcf");
measureDCF();
}
}
@ -95,7 +109,7 @@ function setup(settings) {
if (settings.measure.fcp !== undefined) {
getFCP = settings.measure.fcp;
if (getFCP) {
console.log("will be measuring first-contentful-paint");
raptorLog("will be measuring first-contentful-paint");
measureFCP();
}
}
@ -104,7 +118,7 @@ function setup(settings) {
if (settings.measure.hero.length !== 0) {
getHero = true;
heroesToCapture = settings.measure.hero;
console.log(`hero elements to measure: ${heroesToCapture}`);
raptorLog(`hero elements to measure: ${heroesToCapture}`);
measureHero();
}
}
@ -112,7 +126,7 @@ function setup(settings) {
if (settings.measure.ttfi !== undefined) {
getTTFI = settings.measure.ttfi;
if (getTTFI) {
console.log("will be measuring ttfi");
raptorLog("will be measuring ttfi");
measureTTFI();
}
}
@ -120,7 +134,7 @@ function setup(settings) {
if (settings.measure.loadtime !== undefined) {
getLoadTime = settings.measure.loadtime;
if (getLoadTime) {
console.log("will be measuring loadtime");
raptorLog("will be measuring loadtime");
measureLoadTime();
}
}
@ -130,7 +144,7 @@ function measureHero() {
var obs = null;
var heroElementsFound = window.document.querySelectorAll("[elementtiming]");
console.log(`found ${heroElementsFound.length} hero elements in the page`);
raptorLog(`found ${heroElementsFound.length} hero elements in the page`);
if (heroElementsFound) {
function callbackHero(entries, observer) {
@ -139,7 +153,7 @@ function measureHero() {
// mark the time now as when hero element received
perfData.mark(heroFound);
var resultType = `hero:${heroFound}`;
console.log(`found ${resultType}`);
raptorLog(`found ${resultType}`);
// calculcate result: performance.timing.fetchStart - time when we got hero element
perfData.measure(name = resultType,
startMark = startMeasure,
@ -162,10 +176,10 @@ function measureHero() {
obs.observe(el);
});
} catch (err) {
console.log(err);
raptorLog(err);
}
} else {
console.log("couldn't find hero element");
raptorLog("couldn't find hero element");
}
}
@ -173,21 +187,21 @@ function measureFNBPaint() {
var x = window.performance.timing.timeToNonBlankPaint;
if (typeof(x) == "undefined") {
console.log("ERROR: timeToNonBlankPaint is undefined; ensure the pref is enabled");
raptorLog("ERROR: timeToNonBlankPaint is undefined; ensure the pref is enabled");
return;
}
if (x > 0) {
console.log("got fnbpaint");
raptorLog("got fnbpaint");
gRetryCounter = 0;
var startTime = perfData.timing.fetchStart;
sendResult("fnbpaint", x - startTime);
} else {
gRetryCounter += 1;
if (gRetryCounter <= 10) {
console.log(`\nfnbpaint is not yet available (0), retry number ${gRetryCounter}...\n`);
raptorLog(`fnbpaint is not yet available, retry number ${gRetryCounter}...`);
window.setTimeout(measureFNBPaint, 100);
} else {
console.log(`\nunable to get a value for fnbpaint after ${gRetryCounter} retries\n`);
raptorLog(`unable to get a value for fnbpaint after ${gRetryCounter} retries`);
}
}
}
@ -196,21 +210,21 @@ function measureDCF() {
var x = window.performance.timing.timeToDOMContentFlushed;
if (typeof(x) == "undefined") {
console.log("ERROR: domContentFlushed is undefined; ensure the pref is enabled");
raptorLog("ERROR: domContentFlushed is undefined; ensure the pref is enabled");
return;
}
if (x > 0) {
console.log(`got domContentFlushed: ${x}`);
raptorLog(`got domContentFlushed: ${x}`);
gRetryCounter = 0;
var startTime = perfData.timing.fetchStart;
sendResult("dcf", x - startTime);
} else {
gRetryCounter += 1;
if (gRetryCounter <= 10) {
console.log(`\dcf is not yet available (0), retry number ${gRetryCounter}...\n`);
raptorLog(`dcf is not yet available (0), retry number ${gRetryCounter}...`);
window.setTimeout(measureDCF, 100);
} else {
console.log(`\nunable to get a value for dcf after ${gRetryCounter} retries\n`);
raptorLog(`unable to get a value for dcf after ${gRetryCounter} retries`);
}
}
}
@ -219,11 +233,11 @@ function measureTTFI() {
var x = window.performance.timing.timeToFirstInteractive;
if (typeof(x) == "undefined") {
console.log("ERROR: timeToFirstInteractive is undefined; ensure the pref is enabled");
raptorLog("ERROR: timeToFirstInteractive is undefined; ensure the pref is enabled");
return;
}
if (x > 0) {
console.log(`got timeToFirstInteractive: ${x}`);
raptorLog(`got timeToFirstInteractive: ${x}`);
gRetryCounter = 0;
var startTime = perfData.timing.fetchStart;
sendResult("ttfi", x - startTime);
@ -236,11 +250,11 @@ function measureTTFI() {
// times out at 30 seconds). Some pages will never get 5 seconds
// without a busy period!
if (gRetryCounter <= 25 * (1000 / 200)) {
console.log(`TTFI is not yet available (0), retry number ${gRetryCounter}...\n`);
raptorLog(`TTFI is not yet available (0), retry number ${gRetryCounter}...`);
window.setTimeout(measureTTFI, 200);
} else {
// unable to get a value for TTFI - negative value will be filtered out later
console.log("TTFI was not available for this pageload");
raptorLog("TTFI was not available for this pageload");
sendResult("ttfi", -1);
}
}
@ -267,7 +281,7 @@ function measureFCP() {
}
if (result > 0) {
console.log("got time to first-contentful-paint");
raptorLog("got time to first-contentful-paint");
if (typeof(browser) !== "undefined") {
// Firefox returns a timestamp, not the actual measurement in MS; need to calculate result
var startTime = perfData.timing.fetchStart;
@ -279,10 +293,10 @@ function measureFCP() {
} else {
gRetryCounter += 1;
if (gRetryCounter <= 10) {
console.log(`\ntime to first-contentful-paint is not yet available (0), retry number ${gRetryCounter}...\n`);
raptorLog(`time to first-contentful-paint is not yet available (0), retry number ${gRetryCounter}...`);
window.setTimeout(measureFCP, 100);
} else {
console.log(`\nunable to get a value for time-to-fcp after ${gRetryCounter} retries\n`);
raptorLog(`unable to get a value for time-to-fcp after ${gRetryCounter} retries`);
}
}
}
@ -291,35 +305,39 @@ function measureLoadTime() {
var x = window.performance.timing.loadEventStart;
if (typeof(x) == "undefined") {
console.log("ERROR: loadEventStart is undefined");
raptorLog("ERROR: loadEventStart is undefined");
return;
}
if (x > 0) {
console.log(`got loadEventStart: ${x}`);
raptorLog(`got loadEventStart: ${x}`);
gRetryCounter = 0;
var startTime = perfData.timing.fetchStart;
sendResult("loadtime", x - startTime);
} else {
gRetryCounter += 1;
if (gRetryCounter <= 40 * (1000 / 200)) {
console.log(`\nloadEventStart is not yet available (0), retry number ${gRetryCounter}...\n`);
raptorLog(`loadEventStart is not yet available (0), retry number ${gRetryCounter}...`);
window.setTimeout(measureLoadTime, 100);
} else {
console.log(`\nunable to get a value for loadEventStart after ${gRetryCounter} retries\n`);
raptorLog(`unable to get a value for loadEventStart after ${gRetryCounter} retries`);
}
}
}
function sendResult(_type, _value) {
// send result back to background runner script
console.log(`sending result back to runner: ${_type} ${_value}`);
raptorLog(`sending result back to runner: ${_type} ${_value}`);
chrome.runtime.sendMessage({"type": _type, "value": _value}, function(response) {
if (response !== undefined) {
console.log(response.text);
raptorLog(response.text);
}
});
}
function raptorLog(logText) {
console.log(`[raptor-pageloadjs] ${logText}`);
}
if (window.addEventListener) {
window.addEventListener("load", raptorContentHandler);
}

View File

@ -82,11 +82,11 @@ var results = {
};
function getTestSettings() {
console.log("getting test settings from control server");
raptorLog("getting test settings from control server");
return new Promise(resolve => {
fetch(settingsURL).then(function(response) {
response.text().then(function(text) {
console.log(text);
raptorLog(text);
settings = JSON.parse(text)["raptor-options"];
// parse the test settings
@ -109,7 +109,7 @@ function getTestSettings() {
testURL = testURL.replace("<host>", host);
}
console.log(`testURL: ${testURL}`);
raptorLog(testURL);
results.alert_change_type = settings.alert_change_type;
results.alert_threshold = settings.alert_threshold;
@ -144,7 +144,7 @@ function getTestSettings() {
if (settings.page_timeout !== undefined) {
pageTimeout = settings.page_timeout;
}
console.log(`using page timeout: ${pageTimeout}ms`);
raptorLog(`using page timeout: ${pageTimeout}ms`);
switch (testType) {
case TEST_PAGE_LOAD:
@ -170,7 +170,7 @@ function getTestSettings() {
getLoadTime = settings.measure.loadtime;
}
} else {
console.log("abort: 'measure' key not found in test settings");
raptorLog("abort: 'measure' key not found in test settings");
cleanUp();
}
break;
@ -180,14 +180,14 @@ function getTestSettings() {
if (["firefox", "geckoview", "refbrow", "fenix"].includes(browserName)) {
ext.storage.local.clear().then(function() {
ext.storage.local.set({settings}).then(function() {
console.log("wrote settings to ext local storage");
raptorLog("wrote settings to ext local storage");
resolve();
});
});
} else {
ext.storage.local.clear(function() {
ext.storage.local.set({settings}, function() {
console.log("wrote settings to ext local storage");
raptorLog("wrote settings to ext local storage");
resolve();
});
});
@ -204,7 +204,7 @@ function getBrowserInfo() {
var gettingInfo = browser.runtime.getBrowserInfo();
gettingInfo.then(function(bi) {
results.browser = bi.name + " " + bi.version + " " + bi.buildID;
console.log(`testing on ${results.browser}`);
raptorLog(`testing on ${results.browser}`);
resolve();
});
} else {
@ -216,7 +216,7 @@ function getBrowserInfo() {
break;
}
}
console.log(`testing on ${results.browser}`);
raptorLog(`testing on ${results.browser}`);
resolve();
}
});
@ -242,11 +242,20 @@ function testTabRemoved(tab) {
testTabID = 0;
}
async function testTabUpdated(tab) {
function testTabUpdated(tab) {
postToControlServer("status", `test tab updated: ${testTabID}`);
// now that the tab was updated with the URL, we're ready to get measurements; set the
// page timeout alarm now, so the timer will only be for getting the actual measurements
// themselves; not for the time to open/update the tab + getting measurements
// for benchmark or scenario type tests we can proceed directly to waitForResult;
// however for page-load tests we must first wait until we hear back from pageloaderjs
// that it has been successfully loaded in the test page and has been invoked; and
// only then start looking for measurements
if (testType != TEST_PAGE_LOAD) {
collectResults();
}
}
async function collectResults() {
// now we can set the page timeout timer and wait for pageload test result from content
raptorLog("ready to poll for results; turning on page-timeout timer");
setTimeoutAlarm("raptor-page-timeout", pageTimeout);
// wait for pageload test result from content
await waitForResult();
@ -257,7 +266,7 @@ async function testTabUpdated(tab) {
async function waitForResult() {
let results = await new Promise(resolve => {
function checkForResult() {
console.log("checking results...");
raptorLog("checking results...");
switch (testType) {
case TEST_BENCHMARK:
if (!isBenchmarkPending) {
@ -274,8 +283,10 @@ async function waitForResult() {
!isDCFPending &&
!isTTFIPending &&
!isLoadTimePending) {
raptorLog("no more results pending; resolving checkForResult");
resolve();
} else {
raptorLog("setting timeout to checkForResult again in 250ms");
setTimeout(checkForResult, 250);
}
break;
@ -311,7 +322,7 @@ async function waitForResult() {
}
async function getScreenCapture() {
console.log("capturing screenshot");
raptorLog("capturing screenshot");
try {
let screenshotUri;
@ -324,7 +335,7 @@ async function getScreenCapture() {
}
postToControlServer("screenshot", [screenshotUri, testName, pageCycle]);
} catch (e) {
console.log(`failed to capture screenshot: ${e}`);
raptorLog(`failed to capture screenshot: ${e}`);
}
}
@ -349,7 +360,7 @@ async function getGeckoProfile() {
let arrayBuffer = await browser.geckoProfiler.getProfileAsArrayBuffer();
let textDecoder = new TextDecoder();
let profile = JSON.parse(textDecoder.decode(arrayBuffer));
console.log(profile);
raptorLog(profile);
postToControlServer("gecko_profile", [testName, pageCycle, profile]);
// stop the profiler; must stop so it clears before next cycle
await stopGeckoProfiling();
@ -455,7 +466,7 @@ function setTimeoutAlarm(timeoutName, timeoutMS) {
var now = Date.now(); // eslint-disable-line mozilla/avoid-Date-timing
var timeout_when = now + timeoutMS;
ext.alarms.create(timeoutName, { when: timeout_when });
console.log(`now is ${now}, set raptor alarm ${timeoutName} to expire ` +
raptorLog(`now is ${now}, set raptor alarm ${timeoutName} to expire ` +
`at ${timeout_when}`);
}
@ -465,7 +476,7 @@ function cancelTimeoutAlarm(timeoutName) {
var clearAlarm = ext.alarms.clear(timeoutName);
clearAlarm.then(function(onCleared) {
if (onCleared) {
console.log(`cancelled raptor alarm ${timeoutName}`);
raptorLog(`cancelled raptor alarm ${timeoutName}`);
} else {
console.error(`failed to clear raptor alarm ${timeoutName}`);
}
@ -473,7 +484,7 @@ function cancelTimeoutAlarm(timeoutName) {
} else {
chrome.alarms.clear(timeoutName, function(wasCleared) {
if (wasCleared) {
console.log(`cancelled raptor alarm ${timeoutName}`);
raptorLog(`cancelled raptor alarm ${timeoutName}`);
} else {
console.error(`failed to clear raptor alarm ${timeoutName}`);
}
@ -482,9 +493,17 @@ function cancelTimeoutAlarm(timeoutName) {
}
function resultListener(request, sender, sendResponse) {
console.log(`received message from ${sender.tab.url}`);
raptorLog(`received message from ${sender.tab.url}`);
// check if this is a message from pageloaderjs indicating it is ready to start
if (request.type == "pageloadjs-ready") {
raptorLog("received pageloadjs-ready!");
sendResponse({text: "pageloadjs-ready-response"});
collectResults();
return;
}
if (request.type && request.value) {
console.log(`result: ${request.type} ${request.value}`);
raptorLog(`result: ${request.type} ${request.value}`);
sendResponse({text: `confirmed ${request.type}`});
if (!(request.type in results.measurements))
@ -493,7 +512,7 @@ function resultListener(request, sender, sendResponse) {
switch (testType) {
case TEST_BENCHMARK:
// benchmark results received (all results for that complete benchmark run)
console.log("received results from benchmark");
raptorLog("received results from benchmark");
results.measurements[request.type].push(request.value);
isBenchmarkPending = false;
break;
@ -507,7 +526,7 @@ function resultListener(request, sender, sendResponse) {
if (index > -1) {
pendingHeroes.splice(index, 1);
if (pendingHeroes.length == 0) {
console.log("measured all expected hero elements");
raptorLog("measured all expected hero elements");
isHeroPending = false;
}
}
@ -530,19 +549,19 @@ function resultListener(request, sender, sendResponse) {
break;
}
} else {
console.log(`unknown message received from content: ${request}`);
raptorLog(`unknown message received from content: ${request}`);
}
}
function verifyResults() {
console.log("\nVerifying results:");
console.log(results);
raptorLog("Verifying results:");
raptorLog(results);
for (var x in results.measurements) {
let count = results.measurements[x].length;
if (count == pageCycles) {
console.log(`have ${count} results for ${x}, as expected`);
raptorLog(`have ${count} results for ${x}, as expected`);
} else {
console.log(`ERROR: expected ${pageCycles} results for ${x} ` +
raptorLog(`ERROR: expected ${pageCycles} results for ${x} ` +
`but only have ${count}`);
}
}
@ -552,14 +571,14 @@ function verifyResults() {
function postToControlServer(msgType, msgData = "") {
// if posting a status message, log it to console also
if (msgType == "status") {
console.log(`\n${msgData}`);
raptorLog(msgData);
}
// requires 'control server' running at port 8000 to receive results
var url = `http://${host}:${csPort}/`;
var client = new XMLHttpRequest();
client.onreadystatechange = function() {
if (client.readyState == XMLHttpRequest.DONE && client.status == 200) {
console.log("post success");
raptorLog("post success");
}
};
@ -567,8 +586,8 @@ function postToControlServer(msgType, msgData = "") {
client.setRequestHeader("Content-Type", "application/json");
if (client.readyState == 1) {
console.log("posting to control server");
console.log(msgData);
raptorLog("posting to control server");
raptorLog(`${msgData}`);
var data = { "type": `webext_${msgType}`, "data": msgData};
client.send(JSON.stringify(data));
}
@ -582,9 +601,9 @@ function cleanUp() {
// close tab unless raptor debug-mode is enabled
if (debugMode != 1) {
ext.tabs.remove(testTabID);
console.log(`closed tab ${testTabID}`);
raptorLog(`closed tab ${testTabID}`);
} else {
console.log("raptor debug-mode enabled, leaving tab open");
raptorLog("debug-mode enabled, leaving tab open");
}
if (testType == TEST_PAGE_LOAD) {
@ -593,7 +612,7 @@ function cleanUp() {
ext.runtime.onMessage.removeListener(resultListener);
ext.tabs.onCreated.removeListener(testTabCreated);
}
console.log(`${testType} test finished`);
raptorLog(`${testType} test finished`);
// if profiling was enabled, stop the profiler - may have already
// been stopped but stop again here in cleanup in case of timeout
@ -606,9 +625,10 @@ function cleanUp() {
}
function raptorRunner() {
raptorLog("starting raptorRunner");
let config = getTestConfig();
console.log(`test name is: ${config.test_name}`);
console.log(`test settings url is: ${config.test_settings_url}`);
raptorLog(`test name is: ${config.test_name}`);
raptorLog(`test settings url is: ${config.test_settings_url}`);
testName = config.test_name;
settingsURL = config.test_settings_url;
csPort = config.cs_port;
@ -623,7 +643,7 @@ function raptorRunner() {
getBrowserInfo().then(function() {
getTestSettings().then(function() {
console.log(`${testType} test start`);
raptorLog(`${testType} test start`);
// timeout alarm listener
ext.alarms.onAlarm.addListener(timeoutAlarmListener);
@ -656,6 +676,10 @@ function raptorRunner() {
});
}
function raptorLog(logText) {
console.log(`[raptor-runnerjs] ${logText}`);
}
if (window.addEventListener) {
window.addEventListener("load", raptorRunner);
postToControlServer("status", "Attaching event listener successful!");