Quantcast

moz.build processing time

classic Classic list List threaded Threaded
17 messages Options
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

moz.build processing time

Ehsan Akhgari
Here are the moz.build processing times on my machine when I add one
line to a LOCAL_INCLUDES in one moz.build file:

 0:02.97 Reticulating splines...
 0:37.16 Finished reading 3131 moz.build files in 23.09s
 0:37.16 Processed into 9325 build config descriptors in 3.62s
 0:37.16 RecursiveMake backend executed in 6.50s
 0:37.16   2951 total backend files; 0 created; 2 updated; 2949
unchanged; 0 deleted; 54 -> 1110 Makefile
 0:37.16 FasterMake backend executed in 0.50s
 0:37.16   12 total backend files; 0 created; 0 updated; 12 unchanged; 0
deleted
 0:37.16 Total wall time: 34.22s; CPU time: 16.20s; Efficiency: 47%;
Untracked: 0.50s


 0:37.89 Finished reading 3131 moz.build files in 21.90s
 0:37.89 Processed into 9327 build config descriptors in 3.82s
 0:37.89 RecursiveMake backend executed in 7.85s
 0:37.89   2951 total backend files; 0 created; 4 updated; 2947
unchanged; 0 deleted; 54 -> 1110 Makefile
 0:37.89 FasterMake backend executed in 0.59s
 0:37.89   12 total backend files; 0 created; 0 updated; 12 unchanged; 0
deleted
 0:37.89 Total wall time: 34.70s; CPU time: 17.70s; Efficiency: 51%;
Untracked: 0.55s

The clear offender is "reading moz.build files".  What's involved in
this process?  Is there some low hanging fruit for making it faster?
Are there things non-build developers can do (such as reducing the
number of moz.build files) that would help?

Is there any way for us to avoid reprocessing the world for every single
moz.build file change?

Thanks,
Ehsan
_______________________________________________
dev-builds mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-builds
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: moz.build processing time

Gregory Szorc-3
On Fri, Nov 18, 2016 at 3:50 PM, Ehsan Akhgari <[hidden email]> wrote:
Here are the moz.build processing times on my machine when I add one
line to a LOCAL_INCLUDES in one moz.build file:

 0:02.97 Reticulating splines...
 0:37.16 Finished reading 3131 moz.build files in 23.09s
 0:37.16 Processed into 9325 build config descriptors in 3.62s
 0:37.16 RecursiveMake backend executed in 6.50s
 0:37.16   2951 total backend files; 0 created; 2 updated; 2949
unchanged; 0 deleted; 54 -> 1110 Makefile
 0:37.16 FasterMake backend executed in 0.50s
 0:37.16   12 total backend files; 0 created; 0 updated; 12 unchanged; 0
deleted
 0:37.16 Total wall time: 34.22s; CPU time: 16.20s; Efficiency: 47%;
Untracked: 0.50s


 0:37.89 Finished reading 3131 moz.build files in 21.90s
 0:37.89 Processed into 9327 build config descriptors in 3.82s
 0:37.89 RecursiveMake backend executed in 7.85s
 0:37.89   2951 total backend files; 0 created; 4 updated; 2947
unchanged; 0 deleted; 54 -> 1110 Makefile
 0:37.89 FasterMake backend executed in 0.59s
 0:37.89   12 total backend files; 0 created; 0 updated; 12 unchanged; 0
deleted
 0:37.89 Total wall time: 34.70s; CPU time: 17.70s; Efficiency: 51%;
Untracked: 0.55s

The clear offender is "reading moz.build files".  What's involved in
this process?  Is there some low hanging fruit for making it faster?
Are there things non-build developers can do (such as reducing the
number of moz.build files) that would help?

Is there any way for us to avoid reprocessing the world for every single
moz.build file change?

Please tell us a bit more about your machine. Because on my machine...

Linux
$ ./mach build-backend
 0:00.08 /home/gps/src/firefox/obj-x86_64-pc-linux-gnu/_virtualenv/bin/python /home/gps/src/firefox/obj-x86_64-pc-linux-gnu/config.status
Reticulating splines...
Finished reading 3027 moz.build files in 3.79s
Processed into 9028 build config descriptors in 1.54s
RecursiveMake backend executed in 3.00s
  2829 total backend files; 0 created; 0 updated; 2829 unchanged; 0 deleted; 54 -> 1065 Makefile
FasterMake backend executed in 0.22s
  12 total backend files; 0 created; 0 updated; 12 unchanged; 0 deleted
Total wall time: 8.76s; CPU time: 7.26s; Efficiency: 83%; Untracked: 0.21s
 
Windows 10
$ ./mach build-backend
 0:00.55 c:/dev/src/firefox/obj-i686-pc-mingw32\_virtualenv\Scripts\python.exe c:/dev/src/firefox/obj-i686-pc-mingw32\config.status
Reticulating splines...
Finished reading 3041 moz.build files in 7.01s
Processed into 9841 build config descriptors in 3.19s
RecursiveMake backend executed in 3.81s
  2860 total backend files; 0 created; 1 updated; 2859 unchanged; 0 deleted; 62 -> 1069 Makefile
FasterMake backend executed in 0.38s
  11 total backend files; 0 created; 1 updated; 10 unchanged; 0 deleted
VisualStudio backend executed in 1.71s
Generated Visual Studio solution at c:/dev/src/firefox/obj-i686-pc-mingw32\msvc\mozilla.sln
Total wall time: 16.43s; CPU time: 16.43s; Efficiency: 100%; Untracked: 0.33s

The numbers seem to indicate your machine is a bit old or slow?

FWIW, bug 1308982 is on our radar for speeding up moz.build reading.

_______________________________________________
dev-builds mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-builds
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: moz.build processing time

Ehsan Akhgari
On 2016-11-18 7:22 PM, Gregory Szorc wrote:

