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

Build watch takes 30x as long as cold build, high transformTime #35729

Closed
lingz opened this issue Dec 17, 2019 · 16 comments
Closed

Build watch takes 30x as long as cold build, high transformTime #35729

lingz opened this issue Dec 17, 2019 · 16 comments
Labels
Domain: Declaration Emit The issue relates to the emission of d.ts files Domain: Performance Reports of unusually slow behavior Fix Available A PR has been opened for this issue Needs More Info The issue still hasn't been fully clarified

Comments

@lingz
Copy link

lingz commented Dec 17, 2019

TypeScript Version: 3.7.3 and 3.4.5

Search Terms: transformTime, Watch, Slow compilation

Code

When building our source code, we can do a cold build in about 25 seconds, but a watch build takes 15 minutes to start on Typescript 3.4.5. On Typescript 3.7.3, the watch time doubles to 30 minutes (60x as slow).

Running extended diagnostics shows that the vast majority of the time (96%) is spent on "transformTime". Is there any way to speed this up, as I do not consider our project too large on the grander scale (600k LOC).

One thing that was causing slow builds that I already fixed and ruled out was the inlined type definitions bug mentioned in #34119, which cut my build time by a third. But even after this, I still get a very slow transformTime.

Files:                  3043
Lines:                637432
Nodes:               2372135
Identifiers:          850259
Symbols:             1167934
Types:                462989
Memory used:        2036527K
I/O Read time:         1.03s
Parse time:            2.81s
Program time:          6.12s
Bind time:             3.05s
Check time:           11.54s
transformTime time:  473.05s
commentTime time:      0.14s
I/O Write time:        0.43s
printTime time:      474.27s
Emit time:           474.27s
Total time:          494.99s

Expected behavior:

Watch build is slightly slower than cold build

Actual behavior:

Watch build is significantly slower

Playground Link:

Related Issues:

@RyanCavanaugh RyanCavanaugh added the Bug A bug in TypeScript label Dec 17, 2019
@RyanCavanaugh RyanCavanaugh added Needs Investigation This issue needs a team member to investigate its status. and removed Bug A bug in TypeScript labels Dec 17, 2019
@RyanCavanaugh RyanCavanaugh added this to the TypeScript 3.8.1 milestone Dec 17, 2019
@sheetalkamat
Copy link
Member

Can you please provide more details on repro. This seems like its taking long time to do declaration emit but I cant be certain.. Did you try running tsc --d --extendedDiagnostics. What do you see then.

@sheetalkamat sheetalkamat added Needs More Info The issue still hasn't been fully clarified and removed Needs Investigation This issue needs a team member to investigate its status. labels Dec 17, 2019
@sheetalkamat sheetalkamat assigned lingz and unassigned sheetalkamat Dec 17, 2019
@lingz
Copy link
Author

lingz commented Dec 17, 2019

@sheetalkamat the above pasted diagnostics is in fact from extendedDiagnostics and declarations emit only as you suggested. Let me know if any other information could help give clues.

@lingz lingz removed their assignment Dec 17, 2019
@sheetalkamat sheetalkamat added Domain: Declaration Emit The issue relates to the emission of d.ts files Domain: Performance Reports of unusually slow behavior labels Dec 17, 2019
@sheetalkamat
Copy link
Member

We would need sample code for repro..

@weswigham
Copy link
Member

Yeah, definitely going to need to see some sample code - when declaration emit takes a long time, it's usually because some type somewhere was easy to compute, but complicated to serialize. Did you check the sizes (and contents) of your output .d.ts files by compiling with declarations on?

@lingz
Copy link
Author

lingz commented Dec 18, 2019

I can't provide the source code unfortunately, but I did a CPU profile, and it seems like almost all the time is spent in GC, and trySymbolTable. I ran a size profile on the generated .d.ts, and they are all small files, almost all the files are only a few lines long (see size profile treemap below)

Screenshot 2019-12-18 at 11 38 54

