Closed Bug 1191575 Opened 4 years ago Closed Last year

config.status execution time has nearly doubled since Firefox 35

Categories

(Firefox Build System :: General, defect)

defect
Not set

Tracking

(Not tracked)

RESOLVED FIXED

People

(Reporter: gps, Assigned: glandium)

References

Details

Attachments

(1 file)

The wall time of mach build-backend (config.status) has doubled recently. Here are some timings from various tags. I took numbers from a non-initial run to rule out I/O wait.

FIREFOX_30_0_RELEASSE
Reticulating splines...
Finished reading 2512 moz.build files in 1.77s
Processed into 6903 build config descriptors in 2.72s
Backend executed in 2.10s
2073 total backend files; 0 created; 0 updated; 2073 unchanged; 0 deleted; 235 -> 998 Makefile
Total wall time: 6.74s; CPU time: 6.24s; Efficiency: 93%; Untracked: 0.14s

FIREFOX_35_0_RELEASE
Reticulating splines...
Finished reading 2704 moz.build files in 2.04s
Processed into 6994 build config descriptors in 1.33s
Backend executed in 2.08s
1786 total backend files; 0 created; 0 updated; 1786 unchanged; 0 deleted; 148 -> 857 Makefile
Total wall time: 5.68s; CPU time: 5.13s; Efficiency: 90%; Untracked: 0.23s

FIREFOX_40_0_RELEASE
Reticulating splines...
Finished reading 2562 moz.build files in 2.28s
Processed into 7912 build config descriptors in 1.70s
Backend executed in 4.26s
2307 total backend files; 0 created; 0 updated; 2307 unchanged; 0 deleted; 127 -> 847 Makefile
Total wall time: 8.45s; CPU time: 7.91s; Efficiency: 94%; Untracked: 0.20s

central (b12a261ee32e)
Reticulating splines...
Finished reading 2449 moz.build files in 2.23s
Processed into 8938 build config descriptors in 2.14s
Backend executed in 4.73s
2395 total backend files; 0 created; 0 updated; 2395 unchanged; 0 deleted; 127 -> 876 Makefile
Total wall time: 9.27s; CPU time: 8.77s; Efficiency: 95%; Untracked: 0.17s

Here is everything taking longer than 0.5s in cumulative time:

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        2    0.099    0.049   12.453    6.227 config.status:4(<module>)
        1    0.000    0.000   12.274   12.274 config_status.py:57(config_status)
        1    0.030    0.030   12.245   12.245 base.py:166(consume)
     8939    0.019    0.000    6.604    0.001 emitter.py:129(emit)
        1    0.021    0.021    3.755    3.755 recursivemake.py:742(consume_finished)
4681/1169    0.004    0.000    3.299    0.003 reader.py:1013(read_mozbuild)
4681/1169    0.027    0.000    3.298    0.003 reader.py:1063(_read_mozbuild)
     9169    0.037    0.000    3.209    0.000 emitter.py:513(emit_from_context)
     1450    0.013    0.000    2.375    0.002 emitter.py:954(_process_test_manifests)
       54    0.008    0.000    2.293    0.042 gyp_reader.py:76(read_from_gyp)
        8    0.000    0.000    2.196    0.275 __init__.py:48(Load)
        8    0.001    0.000    2.196    0.274 input.py:2512(Load)
      869    0.027    0.000    2.174    0.003 recursivemake.py:726(_check_blacklisted_variables)
    58437    0.027    0.000    2.151    0.000 re.py:143(search)
   103309    2.112    0.000    2.112    0.000 {method 'search' of '_sre.SRE_Pattern' objects}
     8938    0.044    0.000    1.836    0.000 recursivemake.py:416(consume_object)
   248404    1.126    0.000    1.659    0.000 posixpath.py:329(normpath)
    128/8    0.002    0.000    1.627    0.203 input.py:338(LoadTargetBuildFile)
 7542/135    0.095    0.000    1.445    0.011 input.py:1114(ProcessVariablesAndConditionsInDict)
     1154    0.052    0.000    1.216    0.001 emitter.py:1001(_process_test_manifest)
     8937    0.046    0.000    1.206    0.000 common.py:194(consume_object)
    40982    0.166    0.000    1.012    0.000 common.py:165(add)
   130380    0.088    0.000    0.989    0.000 path.py:41(normpath)
    33886    0.042    0.000    0.920    0.000 path.py:28(relpath)
    33886    0.153    0.000    0.870    0.000 posixpath.py:424(relpath)