> On Fri, Nov 18, 2016 at 3:50 PM, Ehsan Akhgari <[hidden email]
> <mailto:[hidden email]>> wrote:
>
>     Here are the moz.build processing times on my machine when I add one
>     line to a LOCAL_INCLUDES in one moz.build file:
>
>      0:02.97 Reticulating splines...
>      0:37.16 Finished reading 3131 moz.build files in 23.09s
>      0:37.16 Processed into 9325 build config descriptors in 3.62s
>      0:37.16 RecursiveMake backend executed in 6.50s
>      0:37.16   2951 total backend files; 0 created; 2 updated; 2949
>     unchanged; 0 deleted; 54 -> 1110 Makefile
>      0:37.16 FasterMake backend executed in 0.50s
>      0:37.16   12 total backend files; 0 created; 0 updated; 12 unchanged; 0
>     deleted
>      0:37.16 Total wall time: 34.22s; CPU time: 16.20s; Efficiency: 47%;
>     Untracked: 0.50s
>
>
>      0:37.89 Finished reading 3131 moz.build files in 21.90s
>      0:37.89 Processed into 9327 build config descriptors in 3.82s
>      0:37.89 RecursiveMake backend executed in 7.85s
>      0:37.89   2951 total backend files; 0 created; 4 updated; 2947
>     unchanged; 0 deleted; 54 -> 1110 Makefile
>      0:37.89 FasterMake backend executed in 0.59s
>      0:37.89   12 total backend files; 0 created; 0 updated; 12 unchanged; 0
>     deleted
>      0:37.89 Total wall time: 34.70s; CPU time: 17.70s; Efficiency: 51%;
>     Untracked: 0.55s
>
>     The clear offender is "reading moz.build files".  What's involved in
>     this process?  Is there some low hanging fruit for making it faster?
>     Are there things non-build developers can do (such as reducing the
>     number of moz.build files) that would help?
>
>     Is there any way for us to avoid reprocessing the world for every single
>     moz.build file change?
>
>
> Please tell us a bit more about your machine. Because on my machine...
>
> Linux
> $ ./mach build-backend
>  0:00.08
> /home/gps/src/firefox/obj-x86_64-pc-linux-gnu/_virtualenv/bin/python
> /home/gps/src/firefox/obj-x86_64-pc-linux-gnu/config.status
> Reticulating splines...
> Finished reading 3027 moz.build files in 3.79s
> Processed into 9028 build config descriptors in 1.54s
> RecursiveMake backend executed in 3.00s
>   2829 total backend files; 0 created; 0 updated; 2829 unchanged; 0
> deleted; 54 -> 1065 Makefile
> FasterMake backend executed in 0.22s
>   12 total backend files; 0 created; 0 updated; 12 unchanged; 0 deleted
> Total wall time: 8.76s; CPU time: 7.26s; Efficiency: 83%; Untracked: 0.21s
>  
> Windows 10
> $ ./mach build-backend
>  0:00.55
> c:/dev/src/firefox/obj-i686-pc-mingw32\_virtualenv\Scripts\python.exe
> c:/dev/src/firefox/obj-i686-pc-mingw32\config.status
> Reticulating splines...
> Finished reading 3041 moz.build files in 7.01s
> Processed into 9841 build config descriptors in 3.19s
> RecursiveMake backend executed in 3.81s
>   2860 total backend files; 0 created; 1 updated; 2859 unchanged; 0
> deleted; 62 -> 1069 Makefile
> FasterMake backend executed in 0.38s
>   11 total backend files; 0 created; 1 updated; 10 unchanged; 0 deleted
> VisualStudio backend executed in 1.71s
> Generated Visual Studio solution at
> c:/dev/src/firefox/obj-i686-pc-mingw32\msvc\mozilla.sln
> Total wall time: 16.43s; CPU time: 16.43s; Efficiency: 100%; Untracked:
> 0.33s
>
> The numbers seem to indicate your machine is a bit old or slow?

Hmm, my machine is a MacBook Pro (this is my main development machine).
It's a MacBook Pro (Retina, 15-inch, Mid 2014), 2.8Ghz processor, 16GB
Memory, 1TB APPLE SSD SM1024F, Running Sierra 10.12.1.

My machine wasn't entirely idle, I had things like a Terminal with a
bunch of vim's open, Nightly, Chrome, Thunderbird, LimeChat.  But these
numbers are in the usual ballpark I get.

> FWIW, bug 1308982 is on our radar for speeding up moz.build reading.

That's great!  I think that will help people like me a lot.  Thankfully
Chris seems to be currently working on it.

But I'm still not sure why we can't only re-process the moz.build file
that has changed...

Thanks,
Ehsan
_______________________________________________
dev-builds mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-builds
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: moz.build processing time

Mike Hommey
On Sat, Nov 19, 2016 at 04:12:22PM -0500, Ehsan Akhgari wrote:

> On 2016-11-18 7:22 PM, Gregory Szorc wrote:
> > On Fri, Nov 18, 2016 at 3:50 PM, Ehsan Akhgari <[hidden email]
> > <mailto:[hidden email]>> wrote:
> >
> >     Here are the moz.build processing times on my machine when I add one
> >     line to a LOCAL_INCLUDES in one moz.build file:
> >
> >      0:02.97 Reticulating splines...
> >      0:37.16 Finished reading 3131 moz.build files in 23.09s
> >      0:37.16 Processed into 9325 build config descriptors in 3.62s
> >      0:37.16 RecursiveMake backend executed in 6.50s
> >      0:37.16   2951 total backend files; 0 created; 2 updated; 2949
> >     unchanged; 0 deleted; 54 -> 1110 Makefile
> >      0:37.16 FasterMake backend executed in 0.50s
> >      0:37.16   12 total backend files; 0 created; 0 updated; 12 unchanged; 0
> >     deleted
> >      0:37.16 Total wall time: 34.22s; CPU time: 16.20s; Efficiency: 47%;
> >     Untracked: 0.50s
> >
> >
> >      0:37.89 Finished reading 3131 moz.build files in 21.90s
> >      0:37.89 Processed into 9327 build config descriptors in 3.82s
> >      0:37.89 RecursiveMake backend executed in 7.85s
> >      0:37.89   2951 total backend files; 0 created; 4 updated; 2947
> >     unchanged; 0 deleted; 54 -> 1110 Makefile
> >      0:37.89 FasterMake backend executed in 0.59s
> >      0:37.89   12 total backend files; 0 created; 0 updated; 12 unchanged; 0
> >     deleted
> >      0:37.89 Total wall time: 34.70s; CPU time: 17.70s; Efficiency: 51%;
> >     Untracked: 0.55s
> >
> >     The clear offender is "reading moz.build files".  What's involved in
> >     this process?  Is there some low hanging fruit for making it faster?
> >     Are there things non-build developers can do (such as reducing the
> >     number of moz.build files) that would help?

Please note that "reading moz.build files" is actually misleading,
because usually half of the time is spent not reading moz.build files.
That also seems like a lot of time to spend on reading a "small" number
of files (because the printed number of files is actually wrong, see bug
1208380). It would be interesting to see a profile for that "reading
moz.build files" phase.

