Add [TIMING] instrumentation to the integration test suite

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,20 +238,31 @@ 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.
                 return Q.delay(1000);
             })
             .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.

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();

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();

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);

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<string> {
+        const t0 = Date.now();
         const bundleFolder: string = path.join(projectDirectory, TestConfig.TestAppName, "CodePush/");
         const bundleName: string = (<RNPlatform><any>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<string>(TestUtil.archiveFolder.bind(undefined, bundleFolder, "", path.join(projectDirectory, TestConfig.TestAppName, "update.zip"), isDiff));
+                .then<string>(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<string>(TestUtil.archiveFolder.bind(undefined, bundleFolder, "", path.join(projectDirectory, TestConfig.TestAppName, "update.zip"), isDiff));
+                .then<string>(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<void> {
         console.log("Running project in " + projectDirectory + " on " + targetPlatform.getName());
+        const runAppStart = Date.now();
+        const willBuild = !RNProjectManager.currentScenarioHasBuilt[projectDirectory];
 
         return Q<void>(null)
             .then(() => {
                 // Build if this scenario has not yet been built.
                 if (!RNProjectManager.currentScenarioHasBuilt[projectDirectory]) {
                     RNProjectManager.currentScenarioHasBuilt[projectDirectory] = true;
-                    return (<RNPlatform><any>targetPlatform).buildApp(projectDirectory);
+                    const buildStart = Date.now();
+                    return (<RNPlatform><any>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 (<RNPlatform><any>targetPlatform).installApp(projectDirectory)
-                    .then<void>(targetPlatform.getEmulatorManager().launchInstalledApplication.bind(undefined, TestConfig.TestNamespace));
+                    .then<void>(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`);
             });
     }
 }