Build performance decreased from v12.2.x to v13.1.1 (process assets / seal compilation) if Bootstrap is imported in styles.scss

[DavideViolante]

Which @angular/* package(s) are the source of the bug?

angular_devkit/build_angular

Is this a regression?

Yes

Description

I just upgraded a pretty big private project from v12 to v13 and the build time increased x10, can't really find why. Just to be sure that it was Angular upgrade I tried to downgrade again and the performance restored as expected. I post here a part of the verbose log of the build, in particular note the extreme difference between v12 and v13 in assets time / seal compilation:

v12 (edit)

...
<t> record hash: 0.12885 ms
<t> module assets: 0.478536 ms
<t> create chunk assets: 6.774782 ms
<t> process assets: 30310.76689 ms <--------

LOG from webpack.Compiler
<t> make hook: 18985.143228 ms
<t> finish make hook: 0.206746 ms
<t> finish compilation: 72.86418 ms
<t> seal compilation: 32318.405325 ms <----------
<t> afterCompile hook: 0.280398 ms
...

v13

...
<t> record hash: 0.130436 ms
<t> module assets: 0.797611 ms
<t> create chunk assets: 6.450294 ms
<t> process assets: 302297.57658 ms <-----------

LOG from webpack.Compiler
<t> make hook: 21553.025473 ms
<t> finish make hook: 0.179688 ms
<t> finish compilation: 86.421 ms
<t> seal compilation: 304301.925952 ms <-----------
<t> afterCompile hook: 0.207707 ms
...

tsconfig.json:

/* To learn more about this file see: https://angular.io/config/tsconfig. */
{
  "compileOnSave": false,
  "compilerOptions": {
    "baseUrl": "./",
    "outDir": "./dist/out-tsc",
    "forceConsistentCasingInFileNames": true,
    //"strict": true,
    "noImplicitOverride": true,
    //"noPropertyAccessFromIndexSignature": true,
    "noImplicitReturns": true,
    "noFallthroughCasesInSwitch": true,
    "sourceMap": true,
    "declaration": false,
    "downlevelIteration": true,
    "experimentalDecorators": true,
    "moduleResolution": "node",
    "importHelpers": true,
    "target": "es2017",
    "module": "es2020",
    "lib": [
      "es2020",
      "dom"
    ]
  },
  "angularCompilerOptions": {
    "enableI18nLegacyMessageIdFormat": false,
    "strictInjectionParameters": true,
    "strictInputAccessModifiers": true,
    "strictTemplates": true
  }
}

Any help to debug this issue deeply? What other tests could I do to find out more?

Thanks

Please provide a link to a minimal reproduction of the bug

https://github.com/angular/angular/issues/44555#issuecomment-1005045938

Please provide the exception or error you saw

Performance issue

Please provide the environment you discovered this bug in (run ng version)

Angular CLI: 13.1.2
Node: 16.13.1
Package Manager: npm 8.3.0
OS: linux x64

Angular: 13.1.1
... animations, common, compiler, compiler-cli, core, forms
... language-service, platform-browser, platform-browser-dynamic
... router

Package                         Version
---------------------------------------------------------
@angular-devkit/architect       0.1301.2
@angular-devkit/build-angular   13.1.2
@angular-devkit/core            13.1.2
@angular-devkit/schematics      13.1.2
@angular/cli                    13.1.2
@schematics/angular             13.1.2
rxjs                            7.4.0
typescript                      4.5.4

Anything else?

The issue is not present on development build (-c development) The issue is present in v13.0.0 too

[JoostK]

Related: angular/angular#44372

Could you please share a reproduction of some sorts, a CPU profiling or anything else that might help us determine what is going on here; without this information we won't be able to help you here. There's instructions in https://github.com/angular/angular-cli/issues/8259#issue-269908550 to create such a profile, or you could use the --cpu-prof flag in Node 16:

node --cpu-prof ./node_modules/.bin/ng build

that should write a .cpuprofile file into the current directory (but I am not sure if Node will be able to make it through, as profiling for longer durations may just fail, or the profile so large that it may not open in web inspector).

It would be most valuable for us to have a real reproduction we can use to assess this, so if you can share the project privately that would be most helpful.

The issue is not present on development build (-c development)

This is interesting, as it points towards an optimization step that has regressed. Optimizations do indeed run in the "seal optimization" phase.

[DavideViolante]

I executed the build with --cpu-prof and loaded it in Chrome DevTools. It seems like the majority of time is spent through this file (I sorted by Total Time spent). History of the file.

