995762 - moz.build processing could take as much as 15 minutes!

Status: RESOLVED FIXED

(Firefox Build System :: General, defect)

Description

[(no longer active)]

I just rebased on top of master and did a ./mach build, and here's what happened:

 0:17.57 checking for LC_MESSAGES... (cached) yes
 0:17.57 checking for localeconv... (cached) yes
 0:17.64 checking for __cxa_demangle... (cached) yes
 0:17.65 checking for -pipe support... yes
 0:17.66 checking whether C compiler supports -fprofile-generate... yes
 0:17.68 checking for correct overload resolution with const and templates... no
 0:17.69 checking for tm_zone tm_gmtoff in struct tm... (cached) yes
 0:17.74 checking what kind of list files are supported by the linker... filelist
 0:17.76 checking for posix_fadvise... (cached) no
 0:17.77 checking for posix_fallocate... (cached) no
 0:17.80 checking for setlocale... (cached) yes
 0:17.80 checking for localeconv... (cached) yes
 0:17.81 creating ./config.status
 0:18.02 Reticulating splines...
15:38.34 Finished reading 2541 moz.build files in 1.91s
15:38.34 Processed into 6927 build config descriptors in 4.01s
15:38.34 Backend executed in 914.20s
15:38.34 2573 total backend files; 3 created; 40 updated; 2530 unchanged; 0 deleted; 238 -> 1025 Makefile
15:38.34 Total wall time: 920.32s; CPU time: 919.51s; Efficiency: 100%; Untracked: 0.20s
15:38.76 From dist/public: Kept 0 existing; Added/updated 0; Removed 0 files and 0 directories.
15:38.77 From dist/sdk: Kept 0 existing; Added/updated 0; Removed 26 files and 4 directories.
15:38.82 From dist/private: Kept 0 existing; Added/updated 0; Removed 155 files and 2 directories.
15:39.45 From dist/bin: Kept 85 existing; Added/updated 0; Removed 3432 files and 356 directories.
15:39.49 From dist/idl: Kept 1138 existing; Added/updated 1; Removed 0 files and 0 directories.
15:39.66 From dist/include: Kept 3979 existing; Added/updated 4; Removed 192 files and 6 directories.
15:41.00 From _tests: Kept 17373 existing; Added/updated 13; Removed 764 files and 110 directories.
15:41.24 cd include; /Applications/Xcode.app/Contents/Developer/usr/bin/make private_export
15:41.24 Creating /Users/ehsan/moz/src/obj-ff-dbg.noindex/dist/private/nss
15:41.25 cd mangle; /Applications/Xcode.app/Contents/Developer/usr/bin/make private_export
15:41.27 Creating /Users/ehsan/moz/src/obj-ff-dbg.noindex/dist/private/dbm

Not sure at all what happened there.  Previously I was on https://hg.mozilla.org/mozilla-central/rev/d68c74e48075, and now I am on https://hg.mozilla.org/mozilla-central/rev/ebdf2740dc3e.

Comment 1

[(no longer active)]

Attachment: Full build log

Comment 2

[(no longer active)]

Attachment: git diff origin/master

This is all of my local modifications

Comment 3

[(no longer active)]

To make things more interesting, after a clobber I could not reproduce.  My tree was fully built before the rebase of course.

Comment 4

[Michael Shal [:mshal]]

Attachment: profile-bad.png

I can reproduce this by switching between git commits d506740 and efc5497c, and just running './config.status' in between. froydnj pointed out in IRC that it appears to be related to file diffing. Attached is a profile graph from a bad run (that takes ~3 minutes instead of the usual ~9 seconds).

The slow runtime goes away if I force self._capture_diff to False in FileAvoidWrite(). I'm still looking at why exactly the diffing is so slow - just thought I'd mention it in case gps would know off-hand :)

Comment 5

[Michael Shal [:mshal]]

At least in the particular case of the two commits I tested, the slow runtime is all because of diffing all-tests.json, which is ~15MB.

Comment 6

[Michael Shal [:mshal]]

Attachment: 0001-Bug-995762-don-t-evaluate-diff-unless-it-s-needed.patch

It seems the problem is a severe performance limitation of difflib, and I'm not sure how easy that will be to fix. In the meantime we can avoid evaluating the diff generator unless --diff is specified. The '\n'.join() was causing the immediate evaluation even if --diff wasn't used, so this patch moves the join to config_status.py where the diff is displayed.

Note that fh.diff is also used in BackendMakeFile:diff(), but I don't know if that's actually used.

Comment 7

[Gregory Szorc [:gps]]

Comment on attachment 8406280 [details] [diff] [review]
0001-Bug-995762-don-t-evaluate-diff-unless-it-s-needed.patch

Review of attachment 8406280 [details] [diff] [review]:
-----------------------------------------------------------------

Generators FTW! Great patch.

Comment 8

[Michael Shal [:mshal]]

Unfortunately my patch breaks 'make check' due to 'self.assertIsInstance(faw.diff, unicode)' lines in test_util.py, since the generator object doesn't count as unicode. Should I just delete those assertIsInstance lines? Or is there a better way to fix that?

Comment 9

[Michael Shal [:mshal]]

Attachment: 0001-Bug-995762-don-t-evaluate-diff-unless-it-s-needed.patch

Assuming that removing those lines is ok, here's the new patch. It passes try this time: https://tbpl.mozilla.org/?tree=Try&rev=18d454d1d426

If you want me to fix the tests some other way just let me know!

Comment 10

[Gregory Szorc [:gps]]

Comment on attachment 8406853 [details] [diff] [review]
0001-Bug-995762-don-t-evaluate-diff-unless-it-s-needed.patch

Review of attachment 8406853 [details] [diff] [review]:
-----------------------------------------------------------------

::: python/mozbuild/mozbuild/test/test_util.py
@@ -132,2 @@
>              self.assertIn('-old', faw.diff)
>              self.assertIn('+new', faw.diff)

Oh, I'm surprised this still works!

I would rewrite this as:

diff = '\n'.join(faw.diff)
self.assertIn('-old', diff)
self.assertIn('+new', diff)

@@ -141,5 @@
>              faw = FileAvoidWrite(path, capture_diff=True)
>              faw.write('new')
>              faw.close()
>  
> -            self.assertIsInstance(faw.diff, unicode)

Ditto. Expand the diff inline.

Comment 11

[Michael Shal [:mshal]]

Attachment: 0001-Bug-995762-don-t-evaluate-diff-unless-it-s-needed-r-.patch

Updated with review comments, r+ carried forward.

Comment 12

[Michael Shal [:mshal]]

inbound: https://hg.mozilla.org/integration/mozilla-inbound/rev/a0aa1d05d7cf

Comment 13

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/a0aa1d05d7cf