Compilation time significantly slower in 3.7.1-RC vs 3.5.2, essentially the "check time" part.

[Ikaer]

TypeScript Version: 3.7.1-RC

Search Terms: Compilation time Check time 3.7.1-RC

Code

// takes 25-30 minutes
node --max-old-space-size=8092 "C:\Program Files (x86)\Microsoft SDKs\TypeScript\3.7\tsc.js"
// takes 2-3 minutes
node --max-old-space-size=8092 "C:\Program Files (x86)\Microsoft SDKs\TypeScript\3.5\tsc.js"

Expected behavior: Compilation should take a reasonable amount of time

Actual behavior: Compilation is 10 times slower than 3.5.2 version.

Related Issues: maybe related: #24435

Hi, we give a try at typescript 3.7.1-RC today (upgrading from 3.5.2) and we are facing a significant increase of build time.

I've launched the compilation with extendedDiagnostics flag and this is the "check time" which is a lot slower.

In 3.7.1-rc:

Files: 532
Lines: 402274
Nodes: 1927658
Identifiers: 684045
Symbols: 1844544
Types: 528324
Memory used: 1857090K
Assignability cache size: 337352
Identity cache size: 10477
Subtype cache size: 88675
I/O Read time: 0.15s
Parse time: 3.89s
Program time: 4.72s
Bind time: 2.84s
Check time: 1480.74s
transformTime time: 9.18s
commentTime time: 0.28s
I/O Write time: 0.41s
printTime time: 22.17s
Emit time: 22.25s
Total time: 1510.55s

In 3.5.2:

Files: 532
Lines: 400795
Nodes: 2122066
Identifiers: 672829
Symbols: 1707809
Types: 518149
Memory used: 1781530K
Assignability cache size: 333702
Identity cache size: 1968
Subtype cache size: 88497
I/O Read time: 0.14s
Parse time: 3.51s
Program time: 4.22s
Bind time: 2.50s
Check time: 85.37s
transformTime time: 11.09s
commentTime time: 0.13s
I/O Write time: 0.56s
printTime time: 33.09s
Emit time: 33.16s
Total time: 125.24s

Do you have any clue of what is going on ? I've saw nothing in breaking change that could cause that.

Thanks in advance.

the tsconfig.json used:

{
  "compileOnSave": true,
  "compilerOptions": {
    "incremental": false,
    "outDir": "./dist/js",
    "noImplicitAny": false,
    "allowJs": false,
    "checkJs": false,
    "noEmitOnError": true,
    "removeComments": true,
    "sourceMap": false,
    "target": "es5",
    "lib": [
      "dom",
      "es5",
      "scripthost",
      "es2015.promise",
      "es2015.collection",
      "es2015.core",
      "es2015.generator",
      "es2015.iterable",
      "es2015.proxy",
      "es2015.reflect",
      "es2015.symbol",
      "es2015.symbol.wellknown"
    ],
    "rootDir": "./src/js",
    "noResolve": true,
    "module": "amd",
    "moduleResolution": "node",
    "experimentalDecorators": false,
    "jsx": "react"
  },
  "include": [
    "./src/**/*.js",
    "./src/**/*.ts",
    "./src/**/*.tsx",
    "./Scripts/typings/**/*.ts"
  ],
  "exclude": [
    "./Scripts/excludedtypings/**/*.ts",
    "node_modules",
    "node_modules/@types",
    "wwwroot"
  ]
}

[temeass]

`

Su
`

[Shinigami92]

yarn build triggers vue-cli-service build
Medium sized SPA

Version	1. build	2. build	3. build
3.6.4	37.51s	16.65s	17.36s
3.7.2	37.59s	16.14s	16.41s

... cant see any problem in our project 👍

[amcasey]

