Build mode explicitly checks file stamps in watch mode rather than using file watcher events

[dko-slapdash]

Bug Report

In a monorepo with composite projects, adding -b slows down the --watch mode reaction time, even when tsc -b --watch is run inside some packages/shared/ project which has 0 references in its tsconfig.json. The compilation time is like 3.4s vs. 0.3s when used without -b on a small sub-project, and is way higher for large projects (or even when tsc -b --watch is executed in the root).

In both of these cases, tsBuildInfoFile is utilized (and successfully updated).

🔎 Search Terms

tsc watch build slow

I found #42960, but not sure it's about the same topic: it says nothing about --build and non-build modes.

🕗 Version & Regression Information

@next 4.4.0-dev.20210716

💻 Code

$ tsc -b --watch --extendedDiagnostics # SLOW

FileWatcher:: Triggered with ...AssetType.ts 1:: WatchInfo: ... Elapsed:: 0.9445369839668274ms ...
[8:20:21 PM] File change detected. Starting incremental compilation...

Files:                        1014
Lines of Library:            27948
Lines of Definitions:       205178
Lines of TypeScript:         15524
Lines of JavaScript:            63
Lines of JSON:                   0
Lines of Other:                  0
Nodes of Library:           119542
Nodes of Definitions:       701795
Nodes of TypeScript:         53084
Nodes of JavaScript:           286
Nodes of JSON:                   0
Nodes of Other:                  0
Identifiers:                297572
Symbols:                    183176
Types:                        1262
Instantiations:                193
Memory used:               293087K
Assignability cache size:      174
Identity cache size:             6
Subtype cache size:             42
Strict subtype cache size:       0
I/O Read time:               0.10s
Parse time:                  1.60s
ResolveModule time:          0.34s
ResolveTypeReference time:   0.11s
Program time:                2.39s
Bind time:                   0.85s
Check time:                  0.09s
transformTime time:          0.03s
commentTime time:            0.01s
printTime time:              0.15s
Emit time:                   0.15s
Source Map time:             0.01s
I/O Write time:              0.00s
Total time:                  3.48s

[8:20:25 PM] Found 0 errors. Watching for file changes.

$ tsc --watch --extendedDiagnostics # FAST

FileWatcher:: Triggered with .../AssetType.ts ... Elapsed:: 0.6002329587936401ms ...
[8:21:50 PM] File change detected. Starting incremental compilation...

Synchronizing program
CreatingProgramWith::
  roots: [".../AppPaywall.ts",".../AppRoutes.ts",...lots of other paths here]
  options: {"composite":true,"incremental":true,"allowJs":true,"skipLibCheck":true,"jsx":2,"module":1,"removeComments":false,"moduleResolution":2,"experimentalDecorators":true,"pretty":true,"noErrorTruncation":true,"resolveJsonModule":true,"sourceMap":true,"declaration":true,"declarationMap":true,"target":6,"esModuleInterop":true,"noImplicitReturns":true,"strict":true,"typeRoots":[".../node_modules/@types",".../packages/shared/@types"],"tsBuildInfoFile":".../packages/shared/dist.tsc/tsconfig.tsbuildinfo","rootDir":".../packages/shared/src","outDir":".../packages/shared/dist.tsc","paths":{},"lib":["lib.es2019.d.ts","lib.dom.d.ts"],"pathsBasePath":".../packages/shared","watch":true,"extendedDiagnostics":true,"configFilePath":".../packages/shared/tsconfig.json"}

Files:                        1014
Lines of Library:            27948
Lines of Definitions:       205178
Lines of TypeScript:         15524
Lines of JavaScript:            63
Lines of JSON:                   0
Lines of Other:                  0
Nodes of Library:           119542
Nodes of Definitions:       701795
Nodes of TypeScript:         53079
Nodes of JavaScript:           286
Nodes of JSON:                   0
Nodes of Other:                  0
Identifiers:                297571
Symbols:                    183175
Types:                        1260
Instantiations:                193
Memory used:               290998K
Assignability cache size:      174
Identity cache size:             6
Subtype cache size:             42
Strict subtype cache size:       0
I/O Read time:               0.00s
Parse time:                  0.01s
ResolveModule time:          0.00s
Program time:                0.03s
Bind time:                   0.01s
Check time:                  0.12s
transformTime time:          0.04s
commentTime time:            0.01s
printTime time:              0.17s
Emit time:                   0.18s
Source Map time:             0.01s
I/O Write time:              0.00s
Total time:                  0.33s

[8:21:51 PM] Found 0 errors. Watching for file changes.

🙁 Actual behavior

tsc -b --watch compiles a single changed file way slower than tsc --watch.

🙂 Expected behavior

They work at comparable speeds.

---

$ cat packages/shared/tsconfig.json
{
  "extends": "../../tsconfig.base.json",
  "include": [
    "src/**/*"
  ],
  "compilerOptions": {
    "composite": true,
    "tsBuildInfoFile": "dist.tsc/tsconfig.tsbuildinfo",
    "rootDir": "src",
    "outDir": "dist.tsc",
    "paths": {},
    "module": "commonjs",
    "lib": [
      "es2019",
      "DOM"
    ],
  }
}

$ cat ./tsconfig.base.json
{
  "compilerOptions": {
    "composite": true,
    "incremental": true,
    "allowJs": true,
    "skipLibCheck": true,
    "jsx": "react",
    "module": "esnext",
    "removeComments": false,
    "moduleResolution": "node",
    "experimentalDecorators": true,
    "pretty": true,
    "noErrorTruncation": true,
    "resolveJsonModule": true,
    "sourceMap": true,
    "declaration": true,
    "declarationMap": true,
    "target": "es2019",
    "esModuleInterop": true,
    "noImplicitReturns": true,
    "strict": true,
    "typeRoots": [
      "./node_modules/@types",
      "./packages/shared/@types"
    ]
  },
}

[DanielRosenwasser]

Thanks for reporting this - would you be able to profile the compiler on both builds? Minimally just with generateCpuProfile? We have instructions on this section of our performance page.

[deftomat]

The same for me. It happens on every project which I tried.

[deftomat]

@DanielRosenwasser You can try it here: https://github.com/deftomat/typescript-build-watch-perf

On my PC, recompilation took 2.5s with -b and 0.3s without it.

Our goal is to be able to run tsc -b -w from the root of the repo to typecheck every package which we have in that monorepo.
Running tsc -w in each monorepo package separately consume too much of RAM and CPU.

However, it is just too slow right now. Larger packages easily took 15s even on small changes.

[dko-slapdash]

@DanielRosenwasser is the repro created by @deftomat helpful here, or you would prefer us to generate some more input? This particular GitHub issue is kinda deal breaker for us... we would love to switch to single-tsc build-watch process for the entire monorepo, but we can't due to this perf aspect, so we have to run one tsc instance for each of inter-dependent projects in the monorepo (more than 5 so far) and suffer from them being watch-rebuilt with errors multiple times (until it finally settles) after pulling from Git, when multiple monorepo projects change at the same time. With -w -b being as fast as -w, this problem would go away and significantly simplify the dev experience.

[DanielRosenwasser]

Sorry for the delay. I (unnecessarily?) spent a bit of time in pprof and basically saw that findSourceFile and parsing were taking a decent amount more time. This should've been obvious from a glance at your original issue.

I tossed a console.log in parseSourceFile and found that it was getting called on every .d.ts in node_modules which I found suspicious. I'm not sure if there's a reason we can't retain source files in node_modules when programs share the same settings in --build --watch scenarios.

[amcasey]

@dko-slapdash Have you tried with 4.4 RC? It includes a bunch of fixes specifically for closing the gap between project-mode and build-mode perf.

[amcasey]

I'd be pretty surprised if #43995 wasn't a factor.

Edit: it's not.

[amcasey]

@deftomat Can you tell me more about your repro steps? Which project are you building when you don't pass -p? I assume it's not the root tsconfig, since that contains 0 files.

Ignoring watch mode for a second, here's what I'm seeing:

typescript-build-watch-perf>npx tsc -p packages\api\tsconfig.json -extendedDiagnostics                    
Files:                        1392
Lines of Library:             8664
Lines of Definitions:       359151
Lines of TypeScript:            70
Lines of JavaScript:             0
Lines of JSON:                   0
Lines of Other:                  0
Nodes of Library:            23282
Nodes of Definitions:       682027
Nodes of TypeScript:           273
Nodes of JavaScript:             0
Nodes of JSON:                   0
Nodes of Other:                  0
Identifiers:                244853
Symbols:                    106616
Types:                          76
Instantiations:                  0
Memory used:               225349K
Assignability cache size:        0
Identity cache size:             0
Subtype cache size:              0
Strict subtype cache size:       0
I/O Read time:               0.18s
Parse time:                  1.67s
ResolveModule time:          0.42s
ResolveTypeReference time:   0.00s
Program time:                2.45s
Bind time:                   0.62s
Total time:                  3.07s

typescript-build-watch-perf>npx tsc -b packages\api\tsconfig.json -extendedDiagnostics 
Files:                        1392
Lines of Library:             8664
Lines of Definitions:       359151
Lines of TypeScript:            70
Lines of JavaScript:             0
Lines of JSON:                   0
Lines of Other:                  0
Nodes of Library:            23282
Nodes of Definitions:       682027
Nodes of TypeScript:           273
Nodes of JavaScript:             0
Nodes of JSON:                   0
Nodes of Other:                  0
Identifiers:                244853
Symbols:                    106616
Types:                          76
Instantiations:                  0
Memory used:               223277K
Assignability cache size:        0
Identity cache size:             0
Subtype cache size:              0
Strict subtype cache size:       0
I/O Read time:               0.18s
Parse time:                  1.73s
ResolveModule time:          0.75s
ResolveTypeReference time:   0.00s
Program time:                2.87s
Bind time:                   0.56s
Total time:                  3.43s

