diff --git a/code-push-plugin-testing-framework/script/platform.js b/code-push-plugin-testing-framework/script/platform.js index 351cbceb..c41fe781 100644 --- a/code-push-plugin-testing-framework/script/platform.js +++ b/code-push-plugin-testing-framework/script/platform.js @@ -102,6 +102,12 @@ var emulatorReadyCheckDelayMs = 5 * 1000; */ function bootEmulatorInternal(platformName, restartEmulators, targetEmulator, checkEmulator, startEmulator, killEmulator) { var deferred = Q.defer(); + var bootStart = Date.now(); + deferred.promise.then(function () { + console.log("[TIMING] " + platformName + " bootEmulator took " + (Date.now() - bootStart) + "ms"); + }, function () { + console.log("[TIMING] " + platformName + " bootEmulator FAILED after " + (Date.now() - bootStart) + "ms"); + }); console.log("Setting up " + platformName + " emulator."); function onEmulatorReady() { console.log(platformName + " emulator is ready!"); @@ -232,13 +238,20 @@ var AndroidEmulatorManager = (function () { * Ends a running application given its app id. */ AndroidEmulatorManager.prototype.endRunningApplication = function (appId) { - return testUtil_1.TestUtil.getProcessOutput("adb shell am force-stop " + appId).then(function () { return Q.delay(10000); }); + var t0 = Date.now(); + return testUtil_1.TestUtil.getProcessOutput("adb shell am force-stop " + appId).then(function () { + var waitStart = Date.now(); + return Q.delay(10000).then(function () { + console.log("[TIMING] android endRunningApplication: force-stop took " + (Date.now() - t0) + "ms, teardown wait took " + (Date.now() - waitStart) + "ms"); + }); + }); }; /** * Restarts an already installed application by app id. */ AndroidEmulatorManager.prototype.restartApplication = function (appId) { var _this = this; + var t0 = Date.now(); return this.endRunningApplication(appId) .then(function () { // Wait for a 1 second before restarting. @@ -246,6 +259,10 @@ var AndroidEmulatorManager = (function () { }) .then(function () { return _this.launchInstalledApplication(appId); + }) + .then(function (result) { + console.log("[TIMING] android restartApplication total took " + (Date.now() - t0) + "ms"); + return result; }); }; /** @@ -269,9 +286,14 @@ var AndroidEmulatorManager = (function () { * Prepares the emulator for a test. */ AndroidEmulatorManager.prototype.prepareEmulatorForTest = function (appId) { + var t0 = Date.now(); return this.endRunningApplication(appId) .then(function () { return commandWithCheckAppExistence("adb shell pm clear", appId); + }) + .then(function (result) { + console.log("[TIMING] android prepareEmulatorForTest total took " + (Date.now() - t0) + "ms"); + return result; }); }; /** @@ -387,7 +409,11 @@ var IOSEmulatorManager = (function () { * Prepares the emulator for a test. */ IOSEmulatorManager.prototype.prepareEmulatorForTest = function (appId) { - return this.endRunningApplication(appId); + var t0 = Date.now(); + return this.endRunningApplication(appId).then(function (result) { + console.log("[TIMING] ios prepareEmulatorForTest total took " + (Date.now() - t0) + "ms"); + return result; + }); }; /** * Uninstalls the app from the emulator. diff --git a/code-push-plugin-testing-framework/script/test.js b/code-push-plugin-testing-framework/script/test.js index 2a209edc..2fe2d9b9 100644 --- a/code-push-plugin-testing-framework/script/test.js +++ b/code-push-plugin-testing-framework/script/test.js @@ -46,19 +46,30 @@ function initializeTests(projectManager, supportedTargetPlatforms, describeTests */ function setupTests() { it("sets up tests correctly", function (done) { + var setupStart = Date.now(); var promises = []; targetPlatforms.forEach(function (platform) { promises.push(platform.getEmulatorManager().bootEmulator(TestConfig.restartEmulators)); }); console.log("Building test project."); + var testProjectStart = Date.now(); // create the test project promises.push(createTestProject(TestConfig.testRunDirectory) .then(function () { + console.log("[TIMING] createTestProject(testRunDirectory) took " + (Date.now() - testProjectStart) + "ms"); console.log("Building update project."); + var updateProjectStart = Date.now(); // create the update project - return createTestProject(TestConfig.updatesDirectory); + return createTestProject(TestConfig.updatesDirectory) + .then(function (result) { + console.log("[TIMING] createTestProject(updatesDirectory) took " + (Date.now() - updateProjectStart) + "ms"); + return result; + }); }).then(function () { return null; })); - Q.all(promises).then(function () { done(); }, function (error) { done(error); }); + Q.all(promises).then(function () { + console.log("[TIMING] setupTests total took " + (Date.now() - setupStart) + "ms"); + done(); + }, function (error) { done(error); }); }); } /** @@ -73,10 +84,15 @@ function initializeTests(projectManager, supportedTargetPlatforms, describeTests function createAndRunTests(targetPlatform) { describe("CodePush", function () { before(function () { + var beforeStart = Date.now(); ServerUtil.setupServer(targetPlatform); return targetPlatform.getEmulatorManager().uninstallApplication(TestConfig.TestNamespace) .then(projectManager.preparePlatform.bind(projectManager, TestConfig.testRunDirectory, targetPlatform)) - .then(projectManager.preparePlatform.bind(projectManager, TestConfig.updatesDirectory, targetPlatform)); + .then(projectManager.preparePlatform.bind(projectManager, TestConfig.updatesDirectory, targetPlatform)) + .then(function (result) { + console.log("[TIMING] " + targetPlatform.getName() + " suite before() (uninstall + preparePlatform x2) took " + (Date.now() - beforeStart) + "ms"); + return result; + }); }); after(function () { ServerUtil.cleanupServer(); diff --git a/code-push-plugin-testing-framework/script/testBuilder.js b/code-push-plugin-testing-framework/script/testBuilder.js index 34a20295..ad6670fa 100644 --- a/code-push-plugin-testing-framework/script/testBuilder.js +++ b/code-push-plugin-testing-framework/script/testBuilder.js @@ -39,7 +39,12 @@ function describeInternal(func, description, spec, scenarioPath) { }); if (scenarioPath) { before(function () { - return TestContext.projectManager.setupScenario(TestConfig.testRunDirectory, TestConfig.TestNamespace, TestConfig.templatePath, scenarioPath, TestContext.targetPlatform); + var t0 = Date.now(); + return TestContext.projectManager.setupScenario(TestConfig.testRunDirectory, TestConfig.TestNamespace, TestConfig.templatePath, scenarioPath, TestContext.targetPlatform) + .then(function (result) { + console.log("[TIMING] setupScenario(" + scenarioPath + ") for \"" + description + "\" took " + (Date.now() - t0) + "ms"); + return result; + }); }); } spec(); diff --git a/code-push-plugin-testing-framework/script/testUtil.js b/code-push-plugin-testing-framework/script/testUtil.js index b47ce89a..5afd21a1 100644 --- a/code-push-plugin-testing-framework/script/testUtil.js +++ b/code-push-plugin-testing-framework/script/testUtil.js @@ -50,7 +50,10 @@ var TestUtil = (function () { options.timeout = 10 * 60 * 1000; if (!options.noLogCommand) console.log("Running command: " + command); + var timingStart = Date.now(); + var timingLabel = command.length > 80 ? command.slice(0, 80) + "..." : command; var execProcess = child_process.exec(command, options, function (error, stdout, stderr) { + console.log("[TIMING] exec \"" + timingLabel + "\" took " + (Date.now() - timingStart) + "ms"); if (error) { if (!options.noLogStdErr) console.error("" + error); diff --git a/test/test.ts b/test/test.ts index 1fd3862d..86608b42 100644 --- a/test/test.ts +++ b/test/test.ts @@ -440,6 +440,7 @@ class RNProjectManager extends ProjectManager { * Creates a CodePush update package zip for a project. */ public createUpdateArchive(projectDirectory: string, targetPlatform: Platform.IPlatform, isDiff?: boolean): Q.Promise { + const t0 = Date.now(); const bundleFolder: string = path.join(projectDirectory, TestConfig.TestAppName, "CodePush/"); const bundleName: string = (targetPlatform).getBundleName(); const bundlePath: string = path.join(bundleFolder, bundleName); @@ -460,12 +461,14 @@ class RNProjectManager extends ProjectManager { { cwd: path.join(projectDirectory, TestConfig.TestAppName) })) .then(TestUtil.getProcessOutput.bind(undefined, "npx react-native bundle --entry-file index.js --platform " + targetPlatform.getName() + " --bundle-output " + bundlePath + " --assets-dest " + bundleFolder + " --dev false", { cwd: path.join(projectDirectory, TestConfig.TestAppName) })) - .then(TestUtil.archiveFolder.bind(undefined, bundleFolder, "", path.join(projectDirectory, TestConfig.TestAppName, "update.zip"), isDiff)); + .then(TestUtil.archiveFolder.bind(undefined, bundleFolder, "", path.join(projectDirectory, TestConfig.TestAppName, "update.zip"), isDiff)) + .then((result) => { console.log(`[TIMING] createUpdateArchive(${projectDirectory}, ${targetPlatform.getName()}) took ${Date.now() - t0}ms`); return result; }); } else { return deferred.promise .then(TestUtil.getProcessOutput.bind(undefined, "npx react-native bundle --entry-file index.js --platform " + targetPlatform.getName() + " --bundle-output " + bundlePath + " --assets-dest " + bundleFolder + " --dev false", { cwd: path.join(projectDirectory, TestConfig.TestAppName) })) - .then(TestUtil.archiveFolder.bind(undefined, bundleFolder, "", path.join(projectDirectory, TestConfig.TestAppName, "update.zip"), isDiff)); + .then(TestUtil.archiveFolder.bind(undefined, bundleFolder, "", path.join(projectDirectory, TestConfig.TestAppName, "update.zip"), isDiff)) + .then((result) => { console.log(`[TIMING] createUpdateArchive(${projectDirectory}, ${targetPlatform.getName()}) took ${Date.now() - t0}ms`); return result; }); } } @@ -523,23 +526,34 @@ class RNProjectManager extends ProjectManager { */ public runApplication(projectDirectory: string, targetPlatform: Platform.IPlatform): Q.Promise { console.log("Running project in " + projectDirectory + " on " + targetPlatform.getName()); + const runAppStart = Date.now(); + const willBuild = !RNProjectManager.currentScenarioHasBuilt[projectDirectory]; return Q(null) .then(() => { // Build if this scenario has not yet been built. if (!RNProjectManager.currentScenarioHasBuilt[projectDirectory]) { RNProjectManager.currentScenarioHasBuilt[projectDirectory] = true; - return (targetPlatform).buildApp(projectDirectory); + const buildStart = Date.now(); + return (targetPlatform).buildApp(projectDirectory) + .then(() => { console.log(`[TIMING] ${targetPlatform.getName()} buildApp(${projectDirectory}) took ${Date.now() - buildStart}ms`); }); } }) .then(() => { // Uninstall the app so that the installation is clean and no files are left around for each test. - return targetPlatform.getEmulatorManager().uninstallApplication(TestConfig.TestNamespace); + const uninstallStart = Date.now(); + return targetPlatform.getEmulatorManager().uninstallApplication(TestConfig.TestNamespace) + .then(() => { console.log(`[TIMING] ${targetPlatform.getName()} uninstallApplication took ${Date.now() - uninstallStart}ms`); }); }) .then(() => { // Install and launch the app. + const installStart = Date.now(); return (targetPlatform).installApp(projectDirectory) - .then(targetPlatform.getEmulatorManager().launchInstalledApplication.bind(undefined, TestConfig.TestNamespace)); + .then(targetPlatform.getEmulatorManager().launchInstalledApplication.bind(undefined, TestConfig.TestNamespace)) + .then(() => { console.log(`[TIMING] ${targetPlatform.getName()} installApp+launch took ${Date.now() - installStart}ms`); }); + }) + .then(() => { + console.log(`[TIMING] ${targetPlatform.getName()} runApplication total (built=${willBuild}) took ${Date.now() - runAppStart}ms`); }); } }