Skip to content

Prevent excessive compilation of files within a cycle #33061

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

Conversation

ericanderson
Copy link
Contributor

@ericanderson ericanderson commented Aug 23, 2019

Cycles within a project previously would emit (to both memory and then later to disk) multiple times per file.

This would not have been possible without the large amount of time that @bjlaub put into debugging.

This was affecting us on versions 3.4 and 3.5 and master.

Fixes #31398

Nature: When using a tsbuildinfo file, a project with code that was circular in nature, would often OOM the compiler and would take far longer to rebuild for a tiny change vs just rebuilding from scratch.

Repro:

  • Checkout https://github.com/ericanderson/test-case-ts-bug-a
  • Add logging to emitter.ts in the file printSourceFileOrBundle, first line add console.log(=== printSourceFileOrBundle: jsFilePath=${jsFilePath} sourceMapFilePath=${sourceMapFilePath} );
  • rebuild typescript
  • build the project node ../locationOfTypescriptCheckout/built/local/tsc.js --build packages/*
  • Notice that each file is basically printed once (there is another bug I believe that is not addressed here, in which the .d.ts files are printed an extra time)
  • Change a.ts to add foo: any to the interface A.
  • build the project node ../locationOfTypescriptCheckout/built/local/tsc.js --build packages/*
  • Notice many prints.

Internally to our company, we have a project that was building in about 110s when there were no tsbuildinfo files. When starting with tsbuildinfo files in place and making a trivial change it would oom 4gb and if we set it to 6gb it would take over 20m to complete.

After this change we can get back to a 3gb heap and the rebuild from a tsbuildinfo file takes 108 seconds.

cc/ @ahejlsberg @weswigham @sheetalkamat @RyanCavanaugh @DanielRosenwasser

Shoutout to @bjlaub for the countless hours of debugging to track this down.

Cycles within a project previously would emit (to
both memory and then later to disk) multiple times
per file.

This would not have been possible without the large
amount of time that @bjlaub put into debugging.
@msftclas
Copy link

msftclas commented Aug 23, 2019

CLA assistant check
All CLA requirements met.

@weswigham weswigham requested a review from sheetalkamat August 23, 2019 22:28
@bjlaub
Copy link

bjlaub commented Aug 26, 2019

Just to provide some more background on our testing and debugging with this change:

For our tests, we typically ran the compiler in watch mode, with project references
enabled and experimented with/without incremental build state on disk. In all cases,
if we started tsc with no tsbuildinfo files on disk, compilation would succeed.
However, starting up the compiler in watch mode with existing incremental build
state on disk was frequently resulting in OOMs/crashes and general slowness on our
codebase.

At this point our developers have been using a 6GB max heap (because more memory
seemed to perform better, until it didn't...). For debugging this problem, we tested
with a 4GB heap. (NOTE: the data here was run on our production codebase, not
the small test case repository mentioned in the PR).

To trigger the behavior we were seeing, we had to do the following:

  1. recompile the codebase from scratch without any incremental build state on disk
  2. once complete, start tsc --build --watch - this starts up fast, since the
    first step has already built everything
  3. make a small code change in project that would trigger downstream rebuilds of
    dependent projects
  4. when the compiler reached one very large project (the one with significant
    numbers of cycles), it would take significantly longer to compile than it had in
    step 1, and eventually possibly run out of memory and crash.

We started testing with Node 8.15.1 (the version our codebase is currently building
with); it seems the V8 that ships with this version of node has some significantly
different GC behavior compared to newer versions. In particular, we noticed that when
reached step 4, once there was enough memory in use, the GC was unable to complete
scavenge cycles, and eventually would only perform expensive mark-sweep cycles.
In each mark-sweep, it would reclaim a very small amount of memory and try to continue,
but eventually would hit a limit and crash. This took a very long time (on the order
of 30-40 minutes).

We then switched to Node 12.9.0, which has a newer V8 which seems to perform differently;
in particular, the V8 GC on Node 12 seems to abort when it detects memory pressure
much sooner than Node 8 - instead of getting stuck in a lengthy loop of mark-sweeps,
it would trigger an out-of-memory crash when there were approximately 20-30MB of remaining
total memory. We didn't investigate the differences in the GC too much between these
versions of Node - but suffice it to say, reproducing this on Node 12 was much easier.

We ran our experiments with the --trace-gc, --trace-gc-ignore-scavenger and
--trace-gc-verbose Node options enabled, with --max-old-space-size set to 4096.
In step 4 above when we make our code change and tsc hits this particular project, the
V8 memory allocator statistics look something like this:

[8233:0x102846000] Memory allocator,       used:  45256 KB, available: 4198200 KB
[8233:0x102846000] Memory allocator,       used: 157788 KB, available: 4085668 KB
[8233:0x102846000] Memory allocator,       used: 112264 KB, available: 4131192 KB
[8233:0x102846000] Memory allocator,       used: 179872 KB, available: 4063584 KB
[8233:0x102846000] Memory allocator,       used: 443424 KB, available: 3800032 KB
[8233:0x102846000] Memory allocator,       used: 690616 KB, available: 3552840 KB
[8233:0x102846000] Memory allocator,       used: 1154416 KB, available: 3089040 KB
[8233:0x102846000] Memory allocator,       used: 1415288 KB, available: 2828168 KB
[8233:0x102846000] Memory allocator,       used: 1977320 KB, available: 2266136 KB
[8233:0x102846000] Memory allocator,       used: 1826036 KB, available: 2417420 KB
[8233:0x102846000] Memory allocator,       used: 2107652 KB, available: 2135804 KB
[8233:0x102846000] Memory allocator,       used: 2993992 KB, available: 1249464 KB
[8233:0x102846000] Memory allocator,       used: 3331432 KB, available: 912024 KB
[8233:0x102846000] Memory allocator,       used: 3595284 KB, available: 648172 KB
[8233:0x102846000] Memory allocator,       used: 3731988 KB, available: 511468 KB
[8233:0x102846000] Memory allocator,       used: 3820564 KB, available: 422892 KB
[8233:0x102846000] Memory allocator,       used: 3938268 KB, available: 305188 KB
[8233:0x102846000] Memory allocator,       used: 4028892 KB, available: 214564 KB
[8233:0x102846000] Memory allocator,       used: 4090268 KB, available: 153188 KB
[8233:0x102846000] Memory allocator,       used: 4140956 KB, available: 102500 KB
[8233:0x102846000] Memory allocator,       used: 4180636 KB, available:  62820 KB
[8233:0x102846000] Memory allocator,       used: 4203932 KB, available:  39524 KB
[8233:0x102846000] Memory allocator,       used: 4205212 KB, available:  38244 KB
[8233:0x102846000] Memory allocator,       used: 4207516 KB, available:  35940 KB
[8233:0x102846000] Memory allocator,       used: 4216732 KB, available:  26724 KB
[8233:0x102846000] Memory allocator,       used: 4209052 KB, available:  34404 KB
[8233:0x102846000] Memory allocator,       used: 4217500 KB, available:  25956 KB
[8233:0x102846000] Memory allocator,       used: 4213148 KB, available:  30308 KB
[8233:0x102846000] Memory allocator,       used: 4216732 KB, available:  26724 KB
[8233:0x102846000] Memory allocator,       used: 4214684 KB, available:  28772 KB
[8233:0x102846000] Memory allocator,       used: 4217500 KB, available:  25956 KB

until it eventually crashes.

We discovered that tsc was calling the emit pipeline end-to-end on the same set of files multiple
times, even writing them to disk. Worse, each call to emit returned an object with
the transpiled source code that was held in a string in memory before it reached
the stage that wrote that code to disk. This meant that if the compiler discovered
cycles in source code during the course of compilation, it was transpiling that code
multiple times, but keeping the transpiled code in memory in new objects until it had finished and
then wrote all the objects to disk, overwriting the same file multiple times.

In a "clean" state (i.e. one without any incremental build info), our problematic
project builds in about 2 minutes. Here's the compiler diagnostics from a clean build:

Files:           8456
Lines:         520186
Nodes:        2357208
Identifiers:   785249
Symbols:       920538
Types:         305705
Memory used: 2492156K
I/O read:       0.77s
I/O write:      1.52s
Parse time:     4.65s
Bind time:      0.82s
Check time:    25.15s
Emit time:     80.80s
Total time:   111.43s

To test the theory that tsc was re-emitting the same source files multiple times and
retaining the transpiled code in memory, we added a small change to cache the results
of emit and deduplicate them:

diff --git a/src/compiler/tsbuild.ts b/src/compiler/tsbuild.ts
index 0503d0a49d..9307d0c4ab 100644
--- a/src/compiler/tsbuild.ts
+++ b/src/compiler/tsbuild.ts
@@ -1049,7 +1049,11 @@ namespace ts {
                 reportDeclarationDiagnostics,
                 /*writeFileName*/ undefined,
                 /*reportSummary*/ undefined,
