Last Comment Bug 459891 - (build-perf) Mozilla Firefox build time on Windows is extremely slow
(build-perf)
: Mozilla Firefox build time on Windows is extremely slow
Status: NEW
[tracking][buildfaster:p3]
:
Product: Core
Classification: Components
Component: Build Config (show other bugs)
: Trunk
: x86 Windows Vista
: -- normal with 6 votes (vote)
: ---
Assigned To: Nobody; OK to take it and work on it
:
Mentors:
http://zenit.senecac.on.ca/wiki/index...
Depends on: PCH 585010 602492 602497 602498 602499 428532 461395 461444 462381 462463 462464 466486 466492 485412 518107 518136 603214 623617 717620 832472
Blocks: 755684
  Show dependency treegraph
 
Reported: 2008-10-14 11:07 PDT by Patrick PC Lam
Modified: 2014-06-29 18:34 PDT (History)
26 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---


Attachments
Dtrace output from building xpcom, no-change depend (135.75 KB, text/plain)
2008-11-21 14:23 PST, Benjamin Smedberg AWAY UNTIL 2-AUG-2016 [:bsmedberg]
no flags Details

Description Patrick PC Lam 2008-10-14 11:07:28 PDT
User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 6.0; en-US; rv:1.9.0.3) Gecko/2008092417 Firefox/3.0.3
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 6.0; en-US; rv:1.9.0.3) Gecko/2008092417 Firefox/3.0.3

Mozilla Firefox build time on Windows is extremely slow. Compared to other platforms, the build time on Windows can take up to 2-3 times longer. I am currently trying to look for the source of this problem and possibly enhance the build time.

Reproducible: Always

Steps to Reproduce:
1.
2.
3.
Comment 1 Benjamin Smedberg AWAY UNTIL 2-AUG-2016 [:bsmedberg] 2008-10-20 06:24:54 PDT
Assuming you've done the obvious stuff like disable virus-scan and use FAT32 instead of NTFS, the next steps are all "hard". Although if you have the ability to create profiles of where we're spending time, that could be useful.
Comment 2 Patrick PC Lam 2008-10-20 07:43:21 PDT
Well, right now, I have managed to create a simple profile which just calculates where time was spent according to the directories that are 1 level down from root. I am going to try and build a more detail profile soon. But for now, this is what I have.

http://zenit.senecac.on.ca/wiki/index.php/Profile_the_build_system#Release_0.1_-_Oct_13
Comment 3 Ted Mielczarek [:ted.mielczarek] 2008-10-20 07:51:24 PDT
Patrick: I think Benjamin just thought this was a bug report, instead of a bug about the work you're doing. We often get people complaining that the build is slow, or things are broken.
Comment 4 Patrick PC Lam 2008-10-20 08:05:09 PDT
Oh, oops, sorry for not making the bug descriptioin clear or filing the bug properly. I'm still not too familiar with bugzilla and I guess I should have been more descriptive in the description.

Right now, the info I have posted is just for the rebuilt of mozilla. I'm going to analyze the rest of my data and have the built time from scratch up as well within this week.

Ted: Any pointers what the next step I should do now?
Comment 5 Ted Mielczarek [:ted.mielczarek] 2008-10-20 08:20:40 PDT
Patrick: so that chart is from a rebuild after doing a full build, with nothing changed? That's the case we're most interested in, I think, since in a build from scratch, most of the time is spent compiling. In a rebuild with nothing changed, most of the time is wasted, since ideally it would take no time at all.

Shaver had some ideas for speeding things up a bit, I might have a patch you can try sometime this week for comparison.

One thing I'd love to see, if you can figure out how (perhaps using Process Explorer? http://technet.microsoft.com/en-us/sysinternals/bb896653.aspx) is a list of all the programs that get executed in a build (or rebuild) and how much time they take up. I suspect part of our slowness is due to lots of process spawning, but it's hard to know if that's a real problem or not. Clearly we run 'make' itself way too many times, but there may be some other things that the build system does that we could make better.
Comment 6 Ted Mielczarek [:ted.mielczarek] 2008-10-23 11:31:50 PDT
Added a few dependencies on things I'm currently working on that can help here.
Comment 7 Chris AtLee [:catlee] 2008-10-24 09:57:18 PDT
It'd be nice to get a log of something like:
pid, ppid, start time, end time, process name

for every process in the build.  We may be able to use some of the work done for http://www.bootchart.org/ to process the logs.

