Skip to content
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

TypeScript --watch initial compilation several times slower for the same codebase since 2.8 #25018

Closed
devuo opened this issue Jun 16, 2018 · 15 comments
Assignees
Labels
Bug A bug in TypeScript

Comments

@devuo
Copy link

devuo commented Jun 16, 2018

TypeScript Version: 2.9.2, >= 2.8

Search Terms: Slow compilation, Slow watch

Code
The initial watch compilation time issue is not directly reproducible under OSX, and is only manifested when executed under a Docker container. Thus for easier debugging and demonstration of the issue, I've created a repo with all the required code that reproduces the issue and contains additional supporting documentation such as v8 profiling. See the following repository for a reproducible step-by-step instructions and code.

https://github.com/devuo/typescript-slow-watch-bug

Expected behavior:
Initial --watch compilation times should take about the same time the same time as they did in 2.7. Here's how --watch looks like in 2.7 for the codebase referred above:

node_modules/.bin/tsc --watch --extendedDiagnostics

08:31:33 - Starting compilation in watch mode...
Files:                   61
Lines:                62744
Nodes:               273576
Identifiers:          98075
Symbols:              80280
Types:                29130
Memory used:        125488K
I/O Read time:        0.19s
Parse time:           0.77s
Program time:         1.97s
Bind time:            0.48s
Check time:           1.62s
transformTime time:   0.02s
printTime time:       0.02s
Emit time:            0.04s
commentTime time:     0.00s
Source Map time:      0.00s
I/O Write time:       0.01s
Total time:           4.12s
08:31:37 - Compilation complete. Watching for file changes.

Actual behavior:
Initial --watch compilation times for the same codebase take many times under >= 2.8 than they did in 2.7. Exact initial compilation times since 2.8 appears to depend on the number of files being scanned under the root project directory. Here's how --watch looks like in 2.9 for the same codebase above:

node_modules/.bin/tsc --watch --extendedDiagnostics

08:27:10 - Starting compilation in watch mode..
08:27:43 - Found 0 errors. Watching for file changes.
Files:                   61
Lines:                63371
Nodes:               279942
Identifiers:          99371
Symbols:              79865
Types:                30108
Memory used:        140212K
I/O Read time:        0.18s
Parse time:           0.70s
Program time:        30.17s
Bind time:            0.45s
Check time:           1.80s
transformTime time:   0.02s
commentTime time:     0.00s
Source Map time:      0.00s
I/O Write time:       0.01s
printTime time:       0.05s
Emit time:            0.05s
Total time:          32.47s

Here's where 2.9 appears to spend most of its time during a profiling session:

   ticks parent  name
  22067   67.1%  /lib/ld-musl-x86_64.so.1
  15181   68.8%    LazyCompile: *getAccessibleFileSystemEntries /app/node_modules/typescript/lib/tsc.js:3502:52
  15161   99.9%      LazyCompile: ~getAccessibleSortedChildDirectories /app/node_modules/typescript/lib/tsc.js:3303:67
  15161  100.0%        LazyCompile: ~watchChildDirectories /app/node_modules/typescript/lib/tsc.js:3120:39
  15161  100.0%          LazyCompile: ~updateChildWatches /app/node_modules/typescript/lib/tsc.js:3115:36
  15152   99.9%            LazyCompile: ~createDirectoryWatcher /app/node_modules/typescript/lib/tsc.js:3098:40

Compare with 2.7:

   ticks parent  name
   1831   35.4%  /usr/local/bin/node
   1667   91.0%    /usr/local/bin/node
    253   15.2%      LazyCompile: ~directoryExists /app/node_modules/typescript/lib/tsc.js:2766:37
    249   98.4%        LazyCompile: ~directoryExists /app/node_modules/typescript/lib/tsc.js:61964:39
    249  100.0%          LazyCompile: ~directoryExists /app/node_modules/typescript/lib/tsc.js:58876:33
    249  100.0%            LazyCompile: ~compilerHost.directoryExists /app/node_modules/typescript/lib/tsc.js:62085:82

Related Issues: #22953

@nelsonfamorim
Copy link

Can confirm, getting this behaviour as well

@sheetalkamat
Copy link
Member

This seems like a correct change as part of #21243 since we added support for recursive directory watching on OS that werent supported by node. Can you please use tsc --w --extendedDiagnostics with typescript@next and share the result. We can investigate further to decide how to optimize this further from those result.

@devuo
Copy link
Author

devuo commented Jun 18, 2018

Will do, however I cannot comprehend how you can define this as a "correct change", as it made --watch non-useable/broken for development purposes since 2.8 whereas it was until 2.7.

@sheetalkamat
Copy link
Member

It was correct change because thats what will give you right behavior. The issue has various options to try out different kinds of watches on different. There is always scope to do optimize based on user experience.

@devuo
Copy link
Author

devuo commented Jun 18, 2018

typescript 3.0.0-dev.20180616

21:15:10 - Starting compilation in watch mode...