@Ikaer thanks for the detailed feedback! Any chance your build is something we can set up locally? If not (no worries, it's pretty common), could you possibly try with 3.6.4 and let us know what you see? That will help us narrow down the span of possible changes.

[Ikaer]

@amcasey We try to compile with 3.6.2 (we don't have the 3.6.4 installed on this server). It takes the same amount of time than the 3.7. So It is probably a change made between the 3.5.2 and the 3.6.2.
I cannot provide the source code for this specific solution, sorry :(

[Ikaer]

Maybe this can help you to find where the problem is: I've done a node profiling of the compilation with 3.7, and below is a summary (the complete file is attached).

profiling.txt

For comparison this is the profiling with 3.5.2: Profiling352.txt

Code move event for unknown code: 0x2d515da98c0
Statistical profiling result from v8.log, (755274 ticks, 5355 unaccounted, 0 excluded).

 [Shared libraries]:
   ticks  total  nonlib   name
  660248   87.4%          C:\Program Files\nodejs\node.exe
   1397    0.2%          C:\windows\SYSTEM32\ntdll.dll
     48    0.0%          C:\windows\System32\KERNEL32.DLL
     37    0.0%          C:\windows\System32\KERNELBASE.dll

 [JavaScript]:
   ticks  total  nonlib   name
  23009    3.0%   24.6%  Stub: FastNewClosureStub
  14423    1.9%   15.4%  Stub: LoadICStub
   6322    0.8%    6.8%  LazyCompile: *checkTypeRelatedTo F:\Users\xlefebvre\TestBuildTS\binaries\NodejsConsoleApp1\tsc.js:45724:36
   4570    0.6%    4.9%  LazyCompile: ~isRelatedTo F:\Users\xlefebvre\TestBuildTS\binaries\NodejsConsoleApp1\tsc.js:45989:33
   3441    0.5%    3.7%  Stub: CEntryStub
   2335    0.3%    2.5%  LazyCompile: *isTypeOrBaseIdenticalTo F:\Users\xlefebvre\TestBuildTS\binaries\NodejsConsoleApp1\tsc.js:49246:41
   1858    0.2%    2.0%  Handler: An IC handler from the snapshot
   1668    0.2%    1.8%  Stub: FastNewContextStub {5}
   1394    0.2%    1.5%  LazyCompile: *isTypeRelatedTo F:\Users\xlefebvre\TestBuildTS\binaries\NodejsConsoleApp1\tsc.js:45687:33
   1270    0.2%    1.4%  Stub: RecordWriteStub {8}
   1222    0.2%    1.3%  Builtin: ArgumentsAdaptorTrampoline
   1096    0.1%    1.2%  LazyCompile: *inferFromMatchingTypes F:\Users\xlefebvre\TestBuildTS\binaries\NodejsConsoleApp1\tsc.js:48929:44
   1084    0.1%    1.2%  LazyCompile: *getDeclaredTypeOfEnum F:\Users\xlefebvre\TestBuildTS\binaries\NodejsConsoleApp1\tsc.js:40091:39
   1011    0.1%    1.1%  Builtin: CallFunction_ReceiverIsNotNullOrUndefined
[...]
[Summary]:
   ticks  total  nonlib   name
  88189   11.7%   94.3%  JavaScript
      0    0.0%    0.0%  C++
  566406   75.0%  605.5%  GC
  661730   87.6%          Shared libraries
   5355    0.7%          Unaccounted

 [C++ entry points]:
   ticks    cpp   total   name

 [Bottom up (heavy) profile]:
  Note: percentage shows a share of a particular caller in the total
  amount of its parent calls.
  Callers occupying less than 2.0% are not shown.

   ticks parent  name
  660248   87.4%  C:\Program Files\nodejs\node.exe
  88759   13.4%    C:\Program Files\nodejs\node.exe
  68263   76.9%      LazyCompile: *checkTypeRelatedTo F:\Users\xlefebvre\TestBuildTS\binaries\NodejsConsoleApp1\tsc.js:45724:36
  68239  100.0%        LazyCompile: *isTypeRelatedTo F:\Users\xlefebvre\TestBuildTS\binaries\NodejsConsoleApp1\tsc.js:45687:33
  68063   99.7%          LazyCompile: *isTypeOrBaseIdenticalTo F:\Users\xlefebvre\TestBuildTS\binaries\NodejsConsoleApp1\tsc.js:49246:41
  68062  100.0%            LazyCompile: *inferFromMatchingTypes F:\Users\xlefebvre\TestBuildTS\binaries\NodejsConsoleApp1\tsc.js:48929:44

  23009    3.0%  Stub: FastNewClosureStub
  22522   97.9%    LazyCompile: *checkTypeRelatedTo F:\Users\xlefebvre\TestBuildTS\binaries\NodejsConsoleApp1\tsc.js:45724:36
  22511  100.0%      LazyCompile: *isTypeRelatedTo F:\Users\xlefebvre\TestBuildTS\binaries\NodejsConsoleApp1\tsc.js:45687:33
  22429   99.6%        LazyCompile: *isTypeOrBaseIdenticalTo F:\Users\xlefebvre\TestBuildTS\binaries\NodejsConsoleApp1\tsc.js:49246:41
  22428  100.0%          LazyCompile: *inferFromMatchingTypes F:\Users\xlefebvre\TestBuildTS\binaries\NodejsConsoleApp1\tsc.js:48929:44
  13597   60.6%            LazyCompile: *inferFromTypes F:\Users\xlefebvre\TestBuildTS\binaries\NodejsConsoleApp1\tsc.js:48710:36
   8831   39.4%            LazyCompile: ~inferFromTypes F:\Users\xlefebvre\TestBuildTS\binaries\NodejsConsoleApp1\tsc.js:48710:36

[amcasey]

@Ikaer Wow, thanks for the profile! Any chance you'd be willing to share the underlying isolate logs? They should only point into our source, not yours. Better still, if you wanted to do a run with --trace-maps --trace-ic --prof, we could visualize which parts of our code are contributing to the slowdown.

Edit: that's overkill. In 3.7, you should be able to pass --generateCpuProfile filename.cpuprofile to tsc and get a clean CPU trace (i.e. we attempt to scrub any user data).

[amcasey]

I think the trace shows a huge increase in the amount of GC going on in the newer compiler and the extended diagnostics above seem to indicate that there are 5X as many identity cache entries. That's pretty suspicious.

[amcasey]

@Ikaer are you using a lot of intersection types? There was some work done in 3.6 to eliminate duplicate signatures that requires a bunch of new identity checks: #32049

If that seems promising, I can try to make you a private build without that change to confirm that it's the culprit. If it is, we can refine the check.

[amcasey]

@Ikaer you should be able to get a build of 3.6 without the potentially problematic check from #35073 when the bot finishes.

This creates a build which does a build, runs an LKG, runs normal tests, and then packs the result into an installable tarball (which can be downloaded from the build artifacts on the azure pipelines build status page), perfect for installing with npm i {URL to tarball} to test with.

[Ikaer]

I will get a run with this version and will let you know how it goes.
For the intersections, yep, we use them a lot, we have a transpilation engine which convert C# code (from server side) into declaration file with enums converted to string literal intersection type.

[Ikaer]

@amcasey this build does not effect the build time (still very long). In this files36Fix.zip , I've put the extenddiagnostics and the isolate file.

I was not able to use the flag --trace-maps (I'm using node 6.5.0, maybe its an option who appeared later ?),

but --trace-ic worked