> >
> >     Is there any way for us to avoid reprocessing the world for every single
> >     moz.build file change?
> >
> >
> > Please tell us a bit more about your machine. Because on my machine...
> >
> > Linux
> > $ ./mach build-backend
> >  0:00.08
> > /home/gps/src/firefox/obj-x86_64-pc-linux-gnu/_virtualenv/bin/python
> > /home/gps/src/firefox/obj-x86_64-pc-linux-gnu/config.status
> > Reticulating splines...
> > Finished reading 3027 moz.build files in 3.79s
> > Processed into 9028 build config descriptors in 1.54s
> > RecursiveMake backend executed in 3.00s
> >   2829 total backend files; 0 created; 0 updated; 2829 unchanged; 0
> > deleted; 54 -> 1065 Makefile
> > FasterMake backend executed in 0.22s
> >   12 total backend files; 0 created; 0 updated; 12 unchanged; 0 deleted
> > Total wall time: 8.76s; CPU time: 7.26s; Efficiency: 83%; Untracked: 0.21s
> >  
> > Windows 10
> > $ ./mach build-backend
> >  0:00.55
> > c:/dev/src/firefox/obj-i686-pc-mingw32\_virtualenv\Scripts\python.exe
> > c:/dev/src/firefox/obj-i686-pc-mingw32\config.status
> > Reticulating splines...
> > Finished reading 3041 moz.build files in 7.01s
> > Processed into 9841 build config descriptors in 3.19s
> > RecursiveMake backend executed in 3.81s
> >   2860 total backend files; 0 created; 1 updated; 2859 unchanged; 0
> > deleted; 62 -> 1069 Makefile
> > FasterMake backend executed in 0.38s
> >   11 total backend files; 0 created; 1 updated; 10 unchanged; 0 deleted
> > VisualStudio backend executed in 1.71s
> > Generated Visual Studio solution at
> > c:/dev/src/firefox/obj-i686-pc-mingw32\msvc\mozilla.sln
> > Total wall time: 16.43s; CPU time: 16.43s; Efficiency: 100%; Untracked:
> > 0.33s
> >
> > The numbers seem to indicate your machine is a bit old or slow?
>
> Hmm, my machine is a MacBook Pro (this is my main development machine).
> It's a MacBook Pro (Retina, 15-inch, Mid 2014), 2.8Ghz processor, 16GB
> Memory, 1TB APPLE SSD SM1024F, Running Sierra 10.12.1.
>
> My machine wasn't entirely idle, I had things like a Terminal with a
> bunch of vim's open, Nightly, Chrome, Thunderbird, LimeChat.  But these
> numbers are in the usual ballpark I get.
>
> > FWIW, bug 1308982 is on our radar for speeding up moz.build reading.
>
> That's great!  I think that will help people like me a lot.  Thankfully
> Chris seems to be currently working on it.
>
> But I'm still not sure why we can't only re-process the moz.build file
> that has changed...

Not sure there's a bug on file, but we've been talking about doing this
for a long time. It's not exactly trivial, but we'll get there
eventually.

Mike
_______________________________________________
dev-builds mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-builds
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: moz.build processing time

Ehsan Akhgari
On 2016-11-19 4:26 PM, Mike Hommey wrote:

> On Sat, Nov 19, 2016 at 04:12:22PM -0500, Ehsan Akhgari wrote:
>> On 2016-11-18 7:22 PM, Gregory Szorc wrote:
>>> On Fri, Nov 18, 2016 at 3:50 PM, Ehsan Akhgari <[hidden email]
>>> <mailto:[hidden email]>> wrote:
>>>
>>>     Here are the moz.build processing times on my machine when I add one
>>>     line to a LOCAL_INCLUDES in one moz.build file:
>>>
>>>      0:02.97 Reticulating splines...
>>>      0:37.16 Finished reading 3131 moz.build files in 23.09s
>>>      0:37.16 Processed into 9325 build config descriptors in 3.62s
>>>      0:37.16 RecursiveMake backend executed in 6.50s
>>>      0:37.16   2951 total backend files; 0 created; 2 updated; 2949
>>>     unchanged; 0 deleted; 54 -> 1110 Makefile
>>>      0:37.16 FasterMake backend executed in 0.50s
>>>      0:37.16   12 total backend files; 0 created; 0 updated; 12 unchanged; 0
>>>     deleted
>>>      0:37.16 Total wall time: 34.22s; CPU time: 16.20s; Efficiency: 47%;
>>>     Untracked: 0.50s
>>>
>>>
>>>      0:37.89 Finished reading 3131 moz.build files in 21.90s
>>>      0:37.89 Processed into 9327 build config descriptors in 3.82s
>>>      0:37.89 RecursiveMake backend executed in 7.85s
>>>      0:37.89   2951 total backend files; 0 created; 4 updated; 2947
>>>     unchanged; 0 deleted; 54 -> 1110 Makefile
>>>      0:37.89 FasterMake backend executed in 0.59s
>>>      0:37.89   12 total backend files; 0 created; 0 updated; 12 unchanged; 0
>>>     deleted
>>>      0:37.89 Total wall time: 34.70s; CPU time: 17.70s; Efficiency: 51%;
>>>     Untracked: 0.55s
>>>
>>>     The clear offender is "reading moz.build files".  What's involved in
>>>     this process?  Is there some low hanging fruit for making it faster?
>>>     Are there things non-build developers can do (such as reducing the
>>>     number of moz.build files) that would help?
>
> Please note that "reading moz.build files" is actually misleading,
> because usually half of the time is spent not reading moz.build files.
> That also seems like a lot of time to spend on reading a "small" number
> of files (because the printed number of files is actually wrong, see bug
> 1208380). It would be interesting to see a profile for that "reading
> moz.build files" phase.

If there is an easy thing I can do to capture such a profile, please let
me know.  I don't know where in the code you're referring to, and I have
also never really profiled Python code.  :-)