21:15:42 - Found 0 errors. Watching for file changes.
Files:                   67
Lines:                64772
Nodes:               284175
Identifiers:         100872
Symbols:              81598
Types:                30924
Memory used:        147366K
I/O Read time:        0.19s
Parse time:           0.74s
Program time:        29.77s
Bind time:            0.48s
Check time:           1.77s
transformTime time:   0.03s
commentTime time:     0.00s
Source Map time:      0.00s
I/O Write time:       0.01s
printTime time:       0.07s
Emit time:            0.07s
Total time:          32.09s
20847   66.9%  /lib/ld-musl-x86_64.so.1
  14557   69.8%    LazyCompile: *getAccessibleFileSystemEntries /app/node_modules/typescript/lib/tsc.js:2438:52
  14534   99.8%      LazyCompile: ~getAccessibleSortedChildDirectories /app/node_modules/typescript/lib/tsc.js:2238:67
  14534  100.0%        LazyCompile: ~watchChildDirectories /app/node_modules/typescript/lib/tsc.js:2053:39
  14534  100.0%          LazyCompile: ~updateChildWatches /app/node_modules/typescript/lib/tsc.js:2048:36
  14496   99.7%            LazyCompile: ~createDirectoryWatcher /app/node_modules/typescript/lib/tsc.js:2031:40

No difference whatsoever. Updated the repository https://github.com/devuo/typescript-slow-watch-bug with this information. You can use it to reproduce the issue.

@devuo
Copy link
Author

devuo commented Jun 18, 2018

I've also seen it scanning recursively folders like .git, go to the depths of node_modules/ and other folders not specified in include or exclude, I can't see the point of recursively scanning under directories not specified in tsconfig by the authors.

@devuo
Copy link
Author

devuo commented Jun 18, 2018

I also tried to use all the different environment variable values for TSC_WATCHFILE and TSC_WATCHDIRECTORY to no avail and made no difference whatsoever, e.g:

export TSC_WATCHFILE="UseFsEventsOnParentDirectory"
export TSC_WATCHDIRECTORY="RecursiveDirectoryUsingFsWatchFile"

node_modules/.bin/tsc --watch --extendedDiagnostics

[21:38:29] Starting compilation in watch mode...
[21:39:03] Found 0 errors. Watching for file changes.

Files:                   62
Lines:                63379
Nodes:               279962
Identifiers:          99376
Symbols:              79869
Types:                30111
Memory used:        140182K
I/O Read time:        0.19s
Parse time:           0.71s
Program time:        30.35s
Bind time:            0.50s
Check time:           1.79s
transformTime time:   0.04s
commentTime time:     0.01s
Source Map time:      0.00s
I/O Write time:       0.01s
printTime time:       0.09s
Emit time:            0.10s
Total time:          32.74s

@mhegazy mhegazy added the Bug A bug in TypeScript label Jun 19, 2018
@mhegazy mhegazy added this to the TypeScript 3.0 milestone Jun 19, 2018
sheetalkamat added a commit that referenced this issue Jul 5, 2018
sheetalkamat added a commit that referenced this issue Jul 5, 2018
@sheetalkamat
Copy link
Member

@devuo Can you please try typescript@next drop that gets released tonight to see if its any better. PR #25464 should cache the recursive directory watches by reducing the child iteration when watching same or child directory of existing directory watcher.

@devuo
Copy link
Author

devuo commented Jul 12, 2018

There was some improvement (around ~8s in the case of the example codebase I made available for you guys to test and where you can reproduce the behaviour yourselves). However in a bit larger codebase it still takes a whole full minute to start compiling when before it took under 10 seconds.

In any case it still feels weird to me to be creating recursively file/folder watchers for directories excluded or not explicitly included in tsconfig, such as .git/**/* node_modules/**/* etc.

Here's the extendedDiagnostics of typescript@3.0.0-dev.20180712 for the https://github.com/devuo/typescript-slow-watch-bug codebase

 08:32:57 - Starting compilation in watch mode...

 Current directory: /app CaseSensitiveFileNames: true
 FileWatcher:: Added:: WatchInfo: /app/tsconfig.json 2000 Config file
 Synchronizing program
 CreatingProgramWith::
   roots: ["/app/src/index.ts"]
   options: {"target":3,"module":1,"sourceMap":true,"outDir":"/app/dist","strict":true,"noImplicitAny":true,"strictNullChecks":true,"alwaysStrict":true,"noUnusedLocals":true,"noUnusedParameters":true,"typeRoots":["/app/node_modules/@types"],"watch":true,"extendedDiagnostics":true,"configFilePath":"/app/tsconfig.json"}
 FileWatcher:: Added:: WatchInfo: /app/src/index.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/accepts/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/node/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/node/inspector.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/events/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/bluebird/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/body-parser/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/connect/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/caseless/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/chai/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/cookiejar/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/cookies/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/keygrip/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/express/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/express-serve-static-core/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/range-parser/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/serve-static/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/mime/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/form-data/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/helmet/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/http-assert/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/joi/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/knex/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/koa/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/koa-compose/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/koa-bodyparser/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/koa-helmet/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/koa-router/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/lodash/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/lodash/common/common.d.ts 250 Source file
 DirectoryWatcher:: Added:: WatchInfo: /app 1 Failed Lookup Locations
 Elapsed:: 19980ms DirectoryWatcher:: Added:: WatchInfo: /app 1 Failed Lookup Locations
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/lodash/common/array.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/lodash/common/collection.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/lodash/common/date.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/lodash/common/function.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/lodash/common/lang.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/lodash/common/math.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/lodash/common/number.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/lodash/common/object.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/lodash/common/seq.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/lodash/common/string.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/lodash/common/util.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/mocha/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/nano/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/request/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/tough-cookie/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/request-promise-native/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/sinon/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/superagent/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/@types/supertest/index.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/typescript/lib/lib.es2016.full.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/typescript/lib/lib.es2016.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/typescript/lib/lib.es2015.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/typescript/lib/lib.es5.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/typescript/lib/lib.es2015.core.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/typescript/lib/lib.es2015.collection.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/typescript/lib/lib.es2015.generator.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/typescript/lib/lib.es2015.promise.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/typescript/lib/lib.es2015.iterable.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/typescript/lib/lib.es2015.symbol.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/typescript/lib/lib.es2015.proxy.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/typescript/lib/lib.es2015.reflect.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/typescript/lib/lib.es2015.symbol.wellknown.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/typescript/lib/lib.es2016.array.include.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/typescript/lib/lib.dom.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/typescript/lib/lib.webworker.importscripts.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/typescript/lib/lib.scripthost.d.ts 250 Source file
 FileWatcher:: Added:: WatchInfo: /app/node_modules/typescript/lib/lib.dom.iterable.d.ts 250 Source file
 DirectoryWatcher:: Added:: WatchInfo: /app/node_modules/@types 1 Type roots
 Elapsed:: 0ms DirectoryWatcher:: Added:: WatchInfo: /app/node_modules/@types 1 Type roots

 08:33:21 - Found 0 errors. Watching for file changes.
 Files:                   67
 Lines:                64883
 Nodes:               284468
 Identifiers:         100944
 Symbols:              81975
 Types:                30952
 Memory used:        152720K
 I/O Read time:        0.18s
 Parse time:           0.73s
 Program time:        21.90s
 Bind time:            0.55s
 Check time:           1.67s
 transformTime time:   0.02s
 commentTime time:     0.00s
 Source Map time:      0.00s
 I/O Write time:       0.01s
 printTime time:       0.04s
 Emit time:            0.05s
 Total time:          24.17s
 DirectoryWatcher:: Added:: WatchInfo: /app/src 1 Wild card directories
 Elapsed:: 0ms DirectoryWatcher:: Added:: WatchInfo: /app/src 1 Wild card directories

@sheetalkamat
Copy link
Member

The exclude location only impacts initial list of files, not where module resolution takes place.

@sheetalkamat
Copy link
Member

@devuo can you please check if #25811 helps you further?

@devuo
Copy link
Author

devuo commented Jul 23, 2018

@sheetalkamat nope, no changes. I also added .git/ to excludes, but it appears to be scanning it nonetheless. Will try to check in a bit more detail tomorrow

@sheetalkamat
Copy link
Member

@devuo #25811 will help you with watching /app/node_modules instead of /app for failed lookup locations (which created child watches for each directory in it.
As mentioned exclude just helps with the initial list, the files from node_modules even if in exclude list can be added to your program to resolve modules.
I ran #25811 and was able to see that only three directory watchers were added as:

DirectoryWatcher:: Added:: WatchInfo: c:/temp/typescript-slow-watch-bug/node_modules 1 Failed Lookup Locations
DirectoryWatcher:: Added:: WatchInfo: c:/temp/typescript-slow-watch-bug/node_modules/@types 1 Type roots
DirectoryWatcher:: Added:: WatchInfo: c:/temp/typescript-slow-watch-bug/src 1 Wild card directories

which is better than whats in main branch ( where in the only change is DirectoryWatcher:: Added:: WatchInfo: c:/temp/typescript-slow-watch-bug 1 Failed Lookup Locations and watching complete folder. )

@rs3d
Copy link

rs3d commented Jul 26, 2018

My experience with 3.1.0-dev.20180726 is much better in watch mode. It's around 10-13s faster than before watching 148 files.

Lines:         56845
Nodes:        238817
Identifiers:   77317
Symbols:       59517
Types:         13769
Memory used: 137311K
I/O read:      0.06s
I/O write:     0.01s
Parse time:    0.83s
Bind time:     0.73s
Check time:    1.28s
Emit time:     0.88s
Total time:    3.72s

@sheetalkamat
Copy link
Member

Closing this now since we have handled the optimization as best as we can for recursive directory watching where node doesnt support file system level events for recursive watching

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

No branches or pull requests

5 participants