71001691-b54bfb80-20d5-11ea-9f69-faa5186a614e

@lingz
Copy link
Author

lingz commented Dec 18, 2019

Seems like the 1 mil symbols might be what is causing the slowdown. But I'm not sure what is causing such a high number of symbols, perhaps generated types?

Do you have any advice on identifying which files might be causing this high number of symbols?

@lingz
Copy link
Author

lingz commented Dec 18, 2019

I've managed to find out the culprit, and reduced the transform time from 473 seconds to 6 seconds.

It turns out it was a recursive type that was used only a few places in our code:

/**
 * The JSON version, without functions, methods, class
 */
export type LitNative = string | number | boolean | undefined | null | void;
export type WithoutFunctions<T> = T extends any
  ? Omit<T, FunctionKeys<Required<T>>>
  : T

export type Serialized<T> = T extends any[]
  ? InnerSerialized<T[number]>[]
  : (T extends LitNative ? T : InnerSerialized<WithoutFunctions<T>>);

type InnerSerialized<T> = {
  [k in keyof T]: T[k] extends any[]
    ? Serialized<T[k][number]>[]
    : Serialized<T[k]>
};

This type Serialized is recursive, and takes an object and gives a version of it without any functions (as if it went through JSON.serialize). It was only used a few places in the code but it was exploding the transformTime.

The way I found it, was after seeing that trySymbolTable was taking up most of the time, I ran the tsc compiler with the chrome inspector, and set a breakpoint on the function. I saw all the function calls were looking up Serialized over and over again. I would speculate that this could be mitigated by some caching in the tsc architecture?

The command I ran (in case it is helpful to others) is:

node --inspect-brk $(which tsc) -p ./tsconfig.json --declaration --emitDeclarationOnly --extendedDiagnostics --declarationDir ~/Temp/declarations/out > ~/Temp/declarations/diagnostics.txt

@AnyhowStep
Copy link
Contributor

AnyhowStep commented Dec 18, 2019

Are there functions that are supposed to return Serialized<>?
Is the return type of those functions implicit or explicit?

I ask because the return type of a generic function should almost always be explicitly annotated. This goes double for complex recursive types.

I have opened a bunch of issues in the past where emit goes crazy because I did not use an explicit return type annotation on a generic function.

TS is pretty bad at figuring out good emit for generic return types.

@jamshally
Copy link

I ran the tsc compiler with the chrome inspector

Hi @lingz - I am running into a similar issue, and trying to follow your debug process. Thanks for providing the command. Could you share a little more info about you managed to find the trySymbolTable function, and then set a breakpoint on it?

@lingz
Copy link
Author

lingz commented Dec 23, 2019

Hi @ahrnee , The whole typescript compiler is one flat JS file (on production builds), So just step inside the definition from the chrome terminal and search for the trySymbolTable function.

@lingz
Copy link
Author

lingz commented Dec 23, 2019

@AnyhowStep It was always explicit, but nonetheless, still causing this bug to emit.

@RyanCavanaugh RyanCavanaugh removed this from the TypeScript 3.8.1 milestone Jan 23, 2020
@jrmyio
Copy link

jrmyio commented Feb 5, 2020

Ran into similar issues with a project that uses https://github.com/mobxjs/mobx-state-tree and managed to fix my issues going from 200s to 13s in watch mode (on initial type check).

In my case I was using exported interfaces instead of types for most of the typings, but not all. This resulted in many of the types (when referenced by other files) being recalculated because there is apparently not much caching going on with typescript types (while there is when you export interfaces). For mobx-state-tree this means using
export interface ModelSnapshot extends SnapshotIn<typeof Model>{}
and using ModelSnapshot instead of SnapshotIn<typeof Model> directly.

After optimizing some typings from types and inline types to interfaces I went from 200s initial watch time to just 13 seconds while using tsc without watch was always fast and didn't improve much of anything.

