Skip to content

feat: track module execution totalTime and selfTime #8027

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

Merged

Conversation

abrenneke
Copy link
Contributor

@abrenneke abrenneke commented May 25, 2025

Current Description

Description

Implements #8026 partially

This PR internally tracks the "Total Time" and "Self Time" for importing every non-externalized module in the Vitest Node Runner (vm and non-vm), for the purposes of breaking down the collect statistic.

  • Total Time: The time spent importing & executing the module, and all its imports
  • Self Time: The time spent importing & executing the module, minus the time spent executing all non-externalized imports. Therefore, it's the time executing the module itself + direct imports to externalized modules

This will help in the future for adding to existing reporters, or deeply integrating into existing reporters.

This adds a new importDurations property to the File type, which, for the given test file, is the time spent on imports (collect).

Please don't delete this checklist! Before submitting the PR, please make sure you do the following:

  • It's really useful if your PR references an issue where it is discussed ahead of time. If the feature is substantial or introduces breaking changes without a discussion, PR might be closed.
  • Ideally, include a test that fails without this PR but passes with it.
  • Please, don't make changes to pnpm-lock.yaml unless you introduce a new test example.

Tests

  • Run the tests with pnpm test:ci.

Documentation

  • If you introduce new functionality, document it. You can run documentation with pnpm run docs command.

Changesets

  • Changes in changelog are generated from PR name. Please, make sure that it explains your changes in an understandable manner. Please, prefix changeset messages with feat:, fix:, perf:, docs:, or chore:.

Original Description Below!

Description

Implements #8026

This is a rough PR right now. The reporter itself was whipped up quickly using AI. The rest of the changes were not. I'm happy to make any changes at all. I'd just like to get some feedback whether this is something you'd even consider merging - if so I can clean it up, add documentation, add tests, etc.

This PR tracks the import time for every file the Vitest processes. When the --reporter=collect-time is used, it will report the sum of the collect times per file. That is to say, in profiling terms it returns Total Time, not Self Time for the imports. Self Time would be possible with a bit more work probably.

Personally, I have already found this very useful when working on our large monorepo. It lets me find bottnecks in testing and optimize the imports.

Here is what the reporter looks like on Vitest itself:

image

Alternatively: we could just to the type and other minimal changes to track the import time, then let a custom reporter package do the actual reporting. That would make this PR very small and targeted, with no user-visible changes.

Let me know if this is worth continuing! Thanks!

Please don't delete this checklist! Before submitting the PR, please make sure you do the following:

  • It's really useful if your PR references an issue where it is discussed ahead of time. If the feature is substantial or introduces breaking changes without a discussion, PR might be closed.
  • Ideally, include a test that fails without this PR but passes with it.
  • Please, don't make changes to pnpm-lock.yaml unless you introduce a new test example.

Tests

  • Run the tests with pnpm test:ci.

Documentation

  • If you introduce new functionality, document it. You can run documentation with pnpm run docs command.

Changesets

  • Changes in changelog are generated from PR name. Please, make sure that it explains your changes in an understandable manner. Please, prefix changeset messages with feat:, fix:, perf:, docs:, or chore:.

Copy link

netlify bot commented May 25, 2025

Deploy Preview for vitest-dev ready!

Built without sensitive environment variables

Name Link
🔨 Latest commit ba7378d
🔍 Latest deploy log https://app.netlify.com/projects/vitest-dev/deploys/68360ffcd06a93000877da2d
😎 Deploy Preview https://deploy-preview-8027--vitest-dev.netlify.app
📱 Preview on mobile
Toggle QR Code...

QR Code

Use your smartphone camera to open QR code link.

To edit notification comments on pull requests, go to your Netlify project configuration.

const fn = vm.runInThisContext(code, options)
await fn(...Object.values(context))

this.options.moduleExecutionInfo?.set(options.filename, { startOffset: codeDefinition.length, duration: performance.now() - start })
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Awkward setting it twice like this, but reusing moduleExecutionInfo is convenient

@abrenneke
Copy link
Contributor Author

abrenneke commented May 25, 2025

here's some changes that adds Self Time reporting capabilities. It's a bit more invasive with the stack tracking (disclosure: that part is AI generated, just a proof-of-concept)

image

@hi-ogawa
Copy link
Contributor

hi-ogawa commented May 26, 2025

Tracking runModule sounds interesting, but as you pointed out, "self time" seems important to find out which import is actually costly.

