Skip to content

Commit 307b43a

Browse files
ofalvaiofalvai
authored
Add [TIMING] instrumentation to the integration test suite (#18)
The mocha-driven iOS/Android integration suite is slow and opaque - a single test run takes many minutes with no visibility into which phase (emulator boot, npm/pod install, native build, JS bundling, app install/launch) is responsible. Add lightweight [TIMING] console.log lines around the major phases in the test harness and helper scripts so future CI runs' logs can be mined for bottlenecks without re-instrumenting from scratch each time.
1 parent 02d4abd commit 307b43a

5 files changed

Lines changed: 75 additions & 11 deletions

File tree

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

Lines changed: 28 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -102,6 +102,12 @@ var emulatorReadyCheckDelayMs = 5 * 1000;
102102
*/
103103
function bootEmulatorInternal(platformName, restartEmulators, targetEmulator, checkEmulator, startEmulator, killEmulator) {
104104
var deferred = Q.defer();
105+
var bootStart = Date.now();
106+
deferred.promise.then(function () {
107+
console.log("[TIMING] " + platformName + " bootEmulator took " + (Date.now() - bootStart) + "ms");
108+
}, function () {
109+
console.log("[TIMING] " + platformName + " bootEmulator FAILED after " + (Date.now() - bootStart) + "ms");
110+
});
105111
console.log("Setting up " + platformName + " emulator.");
106112
function onEmulatorReady() {
107113
console.log(platformName + " emulator is ready!");
@@ -232,20 +238,31 @@ var AndroidEmulatorManager = (function () {
232238
* Ends a running application given its app id.
233239
*/
234240
AndroidEmulatorManager.prototype.endRunningApplication = function (appId) {
235-
return testUtil_1.TestUtil.getProcessOutput("adb shell am force-stop " + appId).then(function () { return Q.delay(10000); });
241+
var t0 = Date.now();
242+
return testUtil_1.TestUtil.getProcessOutput("adb shell am force-stop " + appId).then(function () {
243+
var waitStart = Date.now();
244+
return Q.delay(10000).then(function () {
245+
console.log("[TIMING] android endRunningApplication: force-stop took " + (Date.now() - t0) + "ms, teardown wait took " + (Date.now() - waitStart) + "ms");
246+
});
247+
});
236248
};
237249
/**
238250
* Restarts an already installed application by app id.
239251
*/
240252
AndroidEmulatorManager.prototype.restartApplication = function (appId) {
241253
var _this = this;
254+
var t0 = Date.now();
242255
return this.endRunningApplication(appId)
243256
.then(function () {
244257
// Wait for a 1 second before restarting.
245258
return Q.delay(1000);
246259
})
247260
.then(function () {
248261
return _this.launchInstalledApplication(appId);
262+
})
263+
.then(function (result) {
264+
console.log("[TIMING] android restartApplication total took " + (Date.now() - t0) + "ms");
265+
return result;
249266
});
250267
};
251268
/**
@@ -269,9 +286,14 @@ var AndroidEmulatorManager = (function () {
269286
* Prepares the emulator for a test.
270287
*/
271288
AndroidEmulatorManager.prototype.prepareEmulatorForTest = function (appId) {
289+
var t0 = Date.now();
272290
return this.endRunningApplication(appId)
273291
.then(function () {
274292
return commandWithCheckAppExistence("adb shell pm clear", appId);
293+
})
294+
.then(function (result) {
295+
console.log("[TIMING] android prepareEmulatorForTest total took " + (Date.now() - t0) + "ms");
296+
return result;
275297
});
276298
};
277299
/**
@@ -387,7 +409,11 @@ var IOSEmulatorManager = (function () {
387409
* Prepares the emulator for a test.
388410
*/
389411
IOSEmulatorManager.prototype.prepareEmulatorForTest = function (appId) {
390-
return this.endRunningApplication(appId);
412+
var t0 = Date.now();
413+
return this.endRunningApplication(appId).then(function (result) {
414+
console.log("[TIMING] ios prepareEmulatorForTest total took " + (Date.now() - t0) + "ms");
415+
return result;
416+
});
391417
};
392418
/**
393419
* Uninstalls the app from the emulator.

‎code-push-plugin-testing-framework/script/test.js‎

Lines changed: 19 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -46,19 +46,30 @@ function initializeTests(projectManager, supportedTargetPlatforms, describeTests
4646
*/
4747
function setupTests() {
4848
it("sets up tests correctly", function (done) {
49+
var setupStart = Date.now();
4950
var promises = [];
5051
targetPlatforms.forEach(function (platform) {
5152
promises.push(platform.getEmulatorManager().bootEmulator(TestConfig.restartEmulators));
5253
});
5354
console.log("Building test project.");
55+
var testProjectStart = Date.now();
5456
// create the test project
5557
promises.push(createTestProject(TestConfig.testRunDirectory)
5658
.then(function () {
59+
console.log("[TIMING] createTestProject(testRunDirectory) took " + (Date.now() - testProjectStart) + "ms");
5760
console.log("Building update project.");
61+
var updateProjectStart = Date.now();
5862
// create the update project
59-
return createTestProject(TestConfig.updatesDirectory);
63+
return createTestProject(TestConfig.updatesDirectory)
64+
.then(function (result) {
65+
console.log("[TIMING] createTestProject(updatesDirectory) took " + (Date.now() - updateProjectStart) + "ms");
66+
return result;
67+
});
6068
}).then(function () { return null; }));
61-
Q.all(promises).then(function () { done(); }, function (error) { done(error); });
69+
Q.all(promises).then(function () {
70+
console.log("[TIMING] setupTests total took " + (Date.now() - setupStart) + "ms");
71+
done();
72+
}, function (error) { done(error); });
6273
});
6374
}
6475
/**
@@ -73,10 +84,15 @@ function initializeTests(projectManager, supportedTargetPlatforms, describeTests
7384
function createAndRunTests(targetPlatform) {
7485
describe("CodePush", function () {
7586
before(function () {
87+
var beforeStart = Date.now();
7688
ServerUtil.setupServer(targetPlatform);
7789
return targetPlatform.getEmulatorManager().uninstallApplication(TestConfig.TestNamespace)
7890
.then(projectManager.preparePlatform.bind(projectManager, TestConfig.testRunDirectory, targetPlatform))
79-
.then(projectManager.preparePlatform.bind(projectManager, TestConfig.updatesDirectory, targetPlatform));
91+
.then(projectManager.preparePlatform.bind(projectManager, TestConfig.updatesDirectory, targetPlatform))
92+
.then(function (result) {
93+
console.log("[TIMING] " + targetPlatform.getName() + " suite before() (uninstall + preparePlatform x2) took " + (Date.now() - beforeStart) + "ms");
94+
return result;
95+
});
8096
});
8197
after(function () {
8298
ServerUtil.cleanupServer();

‎code-push-plugin-testing-framework/script/testBuilder.js‎

Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -39,7 +39,12 @@ function describeInternal(func, description, spec, scenarioPath) {
3939
});
4040
if (scenarioPath) {
4141
before(function () {
42-
return TestContext.projectManager.setupScenario(TestConfig.testRunDirectory, TestConfig.TestNamespace, TestConfig.templatePath, scenarioPath, TestContext.targetPlatform);
42+
var t0 = Date.now();
43+
return TestContext.projectManager.setupScenario(TestConfig.testRunDirectory, TestConfig.TestNamespace, TestConfig.templatePath, scenarioPath, TestContext.targetPlatform)
44+
.then(function (result) {
45+
console.log("[TIMING] setupScenario(" + scenarioPath + ") for \"" + description + "\" took " + (Date.now() - t0) + "ms");
46+
return result;
47+
});
4348
});
4449
}
4550
spec();

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

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -50,7 +50,10 @@ var TestUtil = (function () {
5050
options.timeout = 10 * 60 * 1000;
5151
if (!options.noLogCommand)
5252
console.log("Running command: " + command);
53+
var timingStart = Date.now();
54+
var timingLabel = command.length > 80 ? command.slice(0, 80) + "..." : command;
5355
var execProcess = child_process.exec(command, options, function (error, stdout, stderr) {
56+
console.log("[TIMING] exec \"" + timingLabel + "\" took " + (Date.now() - timingStart) + "ms");
5457
if (error) {
5558
if (!options.noLogStdErr)
5659
console.error("" + error);

‎test/test.ts‎

Lines changed: 19 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -440,6 +440,7 @@ class RNProjectManager extends ProjectManager {
440440
* Creates a CodePush update package zip for a project.
441441
*/
442442
public createUpdateArchive(projectDirectory: string, targetPlatform: Platform.IPlatform, isDiff?: boolean): Q.Promise<string> {
443+
const t0 = Date.now();
443444
const bundleFolder: string = path.join(projectDirectory, TestConfig.TestAppName, "CodePush/");
444445
const bundleName: string = (<RNPlatform><any>targetPlatform).getBundleName();
445446
const bundlePath: string = path.join(bundleFolder, bundleName);
@@ -460,12 +461,14 @@ class RNProjectManager extends ProjectManager {
460461
{ cwd: path.join(projectDirectory, TestConfig.TestAppName) }))
461462
.then(TestUtil.getProcessOutput.bind(undefined, "npx react-native bundle --entry-file index.js --platform " + targetPlatform.getName() + " --bundle-output " + bundlePath + " --assets-dest " + bundleFolder + " --dev false",
462463
{ cwd: path.join(projectDirectory, TestConfig.TestAppName) }))
463-
.then<string>(TestUtil.archiveFolder.bind(undefined, bundleFolder, "", path.join(projectDirectory, TestConfig.TestAppName, "update.zip"), isDiff));
464+
.then<string>(TestUtil.archiveFolder.bind(undefined, bundleFolder, "", path.join(projectDirectory, TestConfig.TestAppName, "update.zip"), isDiff))
465+
.then((result) => { console.log(`[TIMING] createUpdateArchive(${projectDirectory}, ${targetPlatform.getName()}) took ${Date.now() - t0}ms`); return result; });
464466
} else {
465467
return deferred.promise
466468
.then(TestUtil.getProcessOutput.bind(undefined, "npx react-native bundle --entry-file index.js --platform " + targetPlatform.getName() + " --bundle-output " + bundlePath + " --assets-dest " + bundleFolder + " --dev false",
467469
{ cwd: path.join(projectDirectory, TestConfig.TestAppName) }))
468-
.then<string>(TestUtil.archiveFolder.bind(undefined, bundleFolder, "", path.join(projectDirectory, TestConfig.TestAppName, "update.zip"), isDiff));
470+
.then<string>(TestUtil.archiveFolder.bind(undefined, bundleFolder, "", path.join(projectDirectory, TestConfig.TestAppName, "update.zip"), isDiff))
471+
.then((result) => { console.log(`[TIMING] createUpdateArchive(${projectDirectory}, ${targetPlatform.getName()}) took ${Date.now() - t0}ms`); return result; });
469472
}
470473
}
471474

@@ -523,23 +526,34 @@ class RNProjectManager extends ProjectManager {
523526
*/
524527
public runApplication(projectDirectory: string, targetPlatform: Platform.IPlatform): Q.Promise<void> {
525528
console.log("Running project in " + projectDirectory + " on " + targetPlatform.getName());
529+
const runAppStart = Date.now();
530+
const willBuild = !RNProjectManager.currentScenarioHasBuilt[projectDirectory];
526531

527532
return Q<void>(null)
528533
.then(() => {
529534
// Build if this scenario has not yet been built.
530535
if (!RNProjectManager.currentScenarioHasBuilt[projectDirectory]) {
531536
RNProjectManager.currentScenarioHasBuilt[projectDirectory] = true;
532-
return (<RNPlatform><any>targetPlatform).buildApp(projectDirectory);
537+
const buildStart = Date.now();
538+
return (<RNPlatform><any>targetPlatform).buildApp(projectDirectory)
539+
.then(() => { console.log(`[TIMING] ${targetPlatform.getName()} buildApp(${projectDirectory}) took ${Date.now() - buildStart}ms`); });
533540
}
534541
})
535542
.then(() => {
536543
// Uninstall the app so that the installation is clean and no files are left around for each test.
537-
return targetPlatform.getEmulatorManager().uninstallApplication(TestConfig.TestNamespace);
544+
const uninstallStart = Date.now();
545+
return targetPlatform.getEmulatorManager().uninstallApplication(TestConfig.TestNamespace)
546+
.then(() => { console.log(`[TIMING] ${targetPlatform.getName()} uninstallApplication took ${Date.now() - uninstallStart}ms`); });
538547
})
539548
.then(() => {
540549
// Install and launch the app.
550+
const installStart = Date.now();
541551
return (<RNPlatform><any>targetPlatform).installApp(projectDirectory)
542-
.then<void>(targetPlatform.getEmulatorManager().launchInstalledApplication.bind(undefined, TestConfig.TestNamespace));
552+
.then<void>(targetPlatform.getEmulatorManager().launchInstalledApplication.bind(undefined, TestConfig.TestNamespace))
553+
.then(() => { console.log(`[TIMING] ${targetPlatform.getName()} installApp+launch took ${Date.now() - installStart}ms`); });
554+
})
555+
.then(() => {
556+
console.log(`[TIMING] ${targetPlatform.getName()} runApplication total (built=${willBuild}) took ${Date.now() - runAppStart}ms`);
543557
});
544558
}
545559
}

0 commit comments

Comments
 (0)