-
-
Notifications
You must be signed in to change notification settings - Fork 1.4k
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
feat: track module execution totalTime and selfTime #8027
Conversation
✅ Deploy Preview for vitest-dev ready!Built without sensitive environment variables
To edit notification comments on pull requests, go to your Netlify project configuration. |
packages/vite-node/src/client.ts
Outdated
const fn = vm.runInThisContext(code, options) | ||
await fn(...Object.values(context)) | ||
|
||
this.options.moduleExecutionInfo?.set(options.filename, { startOffset: codeDefinition.length, duration: performance.now() - start }) |
There was a problem hiding this comment.
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
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) |
Tracking
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; |
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 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 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. 🤔 |
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. |
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 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 |
Can we get this to work on browser-mode too, or will it be just vite-node specific option? |
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? |
@AriPerkkio since the browser mode just uses the browser's own One feasible approach might be to transform this file:
import { dep1 } from 'dep1';
dep1(); into two files:
import { importsDone, codeDone } from 'some-vitest-generated-url?index.ts"
import { dep1 } from 'dep1';
importsDone();
dep1();
codeDone();
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 Or maybe we could utilize |
I think browser can wait, we don't even show the transform time at the moment. |
7a066c1
to
0f11175
Compare
@@ -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 |
There was a problem hiding this comment.
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
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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.
0f11175
to
29f8840
Compare
@sheremet-va @hi-ogawa @AriPerkkio I've reworked this PR to:
Now this PR is just the internals for tracking the time, without any of the reporting additions (yet). Please give it a review! |
There was a problem hiding this 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
packages/vite-node/src/client.ts
Outdated
* Returns a function to call once the module has finished executing. | ||
*/ | ||
protected startCalculateModuleExecutionInfo(filename: string, startOffset: number): () => ModuleExecutionInfoEntry { | ||
const startTime = performance.now() |
There was a problem hiding this comment.
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
There was a problem hiding this comment.
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() |
There was a problem hiding this comment.
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()
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
perfect thanks!
There was a problem hiding this 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)
vitest/docs/advanced/api/test-module.md
Line 71 in 69ca425
interface ModuleDiagnostic { |
packages/runner/src/types/tasks.ts
Outdated
@@ -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 }> |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
importDurations?: Record<string, { selfTime: number; totalTime: number }> | |
importDurations?: Record<string, ImportDuration> |
ba006d2
to
44a98d5
Compare
There was a problem hiding this 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' |
There was a problem hiding this comment.
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
There was a problem hiding this comment.
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
44a98d5
to
7ebe548
Compare
oh I think I need to fix something for CI too |
ha I accidentally used edit: oh it's because you have |
d358787
to
1f26eda
Compare
@vitest/browser
@vitest/coverage-istanbul
@vitest/coverage-v8
@vitest/expect
@vitest/mocker
@vitest/pretty-format
@vitest/runner
@vitest/snapshot
@vitest/spy
@vitest/ui
@vitest/utils
vite-node
vitest
@vitest/web-worker
@vitest/ws-client
commit: |
const durations = runner.getImportDurations?.() | ||
if (durations) { | ||
file.importDurations = durations | ||
} |
There was a problem hiding this comment.
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 }
}
}
There was a problem hiding this comment.
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...
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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
There was a problem hiding this 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.
I'm a bit stumped on the CI tests failing, they seem to work locally for me? |
vitest/test/reporters/tests/html.test.ts Lines 24 to 38 in 07a411b
|
86cf156
to
f599420
Compare
f599420
to
70ea55f
Compare
Alright, all tests green :) (except for a windows webdriverio one that seems to be failing on other branches as well) |
Is there a way to use this collect reporter now? |
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.This will help in the future for adding to existing reporters, or deeply integrating into existing reporters.
This adds a new
importDurations
property to theFile
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:
pnpm-lock.yaml
unless you introduce a new test example.Tests
pnpm test:ci
.Documentation
pnpm run docs
command.Changesets
feat:
,fix:
,perf:
,docs:
, orchore:
.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:
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:
pnpm-lock.yaml
unless you introduce a new test example.Tests
pnpm test:ci
.Documentation
pnpm run docs
command.Changesets
feat:
,fix:
,perf:
,docs:
, orchore:
.