Closed Bug 933558 Opened 11 years ago Closed 3 years ago

Speed up cl.py

Categories

(Firefox Build System :: General, defect)

All
Windows 7
defect
Not set
normal

Tracking

(Not tracked)

RESOLVED INVALID

People

(Reporter: ziga.seilnacht, Unassigned)

Details

Attachments

(8 files, 9 obsolete files)

(deleted), patch
glandium
: review+
Details | Diff | Splinter Review
(deleted), patch
glandium
: review+
Details | Diff | Splinter Review
(deleted), patch
glandium
: review+
Details | Diff | Splinter Review
(deleted), application/zip
Details
(deleted), patch
glandium
: review-
Details | Diff | Splinter Review
(deleted), patch
glandium
: review+
Details | Diff | Splinter Review
(deleted), patch
Details | Diff | Splinter Review
(deleted), application/octet-stream
Details
Bug 585011 has nicely sped up cl.py for pymake clobber builds, however cl.py still takes up a large part of mozmake builds: Running 'python mach build' took 00:30:09 seconds. Ran 77128 processes. top programs, by CPU time used: ncalls CPU time memory(max) IO(ops) IO(bytes) program ========================================================================== 6801 6375.4 s 114 MB 57638041 58.6 GB cl.exe 5429 1621.6 s 12.0 MB 182712509 7.18 GB mozbuild.action.cl 43346 782.9 s 6.50 MB 34856912 1.98 GB sh.exe 5539 537.2 s 7.45 MB 13228880 3.77 GB nsinstall.py 3282 256.0 s 9.67 MB 3424806 736 MB mozmake.exe 1086 90.6 s 453 MB 294645 5.57 MB link.exe 945 69.2 s 21.0 MB 2132361 672 MB mozbuild.action.link_deps 176 68.0 s 15.4 MB 617385 180 MB xpidl-process.py 1767 65.7 s 90.9 MB 122651 29.7 MB genrb.exe 1 24.7 s 66.9 MB 45467 13.4 MB ipdl.py cl.py is also still a large part of pymake clobber build (as part of multiprocessing.forking:main): Running 'python mach build -p' took 00:35:00 seconds. Ran 23890 processes. top programs, by CPU time used: ncalls CPU time memory(max) IO(ops) IO(bytes) program ============================================================================ 6800 5791.7 s 114 MB 57591919 58.6 GB cl.exe 433 496.5 s 24.1 MB 150339475 1.73 GB multiprocessing.forking:main 54 338.6 s 37.7 MB 947626 389 MB make.py 1200 123.0 s 7.45 MB 2878773 797 MB nsinstall.py 1086 83.2 s 453 MB 293733 5.57 MB link.exe 7471 83.0 s 6.44 MB 4526378 336 MB sh.exe 176 68.4 s 15.3 MB 616769 180 MB xpidl-process.py 1767 43.8 s 90.9 MB 124688 29.7 MB genrb.exe 162 20.5 s 9.42 MB 587515 127 MB expandlibs_exec.py 361 20.4 s 6.85 MB 681885 195 MB expandlibs_gen.py I perfomed all measurements on mozilla-central changeset 186e834d87dc, which includes fixes for bug 585011 and bug 929983, with a slightly modified version of tool from bug 755684. Before running `mach build` I ran `hg purge --all` followed by `mach configure`. I used mozmake from birch changeset c06c1c751c7c. The measurements were taken on an 8 core (with hyperthreading) 3rd gen i7 laptop with 8GB of RAM and a fast SSD running Windows 7 professional 64bit. From the profiles for cl.py it seems that most time is spent in mozprocess and the modules it imports: top functions for 'mozbuild.action.cl', by function's internal time: ncalls tottime cumtime filename:lineno(function) ------------------------------------------------------------------------------ 163752 10975.772 11193.166 {time.sleep} 3072934 4035.468 4041.584 {file.readline} 5429 79.669 84.244 Lib/platform.py:553(win32_ver) 3059479 68.443 156.290 mozbuild/action/cl.py:25(normcase) 5429 58.913 841.478 mozprocess/processhandler.py:5(<module>) 5429 54.946 476.647 mozfile/mozfile.py:7(<module>) 5429 51.996 52.076 Lib/shutil.py:5(<module>) 5429 50.603 51.898 Lib/socket.py:45(<module>) 5429 46.696 53.471 Lib/ctypes/__init__.py:4(<module>) 6124387 39.660 46.747 lib/ntpath.py:164(split) 5429 39.405 65.394 Lib/tarfile.py:31(<module>) 5429 36.129 99.410 Lib/tempfile.py:18(<module>) 5429 35.981 35.981 {nt.urandom} 5429 34.109 8713.745 mozprocess/processhandler.py:723(wait) 5429 31.648 729.919 mozinfo/mozinfo.py:11(<module>) 5429 31.506 160.940 Lib/urllib2.py:76(<module>) 5429 26.387 26.387 {compile} 16287 26.063 30.340 {__import__} 5429 24.559 24.582 Lib/copy.py:49(<module>) 2312976 24.346 42.577 mozbuild/makeutil.py:76(update) I have some patches that should reduce cl.py overhead.
This patch fixes error checking in cl.py, it might have caught bug 929983.
Attachment #825666 - Flags: review?(gps)
This effectively reverts bug 799189. The issue of output from cl.exe getting buffered, which was the reason for switching to mozprocess, should be solved by flushing stdout and stderr. This reduces clobber build time by 2-3 minutes when using mozmake and by 1 minute when using pymake for me. The reduction in used CPU time is even more noticeable: ncalls CPU time memory(max) IO(ops) IO(bytes) program ============================================================================ 6801 6336.7 s 114 MB 57617490 58.6 GB cl.exe 43345 789.8 s 6.50 MB 34856414 1.98 GB sh.exe 5429 707.1 s 8.73 MB 18156891 3.35 GB mozbuild.action.cl 5538 535.3 s 7.46 MB 13217412 3.77 GB nsinstall.py 3282 254.0 s 9.63 MB 3423498 736 MB mozmake.exe The profile also looks muck nicer, most of the time is now spent waiting on cl.exe to finish: ncalls tottime cumtime filename:lineno(function) ------------------------------------------------------------------------------ 16287 7458.547 7370.008 {file.read} 119390 7051.288 7747.966 {thread.lock.acquire} 3059479 60.524 132.255 mozbuild/action/cl.py:25(normcase) 5429 45.818 52.497 Lib/ctypes/__init__.py:4(<module>) 6124387 33.971 39.502 lib/ntpath.py:164(split) 5429 26.403 26.403 {compile} 10858 23.511 25.129 {__import__} 16275 21.966 7487.411 Lib/threading.py:308(wait) 2312976 17.161 31.592 mozbuild/makeutil.py:76(update) 5429 11.782 11.782 {_subprocess.WaitForSingleObject} 5429 11.614 11.614 {_subprocess.CreateProcess} 3070337 11.613 16.235 lib/ntpath.py:63(join) 148668 9.099 9.287 Lib/ctypes/__init__.py:297(create_unicode_buffer) 3997007 8.626 12.122 mozbuild/makeutil.py:77(_add) 5429 8.533 8.975 Lib/runpy.py:8(<module>) 2302118 7.974 50.367 mozbuild/makeutil.py:108(add_dependencies) 9205582 6.007 6.007 lib/ntpath.py:122(splitdrive) 4941247 5.532 14.406 {isinstance} 2312976 4.548 8.877 lib/abc.py:128(__instancecheck__) 5429 3.982 9.865 mozbuild/makeutil.py:5(<module>)
Attachment #825669 - Flags: review?(gps)
Adding all dependencies at once reduces clobber build time by 10-15 seconds for both mozmake and pymake, the reduction in CPU time is a bit larger, 60s. This also skips path normalization for paths with spaces (presumed system headers) and moves deps file manipulation to a single place. rule.add_dependencies and most of its callees is now gone from the profile: ncalls tottime cumtime filename:lineno(function) ---------------------------------------------------------------------------- 16287 7328.636 7236.032 {file.read} 119354 6897.176 7621.408 {thread.lock.acquire} 2302118 45.496 99.596 python/mozbuild/mozbuild/action/cl.py:25(normcase) 5429 45.079 51.931 Lib/ctypes/__init__.py:4(<module>) 5429 26.500 26.500 {compile} 4609665 25.477 29.537 lib/ntpath.py:164(split) 10858 23.573 25.368 {__import__} 16266 21.685 7346.199 Lib/threading.py:308(wait) 5429 11.456 11.456 {_subprocess.CreateProcess} 5429 10.264 10.264 {_subprocess.WaitForSingleObject} 5429 8.529 8.973 Lib/runpy.py:8(<module>) 2312976 8.366 11.734 lib/ntpath.py:63(join) 114148 7.825 8.003 Lib/ctypes/__init__.py:297(create_unicode_buffer) 6933499 4.425 4.425 lib/ntpath.py:122(splitdrive) 5429 4.419 10.038 python/mozbuild/mozbuild/makeutil.py:5(<module>) 1700318 4.289 6.885 python/mozbuild/mozbuild/makeutil.py:77(_add) 5429 3.585 4.912 Lib/subprocess.py:579(list2cmdline) 9473775 3.161 3.161 {list.append} 46023 2.591 7.668 {file.write} 5429 2.295 2.404 Lib/subprocess.py:389(<module>) Call count for _add is unrealistically high due to cProfile getting confused by generators.
Attachment #825677 - Flags: review?(mh+mozilla)
The added filename cache helps mostly with pymake builds, where os.path.split and os.path.join were showing in profiles. Overallocating the ctypes buffer is useful mostly with mozmake, where the directory cache isn't as effective as with pymake. These changes reduce both pymake and mozmake clobber build times by about 5-10 seconds, almost in the noise. However, they do reduce cl.py's use of CPU time by 40-50 seconds.
Attachment #825683 - Flags: review?(mh+mozilla)
cl.py becoming a native pymake command has exposed an inefficiency in pymake, in the way it clears an repopulates the os.environ dictionary. This patch reduces the amount of time spent in nt.putenv by more than 60 seconds: before: ncalls tottime cumtime filename:lineno(function) ----------------------------------------------------------------------------- 14942 7117.281 7117.281 {_multiprocessing.SemLock.acquire} 209340 5860.493 5787.207 {file.read} 97150 5472.285 6148.436 {thread.lock.acquire} 14929 1285.981 1285.981 {_multiprocessing.PipeConnection.recv} 9034 812.121 812.356 {_subprocess.WaitForSingleObject} 4972386 79.754 79.754 {nt.putenv} 9034 10.436 10.436 {_subprocess.CreateProcess} 9454 5.345 13.640 lib/threading.py:724(start) 25795 3.933 3.933 {open} 9034 3.540 4.535 lib/subprocess.py:579(list2cmdline) after: ncalls tottime cumtime filename:lineno(function) ----------------------------------------------------------------------------- 16998 8110.911 8110.911 {_multiprocessing.SemLock.acquire} 237552 6704.982 6617.556 {file.read} 110612 6277.734 7003.540 {thread.lock.acquire} 16984 1421.208 1421.208 {_multiprocessing.PipeConnection.recv} 10312 891.730 892.131 {_subprocess.WaitForSingleObject} 10312 11.631 11.631 {_subprocess.CreateProcess} 51280 7.390 7.390 {open} 173402 5.491 5.491 {nt.putenv} 10800 4.253 12.023 lib/threading.py:724(start) 10312 3.949 5.056 lib/subprocess.py:579(list2cmdline) The clobber build time with pymake is reduced by 15-20 seconds.
Attachment #825700 - Flags: review?(mh+mozilla)
All of these patches combined reduce the clobber build time by 2-3 minutes for me. The data for mozmake with all patches applied: Running 'python mach build' took 00:27:25 seconds. Ran 77126 processes. top programs, by CPU time used: ncalls CPU time memory(max) IO(ops) IO(bytes) program ============================================================================== 6801 6338.7 s 114 MB 57617445 58.6 GB cl.exe 43345 790.6 s 6.48 MB 34856300 1.98 GB sh.exe 5429 589.4 s 8.76 MB 16008330 3.29 GB mozbuild.action.cl 5538 536.5 s 7.46 MB 13217694 3.77 GB nsinstall.py 3282 252.6 s 9.65 MB 3422853 736 MB mozmake.exe 1086 89.9 s 453 MB 294640 5.57 MB link.exe 945 69.1 s 20.9 MB 2131829 672 MB mozbuild.action.link_deps 176 68.2 s 15.4 MB 617281 180 MB xpidl-process.py 1767 65.6 s 90.9 MB 122654 29.7 MB genrb.exe 1 25.2 s 66.9 MB 44119 13.4 MB ipdl.py and for pymake: Running 'python mach build -p' took 00:33:27 seconds. Ran 23892 processes. top programs, by CPU time used: ncalls CPU time memory(max) IO(ops) IO(bytes) program =========================================================================== 6800 5764.8 s 114 MB 57597364 58.6 GB cl.exe 54 338.6 s 37.7 MB 947535 389 MB make.py 433 143.2 s 24.1 MB 6228218 1.73 GB multiprocessing.forking:main 1201 122.9 s 7.44 MB 2881015 797 MB nsinstall.py 1086 84.0 s 453 MB 293730 5.57 MB link.exe 7472 82.1 s 6.46 MB 4527088 336 MB sh.exe 176 67.9 s 15.4 MB 616993 181 MB xpidl-process.py 1767 44.3 s 90.9 MB 124688 29.7 MB genrb.exe 162 20.1 s 9.45 MB 587546 127 MB expandlibs_exec.py 361 18.8 s 6.88 MB 681979 195 MB expandlibs_gen.py
Assignee: nobody → ziga.seilnacht
Status: UNCONFIRMED → ASSIGNED
Ever confirmed: true
Comment on attachment 825666 [details] [diff] [review] (part 1) cl.py should exit with an error when called without a target file Review of attachment 825666 [details] [diff] [review]: ----------------------------------------------------------------- ::: python/mozbuild/mozbuild/action/cl.py @@ +51,5 @@ > if arg.startswith("-Fo"): > target = arg[3:] > break > > + if target == "": if not target. @@ +52,5 @@ > target = arg[3:] > break > > + if target == "": > + print >>sys.stderr, "No dependency target set: %r" % cmdline Might as well make it "-Fo argument not found". Please attach a revised patch.
Attachment #825666 - Flags: review?(gps)
Comment on attachment 825669 [details] [diff] [review] (part 2) don't use mozprocess in cl.py, its use accounts for 20% of clobber build CPU time Review of attachment 825669 [details] [diff] [review]: ----------------------------------------------------------------- I think I'd prefer to see improvements made to mozprocess, which would result in improvements to other things, than a local cl.py workaround by moving off it.
Attachment #825669 - Flags: review?(gps) → review-
Comment on attachment 825677 [details] [diff] [review] (part 3) speed up cl.py's dependency addition, by adding all dependencies at once. Review of attachment 825677 [details] [diff] [review]: ----------------------------------------------------------------- Like for part 2, this ought to be made at another level. Here, that should be done in makeutil.py, which would then benefit to other things using makeutil.py. On simple way to do this is to make makeutil.py store the list of things that are added, and only actually add them when dependencies are being read (which is what it already does to eliminate circular dependencies). You could also do the same for targets, for consistency.
Attachment #825677 - Flags: review?(mh+mozilla) → review-
Comment on attachment 825683 [details] [diff] [review] (part 4) speed up normcase by adding a cache for filenames and reducing the number of ctypes calls Review of attachment 825683 [details] [diff] [review]: ----------------------------------------------------------------- ::: python/mozbuild/mozbuild/action/cl.py @@ +48,5 @@ > + if length > buflen: > + buflen = length > + buf = ctypes.create_unicode_buffer(dir, buflen) > + length = GetShortPathName(buf, buf, buflen) > + shortdir = buf[:length] you don't need this assignment until you actually call create_unicode_buffer below. @@ +53,5 @@ > + length = GetLongPathName(buf, buf, buflen) > + if length > buflen: > + buf = ctypes.create_unicode_buffer(shortdir, length) > + length = GetLongPathName(buf, buf, length) > + result = _normcase_cache[dir] = buf[:length] buf.value. @@ +55,5 @@ > + buf = ctypes.create_unicode_buffer(shortdir, length) > + length = GetLongPathName(buf, buf, length) > + result = _normcase_cache[dir] = buf[:length] > + path = os.path.join(result, name) > + _normcase_file_cache[origpath] = path Might as well use the same cache. That being said, I think this cache here would benefit from sharing some logic with the other normcase cache in link_deps.py. I'll attach an alternative proposal.
Attachment #825683 - Flags: review?(mh+mozilla)
Comment on attachment 825700 [details] [diff] [review] (part 5) speed up os.environ cleaning, putenv is expensive on Windows Review of attachment 825700 [details] [diff] [review]: ----------------------------------------------------------------- ::: build/pymake/pymake/process.py @@ +416,4 @@ > return 0 > > + > +def _replace_env(env): This should be a class method. @@ +420,5 @@ > + # Don't use os.environ.clear(); os.environ.update(), they use putenv > + # instead of rewriting the whole environment block at once. And on > + # Windows, putenv needs to rewrite the whole environment block each > + # time it is called. > + for var in set(os.environ).difference(env): set(os.environ) - set(env)
Attachment #825700 - Flags: review?(mh+mozilla) → feedback+
Comment on attachment 825683 [details] [diff] [review] (part 4) speed up normcase by adding a cache for filenames and reducing the number of ctypes calls (In reply to Mike Hommey [:glandium] from comment #10) > That being said, I think this cache here would benefit from sharing some > logic with the other normcase cache in link_deps.py. I'll attach an > alternative proposal. On further thought, this wouldn't be beneficial. So please attach a new revision with the review comments addressed.
Attachment #825683 - Flags: feedback+
(In reply to Mike Hommey [:glandium] from comment #7) >> + if target == "": > > if not target. OK. >> + print >>sys.stderr, "No dependency target set: %r" % cmdline > > Might as well make it "-Fo argument not found". OK.
Attachment #825666 - Attachment is obsolete: true
Attachment #828469 - Flags: review?(mh+mozilla)
(In reply to Mike Hommey [:glandium] from comment #8) > I think I'd prefer to see improvements made to mozprocess, which would > result in improvements to other things, than a local cl.py workaround by > moving off it. OK. It turns out that improving mozprocess should be fairly simple, most of its overhead is spent importing mozinfo. Replacing mozinfo use with os.name and removing the unused logging import removes almost all of mozprocess overhead. Improving mozinfo would be harder, see the comments in the patch. I'll rebase this patch against the github repo, let me know if I should open a separate bug for it or if you wish to handle the patch in this bug. Some numbers for this patch: ncalls CPU time memory(max) IO(ops) IO(bytes) program ============================================================================== before: 5429 1727.8 s 12.0 MB 182701611 7.18 GB mozbuild.action.cl after: 5429 911.7 s 8.40 MB 164145455 3.67 GB mozbuild.action.cl ncalls tottime cumtime filename:lineno(function) ------------------------------------------------------------------------------ before: 5429 60.866 874.248 mozprocess/processhandler.py:5(<module>) after: 5429 37.060 62.930 mozprocess/processhandler.py:5(<module>)
Attachment #825669 - Attachment is obsolete: true
Attachment #828475 - Flags: feedback?(mh+mozilla)
I think that collecting the output from cl.exe and writing it out in a single operation would still be beneficial, I think this is one of the causes of bug 935050. Not doing that can also mix up compiler output from concurrently running processes, which could lead to confusing compiler error messages.
Attachment #828478 - Flags: review?(mh+mozilla)
(In reply to Mike Hommey [:glandium] from comment #9) > Like for part 2, this ought to be made at another level. Here, that should > be done in makeutil.py, which would then benefit to other things using > makeutil.py. On simple way to do this is to make makeutil.py store the list > of things that are added, and only actually add them when dependencies are > being read (which is what it already does to eliminate circular > dependencies). You could also do the same for targets, for consistency. OK. It turns out that most of the time was spent creating the closure in makeutil._SimpleOrderedSet.update. Other makeutil users weren't affected by that because they already add all the dependencies in a single add_dependencies call. The old patch still adds a minor improvement and it also reduces the number of normpath calls by checking for spaces in path twice. Let me know if you want me to rebase it and which parts should be kept.
Attachment #825677 - Attachment is obsolete: true
Attachment #828483 - Flags: review?(mh+mozilla)
(In reply to Mike Hommey [:glandium] from comment #10) >> + shortdir = buf[:length] > > you don't need this assignment until you actually call create_unicode_buffer > below. OK. >> + result = _normcase_cache[dir] = buf[:length] > > buf.value. OK. I expected that buf.value returns the whole buffer, not just the value up to the first null byte. > > + _normcase_file_cache[origpath] = path > > Might as well use the same cache. OK.
Attachment #825683 - Attachment is obsolete: true
Attachment #828486 - Flags: review?(mh+mozilla)
(In reply to Mike Hommey [:glandium] from comment #11) >> +def _replace_env(env): > > This should be a class method. OK. >> + for var in set(os.environ).difference(env): > > set(os.environ) - set(env) OK.
Attachment #825700 - Attachment is obsolete: true
Attachment #828488 - Flags: review?(mh+mozilla)
What tool did you use to capture all this data?
Attached file mwtrace.zip (deleted) —
(In reply to Gregory Szorc [:gps] from comment #19) > What tool did you use to capture all this data? A hacked up version of tool from bug 755684, see the attachment. You need to run it from the root of a hg repo like this: python path/to/mwtrace/tracemach.py <path/to/collected/data/directory> Note: the tool runs `hg purge --all` as part of the process. You also need to have pywin32 installed. The tool will perform a clobber build four times, twice with mozmake and twice with pymake. The first time it injects cProfile in every python process, the second time it runs without the profiler, collecting just the process data. At the end of the run, it generates a report.txt file for each step performed in the specified folder, containing the summary of collected data. The folder also contains the raw collected data. The tool itself cannot be installed, because it abuses the usersite machinery to inject the profiler into python child processes. It also comes with a slightly modified copy of multiprocessing, because multipocessing is horrible and doesn't run atexit handlers. The caller / callee profile data is not entirely correct, because cProfile doesn't support multiple threads, but the timing information should be reasonably accurate.
Attachment #828469 - Flags: review?(mh+mozilla) → review+
Attachment #828475 - Flags: feedback?(mh+mozilla) → feedback+
Comment on attachment 828478 [details] [diff] [review] (part 2b) make sure that all relevant output from cl.exe is flushed and kept together Review of attachment 828478 [details] [diff] [review]: ----------------------------------------------------------------- ::: python/mozbuild/mozbuild/action/cl.py @@ +99,5 @@ > ret = p.wait() > > + # Flush stdout so that compiler errors don't get hidden. > + sys.stdout.writelines(stdout_lines) > + sys.stdout.flush() This flush is not necessary, with the recent pymake changes.
Attachment #828478 - Flags: review?(mh+mozilla) → feedback+
Attachment #828483 - Flags: review?(mh+mozilla) → review+
Attachment #828486 - Flags: review?(mh+mozilla) → review+
Attachment #828488 - Flags: review?(mh+mozilla) → review+
Comment on attachment 828469 [details] [diff] [review] (part 1v2) cl.py should exit with an error when called without a target file Review of attachment 828469 [details] [diff] [review]: ----------------------------------------------------------------- Actually, I have to retract, here, this breaks the preprocessing rules (make -C path foo.i)
Attachment #828469 - Flags: review+ → review-
(In reply to Mike Hommey [:glandium] from comment #22) > Actually, I have to retract, here, this breaks the preprocessing rules (make > -C path foo.i) OK, I think the check should be removed then, to prevent confusion.
Attachment #828469 - Attachment is obsolete: true
Attachment #833106 - Flags: review?(mh+mozilla)
Here is the previously posted patch against the mozbase git repo. The mozinfo import in mozprocess is very expensive, replacing it with a os.name check reduced the clobber build time on Windows by more than 2 minutes for me.
Attachment #828475 - Attachment is obsolete: true
Attachment #833110 - Flags: review?(ahalberstadt)
(In reply to Mike Hommey [:glandium] from comment #21) > > + # Flush stdout so that compiler errors don't get hidden. > > + sys.stdout.writelines(stdout_lines) > > + sys.stdout.flush() > > This flush is not necessary, with the recent pymake changes. OK, removed. The updated patch is based on top of patch from bug 938428.
Attachment #828478 - Attachment is obsolete: true
Attachment #833116 - Flags: review?(mh+mozilla)
Comment on attachment 833110 [details] [diff] [review] [mozbase] (part 2a) don't depend on mozinfo, it is slow to import, making mozprocess unsuitable for short, often run scripts Review of attachment 833110 [details] [diff] [review]: ----------------------------------------------------------------- Out of curiosity do you have a rough estimate of how many processes we are spawning with mozprocess? I know you said Windows, but it's not bad at all on linux: $ time python -c "import mozinfo" python -c "import mozinfo" 0.05s user 0.04s system 95% cpu 0.099 total I'm ok with taking this, but I think the real fix is making mozinfo cheaper to import (i.e lazy load attributes only when they are accessed, use an alternative to platform.uname, etc). There are many other places where it gets imported and fixing the problem there will give speedups across the board. I'll file a separate bug. Also, please remove the dependency on it from setup.py. r+ with that and below comment addressed. ::: mozprocess/mozprocess/processhandler.py @@ +17,5 @@ > # Set the MOZPROCESS_DEBUG environment variable to 1 to see some debugging output > MOZPROCESS_DEBUG = os.getenv("MOZPROCESS_DEBUG") > > +isWin = os.name == "nt" > +isPosix = os.name == "posix" # includes MacOS X Please add comment explaining why we don't use mozinfo and reference this bug
Attachment #833110 - Flags: review?(ahalberstadt) → review+
Actually scratch that part about removing the dependency. It looks like pid.py still imports it.
(In reply to Andrew Halberstadt [:ahal] from comment #26) > Out of curiosity do you have a rough estimate of how many processes we are > spawning with mozprocess? cl.py is invoked as a script roughly 5400 times during clobber build, each time it imports mozprocess and spawns a single subprocess with it. > I know you said Windows, but it's not bad at all > on linux: > $ time python -c "import mozinfo" > > python -c "import mozinfo" 0.05s user 0.04s system 95% cpu 0.099 total It is not that different on Windows, "python -c 'import mozinfo'" takes between 0.15s and 0.17s for me. However compared to "python -c 'import subprocess'", which takes between 0.7s and 0.9s, most of which is measurement and interpreter startup overhead ("python -c 'pass'" takes between 0.6s and 0.8s) it is quite slow. The profiles show that most of the time is spent importing mozfile, which spends most of the time importing urllib2: ncalls tottime cumtime filename:lineno(function) ------------------------------------------------------------------------------ 1 0.002 0.106 testing/mozbase/mozinfo/mozinfo/__init__.py:52(<module>) 1 0.004 0.105 testing/mozbase/mozinfo/mozinfo/mozinfo.py:11(<module>) 1 0.000 0.076 testing/mozbase/mozfile/mozfile/__init__.py:5(<module>) 1 0.007 0.076 testing/mozbase/mozfile/mozfile/mozfile.py:7(<module>) 1 0.003 0.035 Lib/urllib2.py:76(<module>) 1 0.002 0.029 Lib/httplib.py:67(<module>) 1 0.024 0.024 Lib/socket.py:45(<module>) 1 0.000 0.012 Lib/platform.py:1166(uname) 1 0.004 0.011 Lib/tempfile.py:18(<module>) 27 0.000 0.011 lib/re.py:226(_compile) 26 0.000 0.011 lib/re.py:188(compile) 1 0.006 0.011 Lib/tarfile.py:31(<module>) 26 0.000 0.010 lib/sre_compile.py:496(compile) 1 0.008 0.009 Lib/platform.py:553(win32_ver) 1 0.009 0.009 Lib/shutil.py:5(<module>) 1 0.001 0.007 Lib/random.py:40(<module>) 1 0.001 0.007 Lib/platform.py:10(<module>) I'll attach cl.py's combined profile for a complete clobber build, it's in the standard profile format that can be analyzed with the stdlib's pstats module. > > > > +isWin = os.name == "nt" > > +isPosix = os.name == "posix" # includes MacOS X > > Please add comment explaining why we don't use mozinfo and reference this bug OK.
Attachment #833110 - Attachment is obsolete: true
Attachment #833198 - Flags: checkin?
Comment on attachment 833106 [details] [diff] [review] (part 1v3) remove misleading check, missing -Fo argument must be tolerated Review of attachment 833106 [details] [diff] [review]: ----------------------------------------------------------------- The -showIncludes part and dependency gathering should be avoided when there is no target detected.
Attachment #833106 - Flags: review?(mh+mozilla) → review-
Attachment #833116 - Flags: review?(mh+mozilla) → review+
Comment on attachment 833198 [details] [diff] [review] [mozbase] (part 2a) don't depend on mozinfo, it is slow to import (for checkin) Checked into mozbase: https://github.com/mozilla/mozbase/commit/564d252a176f63fe359c79ee23481bcfcb43800a Note this change will still need to be landed in mozilla-central.
Attachment #833198 - Flags: checkin? → checkin+
Product: Core → Firefox Build System

The bug assignee didn't login in Bugzilla in the last 7 months.
:mhentges, could you have a look please?
For more information, please visit auto_nag documentation.

Assignee: ziga.seilnacht → nobody
Status: ASSIGNED → NEW
Flags: needinfo?(mhentges)

cl.py no longer exists

Status: NEW → RESOLVED
Closed: 3 years ago
Flags: needinfo?(mhentges)
Resolution: --- → INVALID
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: