tsc compilation slow on moderate sized project

[rightisleft]

TypeScript Version: 3.9.0-dev.20200326

Search Terms:

tsc slow compilation, tsc memory, tsc slow Program time, tsc Program time

Code

I'm trying to debug why my typescript compiler is taking 9-13 seconds to recompile. This impacts ts-node and development drastically.

typescript version: ^3.X.X

tsconfig.json:

{
  "compilerOptions": {
    "extendedDiagnostics": true,
    "target": "es6",
    "lib": ["es2017"],
    "module": "commonjs",
    "emitDeclarationOnly": true,
    "emitDecoratorMetadata": true,
    "experimentalDecorators": true,
    "incremental": true,
    "noResolve": false,
    "noEmitOnError": false,
    "noImplicitAny": true,
    "declaration": true,
    "sourceMap": true,
    "outDir": "dist/",
    "moduleResolution": "node",
    "skipLibCheck": true
  },
  "include": [
    "src/**/*.ts",
    "test/**/*.ts"
  ],
  "exclude": [
    "node_modules"
  ]
}

npx tsc --listFiles --generateCpuProfile profile

Files: 732
Lines: 364288
Nodes: 1133413
Identifiers: 417612
Symbols: 236577
Types: 76
Instantiations: 0
Memory used: 330244K
Assignability cache size: 0
Identity cache size: 0
Subtype cache size: 0
Strict subtype cache size: 0
I/O Read time: 2.51s
Parse time: 3.77s
ResolveTypeReference time: 0.33s
ResolveModule time: 2.91s
Program time: 9.86s
Bind time: 1.39s
Total time: 11.25s

File List Here: https://pastebin.com/zX7TpM2x

Generated CPU Profile Here: https://gist.github.com/rightisleft/d3c77fe2c643ba4c7832a94209f53ef2

Expected behavior:

This is a mid sized project, it should have a 1-3 second compile time

Actual behavior:

Compile takes anywhere from 9-14 seconds per line change

[amcasey]

@rightisleft Thanks for the detailed report!

Some initial observations, before I look at your CPU profile:

1. Your tsconfig has all the recommended settings for good perf.
2. It looks like your project is organized in such a way that you could trivially split it into separate composite projects for src and test - that would probably save you a bunch of time on every rebuild.
3. I've never seen extendedDiagnostics output with zero in those places. That actually looks like the output from --diagnostics, rather than --extendedDiagnostics (which would be a bug on us). Could you please try again with --extendedDiagnostics on the command line, rather than in the tsconfig?
4. I don't think it's even possible to have only 76 types.

[amcasey]

Now that I've looked at your file list, I'd guess there's no reason to use project references, given that you appear to have only two test files (which, presumably, are not enormous?).

[amcasey]

Are the files in database/migrations enormous? The names make me think they might be generated.

[rightisleft]

1. Awesome
2. We have 2 very small tests.
3. See below, the results change over multiple runs:

root@b1ea7e68f8a6:/app# npx tsc --extendedDiagnostics
Files:                         732
Lines:                      364288
Nodes:                     1133418
Identifiers:                417613
Symbols:                    238370
Types:                        1004
Instantiations:               1899
Memory used:               333494K
Assignability cache size:       59
Identity cache size:             0
Subtype cache size:            107
Strict subtype cache size:       0
I/O Read time:               2.38s
Parse time:                  3.38s
ResolveTypeReference time:   0.41s
ResolveModule time:          2.63s
Program time:                9.14s
Bind time:                   1.54s
Check time:                  0.14s
transformTime time:          0.02s
commentTime time:            0.01s
printTime time:              0.17s
Emit time:                   0.18s
I/O Write time:              0.03s
Total time:                 11.00s

root@b1ea7e68f8a6:/app# npx tsc --extendedDiagnostics
Files:                         732
Lines:                      364288
Nodes:                     1133418
Identifiers:                417613
Symbols:                    236577
Types:                          76
Instantiations:                  0
Memory used:               327263K
Assignability cache size:        0
Identity cache size:             0
Subtype cache size:              0
Strict subtype cache size:       0
I/O Read time:               2.33s
Parse time:                  2.95s
ResolveTypeReference time:   0.35s
ResolveModule time:          2.56s
Program time:                8.53s
Bind time:                   1.40s
Total time:                  9.92s

root@b1ea7e68f8a6:/app# npx tsc --extendedDiagnostics
Files:                         732
Lines:                      364288
Nodes:                     1133418
Identifiers:                417613
Symbols:                    236577
Types:                          76
Instantiations:                  0
Memory used:               330190K
Assignability cache size:        0
Identity cache size:             0
Subtype cache size:              0
Strict subtype cache size:       0
I/O Read time:               2.38s
Parse time:                  3.07s
ResolveTypeReference time:   0.40s
ResolveModule time:          2.88s
Program time:                9.06s
Bind time:                   1.43s
Total time:                 10.49s

4. I agree?

5: In regards to database/migrations - they are generated by TypeORM. We have 54 migration files. A majority of them are sql code wrapped as strings.

[rightisleft]

I've tried excluding both the migrations and test folders... i see about a .5 second increase in complication times.

[amcasey]

Ah, I see what I was missing - 76 types is for an incremental compilation. Can you please try a couple of tests that explicitly defeat that?