In particular this commit message makes me think about the slower performance (but not sure).

I cant provide the full cpu-prof at the moment but I'll try to investigate more. Let me know if you need more info from the cpu-prof file and I will provide that of course.

I will try to find out which part of the private project causes the issue, because the issue is not happening on the public project that is the "basic structure" of the private project too, but the private one is way more complex and expanded.

edit: attached the full cpu-prof of v13 compilation.

cpu-prof-v13.zip

[JoostK]

Thanks. esbuild-wasm is only used when the native esbuild binary is unavailable, which was mostly introduced to counter issues on Windows. esbuild-wasm is significantly slower than the native Go binary, so you may want to check which binary ends up being used.

The JS Optimizer plugin in the CLI also runs Terser, and that is known to be expensive. It's actually surprising to me how your NG12 logs show that the sealing phase finished within milliseconds, as the optimization phase is known to take seconds to minutes, not milliseconds. Was the NG12 build configured identically, i.e. also a production build with optimizations enabled?

[DavideViolante]

I'm sorry I picked the wrong part of the logs from v12, I edited first post, the times are around 30s, compared to 300s in v13.

Here the full ng build verbose logs: v12: https://pastebin.com/XAxkHw5A v13: https://pastebin.com/6mme47Lr

I also edited the previous post to provide the full cpu-prof files.

Just a side note: while building v13 the system is not usable due to 100% CPU, not happening "so strong" with v12.

[DavideViolante]

So, after several tests, I found out the root cause.

How I found it

To find it out, as I said, I've 2 projects, one of which is a more complex version of the other. The simple project didn't have any issue with v13, while the complex one does. So I started from the complex project and I went back hundreds of commits (but keeping v13 in package.json), to discover which change caused the build time to increase a lot.

Root cause

I found out that it's related to SCSS and Bootstrap, in particular if you import Bootsrap in styles.scss as they say here, the production build times increases by several factors.

How to reproduce

1. Clone this repo
2. Run ng config cli.cache.enabled false to disable the caching on build (important to compare different v13 builds)
3. (optional) Run npm i then npm run build to annotate the normal build timings and be able to compare later
4. Edit styles.scss and add this line @import '../node_modules/bootstrap/scss/bootstrap'; on top
5. Run npm i then npm run build and get a coffee meanwhile
6. Annotate the new build timings (below are mine)

Compare with v12

1. After the steps above, on my repo run git reset --hard HEAD~16 to revert to v12
2. Repeat step 4 above
3. Run npm i then npm run build and annotate the timings and compare them with v13 (below are mine)

Differences

v13 no Bootstrap import on styles.scss cache disabled
Build at: 2022-01-04T17:23:04.303Z - Hash: abc86b58f4200b3d - Time: 88389ms

v13 Bootstrap import on styles.scss cache disabled
Build at: 2022-01-04T17:34:43.699Z - Hash: 474fdca2989cd28d - Time: 627843ms <-----

v12 no Bootstrap import on styles.scss cache disabled
Build at: 2022-01-04T17:51:44.189Z - Hash: 59b34432059ba04e80f6 - Time: 88004ms

v12 Bootstrap import on styles.scss cache disabled
Build at: 2022-01-04T17:49:26.608Z - Hash: 0768bac24ea295cba933 - Time: 153772ms <----- increased but not as much as v13

[jpike88]

Just moved from fusebox... god the cli builder is worse than I thought. How is it possible that I can wait for only 10 seconds with fusebox, but wait 5x the amount with the first party angular tool, taking up triple the memory, causing my CPU to spin like nuts? Terrible.

[JoostK]

Just moved from fusebox... god the cli builder is worse than I thought. How is it possible that I can wait for only 10 seconds with fusebox, but wait 5x the amount with the first party angular tool, taking up triple the memory, causing my CPU to spin like nuts? Terrible.

@jpike88 please be a bit more thoughtful in how you raise the problem you're seeing. It would be helpful if you could provide constructive information that we may be able to act on.

[JoostK]

Moving to the CLI repo as this seems to be about CSS processing/optimization performance.

[SebastianStehle]

In general: have you considered fast-scss-loader in the angular team?

[alan-agius4]

In general: have you considered fast-scss-loader in the angular team?

One of the reasons why this is faster, is because this loader doesn't generate sourcemaps which makes this not a viable alternative in our case. In addition to that we try to stick with official plugins whenever possible.

[DavideViolante]

@alan-agius4 I just saw your PR (thanks), in which version of esbuild it was fixed? Can't figure it out from their changelog.