Personally, I have already found this very useful when working on our large monorepo. It lets me find bottnecks in testing and optimize the imports.

Can you explain what kind of patterns you saw and how you optimized it?

Also I wonder how you got the data with current Vitest. Did you patch it? Technically this seems possible on user land with custom runner. I just made this based on your PR https://stackblitz.com/edit/vitest-dev-vitest-8mxc882g?file=runner.ts

// runner.ts
import type { RunnerTestFile } from 'vitest';
import type { VitestRunner } from 'vitest/suite';
import { VitestTestRunner } from 'vitest/runners';

class CustomRunner extends VitestTestRunner implements VitestRunner {
  onCollectStart(file: RunnerTestFile): void {
    super.onCollectStart(file);

    const stats: Record<string, number> = {};
    (file.meta as any).runModuleStats = stats;  // pass data to reporter via "meta"
    const executor = (this as any).__vitest_executor;
    const runModule = executor.runModule;
    executor.runModule = async function (this: any, ...args: any[]) {
      const start = performance.now();
      try {
        return await runModule.apply(this, args);
      } finally {
        const end = performance.now();
        stats[args[0].__vite_ssr_import_meta__.url] = end - start;
      }
    };
  }
}

export default CustomRunner;

@sheremet-va
Copy link
Member

sheremet-va commented May 26, 2025

Here is what the reporter looks like on Vitest itself:

Wouldn't it be more useful to sort it as a tree? The test will always be the first since it's the entry point which imports all other files. How do I track actual files that take a lot to load? 🤔 (Maybe I am missing something)

@abrenneke
Copy link
Contributor Author

abrenneke commented May 26, 2025

@hi-ogawa

Tracking runModule sounds interesting, but as you pointed out, "self time" seems important to find out which import is actually costly.

Right, as with normal profiling tools, I've found both total time and self time to be useful at different times. Did you look at the "self-time" addendum I commented?

Can you explain what kind of patterns you saw and how you optimized it?

Sure! The main culprits have generally been:

  1. Barrel files / files with too many imports

Not necessarily files that just export * frombut files that simply have too many concerns and thus, too many imports/exports. For example

import { dep1 } from 'dep1';
import { dep2 } from 'dep2';

export const something1 = something(dep1);
export const something2 = something(dep2);

Means that you pay the price of loading dep1 and dep2 even if you only need one of these thing. Actual index.ts barrel files are even worse, and Vitest suffers greatly from them. I'm working on a whole blog post about a Vitest transformer that avoids these barrel files. The solution here is avoiding barrel files, and splitting files up into smaller pieces that only focus on one thing at a time. Vitest is flat-out slower than Jest without doing a bunch of work, unfortunately - do you want me to open an issue about that?

  1. Large external tree-shaken dependencies

Talking about your lodash-es and your date-fns - these are large packages that generally get tree-shaken by bundlers in the end. However they don't get tree-shaken by Vitest and the entire import cost is paid. The solution here is to do the direct imports of

import { isEqual } from 'lodash-es/isEqual';
import { isAfter } from 'date-fns/isAfter';
  1. Large external dependencies

There are many dependencies that simply have a huge import cost when loaded. Talking about you, @google-cloud. Switching these to a dynamic import to only load the package when it's actually needed speeds things up a bunch.

Also I wonder how you got the data with current Vitest. Did you patch it?

I mean, I forked Vitest then made changes to it? Not really sure what you're looking for... Do you mean how did I hook the forked Vitest up to our code?

Technically this seems possible on user land with custom runner. I just made this based on your PR

I'm not sure I personally consider monkey-patching a private internal of Vitest to be "user-land" but that's definitely more self-contained than what I have! If this PR is a dead-end I'll definitely go with that approach rather than a fork.

@sheremet-va

Wouldn't it be more useful to sort it as a tree? The test will always be the first since it's the entry point which imports all other files. How do I track actual files that take a lot to load? 🤔 (Maybe I am missing something)

Well it works when you run multiple test files too, so it's not a single tree. Loading modules can be cyclic too, so it's not even a DAG that can be rendered, it's a freeform graph. Module loading time is unfortunately not as "clean" as stack frames. vitest --ui handles this as well as it can. Which is to say, not so well for us:

image

@abrenneke
Copy link
Contributor Author

For the curious, vitest's own tests ordered by self time