i.e. Build mode is ~10% slower, rather than the 8X you're seeing. This is with 4.5.0-dev.20210813.

Also, you mention "recompilation" - what edit should I be making to see those incremental build times?

Thanks!

Edit: I believe I have a repro, building packages/api with both -b -w and -p -w and editing the constructor signature of ApiStack.

[dko-slapdash]

@dko-slapdash Have you tried with 4.4 RC?

@amcasey Just tried 4.4.0-beta. Still the similar effect. Below is a screencast which illustrates that sitting in a leaf monorepo package, tsc -b --watch takes ~4s to unfreeze after a change (between "file change detected" and , and tsc --watch takes less than a second to unfreeze. By "leaf" I mean that there are no other packages dependent on this one.

Code.-.__git_slapdash_packages_worker_src_lib_worker_indexAppFullJob.ts.mp4

// packages/worker/tsconfig.json
{
  "extends": "../../tsconfig.base.json",
  "include": [
    "src/**/*"
  ],
  "compilerOptions": {
    "tsBuildInfoFile": "dist/tsconfig.tsbuildinfo",
    "rootDir": "src",
    "outDir": "dist",
    "paths": {
      "slapdash-shared/dist/*": [
        "../shared/src/*"
      ],
      "slapdash-server/dist/*": [
        "../server/src/*"
      ],
    },
    "lib": [
      "es2019",
      "esnext.asynciterable",
      "DOM"
    ],
    "module": "commonjs",
  },
  "references": [
    {
      "path": "../shared"
    },
    {
      "path": "../server"
    },
  ]
}

// tsconfig.base.json is the same as mentioned in the initial post

[amcasey]

@dko-slapdash Thanks for the update! I believe I have a reliable repro, so I've already started profiling. Unfortunately, this looks separate from \the issues we fixed in the RC.

[amcasey]

My first impression is that all the extra time is spent on file existence checks. 😢

[xasopheno]

Seeing the same behavior. While this is being investigated, is there a version that does not have this problem?

[deftomat]

@xasopheno I tried a few and they all behave like the latest one.

[amcasey]

I'm pretty sure this isn't new. It looks like regular watch mode is depending on file watchers to catch file changes and build-mode watch is redoing the mtime checks every iteration. An issue like that is generally baked in from the beginning.

[dko-slapdash]

@amcasey You think that the extra time is all explained by file mtime checks? On our end, the difference in --watch mode with and without -b is huge - 3 seconds; I personally doubt that mtime checks for all the files takes extra 3 seconds (we don't have that many of them, only a little over a thousand). Our usecase is very similar to what #45082 (comment) writes about.

[amcasey]

@dko-slapdash It's not just the mtime calls, it's the file system traversal and then the state updates that make up the staleness check. But based on profiling both, my assessment was that, yes, that explains most/all of the extra time.

Out of curiosity, how did you could your mtime checks?

[dko-slapdash]

Out of curiosity, how did you could your mtime checks?

@amcasey Thanks! How did I what, sorry?

[amcasey]

@dko-slapdash How did you count your mtime checks? 🤦

[sledorze]

Seeing the same performance difference.
Some complementary info (maybe another issue): I've noticed that in build mode all files timestamp are updated, whereas in watch mode, only the modified source files have their counterpart timestamp up to date (normal as reemited).

[sledorze]

@amcasey do you think it would be possible, design wise, to get the same speed than watch mode?
(I can see how watching the root might provide a way to consolidate file statuses without rechecking all of those via the file system for instance..)

[amcasey]

@sledorze My intuition is yes, but it's a pretty complex area and it might be an expensive change.

[sledorze]

@amcasey thanks for the reply
That's decouraging teams to use monorepos with tsc; they're using some alternative setup, transpiling via esbuild / swc in ordre to have fast feedback.
In some particular context relying on compiler code transforms (with runtime impact), this transpilers are not enough.

from your answer, do you think it may be scheduled in the mid (if not short) term, knowing the possible impact ?

[amcasey]

@sledorze Sorry for the frustrating experience. I can't make any promises but of course this will be considered as we draw up the iteration plan for the next release.

[DanielRosenwasser]

So when it came to checking file stamps, it was about checking the output file stamps, right? I've opened #46677 as a possible strategy to circumvent this.

[zen0wu]

I believe this is the same issue as #31932

[DanielRosenwasser]

If people here would be willing to try out tomorrow's nightly build, we'd appreciate the feedback!