Babel is slowest tree about ember-cli-babel

[stefanpenner]

@aalasolutions so your initial build takes 61s of babel, but rebuild takes 200ms? What are warm build times? (e.g. quick restart)

be sure to read: https://github.com/ember-cli/ember-cli/blob/master/PERF_GUIDE.md which provides both ways of debugging/improve performance and importantly how to report actionable issues.

[aalasolutions-zz]

that 61 seconds is not the initial build, it is after I have changed the files as you can see the message, FILE CHANGED before that. so quick restart times are less.

Any how I have noticed that my tmp folder is above 5gb, and when I cleaned it. my cold build and rebuilds both are speedy. After doing changes in my large file. it again started to get slow. and I noticed tmp folder is getting filled.

I have created an ember script to clean the tmp folder, which i run time to time to keep my tmp folder empty. I also have published that as addon now.

[stefanpenner]

Any how I have noticed that my tmp folder is above 5gb, and when I cleaned it. my cold build and rebuilds both are speedy. After doing changes in my large file. it again started to get slow. and I noticed tmp folder is getting filled.

Reproduction would be great as something is obviously going sideways as at the very least apps do not (should not) leak tmp files. And then I have something to debug.

[aalasolutions-zz]

Cold Build

Build successful - 89470ms.

Slowest Trees                                 | Total               
----------------------------------------------+---------------------
Babel                                         | 54438ms             
Babel                                         | 6545ms              
Babel                                         | 6222ms              
JSHint app- QUnit                             | 5579ms              

Slowest Trees (cumulative)                    | Total (avg)         
----------------------------------------------+---------------------
Babel (20)                                    | 77481ms (3874 ms)   
JSHint app- QUnit (1)                         | 5579ms      

Warm Build

Build successful - 5099ms.

Slowest Trees                                 | Total               
----------------------------------------------+---------------------
Babel                                         | 446ms               
SassCompiler                                  | 372ms               

Slowest Trees (cumulative)                    | Total (avg)         
----------------------------------------------+---------------------
Babel (20)                                    | 1646ms (82 ms)      
SassCompiler (2)                              | 502ms (251 ms)      
TemplateCompiler (4)                          | 369ms (92 ms)       

Right now my rebuilds are quite fast, I will update this after 1 or 2 days without emptying temp folder.

[stefanpenner]

@aalasolutions as requested above, please provide a reproduction as requested or this isn't actionable.

[aalasolutions-zz]

@stefanpenner I am not understanding what do you mean by Reproduction

[stefanpenner]

@aalasolutions I need a way to reproduce your exact issue so I can diagnose

• share your app
• share an open-source contrived app that demonstrates the same issue.

[aalasolutions-zz]

@stefanpenner I am afraid I cant share you app right away, i might, but I need to change couple of things before I can shave in PM , but cant at the moment.

Here is just a very recent error

file changed site/components/tabs-head/component.js
The Broccoli Plugin: [BroccoliMergeTrees: TreeMerger (vendor & appJS)] failed with:
Error: EEXIST: file already exists, symlink '/Volumes/Work/htdocs/LP/lp2/tmp/broccoli_merge_trees-input_base_path-QXKZrk7B.tmp/0/.DS_Store' -> '/Volumes/Work/htdocs/LP/lp2/tmp/broccoli_merge_trees-output_path-2jC2Et1S.tmp/.DS_Store'
    at Error (native)
    at Object.fs.symlinkSync (fs.js:897:18)
    at symlink (/Volumes/Work/htdocs/LP/lp2/node_modules/symlink-or-copy/index.js:79:14)
    at symlinkOrCopySync (/Volumes/Work/htdocs/LP/lp2/node_modules/symlink-or-copy/index.js:55:5)
    at BroccoliMergeTrees.<anonymous> (/Volumes/Work/htdocs/LP/lp2/node_modules/broccoli-merge-trees/index.js:114:32)
    at Array.forEach (native)
    at BroccoliMergeTrees._applyPatch (/Volumes/Work/htdocs/LP/lp2/node_modules/broccoli-merge-trees/index.js:95:9)
    at BroccoliMergeTrees.build (/Volumes/Work/htdocs/LP/lp2/node_modules/broccoli-merge-trees/index.js:69:10)
    at /Volumes/Work/htdocs/LP/lp2/node_modules/broccoli-plugin/read_compat.js:61:34
    at lib$rsvp$$internal$$tryCatch (/Volumes/Work/htdocs/LP/lp2/node_modules/rsvp/dist/rsvp.js:493:16)