image

@hi-ogawa
Copy link
Contributor

@abrenneke Thanks for providing the details. I understand that those 3 patterns are common culprits, but what I'm curious about is how you ended up identifying such patterns based on the report. For example, I think externalized dependencies like lodash-es and @google-cloud won't directly show up on the report. Also when you have a long import chain like example.test.ts -> my-service.ts -> my-util.ts -> @google-cloud, "total time" report shows the cost of @google-cloud included in all import ancestors, so I'm wondering whether the report make it obvious that @google-cloud is the culprit.

I'm not doubting the usefulness as a starting point of profiling, but I'm just curious how much this report provides clear actionable data and whether "total time" is useful enough or providing "self time" is crucial. 🤔

@abrenneke
Copy link
Contributor Author

abrenneke commented May 26, 2025

I see, sorry for the misunderstanding. Self time was indeed necessary to find 2 and 3 it was a matter of deducing or guessing which externalized imports were the problem from the high self time files. But total time pointed directly at the barrel files for number 1. So you're right that total time on its own is less useful.

If self time is important I can get it included in this PR like my other branch has. But if you think this all should just be a third party package I'll just go down that route instead.

@sheremet-va
Copy link
Member

I really like this idea, but I am not sure if it should be a separate reporter. I think it might always be useful to print the list of files after the test run is finished (can have a flag to disable/enable). I also think we can add this information to testModule.diagnostic() for public use.

In nonTTY mode we can just print a list of N-files (how do we know how many?) after the test run is finished. And in watch mode we can have a line like Found N files that took longer than S seconds. To see the list of files, press O (or any other letter we decide). In verbose reporter we can even print a list of files after every test file (in nonTTY mode)

@AriPerkkio
Copy link
Member

Can we get this to work on browser-mode too, or will it be just vite-node specific option?

@abrenneke
Copy link
Contributor Author

Sounds cool! How about I split this into two PRs: one to internally track the total and self time, then another we can figure out reporting?

@abrenneke
Copy link
Contributor Author

abrenneke commented May 27, 2025

@AriPerkkio since the browser mode just uses the browser's own import, it's going to be a lot more tricky to calculate this stuff. Do you think we could put that off for later?

One feasible approach might be to transform this file:

index.ts

import { dep1 } from 'dep1';

dep1();

into two files:

index.ts

import { importsDone, codeDone } from 'some-vitest-generated-url?index.ts"
import { dep1 } from 'dep1';
importsDone();
dep1();
codeDone();

some-vitest-generated-url?index.ts

const start = performance.now();

export function importsDone() {
  // Send metrics back to the node server for "performance.now() - start"
}

export function codeDone() {
  // Send metrics back to the node server for "performance.now() - start"
}

And then reassemble all the timings on the node server side.

But I'm just spitballing on an approach. It would double the number of files the browser loads, which isn't great at all. The problem is we can't really hoist anything above the imports, right?

Or maybe we could utilize vi.hoisted to calculate the start time. Either way, would probably require additional code transforms I'm not too comfortable with at the moment.

@sheremet-va
Copy link
Member

I think browser can wait, we don't even show the transform time at the moment.

@abrenneke abrenneke force-pushed the abrenneke/collect-time-reporter branch from 7a066c1 to 0f11175 Compare May 27, 2025 16:03
@@ -352,6 +352,9 @@ export class VitestExecutor extends ViteNodeRunner {
.importModuleDynamically as any,
} as any)
await fn(...Object.values(context))

// TODO I'm assuming we only need startOffset _after_ the module has finished executing, and not _during_ execution
Copy link
Contributor Author

Choose a reason for hiding this comment

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

If someone could verify this, I couldn't find a conclusion

Copy link
Member

Choose a reason for hiding this comment

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

startOffset is only used for code coverage in result post-processing. That happens after all tests have finished.

Let's wrap this with try { ... } finally {} just to make sure throwing script would still store this info.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Good call. Added a unit test for this too. Thanks for verifying that this can be moved.

@abrenneke abrenneke force-pushed the abrenneke/collect-time-reporter branch from 0f11175 to 29f8840 Compare May 27, 2025 16:05
@abrenneke abrenneke changed the title feat: collect time reporter feat: track module execution totalTime and selfTime May 27, 2025
@abrenneke
Copy link
Contributor Author

