1062668 - no-op mach build binaries takes around 3 seconds

Status: RESOLVED FIXED

(Firefox Build System :: General, defect)

Description

[Boris Zbarsky [:bzbarsky]]

Recent mbp with an SSD.

Timestamped log:

 0:00.22 /usr/bin/make -C /Users/bzbarsky/mozilla/vanilla/obj-firefox -j8 -s backend.RecursiveMakeBackend
 0:00.40 /usr/bin/make -j8 -s binaries
 0:00.76 From dist/sdk: Kept 0 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:00.77 From dist/public: Kept 0 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:00.78 From dist/private: Kept 0 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:00.82 From dist/idl: Kept 1101 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:00.88 From dist/bin: Kept 94 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:00.96 From dist/include: Kept 4218 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:02.31 From _tests: Kept 19508 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:02.43 make[1]: Circular memory/replace/dummy/target <- mozglue/build/target dependency dropped.
 0:02.96 make[3]: warning: -jN forced in submake: disabling jobserver mode.
 0:02.96 Note: rebuild with "/Applications/Xcode.app/Contents/Developer/usr/bin/make VERBOSE=1 " to show all compiler parameters.
 0:02.97 /Applications/Xcode.app/Contents/Developer/usr/bin/make[3]: Making `all' in `stubdata'
 0:02.98 /Applications/Xcode.app/Contents/Developer/usr/bin/make[3]: Making `all' in `common'
 0:03.03 /Applications/Xcode.app/Contents/Developer/usr/bin/make[3]: Making `all' in `i18n'
 0:03.09 /Applications/Xcode.app/Contents/Developer/usr/bin/make[3]: Making `all' in `tools'
 0:03.10 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `toolutil'
 0:03.11 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `ctestfw'
 0:03.12 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `makeconv'
 0:03.13 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `genrb'
 0:03.13 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `genbrk'
 0:03.14 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `gencnval'
 0:03.14 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `gensprep'
 0:03.15 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `icuinfo'
 0:03.16 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `genccode'
 0:03.16 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `gencmn'
 0:03.17 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `icupkg'
 0:03.17 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `pkgdata'
 0:03.18 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `gentest'
 0:03.19 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `gennorm2'
 0:03.19 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `gencfu'
 0:03.20 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `gendict'
 0:03.21 /Applications/Xcode.app/Contents/Developer/usr/bin/make[3]: Making `all' in `data'
 0:03.46 Note: rebuild with "/Applications/Xcode.app/Contents/Developer/usr/bin/make VERBOSE=1 all-local" to show all compiler parameters.
 0:03.99 cd include; /Applications/Xcode.app/Contents/Developer/usr/bin/make libs
 0:04.01 cd src; /Applications/Xcode.app/Contents/Developer/usr/bin/make libs
 0:04.01 mkdir: /Users/bzbarsky/mozilla/vanilla/obj-firefox/security/nss/lib/freebl: File exists
 0:04.02 cd builtins; /Applications/Xcode.app/Contents/Developer/usr/bin/make libs
 0:04.04 cd mangle; /Applications/Xcode.app/Contents/Developer/usr/bin/make libs
 0:04.06 cd legacydb; /Applications/Xcode.app/Contents/Developer/usr/bin/make libs

Note that for that run "time" claimed:

  12.514u 3.364s 0:04.63 342.7%   0+0k 0+97io 0pf+0w

so there's another 0.6 seconds hiding somewhere outside of the timestamps.

Comment 1

[Mike Hommey [:glandium]]

