922517 - Parsing test manifests significantly slowed down moz.build reading

Status: RESOLVED FIXED

(Firefox Build System :: General, defect)

Description

[Gregory Szorc [:gps]]

When we moved mochitests to manifests in bug 920223, moz.build traversal slowed down by a few seconds on my machine. We went from ~4s for everything, including backend generation, to ~8s.

In this bug, we should profile why manifest loading is slow and we should see if we can make it faster. This bug may get reassigned to mozbase/manifestdestiny. But first, let's collect data to be sure it isn't the build system doing something silly.

Comment 1

[Mike Hommey [:glandium]]

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
   284865    1.382    0.000    2.106    0.000 posixpath.py:321(normpath)
   571983    0.642    0.000    0.897    0.000 posixpath.py:68(join)
      742    0.513    0.001    5.230    0.007 emitter.py:235(_process_test_manifest)


Removing _process_test_manifest makes normpath and join disappear from the profile, too.

Comment 2

[Mike Hommey [:glandium]]

The number of calls is absurdly high. There might be some O(n*m) badness.

Comment 3

[Ziga Seilnacht]

Attachment: debug patch with split _process_test_manifest() for easier profiling

It looks like most of the time is spent normalizing |support-files| paths, here is a profile with _process_test_manifest() split into multiple smaller functions (see the attached patch):

   ncalls  cumtime filename:lineno(function)
        1   10.640 build\ConfigStatus.py:28(config_status)
        1   10.632 mozbuild\backend\base.py:174(consume)
     4469    8.277 mozbuild\frontend\emitter.py:66(emit)
     5665    7.516 mozbuild\frontend\emitter.py:89(emit_from_sandbox)
      750    6.881 mozbuild\frontend\emitter.py:244(_process_test_manifest)
     7903    5.786 mozbuild\frontend\emitter.py:341(_install_extra_support_files)
   498993    2.198 mozpack\path.py:31(join)
        1    1.967 mozbuild\backend\recursivemake.py:600(consume_finished)
   234540    1.965 mozpack\path.py:36(normpath)
   235749    1.608 _virtualenv\lib\posixpath.py:321(normpath)

The issue occurs when a test manifest has many |support-files| specified in the [DEFAULT] section and lists many tests. manifestparser.read_ini() copies this value to each test's individual config section, and _process_test_manifest() then splits these paths and normalizes them once for each individual test. E.g., for /content/base/test/mochitest.ini, _process_test_manifest() adds 77381 duplicate paths to the |obj.installs| dict. Below is a list of test manifests which cause the most duplicates to be added:

77381 /content/base/test/mochitest.ini
33915 /content/html/content/test/mochitest.ini
15656 /browser/base/content/test/general/browser.ini
12690 /browser/devtools/webconsole/test/browser.ini
11900 /toolkit/mozapps/extensions/test/xpcshell/xpcshell.ini
07504 /browser/devtools/debugger/test/browser.ini
04280 /toolkit/content/tests/chrome/chrome.ini
03264 /dom/tests/mochitest/bugs/mochitest.ini
02912 /netwerk/test/unit/xpcshell.ini
02756 /dom/workers/test/mochitest.ini

Comment 4

[Gregory Szorc [:gps]]

Nice investigation!

We should avoid the redundant computation for each [test] section, if possible. Since support-files is only supposed to come from the [DEFAULT] section, we should just process it once. We probably also want to verify that support-files isn't defined outside of [DEFAULT].

Comment 5

[:Ms2ger (he/him; ⌚ UTC+1/+2)]

Actually, I think it might be useful to support support-files under specific files, so we can avoid copying them when those tests are disabled?

Comment 6

[Ziga Seilnacht]

Attachment: fix O(tests * support-files) behaviour in _process_test_manifest

Having |support-files| under specific tests should already be working, changing that is not needed to fix this issue. The attached patch seems to fix the O(tests * support-files) issue for me, most of the time is now spent in ManifestParser._read() path manipulations:

   ncalls  cumtime filename:lineno(function)
        1    5.108 ConfigStatus.py:28(config_status)
        1    5.100 mozbuild\backend\base.py:174(consume)
     4469    2.769 mozbuild\frontend\emitter.py:66(emit)
     5665    2.021 mozbuild\frontend\emitter.py:89(emit_from_sandbox)
        1    1.919 mozbuild\backend\recursivemake.py:600(consume_finished)
      750    1.149 mozbuild\frontend\emitter.py:244(_process_test_manifest)
     1204    1.079 mozbuild\backend\configenvironment.py:214(create_makefile)
    13715    0.847 _virtualenv\lib\ntpath.py:494(relpath)
5934/1199    0.740 mozbuild\frontend\reader.py:568(read_mozbuild)
5934/1199    0.740 mozbuild\frontend\reader.py:625(_read_mozbuild)
      375    0.720 manifestparser\manifestparser.py:359(__init__)
      375    0.720 manifestparser\manifestparser.py:420(read)
    79175    0.717 _virtualenv\lib\ntpath.py:398(normpath)
  378/375    0.704 manifestdestiny\manifestparser\manifestparser.py:371(_read)
    27430    0.675 _virtualenv\lib\ntpath.py:486(_abspath_split)
    39118    0.447 _virtualenv\lib\ntpath.py:466(abspath) 

There is still a problem with individual test sections overriding the settings in the [DEFAULT] section; if every test has its own |support-files| specified, then the files listed in [DEFAULT]'s |support-files| wouldn't get installed. To change that, manifestparser.TestManifest would need to expose its |_defaults| dict and its consumers would need to be modified to take the default section into consideration.

Comment 7

[Ziga Seilnacht]

Attachment: optimize ManifestParser's path manipulations

Removing a redundant os.path.abspath() call in ManifestParser._read() and bypassing os.path.relpath() call when relative path calculation is trivial shaves another half a second from _process_test_manifest():

   ncalls  cumtime filename:lineno(function)
        1    4.397 ConfigStatus.py:28(config_status)
        1    4.389 mozbuild\backend\base.py:174(consume)
     4469    2.020 mozbuild\frontend\emitter.py:66(emit)
        1    1.970 mozbuild\backend\recursivemake.py:600(consume_finished)
     5665    1.274 mozbuild\frontend\emitter.py:89(emit_from_sandbox)
     1204    1.109 mozbuild\backend\configenvironment.py:214(create_makefile)
5934/1199    0.738 mozbuild\frontend\reader.py:568(read_mozbuild)
5934/1199    0.738 mozbuild\frontend\reader.py:625(_read_mozbuild)
      750    0.603 mozbuild\frontend\emitter.py:244(_process_test_manifest)
     1209    0.460 mozbuild\backend\configenvironment.py:238(_get_preprocessor)
     5810    0.407 _virtualenv\lib\ntpath.py:494(relpath)
    83768    0.405 mozbuild\frontend\sandbox.py:353(__getitem__)
        1    0.405 mozbuild\backend\recursivemake.py:414(_fill_root_mk)
    31837    0.394 config\Preprocessor.py:219(handleLine)
    86829    0.389 mozbuild\frontend\sandbox.py:105(__getitem__)
     4468    0.375 mozbuild\backend\recursivemake.py:329(consume_object)
    39650    0.363 _virtualenv\lib\ntpath.py:398(normpath)

Where should I submit a patch for mozbase, is here OK or do I need to post it to Github?

Comment 8

[Jeff Hammel]

A patch can be submitted to this bug against the github repo as according to https://wiki.mozilla.org/Auto-tools/Projects/Mozbase

Comment 9

[Gregory Szorc [:gps]]

(In reply to :Ms2ger from comment #5)
> Actually, I think it might be useful to support support-files under specific
> files, so we can avoid copying them when those tests are disabled?

I /think/ ATeam wants *every* file in the test archives. I could be wrong.

Comment 10

[Ziga Seilnacht]

Attachment: optimize ManifestParser._read() path manipulations

Here is the manifestparser patch against the github repo's master.

Comment 11

[Ziga Seilnacht]

Attachment: fix preexisting manifestdestiny test failures on Windows.

Two of the manifestdestiny's tests are currently failing on Windows due to path separator differences, predating my changes. This fixes them.

Comment 12

[Gregory Szorc [:gps]]

Comment on attachment 816225 [details] [diff] [review]
fix O(tests * support-files) behaviour in _process_test_manifest

Review of attachment 816225 [details] [diff] [review]:
-----------------------------------------------------------------

Please add an inline comment that the skipping is perf related. Things like this have a tendency to get dropped during refactors unless posterity knows about them.

Comment 13

[Jeff Hammel]

(In reply to Gregory Szorc [:gps] from comment #12)
> Comment on attachment 816225 [details] [diff] [review]
> fix O(tests * support-files) behaviour in _process_test_manifest
> 
> Review of attachment 816225 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Please add an inline comment that the skipping is perf related. Things like
> this have a tendency to get dropped during refactors unless posterity knows
> about them.

+1

Comment 14

[Jeff Hammel]

Comment on attachment 816723 [details] [diff] [review]
optimize ManifestParser._read() path manipulations

Review of attachment 816723 [details] [diff] [review]:
-----------------------------------------------------------------

I'd like a bunch more comments, but if behaviour is kept and comments are added, this seems fine.

::: manifestdestiny/manifestparser/manifestparser.py
@@ +425,5 @@
>  
> +        if self.rootdir is None:
> +            rootdir = ""
> +        else:
> +            rootdir = self.rootdir + os.path.sep

why `+ os.path.sep`?

@@ +469,5 @@
> +                # microoptimization, because relpath is quite expensive
> +                if path.startswith(rootdir):
> +                    _relpath = path[len(rootdir):]
> +                else:
> +                    _relpath = relpath(path, rootdir)

Maybe worth busting out to a function?

Comment 15

[Jeff Hammel]

> @@ +469,5 @@
> > +                # microoptimization, because relpath is quite
> expensive
> > +                if path.startswith(rootdir):
> > +                    _relpath = path[len(rootdir):]
> > +                else:
> > +                    _relpath = relpath(path, rootdir)
> Maybe worth busting out to a function?

Scratch thate; probably better as is.

Comment 16

[Jeff Hammel]

Comment on attachment 816723 [details] [diff] [review]
optimize ManifestParser._read() path manipulations

Review of attachment 816723 [details] [diff] [review]:
-----------------------------------------------------------------

Sorry, I thought I r+ed this last week. Looks good! Thanks for the patch.

Comment 17

[Jeff Hammel]

Comment on attachment 816725 [details] [diff] [review]
fix preexisting manifestdestiny test failures on Windows.

Review of attachment 816725 [details] [diff] [review]:
-----------------------------------------------------------------

lgtm

Comment 18

[Ziga Seilnacht]

Attachment: [gecko] fix O(tests * support-files) behaviour in _process_test_manifest (for checkin)

Here is a patch with added comments, as requested in review. Can somebody please check this in for me, or set the checkin-needed keyword?

Comment 19

[Ziga Seilnacht]

Attachment: [mozbase] optimize ManifestParser._read() path manipulations (for checkin)

Updated patch with added comments, and some additional tests to verify that this patch doesn't change the old behavior.

> why `+ os.path.sep`?

This is needed so that paths to sibling directories whose name has the same prefix as the manifest's directory don't get corrupt (e.g. manifest in /test, and a test with path ../test2/test would otherwise result in relpath 2/test). See also the added test and comment.

Comment 20

[Ziga Seilnacht]

Attachment: [mozbase] fix preexisting manifestdestiny test failures on Windows (for checkin)

Updated patch with review info in the commit message. I don't know if this is actually needed, is the process for commiting patches to mozbuild from non-commiters the same as for mozilla central, I just wait for some good soul to check it in for me?

Comment 21

[(not currently active) Ted Mielczarek]

mozbase patches technically need to land in the github repository first.

Comment 22

[Gregory Szorc [:gps]]

Comment on attachment 820637 [details] [diff] [review]
[gecko] fix O(tests * support-files) behaviour in _process_test_manifest (for checkin)

Review of attachment 820637 [details] [diff] [review]:
-----------------------------------------------------------------

https://hg.mozilla.org/integration/mozilla-inbound/rev/9dd234437dd1

Comment 23

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/9dd234437dd1

Comment 24

[Ed Morley [:emorley]]

Reopening, the mozbase parts still need to land. (To prevent automatic closure by mcMerge, use [leave open] in the bug whiteboard)

Comment 25

[Ed Morley [:emorley]]

No idea why this doesn't work, I'm not that familiar with git.

manifestdestiny/tests/relative-path.ini doesn't exist in the mozbase repo already, so it's not like the patch just needs rebasing?!

[/c/src/mozbase]$ git am ~/Desktop/import/*
Applying: Bug 922517 - optimize ManifestParser._read() path manipulations, r=jhammel
error: manifestdestiny/tests/relative-path.ini: already exists in working directory
Patch failed at 0001 Bug 922517 - optimize ManifestParser._read() path manipulations, r=jhammel
The copy of the patch that failed is found in:
   c:/src/mozbase/.git/rebase-apply/patch
When you have resolved this problem, run "git am --resolved".
If you prefer to skip this patch, run "git am --skip" instead.
To restore the original branch and stop patching, run "git am --abort".

Comment 26

[(no longer active)]

(In reply to comment #25)
> No idea why this doesn't work, I'm not that familiar with git.
> 
> manifestdestiny/tests/relative-path.ini doesn't exist in the mozbase repo
> already, so it's not like the patch just needs rebasing?!
> 
> [/c/src/mozbase]$ git am ~/Desktop/import/*
> Applying: Bug 922517 - optimize ManifestParser._read() path manipulations,
> r=jhammel
> error: manifestdestiny/tests/relative-path.ini: already exists in working
> directory

This means the file that the patch adds already exists as a file not tracked by git in your working directory. rm it and try again!

Comment 27

[Ed Morley [:emorley]]

(In reply to :Ehsan Akhgari (needinfo? me!) [Away 10/29-11/6] from comment #26)
> This means the file that the patch adds already exists as a file not tracked
> by git in your working directory. rm it and try again!

I did a |git reset --hard| immediately prior though?

Comment 28

[Ed Morley [:emorley]]

Hmm I obviously misunderstood what git reset --hard does (I thought it was something similar to |hg revert -a && hg purge), since the file does indeed exist in the working directory. (My fault for not checking)

Comment 29

[Ed Morley [:emorley]]

Comment on attachment 820651 [details] [diff] [review]
[mozbase] optimize ManifestParser._read() path manipulations (for checkin)

https://github.com/mozilla/mozbase/commit/ba8bace6a5ace578e5967b3b7c8afd13ec614c9f

Comment 30

[Ed Morley [:emorley]]

Comment on attachment 820665 [details] [diff] [review]
[mozbase] fix preexisting manifestdestiny test failures on Windows (for checkin)

https://github.com/mozilla/mozbase/commit/526596737d77d72bea9a771a2292f2beecb9015e

Comment 31

[Ed Morley [:emorley]]

Bug 930590 will deal with syncing from the github repo to the in-tree copy, but for now we're all done here. Thank you for the patches :-)