61139/51268    0.089    0.000    0.826    0.000 input.py:692(ExpandVariables)
7542/4071    0.025    0.000    0.822    0.000 input.py:990(ProcessConditionsInDict)
 1015/823    0.002    0.000    0.782    0.001 reader.py:223(exec_file)
 1015/823    0.004    0.000    0.762    0.001 sandbox.py:142(exec_file)
 1015/823    0.001    0.000    0.730    0.001 sandbox.py:157(exec_source)
 1359/823    0.007    0.000    0.729    0.001 sandbox.py:187(exec_function)
 1015/823    0.004    0.000    0.719    0.001 sandbox.py:167(execute)
        1    0.000    0.000    0.693    0.693 common.py:258(consume_finished)
        4    0.031    0.008    0.682    0.170 emitter.py:1148(_process_reftest_manifest)
    73040    0.052    0.000    0.586    0.000 posixpath.py:358(abspath)
    394/2    0.131    0.000    0.539    0.270 __init__.py:50(load)

Here is sorted by total time, >100ms:
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
   103309    2.445    0.000    2.445    0.000 {method 'search' of '_sre.SRE_Pattern' objects}
   248404    1.135    0.000    1.671    0.000 posixpath.py:329(normpath)
       52    0.476    0.009    0.476    0.009 {select.select}
        2    0.314    0.157    0.314    0.157 encoder.py:212(iterencode)
1938742/1938739    0.289    0.000    0.292    0.000 {isinstance}
  2192517    0.219    0.000    0.219    0.000 {method 'append' of 'list' objects}
     6744    0.194    0.000    0.194    0.000 {compile}
     4414    0.185    0.000    0.185    0.000 {method 'read' of 'file' objects}
   712688    0.166    0.000    0.166    0.000 {method 'startswith' of 'unicode' objects}
   161086    0.166    0.000    0.243    0.000 posixpath.py:61(join)
    40982    0.166    0.000    1.005    0.000 common.py:165(add)
    73794    0.158    0.000    0.189    0.000 {sorted}
    33886    0.155    0.000    0.887    0.000 posixpath.py:424(relpath)
   129483    0.147    0.000    0.222    0.000 posixpath.py:120(dirname)
   259756    0.145    0.000    0.145    0.000 {method 'split' of 'unicode' objects}
    37904    0.142    0.000    0.142    0.000 {method 'copy' of 'dict' objects}
    394/2    0.124    0.000    0.524    0.262 __init__.py:50(load)
23637/3986    0.124    0.000    0.333    0.000 input.py:1851(MergeLists)
    32972    0.122    0.000    0.122    0.000 {posix.stat}
212459/208577    0.114    0.000    0.278    0.000 {method 'join' of 'unicode' objects}


emitter.py:954(_process_test_manifests) and recursivemake.py:726(_check_blacklisted_variables) stand out to me as culprits in need of optimizing. Testing variable blacklisting, which was introduced in bug 852814:

84d9ae40699e0d604fe49066e0799e74ae466aea (before blacklist refactor)
Reticulating splines...
Finished reading 2545 moz.build files in 2.08s
Processed into 7779 build config descriptors in 1.63s
Backend executed in 2.33s
2302 total backend files; 0 created; 0 updated; 2302 unchanged; 0 deleted; 132 -> 842 Makefile
Total wall time: 6.23s; CPU time: 5.70s; Efficiency: 92%; Untracked: 0.20s

7f73bbf6df768b8bef39ac406fe883b9d4ca5c87 (refactored blacklist)
Reticulating splines...
Finished reading 2545 moz.build files in 2.01s
Processed into 7779 build config descriptors in 1.62s
Backend executed in 2.78s
2302 total backend files; 0 created; 0 updated; 2302 unchanged; 0 deleted; 132 -> 842 Makefile
Total wall time: 6.60s; CPU time: 6.09s; Efficiency: 92%; Untracked: 0.19s

Small regression, but not much. 93ecf9651b20576618e2fbdc82708f357e7b68f7 (bug 1153566) changed the regular expression in this function. Let's see if it had an impact:

p1(93ecf9651b20576618e2fbdc82708f357e7b68f7)
Reticulating splines...
Finished reading 2570 moz.build files in 2.11s
Processed into 7932 build config descriptors in 1.72s
Backend executed in 2.79s
2315 total backend files; 0 created; 0 updated; 2315 unchanged; 0 deleted; 131 -> 851 Makefile
Total wall time: 6.82s; CPU time: 6.30s; Efficiency: 92%; Untracked: 0.20s