Not sure if Process Explorer or some other app could get this data for us on windows.  If not, we may be able to write our own:
http://msdn.microsoft.com/en-us/library/aa390425%28vs.85%29.aspx
Comment 8 Patrick PC Lam 2008-11-05 19:20:03 PST
I managed to find Process Monitor (http://technet.microsoft.com/en-us/sysinternals/bb896645.aspx) which I think does the trick. I tracks down the process name, pid, ppid, time, duration, and many other things.

I'll try to get a log posted for a rebuild of firefox with no change asap.

Any hints on what to do after this point?
Comment 9 Ted Mielczarek [:ted.mielczarek] 2008-11-06 03:54:23 PST
Patrick: making things faster is sort of dependent on knowing what makes it slow. I've marked a bunch of bugs as dependent bugs here, I think they'll all have a positive effect on build time. Ideally, you could produce some data for us showing what is taking the most time in a rebuild currently, and if it's not something that's already covered by a bug, figure out what to fix, file a new bug and fix it. :)
Comment 10 Patrick PC Lam 2008-11-06 13:22:52 PST
I've got a CSV file containing the logs of all the processes during the rebuild. The file is rather big (112MB, not sure where to post it) and I'm not sure what to do with the data. The log has the Process Name, PID, PPID, Time started, Duration, Operation, Command Line, and Path.

It captured the following process: basename.exe, bash.exe, cat.exe, cmp.exe, cp.exe, dirname.exe, iconv.exe, make.exe, makensis.exe, mkdir.exe, mv.exe, nsinstall.exe, perl.exe, python.exe, rm.exe, sed.exe, sh.exe, tar.exe, touch.exe, uname.exe, xpidl.exe, xpt_link.exe, zip.exe.

There is a total of 624229 processes captures in this log and 98346 of them are make.exe. And the Operations called by make.exe are: Load Image, Process Create, Process Exit, Process Start, Thread Create, and Thread Exit.
I'm not sure why, but all the processes in this log had a duration of 0 even down to 7 decimal points. So I don't even know how to go about calculating the time used by the processes.
Comment 11 Benjamin Smedberg AWAY UNTIL 2-AUG-2016 [:bsmedberg] 2008-11-06 13:31:57 PST
To be clear: this log is just a do-nothing rebuild, right?

Is it possible to get a log with the working directory also?

Sounds like the duration information is bogus... many of the intermediate make invocations will have long duration, but will spend little or no actual CPU time; they will just sit around and wait for other sub-makes to finish. Is it possible to collect total CPU time per process, and/or the time the process ended?
Comment 12 Patrick PC Lam 2008-11-06 14:11:57 PST
Yes, this log is for a do-nothing rebuild.

Working directory as in where in the mozilla code the process is being called?

Maybe the duration is for how long it needs to invoke the process? And not the actual duration of the process from start to exit. Let me dig around and see if I can get the CPU time for the processes.
Comment 13 Benjamin Smedberg AWAY UNTIL 2-AUG-2016 [:bsmedberg] 2008-11-06 14:16:27 PST
Well... the working directory will help tell us where in the code it was called... but it's just the result of GetWorkingDirectory() for the process.
Comment 14 Patrick PC Lam 2008-11-11 09:55:05 PST
I still haven't been able to log their current working directory, but I was able to get their process time now.

As of now, with the profiling done so far, I suspect that the cause for the slowness in compiling is due to the excessive make call throughout the whole structure. So I believe this is related to bug 461444 (remove cases of excessive recursion in makefiles) and 462463 (make dependencies smarter).

I'll try to get the working directories of the make.exe and see if there is such a problem exisiting in the directories using a lot of time during the build.
Comment 15 Patrick PC Lam 2008-11-18 13:38:27 PST
Sorry guys, I had a project change and won't be able to spend time on this project.
Comment 16 Benjamin Smedberg AWAY UNTIL 2-AUG-2016 [:bsmedberg] 2008-11-21 14:23:56 PST
Created attachment 349492 [details]
Dtrace output from building xpcom, no-change depend

This is interesting: I ran trace profiling of a no-change rebuild of xpcom/ on solaris. A few things stand out:

1) when DIRS isn't set we're still launching a shell to recurse into subdirs: it just happens to do nothing:

`/bin/sh -c set -e; true`

2) We're checking for jar.mn in each directory with a shell command: we could avoid launching the subshell by using a $(wildcard jar.mn) check

3) running mddepend.pl is by far our largest consumer of CPU

Note You need to log in before you can comment on or make changes to this bug.