I used the same methods as listed above, using tsc --noEmit false --declaration --emitDeclarationOnly --extendedDiagnostics --declarationDir ./declarations to find the biggest files with windirstat. In these files there were tons of duplicated nested types, one file was as large as 17MB. Because I run typescript with --noEmit via webpack I never knew this was the actual reason for it being so slow.

Just like OP for me "transformTime time" was also taking the longest time. After my changes that value dropped from minutes to just seconds.

@ShuiRuTian
Copy link
Contributor

ShuiRuTian commented Aug 10, 2020

@lingz Sorry for asking, how does FunctionKeys<T> implement? It is amazing for me!

@kumar303
Copy link

kumar303 commented Aug 21, 2020

TL;DR it would be nice to have better diagnostics tools to tell us which exact types are the slowest (and what file / module they come from)

After my own debugging adventure, I tracked down the slowness to a third party library type. Because of that, the above techniques didn't help me discover it. Here was my process, in case it helps someone else.

For context, I was converting an 80k LOC monorepo from Flow to TypeScript. When editing any file during tsc --watch, it was taking 57 seconds to re-compile (every time).

code mod to add @ts-nocheck
// I named this ./codemods/transforms/add-ts-nocheck.ts
//
// I ran it from ./codemods like:
// jscodeshift -t ./transforms/add-ts-nocheck.ts ../my-actual-project --extensions=tsx --parser=tsx

import { Transform } from "jscodeshift";

/*
 * Add a @ts-nocheck comment to the top of every file.
 */
const transform: Transform = function (fileInfo, api) {
  const filePath = fileInfo.path ?? "";

  // I was eliminating types by directory like this:
  // if (!filePath.startsWith("../my-actual-project/packages/some-package")) {
  //   return null;
  // }
  if (filePath.includes("node_modules")) {
    return null;
  }

  const root = api.jscodeshift(fileInfo.source);
  root.get().node.program.body.unshift("// @ts-nocheck");
  return root.toSource();
};

transform.parser = "ts";
export default transform;
  • After adding // @ts-nocheck to literally every file in my source, I began to wonder if it even had an effect on compilation at all but I also wondered if it could be a third party typing problem.
  • My first guess was reakit since we were on an ancient version written in TypeScript (I dunno, just a sixth sense). I added this to @types/reakit/index.d.ts to override all its types:
@types/reakit/index.d.ts
declare module "reakit" {
  var x: any;
  export = x;
}

This brought my watch mode re-compiles down from 57 seconds to 3 seconds ✨ 🌈 🥇

I tried narrowing down the exact type in reakit like this:

@types/reakit/index.d.ts
import {
  Provider,
  // Tooltip,
} from "reakit";

declare module "reakit" {
  // Replace just this one export:
  var Tooltip: any;

  var allExports = {
    Provider,
    Tooltip,
    // Re-add all original exports ...
  };
  export = allExports;
  export default allExports;
}

...but I couldn't find a single export that was slow. They were all slow. I guess there is a shared internal type somewhere causing the problem.

If I hadn't gotten lucky and guessed the bad third party lib, I probably would have written a script to override all third party types then re-enable them one by one. I looked for an easier way to do that in TS but couldn't find one.

I was really in the dark here so better diagnostic tools would have been super helpful.

@grumd
Copy link

grumd commented Nov 20, 2020

Just wanted to contribute that I get the same situation in my 600k LOC codebase (most of it is JS):
image

Just running a typecheck with no emit takes 15 seconds, adding --watch results in it taking 10 minutes.

TS team should really look into making --watch possible without serializing types

@kumar303
Copy link

Just FYI, the new --enableTrace flag (I think that's it?) is documented in microsoft/vscode#110534

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Domain: Declaration Emit The issue relates to the emission of d.ts files Domain: Performance Reports of unusually slow behavior Fix Available A PR has been opened for this issue Needs More Info The issue still hasn't been fully clarified
Projects
None yet
Development

Successfully merging a pull request may close this issue.