Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat(jest-core): Add performance markers around significant lifecycle events #13859

Merged
merged 4 commits into from
Feb 5, 2023
Merged
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Next Next commit
Add start/end performance markers around significant lifecycle events
robhogan committed Feb 3, 2023

Verified

This commit was created on GitHub.com and signed with GitHub’s verified signature. The key has expired.
commit 0def924f3faca1498004a67923b7073d16a8c98a
11 changes: 11 additions & 0 deletions packages/jest-core/src/cli/index.ts
Original file line number Diff line number Diff line change
@@ -5,6 +5,7 @@
* LICENSE file in the root directory of this source tree.
*/

import {performance} from 'perf_hooks';
import chalk = require('chalk');
import exit = require('exit');
import * as fs from 'graceful-fs';
@@ -41,6 +42,7 @@ export async function runCLI(
results: AggregatedResult;
globalConfig: Config.GlobalConfig;
}> {
performance.mark('jest/runCLI:start');
let results: AggregatedResult | undefined;

// If we output a JSON object, we can't write anything to stdout, since
@@ -133,6 +135,7 @@ export async function runCLI(
console.error(message);
}

performance.mark('jest/runCLI:end');
return {globalConfig, results};
}

@@ -173,6 +176,12 @@ const _run10000 = async (
// Queries to hg/git can take a while, so we need to start the process
// as soon as possible, so by the time we need the result it's already there.
const changedFilesPromise = getChangedFilesPromise(globalConfig, configs);
if (changedFilesPromise) {
performance.mark('jest/getChangedFiles:start');
changedFilesPromise.finally(() => {
performance.mark('jest/getChangedFiles:end');
});
}

// Filter may need to do an HTTP call or something similar to setup.
// We will wait on an async response from this before using the filter.
@@ -204,11 +213,13 @@ const _run10000 = async (
};
}

performance.mark('jest/buildContextsAndHasteMaps:start');
const {contexts, hasteMapInstances} = await buildContextsAndHasteMaps(
configs,
globalConfig,
outputStream,
);
performance.mark('jest/buildContextsAndHasteMaps:end');
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

would using something like https://nodejs.org/api/perf_hooks.html#performancetimerifyfn-options make sense? both here and other places with a start & end pair

Copy link
Contributor Author

@robhogan robhogan Feb 5, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I did consider timerify, but it's limited - there's no way to pass detail, unlike with marks (I used that here for numTests), and the only label on the entry is the literal name of the function, which isn't necessarily descriptive out of context. It's not interchangeable with mark either, because it requires a PerformanceObserver and creates different entry types.

One thing I like about being able to specify the labels is being able to namespace them to Jest, which is important if you've got other instrumented code in the same process (if, e.g, Babel introduced instrumentation, we'd want to be able to distinguish it from Jest's, and at Meta we run Jest programmatically in a wrapper that has its own instrumentation).

Another alternative I looked at is measure, but it pretty much just changes the syntax of the end marker:

const fooStartMarker = performance.mark('foo:start');
// ...foo
performance.measure('foo', fooStartMarker); // OR performance.measure('foo', 'foo:start');

vs

performance.mark('foo:start');
// ...foo
performance.mark('foo:end');

..I'm not sure the former is any cleaner. Also, a consumer can trivially create measures from marks if that's what they want, whereas the reverse is harder.

So TL;DR IMO mark optimises for flexibility and simplicity. Admittedly it isn't super clean, but I wouldn't anticipate littering the whole codebase or even much more than what's in this PR - if we did end up adding lots more markers, we could reduce some duplication and strengthen typing with an abstraction (require('jest-instrumentation').startMark('foo') or similar).

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Cool, thanks for the thorough response 👍


globalConfig.watch || globalConfig.watchAll
? await runWatch(
16 changes: 16 additions & 0 deletions packages/jest-core/src/runJest.ts
Original file line number Diff line number Diff line change
@@ -6,6 +6,7 @@
*/

import * as path from 'path';
import {performance} from 'perf_hooks';
import chalk = require('chalk');
import exit = require('exit');
import * as fs from 'graceful-fs';
@@ -179,6 +180,7 @@ export default async function runJest({

const searchSources = contexts.map(context => new SearchSource(context));

performance.mark('jest/getTestPaths:start');
const testRunData: TestRunData = await Promise.all(
contexts.map(async (context, index) => {
const searchSource = searchSources[index];
@@ -195,6 +197,7 @@ export default async function runJest({
return {context, matches};
}),
);
performance.mark('jest/getTestPaths:end');

if (globalConfig.shard) {
if (typeof sequencer.shard !== 'function') {
@@ -260,7 +263,9 @@ export default async function runJest({
}

if (hasTests) {
performance.mark('jest/globalSetup:start');
await runGlobalHook({allTests, globalConfig, moduleName: 'globalSetup'});
performance.mark('jest/globalSetup:end');
}

if (changedFilesPromise) {
@@ -289,14 +294,24 @@ export default async function runJest({
...testSchedulerContext,
});

// @ts-expect-error - second arg is unsupported (but harmless) in Node 14
performance.mark('jest/scheduleAndRun:start', {
detail: {numTests: allTests.length},
});
const results = await scheduler.scheduleTests(allTests, testWatcher);
performance.mark('jest/scheduleAndRun:start');

performance.mark('jest/cacheResults:start');
sequencer.cacheResults(allTests, results);
performance.mark('jest/cacheResults:end');

if (hasTests) {
performance.mark('jest/globalTeardown:start');
await runGlobalHook({allTests, globalConfig, moduleName: 'globalTeardown'});
performance.mark('jest/globalTeardown:end');
}

performance.mark('jest/processResults:start');
await processResults(results, {
collectHandles,
json: globalConfig.json,
@@ -305,4 +320,5 @@ export default async function runJest({
outputStream,
testResultsProcessor: globalConfig.testResultsProcessor,
});
performance.mark('jest/processResults:end');
}