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.
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.
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.
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
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.
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:
One important thing is missing: make itself.
ReplyDeletePlanet is confused by your strange script tag which includes both a src attribute and some content which looks like data rather than actual script.
ReplyDeleteI'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.
ReplyDeleteNot entirely surprising, we spend most of our time compiling code. There are a few things in there that are silly, like "echo", certainly.
ReplyDeleteI'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.
Love the visual. Interesting how much time sh takes. How did you come up with the numbers?
ReplyDelete@Neil
ReplyDeleteIt'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
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.
ReplyDeleteSo this is a make -j2 presumably with one core totally slammed by your while true loop, it looks like.
ReplyDeleteIgnoring 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.
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.
ReplyDeleteWhat tool did you use to do this? Does "sh" time also account for the things that are launched by the shell?
ReplyDeletebsmedberg: See the reply to jag above; that's the series of commands I used.
ReplyDeletebsmedberg: It looks like sh gets counted for stuff run under it:
ReplyDeleteCOMMAND
...
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