(In reply to Boris Zbarsky [:bz] from comment #0)
> Recent mbp with an SSD.
> 
> Timestamped log:
> 
>  0:00.22 /usr/bin/make -C /Users/bzbarsky/mozilla/vanilla/obj-firefox -j8 -s
> backend.RecursiveMakeBackend
>  0:00.40 /usr/bin/make -j8 -s binaries
>  0:00.76 From dist/sdk: Kept 0 existing; Added/updated 0; Removed 0 files
> and 0 directories.
>  0:00.77 From dist/public: Kept 0 existing; Added/updated 0; Removed 0 files
> and 0 directories.
>  0:00.78 From dist/private: Kept 0 existing; Added/updated 0; Removed 0
> files and 0 directories.
>  0:00.82 From dist/idl: Kept 1101 existing; Added/updated 0; Removed 0 files
> and 0 directories.
>  0:00.88 From dist/bin: Kept 94 existing; Added/updated 0; Removed 0 files
> and 0 directories.
>  0:00.96 From dist/include: Kept 4218 existing; Added/updated 0; Removed 0
> files and 0 directories.
>  0:02.31 From _tests: Kept 19508 existing; Added/updated 0; Removed 0 files
> and 0 directories.

We should at the very least skip _tests during mach build binaries.

>  0:02.43 make[1]: Circular memory/replace/dummy/target <-
> mozglue/build/target dependency dropped.
>  0:02.96 make[3]: warning: -jN forced in submake: disabling jobserver mode.
>  0:02.96 Note: rebuild with
> "/Applications/Xcode.app/Contents/Developer/usr/bin/make VERBOSE=1 " to show
> all compiler parameters.
>  0:02.97 /Applications/Xcode.app/Contents/Developer/usr/bin/make[3]: Making
> `all' in `stubdata'
>  0:02.98 /Applications/Xcode.app/Contents/Developer/usr/bin/make[3]: Making
> `all' in `common'
>  0:03.03 /Applications/Xcode.app/Contents/Developer/usr/bin/make[3]: Making
> `all' in `i18n'
>  0:03.09 /Applications/Xcode.app/Contents/Developer/usr/bin/make[3]: Making
> `all' in `tools'
>  0:03.10 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making
> `all' in `toolutil'
>  0:03.11 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making
> `all' in `ctestfw'
>  0:03.12 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making
> `all' in `makeconv'
>  0:03.13 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making
> `all' in `genrb'
>  0:03.13 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making
> `all' in `genbrk'
>  0:03.14 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making
> `all' in `gencnval'
>  0:03.14 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making
> `all' in `gensprep'
>  0:03.15 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making
> `all' in `icuinfo'
>  0:03.16 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making
> `all' in `genccode'
>  0:03.16 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making
> `all' in `gencmn'
>  0:03.17 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making
> `all' in `icupkg'
>  0:03.17 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making
> `all' in `pkgdata'
>  0:03.18 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making
> `all' in `gentest'
>  0:03.19 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making
> `all' in `gennorm2'
>  0:03.19 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making
> `all' in `gencfu'
>  0:03.20 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making
> `all' in `gendict'
>  0:03.21 /Applications/Xcode.app/Contents/Developer/usr/bin/make[3]: Making
> `all' in `data'
>  0:03.46 Note: rebuild with
> "/Applications/Xcode.app/Contents/Developer/usr/bin/make VERBOSE=1
> all-local" to show all compiler parameters.
>  0:03.99 cd include; /Applications/Xcode.app/Contents/Developer/usr/bin/make
> libs
>  0:04.01 cd src; /Applications/Xcode.app/Contents/Developer/usr/bin/make libs
>  0:04.01 mkdir:
> /Users/bzbarsky/mozilla/vanilla/obj-firefox/security/nss/lib/freebl: File
> exists
>  0:04.02 cd builtins;
> /Applications/Xcode.app/Contents/Developer/usr/bin/make libs
>  0:04.04 cd mangle; /Applications/Xcode.app/Contents/Developer/usr/bin/make
> libs
>  0:04.06 cd legacydb;
> /Applications/Xcode.app/Contents/Developer/usr/bin/make libs
>
> Note that for that run "time" claimed:
> 
>   12.514u 3.364s 0:04.63 342.7%   0+0k 0+97io 0pf+0w
> 
> so there's another 0.6 seconds hiding somewhere outside of the timestamps.

That probably comes from the fact that there is no "build is finished" message when doing mach build binaries.

So, part of this is _tests, as mentioned above, another part is a conscious regression from bug 1043862. Eventually, we'll come back to using the same trick as before. And yet another part is from the fact that mach build binaries now also recurses icu and nss, which it didn't do before.

The first is actionable now.

Comment 2

[Mike Hommey [:glandium]]

Attachment: Only process the "include" install manifest when invoking the binaries target

Comment 3

[Mike Hommey [:glandium]]

Comment on attachment 8483927 [details] [diff] [review]
Only process the "include" install manifest when invoking the binaries target

Boris, can you paste a new timestamped log with this patch applied?

Comment 4

[Mike Hommey [:glandium]]

Comment on attachment 8483927 [details] [diff] [review]
Only process the "include" install manifest when invoking the binaries target

Mmmm in fact forget it, that doesn't remove _tests.

Comment 5

[Mike Hommey [:glandium]]

> That probably comes from the fact that there is no "build is finished" message
> when doing mach build binaries.

Actually, there is, but it's not timestamped.

Comment 6

[Mike Hommey [:glandium]]

Attachment: Only process the "include" install manifest when invoking the binaries target

Comment 7

[Mike Hommey [:glandium]]

Attachment: Add a timestamp to the message mach prints to indicate the end of the build

Comment 8

[Boris Zbarsky [:bzbarsky]]

Comment on attachment 8483930 [details] [diff] [review]
Only process the "include" install manifest when invoking the binaries target

With this patch:

 0:00.21 /usr/bin/make -C /Users/bzbarsky/mozilla/vanilla/obj-firefox -j8 -s backend.RecursiveMakeBackend
 0:00.40 /usr/bin/make -j8 -s binaries
 0:00.87 From dist/include: Kept 4218 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:00.99 make[1]: Circular memory/replace/dummy/target <- mozglue/build/target dependency dropped.
 0:01.51 make[3]: warning: -jN forced in submake: disabling jobserver mode.
 0:01.52 Note: rebuild with "/Applications/Xcode.app/Contents/Developer/usr/bin/make VERBOSE=1 " to show all compiler parameters.
 0:01.53 /Applications/Xcode.app/Contents/Developer/usr/bin/make[3]: Making `all' in `stubdata'
 0:01.53 /Applications/Xcode.app/Contents/Developer/usr/bin/make[3]: Making `all' in `common'
 0:01.59 /Applications/Xcode.app/Contents/Developer/usr/bin/make[3]: Making `all' in `i18n'
 0:01.65 /Applications/Xcode.app/Contents/Developer/usr/bin/make[3]: Making `all' in `tools'
 0:01.66 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `toolutil'
 0:01.67 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `ctestfw'
 0:01.68 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `makeconv'
 0:01.68 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `genrb'
 0:01.69 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `genbrk'
 0:01.70 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `gencnval'
 0:01.71 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `gensprep'
 0:01.71 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `icuinfo'
 0:01.72 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `genccode'
 0:01.72 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `gencmn'
 0:01.73 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `icupkg'
 0:01.73 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `pkgdata'
 0:01.74 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `gentest'
 0:01.74 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `gennorm2'
 0:01.75 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `gencfu'
 0:01.76 /Applications/Xcode.app/Contents/Developer/usr/bin/make[4]: Making `all' in `gendict'
 0:01.77 /Applications/Xcode.app/Contents/Developer/usr/bin/make[3]: Making `all' in `data'
 0:01.99 Note: rebuild with "/Applications/Xcode.app/Contents/Developer/usr/bin/make VERBOSE=1 all-local" to show all compiler parameters.
 0:02.50 cd include; /Applications/Xcode.app/Contents/Developer/usr/bin/make libs
 0:02.52 mkdir: /Users/bzbarsky/mozilla/vanilla/obj-firefox/security/nss/lib/freebl: File exists
 0:02.52 cd src; /Applications/Xcode.app/Contents/Developer/usr/bin/make libs
 0:02.52 cd builtins; /Applications/Xcode.app/Contents/Developer/usr/bin/make libs
 0:02.53 cd mangle; /Applications/Xcode.app/Contents/Developer/usr/bin/make libs
 0:02.57 cd legacydb; /Applications/Xcode.app/Contents/Developer/usr/bin/make libs
Your build was successful!
10.530u 2.892s 0:03.13 428.7%   0+0k 11+1286io 0pf+0w

which is a good bit better!

Comment 9

[Mike Hommey [:glandium]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/7dac4acfe611
https://hg.mozilla.org/integration/mozilla-inbound/rev/4ec0be60b1cc

Comment 10

[Mike Hommey [:glandium]]

And a fixup:
https://hg.mozilla.org/integration/mozilla-inbound/rev/1231f95f48a7

Comment 11

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/7dac4acfe611
https://hg.mozilla.org/mozilla-central/rev/4ec0be60b1cc
https://hg.mozilla.org/mozilla-central/rev/1231f95f48a7

Comment 12

[BugBot [:suhaib / :marco/ :calixte]]

The leave-open keyword is there and there is no activity for 6 months.
:glandium, maybe it's time to close this bug?

Comment 13

[Mike Hommey [:glandium]]

What do you think, Greg?

Comment 14

[Chris Manchester (limited bugmail, email directly)]

Quite a few improvements and changes have landed since the patches in this bug, we can track new work in new bugs.