>>>
>>>     Is there any way for us to avoid reprocessing the world for every single
>>>     moz.build file change?
>>>
>>>
>>> Please tell us a bit more about your machine. Because on my machine...
>>>
>>> Linux
>>> $ ./mach build-backend
>>>  0:00.08
>>> /home/gps/src/firefox/obj-x86_64-pc-linux-gnu/_virtualenv/bin/python
>>> /home/gps/src/firefox/obj-x86_64-pc-linux-gnu/config.status
>>> Reticulating splines...
>>> Finished reading 3027 moz.build files in 3.79s
>>> Processed into 9028 build config descriptors in 1.54s
>>> RecursiveMake backend executed in 3.00s
>>>   2829 total backend files; 0 created; 0 updated; 2829 unchanged; 0
>>> deleted; 54 -> 1065 Makefile
>>> FasterMake backend executed in 0.22s
>>>   12 total backend files; 0 created; 0 updated; 12 unchanged; 0 deleted
>>> Total wall time: 8.76s; CPU time: 7.26s; Efficiency: 83%; Untracked: 0.21s
>>>  
>>> Windows 10
>>> $ ./mach build-backend
>>>  0:00.55
>>> c:/dev/src/firefox/obj-i686-pc-mingw32\_virtualenv\Scripts\python.exe
>>> c:/dev/src/firefox/obj-i686-pc-mingw32\config.status
>>> Reticulating splines...
>>> Finished reading 3041 moz.build files in 7.01s
>>> Processed into 9841 build config descriptors in 3.19s
>>> RecursiveMake backend executed in 3.81s
>>>   2860 total backend files; 0 created; 1 updated; 2859 unchanged; 0
>>> deleted; 62 -> 1069 Makefile
>>> FasterMake backend executed in 0.38s
>>>   11 total backend files; 0 created; 1 updated; 10 unchanged; 0 deleted
>>> VisualStudio backend executed in 1.71s
>>> Generated Visual Studio solution at
>>> c:/dev/src/firefox/obj-i686-pc-mingw32\msvc\mozilla.sln
>>> Total wall time: 16.43s; CPU time: 16.43s; Efficiency: 100%; Untracked:
>>> 0.33s
>>>
>>> The numbers seem to indicate your machine is a bit old or slow?
>>
>> Hmm, my machine is a MacBook Pro (this is my main development machine).
>> It's a MacBook Pro (Retina, 15-inch, Mid 2014), 2.8Ghz processor, 16GB
>> Memory, 1TB APPLE SSD SM1024F, Running Sierra 10.12.1.
>>
>> My machine wasn't entirely idle, I had things like a Terminal with a
>> bunch of vim's open, Nightly, Chrome, Thunderbird, LimeChat.  But these
>> numbers are in the usual ballpark I get.
>>
>>> FWIW, bug 1308982 is on our radar for speeding up moz.build reading.
>>
>> That's great!  I think that will help people like me a lot.  Thankfully
>> Chris seems to be currently working on it.
>>
>> But I'm still not sure why we can't only re-process the moz.build file
>> that has changed...
>
> Not sure there's a bug on file, but we've been talking about doing this
> for a long time. It's not exactly trivial, but we'll get there
> eventually.

Thank you, that is good to know.

Cheers,
Ehsan

_______________________________________________
dev-builds mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-builds
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: moz.build processing time

Gregory Szorc-3
On Sat, Nov 19, 2016 at 1:32 PM, Ehsan Akhgari <[hidden email]> wrote:
On 2016-11-19 4:26 PM, Mike Hommey wrote:
> On Sat, Nov 19, 2016 at 04:12:22PM -0500, Ehsan Akhgari wrote:
>> On 2016-11-18 7:22 PM, Gregory Szorc wrote:
>>> On Fri, Nov 18, 2016 at 3:50 PM, Ehsan Akhgari <[hidden email]
>>> <mailto:[hidden email]>> wrote:
>>>
>>>     Here are the moz.build processing times on my machine when I add one
>>>     line to a LOCAL_INCLUDES in one moz.build file:
>>>
>>>      0:02.97 Reticulating splines...
>>>      0:37.16 Finished reading 3131 moz.build files in 23.09s
>>>      0:37.16 Processed into 9325 build config descriptors in 3.62s
>>>      0:37.16 RecursiveMake backend executed in 6.50s
>>>      0:37.16   2951 total backend files; 0 created; 2 updated; 2949
>>>     unchanged; 0 deleted; 54 -> 1110 Makefile
>>>      0:37.16 FasterMake backend executed in 0.50s
>>>      0:37.16   12 total backend files; 0 created; 0 updated; 12 unchanged; 0
>>>     deleted
>>>      0:37.16 Total wall time: 34.22s; CPU time: 16.20s; Efficiency: 47%;
>>>     Untracked: 0.50s
>>>
>>>
>>>      0:37.89 Finished reading 3131 moz.build files in 21.90s
>>>      0:37.89 Processed into 9327 build config descriptors in 3.82s
>>>      0:37.89 RecursiveMake backend executed in 7.85s
>>>      0:37.89   2951 total backend files; 0 created; 4 updated; 2947
>>>     unchanged; 0 deleted; 54 -> 1110 Makefile
>>>      0:37.89 FasterMake backend executed in 0.59s
>>>      0:37.89   12 total backend files; 0 created; 0 updated; 12 unchanged; 0
>>>     deleted
>>>      0:37.89 Total wall time: 34.70s; CPU time: 17.70s; Efficiency: 51%;
>>>     Untracked: 0.55s
>>>
>>>     The clear offender is "reading moz.build files".  What's involved in
>>>     this process?  Is there some low hanging fruit for making it faster?
>>>     Are there things non-build developers can do (such as reducing the
>>>     number of moz.build files) that would help?
>
> Please note that "reading moz.build files" is actually misleading,
> because usually half of the time is spent not reading moz.build files.
> That also seems like a lot of time to spend on reading a "small" number
> of files (because the printed number of files is actually wrong, see bug
> 1208380). It would be interesting to see a profile for that "reading
> moz.build files" phase.

If there is an easy thing I can do to capture such a profile, please let
me know.  I don't know where in the code you're referring to, and I have
also never really profiled Python code.  :-)

You can profile any Python process by running it with:

$ python -mcProfile <program> <args>

e.g.

$ python -mcProfile mach build-backend

You probably want to sort the output using "tottime" or "cumtime" (total and cumulative) respectively. e.g.

$ python -mcProfile -s cumtime mach build-backend

