933558 - Speed up cl.py

Status: RESOLVED INVALID

(Firefox Build System :: General, defect)

Description

[Ziga Seilnacht]

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.

Comment 1

[Ziga Seilnacht]

Attachment: (part 1) cl.py should exit with an error when called without a target file

This patch fixes error checking in cl.py, it might have caught bug 929983.

Comment 2

[Ziga Seilnacht]

Attachment: (part 2) don't use mozprocess in cl.py, its use accounts for 20% of clobber build CPU time

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>)

Comment 3

[Ziga Seilnacht]

Attachment: (part 3) speed up cl.py's dependency addition, by adding all dependencies at once.

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.

Comment 4

[Ziga Seilnacht]

Attachment: (part 4) speed up normcase by adding a cache for filenames and reducing the number of ctypes calls

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.

Comment 5

[Ziga Seilnacht]

Attachment: (part 5) speed up os.environ cleaning, putenv is expensive on Windows

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.

Comment 6

[Ziga Seilnacht]

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

Comment 7

[Mike Hommey [:glandium]]

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.

Comment 8

[Mike Hommey [:glandium]]

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.

Comment 9

[Mike Hommey [:glandium]]

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.

Comment 10

[Mike Hommey [:glandium]]

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.

Comment 11

[Mike Hommey [:glandium]]

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)

Comment 12

[Mike Hommey [:glandium]]

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.

Comment 13

[Ziga Seilnacht]

Attachment: (part 1v2) cl.py should exit with an error when called without a target file

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

Comment 14

[Ziga Seilnacht]

Attachment: (part 2a) don't depend on mozinfo, it is slow to import, making mozprocess unsuitable for short, often run scripts

(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>)

Comment 15

[Ziga Seilnacht]

Attachment: (part 2b) make sure that all relevant output from cl.exe is flushed and kept together

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.

Comment 16

[Ziga Seilnacht]

Attachment: (part 3a) speed up makeutil._SimpleOrderedSet.update by adding the elements directly, without using a closure

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

Comment 17

[Ziga Seilnacht]

Attachment: (part 4v2) 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)
>> +        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.

Comment 18

[Ziga Seilnacht]

Attachment: (part 5v2) speed up os.environ cleaning, putenv is expensive on Windows

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

Comment 19

[Gregory Szorc [:gps]]

What tool did you use to capture all this data?

Comment 20

[Ziga Seilnacht]

Attachment: mwtrace.zip

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

Comment 21

[Mike Hommey [:glandium]]

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.

Comment 22

[Mike Hommey [:glandium]]

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)

Comment 23

[Ziga Seilnacht]

Attachment: (part 1v3) remove misleading check, missing -Fo argument must be tolerated

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

Comment 24

[Ziga Seilnacht]

Attachment: [mozbase] (part 2a) don't depend on mozinfo, it is slow to import, making mozprocess unsuitable for short, often run scripts

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.

Comment 25

[Ziga Seilnacht]

Attachment: (part 2b v2) make sure that all relevant output from cl.exe is kept together

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

Comment 26

[Andrew Halberstadt [:ahal]]

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

Comment 27

[Andrew Halberstadt [:ahal]]

Actually scratch that part about removing the dependency. It looks like pid.py still imports it.

Comment 28

[Ziga Seilnacht]

Attachment: [mozbase] (part 2a) don't depend on mozinfo, it is slow to import (for checkin)

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

Comment 29

[Ziga Seilnacht]

Attachment: Combined profile data for all mozbuild.action.cl calls during clobber build

Comment 30

[Mike Hommey [:glandium]]

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.

Comment 31

[Andrew Halberstadt [:ahal]]

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.

Comment 32

[BugBot [:suhaib / :marco/ :calixte]]

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.

Comment 33

[Mitchell Hentges [:mhentges] 🦀]

cl.py no longer exists