93ecf9651b20576618e2fbdc82708f357e7b68f7
Reticulating splines...
Finished reading 2570 moz.build files in 2.19s
Processed into 7932 build config descriptors in 1.69s
Backend executed in 4.33s
2315 total backend files; 0 created; 0 updated; 2315 unchanged; 0 deleted; 131 -> 851 Makefile
Total wall time: 8.42s; CPU time: 7.89s; Efficiency: 94%; Untracked: 0.20s

So, a ~1.5s regression from using a different regexp. Ugh.

There's still ~0.75s unaccounted for though. My best guess would be introducing reftest manifest parsing.
Seems like a good candidate for using a pre-compiled regexp.
CPython has an LRU cache of regexps. I think this is a result of the newer regexp being greedy where the former one wasn't. This translates to more character scanning and longer execution time. We could probably outsmart regexps by first checking for simple string presence of the variable before involving an individual line scanning regexp. (Python's regexp library isn't too smart, apparently. Apparently re2 is very nice.)
except each iteration actually uses a different regexp. I'm actually wondering why we need such a complex per-variable regexp. I'm pretty sure splitlines + strip + checking the line isn't a comment + checking literal variable names would be faster.
Bug 1153566 changed the regexp used in that method in such a way that there
has been a big hit in the time spent executing the make backend. On my machine,
with the current code, mach build-backend indicates:
  Backend executed in 5.01s
With the change from bug 1153566 reverted:
  Backend executed in 2.97s
That's a significant regression for a 4-character change.
But we can actually avoid using regexp in most cases, which can make things faster
than they were. With this change, we get down to:
  Backend executed in 2.28s
For reference, making the _check_blacklisted_variables method do nothing at all
ends with:
  Backend executed in 2.20s
Assignee: nobody → mh+mozilla
Attachment #8644103 - Flags: review?(gps)
As for emitter.py:954(_process_test_manifests), most of the time spent in there is in posixpath.py:336(normpath)
with 101294 calls to this function (I did limit profiling to the _process_test_manifests function itself), which may well be the number of tests we have...
For reference, we have 125K files in the tree now, and had 92K in FIREFOX_30_0_RELEASE. I bet most of the new ones are tests (.cpp files, for instance, went up from ~5.6K to ~6.5K).
Probably ran this on a different tree but here are additional numbers about normpath calls from during the execution of _process_test_manifests:
- 101301 calls
- 50191 unique argument values it's called with
- 50191 unique results it returns
- 99931 calls return the exact value given as argument

So not only are we roughly calling normpath twice for the same path, but most of the time, it's useless.
Wrapping normpath with a function that does a stupid "if '..' in path" first (wrapping only during _process_test_manifests) removes 0.4s on my machine.
Comment on attachment 8644103 [details] [diff] [review]
Optimize the RecursiveMakeBackend._check_blacklisted_variables test

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

>50% reduction in backend execution time. Nice.

::: python/mozbuild/mozbuild/backend/recursivemake.py
@@ +748,5 @@
>  
> +                # Finding the variable name in the Makefile is not enough: it
> +                # may just appear as part of something else, like DIRS appears
> +                # in GENERATED_DIRS.
> +                if re.search(r'\b%s\s*[:?+]?=' % x, l, re.M):

You can ditch re.M since we're no longer operating on multiple lines.
Attachment #8644103 - Flags: review?(gps) → review+
Attachment #8644103 - Flags: checkin+
glandium,
Have you try to run the "mach build-backend -b CppEclipse"? Looks like your patch might cause CppEclipse malfunction.
Flags: needinfo?(mh+mozilla)
(In reply to Chia-hung Tai [:ctai :ctai_mozilla :cht] from comment #12)
> glandium,
> Have you try to run the "mach build-backend -b CppEclipse"? Looks like your
> patch might cause CppEclipse malfunction.

Please define "malfunction". Running "mach build-backend -b CppEclipse" doesn't fail for me.
Flags: needinfo?(mh+mozilla)
Hi, Mike,
I try it on another PC and it works. Sorry for bother you.
Product: Core → Firefox Build System
The leave-open keyword is there and there is no activity for 6 months.
:glandium, maybe it's time to close this bug?
Flags: needinfo?(mh+mozilla)
config.status got even worse over time, but it doesn't seem keeping this bug around is doing any good. It did some good 3 years ago, though.
Status: NEW → RESOLVED
Closed: Last year
Flags: needinfo?(mh+mozilla)
Keywords: leave-open
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.