View source for User:Gszorc/Build System Experimentation

The Mozilla build system, specifically all the makefiles and the things they do, is scary. I have a personal project (which will inevitably bleed into bugs and patches) to improve it any way I can.

==Impetus==
[[User:ally]] and I were opining how developing mozilla-central on Windows isn't very ''Windows-y''. Specifically, there is no official Visual Studio story. Windows developers love Visual Studio and it is really unfortunate we can't give them what they love (no, scanning existing directories for source or simply using the debugger does not count). So, all the work on this page started as a way to explore generating Visual Studio project files automatically with the goal of eventually bundling them in the source tree (or at least providing a way for them to be generated automatically on checkout).

==PyMake Hacking==

I'm working on a number of features to PyMake to make it more useful and faster. My work can be found at https://github.com/indygreg/pymake (typically inside a branch). This Github repository is an unofficial import of the Mercurial repository hosted by Mozilla. I make no promises that Mercurial changes are pushed to Github.

===Tracing===
I've implemented ''tracing'' to PyMake. When you load a *Makefile* instance in PyMake, you have the option of passing an object which will receive notifications during certain build events, such as:

* Start/end of new Makefile processing
* Start/end of target processing
* Start/end of command execution

These callbacks all pass information about the object they are operating on.

Using this callback API, I've implemented a basic tracing logger and integrated it with the PyMake ''make.py'' driver. It takes the callback data, converts it to JSON, and writes it to a file. This stream contains very detailed records, including dependencies and variables. From that stream, we should be able to perform magic not previously conceivable.

Tracing is available in the *tracing* branch of the aforementioned Git repository.

====Tracing Your Builds====
'''WARNING: tracing is still in early development. File formats and the APIs WILL change. Use at your own risk.'''

To trace builds with PyMake, you simply invoke pymake.py with the ''--trace-log'' argument.

 $ cd mozilla-central/objdir
 $ /path/to/pymake/make.py --trace-log=/home/gps/pymake-trace00.log -f ./Makefile
 # wait for make to finish - this takes a while

As PyMake is running, the file specified by ''--trace-log'' will be appended with events as they happen. Parallel builds should work fine, as PyMake obtain an exclusive lock on a lock file before writing to it.

'''Be sure to specify a full path to the --trace-log file. If you don't, you may be bitten by relative paths and current working directories.'''

====Analyzing Your Traces====
There are 3 options for analyzing traces:

# Write your own parser/analyzer
# Use the CLI script in my tree
# Code Python against the parser class in PyMake

I would hold off on #1 right now because data formats will likely change and your custom code will break.

My Git repository contains a CLI script in ''build/pymake/pymaketrace.py''. To see how to use it:

 $ ./build/pymake/pymaketrace.py --help
 # or
 $ python ./build/pymake/pymaketrace.py --help

There is also a Python module for analyzing the trace files, ''pymake.traceparser''. This modules contains a class, ''TraceParser''. This class has a number of convenient methods for analyzing the trace file. All this is in ''build/pymake/pymake/traceparser''.

By far the easiest is the supplied CLI script. For example, to analyze the command counts during a trace run:

 $ ./build/pymake/pymaketrace.py --print-command-counts ~/trace00.log

===Native Python Execution===
Creating a new Python interpreter to run Python code from an existing Python interpreter (PyMake) is silly.

During the course of a normal build, PyMake calls out to numerous Python scripts (see observations below). For each command executed this way, we spin off a new process, fire up a new Python interpreter, and execute the script. This is slow, especially on Windows, where new processes aren't as cheap as they are on NIX platforms. It is grossly inefficient when you take into account the simplicity of the scripts being executed (e.g. *nsinstall.py*). The execution time is most often dominated by the Python interpreter process creation overhead.

To make matters even more ridiculous, *PyMake already has support for native Python command execution*! By simply prefixing a recipe line with *%*, PyMake can call out into Python modules!

I plan to rewrite things so some of the most abused Python scripts are called natively from PyMake. This is a 2 step process:

# Rewrite existing scripts so they can be called as routines in a module
# Rewrite Makefiles to use the native syntax when running under PyMake

==Observations==
===Fresh Builds===
====Linux====
On Linux, I performed a trace on a fresh obj directory following a ''make configure''. First, my .mozconfig:

<pre>
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/obj-ff-debug
mk_add_options MOZ_MAKE_FLAGS="-j8"
ac_add_options --enable-application=browser
ac_add_options --enable-tests
ac_add_options --with-ccache=/usr/bin/ccache
ac_add_options --enable-optimize=-O2
</pre>

Using ''pymaketrace.py --print-target-counts'', we see a number of targets evaluated more than 10 times:

<pre>
12      /build/automation-build.mk
12      /obj-ff-debug/gfx/qcms/Makefile
12      /obj-ff-debug/widget/src/gtkxtbin/Makefile
12      /xpcom/glue/objs.mk
16      /nsprpub/config/prdepend.h
19      /js/src/config/config.mk
19      /js/src/config/rules.mk
19      /js/src/config/static-checking-config.mk
19      /js/src/config/version.mk
19      /js/src/@MOZ_BUILD_APP@/app-config.mk
19      /js/src/@MOZ_BUILD_APP@/app-rules.mk
19      /obj-ff-debug/js/src/config/myconfig.mk
19      /obj-ff-debug/js/src/config/myrules.mk
21      /obj-ff-debug/js/src/config/autoconf.mk
25      /obj-ff-debug/dist/lib/libxpcomglue_s.a.desc
36      /browser/build.mk
36      /config/js/build.mk
36      /config/nspr/build.mk
36      /obj-ff-debug/Makefile.in
36      /testing/testsuite-targets.mk
36      /toolkit/toolkit-tiers.mk
37      /obj-ff-debug/Makefile
39      /toolkit/mozapps/installer/package-name.mk
45      /nsprpub/config/config.mk
45      /nsprpub/config/rules.mk
45      /obj-ff-debug/nsprpub/config/autoconf.mk
48      /build/binary-location.mk
147     /obj-ff-debug/dist/idl
147     /obj-ff-debug/dist/include
155     /ipc/chromium/chromium-config.mk
294     /xpcom/idl-parser/typelib.py
295     /xpcom/idl-parser/header.py
295     /xpcom/idl-parser/xpidl.py
886     /obj-ff-debug/dist/bin/chrome
2613    /browser/app-config.mk
2613    /browser/app-rules.mk
2613    /config/config.mk
2613    /config/rules.mk
2613    /config/static-checking-config.mk
2613    /config/version.mk
2613    /obj-ff-debug/config/autoconf.mk
2613    /obj-ff-debug/config/myconfig.mk
2613    /obj-ff-debug/config/myrules.mk
</pre>

As for commands, here are the ones executed more than 10 times:

<pre>
14      chmod
18      /home/gps/src/mozilla-central/config/Preprocessor.py
20      ranlib
29      yasm
31      set
61      /home/gps/src/mozilla-central/build/xpccheck.py
72      /home/gps/src/mozilla-central/config/JarMaker.py
84      rm
136     perl
146     /home/gps/src/mozilla-central/obj-ff-debug/dist/sdk/bin/xpt.py
364     /home/gps/src/mozilla-central/config/buildlist.py
381     /home/gps/src/mozilla-central/config/pythonpath.py
693     pymake.builtins
1276    if
1653    nsinstall
2680    /home/gps/src/mozilla-central/build/pymake/make.py
3303    ccache
5598    echo
</pre>

====Windows====
On Windows, I performed a trace on a fresh obj directory following a ''make configure''. My .mozconfig:

<pre>
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/obj-ff-debug
mk_add_options MOZ_MAKE_FLAGS="-j1"
ac_add_options --enable-application=browser
ac_add_options --enable-tests
ac_add_options --disable-angle
</pre>

For the fresh build, PyMake churned through '''26060''' targets. The most processed targets were:

