Add [TIMING] instrumentation to integration test runner

.github/workflows/ci-test.yml

@@ -37,6 +37,14 @@ jobs:
 
       - uses: jdx/mise-action@v4
 
+      - name: Cache npm packages
+        uses: actions/cache@v4
+        with:
+          path: ~/.npm
+          key: ${{ runner.os }}-npm-${{ hashFiles('package-lock.json', 'test/test.ts') }}
+          restore-keys: |
+            ${{ runner.os }}-npm-
+
       - name: Install dependencies
         run: npm install
 
@@ -76,7 +84,32 @@ jobs:
 
       - uses: jdx/mise-action@v4
 
+      - name: Cache npm packages
+        uses: actions/cache@v4
+        with:
+          path: ~/.npm
+          key: ${{ runner.os }}-npm-${{ hashFiles('package-lock.json', 'test/test.ts') }}
+          restore-keys: |
+            ${{ runner.os }}-npm-
+
+      - name: Cache CocoaPods
+        uses: actions/cache@v4
+        with:
+          path: |
+            ~/.cocoapods
+            ~/Library/Caches/CocoaPods
+          key: ${{ runner.os }}-cocoapods-${{ hashFiles('test/test.ts') }}
+          restore-keys: |
+            ${{ runner.os }}-cocoapods-
+
       - name: Run iOS Tests
         run: |
           npm install
           npm run ${{ matrix.test-command }}
+
+      - name: Debug CocoaPods cache size after test run
+        if: always()
+        run: |
+          du -sh ~/.cocoapods 2>&1 || true
+          du -sh ~/Library/Caches/CocoaPods 2>&1 || true
+          find ~/Library/Caches/CocoaPods -type f 2>/dev/null | xargs du -sh 2>/dev/null | sort -rh | head -100 || true

code-push-plugin-testing-framework/script/platform.js

@@ -97,11 +97,47 @@ exports.IOS = IOS;
 // bootEmulatorInternal constants
 var emulatorMaxReadyAttempts = 50;
 var emulatorReadyCheckDelayMs = 5 * 1000;