The broccoli plugin was instantiated at: 
    at BroccoliMergeTrees.Plugin (/Volumes/Work/htdocs/LP/lp2/node_modules/broccoli-plugin/index.js:7:31)
    at new BroccoliMergeTrees (/Volumes/Work/htdocs/LP/lp2/node_modules/broccoli-merge-trees/index.js:29:10)
    at BroccoliMergeTrees (/Volumes/Work/htdocs/LP/lp2/node_modules/broccoli-merge-trees/index.js:23:53)
    at module.exports (/Volumes/Work/htdocs/LP/lp2/node_modules/ember-cli/lib/broccoli/merge-trees.js:8:14)
    at EmberApp.javascript (/Volumes/Work/htdocs/LP/lp2/node_modules/ember-cli/lib/broccoli/ember-app.js:1199:10)
    at EmberApp.toArray (/Volumes/Work/htdocs/LP/lp2/node_modules/ember-cli/lib/broccoli/ember-app.js:1542:10)
    at EmberApp.toTree (/Volumes/Work/htdocs/LP/lp2/node_modules/ember-cli/lib/broccoli/ember-app.js:1564:30)
    at module.exports (/Volumes/Work/htdocs/LP/lp2/ember-cli-build.js:42:16)
    at Class.module.exports.Task.extend.setupBroccoliBuilder (/Volumes/Work/htdocs/LP/lp2/node_modules/ember-cli/lib/models/builder.js:55:19)
    at Class.module.exports.Task.extend.init (/Volumes/Work/htdocs/LP/lp2/node_modules/ember-cli/lib/models/builder.js:89:10)

Apart from that I need to discuss this with my manager before i can share. Thanks for your time

[stefanpenner]

@aalasolutions if it works, you can also share privately with just me. That would be more the sufficient for me to see if this is a new issue, or something already known.

[aalasolutions-zz]

@stefanpenner I have sent you an emaill.

[stefanpenner]

@aalasolutions awesome thanks, unfortunately I haven't seen the message (it may have gotten spam filtered by google) should I expect the sender email to be the same as your github profile?

[aalasolutions-zz]

@stefanpenner I have sent it from [email protected] (hosted on gmail) and sent it to your [email protected] account.

I have just sent the code, run npm install and bower install 😄 I know you know this.

[stv8]

I am also experiencing this, here is an example of a cold boot.

Build successful - 63231ms.

Slowest Trees                                 | Total
----------------------------------------------+---------------------
Babel                                         | 23104ms
Babel                                         | 19902ms
Babel                                         | 10723ms
Babel                                         | 5115ms

Slowest Trees (cumulative)                    | Total (avg)
----------------------------------------------+---------------------
Babel (20)                                    | 59772ms (2988 ms)

One thing I noticed is that I started getting these warnings in the output recently.

[BABEL] Note: The code generator has deoptimised the styling of...

I used to not get those. I tried toggling compact every which way but that didn't help.

I am using

ember-cli: 2.7.0
node: 6.0.0
os: darwin x64
npm: 3.8.6

And here are my dependencies
https://gist.github.com/stv8/0433fcbab697a1fa3231faa9d0e838e4

[stefanpenner]

@stv8 how many files are you babeling? What is warm boot times, what are rebuild times?

[stv8]

@stefanpenner what is the best way to find how many files? Do I include node_modules?

Here is a warm boot and rebuild

Build successful - 64075ms.

Slowest Trees                                 | Total
----------------------------------------------+---------------------
Babel                                         | 23637ms
Babel                                         | 20466ms
Babel                                         | 10997ms
Babel                                         | 4995ms

Slowest Trees (cumulative)                    | Total (avg)
----------------------------------------------+---------------------
Babel (20)                                    | 61092ms (3054 ms)

file changed templates/index.hbs

Build successful - 1016ms.

Slowest Trees                                 | Total
----------------------------------------------+---------------------
SourceMapConcat: Concat: App                  | 186ms
Babel                                         | 88ms

Slowest Trees (cumulative)                    | Total (avg)
----------------------------------------------+---------------------
StaticCompiler (25)                           | 293ms (11 ms)
SourceMapConcat: Concat: App (1)              | 186ms
Babel (20)                                    | 164ms (8 ms)

[stefanpenner]

those build times seems more or less expected, for cold boot and rebuild times, babel is slow.

[stv8]

@stefanpenner Okay gotcha, but what about the warm boot above? It consistently takes an average of 60 seconds. It becomes quite painful when running tests :p

[stefanpenner]

@stv8 that does not seems correct, it seems like something upstream of your babel transpiler is making changes that prevent babel from resuming quickly?

My guess is it should be like 5s -> 10s for a warm boot if the "resume" works correctly.

@stv8 is this a recent change or has "warm boot" always been crappy?

[rwjblue]

Are there any warnings printed to the console? There have been recent changes that would prevent caching across a restart, but they would all include console output indicating that something needs to be updated.

[stv8]

