Profile the build system

From CDOT Wiki
Jump to: navigation, search

Name of Project

Profile the build system

Description

It's a well known fact that it takes longer to build on Windows than on a comparable Linux or Mac machine. We don't know exactly why, however. There have been many theories, but no real data. Profiling the build system would allow us to figure out where all of the time is being spent. The best place to start might be by adding some profiling to GNU Make, to figure out which targets in our makefiles take the most time. From there, depending on the results, profiling could be added to other parts of the build system to narrow down specific bottlenecks.

References:

  1. http://wiki.services.openoffice.org/wiki/BuildSpeedup - OpenOffice.org did something similar

Resources: ted

Bugzilla

A bug has been submitted for enhancement on [Bugzilla].

Leader(s)

Project Contributor(s)

Project Details

  • Get where time is spent during the build
    • 1 set of data from scratch builds and 1 set of data from rebuilds


  • Collect Data
    • Get build time info from others
      • Build From Scratch, Rebuild with no changes, using/not using -j4 option, hardware info (RAM, CPU, RPM)


  • The -j4 option is used in the .mozconfig file
  • -j specifies how many concurrent jobs you can run, so for some parts of the tree you get more makes going at once
    • mk_add_options MOZ_MAKE_FLAGS=-j4

Releases

Release 0.1 - Oct 13

Goal

  • Try out different build options
    • See how they affect built
  • Try profiling the run-time build
    • Time how long it takes on each file/directory during the build

Results for Rebuilds with No Changes

  • Looking at the breakdown of the time, it can be seen that dom, browser, content, toolkit, netwerk, and xpcom take up a large portion of the build time
  • The remaining 39.3% of the build time is divided into layout, intl, embedding and other 23 different directories
Charts

Data from 10 Rebuilds were used to create the following charts:

TimeChartCondensed.jpg TimeChartAll.jpg

Data
Rebuild Profile Data
Folders 1 (sec) 2 (sec) 3 (sec) 4 (sec) 5 (sec) 6 (sec) 7 (sec) 8 (sec) 9 (sec) 10 (sec) AVG (sec)  %
dom 100.359 78.483 78.530 83.454 85.608 105.346 121.647 94.457 86.579 81.220 91.568 12.46%
content 107.504 72.521 76.064 72.693 72.175 84.936 101.252 75.230 76.487 70.748 80.961 11.02%
browser 79.352 78.662 85.827 73.574 75.665 79.911 82.024 71.726 72.534 71.356 77.063 10.49%
netwerk 73.646 58.749 68.171 61.736 61.747 77.301 89.820 66.909 65.089 59.837 68.301 9.30%
toolkit 67.833 63.092 70.699 64.975 66.265 72.723 76.762 67.938 67.456 63.604 68.135 9.27%
xpcom 63.494 57.616 54.563 50.040 51.008 71.673 77.560 61.735 63.407 48.072 59.917 8.16%
layout 67.544 41.636 43.673 43.222 44.494 49.144 76.850 45.768 43.555 42.665 49.855 6.79%
intl 50.631 40.152 42.585 40.364 40.779 52.670 59.998 44.475 40.644 38.891 45.119 6.14%
embedding 39.713 33.534 33.525 34.321 35.067 39.370 44.234 36.592 34.942 33.886 36.518 4.97%
editor 26.544 20.365 23.146 20.031 20.868 22.450 26.921 21.583 22.397 19.463 22.377 3.05%
gfx 22.279 14.212 14.587 14.673 16.167 17.449 26.159 15.635 14.128 14.231 16.952 2.31%
docshell 15.935 12.512 13.759 13.092 13.857 15.978 19.985 14.177 12.954 12.567 14.482 1.97%
rdf 15.287 12.746 12.636 13.285 13.497 15.735 19.098 14.593 13.312 12.964 14.315 1.95%
xpfe 11.707 10.972 11.337 11.267 11.531 12.907 13.344 11.754 11.429 10.915 11.716 1.59%
widget 14.399 9.812 10.078 10.383 10.472 12.203 14.493 10.947 12.513 10.354 11.565 1.57%
nsprpub 9.411 8.017 7.098 7.356 7.802 16.656 10.980 7.587 7.347 7.373 8.963 1.22%
uriloader 8.707 7.224 7.098 7.859 8.264 10.349 11.157 8.413 7.926 7.313 8.431 1.15%
storage 7.811 6.412 6.708 6.909 6.848 7.746 9.900 7.387 6.413 6.513 7.265 0.99%
caps 6.484 5.304 5.288 5.663 6.321 6.668 6.985 6.335 5.529 5.406 5.998 0.82%
profile 5.775 5.461 5.897 5.449 5.604 6.239 6.266 5.755 5.404 5.317 5.717 0.78%
xpinstall 4.772 4.072 4.570 4.243 4.264 5.161 5.592 4.349 4.183 4.068 4.527 0.62%
sun-java 3.528 3.307 3.214 3.353 3.557 4.090 5.230 3.630 3.271 3.332 3.651 0.50%
extensions 3.212 3.358 4.555 3.236 3.209 3.381 3.321 2.930 3.218 3.225 3.365 0.46%
chrome 3.428 3.121 3.026 3.268 3.209 3.412 3.733 3.284 3.113 3.047 3.264 0.44%
db 2.898 2.558 2.543 2.613 2.672 2.915 3.232 2.978 2.554 2.642 2.761 0.38%
view 2.768 2.497 2.434 2.609 2.570 2.926 3.120 2.626 2.832 2.538 2.692 0.37%
webshell 2.585 2.477 2.709 2.541 2.565 2.946 3.311 2.745 2.601 2.437 2.692 0.37%
build 2.252 2.066 2.162 2.139 2.191 2.201 3.217 2.232 2.486 2.054 2.300 0.31%
jpeg 3.053 1.529 2.110 1.651 1.617 2.396 2.641 1.647 1.526 1.573 1.974 0.27%
config 2.131 1.373 1.466 1.489 1.422 2.659 2.424 1.425 2.003 1.364 1.776 0.24%
probes 0.423 0.426 0.437 0.455 0.447 0.422 0.543 0.435 0.468 0.412 0.447 0.06%


  • A copy of the rules.mk I've edited from the config folder can be found here: config/rules.mk
  • An interesting and note worthy point in the analysis, is that most of these folders are visited multiple times during the build

Release 0.2 - Nov 10

Goal

  • Capture the processes being spawned during build along with its pid, ppid, time, duration, and working directory
  • Try identifying the cause for slow Windows build

Release 0.3 - Dec 1

  • TBA

Project Data

Contribution Instructions

  • Ideas on how to log the following during build time: pid, ppid, start time, end time, process name, current working directory
  • Please feel free to fill in the table to help me collect more data
  • YOU WILL BE CONSIDERED AS A PROJECT CONTRIBUTOR FOR PROVIDING DATA
  • you can time your build by adding the "time" command in front of your build command like so:
    • time make -f client.mk build

Sample Build Data

Build Time Data
Build From Scratch

HH:MM:SS

Rebuilt No Changes

HH:MM:SS

with -j# RAM

(GB)

CPU

(GHz)

HD

(rpm)

