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.

Sign up for GitHub

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

Jump to bottom

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

Merged
merged 4 commits into from Feb 5, 2023
Merged

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

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
0def924
Add start/end performance markers around significant lifecycle events
robhogan Feb 3, 2023
3514392
Changelog
robhogan Feb 3, 2023
3b731df
Typo
robhogan Feb 3, 2023
b5cb25e
Prettier
robhogan Feb 3, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
2 changes: 2 additions & 0 deletions CHANGELOG.md
View file
Open in desktop
Expand Up @@ -2,6 +2,8 @@

### Features

- `[@jest/core]` Instrument significant lifecycle events with [`performance.mark()`](https://nodejs.org/docs/latest-v16.x/api/perf_hooks.html#performancemarkname-options) ([#13859](https://github.com/facebook/jest/pull/13859))

### Fixes

- `[expect, @jest/expect]` Provide type of `actual` as a generic argument to `Matchers` to allow better-typed extensions ([#13848](https://github.com/facebook/jest/pull/13848))
Expand Down
11 changes: 11 additions & 0 deletions packages/jest-core/src/cli/index.ts
View file
Open in desktop
Expand Up @@ -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';
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -133,6 +135,7 @@ export async function runCLI(
console.error(message);
}

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

Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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 •
edited

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(
Expand Down
16 changes: 16 additions & 0 deletions packages/jest-core/src/runJest.ts
View file
Open in desktop
Expand Up @@ -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';
Expand Down Expand Up @@ -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];
Expand All @@ -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') {
Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -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,
Expand All @@ -305,4 +320,5 @@ export default async function runJest({
outputStream,
testResultsProcessor: globalConfig.testResultsProcessor,
});
performance.mark('jest/processResults:end');
}