@sheremet-va @hi-ogawa @AriPerkkio I've reworked this PR to:

  • Clean up the code
  • Implement self-time tracking
  • Removed the reporter
  • Added unit tests
  • Updated PR description

Now this PR is just the internals for tracking the time, without any of the reporting additions (yet).

Please give it a review!

Copy link
Member

@sheremet-va sheremet-va left a comment

Choose a reason for hiding this comment

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

Looks really good! Just a small note

* Returns a function to call once the module has finished executing.
*/
protected startCalculateModuleExecutionInfo(filename: string, startOffset: number): () => ModuleExecutionInfoEntry {
const startTime = performance.now()
Copy link
Member

Choose a reason for hiding this comment

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

performance can be mocked, we need to store the now function

Copy link
Contributor Author

Choose a reason for hiding this comment

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

oh good catch

const root = resolve(__dirname, '..', 'fixtures')

it('should populate importDurations on File with import durations during execution', async () => {
const reporter = new ImportDurationsReporter()
Copy link
Member

Choose a reason for hiding this comment

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

You don't really need a separate reporter. runVitest returns vitest and you can access all finished tests in vitest.state.getFiles()

Copy link
Contributor Author

Choose a reason for hiding this comment

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

perfect thanks!

Copy link
Member

@sheremet-va sheremet-va left a comment

Choose a reason for hiding this comment

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

Almost forgot, but we also need to expose this here:

export interface ModuleDiagnostic {

And have this in the API documentation (one line and a small comment should be enough)

interface ModuleDiagnostic {

@@ -239,6 +248,9 @@ export interface File extends Suite {
* @internal
*/
local?: boolean

/** The time spent importing every dependency that Vitest has processed. */
importDurations?: Record<string, { selfTime: number; totalTime: number }>
Copy link
Member

Choose a reason for hiding this comment

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

Suggested change
importDurations?: Record<string, { selfTime: number; totalTime: number }>
importDurations?: Record<string, ImportDuration>

@abrenneke abrenneke requested a review from sheremet-va May 27, 2025 18:36
@abrenneke abrenneke force-pushed the abrenneke/collect-time-reporter branch 3 times, most recently from ba006d2 to 44a98d5 Compare May 27, 2025 19:49
Copy link
Member

@sheremet-va sheremet-va left a comment

Choose a reason for hiding this comment

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

Last touches!

@@ -5,6 +5,7 @@ import type {
Suite as RunnerTestSuite,
TaskMeta,
} from '@vitest/runner'
import type { ImportDuration } from '@vitest/runner/types/tasks'
Copy link
Member

Choose a reason for hiding this comment

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

ImportDuration needs to be exported from the @vitest/runner entry point manually, types/tasks doesn't exist at runtime

It should also be re-exported from public/index.ts

Copy link
Contributor Author

@abrenneke abrenneke May 27, 2025

Choose a reason for hiding this comment

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

done, auto-import got me here

@abrenneke abrenneke force-pushed the abrenneke/collect-time-reporter branch from 44a98d5 to 7ebe548 Compare May 27, 2025 20:53
@abrenneke abrenneke requested a review from sheremet-va May 27, 2025 20:54
@abrenneke
Copy link
Contributor Author

oh I think I need to fix something for CI too

@abrenneke
Copy link
Contributor Author

abrenneke commented May 27, 2025

ha I accidentally used (iterator).map because I'm on Node 24 - I wonder why TS isn't complaining about that

edit: oh it's because you have "lib": ["esnext"] in the base tsconfig - you might want to lock that down if you want support down to Node 18. It looks like ES2022 accomplishes that according to node.green

@abrenneke abrenneke force-pushed the abrenneke/collect-time-reporter branch 2 times, most recently from d358787 to 1f26eda Compare May 27, 2025 21:19
Copy link

pkg-pr-new bot commented May 28, 2025

@vitest/browser

npm i https://pkg.pr.new/@vitest/browser@8027

@vitest/coverage-istanbul

npm i https://pkg.pr.new/@vitest/coverage-istanbul@8027

@vitest/coverage-v8

npm i https://pkg.pr.new/@vitest/coverage-v8@8027

@vitest/expect

npm i https://pkg.pr.new/@vitest/expect@8027

@vitest/mocker

npm i https://pkg.pr.new/@vitest/mocker@8027

@vitest/pretty-format

npm i https://pkg.pr.new/@vitest/pretty-format@8027

@vitest/runner

npm i https://pkg.pr.new/@vitest/runner@8027

@vitest/snapshot

npm i https://pkg.pr.new/@vitest/snapshot@8027

@vitest/spy

npm i https://pkg.pr.new/@vitest/spy@8027

@vitest/ui

npm i https://pkg.pr.new/@vitest/ui@8027

@vitest/utils

npm i https://pkg.pr.new/@vitest/utils@8027

vite-node

npm i https://pkg.pr.new/vite-node@8027

vitest

npm i https://pkg.pr.new/vitest@8027

@vitest/web-worker

npm i https://pkg.pr.new/@vitest/web-worker@8027

@vitest/ws-client

npm i https://pkg.pr.new/@vitest/ws-client@8027

commit: 70ea55f

Comment on lines +57 to +60
const durations = runner.getImportDurations?.()
if (durations) {
file.importDurations = durations
}
Copy link
Contributor

@hi-ogawa hi-ogawa May 28, 2025

Choose a reason for hiding this comment

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

Shouldn't we delay collecting this after test execution? Otherwise, I think this misses dynamic import executed during tests. Example https://stackblitz.com/edit/vitest-dev-vitest-335d17yc?file=src%2Fbasic.test.ts

import { test } from 'vitest';

test('repro', async () => {
  const repro = await import('./repro.js');
  console.log(repro);
});
{
  name: '/home/projects/vitest-dev-vitest-xjhmmyxv/src/basic.test.ts',
  importDurations: {
    '/@vite/env': { selfTime: 1.6350000000002183, totalTime: 1.6350000000002183 },
    '/home/projects/vitest-dev-vitest-xjhmmyxv/src/basic.test.ts': { selfTime: 6.535001000000193, totalTime: 6.535001000000193 }
  }
}

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Hm, do we want to track that though? I agree that it's "import time" but it's not really "collect time" - collect has already finished at this point, and if your test has a slow import that will be reported as a slow test already...

Copy link
Contributor

Choose a reason for hiding this comment

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

That's a good point. In terms of "collect time" debugging tool, we might not need this, but yeah the naming importDurations confused me. It's not a blocker for me whether we should change this or not. Perhaps we could add another flag { selfTime, totalTime, collect: boolean }, so the reporter can filter out the cost outside of collect time.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I tried your suggestion for a bit, but piping through whether an import is during the collect phase or not seemed like a bit much for this PR. Perhaps a followup? Or I could rename a bunch of stuff to collectImportDurations so it's not ambiguous

Copy link
Contributor

@hi-ogawa hi-ogawa left a comment

Choose a reason for hiding this comment

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

Great work! I put cr-tracked label so I can provide my examples on stackblitz.

@abrenneke
Copy link
Contributor Author

I'm a bit stumped on the CI tests failing, they seem to work locally for me?

@hi-ogawa
Copy link
Contributor

I'm a bit stumped on the CI tests failing, they seem to work locally for me?

pnpm -C test/reporters test html should show the error locally. The existing snapshot is expecting the data without importDurations property, so it's failing. The stats are non-deterministic between runs, so we can redact it by adding file.importDurations = {} here

const file = resultJson.files[0]
file.id = 0
file.collectDuration = 0
file.environmentLoad = 0
file.prepareDuration = 0
file.setupDuration = 0
file.result.duration = 0
file.result.startTime = 0
const task = file.tasks[0]
task.id = 0
task.result.duration = 0
task.result.startTime = 0
expect(task.result.errors).not.toBeDefined()
expect(task.result.logs).not.toBeDefined()
expect(resultJson).toMatchSnapshot(`tests are ${expected}`)

@abrenneke abrenneke force-pushed the abrenneke/collect-time-reporter branch 2 times, most recently from 86cf156 to f599420 Compare May 28, 2025 06:36
@abrenneke abrenneke force-pushed the abrenneke/collect-time-reporter branch from f599420 to 70ea55f Compare May 28, 2025 06:48
@abrenneke
Copy link
Contributor Author

Alright, all tests green :) (except for a windows webdriverio one that seems to be failing on other branches as well)

@sheremet-va sheremet-va merged commit 95961e4 into vitest-dev:main May 29, 2025
13 of 14 checks passed
@kirillgroshkov
Copy link

Is there a way to use this collect reporter now?
I tried to scan through the changed files in this PR, but haven't found a way to "enable it" 🙏

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants