Watch mode: rebuild takes too long after adding a simple `console.log` to file (~2 minutes)

[OliverJAsh]

Bug Report

🔎 Search Terms

performance, tsc, watch, build, rebuild, declaration, emit, incremental

🕗 Version & Regression Information

This is the behavior in every version I tried, and I reviewed the FAQ for entries about performance.

⏯ Playground Link

Unfortunately I cannot provide a reduced test case as I can only reproduce this on our very large project.

💻 Code

TypeScript 4.1.2

1. Clone and checkout https://github.com/unsplash/unsplash-web/tree/typescript-watch-issue, branch typescript-watch-issue. This is a private repository but I believe some members of the TS team already have access from debugging previous issues. If you don't have access, please send me your email address so I can provide access (TS team members only).
2. Run yarn to install TS
3. Run tsc --build ./tsconfig.json --watch
4. Wait for the first build to complete
5. Go to file app/actions/index.ts and add this line anywhere in the file, e.g. at the very bottom: console.log('foo')
6. Save the changes to trigger tsc to rebuild

🙁 Actual behavior

The rebuild takes too long. On my machine it takes over 2 minutes.

🙂 Expected behavior

I expected the rebuild to be very fast, because we're using all of the performance optimisations at our disposal: e.g. incremental and project references.

---

One thing I noticed that might be helpful for debugging: the generated declaration file for app/actions/index.ts—target-tsc-build/app/actions/index.d.ts—is fairly small after the first build (after step 4) but then for some reason it is significantly larger after the second build (after step 6). I don't understand why these declarations would change after such a simple change.

Subsequent changes to this file do not suffer from this problem, e.g. if we remove the console.log('foo') line that was added in step 5 and then save the changes to trigger another rebuild, the rebuild is very fast.

[OliverJAsh]

I tested this again and the rebuild took closer to 1.5 minutes than 2 minutes (TypeScript 4.1.2).

I then upgraded to TypeScript 4.2 RC and repeated the test, and it seemed like there was no improvement.

I don't know how realistic this is but I would like to see rebuilds in the single digits, especially if I'm just adding a console.log for debugging purposes like in my example above.

[sheetalkamat]

This is because the d.ts emit takes long time.. The project in question C:/temp/unsplash-web/tsconfig.app.json seems to spend lot of time in .d.ts emit and you would need to diagnose which type is causing this and help annotate it.
Checking with @amcasey to see if our profiling tool can help you with that.

Below shows the timings:

[2:49:14 PM] Starting compilation in watch mode...

[2:49:14 PM] Projects in this build:
    * shared/tsconfig.json
    * tsconfig.app.json
    * webpack/tsconfig.json
    * cypress/tsconfig.json
    * build-tracker/tsconfig.json
    * service-worker/tsconfig.json
    * tsconfig.json

[2:49:14 PM] Project 'shared/tsconfig.json' is out of date because output file 'target-tsc-build/shared/api-env.js' does not exist

[2:49:14 PM] Building project 'C:/temp/unsplash-web/shared/tsconfig.json'...

Files:                         498
Lines:                       86589
Nodes:                      440466
Identifiers:                172459
Symbols:                    208442
Types:                       90036
Instantiations:             270050
Memory used:               261562K
Assignability cache size:    13073
Identity cache size:          1379
Subtype cache size:            929
Strict subtype cache size:      53
I/O Read time:               0.10s
Parse time:                  1.28s
ResolveModule time:          0.74s
ResolveTypeReference time:   0.02s
Program time:                2.30s
Bind time:                   0.83s
Check time:                  3.99s
transformTime time:          1.20s
commentTime time:            0.32s
printTime time:              2.65s
Emit time:                   2.66s
Source Map time:             0.08s
I/O Write time:              0.18s
Total time:                  9.78s
[2:49:24 PM] Project 'tsconfig.app.json' is out of date because output file 'target-tsc-build/setup-env-vars.js' does not exist

[2:49:24 PM] Building project 'C:/temp/unsplash-web/tsconfig.app.json'...

Files:                        2304
Lines:                      271633
Nodes:                     1081995
Identifiers:                376118
Symbols:                    829944
Types:                      362773
Instantiations:            1782816
Memory used:               924367K
Assignability cache size:   317066
Identity cache size:         12640
Subtype cache size:          21189
Strict subtype cache size:   51065
I/O Read time:               0.27s
Parse time:                  1.26s
ResolveModule time:          3.60s
ResolveTypeReference time:   0.04s
Program time:                5.84s
Bind time:                   0.74s
Check time:                 28.49s
transformTime time:         86.70s
commentTime time:            9.13s
printTime time:            124.35s
Emit time:                 124.46s
Source Map time:             2.24s
I/O Write time:              3.74s
Total time:                159.54s
[2:52:10 PM] Project 'webpack/tsconfig.json' is out of date because output file 'target-tsc-build/webpack/client.config.js' does not exist

[2:52:10 PM] Building project 'C:/temp/unsplash-web/webpack/tsconfig.json'...

Files:                          317
Lines:                        91119
Nodes:                       437593
Identifiers:                 168473
Symbols:                     162913
Types:                        62147
Instantiations:               65642
Memory used:               1012688K
Assignability cache size:     11352
Identity cache size:             59
Subtype cache size:              47
Strict subtype cache size:       97
ResolveModule time:           0.44s
ResolveTypeReference time:    0.05s
I/O Read time:                0.02s
Parse time:                   0.23s
Program time:                 0.78s
Bind time:                    0.17s
Check time:                   2.36s
transformTime time:           0.03s
commentTime time:             0.03s
printTime time:               0.24s
Emit time:                    0.24s
Source Map time:              0.02s
I/O Write time:               0.01s
Total time:                   3.55s
[2:52:14 PM] Project 'cypress/tsconfig.json' is out of date because output file 'target-tsc-build/cypress/integration/about.test.js' does not exist

[2:52:14 PM] Building project 'C:/temp/unsplash-web/cypress/tsconfig.json'...

Files:                          369
Lines:                       150680
Nodes:                       579199
Identifiers:                 232928
Symbols:                     208554
Types:                        92307
Instantiations:              131663
Memory used:               1188108K
Assignability cache size:     11610
Identity cache size:             84
Subtype cache size:             485
Strict subtype cache size:       32
ResolveModule time:           0.23s
ResolveTypeReference time:    0.03s
I/O Read time:                0.03s
Parse time:                   0.46s
Program time:                 0.80s
Bind time:                    0.20s
Check time:                   3.55s
transformTime time:           0.12s
commentTime time:             0.16s
printTime time:               1.23s
Emit time:                    1.24s
Source Map time:              0.13s
I/O Write time:               0.07s
Total time:                   5.78s
[2:52:22 PM] Project 'build-tracker/tsconfig.json' is out of date because output file 'target-tsc-build/build-tracker/config.js' does not exist

[2:52:22 PM] Building project 'C:/temp/unsplash-web/build-tracker/tsconfig.json'...

Files:                          229
Lines:                        40649
Nodes:                       201041
Identifiers:                  77851
Symbols:                      68195
Types:                        33032
Instantiations:               41225
Memory used:               1236180K
Assignability cache size:      3927
Identity cache size:             21
Subtype cache size:              34
Strict subtype cache size:        1
ResolveModule time:           0.19s
ResolveTypeReference time:    0.01s
I/O Read time:                0.01s
Parse time:                   0.01s
Program time:                 0.24s
Bind time:                    0.01s
Check time:                   1.53s
transformTime time:           0.01s
commentTime time:             0.02s
printTime time:               0.14s
Emit time:                    0.14s
Source Map time:              0.01s
I/O Write time:               0.01s
Total time:                   1.92s
[2:52:24 PM] Project 'service-worker/tsconfig.json' is out of date because output file 'target-tsc-build/service-worker/service-worker.js' does not exist

[2:52:24 PM] Building project 'C:/temp/unsplash-web/service-worker/tsconfig.json'...

Files:                           13
Lines:                        12402
Nodes:                        50116
Identifiers:                  19623
Symbols:                      12673
Types:                         4275
Instantiations:                1441
Memory used:               1240090K
Assignability cache size:       531
Identity cache size:              0
Subtype cache size:               4
Strict subtype cache size:        0
I/O Read time:                0.00s
Parse time:                   0.07s
Program time:                 0.08s
Bind time:                    0.03s
Check time:                   0.21s
transformTime time:           0.00s
commentTime time:             0.01s
printTime time:               0.03s
Emit time:                    0.03s
Source Map time:              0.00s
I/O Write time:               0.00s
Total time:                   0.35s
[2:52:25 PM] Found 0 errors. Watching for file changes.

[2:57:22 PM] File change detected. Starting incremental compilation...

[2:57:23 PM] Project 'tsconfig.app.json' is out of date because oldest output 'target-tsc-build/setup-env-vars.js' is older than newest input 'shared/tsconfig.json'

[2:57:23 PM] Building project 'C:/temp/unsplash-web/tsconfig.app.json'...

[2:59:46 PM] Updating unchanged output timestamps of project 'C:/temp/unsplash-web/tsconfig.app.json'...

Files:                         2304
Lines:                       271633
Nodes:                      1082001
Identifiers:                 376120
Symbols:                     688235
Types:                       252676
Instantiations:             1619352
Memory used:               1180215K
Assignability cache size:    115910
Identity cache size:          11865
Subtype cache size:           19658
Strict subtype cache size:    50671
I/O Read time:                0.39s
Parse time:                   2.03s
ResolveModule time:           4.19s
ResolveTypeReference time:    0.05s
Program time:                 7.40s
Bind time:                    1.16s
Check time:                  26.09s
transformTime time:          90.71s
commentTime time:             4.13s
printTime time:             106.38s
Emit time:                  106.43s
Source Map time:              0.45s
I/O Write time:               0.89s
Total time:                 141.08s
[2:59:47 PM] Found 0 errors. Watching for file changes.

[sheetalkamat]

Just chatted with @amcasey offline and here is the link to analyze the trace https://www.npmjs.com/package/@amcasey/ts-analyze-trace but it might not show anything apart from the fact that d.ts is slow.. He will be looking into improving analysing which type causes slow conversion but thats not yet part of it

[amcasey]

At present, that tool specifically only outputs information about check time. However, it builds on an underlying tracing system that will show tracing time. Unfortunately, it nearly always just shows that many files took a small amount of time each. I've been working on figuring out how to pinpoint problematic input code.

[OliverJAsh]

Do you expect the changes in 4.3 beta (#43314) will help improve this issue at all?

[sheetalkamat]

Don’t think so .. at least for the scenario you shared .. because at some point you do need .d.ts calculation and that’s where the issue lies