That's the best profiler that Python has built in. Unfortunately, the profiler works by registering a hook every time a function is called or finishes. If your code contains a lot of function calls, the profiler overhead can skew results towards functions that are called frequently. I've found statistical/sampling profilers do a much better job (and don't slow down your code during profiling as much). There is a "statprof" profiler floating around. Unfortunately, we'd need to modify `mach` to invoke it, as it doesn't provide a CLI API for recording (only reporting). And the version on PyPI is somewhat old. The version vendored in the Mercurial repository at https://www.mercurial-scm.org/repo/hg/raw-file/default/mercurial/statprof.py contains a number of improvements, including support for showing the "hot path" of code execution. I would not be opposed to vendoring it in mozilla-central and adding `mach --profile` support. Let us know what cProfile says and we can go from there.
 

>>>
>>>     Is there any way for us to avoid reprocessing the world for every single
>>>     moz.build file change?
>>>
>>>
>>> Please tell us a bit more about your machine. Because on my machine...
>>>
>>> Linux
>>> $ ./mach build-backend
>>>  0:00.08
>>> /home/gps/src/firefox/obj-x86_64-pc-linux-gnu/_virtualenv/bin/python
>>> /home/gps/src/firefox/obj-x86_64-pc-linux-gnu/config.status
>>> Reticulating splines...
>>> Finished reading 3027 moz.build files in 3.79s
>>> Processed into 9028 build config descriptors in 1.54s
>>> RecursiveMake backend executed in 3.00s
>>>   2829 total backend files; 0 created; 0 updated; 2829 unchanged; 0
>>> deleted; 54 -> 1065 Makefile
>>> FasterMake backend executed in 0.22s
>>>   12 total backend files; 0 created; 0 updated; 12 unchanged; 0 deleted
>>> Total wall time: 8.76s; CPU time: 7.26s; Efficiency: 83%; Untracked: 0.21s
>>>
>>> Windows 10
>>> $ ./mach build-backend
>>>  0:00.55
>>> c:/dev/src/firefox/obj-i686-pc-mingw32\_virtualenv\Scripts\python.exe
>>> c:/dev/src/firefox/obj-i686-pc-mingw32\config.status
>>> Reticulating splines...
>>> Finished reading 3041 moz.build files in 7.01s
>>> Processed into 9841 build config descriptors in 3.19s
>>> RecursiveMake backend executed in 3.81s
>>>   2860 total backend files; 0 created; 1 updated; 2859 unchanged; 0
>>> deleted; 62 -> 1069 Makefile
>>> FasterMake backend executed in 0.38s
>>>   11 total backend files; 0 created; 1 updated; 10 unchanged; 0 deleted
>>> VisualStudio backend executed in 1.71s
>>> Generated Visual Studio solution at
>>> c:/dev/src/firefox/obj-i686-pc-mingw32\msvc\mozilla.sln
>>> Total wall time: 16.43s; CPU time: 16.43s; Efficiency: 100%; Untracked:
>>> 0.33s
>>>
>>> The numbers seem to indicate your machine is a bit old or slow?
>>
>> Hmm, my machine is a MacBook Pro (this is my main development machine).
>> It's a MacBook Pro (Retina, 15-inch, Mid 2014), 2.8Ghz processor, 16GB
>> Memory, 1TB APPLE SSD SM1024F, Running Sierra 10.12.1.
>>
>> My machine wasn't entirely idle, I had things like a Terminal with a
>> bunch of vim's open, Nightly, Chrome, Thunderbird, LimeChat.  But these
>> numbers are in the usual ballpark I get.
>>
>>> FWIW, bug 1308982 is on our radar for speeding up moz.build reading.
>>
>> That's great!  I think that will help people like me a lot.  Thankfully
>> Chris seems to be currently working on it.
>>
>> But I'm still not sure why we can't only re-process the moz.build file
>> that has changed...
>
> Not sure there's a bug on file, but we've been talking about doing this
> for a long time. It's not exactly trivial, but we'll get there
> eventually.

Thank you, that is good to know.

Cheers,
Ehsan



_______________________________________________
dev-builds mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-builds
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: moz.build processing time

Ehsan Akhgari
On 2016-11-21 1:08 PM, Gregory Szorc wrote:

> On Sat, Nov 19, 2016 at 1:32 PM, Ehsan Akhgari <[hidden email]
> <mailto:[hidden email]>> wrote:
>
>     On 2016-11-19 4:26 PM, Mike Hommey wrote:
>     > On Sat, Nov 19, 2016 at 04:12:22PM -0500, Ehsan Akhgari wrote:
>     >> On 2016-11-18 7:22 PM, Gregory Szorc wrote:
>     >>> On Fri, Nov 18, 2016 at 3:50 PM, Ehsan Akhgari
>     <[hidden email] <mailto:[hidden email]>
>     >>> <mailto:[hidden email]
>     <mailto:[hidden email]>>> wrote:
>     >>>
>     >>>     Here are the moz.build processing times on my machine when I
>     add one
>     >>>     line to a LOCAL_INCLUDES in one moz.build file:
>     >>>
>     >>>      0:02.97 Reticulating splines...
>     >>>      0:37.16 Finished reading 3131 moz.build files in 23.09s
>     >>>      0:37.16 Processed into 9325 build config descriptors in 3.62s
>     >>>      0:37.16 RecursiveMake backend executed in 6.50s
>     >>>      0:37.16   2951 total backend files; 0 created; 2 updated; 2949
>     >>>     unchanged; 0 deleted; 54 -> 1110 Makefile
>     >>>      0:37.16 FasterMake backend executed in 0.50s
>     >>>      0:37.16   12 total backend files; 0 created; 0 updated; 12
>     unchanged; 0
>     >>>     deleted
>     >>>      0:37.16 Total wall time: 34.22s; CPU time: 16.20s;
>     Efficiency: 47%;
>     >>>     Untracked: 0.50s
>     >>>
>     >>>
>     >>>      0:37.89 Finished reading 3131 moz.build files in 21.90s
>     >>>      0:37.89 Processed into 9327 build config descriptors in 3.82s
>     >>>      0:37.89 RecursiveMake backend executed in 7.85s
>     >>>      0:37.89   2951 total backend files; 0 created; 4 updated; 2947
>     >>>     unchanged; 0 deleted; 54 -> 1110 Makefile
>     >>>      0:37.89 FasterMake backend executed in 0.59s
>     >>>      0:37.89   12 total backend files; 0 created; 0 updated; 12
>     unchanged; 0
>     >>>     deleted
>     >>>      0:37.89 Total wall time: 34.70s; CPU time: 17.70s;
>     Efficiency: 51%;
>     >>>     Untracked: 0.55s
>     >>>
>     >>>     The clear offender is "reading moz.build files".  What's
>     involved in
>     >>>     this process?  Is there some low hanging fruit for making it
>     faster?
>     >>>     Are there things non-build developers can do (such as
>     reducing the
>     >>>     number of moz.build files) that would help?
>     >
>     > Please note that "reading moz.build files" is actually misleading,
>     > because usually half of the time is spent not reading moz.build files.
>     > That also seems like a lot of time to spend on reading a "small"
>     number
>     > of files (because the printed number of files is actually wrong,
>     see bug
>     > 1208380). It would be interesting to see a profile for that "reading
>     > moz.build files" phase.
>
>     If there is an easy thing I can do to capture such a profile, please let
>     me know.  I don't know where in the code you're referring to, and I have
>     also never really profiled Python code.  :-)
>
>
> You can profile any Python process by running it with:
>
> $ python -mcProfile <program> <args>
>
> e.g.
>
> $ python -mcProfile mach build-backend
>
> You probably want to sort the output using "tottime" or "cumtime" (total
> and cumulative) respectively. e.g.
>
> $ python -mcProfile -s cumtime mach build-backend

Here is a profile:
<https://gist.github.com/ehsan/b593c20456886be03c0109e92b4fbf4f>

(For some reason now it takes ~15s to read the moz.build files on the
same machine...)

_______________________________________________
dev-builds mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-builds
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: moz.build processing time