+
+/**
+ * Checks whether an Android app is currently running via "pidof", which exits non-zero
+ * (rejecting the promise) with no output when the process isn't found.
+ */
+function isAndroidAppRunning(appId) {
+    return testUtil_1.TestUtil.getProcessOutput("adb shell pidof " + appId, { noLogCommand: true, noLogStdOut: true, noLogStdErr: true })
+        .then(function () { return true; }, function () { return false; });
+}
+
+/**
+ * Polls until an Android app is no longer running, capped at maxWaitMs as a safety net
+ * in case the process never fully tears down (matches the old fixed-delay's worst case).
+ */
+function waitForAndroidAppToStop(appId, maxWaitMs) {
+    var pollIntervalMs = 200;
+    var deferred = Q.defer();
+    var start = Date.now();
+    function poll() {
+        isAndroidAppRunning(appId).then(function (isRunning) {
+            if (!isRunning || Date.now() - start >= maxWaitMs) {
+                deferred.resolve(undefined);
+            } else {
+                setTimeout(poll, pollIntervalMs);
+            }
+        }, function () { deferred.resolve(undefined); });
+    }
+    poll();
+    return deferred.promise;
+}
 /**
  * Helper function for EmulatorManager implementations to use to boot an emulator with a given platformName and check, start, and kill methods.
  */
 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 +268,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 waitForAndroidAppToStop(appId, 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 +316,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 +439,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();
@@ -64,7 +69,7 @@ function itInternal(func, expectation, isCoreTest, assertion) {
     if ((!TestConfig.onlyRunCoreTests || isCoreTest)) {
         // Create a wrapper around the assertion to set the timeout on the test to 10 minutes.
         var assertionWithTimeout = function (done) {
-            this.timeout(10 * 2 * 60 * 1000);
+            this.timeout(6 * 60 * 1000);
             assertion(done);
         };
         return it(expectation, assertionWithTimeout);

code-push-plugin-testing-framework/script/testUtil.js

@@ -50,10 +50,18 @@ 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);
+                // Always surface full output on failure, even if noLogStdOut/noLogStdErr
+                // silenced it on the success path above - otherwise failures are undiagnosable.
+                console.error("" + error);
+                if (stdout)
+                    console.error("stdout:\n" + stdout);
+                if (stderr)
+                    console.error("stderr:\n" + stderr);
                 deferred.reject(error);
             }
             else {
@@ -65,10 +73,85 @@ var TestUtil = (function () {
         if (!options.noLogStdErr)
             execProcess.stderr.pipe(process.stderr);
         execProcess.on('error', function (error) {
+            console.error("" + error);
+            deferred.reject(error);
+        });
+        return deferred.promise;
+    };
+    /**
+     * Like getProcessOutput, but additionally logs a [TIMING] line for each "✔ <phase>"
+     * progress marker the child process prints to stdout (e.g. the phases printed by
+     * `@react-native-community/cli init`), so long opaque commands can be broken down
+     * into their constituent phases without changing their behavior.
+     */
+    TestUtil.getProcessOutputWithPhaseTiming = function (command, options) {
+        var deferred = Q.defer();
+        options = options || {};
+        if (options.timeout === undefined)
+            options.timeout = 10 * 60 * 1000;
+        if (!options.noLogCommand)
+            console.log("Running command: " + command);
+        var __timingStart = Date.now();
+        var __lastMarker = __timingStart;
+        var __label = command.length > 80 ? command.slice(0, 80) + "..." : command;
+        var child = child_process.spawn(command, [], { cwd: options.cwd, env: options.env, shell: true });
+        var stdoutBuf = "";
+        var stderrBuf = "";
+        var pendingStdoutLine = "";
+        var pendingStderrLine = "";
+        function handleLine(line) {
+            var trimmed = line.trim();
+            if (trimmed.indexOf("✔") === 0) {
+                var now = Date.now();
+                var phaseName = trimmed.replace(/^✔\s*/, "");
+                console.log("[TIMING] phase \"" + phaseName + "\" took " + (now - __lastMarker) + "ms (cumulative " + (now - __timingStart) + "ms)");
+                __lastMarker = now;
+            }
+        }
+        child.stdout.on("data", function (chunk) {
+            stdoutBuf += chunk;
+            pendingStdoutLine += chunk.toString();
+            var lines = pendingStdoutLine.split("\n");
+            pendingStdoutLine = lines.pop();
+            lines.forEach(handleLine);
+            if (!options.noLogStdOut)
+                process.stdout.write(chunk);
+        });
+        child.stderr.on("data", function (chunk) {
+            stderrBuf += chunk;
+            pendingStderrLine += chunk.toString();
+            var stderrLines = pendingStderrLine.split("\n");
+            pendingStderrLine = stderrLines.pop();
+            stderrLines.forEach(handleLine);
             if (!options.noLogStdErr)
-                console.error("" + error);
+                process.stderr.write(chunk);
+        });
+        var timeoutHandle = setTimeout(function () {
+            child.kill();
+        }, options.timeout);
+        child.on("error", function (error) {
+            clearTimeout(timeoutHandle);
+            console.error("" + error);
             deferred.reject(error);
         });
+        child.on("close", function (code) {
+            clearTimeout(timeoutHandle);
+            console.log("[TIMING] exec \"" + __label + "\" took " + (Date.now() - __timingStart) + "ms");
+            if (code !== 0) {
+                var error = new Error(command + " exited with code " + code);
+                // Always surface full output on failure, even if noLogStdOut/noLogStdErr
+                // silenced it on the success path above - otherwise failures are undiagnosable.
+                console.error("" + error);
+                if (stdoutBuf)
+                    console.error("stdout:\n" + stdoutBuf);
+                if (stderrBuf)
+                    console.error("stderr:\n" + stderrBuf);
+                deferred.reject(error);
+            }
+            else {
+                deferred.resolve(stdoutBuf.toString());
+            }
+        });
         return deferred.promise;
     };
     /**

code-push-plugin-testing-framework/typings/code-push-plugin-testing-framework.d.ts

@@ -451,6 +451,19 @@ declare module 'code-push-plugin-testing-framework/script/testUtil' {
 	        noLogStdOut?: boolean;
 	        noLogStdErr?: boolean;
 	    }): Q.Promise<string>;
+	    /**
+	     * Like getProcessOutput, but additionally logs a [TIMING] line for each "✔ <phase>"
+	     * progress marker the child process prints to stdout, so long opaque commands can be
+	     * broken down into their constituent phases.
+	     */
+	    static getProcessOutputWithPhaseTiming(command: string, options?: {
+	    	cwd?: string;
+	    	env?: any;
+	    	timeout?: number;
+	    	noLogCommand?: boolean;
+	    	noLogStdOut?: boolean;
+	    	noLogStdErr?: boolean;
+	    }): Q.Promise<string>;
 	    /**
 	     * Returns the name of the plugin that is being tested.
 	     */