Dramatically slow rebuild times against a single file touch

[ghost]

I am currently profiling / adding temporal instrumentation debug console logs to several broccoli plugins in my project in order to find the cause of horribly slow rebuild times (2minutes).

I am particularly looking at 20s to 35s seconds in between handling input trees (adding up to a 1m of the build process). The suspects are:

• Funnel.prototype.read
• Funnel.prototype.handleReadTree
• Funnel.prototype.cleanup.

What I am trying to understand is why does Broccoli use up to 30s in average to process input trees when I touch just a single file in my app? :sos:

[rwjblue]

It seems somewhat unlikely that this is the result of an issue with broccoli-funnel (but definitely still possible). Can you share the results of the slow trees logging? What does your Brocfile.js look like? What are the input options to the Funnel instance that is slow? How large are your input trees (both by file size and file count)?

Most likely this is due to some trees improperly invalidating the tree (and not caching). The recent refactor towards broccoli-plugin and the newer API's will allow a static dependency graph (therefore allowing us to prevent calling .read on all trees, rather only call .build on those trees whose inputs have changed).

[ghost]

By inspecting console traces I ended up in Broc's builder.js where Funnel.proto.read is used several times.

I should have specified that this is an ember-cli app and my Brocfile is pretty basic:

var EmberApp = require('ember-cli/lib/broccoli/ember-app');
var environment = EmberApp.env();

var emberCliConfig = {
  fingerprint: { enabled: false },
  storeConfigInMeta: false
};

var app = new EmberApp(emberCliConfig);

app.import(/*VENDOR INTERNATIONALIZATION JAVASCRIPTS'*/);

app.import(/* BOWER COMPONENTS (moment, jquery ui, antiscroll, fastclick, wanakana, font-awesome)*/)
app.import(/* SPECIFIC APP ICONS */)

I am also on OS X, Windows and Linux, but only on OS X is 2 minutes in average. It's still slow by human standards everywhere else though. :laughing:

How large are your input trees (both by file size and file count)

How can I determine this?

[rwjblue]

I should have specified that this is an ember-cli app and my Brocfile is pretty basic:

It may seem basic, but your Brocfile is quite complex (take a look at what ember-cli/lib/broccoli/ember-app.js is doing).

How large are your input trees (both by file size and file count)

How can I determine this?

Check the size on disk of the directory that is used for the slow instance of broccoli-funnel, look at its size and number of files.

[ghost]

If it seems basic, it should be basic. Whatever magic ember-cli is doing is not the result of good design IMO :stuck_out_tongue_winking_eye:.

I commented those strings due to privacy reasons, but we are talking about no more than 5 bower components, including jQuery UI :confused:

The number of directories inside tmp is relatively large, around 200 MB megabytes.

One more thing I just noticed (this is important) is that the tmp dir on a mbp without SSD is showing tons of unremoved tree_merger_tmp_des... directories that add up to 170 MB, while the same directory on a mbp with SSD is correctly cleaned up to a few bytes.

[rwjblue]

You don't mention SSD at all in your description. SSD's will be much faster than HDD's for the same CPU/mem setup.

[rwjblue]

Also, you can safely rm -rf tmp to clear the temp folders if cleanup wasn't completed properly.

[ghost]

My bad, but the difference is too large. We are talking about 4s VS 2~3 minutes.

Also, what is with these tree_merger_tmp_des directories not getting cleaned up on the slow mbps?

One more thing, even if I clean up tmp the builds don't improve more than a 10 percent.

[rwjblue]

My bad, but the difference is too large. We are talking about 4s VS 2~3 minutes.

Every stage in a broccoli pipeline is writing to disk, in an ember-cli build there are likely at least 20-30 stages that have to be gone through. That leads to massively different results between HDD and SDD (do to I/O throughput).

[ghost]

@raytiley You may be right, you are probably right, but do you hav any hints regarding the tree_merger_tmp_dest directories not getting cleaned up only on regular HDD mbp?

Why is Broccoli only cleaning up on SDDs?

[stefanpenner]

@rwjblue fyi this is already being tracked on https://github.com/ember-cli/ember-cli/issues/4460

[ghost]

@stefanpenner Thanks, but there is no mention about tmp not getting cleaned up correctly on HDD mbps in the link you have provided.

Why is Broccoli only cleaning up on SDDs?

[stefanpenner]

