microsoft / typescript-analyze-trace

A tool for analyzing the output of `tsc --generateTrace`

@typescript/analyze-trace

@typescript/analyze-trace is tool for analyzing the output of tsc --generateTrace in a fast and digestible way (rather than more involved diagnostics here).

Note: The goal is to identify clear-cut hot-spots and provide enough context to extract a small repro. The repro can then be used as the basis of a bug report or a starting point for manual code inspection or profiling.

Usage

The short version is to run these commands:

tsc -p path/to/tsconfig.json --generateTrace traceDir
npm install --no-save @typescript/analyze-trace
npx analyze-trace traceDir

Each of these commands do the following:

1. Building your project with --generateTrace targeting a specific directory (e.g.tsc -p path/to/tsconfig.json --generateTrace traceDir) will create a new traceDir directory with paired trace and types files. Note that running with -b/--build mode works as well.
2. Installing @typescript/analyze-trace makes its various commands available in your project.
3. Running npx analyze-trace traceDir outputs a sorted list of compilation hot-spots - places where TypeScript is taking a high amount of time.

The analyzer tries to refer back to files from your project to provide better output, and uses relative paths to do so. If your project changed since running tsc --generateTrace, or you moved your trace output directory, then the tool's results may be misleading. For best results, re-run --generateTrace when files and dependencies are updated, and ensure the trace output is always in the same relative location with respect to the input project.

You can run npx analyze-trace --help to find out about other options including:

Option	Default	Description
--skipMillis [number]	100	Suppress events that take less than the specified number of milliseconds. Reduce this value to see more output (maybe on faster machines), and increase it to reduce clutter.
--forceMillis [number]	500	Report all un-skipped events that take longer than the specified number of milliseconds. Reduce it to reveal more potential hot-spots that the built-in heuristic will not flag. Note that forceMillis is always lower-bounded by skipMillis.
--color [boolean]	true	Color the output to make it easier to read. Turn this off when redirecting output to a file.
--expandTypes [boolean]	true	Expand the names of types when printing them. Turn this off when types are too verbose.
--json [boolean]	false	Experimental and unstable: Produce JSON output for programmatic consumption.

For a simplified view of a types.json file (useful when investigating an individual trace), you can run npx simplify-trace-types traceDir/types.json output.txt. Note that the resulting file is for human consumption and should not be passed to the analyzer (i.e. don't clobber the original).

Interpreting Results

The analyze-trace output will try to highlight the most expensive portions of a compilation that it was able to measure (a.k.a. "hot spots"). Each hot spot may have a breakdown of other contributing hot spots.

Hot Spots

analyze-trace will also try to point out when multiple versions of the same npm package were loaded and type-checked.

Output may look like the following:

Hot Spots
├─ Check file /some/sample/project/node_modules/typescript/lib/lib.dom.d.ts (899ms)
├─ Check file /some/sample/project/node_modules/@types/lodash/common/common.d.ts (530ms)
│  └─ Compare types 50638 and 50640 (511ms)
│     └─ Compare types 50643 and 50642 (511ms)
│        └─ Compare types 50648 and 50644 (511ms)
│           └─ Determine variance of type 50492 (511ms)
│              └─ Compare types 50652 and 50651 (501ms)
|                 └─ ...
├─ Check file /some/sample/project/node_modules/@types/babel__traverse/index.d.ts (511ms)
└─ Check file /some/sample/project/node_modules/@types/react/index.d.ts (507ms)

Each step here is annotated with check times (e.g. checking two types in lodash took over 500ms).

Some common messages include the following:

Message	Explanation
"Compare types 1234 and 5678"	TypeScript had to check whether two types with internal IDs 1234 and 5678 were related.
"Determine variance of type 1234"	TypeScript had to check whether a Foo<T> was compatible with a Foo<U>. Instead of calculating all the members of Foo<T> and Foo<U> and comparing them, calculating variance allows TypeScript to know whether in such cases, it can just relate T to U, or U to T. Variance calculation requires a few up-front comparisons to possibly save all future ones.
"Emit declaration file"	Generating the declaration file for the current file took a while.
"Consider adding import "./some/import/path" which is used in 1234 places"	TypeScript's --declaration emit needed to generate 1234 imports for ./some/import/path. Consider directly importing this path so the type-checker can avoid emitting the same path over and over in the declaration file. Also consider using explicit type annotations so the type-checker can avoid time calculating the best path to a module and how to best display the type at all.

Other messages correspond roughly to specific functions in the compiler, but are typically self-explanatory.

File names will be the first indicators of where to look. Often, type IDs are used in place of more precise (but often verbose) type names, regardless of whether --expandTypes is on. The types.json file will provide a way to look these up.

Duplicate Packages

analyze-trace will point out instances of duplicate packages in node_modules. These can be caused by multiple projects in a mono-repo that use different versions of the same package, or possibly from dependencies in node_modules that all specify different versions a library.

Duplicate packages may or may not be expected, but loading up multiple copies of a library can have negative effects on a build. For one, they add more time to TypeScript's parsing, binding, and possibly checking stages. Beyond that, duplicate copies of the same types may end up being passed around and compared to each other. Because these types don't share the same root identities, fewer optimizations can be made around them.

Acting on Results

Hot Spots

Once you've found the "culprit" code that's making your build slow, try to create a minimal version of this code to isolate the issue and experiment. In some cases you can try to rewrite or simplify your code, and our team has a few suggestions for common issues here. If culprit code occurs in a library, it may be worth filing an issue with that library or sending a pull request to provide simplifications.

If you believe you have a minimal isolated reproduction of the issue that might be worth optimizing in TypeScript itself, you are encouraged to file an issue.

Duplicate Packages

Updating projects within your monorepo to share the same dependencies may be one way to fix this issue. Updating your dependencies may be another, though it won't always be the case that the most up-to-date versions of your dependencies list their dependencies in a compatible way. If libraries you consume cannot be updated to list compatible dependency ranges, consider using overrides in package.json for npm or for pnpm, or resolutions in package.json for Yarn.

Iterating on Results

You may want to tweak the --skipMillis and --forceMillis options to uncover hot spots that analyze-trace may not reveal.

You may also want to try visualizing a performance trace) for a more detailed view. Iterating between the analyze-trace tool and an interactive visualizer might be a helpful workflow.

Reading up further on the TypeScript compiler's performance diagnostics page may provide ideas and options for your team as well.

Trademarks

This project may contain trademarks or logos for projects, products, or services. Authorized use of Microsoft trademarks or logos is subject to and must follow Microsoft's Trademark & Brand Guidelines. Use of Microsoft trademarks or logos in modified versions of this project must not cause confusion or imply Microsoft sponsorship. Any use of third-party trademarks or logos are subject to those third-party's policies.

typescript-analyze-trace's Issues

output can break if data is too big

Something here is breaking, because it's cutting off our output.

    return new Promise<ProjectResult>(resolve => {
        const child = cp.fork(path.join(__dirname, "analyze-trace-file"), args, { stdio: "pipe" });

        let stdout = "";
        let stderr = "";

        child.stdout!.on("data", chunk => stdout += chunk);
        child.stderr!.on("data", chunk => stderr += chunk);

        child.on("exit", (code, signal) => {
            resolve({
                project,
                stdout: stdout.trim(),
                stderr: stderr.trim(),
                exitCode: code ?? undefined,
                signal: signal ?? undefined,
            });
        });
    });

If we run analyze-trace-file on the command line with the same arguments it works fine.

I tried setting maxBuffer but that's not an option for fork, and even if I changed it to exec it still fails with the same problem.

This is what it looks like when the output gets cut off. Maybe exit is being fired before all of on('data') had a chance to fire?

Consider stopping at the last getVariancesWorker frame

structuredTypeRelatedTo is confusing within a variance check - it would probably make more sense to just pretty-print the type being variance checked.

Make README instructions more digestible

With a bit of time, someone using this tool can probably figure out what commands to run - but if we could make it clearer from a quick glance to

just run this!

with codeblocks and and headings and the like, we can make the process feel less overwhelming.

Add baseline tests

Matrix:

• file vs dir
• types (un)available
• source (un)available
• json vs text

It needs to be possible to diff against the old baseline and accept the new baseline.

The biggest obstacle is likely to be source file lookup - real traces use absolute paths, but those won't be portable (e.g. to CI machines). Post-processing the trace files (i.e. test cases) to use forward-slash-delimited relative paths might suffice.

Support JSON output

Hi!

First, thanks for this tool !
I've tried to use it on a very big project to find hot spots.
Here is an example of output:

Hot Spots
├─ Check file �[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\abtestingtabs\�[36mabtestdashboard.ts�[39m�[35m�[39m (2316ms)
│  └─ Check variable declaration from (line 164, char 11) to (line 164, char 51) (1909ms)
│     └─ Check expression from (line 164, char 21) to (line 164, char 51) (1909ms)
│        └─ Determine variance of type 13937 (1908ms)
│           ├─ Compare types 20107 and 20106 (1074ms)
│           │  └─ Compare types 20191 and 20190 (1064ms)
│           │     └─ Compare types 20197 and 20198 (1064ms)
│           │        └─ Determine variance of type 20192 (1064ms)
│           │           └─ Compare types 20200 and 20199 (1048ms)
│           │              └─ Compare types 20203 and 20202 (1048ms)
│           │                 └─ Compare types 20214 and 20213 (1047ms)
│           │                    └─ Determine variance of type 20208 (1046ms)
│           │                       └─ Compare types 24092 and 24091 (748ms)
│           │                          └─ Compare types 24290 and 24289 (708ms)
│           │                             └─ Check expression from (line 177, char 2) to (line 177, char 2) (708ms)
│           │                                └─ Determine variance of type 14841 (706ms)
│           │                                   └─ {"id":14841,"kind":"GenericType","name":"ButtonProperties","typeArguments":[14842,14843,14844,14845,14846,14847,14848,14849,14850,14851],"location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mbutton.ts�[39m�[35m�[39m","line":20,"char":1}}
│           │                                      ├─ {"id":14842,"kind":"TypeParameter","name":"K","location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mbutton.ts�[39m�[35m�[39m","line":20,"char":35}}
│           │                                      ├─ {"id":14843,"kind":"TypeParameter","name":"S","location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mbutton.ts�[39m�[35m�[39m","line":20,"char":48}}
│           │                                      ├─ {"id":14844,"kind":"TypeParameter","name":"KText","location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mbutton.ts�[39m�[35m�[39m","line":20,"char":61}}
│           │                                      ├─ {"id":14845,"kind":"TypeParameter","name":"SText","location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mbutton.ts�[39m�[35m�[39m","line":20,"char":78}}
│           │                                      ├─ {"id":14846,"kind":"TypeParameter","name":"KIcon","location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mbutton.ts�[39m�[35m�[39m","line":20,"char":95}}
│           │                                      ├─ {"id":14847,"kind":"TypeParameter","name":"SIcon","location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mbutton.ts�[39m�[35m�[39m","line":20,"char":112}}
│           │                                      ├─ {"id":14848,"kind":"TypeParameter","name":"KImage","location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mbutton.ts�[39m�[35m�[39m","line":20,"char":129}}
│           │                                      ├─ {"id":14849,"kind":"TypeParameter","name":"SImage","location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mbutton.ts�[39m�[35m�[39m","line":20,"char":147}}
│           │                                      ├─ {"id":14850,"kind":"TypeParameter","name":"KAnimated","location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mbutton.ts�[39m�[35m�[39m","line":20,"char":165}}
│           │                                      └─ {"id":14851,"kind":"TypeParameter","name":"SAnimated","location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mbutton.ts�[39m�[35m�[39m","line":20,"char":186}}
│           └─ Compare types 35048 and 35047 (834ms)
│              └─ Compare types 35074 and 35073 (650ms)
│                 └─ Compare types 35077 and 35076 (650ms)
│                    └─ Compare types 35080 and 35079 (649ms)
│                       └─ Determine variance of type 14166 (648ms)
│                          └─ Compare types 35101 and 35100 (556ms)
│                             └─ Compare types 35132 and 35131 (546ms)
│                                └─ Compare types 35136 and 35134 (546ms)
│                                   └─ Compare types 35135 and 35133 (546ms)
│                                      └─ Compare types 35107 and 35102 (545ms)
│                                         └─ Determine variance of type 35081 (545ms)
│                                            └─ Compare types 36320 and 36319 (421ms)
│                                               └─ Compare types 36360 and 36356 (408ms)
│                                                  └─ Compare types 36357 and 36353 (295ms)
│                                                     └─ Determine variance of type 35199 (295ms)
│                                                        └─ Compare types 36397 and 36396 (225ms)
│                                                           └─ Compare types 36422 and 36421 (221ms)
│                                                              └─ Compare types 36435 and 36433 (220ms)
│                                                                 └─ Compare types 36434 and 36432 (220ms)
│                                                                    └─ Compare types 36407 and 36400 (218ms)
│                                                                       └─ Determine variance of type 36375 (218ms)
│                                                                          └─ {"id":36375,"kind":"GenericType","name":"HeaderProperties","typeArguments":[36376,36377,36378,36379,36380,36381,36382,36383,36384,36385],"location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mheader.ts�[39m�[35m�[39m","line":20,"char":1}}
│                                                                             ├─ {"id":36376,"kind":"TypeParameter","name":"K","location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mheader.ts�[39m�[35m�[39m","line":20,"char":35}}
│                                                                             ├─ {"id":36377,"kind":"TypeParameter","name":"S","location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mheader.ts�[39m�[35m�[39m","line":20,"char":43}}
│                                                                             ├─ {"id":36378,"kind":"TypeParameter","name":"KSubHeader","location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mheader.ts�[39m�[35m�[39m","line":20,"char":51}}
│                                                                             ├─ {"id":36379,"kind":"TypeParameter","name":"SSubHeader","location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mheader.ts�[39m�[35m�[39m","line":20,"char":68}}
│                                                                             ├─ {"id":36380,"kind":"TypeParameter","name":"KIcon","location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mheader.ts�[39m�[35m�[39m","line":20,"char":85}}
│                                                                             ├─ {"id":36381,"kind":"TypeParameter","name":"SIcon","location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mheader.ts�[39m�[35m�[39m","line":20,"char":97}}
│                                                                             ├─ {"id":36382,"kind":"TypeParameter","name":"KImage","location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mheader.ts�[39m�[35m�[39m","line":20,"char":109}}
│                                                                             ├─ {"id":36383,"kind":"TypeParameter","name":"SImage","location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mheader.ts�[39m�[35m�[39m","line":20,"char":122}}
│                                                                             ├─ {"id":36384,"kind":"TypeParameter","name":"KText","location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mheader.ts�[39m�[35m�[39m","line":20,"char":135}}
│                                                                             └─ {"id":36385,"kind":"TypeParameter","name":"SText","location":{"path":"�[35md:\workspaces\xlefebvre\customer\royal\middleoffice\sparkowstudio\src\js\components\elements\�[36mheader.ts�[39m�[35m�[39m","line":20,"char":147}}

To find the types in question, i'm using the command simplify-trace-types and search for type ids in generated file. But it's can of tedious to go back and forth between the two files.
Would it be possible to have an option for analyze-trace to inline type names ? and another maybe for their location ? (like it's already done for the leafs of the output).

Maybe something like this:

Feature: Instant Events

It might be interesting to report the stacks in which instant events (esp depth limits) occur (hot stacks only?), but we'd need to find a readable output format.

Consider using another metric than time to check for hot spots

This tool is great, I solved a few problems thanks to it.

So I thought that I would add it as a step of our CI to prevent regressions or adding new performance issues.
But our CI runs on much slower machines than mine so it catches a lot more things.

Isn't there a metric more constant that this tool could be based on to figure out how much typescript has to work and where things could be improved?

request: something like `--watch` mode

It would be helpful if there was something like --watch mode, or documentation for how to do this.

Example workflow:

1. We run analyze-trace ts-trace
2. Oh look, a hot spot!

Analyzed /Users/dylang/project/packages/example/tsconfig.json (trace.65458-188.json)
Hot Spots
└─ Check file /Users/dylang/project/packages/example/slow-type-in-here.js (1739ms)
   └─ Check variable declaration from (line 57, char 7) to (line 62, char 2) (1441ms)
      └─ Check expression from (line 57, char 30) to (line 62, char 2) (1441ms)
         └─ Check expression from (line 57, char 30) to (line 57, char 52) (1438ms)
            └─ Compare types 13361 and 4729 (1249ms)

3. We make a change to try to fix it, and hit save....

This is where this feature request starts.

4. analyze-trace automatically runs again. Fewer files may need to be recompiled so analyze-trace is only showing results from those re-compiles. Feature Request
5. The output from analyze-trace tells us how much faster or slower each change is compared to the previous run. Bonus Feature Request

Guidance on output redirection for Windows

If I try running the trace analyzer with npx analyze-trace --color false > foo.txt, then foo.txt gets something like the following output.

Hot Spots
Γö£ΓöÇ Check file c:\users\Daniel\scratch\ant-design-icons\packages\icons-react\node_modules\typescript\lib\lib.dom.d.ts (816ms)
Γö£ΓöÇ Check file c:\users\Daniel\scratch\ant-design-icons\packages\icons-react\node_modules\@types\babel__traverse\index.d.ts (511ms)
ΓööΓöÇ Check file c:\users\Daniel\scratch\ant-design-icons\packages\icons-react\node_modules\@types\react\index.d.ts (507ms)

instead of the expected box drawing characters

Hot Spots
├─ Check file c:\users\Daniel\scratch\ant-design-icons\packages\icons-react\node_modules\typescript\lib\lib.dom.d.ts (816ms)
├─ Check file c:\users\Daniel\scratch\ant-design-icons\packages\icons-react\node_modules\@types\babel__traverse\index.d.ts (511ms)
└─ Check file c:\users\Daniel\scratch\ant-design-icons\packages\icons-react\node_modules\@types\react\index.d.ts (507ms)

This is apparently because Node.js outputs to UTF8, and PowerShell's redirection functionality (at least the version I'm using, 5.1) thinks it's receiving UTF16. The fix is to set

[Console]::OutputEncoding = [System.Text.UTF8Encoding]::new()

State machine incorrectly treats division as the start of a regex

e.g. in x / y, / y will be classified as a regex (to EOL).

To handle this properly, we'd need a parser - you need to know whether the slash is at the start of an expression. Offsets in the incorrectly classified region will (probably) map to the correct line but an incorrect character position, since trivia skipping rules are different within regexes.

Change exit codes to be more CI friendly

Currently, the tool states

Exits with code 0 if highlights were found, 1 if no highlights were found, and 2 if an error occurred

Using this tool within CI, a non-0 exit code typically causes the job to fail which doesn't feel congruent with "no highlights found" (which to my understanding means there's no noteworthy findings?)

Would it make sense to swap the 0 and 1 exit codes? Or to at least add an argument that swaps them?

TIA

Can normalize-positions exit early once all positions have been normalized?

The naive implementation would be to add a global flag that causes all work to be skipped once it's set. However, it would be nicer if we could find some stream API that caused everything to shut down and/or detach.

feature request: Show source code in the output

Showing the filename and line numbers is helpful, but it means a lot of manually digging when looking for common patterns.

I made another POC. The tree component may need to be fixed or replaced to support new lines.

As a developer using TypeScript, and not somebody developing TypeScript, it might even be more helpful to show less of the internal information, and instead display the results similar to how tsc shows errors.

BEFORE

 {"id":4961,"kind":"GenericTypeAlias","name":"Pick","aliasTypeArguments":[4909,4960],"location":{"path":"/users/dylang/repo/node_modules/typescript/lib/lib.es5.d.ts","line":1578,"char":1}}

AFTER

repo/node_modules/typescript/lib/lib.es5.d.ts:1578:1

1578 type Pick<T, K extends keyof T> = {
     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Feature: Support language service traces

1. There won't be types
2. Events (e.g. program construction) are repeated so aggregation will be required
3. Command information is present

Feature: Emit

Sometimes, emit takes a long time - long enough to outweigh other perf problems. However, it is nearly always proportional to the amount of code to be emitted, so there are rarely hotspots. How can we convey this in a useful way? Ideally, we'd identify a type that could be aliased to shrink the output.

Feature: Program Construction

We can already detect and report program building hot-paths (chiefly in findSourceFile), but the output is confusing. We would need to identify imports with high self time and then report causal chains for those.

Customizable thresholds constants

There are a bunch of constants that govern ultimately how many results are shown:

typescript-analyze-trace/src/analyze-trace-file.ts

Lines 31 to 33 in fbca82e

	const thresholdDuration = 5E5; // microseconds
	const minDuration = 1E5; // microseconds
	const minPercentage = 0.6;

IMHO perhaps those constants should be customizable from the CLI, or even better there should just be a "limit" flag to limit the number of files outputted, which by default could be 10 or even the current essentially "auto" limit.

Was amcasey/ts-analyze-trace#7 from @fabiospampinato

Error reading types file: Cannot create a string longer than 0x1fffffe8 characters

In our monorepo, we have 25k+ TS files, this leads to types.json weighing 700MB+ (trace.json is ~40MB).

It seems that readFile has a limit if 512 MB (0x1fffffe8 characters).

typescript-analyze-trace/src/analyze-trace-file.ts

Lines 286 to 291 in fbca82e

	try {
	const json = await fs.promises.readFile(typesPath, { encoding: "utf-8" });
	typesCache = JSON.parse(json);
	}
	catch (e: any) {
	console.error(`Error reading types file: ${e.message}`);

Was amcasey/ts-analyze-trace#10 from @jakub-g