Bootstrap takes 60 seconds to run even when nothing has changed

[edmorley]

STR:

1. Install nodejs 8.1.0 and yarn v0.24.6 under Ubuntu 16.04.
2. git clone https://github.com/mozilla-neutrino/neutrino-dev
3. cd neutrino-dev && git checkout 13adea32550de2f1eae9ae79f2980f8a2f6b5e82
4. yarn install (this installs oao v0.8.0)
5. yarn bootstrap (which runs oao bootstrap from the local node_modules)
6. yarn bootstrap

Expected:
The second time bootstrap is run, the duration is significantly less than the first, ideally <5-10s.

Actual:
The first bootstrap took 125 seconds (see https://emorley.pastebin.mozilla.org/9024429), the second still took 63 seconds (see https://emorley.pastebin.mozilla.org/9024430), even though it had nothing to do.

This also affects us on Travis, since it means caching the sub-package's node_modules gives little time saving (and in fact quite a disadvantage, given travis-ci/travis-ci#7898) - see neutrinojs/neutrino#248.

Do you have any ideas as to what might be causing this?

Many thanks!

[guigrpa]

Thanks for your report!

I'm not sure what's causing the long intervals in your case. I'm on OS X and oao bootstrap runs really fast on the monorepos I used it on (admittedly a bit smaller than Neutrino). Maybe yarn is not so optimised for Ubuntu? (it certainly isn't for Windows, for example).

Could you please check whether it's Phase 1 or Phase 2 of the second oao bootstrap that is the main contributor to delay?

While it won't help you speeding up CI times, you may want to use oao add/remove/upgrade to update subpackage dependencies, instead of a full oao bootstrap.

[edmorley]

Hi, thank you for the quick reply!

I'm on OS X and oao bootstrap runs really fast on the monorepos I used it on (admittedly a bit smaller than Neutrino)

How long do the first/second bootstraps take for Neutrino on your machine, using the STR from above? (So we can rule out platform as an issue)

Could you please check whether it's Phase 1 or Phase 2 of the second oao bootstrap that is the main contributor to delay?

From the timestamps in the pastebin linked above, it looks like phase 1 is taking 48 seconds and phase 2 is 14 seconds.

Of note for phase 1:

• adding up the total time reported by yarn in the sections of form "Done in 3.12s.", the yarn runtime is only 28 seconds out of the 48, meaning the oao overhead for phase 1 is 20 seconds, which seems quite high.
• the 28 seconds spent in yarn itself could also likely be reduced, since the log output from yarn for each package never says "success Already up-to-date.", implying that perhaps phase 2 from the prior invocation has invalidated yarns integrity hash. Would reversing the order of phase 1 and 2 help prevent this?

[guigrpa]

I confirm that I can reproduce your findings on OS X:

• First yarn bootstrap: 1:39 (pass 1) + 0:16 (pass 2) = 1:55
• Second yarn bootstrap: 0:34 (pass 1) + 0:15 (pass 2) = 0:49
  [a third time took 0:38, including ~0:15 again for pass 2]

I did another test replacing all executions of yarn xxx (yarn install and yarn link in this case, to be precise) with echo Hi. Total time? < 2 s. Hence, the overhead is not located in oao, or even in shelljs (which I use to execute commands), but in yarn itself.

Now, I could address some parallelisations, both for Pass 1 and Pass 2, but it may take a little while (a month at most, I guess). Right now I don't have much time… I'll keep you posted!

[edmorley]

Thank you for looking into this more.

I did another test replacing all executions of yarn xxx (yarn install and yarn link in this case, to be precise) with echo Hi. Total time? < 2 s. Hence, the overhead is not located in oao, or even in shelljs (which I use to execute commands), but in yarn itself.

Unless the yarn "done in X seconds" output is incorrect, I'm struggling to see where else the time is being spent. The test using echo won't have exposed any issues with the stdout/stderr processing performed here for example:

oao/src/utils/shell.js

Lines 67 to 74 in 3098ab0

	child.stdout.pipe(split()).on('data', (line) => {
	story.info(cmdName, `${prefix}${line}`);
	});
	child.stderr.pipe(split()).on('data', (line) => {
	if (line) story[errorLogLevel](cmdName, `${prefix}${line}`);
	});
	const { code, stdout, stderr } = await child;
	if (code !== 0) throw new Error(`Command returned non-zero exit code: ${cmd} [${code}]`);

Perhaps replacing yarn install/link with time yarn install/link might help confirm whether yarn's self-declared duration is accurate. In addition, it may be worth trying a run with the child.{stdout,stderr}.pipe(...) commented out.

[edmorley]

Profiling using 0x generated this flamegraph:
flamegraph.html.gz

At first glance I see storyboard taking 23% of the profile, inquirer 14% and oao/lib/utils/git.js 12%.