1. Delete .tsbuildinfo to cause a clean incremental build
2. Disable incremental build (in practice, this is usually faster than (1))

[rightisleft]

root@afdb413072d0:/app# ls -lag
total 5608
drwxr-xr-x  21 root     672 Mar 27 21:35 .
drwxr-xr-x   1 root    4096 Mar 27 21:38 ..
drwxr-xr-x  10 root     320 Mar 27 21:29 .idea
-rw-r--r--   1 root      90 Mar 26 20:12 .node-dev.json
-rw-r--r--   1 root       7 Mar 27 02:32 .npmignore
-rw-r--r--   1 root      70 Mar 12 13:44 .npmrc
-rw-r--r--   1 root    4962 Mar 12 13:44 README.md
drwxr-xr-x   5 root     160 Mar 27 02:32 config
drwxr-xr-x   5 root     160 Mar 27 02:39 dist
drwxr-xr-x 507 root   16224 Mar 27 21:35 node_modules
-rw-r--r--   1 root     449 Mar 27 02:32 nodemon.json
-rw-r--r--   1 root  231049 Mar 27 21:35 package-lock.json
-rw-r--r--   1 root    4134 Mar 27 21:29 package.json
-rw-r--r--   1 root      32 Mar 27 21:35 packagehash.txt
-rw-r--r--   1 root 2710358 Mar 27 02:58 profile
drwxr-xr-x   5 root     160 Mar 27 02:32 src
drwxr-xr-x   5 root     160 Mar 27 21:32 test
-rw-r--r--   1 root     568 Mar 28 18:39 tsconfig.json
-rw-r--r--   1 root    1386 Mar 12 13:44 tslint.json
root@afdb413072d0:/app# npx tsc --extendedDiagnostics
Files:                         781
Lines:                      442157
Nodes:                     1342298
Identifiers:                489887
Symbols:                    304554
Types:                       14191
Instantiations:              35092
Memory used:               404388K
Assignability cache size:     2695
Identity cache size:           278
Subtype cache size:            916
Strict subtype cache size:      99
I/O Read time:               1.81s
Parse time:                  3.33s
ResolveTypeReference time:   0.24s
ResolveModule time:          2.33s
Program time:                7.87s
Bind time:                   1.68s
Check time:                  1.61s
transformTime time:          0.13s
commentTime time:            0.02s
I/O Write time:              0.24s
printTime time:              0.49s
Emit time:                   0.49s
Total time:                 11.65s
root@afdb413072d0:/app# npx tsc --extendedDiagnostics
Files:                         781
Lines:                      442157
Nodes:                     1342298
Identifiers:                489887
Symbols:                    304554
Types:                       14191
Instantiations:              35092
Memory used:               405407K
Assignability cache size:     2695
Identity cache size:           278
Subtype cache size:            916
Strict subtype cache size:      99
I/O Read time:               1.94s
Parse time:                  3.20s
ResolveTypeReference time:   0.27s
ResolveModule time:          2.19s
Program time:                7.76s
Bind time:                   1.43s
Check time:                  1.38s
transformTime time:          0.13s
commentTime time:            0.02s
I/O Write time:              0.31s
printTime time:              0.56s
Emit time:                   0.56s
Total time:                 11.14s
root@afdb413072d0:/app# npx tsc --extendedDiagnostics
Files:                         781
Lines:                      442157
Nodes:                     1342298
Identifiers:                489887
Symbols:                    304554
Types:                       14191
Instantiations:              35092
Memory used:               405923K
Assignability cache size:     2695
Identity cache size:           278
Subtype cache size:            916
Strict subtype cache size:      99
I/O Read time:               1.42s
Parse time:                  3.22s
ResolveTypeReference time:   0.22s
ResolveModule time:          1.91s
Program time:                6.94s
Bind time:                   1.42s
Check time:                  1.40s
transformTime time:          0.14s
commentTime time:            0.03s
I/O Write time:              0.25s
printTime time:              0.50s
Emit time:                   0.50s
Total time:                 10.26s

[amcasey]

Thanks! Those numbers make a lot more sense. Something's going on with "Program time" - it's nearly always (much) smaller than "Check time". Your files aren't on a network share or something, are they?

[amcasey]

My reading of those numbers is that a lot of time is spent reading the code, but it's not very complicated. TS itself, for example, has roughly 1 type for every 3 lines of code and uses a lot more memory. The cache sizes are also quite small.

Is there some way you could exclude the generated files, as an experiment? You might need to insert some casts to any or declare some constants to handle the missing symbols.

[amcasey]

According to the profile you attached, something like 24% of time is spent in f/l/stat calls (!). Of course, that was for an incremental build, which spends a lot of time on freshness checks, but still...

[rightisleft]

@amcasey

1: How would you like me to exclude generated files?
2: Would you like another cpu profile with incremental builds turned off?

[amcasey]

@rightisleft

1. Without knowing the details of your setup, I'd guess you can add an exclude glob in your tsconfig. Having said that, it looks like you may already have tried that? Do other parts of your project have lots of large string literals?
2. Yes please

[amcasey]

@rightisleft I'm keenly aware that the world is upside down right now, but I thought I'd ping this thread in case it's just fallen through the cracks.