[alan-agius4]

@DavideViolante, it appears that it has been addressed in 0.14.6.

[DavideViolante]

I changed the version in my package-lock and the fix works. :+1: Compilation time on Github Action machine (not comparable with my machine) is just ~1min now (on the private bigger project).

Initial Chunk Files               | Names         |      Size
main.d84dddb592b6b05c9ce2.js      | main          | 854.30 kB
scripts.9e8c3619fe40c53a332e.js   | scripts       | 357.44 kB
styles.bf25deb546abd03ffa54.css   | styles        | 222.86 kB
polyfills.d22542734ce5b165217d.js | polyfills     |  36.19 kB
runtime.d4391d1428616e31d353.js   | runtime       |   1.02 kB

| Initial Total |   1.44 MB

Build at: 2022-01-11T16:40:38.854Z - Hash: 0e7843340e376ad4a4aa - Time: 55758ms

On my previous builds on Github Actions without the fix it was around 322943ms.

Thanks.

[alan-agius4]

Closed via https://github.com/angular/angular-cli/pull/22477

[alexandis]

I am getting annoying messages after upgrading from v11 to v13 like this (several projects cause this kind of errors after just opening the folder, no build, no serve). Any ideas - where do I need to dig?

[Info - 02:44:41] Enabling Ivy language service for c:/CT/AbxEps.AbpModules/angular-modules/projects/abxeps/abxeps-modal-window-router-bootstrap/tsconfig.lib.json. [Error - 02:44:41] Failed to run ngcc for c:/CT/AbxEps.AbpModules/angular-modules/projects/abxeps/abxeps-modal-window-router-abstractions/tsconfig.lib.json, language service may not operate correctly: ngcc for c:/CT/AbxEps.AbpModules/angular-modules/projects/abxeps/abxeps-modal-window-router-abstractions/tsconfig.lib.json returned exit code 177, stderr: Error: Timed out waiting 250s for another ngcc process, with id 62720, to complete. (If you are sure no ngcc process is running then you should delete the lock-file at c:/CT/AbxEps.AbpModules/angular-modules/node_modules/.ngcc_lock_file.) at AsyncLocker.create (file:///c:/CT/AbxEps.AbpModules/angular-modules/node_modules/@angular/compiler-cli/bundles/chunk-K5FPDA5B.js:1691:11) at async AsyncLocker.lock (file:///c:/CT/AbxEps.AbpModules/angular-modules/node_modules/@angular/compiler-cli/bundles/chunk-K5FPDA5B.js:1662:5) at async file:///c:/CT/AbxEps.AbpModules/angular-modules/node_modules/@angular/compiler-cli/bundles/ngcc/main-ngcc.js:31:5 [Info - 02:44:41] Enabling Ivy language service for c:/CT/AbxEps.AbpModules/angular-modules/projects/abxeps/abxeps-modal-window-router-abstractions/tsconfig.lib.json. [Error - 02:44:41] Failed to run ngcc for c:/CT/AbxEps.AbpModules/angular-modules/projects/abxeps/abxeps-report-builder/tsconfig.lib.json, language service may not operate correctly: ngcc for c:/CT/AbxEps.AbpModules/angular-modules/projects/abxeps/abxeps-report-builder/tsconfig.lib.json returned exit code 177, stderr: Error: Timed out waiting 250s for another ngcc process, with id 62720, to complete. (If you are sure no ngcc process is running then you should delete the lock-file at c:/CT/AbxEps.AbpModules/angular-modules/node_modules/.ngcc_lock_file.) at AsyncLocker.create (file:///c:/CT/AbxEps.AbpModules/angular-modules/node_modules/@angular/compiler-cli/bundles/chunk-K5FPDA5B.js:1691:11) at async AsyncLocker.lock (file:///c:/CT/AbxEps.AbpModules/angular-modules/node_modules/@angular/compiler-cli/bundles/chunk-K5FPDA5B.js:1662:5) at async file:///c:/CT/AbxEps.AbpModules/angular-modules/node_modules/@angular/compiler-cli/bundles/ngcc/main-ngcc.js:31:5 [Info - 02:44:41] Enabling Ivy language service for c:/CT/AbxEps.AbpModules/angular-modules/projects/abxeps/abxeps-report-builder/tsconfig.lib.json.

[angular-automatic-lock-bot[bot]]

This issue has been automatically locked due to inactivity. Please file a new issue if you are encountering a similar or related problem.

Read more about our automatic conversation locking policy.

_{This action has been performed automatically by a bot.}