OS User Mozconfig
0:55:05 0:20:17 5 4 GB 2.0 Duo 7200 Vista Business Patrick 
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/../obj-@CONFIG_GUESS@
ac_add_options --enable-application=browser
mk_add_options MOZ_CO_PROJECT=browser
mk_add_options MOZ_MAKE_FLAGS=-j5
1:02:35 0:20:09 5 4 GB 2.0 Duo 7200 Vista Business Patrick 
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/../obj-@CONFIG_GUESS@
ac_add_options --enable-application=browser
mk_add_options MOZ_CO_PROJECT=browser
mk_add_options MOZ_MAKE_FLAGS=-j5
ac_add_options --disable-vista-sdk-requirements
ac_add_options --disable-tests
ac_add_options --disable-accessibility
ac_add_options --disable-mochitest
0:59:00 0:20:45 4 4 GB 2.0 Duo 7200 Vista Business Patrick 
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/../obj-@CONFIG_GUESS@
ac_add_options --enable-application=browser
mk_add_options MOZ_CO_PROJECT=browser
mk_add_options MOZ_MAKE_FLAGS=-j4
1:15:25 0:21:22 N/A 4 GB 2.0 Duo 7200 Vista Business Patrick 
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/../obj-@CONFIG_GUESS@
ac_add_options --enable-application=browser
mk_add_options MOZ_CO_PROJECT=browser
1:03:00 0:18:14 N/A 1 GB 1.6 Duo - XP Media Tony
0:58:40 - N/A 1 GB 1.6 Duo - Ubuntu (VirtualBox) Tony
0:55:00 - 4 2.5 GB 1.6 AMD TurionX2 - XP Professional Zaid 
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/../obj-@CONFIG_GUESS@
mk_add_options MOZ_MAKE_FLAGS=-j4
ac_add_options --enable-application=browser
ac_add_options --enable-libxul
ac_add_options --disable-tests
ac_add_options --disable-mochitest
ac_add_options --disable-vista-sdk-requirements
real 0:44:29
user 0:13:16
sys 0:07:52 		real 0:07:48
user 0:05:42
sys 0:03:29 		5 2.5 GB 1.6 AMD TurionX2 - XP Professional Zaid 
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/../obj-@CONFIG_GUESS@
mk_add_options MOZ_MAKE_FLAGS=-j5
ac_add_options --enable-application=browser
ac_add_options --enable-libxul
ac_add_options --disable-tests
ac_add_options --disable-mochitest
ac_add_options --disable-vista-sdk-requirements
real 0:66:34
user 0:13:15
sys 0:07:54 		real 0:09:00
user 0:05:46
sys 0:03:41 		N/A 2.5 GB 1.6 AMD TurionX2 - XP Professional Zaid 
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/../obj-@CONFIG_GUESS@
ac_add_options --enable-application=browser
ac_add_options --enable-libxul
ac_add_options --disable-tests
ac_add_options --disable-mochitest
ac_add_options --disable-vista-sdk-requirements
1:17:44 - 2 1.5 GB 1.8 AMD Mobile Sempron 5400 Vista Business (32-bit) Nino
0:24:15 0:01:07 N/A 2 GB 2.66 Duo 7200 Ubuntu 8.04 (64-bit) Jason
0:15:12 0:01:04 4 2 GB 2.66 Duo 7200 Ubuntu 8.04 (64-bit) Jason
0:28:18 0:01:04 5 1.5 GB 1.66 Duo 5400 Ubuntu 8.04 (32-bit) Jason 
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/../obj-@CONFIG_GUESS@
ac_add_options --enable-application=browser
mk_add_options MOZ_CO_PROJECT=browser
ac_add_options --enable-optimize
ac_add_options --enable-default-toolkit=cairo-gtk2
ac_add_options --disable-tests 
ac_add_options --disable-mochitest
mk_add_options AUTOCONF=autoconf2.13
0:43:14 - - 2 GB 1.80 AMD Mobile Sempron 5400 Ubuntu 8.04 (32-bit) Aaron T 
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/../obj-@CONFIG_GUESS@
ac_add_options --disable-optimize
ac_add_options --disable-static --enable-shared
real 0:18:16
user 0:10:34
sys 0:03:0 		real 0:02:59
user 0:04:15
sys 0:01:23 		5 2 GB (Upgraded to more/faster rame) 2.0 Duo ( OC'd to 2.41 ) 7200 (src) to External (dest) - speed bump doing this Windows XP Professional ( 32-bit) - Visual Studio 2005 Chris Bishop 
 . $topsrcdir/browser/config/mozconfig
mk_add_options MOZ_OBJDIR=/i/mozilla/ff-opt
mk_add_options MOZ_MAKE_FLAGS=-j5
ac_add_options --disable-vista-sdk-requirements
ac_add_options --disable-tests
ac_add_options --disable-debug
ac_add_options --disable-accessibility
real 0:29:13
user 0:11:26
sys 0:03:47 		real 0:05:8
user 0:04:47
sys 0:01:43 		5 1 GB 2.0 Duo ( OC'd to 2.41 ) 7200 Windows XP Professional ( 32-bit) Chris Bishop 
. $topsrcdir/browser/config/mozconfig
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/ff-opt
mk_add_options MOZ_MAKE_FLAGS=-j5
ac_add_options --disable-tests
real 0:36:50
user 0:10:44
sys 0:03:30 		real 0:05:7
user 0:04:17
sys 0:01:31 		5 1 GB 2.0 Duo ( OC'd to 2.41 ) 7200 Windows XP Professional ( 32-bit) - VS 2008 - Vista SDK Chris Bishop 
. $topsrcdir/browser/config/mozconfig
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/ff-opt
ac_add_options --disable-vista-sdk-requirements
ac_add_options --disable-tests
ac_add_options --disable-accessibility
real 0:27:50
user 0:10:51
sys 0:03:42 		real 0:04:46
user 0:04:21
sys 0:01:32 		5 1 GB 2.0 Duo ( OC'd to 2.41 ) 7200 Windows XP Professional ( 32-bit) - VS 2008 - Vista SDK Chris Bishop 
. $topsrcdir/browser/config/mozconfig
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/ff-opt
mk_add_options MOZ_MAKE_FLAGS=-j5
ac_add_options --disable-vista-sdk-requirements
ac_add_options --disable-tests
ac_add_options --disable-accessibility
- 
FireFox:
real    16m12.402s
user    2m23.381s
sys     5m11.815s 

ThunderBird
real    16m26.193s
user    2m15.639s
sys     5m4.316s
5 2 GB AMD turion 64x2 Windows Vista Home ( 32-bit) Chinmay Patel 
. 
ac_add_options --enable-application=mail
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/tbird-debug
mk_add_options MOZ_CO_PROJECT=mail,calendar
ac_add_options --disable-optimize
ac_add_options --enable-debug
mk_add_options MOZ_MAKE_FLAGS=-j5
real 33m57.475s
user 31m40.558s
sys 8m36.924s 		real 2m51.103s
user 0m49.142s
sys 1m3.305s 		4 3 GB 667 MHz Intel Core 2 Duo 2.16 GHz 7200 Mac OSX 10.4.11 Ezadkiel V. Marbella 
. $topsrcdir/browser/config/mozconfig
export MOZCONFIG=~/mozilla/mozconfig-firefox
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/../obj-@CONFIG_GUESS@
mk_add_options MOZ_MAKE_FLAGS=-j5
mk_add_options MOZ_CO_PROJECT=browser
ac_add_options --enable-debug
ac_add_options --enable-tests
ac_add_options --enable-application=browser
53:43 22:18 None 1 GB Intel 3.0 GHZ Single Core 7200 Microsoft Windows XP Service Pack 3 Scott Lunel 
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/obj-firefox
mk_add_options MOZ_CO_PROJECT=browser 
ac_add_options --enable-application=browser
ac_add_options --disable-optimize
ac_add_options --enable-debug
ac_add_options --disable-tests
ac_add_options --disable-vista-sdk-requirements
1Hr 15min _ None 1G Intel 1.8 GHZ Duo Core 7200 Microsoft Windows XP Service Pack 2 Park,KiWon 
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/obj-firefox
mk_add_options MOZ_CO_PROJECT=browser 
ac_add_options --enable-application=browser
ac_add_options --disable-optimize
ac_add_options --enable-debug
ac_add_options --enable-tests
1:05:32 0:11:14 8 4G Quad-core 2.4 7200 Microsoft Windows XP Prof Irina Shoykher 
ac_add_options --enable-application=browser
mk_add_options MOZ_CO_PROJECT=browser
ac_add_options --disable-vista-sdk-requirements
ac_add_options --enable-debug
ac_add_options --disable-optimize
ac_add_options --enable-libxul
ac_add_options --disable-tests
ac_add_options --disable-mochitest
ac_add_options --disable-accessibility
mk_add_options MOZ_MAKE_FLAGS=-j8
real 01:25:35
user 00:14:08
sys 00:18:37 		real 00:19:02
user 00:05:44
sys 00:07:58 		4 1 GB Pentium 4 2.6C 7200 XP Professional Jesse Valianes 
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/../obj-@CONFIG_GUESS@
mk_add_options MOZ_MAKE_FLAGS=-j4
ac_add_options --enable-application=browser
ac_add_options --enable-libxul
ac_add_options --disable-tests
ac_add_options --disable-mochitest
ac_add_options --disable-vista-sdk-requirements

Project News / Updates

November 2008

11/11/2008 -

  • Managed to get process duration

11/06/2008 -

  • Captured processes from a "do-nothing rebuild"
  • Posted description of CSV log on [Bugzilla]
  • Trying to get more accurate data for Benjamin

11/05/2008 -

  • Found a similar app to [Process Explorer] called [Process Monitor]
    • Captures: pid, ppid, start time, end time, process name
    • Can build log file
  • Posted finding on [Bugzilla]
  • Asking for further directions/hints for project

11/04/2008 -

  • Played with [Process Explorer]
    • Captured: pid, ppid, start time, end time, process name
    • Finding ways to log it

October 2008

10/20/2008 -

  • Redo Pie Chart
    • Used all 10 Rebuild Data
  • Changed the app to generate better extractions from logs

10/17/2008 -

  • Finished making app to extract times from log
    • App breaks down log into 3 files
      • File with all lines starting with 'make' (directory path) and 'real' (time)
      • File with just 1 'make' and 1 'real' line for each time - there are times for multiple 'make'
      • File with just level 1 directory times
  • Adding times up for amount spent in each level 1 directory
  • Created diagram to illustrate time breakdown

10/15/2008 -

  • Creating app to extract time from log
  • Timing the build multiple times for both scratch and rebuilds (aiming for 10 builds each)

10/13/2008 -

  • Timed time spent in each directory
  • Working on extracting the data from log

10/02/2008 -

  • Talked with Ted, guided me to look into rules.mk
  • Continuing testing for timing the build

September 2008

09/30/2008 -

  • Looked through many files and still haven't found where code for timing can go
  • Suspect most options don't affect build speed, except -j and optimize

09/25/2008 -

  • After couple more testing with the build options, starting to notice they don't make a big difference

09/18/2008 -

  • Use time command to time build time
    • ie. time make -f client.mk build
  • Start collecting data

09/17/2008 -

  • Built the first time in 1h 20m
  • Rebuilt second time in 35m with all apps off
  • Talked with Shaver and directed me to thread on shrinking build time
    • Thread talked about /MP command for building in VS -> not useful in my case
  • Dave's suggestion
    • Understand what each part of the build is taking
    • Collect win32 build times from colleagues

09/16/2008 -

  • Talked with Ted Mielczarek, briefly discussed about where to start and how to approach this project.
    • Start by timing how long each make file is
    • Identify which make file takes a long time

09/15/2008 -

  • Created Project page for this project.
Retrieved from "https://wiki.cdot.senecapolytechnic.ca/w/index.php?title=Profile_the_build_system&oldid=20360"