In bug 1271035 gps identified disk I/O as a major cause for reftest slowness.
He was able to fix most of it, but the new highest source of I/O in reftest is
reftest.log.
To note, we were only saving reftest.log when running via mach, so this won't
impact automation in any way:
https://hg.mozilla.org/mozilla-central/file/043082cb7bd8/layout/tools/reftest/mach_commands.py#l204
I don't know why we are doing this given that the same output goes to stdout.
And as dholbert pointed out, since bug 1034290 landed, that log contains raw
structured logs, which are not at all useful for debugging. Given that it is
no longer useful and causes slowness, we should stop saving it.
If anyone wishes to keep saving to a log, they can use:
./mach reftest --log-tbpl reftest.log
If they wish this to be the default behaviour they can make a machrc (or
.machrc) in either topsrcdir, ~/.mozbuild or $MACHRC. Then add:
[alias]
reftest = reftest --log-tbpl reftest.log
MozReview-Commit-ID: A3e2X7qF90H
--HG--
extra : rebase_source : 9286e3061c068c6fef55b503017b3f4a9588be46
It was a cold Friday night in San Francisco. Earlier in the day, I
informed Chris AtLee that I was going to start focusing on improving
the efficiency of Firefox automation and asked him where the biggest
capacity issues were. He said "we're hurting most on Windows tests."
As I was casually drinking a barleywine (note to reader: barleywines
are serious beers - there's nothing casual about them), I found myself
tediously clicking through Treeherder looking at logs for Windows jobs,
looking for patterns and other oddities. As I was clicking through,
something stood out to me: the sheer number of reftest jobs. I
recalled a random project I started a few years ago. Its aim was to
analyze buildbot job metadata so we could better understand where time
was spent in automation. I had mostly written off the side project as
a failure and a near complete waste of my time. Not even a stray
random thought of this project had entered my mind in the past year.
But clicking through Treeherder after a few glasses of barleywine
somehow reminded me of one of the few useful findings of that project:
reftest jobs consumed a seemingly disproportiate amount of machine time,
something like 35 or 40% IIRC of the time spent on all jobs.
Now, this finding was several years ago and almost certainly no longer
relevant. But, again, I had a few glasses of barleywine in me and was
bothered by the amount of reftest jobs and their duration, so I thought
"hey, why don't I run reftests and see why they take so long." So I
built Firefox on Windows - the platform Chris AtLee said we're "hurting
most on."
I decided to start my very casual profiling session by recording a
`mach reftest` run using Sysinternals Process Monitor. To my surprise,
it yielded a very obvious and unexpected result: the Places SQLite
database was incurring a lot of I/O. On my i7-6700K Windows 10 desktop
with a high performance SSD, `mach reftest` yielded the following:
File Time #Events #Reads #Writes RBytes WBytes Path
198s 980,872 243,270 669,231 7,971,471,360 20,667,084,080 places.sqlite-wal
165s 645,853 222,407 367,775 7,287,701,820 14.071,529,472 places.sqlite
2s 377,121 1 0 32,768 0 places.sqlite-shm
The Places SQLite database accounts for 2,003,846 of the total of
3,547,527 system calls (56.49%) recorded by procmon during `mach
reftest` execution. This represents a staggering 49,997,786,732 of the
50,307,660,589 (99.38%) bytes of I/O recorded! Yes, that's 50 GB.
I reckon the reason the Places database accumulates so much I/O load
during reftests is because the reftest suite essentially loads thousands
of pages as quickly as possible. This effectively performs a stress
test against the Places history recording service.
As effective as reftests are at stress-testing Places, it adds no value
to reftests because reftests are testing the layout features, not the
performance of history recording. So these 2M system calls and 50 GB
of I/O are overhead.
This commit disables Places when executing reftests and prevents
the overhead.
After this commit, `mach reftest` has significantly reduced interaction
with the Places SQLite database:
File Time #Events #Reads #Writes RBytes WBytes Path
0.09s 502 138 302 4,521,984 8,961,528 places.sqlite-wal
0.07s 254 20 140 524,604 8,126,464 places.sqlite
0.01s 3,289 1 0 32,768 0 places.sqlite-shm
Of the 948,033 system calls recorded with this change (26.7% of
original), 691,322 were related to I/O. The Places SQLite database
only consumed ~22MB of I/O, <0.01% of original. It's worth noting that
~half of the remaining I/O system calls are related to reftest.log,
which now accounts for the largest percentage of write I/O (only
~53 MB, however). It's worth noting that reftest.log appears to be
using unbuffered writes and is requiring an excessive amount of
system calls for writing. But that's for another bug and commit.
In terms of wall time, the drastic I/O reduction during `mach reftest`
appears to have minimal impact on my machine: maybe 30s shaved from a
~900s execution, or ~3%. But my machine with its modern SSD doesn't
struggle with I/O.
In automation, it is a different story.
I pushed this change to Try along with the base revision and triggered
4 runs of most reftest jobs. The runtime improvements in automation
are impressive. Here are the fastest reported times for various jobs:
Job Before After Delta
Linux Opt R1 31m 34m +3m
Linux Opt R2 43m 35m -8m
Linux Opt Ru1 40m 34m -6m
Linux Opt Ru2 43m 37m -6m
Linux Opt R E10s 89m 72m -17m
Linux Debug R1 52m 40m -12m
Linux Debug R2 49m 42m -7m
Linux Debug R3 60m 51m -9m
Linux Debug R4 42m 37m -5m
Linux Debug R1 E10s 84m 72m -12m
Linux Debug R2 E10s 97m 85m -12m
Linux64 Opt R1 35m 24m -11m
Linux64 Opt R2 37m 26m -11m
Linux64 Opt Ru1 32m 29m -3m
Linux64 Opt Ru2 37m 26m -12m
Linux64 Opt TC R1 12m 10m -2m
Linux64 Opt TC R2 10m 7m -3m
Linux64 Opt TC R3 11m 9m -2m
Linux64 Opt TC R4 11m 9m -2m
Linux64 Opt TC R5 13m 11m -2m
Linux64 Opt TC R6 11m 9m -2m
Linux64 Opt TC R7 9m 8m -1m
Linux64 Opt TC R8 11m 10m -1m
Linux64 Opt TC Ru1 30m 25m -5m
Linux64 Opt TC Ru2 36m 27m -11m
OS X 10.10 Opt 31m 27m -4m
OS X 10.10 Opt E10s 26m 25m -1m
OS X 10.10 Debug 68m 55m -13m
Win7 Opt R 30m 28m -2m
Win7 Opt Ru 28m 26m -2m
Win7 Opt R E10S 29m 27m -2m
Win7 Debug R 85m 76m -9m
Win7 Debug R E10S 75m 65m -10m
Win8 x64 Opt R 29m 26m -3m
Win8 x64 Opt Ru 27m 25m -2m
Win8 x64 Debug R 90m 71m -19m
Android 4.3 API15 Opt R1 89m 71m -18m
Android 4.3 API15 Opt R2 78m 64m -14m
Android 4.3 API15 Opt R3 75m 64m -11m
Android 4.3 API15 Opt R4 74m 68m -6m
Android 4.3 API15 Opt R5 75m 69m -6m
Android 4.3 API15 Opt R6 91m 86m -5m
Android 4.3 API15 Opt R7 87m 66m -21m
Android 4.3 API15 Opt R8 87m 82m -5m
Android 4.3 API15 Opt R9 80m 66m -14m
Android 4.3 API15 Opt R10 80m 67m -13m
Android 4.3 API15 Opt R11 73m 66m -7m
Android 4.3 API15 Opt R12 105m 91m -14m
Android 4.3 API15 Opt R13 72m 59m -13m
Android 4.3 API15 Opt R14 82m 61m -21m
Android 4.3 API15 Opt R15 73m 62m -11m
Android 4.3 API15 Opt R16 79m 78m -1m
The savings total 6+ *hours* or ~15% when running all reftests. I'd
say this isn't bad for a one-line code change!
MozReview-Commit-ID: H1LkACgSpVn
--HG--
extra : rebase_source : 891a5ce8e1f6c3d70fc646f116c2f49f897ad735
As of bug 1245092, reftest depends on marionette. Normally marionette client has an internal timeout of around
60 seconds where it waits for the server to become available. But when using debuggers (and especially valgrind),
it can take much much longer than a minute for Firefox to start. This patch adds a couple hidden command line
args to reftest to tweak the marionette timeouts.
MozReview-Commit-ID: 3xF0InBJNEf
--HG--
extra : rebase_source : f18092bc90a7d8aab34b527a15bd3b1dc6afc997
This extra window was initially left open because closing it was causing memory leaks
on debug e10s crashtests. There was pressure to get the regressing patch landed due
to addon signing, so it got landed with this extra window hanging around (as it didn't
impact test results).
But it is a UX wart for several reasons. Upon testing it again recently, the leaks all
seem to have vanished. I'm not sure why, possibly it was a bug fixed in e10s.
MozReview-Commit-ID: CEI2enKAOyv
--HG--
extra : rebase_source : da0e8889f67d57aa61670105c14c2235607d79a7
This is a internal-only syntax for guarding rules from a boolean
preference. Nothing causes @supports rules to be re-evaluated except
html.css registered in Part 2.
This is needed for rendering the disclosure triangle of the
summary element by using "display: list-item".
Usage example:
@supports -moz-bool-pref("dom.details_element.enabled") {
/* css rules */
}
MozReview-Commit-ID: HDCa8zHxYTA
--HG--
extra : rebase_source : b7a72a48166edf1d486014ff37363ed8be9127d9
Be warned. Do not attemp to change the .js "test" source code in ./js
They are meant to check
- the outdated 0666 octal constant is still parsed correctly,
- the outdated 0666 octal constant raises syntax error flag
in strict mode, etc.
So leave them alone.
There is an ImportError on Android, as well as a log related
regression from the structured log patch once that is fixed.
MozReview-Commit-ID: KxSEotr38qO
--HG--
extra : rebase_source : 15d8421aab813d9e0dbf6d00611f921aaa779a49
Structured logs bring many benefits. We can stop parsing the logs for magic strings, we
can modify the format without breaking things, and we can stream results into systems like
ActiveData. The structured logs originate primarily in reftest.js. StructuredLog.jsm is
used to generate the JSON-based log stream. Finally OutputHandler in the python harness
reads structured output from stdout, and formats it into human readable form.
MozReview-Commit-ID: G3ZLkMRl6p7
--HG--
extra : commitid : J3ui9XYWR3Q
extra : rebase_source : 77ed0ba842cc8e557141fb3494212b06868c728a
extra : amend_source : 735d48225a2e627e0fe45fc11b50b6c49a885a4b
extra : source : d1779fe421c3c7cd8e3d191816776390dc104f37
Structured logs bring many benefits. We can stop parsing the logs for magic strings, we
can modify the format without breaking things, and we can stream results into systems like
ActiveData. The structured logs originate primarily in reftest.js. StructuredLog.jsm is
used to generate the JSON-based log stream. Finally OutputHandler in the python harness
reads structured output from stdout, and formats it into human readable form.
--HG--
extra : commitid : J3ui9XYWR3Q
extra : rebase_source : 6bae978126dbd5beddc39332c7cbce0c1354cd87
extra : amend_source : 735d48225a2e627e0fe45fc11b50b6c49a885a4b
Also, add an opt-out for crashtest/reftest for the view-source thing so they don't all break, r=bz
--HG--
extra : commitid : 8NqvmbphSgh
extra : rebase_source : bbe0b6f11a77d7e6241a5733931d9baa95bb3fed