Gregory Szorc-3
On Mon, Nov 21, 2016 at 2:06 PM, Ehsan Akhgari <[hidden email]> wrote:
On 2016-11-21 1:08 PM, Gregory Szorc wrote:
> On Sat, Nov 19, 2016 at 1:32 PM, Ehsan Akhgari <[hidden email]
> <mailto:[hidden email]>> wrote:
>
>     On 2016-11-19 4:26 PM, Mike Hommey wrote:
>     > On Sat, Nov 19, 2016 at 04:12:22PM -0500, Ehsan Akhgari wrote:
>     >> On 2016-11-18 7:22 PM, Gregory Szorc wrote:
>     >>> On Fri, Nov 18, 2016 at 3:50 PM, Ehsan Akhgari
>     <[hidden email] <mailto:[hidden email]>
>     >>> <mailto:[hidden email]
>     <mailto:[hidden email]>>> wrote:
>     >>>
>     >>>     Here are the moz.build processing times on my machine when I
>     add one
>     >>>     line to a LOCAL_INCLUDES in one moz.build file:
>     >>>
>     >>>      0:02.97 Reticulating splines...
>     >>>      0:37.16 Finished reading 3131 moz.build files in 23.09s
>     >>>      0:37.16 Processed into 9325 build config descriptors in 3.62s
>     >>>      0:37.16 RecursiveMake backend executed in 6.50s
>     >>>      0:37.16   2951 total backend files; 0 created; 2 updated; 2949
>     >>>     unchanged; 0 deleted; 54 -> 1110 Makefile
>     >>>      0:37.16 FasterMake backend executed in 0.50s
>     >>>      0:37.16   12 total backend files; 0 created; 0 updated; 12
>     unchanged; 0
>     >>>     deleted
>     >>>      0:37.16 Total wall time: 34.22s; CPU time: 16.20s;
>     Efficiency: 47%;
>     >>>     Untracked: 0.50s
>     >>>
>     >>>
>     >>>      0:37.89 Finished reading 3131 moz.build files in 21.90s
>     >>>      0:37.89 Processed into 9327 build config descriptors in 3.82s
>     >>>      0:37.89 RecursiveMake backend executed in 7.85s
>     >>>      0:37.89   2951 total backend files; 0 created; 4 updated; 2947
>     >>>     unchanged; 0 deleted; 54 -> 1110 Makefile
>     >>>      0:37.89 FasterMake backend executed in 0.59s
>     >>>      0:37.89   12 total backend files; 0 created; 0 updated; 12
>     unchanged; 0
>     >>>     deleted
>     >>>      0:37.89 Total wall time: 34.70s; CPU time: 17.70s;
>     Efficiency: 51%;
>     >>>     Untracked: 0.55s
>     >>>
>     >>>     The clear offender is "reading moz.build files".  What's
>     involved in
>     >>>     this process?  Is there some low hanging fruit for making it
>     faster?
>     >>>     Are there things non-build developers can do (such as
>     reducing the
>     >>>     number of moz.build files) that would help?
>     >
>     > Please note that "reading moz.build files" is actually misleading,
>     > because usually half of the time is spent not reading moz.build files.
>     > That also seems like a lot of time to spend on reading a "small"
>     number
>     > of files (because the printed number of files is actually wrong,
>     see bug
>     > 1208380). It would be interesting to see a profile for that "reading
>     > moz.build files" phase.
>
>     If there is an easy thing I can do to capture such a profile, please let
>     me know.  I don't know where in the code you're referring to, and I have
>     also never really profiled Python code.  :-)
>
>
> You can profile any Python process by running it with:
>
> $ python -mcProfile <program> <args>
>
> e.g.
>
> $ python -mcProfile mach build-backend
>
> You probably want to sort the output using "tottime" or "cumtime" (total
> and cumulative) respectively. e.g.
>
> $ python -mcProfile -s cumtime mach build-backend

Here is a profile:
<https://gist.github.com/ehsan/b593c20456886be03c0109e92b4fbf4f>

