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:

  1. One important thing is missing: make itself.

    ReplyDelete
  2. 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.

    ReplyDelete
  3. 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.

    ReplyDelete
  4. 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.

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

    ReplyDelete
  6. @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

    ReplyDelete
  7. 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.

    ReplyDelete
  8. 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.

    ReplyDelete
  9. 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.

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

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

    ReplyDelete
  12. 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

    ReplyDelete