@stefanpenner it appears to be a recent change, I wasn't experiencing this until I wiped my node and bower modules a few days ago. I wish I had a snapshot of the versions but my guess is that something updated and it is affecting my build.

@rwjblue here is my output when running ember serve, this is a warm boot
https://gist.github.com/stv8/41f4e9df5b84050366a53bf38e58dddb

edit: I got rid of the watch man warnings but it didn't improve the speed

[rwjblue]

These seem pretty fishy to me.

[BABEL] Note: The code generator has deoptimised the styling of "nimbus/assets/pdf.js" as it exceeds the max of "100KB".
[BABEL] Note: The code generator has deoptimised the styling of "nimbus/assets/pdf.worker.js" as it exceeds the max of "100KB".
[BABEL] Note: The code generator has deoptimised the styling of "nimbus/templates/assets/pdf.js" as it exceeds the max of "100KB".
[BABEL] Note: The code generator has deoptimised the styling of "nimbus/templates/assets/pdf.worker.js" as it exceeds the max of "100KB".
[BABEL] Note: The code generator has deoptimised the styling of "nimbus/tests/assets/pdf.js" as it exceeds the max of "100KB".
[BABEL] Note: The code generator has deoptimised the styling of "nimbus/tests/assets/pdf.worker.js" as it exceeds the max of "100KB".
[BABEL] Note: The code generator has deoptimised the styling of "assets/pdf.js" as it exceeds the max of "100KB".
[BABEL] Note: The code generator has deoptimised the styling of "assets/pdf.worker.js" as it exceeds the max of "100KB".