@stefanpenner Thanks. I would appreciate if you could provide an answer or any hints regarding:

Why is Broccoli only cleaning up on SDDs?

if cleanup isn't happening it should be uniform regardless of device type. The only thing that could cause a difference would be differences in the underlying FS. Which are likely to not differ between SSD / HDD

[ghost]

@stefanpenner Both are last generation mbps with exactly the same configuration. The only difference is one has flash storage and the other a regular HDD. The fact of the matter remains, the HDD ones (3 machines are presenting the same issue) are not getting properly cleaned. Have you had this happen to you before? Any hints?

BTW I have added instrumentation to several modules to help me track this down and positively concluded the bottlenecks occur in calls to Funnel.proto.read in Broc#builder. I hope that helps :disappointed_relieved:

One more thing:

Every stage in a broccoli pipeline is writing to disk, in an ember-cli build there are likely at least 20-30 stages that have to be gone through. That leads to massively different results between HDD and SDD (do to I/O throughput).

You as another core member may have your own opinion on the subject, or perhaps agree with @rwjblue? Do you think the only problem is due to SDD vs HDD? Or could there be bugs somewhere else?

Thanks for your time and sorry for creating so many issues lately!

EDIT: I don't think the problem is there, but have you ever considered replacing RSVP with bluebird for a probably faster promise implementation? Don't think that's going to happen anytime soon anyway.

[stefanpenner]

but have you ever considered replacing RSVP with bluebird for a probably faster promise implementation?

they are actually extremely close in performance and in some scenarios RSVP is actually faster. That being said, i do believe over all bluebird is an impressive lib, and in some cases does go the extra mile to carve out additional ounces of perf.

I am a-bit confused, I have provided context on how to resolve the issue (as requested), but it appears you are disregarding my suggestions. Which is frustrating, as you explicitly requested it, I spent the time explaining it, but you are just disregarding it.

[stefanpenner]

tree_merger_tmp_dest directories not getting cleaned up only on regular HDD mbp?

I believe this is actually the result of users doing <ctrl-c> skipping the cleanup. The concept of async finally is non-existent in node. (likely because it is inherently complex topic) We likely need to build a queue of work we must ensure has been pruned on process exist. In that handler, we will have to resort to sync (non-async) removal of contents.

We should not blindly prune all of tmp as other caches and state from other runs may also be present. But maybe better compartmentalization of tmp will result in simply purge on exist strategies.

This explicitly should has nothing to do with funnel.

[stefanpenner]

If you are legitimately interested in helping, are are able to commit to some reasonable amount of work. I can jump on a google hangout and brain dump as more required context as possible.

But only request that if you are serious about contributing.

[ghost]

I am not disregarding anything, I am digesting everything. Let it settle in :smile:

Thanks, I am definitely interested in helping, although I see ember-cli as a problem right now because it's frustrated to my team, I do find it's a complex piece of an even more complex puzzle and I've taken more than a handful of ideas that I hope to implement in Fly at some point. While I did find the lack of instrumentation in Funnel and Broc#builder annoying at least it's instrumented at all!