-                (name, text, writeByteOrderMark) => outputFiles.push({ name, text, writeByteOrderMark }),
+                (name, text, writeByteOrderMark) => {
+                    if (outputFiles.filter((o) => o.name === name).length === 0) {
+                        outputFiles.push({ name, text, writeByteOrderMark });
+                    }
+                },
                 cancellationToken,
                 /*emitOnlyDts*/ false,
                 customTransformers

After running with this change, we were able to run our test case successfully without
an OOM (yay!), but it was still extremely slow compared to the "clean" state case:

Diagnostics:

Files:           8456
Lines:         520186
Nodes:        2357697
Identifiers:   785341
Symbols:       939666
Types:         305691
Memory used: 2190034K
I/O read:       0.89s
I/O write:      1.06s
Parse time:     5.19s
Bind time:      1.10s
Check time:    25.26s
Emit time:    842.12s
Total time:   873.67s

And memory usage:

[23602:0x102846000] Memory allocator,       used:  45000 KB, available: 4198456 KB
[23602:0x102846000] Memory allocator,       used: 149704 KB, available: 4093752 KB
[23602:0x102846000] Memory allocator,       used:  81012 KB, available: 4162444 KB
[23602:0x102846000] Memory allocator,       used:  39796 KB, available: 4203660 KB
[23602:0x102846000] Memory allocator,       used:  35956 KB, available: 4207500 KB
[23602:0x102846000] Memory allocator,       used:  61900 KB, available: 4181556 KB
[23602:0x102846000] Memory allocator,       used:  96136 KB, available: 4147320 KB
[23602:0x102846000] Memory allocator,       used: 305664 KB, available: 3937792 KB
[23602:0x102846000] Memory allocator,       used: 758600 KB, available: 3484856 KB
[23602:0x102846000] Memory allocator,       used: 1107200 KB, available: 3136256 KB
[23602:0x102846000] Memory allocator,       used: 869780 KB, available: 3373676 KB
[23602:0x102846000] Memory allocator,       used: 885760 KB, available: 3357696 KB
[23602:0x102846000] Memory allocator,       used: 1747420 KB, available: 2496036 KB
[23602:0x102846000] Memory allocator,       used: 1323000 KB, available: 2920456 KB
[23602:0x102846000] Memory allocator,       used: 1981736 KB, available: 2261720 KB
[23602:0x102846000] Memory allocator,       used: 1896708 KB, available: 2346748 KB
[23602:0x102846000] Memory allocator,       used: 2160056 KB, available: 2083400 KB
[23602:0x102846000] Memory allocator,       used: 2137104 KB, available: 2106352 KB
[23602:0x102846000] Memory allocator,       used: 2141968 KB, available: 2101488 KB
[23602:0x102846000] Memory allocator,       used: 2273428 KB, available: 1970028 KB
[23602:0x102846000] Memory allocator,       used: 2299228 KB, available: 1944228 KB
[23602:0x102846000] Memory allocator,       used: 2394204 KB, available: 1849252 KB
[23602:0x102846000] Memory allocator,       used: 2420868 KB, available: 1822588 KB
[23602:0x102846000] Memory allocator,       used: 2411396 KB, available: 1832060 KB
[23602:0x102846000] Memory allocator,       used: 2515588 KB, available: 1727868 KB
[23602:0x102846000] Memory allocator,       used: 2706756 KB, available: 1536700 KB
[23602:0x102846000] Memory allocator,       used: 1863576 KB, available: 2379880 KB
[23602:0x102846000] Memory allocator,       used: 1638088 KB, available: 2605368 KB
[23602:0x102846000] Memory allocator,       used: 1372952 KB, available: 2870504 KB

