/* Any copyright is dedicated to the Public Domain. http://creativecommons.org/publicdomain/zero/1.0/ */ /* This test records I/O syscalls done on the main thread during startup. * * To run this test similar to try server, you need to run: * ./mach package * ./mach test --appname=dist * * If you made changes that cause this test to fail, it's likely because you * are touching more files or directories during startup. * Most code has no reason to use main thread I/O. * If for some reason accessing the file system on the main thread is currently * unavoidable, consider defering the I/O as long as you can, ideally after * the end of startup. * If your code isn't strictly required to show the first browser window, * it shouldn't be loaded before we are done with first paint. * Finally, if your code isn't really needed during startup, it should not be * loaded before we have started handling user events. */ "use strict"; /* Set this to true only for debugging purpose; it makes the output noisy. */ const kDumpAllStacks = false; // Shortcuts for conditions. const LINUX = AppConstants.platform == "linux"; const WIN = AppConstants.platform == "win"; const MAC = AppConstants.platform == "macosx"; const kSharedFontList = SpecialPowers.getBoolPref("gfx.e10s.font-list.shared"); /* This is an object mapping string phases of startup to lists of known cases * of IO happening on the main thread. Ideally, IO should not be on the main * thread, and should happen as late as possible (see above). * * Paths in the entries in these lists can: * - be a full path, eg. "/etc/mime.types" * - have a prefix which will be resolved using Services.dirsvc * eg. "GreD:omni.ja" * It's possible to have only a prefix, in thise case the directory will * still be resolved, eg. "UAppData:" * - use * at the begining and/or end as a wildcard * The folder separator is '/' even for Windows paths, where it'll be * automatically converted to '\'. * * Specifying 'ignoreIfUnused: true' will make the test ignore unused entries; * without this the test is strict and will fail if the described IO does not * happen. * * Each entry specifies the maximum number of times an operation is expected to * occur. * The operations currently reported by the I/O interposer are: * create/open: only supported on Windows currently. The test currently * ignores these markers to have a shorter initial list of IO operations. * Adding Unix support is bug 1533779. * stat: supported on all platforms when checking the last modified date or * file size. Supported only on Windows when checking if a file exists; * fixing this inconsistency is bug 1536109. * read: supported on all platforms, but unix platforms will only report read * calls going through NSPR. * write: supported on all platforms, but Linux will only report write calls * going through NSPR. * close: supported only on Unix, and only for close calls going through NSPR. * Adding Windows support is bug 1524574. * fsync: supported only on Windows. * * If an entry specifies more than one operation, if at least one of them is * encountered, the test won't report a failure for the entry if other * operations are not encountered. This helps when listing cases where the * reported operations aren't the same on all platforms due to the I/O * interposer inconsistencies across platforms documented above. */ const startupPhases = { // Anything done before or during app-startup must have a compelling reason // to run before we have even selected the user profile. "before profile selection": [ { // bug 1541200 path: "UAppData:Crash Reports/InstallTime20*", condition: AppConstants.MOZ_CRASHREPORTER, stat: 1, // only caught on Windows. read: 1, write: 2, close: 1, }, { // bug 1541200 path: "UAppData:Crash Reports/LastCrash", condition: WIN && AppConstants.MOZ_CRASHREPORTER, stat: 1, // only caught on Windows. read: 1, }, { // bug 1541200 path: "UAppData:Crash Reports/LastCrash", condition: !WIN && AppConstants.MOZ_CRASHREPORTER, ignoreIfUnused: true, // only if we ever crashed on this machine read: 1, close: 1, }, { // At least the read seems unavoidable for a regular startup. path: "UAppData:profiles.ini", ignoreIfUnused: true, condition: MAC, stat: 1, read: 1, close: 1, }, { // At least the read seems unavoidable for a regular startup. path: "UAppData:profiles.ini", condition: WIN, ignoreIfUnused: true, // only if a real profile exists on the system. read: 1, stat: 1, }, { // bug 1541226, bug 1363586, bug 1541593 path: "ProfD:", condition: WIN, stat: 1, }, { path: "ProfLD:.startup-incomplete", condition: !WIN, // Visible on Windows with an open marker close: 1, }, { // bug 1541491 to stop using this file, bug 1541494 to write correctly. path: "ProfLD:compatibility.ini", write: 18, close: 1, }, { path: "GreD:omni.ja", condition: !WIN, // Visible on Windows with an open marker stat: 1, }, { // bug 1376994 path: "XCurProcD:omni.ja", condition: !WIN, // Visible on Windows with an open marker stat: 1, }, { path: "ProfD:parent.lock", condition: WIN, stat: 1, }, { // bug 1541603 path: "ProfD:minidumps", condition: WIN, stat: 1, }, { // bug 1543746 path: "XCurProcD:defaults/preferences", condition: WIN, stat: 1, }, { // bug 1544034 path: "ProfLDS:startupCache/scriptCache-child-current.bin", condition: WIN, stat: 1, }, { // bug 1544034 path: "ProfLDS:startupCache/scriptCache-child.bin", condition: WIN, stat: 1, }, { // bug 1544034 path: "ProfLDS:startupCache/scriptCache-current.bin", condition: WIN, stat: 1, }, { // bug 1544034 path: "ProfLDS:startupCache/scriptCache.bin", condition: WIN, stat: 1, }, { // bug 1541601 path: "PrfDef:channel-prefs.js", stat: 1, read: 1, close: 1, }, { // At least the read seems unavoidable path: "PrefD:prefs.js", stat: 1, read: 1, close: 1, }, { // bug 1543752 path: "PrefD:user.js", stat: 1, read: 1, close: 1, }, ], "before opening first browser window": [ { // bug 1541226 path: "ProfD:", condition: WIN, ignoreIfUnused: true, // Sometimes happens in the next phase stat: 1, }, { // bug 1534745 path: "ProfD:cookies.sqlite-journal", condition: !LINUX, ignoreIfUnused: true, // Sometimes happens in the next phase stat: 3, write: 4, }, { // bug 1534745 path: "ProfD:cookies.sqlite", condition: !LINUX, ignoreIfUnused: true, // Sometimes happens in the next phase stat: 2, read: 3, write: 1, }, { // bug 1534745 path: "ProfD:cookies.sqlite-wal", ignoreIfUnused: true, // Sometimes happens in the next phase condition: WIN, stat: 2, }, { // Seems done by OS X and outside of our control. path: "*.savedState/restorecount.plist", condition: MAC, ignoreIfUnused: true, write: 1, }, { // Side-effect of bug 1412090, via sandboxing (but the real // problem there is main-thread CPU use; see bug 1439412) path: "*ld.so.conf*", condition: LINUX && !AppConstants.MOZ_CODE_COVERAGE && !kSharedFontList, read: 22, close: 11, }, { // bug 1541246 path: "ProfD:extensions", ignoreIfUnused: true, // bug 1649590 condition: WIN, stat: 1, }, { // bug 1541246 path: "UAppData:", ignoreIfUnused: true, // sometimes before opening first browser window, // sometimes before first paint condition: WIN, stat: 1, }, { // bug 1833104 has context - this is artifact-only so doesn't affect // any real users, will just show up for developer builds and // artifact trypushes so we include it here. path: "GreD:jogfile.json", condition: WIN && Services.prefs.getBoolPref("telemetry.fog.artifact_build"), stat: 1, }, ], // We reach this phase right after showing the first browser window. // This means that any I/O at this point delayed first paint. "before first paint": [ { // bug 1545119 path: "OldUpdRootD:", condition: WIN, stat: 1, }, { // bug 1446012 path: "UpdRootD:updates/0/update.status", condition: WIN, stat: 1, }, { path: "XREAppFeat:formautofill@mozilla.org.xpi", condition: !WIN, stat: 1, close: 1, }, { path: "XREAppFeat:webcompat@mozilla.org.xpi", condition: LINUX, ignoreIfUnused: true, // Sometimes happens in the previous phase close: 1, }, { // We only hit this for new profiles. path: "XREAppDist:distribution.ini", // check we're not msix to disambiguate from the next entry... condition: WIN && !Services.sysinfo.getProperty("hasWinPackageId"), stat: 1, }, { // On MSIX, we actually read this file - bug 1833341. path: "XREAppDist:distribution.ini", condition: WIN && Services.sysinfo.getProperty("hasWinPackageId"), stat: 1, read: 1, }, { // bug 1545139 path: "*Fonts/StaticCache.dat", condition: WIN, ignoreIfUnused: true, // Only on Win7 read: 1, }, { // Bug 1626738 path: "SysD:spool/drivers/color/*", condition: WIN, read: 1, }, { // Sandbox policy construction path: "*ld.so.conf*", condition: LINUX && !AppConstants.MOZ_CODE_COVERAGE, read: 22, close: 11, }, { // bug 1541246 path: "UAppData:", ignoreIfUnused: true, // sometimes before opening first browser window, // sometimes before first paint condition: WIN, stat: 1, }, { // Not in packaged builds; useful for artifact builds. path: "GreD:ScalarArtifactDefinitions.json", condition: WIN && !AppConstants.MOZILLA_OFFICIAL, stat: 1, }, { // Not in packaged builds; useful for artifact builds. path: "GreD:EventArtifactDefinitions.json", condition: WIN && !AppConstants.MOZILLA_OFFICIAL, stat: 1, }, { // bug 1541226 path: "ProfD:", condition: WIN, ignoreIfUnused: true, // Usually happens in the previous phase stat: 1, }, { // bug 1534745 path: "ProfD:cookies.sqlite-journal", condition: WIN, ignoreIfUnused: true, // Usually happens in the previous phase stat: 3, write: 4, }, { // bug 1534745 path: "ProfD:cookies.sqlite", condition: WIN, ignoreIfUnused: true, // Usually happens in the previous phase stat: 2, read: 3, write: 1, }, { // bug 1534745 path: "ProfD:cookies.sqlite-wal", condition: WIN, ignoreIfUnused: true, // Usually happens in the previous phase stat: 2, }, ], // We are at this phase once we are ready to handle user events. // Any IO at this phase or before gets in the way of the user // interacting with the first browser window. "before handling user events": [ { path: "GreD:update.test", ignoreIfUnused: true, condition: LINUX, close: 1, }, { path: "XREAppFeat:webcompat-reporter@mozilla.org.xpi", condition: !WIN, ignoreIfUnused: true, stat: 1, close: 1, }, { // Bug 1660582 - access while running on windows10 hardware. path: "ProfD:wmfvpxvideo.guard", condition: WIN, ignoreIfUnused: true, stat: 1, close: 1, }, { // Bug 1649590 path: "ProfD:extensions", ignoreIfUnused: true, condition: WIN, stat: 1, }, ], // Things that are expected to be completely out of the startup path // and loaded lazily when used for the first time by the user should // be listed here. "before becoming idle": [ { // bug 1370516 - NSS should be initialized off main thread. path: `ProfD:cert9.db`, condition: WIN, read: 5, stat: AppConstants.NIGHTLY_BUILD ? 5 : 4, }, { // bug 1370516 - NSS should be initialized off main thread. path: `ProfD:cert9.db-journal`, condition: WIN, stat: 3, }, { // bug 1370516 - NSS should be initialized off main thread. path: `ProfD:cert9.db-wal`, condition: WIN, stat: 3, }, { // bug 1370516 - NSS should be initialized off main thread. path: "ProfD:pkcs11.txt", condition: WIN, read: 2, }, { // bug 1370516 - NSS should be initialized off main thread. path: `ProfD:key4.db`, condition: WIN, read: 10, stat: AppConstants.NIGHTLY_BUILD ? 5 : 4, }, { // bug 1370516 - NSS should be initialized off main thread. path: `ProfD:key4.db-journal`, condition: WIN, stat: 7, }, { // bug 1370516 - NSS should be initialized off main thread. path: `ProfD:key4.db-wal`, condition: WIN, stat: 7, }, { path: "XREAppFeat:screenshots@mozilla.org.xpi", ignoreIfUnused: true, close: 1, }, { path: "XREAppFeat:webcompat-reporter@mozilla.org.xpi", ignoreIfUnused: true, stat: 1, close: 1, }, { // bug 1391590 path: "ProfD:places.sqlite-journal", ignoreIfUnused: true, fsync: 1, stat: 4, read: 1, write: 2, }, { // bug 1391590 path: "ProfD:places.sqlite-wal", ignoreIfUnused: true, stat: 4, fsync: 3, read: 51, write: 178, }, { // bug 1391590 path: "ProfD:places.sqlite-shm", condition: WIN, ignoreIfUnused: true, stat: 1, }, { // bug 1391590 path: "ProfD:places.sqlite", ignoreIfUnused: true, fsync: 2, read: 4, stat: 3, write: 1324, }, { // bug 1391590 path: "ProfD:favicons.sqlite-journal", ignoreIfUnused: true, fsync: 2, stat: 7, read: 2, write: 7, }, { // bug 1391590 path: "ProfD:favicons.sqlite-wal", ignoreIfUnused: true, fsync: 2, stat: 7, read: 7, write: 15, }, { // bug 1391590 path: "ProfD:favicons.sqlite-shm", condition: WIN, ignoreIfUnused: true, stat: 2, }, { // bug 1391590 path: "ProfD:favicons.sqlite", ignoreIfUnused: true, fsync: 3, read: 8, stat: 4, write: 1300, }, { path: "ProfD:", condition: WIN, ignoreIfUnused: true, stat: 3, }, ], }; for (let name of ["d3d11layers", "glcontext", "wmfvpxvideo"]) { startupPhases["before first paint"].push({ path: `ProfD:${name}.guard`, ignoreIfUnused: true, stat: 1, }); } function expandPathWithDirServiceKey(path) { if (path.includes(":")) { let [prefix, suffix] = path.split(":"); let [key, property] = prefix.split("."); let dir = Services.dirsvc.get(key, Ci.nsIFile); if (property) { dir = dir[property]; } // Resolve symLinks. let dirPath = dir.path; while (dir && !dir.isSymlink()) { dir = dir.parent; } if (dir) { dirPath = dirPath.replace(dir.path, dir.target); } path = dirPath; if (suffix) { path += "/" + suffix; } } if (AppConstants.platform == "win") { path = path.replace(/\//g, "\\"); } return path; } function getStackFromProfile(profile, stack) { const stackPrefixCol = profile.stackTable.schema.prefix; const stackFrameCol = profile.stackTable.schema.frame; const frameLocationCol = profile.frameTable.schema.location; let result = []; while (stack) { let sp = profile.stackTable.data[stack]; let frame = profile.frameTable.data[sp[stackFrameCol]]; stack = sp[stackPrefixCol]; frame = profile.stringTable[frame[frameLocationCol]]; if (frame != "js::RunScript" && !frame.startsWith("next (self-hosted:")) { result.push(frame); } } return result; } function pathMatches(path, filename) { path = path.toLowerCase(); return ( path == filename || // Full match // Wildcard on both sides of the path (path.startsWith("*") && path.endsWith("*") && filename.includes(path.slice(1, -1))) || // Wildcard suffix (path.endsWith("*") && filename.startsWith(path.slice(0, -1))) || // Wildcard prefix (path.startsWith("*") && filename.endsWith(path.slice(1))) ); } add_task(async function () { if ( !AppConstants.NIGHTLY_BUILD && !AppConstants.MOZ_DEV_EDITION && !AppConstants.DEBUG ) { ok( !("@mozilla.org/test/startuprecorder;1" in Cc), "the startup recorder component shouldn't exist in this non-nightly/non-devedition/" + "non-debug build." ); return; } TestUtils.assertPackagedBuild(); let startupRecorder = Cc["@mozilla.org/test/startuprecorder;1"].getService().wrappedJSObject; await startupRecorder.done; // Add system add-ons to the list of known IO dynamically. // They should go in the omni.ja file (bug 1357205). { let addons = await AddonManager.getAddonsByTypes(["extension"]); for (let addon of addons) { if (addon.isSystem) { startupPhases["before opening first browser window"].push({ path: `XREAppFeat:${addon.id}.xpi`, stat: 3, close: 2, }); startupPhases["before handling user events"].push({ path: `XREAppFeat:${addon.id}.xpi`, condition: WIN, stat: 2, }); } } } // Check for main thread I/O markers in the startup profile. let profile = startupRecorder.data.profile.threads[0]; let phases = {}; { const nameCol = profile.markers.schema.name; const dataCol = profile.markers.schema.data; let markersForCurrentPhase = []; let foundIOMarkers = false; for (let m of profile.markers.data) { let markerName = profile.stringTable[m[nameCol]]; if (markerName.startsWith("startupRecorder:")) { phases[markerName.split("startupRecorder:")[1]] = markersForCurrentPhase; markersForCurrentPhase = []; continue; } if (markerName != "FileIO") { continue; } let markerData = m[dataCol]; if (markerData.source == "sqlite-mainthread") { continue; } let samples = markerData.stack.samples; let stack = samples.data[0][samples.schema.stack]; markersForCurrentPhase.push({ operation: markerData.operation, filename: markerData.filename, source: markerData.source, stackId: stack, }); foundIOMarkers = true; } // The I/O interposer is disabled if !RELEASE_OR_BETA, so we expect to have // no I/O marker in that case, but it's good to keep the test running to check // that we are still able to produce startup profiles. is( foundIOMarkers, !AppConstants.RELEASE_OR_BETA, "The IO interposer should be enabled in builds that are not RELEASE_OR_BETA" ); if (!foundIOMarkers) { // If a profile unexpectedly contains no I/O marker, it's better to return // early to avoid having a lot of of confusing "no main thread IO when we // expected some" failures. return; } } for (let phase in startupPhases) { startupPhases[phase] = startupPhases[phase].filter( entry => !("condition" in entry) || entry.condition ); startupPhases[phase].forEach(entry => { entry.listedPath = entry.path; entry.path = expandPathWithDirServiceKey(entry.path); }); } let tmpPath = expandPathWithDirServiceKey("TmpD:").toLowerCase(); let shouldPass = true; for (let phase in phases) { let knownIOList = startupPhases[phase]; info( `known main thread IO paths during ${phase}:\n` + knownIOList .map(e => { let operations = Object.keys(e) .filter(k => k != "path") .map(k => `${k}: ${e[k]}`); return ` ${e.path} - ${operations.join(", ")}`; }) .join("\n") ); let markers = phases[phase]; for (let marker of markers) { if (marker.operation == "create/open") { // TODO: handle these I/O markers once they are supported on // non-Windows platforms. continue; } if (!marker.filename) { // We are still missing the filename on some mainthreadio markers, // these markers are currently useless for the purpose of this test. continue; } // Convert to lower case before comparing because the OS X test machines // have the 'Firefox' folder in 'Library/Application Support' created // as 'firefox' for some reason. let filename = marker.filename.toLowerCase(); if (!WIN && filename == "/dev/urandom") { continue; } // /dev/shm is always tmpfs (a memory filesystem); this isn't // really I/O any more than mmap/munmap are. if (LINUX && filename.startsWith("/dev/shm/")) { continue; } // "Files" from memfd_create() are similar to tmpfs but never // exist in the filesystem; however, they have names which are // exposed in procfs, and the I/O interposer observes when // they're close()d. if (LINUX && filename.startsWith("/memfd:")) { continue; } // Shared memory uses temporary files on MacOS <= 10.11 to avoid // a kernel security bug that will never be patched (see // https://crbug.com/project-zero/1671 for details). This can // be removed when we no longer support those OS versions. if (MAC && filename.startsWith(tmpPath + "/org.mozilla.ipc.")) { continue; } let expected = false; for (let entry of knownIOList) { if (pathMatches(entry.path, filename)) { entry[marker.operation] = (entry[marker.operation] || 0) - 1; entry._used = true; expected = true; break; } } if (!expected) { record( false, `unexpected ${marker.operation} on ${marker.filename} ${phase}`, undefined, " " + getStackFromProfile(profile, marker.stackId).join("\n ") ); shouldPass = false; } info(`(${marker.source}) ${marker.operation} - ${marker.filename}`); if (kDumpAllStacks) { info( getStackFromProfile(profile, marker.stackId) .map(f => " " + f) .join("\n") ); } } for (let entry of knownIOList) { for (let op in entry) { if ( [ "listedPath", "path", "condition", "ignoreIfUnused", "_used", ].includes(op) ) { continue; } let message = `${op} on ${entry.path} `; if (entry[op] == 0) { message += "as many times as expected"; } else if (entry[op] > 0) { message += `allowed ${entry[op]} more times`; } else { message += `${entry[op] * -1} more times than expected`; } ok(entry[op] >= 0, `${message} ${phase}`); } if (!("_used" in entry) && !entry.ignoreIfUnused) { ok( false, `no main thread IO when we expected some during ${phase}: ${entry.path} (${entry.listedPath})` ); shouldPass = false; } } } if (shouldPass) { ok(shouldPass, "No unexpected main thread I/O during startup"); } else { const filename = "profile_startup_mainthreadio.json"; let path = Services.env.get("MOZ_UPLOAD_DIR"); let profilePath = PathUtils.join(path, filename); await IOUtils.writeJSON(profilePath, startupRecorder.data.profile); ok( false, "Unexpected main thread I/O behavior during startup; open the " + `${filename} artifact in the Firefox Profiler to see what happened` ); } });