It is inferring that you have a pdf.js and pdf.worker.js in your projects app tree (otherwise babel wouldn't be running on it in general).

[stv8]

@rwjblue we are using it with the ember-pdfjs add on, would that be why it includes it in the app tree?

[stv8]

@rwjblue I created a fresh ember app and added ember-pdfjs.

The cold boot took ~60 secs and showed the above babel output, however the subsequent warm boots were significantly faster, taking only 2 seconds and not showing the babel output.

I am not sure what this indicates about the build process of my original app and how it has deviated from the fresh one.

[stv8]

@rwjblue I found the problem, and for anyone else who may run into it, it turns out to be an older version of liquid fire. Specifically due to these lines in the output. Specifically we were using 0.22

https://gist.github.com/stv8/41f4e9df5b84050366a53bf38e58dddb#file-ember-server-output-L11-L12

[stefanpenner]

@stv8 yup that is what we thought. Going to close this, as that "regression" is actually catching more places where the warm cache was not safe to use. If those deprecations are fixed not only should the build performance be restored but the caching will work correctly.

[aalasolutions-zz]

@stefanpenner I am back for the same issue.

Here are my build times

file added site\components\site\carpets\neworderform-form\template.hbs___jb_tmp___
file changed site\components\site\carpets\neworderform-form\template.hbs___jb_tmp___
file deleted site\components\site\carpets\neworderform-form\template.hbs___jb_tmp___
file changed site\components\site\carpets\neworderform-form\template.hbs

Build successful - 100820ms.

Slowest Trees                                 | Total
----------------------------------------------+---------------------
Babel                                         | 95629ms

Slowest Trees (cumulative)                    | Total (avg)
----------------------------------------------+---------------------
Babel (28)                                    | 96269ms (3438 ms)

and after few changes it goes to

file changed site\components\site\carpets\neworderform-form\template.hbs

Build successful - 107532ms.

Slowest Trees                                 | Total
----------------------------------------------+---------------------
Babel                                         | 101065ms

Slowest Trees (cumulative)                    | Total (avg)
----------------------------------------------+---------------------
Babel (28)                                    | 101905ms (3639 ms)

This slowness only occurs when I am editing this file "site\components\site\carpets\neworderform-form\template.hbs" on any other change everything works as expected. I hope you still have my source code, just change few lines and see what are the build times for you. I am doing some rearrangements of the layout structure

[aalasolutions-zz]

Hi, I am adding DEBUG=babel* details below for slowness. As you can see neworderform-form/template.js is taking 2+ minutes and sometime 3+ minutes any other page edit is fast, how to further break this down?

$ DEBUG=babel* ember s
version: 2.4.2
Livereload server on http://localhost:49152
Serving on http://localhost:4200/
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Parse start +0ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Parse stop +587ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Start set AST +2ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: End set AST +1s
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Start module formatter init +1ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: End module formatter init +3ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Start transformer htmlbars-inline-precompile +2ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Finish transformer htmlbars-inline-precompile +350ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Start transformer builtin-pre +1ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Finish transformer builtin-pre +396ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Start transformer builtin-basic +2ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Finish transformer builtin-basic +428ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Start transformer builtin-advanced +1ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Finish transformer builtin-advanced +298ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Start transformer builtin-modules +2ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Finish transformer builtin-modules +771ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Start transformer builtin-trailing +2ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Finish transformer builtin-trailing +1s
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Generation start +2ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Generation end +3m

site/components/site/carpets/neworderform-form/component.js: line 824, col 25, 'refCarpetPND' is defined but never used.

1 error

===== 1 JSHint Error


Build successful - 184186ms.

Slowest Trees                                 | Total
----------------------------------------------+---------------------
Babel                                         | 165556ms

Slowest Trees (cumulative)                    | Total (avg)
----------------------------------------------+---------------------
Babel (29)                                    | 170778ms (5888 ms)

file added site\components\site\carpets\neworderform-form\template.hbs___jb_tmp___
file changed site\components\site\carpets\neworderform-form\template.hbs___jb_tmp___
file deleted site\components\site\carpets\neworderform-form\template.hbs
file deleted site\components\site\carpets\neworderform-form\template.hbs___jb_tmp___
file added site\components\site\carpets\neworderform-form\template.hbs
file added site\components\site\colors\colors-form\template.hbs___jb_tmp___
file changed site\components\site\colors\colors-form\template.hbs___jb_tmp___
file deleted site\components\site\colors\colors-form\template.hbs___jb_tmp___
file changed site\components\site\colors\colors-form\template.hbs
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Parse start +51s
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Parse stop +585ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Start set AST +2ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: End set AST +968ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Start module formatter init +1ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: End module formatter init +3ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Start transformer htmlbars-inline-precompile +1ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Finish transformer htmlbars-inline-precompile +260ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Start transformer builtin-pre +1ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Finish transformer builtin-pre +351ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Start transformer builtin-basic +2ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Finish transformer builtin-basic +408ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Start transformer builtin-advanced +2ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Finish transformer builtin-advanced +274ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Start transformer builtin-modules +1ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Finish transformer builtin-modules +717ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Start transformer builtin-trailing +1ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Finish transformer builtin-trailing +1s
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Generation start +1ms
  babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Generation end +2m
  babel [BABEL] lp2/site/components/site/colors/colors-form/template.js: Parse start +83ms
  babel [BABEL] lp2/site/components/site/colors/colors-form/template.js: Parse stop +34ms
  babel [BABEL] lp2/site/components/site/colors/colors-form/template.js: Start set AST +1ms
  babel [BABEL] lp2/site/components/site/colors/colors-form/template.js: End set AST +88ms
  babel [BABEL] lp2/site/components/site/colors/colors-form/template.js: Start module formatter init +1ms
  babel [BABEL] lp2/site/components/site/colors/colors-form/template.js: End module formatter init +3ms
  babel [BABEL] lp2/site/components/site/colors/colors-form/template.js: Start transformer htmlbars-inline-precompile +2ms
  babel [BABEL] lp2/site/components/site/colors/colors-form/template.js: Finish transformer htmlbars-inline-precompile +23ms
  babel [BABEL] lp2/site/components/site/colors/colors-form/template.js: Start transformer builtin-pre +1ms
  babel [BABEL] lp2/site/components/site/colors/colors-form/template.js: Finish transformer builtin-pre +32ms
  babel [BABEL] lp2/site/components/site/colors/colors-form/template.js: Start transformer builtin-basic +2ms
  babel [BABEL] lp2/site/components/site/colors/colors-form/template.js: Finish transformer builtin-basic +59ms
  babel [BABEL] lp2/site/components/site/colors/colors-form/template.js: Start transformer builtin-advanced +1ms
  babel [BABEL] lp2/site/components/site/colors/colors-form/template.js: Finish transformer builtin-advanced +29ms
  babel [BABEL] lp2/site/components/site/colors/colors-form/template.js: Start transformer builtin-modules +1ms
  babel [BABEL] lp2/site/components/site/colors/colors-form/template.js: Finish transformer builtin-modules +68ms
  babel [BABEL] lp2/site/components/site/colors/colors-form/template.js: Start transformer builtin-trailing +2ms
  babel [BABEL] lp2/site/components/site/colors/colors-form/template.js: Finish transformer builtin-trailing +111ms
  babel [BABEL] lp2/site/components/site/colors/colors-form/template.js: Generation start +0ms
  babel [BABEL] lp2/site/components/site/colors/colors-form/template.js: Generation end +346ms

Build successful - 143757ms.

Slowest Trees                                 | Total
----------------------------------------------+---------------------
Babel                                         | 138196ms

Slowest Trees (cumulative)                    | Total (avg)
----------------------------------------------+---------------------
Babel (29)                                    | 138958ms (4791 ms)

[aalasolutions-zz]

Now i have used

DEBUG=* DEBUG_LEVEL=debug ember s and there is nothing between ... so what can i do now???

 babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Generation start +2ms
 babel [BABEL] lp2/site/components/site/carpets/neworderform-form/template.js: Generation end +2m