I am super busy at work at the moment (plus it's 4 AM here in Tokyo), but if you are still available during the weekend let's ghangout Sat or Sun, anytime.

EDIT: ember-cli/ember-cli/issues/4543 :+1:

[stefanpenner]

I am super busy at work at the moment (plus it's 4 AM here in Tokyo), but if you are still available during the weekend let's hangout Sat or Sun, anytime

Likely the following weekend will work, this next weekend I have family in town. But we can play it by ear, stefan.penner@gmail.com is my hangout email.

[ghost]

No problem. I will make the time then for this and thanks.

[ghost]

I believe this is actually the result of users doing skipping the cleanup

BTW this is not the problem right now. I send the SIGINT only once and wait. I even added instrumentation to .cleanup after the promise is resolved and I get the rimraf events logged to the console.

broccoli-fun: ready to rimraf / /Users/b/dev/.../tmp/funnel-dest_LzJntx.tmp / +1ms
...

[stefanpenner]

It is possibly a timing issue, do to how slow HDD would be, manifesting as an early exit? Either before or during rimraf's thing. This seems strange, but \o/

[ghost]

It is possibly a timing issue, do to how slow HDD would be, manifesting as an early exit? Either before or during rimraf's thing. This seems strange, but \o/

Interesting. I will research how to prevent this and post here my findings. Thanks.

[stefanpenner]

Interesting. I will research how to prevent this and post here my findings. Thanks.

Awesome, that would be handy.

[stefanpenner]

broccoli-filter is also known to leak its cache over time. https://github.com/caitp/cauliflower-filter/issues/12 mitigates this, and will benefit others once upstreamed into broccoli-filter (someone just needs to doit)

[ghost]

Can we can get Broc's author @joliss to comment on this:

Every stage in a broccoli pipeline is writing to disk, in an ember-cli build there are likely at least 20-30 stages that have to be gone through. That leads to massively different results between HDD and SDD (do to I/O throughput).

How massive are these differences? (minutes?) and have you investigated a viable solution?

Thanks.

[rwjblue]

Can we can get Broc's author @joliss to comment on this

For what purpose? What I said is correct, pinging everyone under the sun is unlikely to result in anything but annoying people that are working hard to solve these problems.

How massive are these differences? (minutes?)

Feel free to test and report back.

and have you investigated a viable solution?

Yes, we switched to using symlinks a while back which was a very large improvement, but writing anything to disk is slower (by quite a bit) on HDD vs SSD. Also, the dynamic nature of the current Broccoli pipeline forces all plugins to be re-read for every rebuild (even if its input trees have not changed), that is being fixed with the refactor towards using broccoli-plugin as a base class for all plugins.

[ghost]

@rwjblue

Also, the dynamic nature of the current Broccoli pipeline forces all plugins to be re-read for every rebuild (even if its input trees have not changed), that is being fixed with the refactor towards using broccoli-plugin as a base class for all plugins.

Thanks, this information will be useful to other devs that have the same problem. One more thing:

Broccoli pipeline forces all plugins to be re-read for every rebuild (even if its input trees have not changed),

So, Broc will read, compile / transform and rewrite to disk on every file touch?

[stefanpenner]

So, Broc will read, compile / transform and rewrite to disk on every file touch?

no, for more information please read http://www.solitr.com/blog/2014/02/broccoli-first-release/ which is linked from https://github.com/broccolijs/broccoli#broccoli

This issue seems to have gone way off topic.

[ghost]

@stefanpenner

no, for more...

So how should I interpret @rwjblue's:

Broccoli pipeline forces all plugins to be re-read for every rebuild (even if its input trees have not changed),

It seems my understanding was incorrect :disappointed_relieved: , so can you rephrase that for me?

And one more thing, so, I cleaned up the tmp directory in both machines, rebuilt, touch a file

touch app/app.coffee

and finally compared the state of the tmp directory in both the SSD and HDD mbps. Needless to say, all machines are running the same project and have matching configurations. I know the configurations are the same because I used the same script to setup the macs.

The results were the SSD lists way more directories and that they both have quite different directory structures.

So, while having a SSD certainly speeds things up, this data suggests ember-cli or broccoli is doing something quite different in both machines.

I have removed the random strings from the result and sorted them both by repeated items:

SSD MBP	HDD MBP
tree_merger-tmp_dest_dir (298)	tree_merger-tmp_dest_dir (189)
reexporter-tmp_cache_dir (14)	reexporter-tmp_cache_dir (10)
funnel-cache_path (105)
funnel-dest (79)	funnel-dest (105)
core_object-output_path (10)	core_object-output_cache (10)
babel-cache_path (10)	babel-cache_path (10)
babel-output_path (9)
coffee_script_filter-tmp_cache_dir (12)	coffee_script_filter-tmp_cache_dir (12)
core_object-cache_path (7)	core_object-cache_path (8)
template_compiler-tmp_cache_dir (6)	template_compiler-tmp_cache_dir (6)
caching-writer-dest-dir (10)	caching-writer-dest-dir (6)
class-tmp_cache_dir (8)	class-tmp_cache_dir (4)
broccoli_merge_trees-cache_path (6)
broccoli_merge_trees-input_base_path (6)
broccoli_merge_trees-output_path (6)
jshinter-tmp_cache_dir (4)	jshinter-tmp_cache_dir (4)
	read_compat-cache_path (4)
	read_compat-input_base_path (4)
	read_compat-output_path (4)
custom_replace-tmp_dest_dir (4)	custom_replace-tmp_dest_dir (4)
core_object-dest_dir (4)	core_object-dest_dir (2)
core_object-input_staging (4)	core_object-input_staging (2)
sass_compiler-tmp_cache_dir	sass_compiler-tmp_cache_dir (1)
static_compiler-tmp_dest_dir	static_compiler-tmp_dest_dir (1)
config_loader-cache_path (3)	config_loader-tmp_cache_dir (1)
core_object-output_cache (3)

But why...? :sweat_smile:

[stefanpenner]

The article I linked to provides the information you ask for.

The diff in temp did is quite strange can you:

• share a simplified repo that demonstrates the same issue
• do a diff of the two node_module trees to confirm they are not different

[ghost]

Thanks. It's going to be difficult or impossible to create a repo that can replicate the issue unless the same occurs for a blank project, but I can definitely comply to the second request, I will get around that ASAP.

[stefanpenner]

It's going to be difficult or impossible to create a repo that can replicate the issue unless the same occurs for a blank project,

it should be easy to test if a blank project, or a project with the same public addons/modules but very default app code.

[ghost]

Yes, that I can do with the help of a co-worker on Monday. BTW the numbers in parentheses in the table above are the number of repetitions that directory was occurring inside the tmp directory. I removed the random part as that will obviously be different.

By the way, instrumenting quicktemp showed that was one of the main bottlenecks in our application. It's crazy :laughing:

[stefanpenner]

By the way, I instrumented quicktemp and found it to be one of the main bottlenecks in our application, not the only one, though.

teardown or setup? I assume teardown.

[ghost]

Do you mean during the cleanup process? I saw a massive number of instances during cleanup, but it is during setup (startup) and (rebuilds) that the thing gets stuck, or after instrumentation, an infinite continuum of quicktemp.

The others were broc-writer or broc-filter for sure.

[stefanpenner]

quicktemp on setup seems quite strange, it should just me making a single folder with some entropy for the name.

Could we be starving for entropy at the part in time? Seems unlikely, but easy to by instrumenting this function:https://github.com/sasaplus1/mktemp/blob/master/lib/mktemp.js#L142 and counting the iterations of this loop: https://github.com/sasaplus1/mktemp/blob/master/lib/mktemp.js#L146-L158

Can you confirm it is actually setup that is the issue?

If teardown is the problem, in theory each platform (FS) typically has an ultra performant way to purge large directory trees. Although the solutions may be not easy to bundle for all node users, it may be interesting to explore. A quick example: http://serverfault.com/questions/183821/rm-on-a-directory-with-millions-of-files/328305#328305

[ghost]

@stefanpenner Thanks fro the ServerFault link, went straight to my bookmark list, a lot of so much good stuff in there.

The problem is definitely during the rebuilds, cleanup/teardown is done in no time. I instrumented that module too, didn't get the number of iterations, just before/after it was done as I was adding debug lines everywhere and running out of time, but that was one of the hubs.

Also, the ember-coffee-script/node_modules/broc-filter was another bottleneck taking 8 or 10 seconds to complete.

[stefanpenner]

The problem is definitely during the rebuilds, cleanup/teardown is done in no time.

Then why did you mention it.

By the way, instrumenting quicktemp showed that was one of the main bottlenecks in our application. It's crazy :laughing:

[stefanpenner]

Ug, this conversation has returned to the points I raised in the original issue. Please only report new findings, that are very much validated.

If you are looking to help, a good place to start is: https://github.com/ember-cli/ember-cli/issues/4562

[ghost]

I didn't. You asked me whether it was teardown or build and I said that they show up during teardown too, but it is the build/rebuild were the problem is.

[stefanpenner]

@bucaran

By the way, instrumenting quicktemp showed that was one of the main bottlenecks in our application. It's crazy :laughing:

this lead me to believe quicktemp was an issue, then it appears it is not? Or have i misunderstood.

[ghost]

Well, I am not sure whether quicktemp is the only issue, but before the instrumentation we were blacking out for 20 or 30 secs, and after it we found out most of these black holes were spent over at quicktemp summer house.

[stefanpenner]

to cover up some of the extra merges happening in ember-cli, we now do a matcher aware walk https://github.com/broccolijs/broccoli-funnel/pull/29

Cuts the "includes based Funnel" example provided down from alot to just noise.

Future work will add the fast path for excludes as well https://github.com/broccolijs/broccoli-funnel/issues/31 But I'll do that when i encounter a scenario that needs it. JITPerf