We removed the "caching" hack and instead added the change proposed on this PR, which
avoids re-processing files altogether which saves quite a bit of CPU cycles. After
the changes in this PR, our test case now performs even better:

Diagnostics:

Files:           8456
Lines:         520187
Nodes:        2357222
Identifiers:   785253
Symbols:       939668
Types:         305691
Memory used: 2462805K
I/O read:       0.83s
I/O write:      1.23s
Parse time:     4.65s
Bind time:      0.90s
Check time:    25.50s
Emit time:     77.15s
Total time:   108.21s

And memory usage:

[32907:0x102846000] Memory allocator,       used:  46028 KB, available: 4197428 KB
[32907:0x102846000] Memory allocator,       used: 149964 KB, available: 4093492 KB
[32907:0x102846000] Memory allocator,       used:  85368 KB, available: 4158088 KB
[32907:0x102846000] Memory allocator,       used:  36984 KB, available: 4206472 KB
[32907:0x102846000] Memory allocator,       used:  36216 KB, available: 4207240 KB
[32907:0x102846000] Memory allocator,       used:  53712 KB, available: 4189744 KB
[32907:0x102846000] Memory allocator,       used:  99468 KB, available: 4143988 KB
[32907:0x102846000] Memory allocator,       used: 165544 KB, available: 4077912 KB
[32907:0x102846000] Memory allocator,       used: 356744 KB, available: 3886712 KB
[32907:0x102846000] Memory allocator,       used: 413200 KB, available: 3830256 KB
[32907:0x102846000] Memory allocator,       used: 539664 KB, available: 3703792 KB
[32907:0x102846000] Memory allocator,       used: 1076208 KB, available: 3167248 KB
[32907:0x102846000] Memory allocator,       used: 995224 KB, available: 3248232 KB
[32907:0x102846000] Memory allocator,       used: 983608 KB, available: 3259848 KB
[32907:0x102846000] Memory allocator,       used: 1745940 KB, available: 2497516 KB
[32907:0x102846000] Memory allocator,       used: 1736996 KB, available: 2506460 KB
[32907:0x102846000] Memory allocator,       used: 1348184 KB, available: 2895272 KB
[32907:0x102846000] Memory allocator,       used: 1584788 KB, available: 2658668 KB
[32907:0x102846000] Memory allocator,       used: 1251732 KB, available: 2991724 KB

@sheetalkamat sheetalkamat self-assigned this Aug 26, 2019
@sheetalkamat
Copy link
Member

@ericanderson the repro steps you have mentioned don't seem to work:
In the repro you mention building package/* but the repo doesn't contain folder like that.
So I built existing tsconfig at the repo root and here is the result from first build: (clean when there is no tsbuild info file`

c:\temp\test-case-ts-bug-a>node c:\TypeScript\built\local\tsc.js  -b  --listEmittedFiles --listFiles
{"jsFilePath":"c:/temp/test-case-ts-bug-a/lib/c.d.ts"}
{"jsFilePath":"c:/temp/test-case-ts-bug-a/lib/b.d.ts"}
{"jsFilePath":"c:/temp/test-case-ts-bug-a/lib/a.d.ts"}
{"jsFilePath":"c:/temp/test-case-ts-bug-a/lib/c.js"}
{"jsFilePath":"c:/temp/test-case-ts-bug-a/lib/b.js"}
{"jsFilePath":"c:/temp/test-case-ts-bug-a/lib/a.js"}
TSFILE: c:/temp/test-case-ts-bug-a/lib/c.js
TSFILE: c:/temp/test-case-ts-bug-a/lib/b.js
TSFILE: c:/temp/test-case-ts-bug-a/lib/a.js
TSFILE: c:/temp/test-case-ts-bug-a/lib/tsconfig.tsbuildinfo
c:/TypeScript/built/local/lib.d.ts
c:/TypeScript/built/local/lib.es5.d.ts
c:/TypeScript/built/local/lib.dom.d.ts
c:/TypeScript/built/local/lib.webworker.importscripts.d.ts
c:/TypeScript/built/local/lib.scripthost.d.ts
c:/temp/test-case-ts-bug-a/src/c.ts
c:/temp/test-case-ts-bug-a/src/b.ts
c:/temp/test-case-ts-bug-a/src/a.ts

Then built changed a.ts as mentioned and here is the result and you can see a.js and b.js is built only once.

c:\temp\test-case-ts-bug-a>node c:\TypeScript\built\local\tsc.js  -b  --listEmittedFiles --listFiles
{"jsFilePath":"c:/temp/test-case-ts-bug-a/lib/a.d.ts"}
{"jsFilePath":"c:/temp/test-case-ts-bug-a/lib/c.d.ts"}
{"jsFilePath":"c:/temp/test-case-ts-bug-a/lib/b.d.ts"}
{"jsFilePath":"c:/temp/test-case-ts-bug-a/lib/a.js"}
{"jsFilePath":"c:/temp/test-case-ts-bug-a/lib/c.js"}
TSFILE: c:/temp/test-case-ts-bug-a/lib/a.js
TSFILE: c:/temp/test-case-ts-bug-a/lib/c.js
TSFILE: c:/temp/test-case-ts-bug-a/lib/tsconfig.tsbuildinfo
c:/TypeScript/built/local/lib.d.ts
c:/TypeScript/built/local/lib.es5.d.ts
c:/TypeScript/built/local/lib.dom.d.ts
c:/TypeScript/built/local/lib.webworker.importscripts.d.ts
c:/TypeScript/built/local/lib.scripthost.d.ts
c:/temp/test-case-ts-bug-a/src/c.ts
c:/temp/test-case-ts-bug-a/src/b.ts
c:/temp/test-case-ts-bug-a/src/a.ts
TSFILE: c:/temp/test-case-ts-bug-a/lib/src/a.js  /// This is calling update timestamp on these files and i need to check whats going on there (i think something to do with RootDir and folder structure not handled correctly in tsbuild)
TSFILE: c:/temp/test-case-ts-bug-a/lib/src/b.js
TSFILE: c:/temp/test-case-ts-bug-a/lib/src/c.js

@ericanderson
Copy link
Contributor Author

ericanderson commented Aug 26, 2019

Sorry. I forgot to push. One second. Good to go!

@ericanderson
Copy link
Contributor Author

I walked the debugger and can assure you the extra pass is doing real work. Full on re-emits. And its holding the memory until its time to put the files to disk. And @bjlaub said in his testing it was even writing multiple times.

@ericanderson
Copy link
Contributor Author

@bjlaub says he added a console.log in https://github.com/microsoft/TypeScript/blob/master/src/compiler/watch.ts#L298-L313 and saw multiple writes for the same file.

Copy link
Member

@sheetalkamat sheetalkamat left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Was able to repro the issue .. And The fix isnt corrrect. The fix is to set add seenEmittedFiles.set(affectedFile.path, true) at https://github.com/microsoft/TypeScript/blob/master/src/compiler/builder.ts#L384

@@ -997,7 +997,21 @@ namespace ts {
}

function addToAffectedFilesPendingEmit(state: BuilderProgramState, affectedFilesPendingEmit: readonly Path[]) {
state.affectedFilesPendingEmit = concatenate(state.affectedFilesPendingEmit, affectedFilesPendingEmit);
const actualAffectedFilesPendingEmit = affectedFilesPendingEmit.filter((f) => {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Was able to repro the issue. The current fix isnt corrrect.
The fix is to set add seenEmittedFiles.set(affectedFile.path, true) at https://github.com/microsoft/TypeScript/blob/master/src/compiler/builder.ts#L384

return;
}

state.affectedFilesPendingEmit = concatenate(state.affectedFilesPendingEmit, actualAffectedFilesPendingEmit);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Add test in src/testRunner/unittests/tscWatch/emitAndErrorUpdates.ts that has host.writeFile overriding the original one that also checks that file is emitted only once in the repro test case you have mentioned.

@sheetalkamat
Copy link
Member

Actually looking into this, i realise the correct fix is might need more investigations and ensuring that its enough. So i will just take this over. Will report back when i have fix and get everyone here to see if that fixes the issue. Thanks for looking into this.

@ericanderson
Copy link
Contributor Author

Am I reading this right? It looks like seenEmittedFiles never gets anything put into it

@sheetalkamat
Copy link
Member

That's correct and that needs to be handled in multiple scenarios like emitting through getNextAffectedFile , getnextAffectedFilePendingEmit and getNextAffectedFile when semantic diagnostics postpone the emit..

@ericanderson
Copy link
Contributor Author

Happy to have you chase down the rest of the bug. Thank you very much!

@ericanderson
Copy link
Contributor Author

I would love to learn how all of this works in more detail. Like how the diagnostics can postpone the emit? Perhaps at tsconf?

Would PRs be accepted that clean up some of this code? I found certain bits to be hard to follow do to the extra null checking and delayed creation of certain arrays.

sheetalkamat added a commit that referenced this pull request Aug 26, 2019
@ericanderson
Copy link
Contributor Author

@sheetalkamat any luck so far?

@sheetalkamat
Copy link
Member

#33145 handles this. Thanks everyone for helping with the repro and investigation.

sheetalkamat added a commit that referenced this pull request Aug 30, 2019
sheetalkamat added a commit that referenced this pull request Aug 30, 2019
…as complete (#33145)

* Add test that fails because file is written multiple times
Reported from #33061

* Handle seenEmittedFiles which was not being set when emit of a file was complete.
It was issue only when errors are reported before emitting (which puts the files into pendingEmit that needs to check only in seenEmittedFiles)
If emit happens before semantic diagnostics query this issue is not repro, because the affected files come into play and those are being set correctly
Fixes #31398

* make baselining source map optional

* Handle emitDeclarationOnly in --build scenario

* Ensure we are using d.ts emit as signature even when --declarationMap is on (map files are emitted before d.ts)

* Move module specifiers to verifyTsBuildOutput

* implement create Hash to be default hashing plus data so we can verify it easily in baseline

* Remove failing baseline

* Accept correct baseline name
timsuchanek pushed a commit to timsuchanek/TypeScript that referenced this pull request Sep 11, 2019
…as complete (microsoft#33145)

* Add test that fails because file is written multiple times
Reported from microsoft#33061

* Handle seenEmittedFiles which was not being set when emit of a file was complete.
It was issue only when errors are reported before emitting (which puts the files into pendingEmit that needs to check only in seenEmittedFiles)
If emit happens before semantic diagnostics query this issue is not repro, because the affected files come into play and those are being set correctly
Fixes microsoft#31398

* make baselining source map optional

* Handle emitDeclarationOnly in --build scenario

* Ensure we are using d.ts emit as signature even when --declarationMap is on (map files are emitted before d.ts)

* Move module specifiers to verifyTsBuildOutput

* implement create Hash to be default hashing plus data so we can verify it easily in baseline

* Remove failing baseline

* Accept correct baseline name
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

tsc instance reuse in composite project causes out of memory crash
4 participants