On Mon, Nov 21, 2016 at 2:06 PM, Ehsan Akhgari <ehsan.akhg...@gmail.com> wrote:
> On 2016-11-21 1:08 PM, Gregory Szorc wrote: > > On Sat, Nov 19, 2016 at 1:32 PM, Ehsan Akhgari <ehsan.akhg...@gmail.com > > <mailto:ehsan.akhg...@gmail.com>> 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 > > <ehsan.akhg...@gmail.com <mailto:ehsan.akhg...@gmail.com> > > >>> <mailto:ehsan.akhg...@gmail.com > > <mailto:ehsan.akhg...@gmail.com>>> 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 dev-builds@lists.mozilla.org https://lists.mozilla.org/listinfo/dev-builds