(For some reason now it takes ~15s to read the moz.build files on the
same machine...

Doh - I forgot `mach build-backend` invokes a separate Python process - one that doesn't have a profiler attached. You'll need to run:

$ cd objdir
$ mach python -mcProfile -s cumtime config.status

On my machine, I get something like:

        2    0.078    0.039   17.744    8.872 config.status:3(<module>)
        1    0.002    0.002   17.605   17.605 config_status.py:64(config_status)
     9402    0.018    0.000   11.438    0.001 emitter.py:198(emit)
5968/1424    0.006    0.000    8.076    0.006 reader.py:1038(read_mozbuild)
5968/1424    0.035    0.000    8.076    0.006 reader.py:1088(_read_mozbuild)
        2    0.044    0.022    6.147    3.074 base.py:106(consume)
      117    0.037    0.000    4.874    0.042 gyp_reader.py:110(read_from_gyp)
        8    0.000    0.000    4.618    0.577 __init__.py:50(Load)
        8    0.002    0.000    4.617    0.577 input.py:2756(Load)
    301/8    0.004    0.000    4.204    0.526 input.py:362(LoadTargetBuildFile)
13554/328    0.118    0.000    3.995    0.012 input.py:1187(ProcessVariablesAndConditionsInDict)
88715/73832    0.118    0.000    3.465    0.000 input.py:710(ExpandVariables)
15499/9401    0.093    0.000    3.307    0.000 recursivemake.py:421(consume_object)
     9849    0.100    0.000    3.171    0.000 emitter.py:906(emit_from_context)
      148    0.001    0.000    2.893    0.020 subprocess.py:768(communicate)
      147    0.002    0.000    2.891    0.020 subprocess.py:1400(_communicate)
1246/1006    0.003    0.000    2.887    0.003 reader.py:235(exec_file)
      147    0.005    0.000    2.886    0.020 subprocess.py:1433(_communicate_with_poll)
      294    2.876    0.010    2.876    0.010 {built-in method poll}
1246/1006    0.005    0.000    2.858    0.003 sandbox.py:145(exec_file)
1246/1006    0.002    0.000    2.794    0.003 sandbox.py:160(exec_source)
1670/1006    0.009    0.000    2.793    0.003 sandbox.py:186(exec_function)
1246/1006    0.003    0.000    2.780    0.003 sandbox.py:170(execute)

It's worth noting that cProfile increases runtime by ~1.6x. So my trust of profiling results will be a bit waned. Still, it does show that we're spending ~25% of time in GYP. That's why chmanchester is optimizing that :)

I would like to see whether the "shape" of your profile is the same.


_______________________________________________
dev-builds mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-builds
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: moz.build processing time

Ehsan Akhgari
On 2016-11-22 7:39 PM, Gregory Szorc wrote:

> On Mon, Nov 21, 2016 at 2:06 PM, Ehsan Akhgari <[hidden email]
> <mailto:[hidden email]>> wrote:
>
>     On 2016-11-21 1:08 PM, Gregory Szorc wrote:
>     > On Sat, Nov 19, 2016 at 1:32 PM, Ehsan Akhgari <[hidden email] <mailto:[hidden email]>
>     > <mailto:[hidden email] <mailto:[hidden email]>>> wrote:
>     >
>     >     On 2016-11-19 4:26 PM, Mike Hommey wrote:
>     >     > On Sat, Nov 19, 2016 at 04:12:22PM -0500, Ehsan Akhgari wrote:
>     >     >> On 2016-11-18 7:22 PM, Gregory Szorc wrote:
>     >     >>> On Fri, Nov 18, 2016 at 3:50 PM, Ehsan Akhgari
>     >     <[hidden email] <mailto:[hidden email]>
>     <mailto:[hidden email] <mailto:[hidden email]>>
>     >     >>> <mailto:[hidden email]
>     <mailto:[hidden email]>
>     >     <mailto:[hidden email]
>     <mailto:[hidden email]>>>> wrote:
>     >     >>>
>     >     >>>     Here are the moz.build processing times on my machine
>     when I
>     >     add one
>     >     >>>     line to a LOCAL_INCLUDES in one moz.build file:
>     >     >>>
>     >     >>>      0:02.97 Reticulating splines...
>     >     >>>      0:37.16 Finished reading 3131 moz.build files in 23.09s
>     >     >>>      0:37.16 Processed into 9325 build config descriptors
>     in 3.62s
>     >     >>>      0:37.16 RecursiveMake backend executed in 6.50s
>     >     >>>      0:37.16   2951 total backend files; 0 created; 2
>     updated; 2949
>     >     >>>     unchanged; 0 deleted; 54 -> 1110 Makefile
>     >     >>>      0:37.16 FasterMake backend executed in 0.50s
>     >     >>>      0:37.16   12 total backend files; 0 created; 0
>     updated; 12
>     >     unchanged; 0
>     >     >>>     deleted
>     >     >>>      0:37.16 Total wall time: 34.22s; CPU time: 16.20s;
>     >     Efficiency: 47%;
>     >     >>>     Untracked: 0.50s
>     >     >>>
>     >     >>>
>     >     >>>      0:37.89 Finished reading 3131 moz.build files in 21.90s
>     >     >>>      0:37.89 Processed into 9327 build config descriptors
>     in 3.82s
>     >     >>>      0:37.89 RecursiveMake backend executed in 7.85s
>     >     >>>      0:37.89   2951 total backend files; 0 created; 4
>     updated; 2947
>     >     >>>     unchanged; 0 deleted; 54 -> 1110 Makefile
>     >     >>>      0:37.89 FasterMake backend executed in 0.59s
>     >     >>>      0:37.89   12 total backend files; 0 created; 0
>     updated; 12
>     >     unchanged; 0
>     >     >>>     deleted
>     >     >>>      0:37.89 Total wall time: 34.70s; CPU time: 17.70s;
>     >     Efficiency: 51%;
>     >     >>>     Untracked: 0.55s
>     >     >>>
>     >     >>>     The clear offender is "reading moz.build files".  What's
>     >     involved in
>     >     >>>     this process?  Is there some low hanging fruit for
>     making it
>     >     faster?
>     >     >>>     Are there things non-build developers can do (such as
>     >     reducing the
>     >     >>>     number of moz.build files) that would help?
>     >     >
>     >     > Please note that "reading moz.build files" is actually
>     misleading,
>     >     > because usually half of the time is spent not reading
>     moz.build files.
>     >     > That also seems like a lot of time to spend on reading a "small"
>     >     number
>     >     > of files (because the printed number of files is actually wrong,
>     >     see bug
>     >     > 1208380). It would be interesting to see a profile for that
>     "reading
>     >     > moz.build files" phase.
>     >
>     >     If there is an easy thing I can do to capture such a profile,
>     please let
>     >     me know.  I don't know where in the code you're referring to,
>     and I have
>     >     also never really profiled Python code.  :-)
>     >
>     >
>     > You can profile any Python process by running it with:
>     >
>     > $ python -mcProfile <program> <args>
>     >
>     > e.g.
>     >
>     > $ python -mcProfile mach build-backend
>     >
>     > You probably want to sort the output using "tottime" or "cumtime"
>     (total
>     > and cumulative) respectively. e.g.
>     >
>     > $ python -mcProfile -s cumtime mach build-backend
>
>     Here is a profile:
>     <https://gist.github.com/ehsan/b593c20456886be03c0109e92b4fbf4f
>     <https://gist.github.com/ehsan/b593c20456886be03c0109e92b4fbf4f>>
>
>     (For some reason now it takes ~15s to read the moz.build files on the
>     same machine...
>
>
> Doh - I forgot `mach build-backend` invokes a separate Python process -
> one that doesn't have a profiler attached. You'll need to run:
>
> $ cd objdir
> $ mach python -mcProfile -s cumtime config.status

Here is mine:
<https://gist.github.com/ehsan/ad4e56f2d2f70e3e6c578a2517afbc15>

_______________________________________________
dev-builds mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-builds
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: moz.build processing time

Mike Hommey
On Wed, Nov 23, 2016 at 01:57:44PM -0500, Ehsan Akhgari wrote:
> Here is mine:
> <https://gist.github.com/ehsan/ad4e56f2d2f70e3e6c578a2517afbc15>

12.9s spent in 324 calls to select.select.
4.8s spent in 43898 calls to posix.stat.

That's an awful lot of time for I/O. It almost looks like you're using a
good old spinning disk.

Mike
_______________________________________________
dev-builds mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-builds
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: moz.build processing time

Ehsan Akhgari
On 2016-11-23 4:09 PM, Mike Hommey wrote:
> On Wed, Nov 23, 2016 at 01:57:44PM -0500, Ehsan Akhgari wrote:
>> Here is mine:
>> <https://gist.github.com/ehsan/ad4e56f2d2f70e3e6c578a2517afbc15>
>
> 12.9s spent in 324 calls to select.select.
> 4.8s spent in 43898 calls to posix.stat.
>
> That's an awful lot of time for I/O. It almost looks like you're using a
> good old spinning disk.

Fairly certain it's an SSD, but it must be a pretty crappy one.  At any
rate this is Apple hardware which is pretty common at MoCo as you know.  :(
_______________________________________________
dev-builds mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-builds
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: moz.build processing time

Mike Hommey
On Wed, Nov 23, 2016 at 04:24:25PM -0500, Ehsan Akhgari wrote:

> On 2016-11-23 4:09 PM, Mike Hommey wrote:
> > On Wed, Nov 23, 2016 at 01:57:44PM -0500, Ehsan Akhgari wrote:
> >> Here is mine:
> >> <https://gist.github.com/ehsan/ad4e56f2d2f70e3e6c578a2517afbc15>
> >
> > 12.9s spent in 324 calls to select.select.
> > 4.8s spent in 43898 calls to posix.stat.
> >
> > That's an awful lot of time for I/O. It almost looks like you're using a
> > good old spinning disk.
>
> Fairly certain it's an SSD, but it must be a pretty crappy one.  At any
> rate this is Apple hardware which is pretty common at MoCo as you know.  :(

Well, if you run mach build-backend multiple times in a row and times
don't change, then it would be an OS thing rather than a hardware thing.
Because the second time, everything should be in memory.

I know OSX can be bad with I/O, but that seems unusually bad. IIRC gps
found that there's a relatively low limit to the number of files or
inodes that can be in cache, and a working tree of m-c alone is close
to the limit, so changing that configuration could help. Greg, do you
remember what it is?

Other than that, I'd suggest getting a profile through XCode's Instruments.

Mike
_______________________________________________
dev-builds mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-builds
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: moz.build processing time

Nathan Froyd-5
On Wed, Nov 23, 2016 at 4:31 PM, Mike Hommey <[hidden email]> wrote:
> I know OSX can be bad with I/O, but that seems unusually bad. IIRC gps
> found that there's a relatively low limit to the number of files or
> inodes that can be in cache, and a working tree of m-c alone is close
> to the limit, so changing that configuration could help.

Is this the ken.maxvnodes sysctl setting?  You can change it for your
current session with:

sudo sysctl kern.maxvnodes=$((512*1024))

You may want to experiment with higher settings depending on RAM, etc.
You can change it permanently with:

echo kern.maxvnodes=$((512*1024)) | sudo tee -a /etc/sysctl.conf

(settings per https://chromium.googlesource.com/chromium/src/+/master/docs/mac_build_instructions.md#Improving-performance-of)

I've found on my (several years old) Mac that changing this setting
does indeed make a significant performance difference.

-Nathan
_______________________________________________
dev-builds mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-builds
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: moz.build processing time

Mike Hommey
On Thu, Nov 24, 2016 at 07:04:33PM -0500, Nathan Froyd wrote:

> On Wed, Nov 23, 2016 at 4:31 PM, Mike Hommey <[hidden email]> wrote:
> > I know OSX can be bad with I/O, but that seems unusually bad. IIRC gps
> > found that there's a relatively low limit to the number of files or
> > inodes that can be in cache, and a working tree of m-c alone is close
> > to the limit, so changing that configuration could help.
>
> Is this the ken.maxvnodes sysctl setting?  You can change it for your
> current session with:
>
> sudo sysctl kern.maxvnodes=$((512*1024))

Sounds like something we could query from `mach doctor`. Does querying
the current value require sudo?

Mike
_______________________________________________
dev-builds mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-builds
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: moz.build processing time

J. Ryan Stinnett

On Thu, Nov 24, 2016 at 6:23 PM, Mike Hommey <[hidden email]> wrote:
Sounds like something we could query from `mach doctor`. Does querying
the current value require sudo?

No, does not appear to need sudo to read:

$ sysctl kern.maxvnodes
kern.maxvnodes: 524288

(There's also `sysctl -a` to print all the names and values.)

- Ryan

_______________________________________________
dev-builds mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-builds
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: moz.build processing time

Ehsan Akhgari
In reply to this post by Nathan Froyd-5
On 2016-11-24 7:04 PM, Nathan Froyd wrote:

> On Wed, Nov 23, 2016 at 4:31 PM, Mike Hommey <[hidden email]> wrote:
>> I know OSX can be bad with I/O, but that seems unusually bad. IIRC gps
>> found that there's a relatively low limit to the number of files or
>> inodes that can be in cache, and a working tree of m-c alone is close
>> to the limit, so changing that configuration could help.
>
> Is this the ken.maxvnodes sysctl setting?  You can change it for your
> current session with:
>
> sudo sysctl kern.maxvnodes=$((512*1024))
>
> You may want to experiment with higher settings depending on RAM, etc.
> You can change it permanently with:
>
> echo kern.maxvnodes=$((512*1024)) | sudo tee -a /etc/sysctl.conf
>
> (settings per https://chromium.googlesource.com/chromium/src/+/master/docs/mac_build_instructions.md#Improving-performance-of)
>
> I've found on my (several years old) Mac that changing this setting
> does indeed make a significant performance difference.

Thank you!

Doing this reduced the "reading moz.build files" stage of build-backend
down to about 14s, reliably every time.  That seems to suggest that
everything now fits into the cache (I'm now experimenting with a higher
value since I have tons of unused RAM.)

The entire runtime of build-backend now on an unchanged tree is about
25-28s, which is much higher than I would like...  :(
_______________________________________________
dev-builds mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-builds
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: moz.build processing time

Gregory Szorc-3
On Sat, Nov 26, 2016 at 9:31 AM, Ehsan Akhgari <[hidden email]> wrote:
On 2016-11-24 7:04 PM, Nathan Froyd wrote:
> On Wed, Nov 23, 2016 at 4:31 PM, Mike Hommey <[hidden email]> wrote:
>> I know OSX can be bad with I/O, but that seems unusually bad. IIRC gps
>> found that there's a relatively low limit to the number of files or
>> inodes that can be in cache, and a working tree of m-c alone is close
>> to the limit, so changing that configuration could help.
>
> Is this the ken.maxvnodes sysctl setting?  You can change it for your
> current session with:
>
> sudo sysctl kern.maxvnodes=$((512*1024))
>
> You may want to experiment with higher settings depending on RAM, etc.
> You can change it permanently with:
>
> echo kern.maxvnodes=$((512*1024)) | sudo tee -a /etc/sysctl.conf
>
> (settings per https://chromium.googlesource.com/chromium/src/+/master/docs/mac_build_instructions.md#Improving-performance-of)
>
> I've found on my (several years old) Mac that changing this setting
> does indeed make a significant performance difference.

Thank you!

Doing this reduced the "reading moz.build files" stage of build-backend
down to about 14s, reliably every time.  That seems to suggest that
everything now fits into the cache (I'm now experimenting with a higher
value since I have tons of unused RAM.)

The entire runtime of build-backend now on an unchanged tree is about
25-28s, which is much higher than I would like...  :(

I'm very glad to hear things are running faster!

However, I find it *really* difficult to believe that moz.build reading alone was enough to exhaust the default vnode cache. On Linux (where results should be comparable), `strace -e trace=file` says `mach build-backend` accesses 72609 unique paths across ~300k recorded function calls. Even if you count inodes for directories, we shouldn't be near the 256k default limit and immediate subsequent config.status runs should not run into cache eviction issues. There's got to be something funky about your machine or build configuration :/

_______________________________________________
dev-builds mailing list
[hidden email]
https://lists.mozilla.org/listinfo/dev-builds
Loading...