Steps for using 0x:

sudo apt-get install linux-tools-generic linux-tools-`uname -r`
sudo npm install -g 0x
./node_modules/.bin/oao clean
./node_modules/.bin/oao bootstrap
0x node ./node_modules/.bin/oao bootstrap
0x -c gen profile-2808/stacks.2808.out > flamegraph.html

[guigrpa]

Indeed, yarn's reported time seems to err on the low side:

neutrino-dev $ yarn
yarn install v0.24.5
[1/4] 🔍  Resolving packages...
success Already up-to-date.
✨  Done in 0.65s.

neutrino-dev $ time yarn
yarn install v0.24.5
[1/4] 🔍  Resolving packages...
success Already up-to-date.
✨  Done in 0.63s.

real	0m0.821s
user	0m0.832s
sys	0m0.092s

[guigrpa]

If all goes well, yarn links will all run in parallel in the upcoming release. Hopefully this will have a noticeable impact on your build times. I've seen quite an improvement when building my Storyboard monorepo.

[guigrpa]

yarn installs will also run in parallel, except if you explicitly disable it with a --no-parallel flag.

[guigrpa]

Just released v0.8.3:

• yarn link now runs always in parallel
• yarn install now runs in parallel by default (disable it with oao bootstrap --no-parallel)

Perf comparison:

• Neutrino 1st install: from 120 s to 30 s
• Neutrino 2nd install: from 36-45 s to 10 s
• Storyboard 2nd install: from 22 s to 5 s

cc @eliperelman

[eliperelman]

Wow! 👏

I'll give this a shot asap!

[guigrpa]

@eliperelman Btw, I'm also seeing the error reported by @edmorley in neutrinojs/neutrino#251, so it shouldn't be Lerna's fault.

[eliperelman]

@guigrpa didn't oao used to symlink peerDependencies if they were part of packages?

[eliperelman]

Ah I see now, for some reason when I ran oao bootstrap, all the peerDependencies were removed from my packages' package.jsons.

[eliperelman]

If there is a failure during the bootstrap process, the package.jsons aren't reverted and end up being replaced with versions that exclude the local peerDependency.

[eliperelman]

@guigrpa also, if I remove everything:

rm -rf node_modules yarn.lock packages/*/node_modules packages/*/yarn.lock

I constantly fail the bootstrap process, most likely because of some concurrency issue trying to install the same package multiple times with possibly different hashes. These could be related:

yarnpkg/yarn#2629
yarnpkg/yarn#1058
yarnpkg/yarn#1916

[guigrpa]

Do you believe it is an issue with yarn then?

(If it can be of any help, you can temporarily disable parallelism in the yarn installs by running oao bootstrap --no-parallel — it will still get you some perf improvements due to parallel yarn links)

[guigrpa]

In any case, I will investigate why package.jsons are not reverted if an error occurs. In principle, this was handled by the code.

[eliperelman]

My guess is the problems were caused by too much concurrency and yarn wasn't able to handle it and caused some conflicts. You might be able to replicate by checking out neutrino and removing all node_modules and yarn.locks.

[guigrpa]

Yes, I've had no problem reproducing it. It happens systematically on Neutrino. Strangely enough, it doesn't happen on Storyboard, which has around 14 subpackages and lots of cross-dependencies.

Regarding the fact that oao didn't recover the original package.jsons, I've found the problem. When one of the branches of the parallel bootstrap failed, the program terminated too soon. I have released a patch (v0.8.4) that waits for all pending promises to resolve before throwing the error.

[guigrpa]

Have you had a look at yarn's issues with concurrency? Do you think they're widespread? Would you recommend switching parallel bootstrap off (except for yarn links, which have no issues) by default?

[ericclemmons]

Oh, FYI, I had a similar issue and the reason is that I had "postinstall": "oao bootstrap".

It was basically cyclical. What I learned was:

• oao should be global, not local.
• The root should not run oao bootstrap at all.

[guigrpa]

@edmorley @eliperelman oao now has support for Yarn Workspaces; you can try it out in oao@next (0.10.0 prereleases). oao detects the workspaces property in the monorepo package.json file and automatically uses this feature of Yarn. In this mode:

• oao bootstrap just does yarn install
• oao add|remove|upgrade goes into the particular subpackage folder and runs the corresponding yarn add|remove|upgrade command
• Subpackages are defined by the workspaces property, but also take into account the --ignore-src flag

Note that workspaces are still experimental in yarn (0.28+) and behind a flag (yarn config set workspaces-experimental true). They also may have some limitations wrt. the non-workspace-based behaviour of yarn, so you may want to experiment to see what works better for you.

In principle, this would solve both the performance issue (no overhead wrt. bare-bones yarn) and the concurrency issue described above, so I'm closing this issue. Please send your feedback on the new oao feature!