<pre>
11      \dist\lib\mozjs.lib
12      \gfx\qcms\Makefile
12      c:\dev\src\mozilla-central-git\build\automation-build.mk
12      c:\dev\src\mozilla-central-git\xpcom\glue\objs.mk
15      \js\src\config\myconfig.mk
15      \js\src\config\myrules.mk
15      c:\dev\src\mozilla-central-git\js\src\@MOZ_BUILD_APP@\app-config.mk
15      c:\dev\src\mozilla-central-git\js\src\@MOZ_BUILD_APP@\app-rules.mk
15      c:\dev\src\mozilla-central-git\js\src\config\config.mk
15      c:\dev\src\mozilla-central-git\js\src\config\rules.mk
15      c:\dev\src\mozilla-central-git\js\src\config\static-checking-config.mk
15      c:\dev\src\mozilla-central-git\js\src\config\version.mk
16      c:\dev\src\mozilla-central-git\nsprpub\config\prdepend.h
17      \js\src\config\autoconf.mk
20      \dist\lib\xul.lib
24      \dist\lib\xpcomglue_s.lib.desc
26      \dist\lib\xpcom.lib
29      \dist\lib\mozalloc.lib
29      c:\dev\src\mozilla-central-git\config\version_win.pl
33      \dist\lib\nspr4.lib
33      \dist\lib\plc4.lib
33      \dist\lib\plds4.lib
35      \Makefile.in
36      \Makefile
36      c:\dev\src\mozilla-central-git\browser\build.mk
36      c:\dev\src\mozilla-central-git\config\js\build.mk
36      c:\dev\src\mozilla-central-git\config\nspr\build.mk
36      c:\dev\src\mozilla-central-git\testing\testsuite-targets.mk
36      c:\dev\src\mozilla-central-git\toolkit\toolkit-tiers.mk
43      c:\dev\src\mozilla-central-git\toolkit\mozapps\installer\package-name.mk
45      \nsprpub\config\autoconf.mk
45      c:\dev\src\mozilla-central-git\nsprpub\config\config.mk
45      c:\dev\src\mozilla-central-git\nsprpub\config\rules.mk
48      c:\dev\src\mozilla-central-git\build\binary-location.mk
146     \dist\idl
146     \dist\include
158     c:\dev\src\mozilla-central-git\ipc\chromium\chromium-config.mk
292     c:\dev\src\mozilla-central-git\xpcom\idl-parser\typelib.py
293     c:\dev\src\mozilla-central-git\xpcom\idl-parser\header.py
293     c:\dev\src\mozilla-central-git\xpcom\idl-parser\xpidl.py
879     \dist\bin\chrome
2588    \config\autoconf.mk
2588    \config\myconfig.mk
2588    \config\myrules.mk
2588    c:\dev\src\mozilla-central-git\browser\app-config.mk
2588    c:\dev\src\mozilla-central-git\browser\app-rules.mk
2588    c:\dev\src\mozilla-central-git\config\config.mk
2588    c:\dev\src\mozilla-central-git\config\rules.mk
2588    c:\dev\src\mozilla-central-git\config\static-checking-config.mk
2588    c:\dev\src\mozilla-central-git\config\version.mk
</pre>

For commands, PyMake spun off '''30116'''. The grouping of commands is currently unavailable on Windows due to a bug in the PyMake trace parser.

===Previously-Built Trees===
While fresh builds are interesting, most developers care about the time to build on existing tree, because that is something we find ourselves doing every day. We typically shy away from rebuilding the whole tree because it takes so long. Instead, we typically ''make -C'' in the component we change. There's nothing wrong with that. But, there is always the possibility we could have missed a cascading dependency.

I would argue that in the ideal build system the output of a simple ''make'' for an already completely built tree would only consist of the following messages:

 Make: Entering directory A
 Make: Entering directory B
 Make: Nothing to be done for B
 Make: Leaving directory B
 Make: Leaving directory B

Actually, a perfect build system would just say ''nothing to be done'' and exit. But, make's little brain can't grok the state of the world like that, since it has to parse Makefiles in other directories (which is what the ''Entering directory'' logs signify).

Anyway, when you build mozilla-central on a tree that's already fully built, we see tons of other output. e.g.

<pre>
make.py[6]: Entering directory '/home/gps/src/mozilla-central/obj-ff-debug/js/src/ctypes/libffi'
/home/gps/src/mozilla-central/obj-ff-debug/js/src/ctypes/libffi/Makefile:1035:0$ depbase=`echo src/debug.lo | sed 's|[^/]*$|.deps/&|;s|\.lo$||'`;\
/bin/bash ./libtool --tag=CC   --mode=compile gcc -DHAVE_CONFIG_H -I. -I../../../../../js/src/ctypes/libffi  -I. -I../../../../../js/src/ctypes/libffi/include -Iinclude -I../../../../../js/src/ctypes/libffi/src  -Wall -g -fexceptions  -O2  -MT src/debug.lo -MD -MP -MF $depbase.Tpo -c -o src/debug.lo ../../../../../js/src/ctypes/libffi/src/debug.c &&\
mv -f $depbase.Tpo $depbase.Plo
libtool: compile:  gcc -DHAVE_CONFIG_H -I. -I../../../../../js/src/ctypes/libffi -I. -I../../../../../js/src/ctypes/libffi/include -Iinclude -I../../../../../js/src/ctypes/libffi/src -Wall -g -fexceptions -O2 -MT src/debug.lo -MD -MP -MF src/.deps/debug.Tpo -c ../../../../../js/src/ctypes/libffi/src/debug.c  -fPIC -DPIC -o src/debug.o
/home/gps/src/mozilla-central/obj-ff-debug/js/src/ctypes/libffi/Makefile:1035:0$ depbase=`echo src/prep_cif.lo | sed 's|[^/]*$|.deps/&|;s|\.lo$||'`;\
/bin/bash ./libtool --tag=CC   --mode=compile gcc -DHAVE_CONFIG_H -I. -I../../../../../js/src/ctypes/libffi  -I. -I../../../../../js/src/ctypes/libffi/include -Iinclude -I../../../../../js/src/ctypes/libffi/src  -Wall -g -fexceptions  -O2  -MT src/prep_cif.lo -MD -MP -MF $depbase.Tpo -c -o src/prep_cif.lo ../../../../../js/src/ctypes/libffi/src/prep_cif.c &&\
mv -f $depbase.Tpo $depbase.Plo
libtool: compile:  gcc -DHAVE_CONFIG_H -I. -I../../../../../js/src/ctypes/libffi -I. -I../../../../../js/src/ctypes/libffi/include -Iinclude -I../../../../../js/src/ctypes/libffi/src -Wall -g -fexceptions -O2 -MT src/prep_cif.lo -MD -MP -MF src/.deps/prep_cif.Tpo -c ../../../../../js/src/ctypes/libffi/src/prep_cif.c  -fPIC -DPIC -o src/prep_cif.o
/home/gps/src/mozilla-central/obj-ff-debug/js/src/ctypes/libffi/Makefile:1035:0$ depbase=`echo src/types.lo | sed 's|[^/]*$|.deps/&|;s|\.lo$||'`;\
/bin/bash ./libtool --tag=CC   --mode=compile gcc -DHAVE_CONFIG_H -I. -I../../../../../js/src/ctypes/libffi  -I. -I../../../../../js/src/ctypes/libffi/include -Iinclude -I../../../../../js/src/ctypes/libffi/src  -Wall -g -fexceptions  -O2  -MT src/types.lo -MD -MP -MF $depbase.Tpo -c -o src/types.lo ../../../../../js/src/ctypes/libffi/src/types.c &&\
mv -f $depbase.Tpo $depbase.Plo
</pre>

Wha!? I just built the tree! y u repeat compilation?

On Linux, when I trace PyMake, I find '''5022''' commands executed in total. Keep in mind these are only commands directly spun off from PyMake. The total does not include all fork()s, exec()s, etc. (I could probably find this using DTrace if I really wanted...)

The full breakdown of commands counts is as follows:

<pre>
2677    /home/gps/src/mozilla-central/build/pymake/make.py
1638    nsinstall
364     /home/gps/src/mozilla-central/config/buildlist.py
72      /home/gps/src/mozilla-central/config/JarMaker.py
68      /home/gps/src/mozilla-central/config/pythonpath.py
61      /home/gps/src/mozilla-central/build/xpccheck.py
30      set
22      echo
18      rm
9       /home/gps/src/mozilla-central/config/Preprocessor.py
8       if
8       depbase=`echo
7       make
5       cp
5       (cd
4       /home/gps/src/mozilla-central/js/src/config/pythonpath.py
4       :
3       mv
2       /home/gps/src/mozilla-central/toolkit/xre/make-platformini.py
2       cd
2       ccache
2       cat
2       bash
1       tar
1       sed
1       ranlib
1       pymake.builtins
1       perl
1       /home/gps/src/mozilla-central/js/src/config/Preprocessor.py
1       /home/gps/src/mozilla-central/config/nsinstall.py
1       fail=
1       chmod
</pre>

There is some noise in there. I hope to figure that out and clean it up in a future version.

If we look at the targets evaluated during a build on a built tree, I find '''26032''' unique targets with '''5075''' evaluated multiple times. Of those with multiple evaluation, the top 50 in terms of invocations are:

<pre>
2613    /home/gps/src/mozilla-central/config/version.mk
2613    /home/gps/src/mozilla-central/config/static-checking-config.mk
2613    /home/gps/src/mozilla-central/config/rules.mk
2613    /home/gps/src/mozilla-central/config/config.mk
2613    /home/gps/src/mozilla-central/browser/app-rules.mk
2613    /home/gps/src/mozilla-central/browser/app-config.mk
2613    /config/myrules.mk
2613    /config/myconfig.mk
2613    /config/autoconf.mk
886     /dist/bin/chrome
295     /home/gps/src/mozilla-central/xpcom/idl-parser/xpidl.py
295     /home/gps/src/mozilla-central/xpcom/idl-parser/header.py
294     /home/gps/src/mozilla-central/xpcom/idl-parser/typelib.py
155     /home/gps/src/mozilla-central/ipc/chromium/chromium-config.mk
147     /dist/include
147     /dist/idl
48      /home/gps/src/mozilla-central/build/binary-location.mk
45      /nsprpub/config/autoconf.mk
45      /home/gps/src/mozilla-central/nsprpub/config/rules.mk
45      /home/gps/src/mozilla-central/nsprpub/config/config.mk
39      /home/gps/src/mozilla-central/toolkit/mozapps/installer/package-name.mk
36      /Makefile
36      /home/gps/src/mozilla-central/toolkit/toolkit-tiers.mk
36      /home/gps/src/mozilla-central/testing/testsuite-targets.mk
36      /home/gps/src/mozilla-central/config/nspr/build.mk
36      /home/gps/src/mozilla-central/config/js/build.mk
36      /home/gps/src/mozilla-central/browser/build.mk
35      /Makefile.in
25      /dist/lib/libxpcomglue_s.a.desc
20      /js/src/config/autoconf.mk
18      /js/src/config/myrules.mk
18      /js/src/config/myconfig.mk
18      /home/gps/src/mozilla-central/js/src/@MOZ_BUILD_APP@/app-rules.mk
18      /home/gps/src/mozilla-central/js/src/@MOZ_BUILD_APP@/app-config.mk
18      /home/gps/src/mozilla-central/js/src/config/version.mk
18      /home/gps/src/mozilla-central/js/src/config/static-checking-config.mk
18      /home/gps/src/mozilla-central/js/src/config/rules.mk
18      /home/gps/src/mozilla-central/js/src/config/config.mk
16      /home/gps/src/mozilla-central/nsprpub/config/prdepend.h
12      /widget/src/gtkxtbin/Makefile
12      /home/gps/src/mozilla-central/xpcom/glue/objs.mk
12      /home/gps/src/mozilla-central/build/automation-build.mk
12      /gfx/qcms/Makefile
9       /home/gps/src/mozilla-central/rdf/util/src/objs.mk
9       /home/gps/src/mozilla-central/intl/unicharutil/util/objs.mk
9       /dist/lib/libjs_static.a.desc
9       /browser/branding/nightly/Makefile
9       /browser/branding/nightly/locales/Makefile
8       /toolkit/xre/test/Makefile
8       /dist/sdk/lib
</pre>

What does redundant target evaluation mean? Well, I can't make any hard or fast rules because I believe some redundant evaluation will occur as a result of parallel execution and due to the way Makefile processing works. But, I can say that any time a target is processes more than once, there is some extra work involved.

To boil it down, '''a build on a fully built tree does a lot of work. This work should be skipped because the tree is fully built.''' The good news is my tracing feature described above makes it pretty darn easy to isolate exact work performed. So, hopefully we can find the offenders and start fixing them.