Thursday, February 24, 2011

Build Times Visualized

Here's a graph (whipped up in a couple of lines of bash) of where we spend our time when building a clean Firefox from scratch. Tested on Mac OS X 10.6 on a Core 2 Duo MacBook Pro, with a -j2 parallel build.

12 comments:

glandium said...

One important thing is missing: make itself.

Neil Rashbrook said...

Planet is confused by your strange script tag which includes both a src attribute and some content which looks like data rather than actual script.

Anonymous said...

I'm surprised that make itself doesn't show up in your graph. By all the talk we have about how complex our makefiles are, I'd expect it to be at least in the long tail.

Ted Mielczarek said...

Not entirely surprising, we spend most of our time compiling code. There are a few things in there that are silly, like "echo", certainly.

I'd be interested to see the same results from a no-op depend build. That would more closely show where we're wasting time, since it should be nearly 100% make.

jag said...

Love the visual. Interesting how much time sh takes. How did you come up with the numbers?

Patrick Walton said...

@Neil

It's the snippet that Google Docs provides. Odd.

@glandium

Yeah, I stripped out make because of accounting issues (it would show up everywhere if I didn't, since make is always running). A better analysis would look only at the *leaves* of the process graph rooted at make (not counting gcc-internal stuff).

@jag

$ while true; do ps -o command -w -w -g `pidof make` | egrep -v 'make|ccache|libexec/gcc|COMM|i686-apple-darwin10-g++' >> makeprof.out; done

Then

$ cut -f 1 -d ' ' makeprof.out | xargs basename -a | sed -E 's/^\(([^)]+)\)/\1/' | sort | uniq -c | sort -n -r

ericm said...

You can get this information from SparkBuild too (free as in beer), which also allows you to "drill down" into the build performance data in some interesting ways. It's only available for Windows and Linux, so I suppose it wouldn't have helped in this particular example, but perhaps it will be interesting to some of your readers.

sfink said...

So this is a make -j2 presumably with one core totally slammed by your while true loop, it looks like.

Ignoring that, wouldn't 'sh' have the same problem as 'make' in terms of blaming it for time used by child processes? My ps has a 'r' option for only displaying running processes, which would fix that, or you could egrep '^[^ ]*[RD]'.

After some experimentation, I came up with this on Linux:

while true; do S=$(ps --no-heading -o sid -p $(pidof -s make)) && ps r --no-heading -o ucmd -w -s "$S"; done > makeprof.out

On OS X using BSD tools, it's harder. The 'r' option doesn't exist, and various other difficulties. All I could come up with is:

while true; do G=$(ps -o pgid -p $(pidof make)) && ps -o ucomm,stat -w -g "$G" | egrep -v UCOMM | egrep ' .*[RD]' | cut -d' ' -f1; done > makeprof.out

This also avoids the basename. It does not bucket gcc-related processes, though.

jlebar said...

Is this CPU time or wall time? That is, we usually run multiple GCCs at once, but we often run only one Python at a time.

Benjamin Smedberg said...

What tool did you use to do this? Does "sh" time also account for the things that are launched by the shell?

Patrick Walton said...

bsmedberg: See the reply to jag above; that's the series of commands I used.

jag said...

bsmedberg: It looks like sh gets counted for stuff run under it:

COMMAND
...
make -C interfaces/geolocation libs
/bin/sh -c /opt/local/bin/python2.6 /Users/jag/moz-hg/mozilla/mozilla/config/buildlist.py ../../../dist/bin/components/interfaces.manifest "interfaces dom_geolocation.xpt"

COMMAND
...
make -C interfaces/geolocation libs
/opt/local/Library/Frameworks/Python.framework/Versions/2.6/Resources/Python.app/Contents/MacOS/Python /Users/jag/moz-hg/mozilla/mozilla/config/buildlist.py ../../../dist/bin/components/interfaces.manifest interfaces dom_geolocation.xpt