Mercurial > hg
view tests/test-run-tests.t @ 23031:3c0983cc279e
i18n: cache the result of every gettext call
In looking at profiler output for 'hg log' on mozilla-central, I
noticed we spent a _huge_ amount of time in gettext relative to what
it's doing. Caching provides a roughly 15% performance improvement
even on repositories as small as hg.
== hg repo on linux ==
Before:
% cumulative self
time seconds seconds name
5.05 0.19 0.19 i18n.py:62:gettext
4.84 0.18 0.18 revlog.py:88:decompress
2.95 0.17 0.11 changelog.py:201:node
2.32 0.09 0.09 ui.py:577:write
2.11 0.08 0.08 i18n.py:72:gettext
2.11 0.08 0.08 obsolete.py:196:_fm0readmarkers
1.89 0.07 0.07 obsolete.py:569:_load
1.68 0.63 0.06 localrepo.py:29:__get__
real 0m4.026s
user 0m3.993s
sys 0m0.034s
After:
% cumulative self
time seconds seconds name
8.05 0.26 0.26 revlog.py:88:decompress
2.68 0.22 0.09 color.py:395:write
2.20 0.07 0.07 obsolete.py:196:_fm0readmarkers
1.95 0.06 0.06 obsolete.py:174:_fm0readmarkers
1.95 0.06 0.06 ui.py:577:write
1.95 0.06 0.06 util.py:1228:datestr
1.71 0.06 0.06 utf_8.py:16:decode
1.71 0.06 0.06 revlog.py:273:__len__
real 0m3.519s
user 0m3.447s
sys 0m0.073s
== mozilla-central repo on linux ==
Before:
% cumulative self
time seconds seconds name
7.72 2.35 2.35 revlog.py:88:decompress
4.46 1.36 1.36 i18n.py:62:gettext
2.22 0.67 0.67 i18n.py:72:gettext
2.19 1.14 0.67 changelog.py:201:node
2.16 0.66 0.66 ui.py:577:write
1.96 0.60 0.60 utf_8.py:16:decode
1.93 1.97 0.59 color.py:395:write
1.85 0.81 0.56 changelog.py:136:tip
real 0m30.822s
user 0m30.660s
sys 0m0.149s
After:
% cumulative self
time seconds seconds name
9.82 2.49 2.49 revlog.py:88:decompress
2.67 1.31 0.68 localrepo.py:29:__get__
2.57 0.65 0.65 utf_8.py:16:decode
2.48 1.01 0.63 changelog.py:201:node
2.10 0.82 0.53 changelog.py:136:tip
2.01 0.51 0.51 ui.py:577:write
1.91 0.49 0.49 util.py:1232:datestr
1.85 1.65 0.47 color.py:395:write
real 0m25.619s
user 0m25.446s
sys 0m0.166s
== cpython repo on os x =
Before:
% cumulative self
time seconds seconds name
5.05 1.35 1.35 cmdutil.py:982:_show
4.59 1.22 1.22 revlog.py:274:__len__
3.98 1.06 1.06 i18n.py:62:gettext
3.91 1.04 1.04 revlog.py:1016:revision
3.68 0.98 0.98 revlog.py:337:parents
3.45 0.92 0.92 revlog.py:88:decompress
2.91 0.78 0.78 revlog.py:309:rev
2.62 0.70 0.70 revlog.py:1033:revision
real 0m30.414s
user 0m28.145s
sys 0m0.541s
After:
% cumulative self
time seconds seconds name
7.98 1.66 1.66 cmdutil.py:982:_show
6.83 1.42 1.42 changelog.py:46:decodeextra
5.18 1.08 1.08 revlog.py:274:__len__
3.94 0.82 0.82 revlog.py:1016:revision
3.41 0.71 0.71 revlog.py:309:rev
3.32 0.69 0.69 revlog.py:88:decompress
2.99 0.63 0.62 revlog.py:1033:revision
2.69 0.56 0.56 revlog.py:341:start
real 0m22.811s
user 0m21.883s
sys 0m0.397s
author | Augie Fackler <raf@durin42.com> |
---|---|
date | Fri, 17 Oct 2014 13:52:10 -0400 |
parents | ba5c635921e1 |
children | 5459b30aa498 |
line wrap: on
line source
This file tests the behavior of run-tests.py itself. Smoke test ============ $ $TESTDIR/run-tests.py # Ran 0 tests, 0 skipped, 0 warned, 0 failed. a succesful test ======================= $ cat > test-success.t << EOF > $ echo babar > babar > $ echo xyzzy > xyzzy > EOF $ $TESTDIR/run-tests.py --with-hg=`which hg` . # Ran 1 tests, 0 skipped, 0 warned, 0 failed. failing test ================== $ cat > test-failure.t << EOF > $ echo babar > rataxes > This is a noop statement so that > this test is still more bytes than success. > EOF $ $TESTDIR/run-tests.py --with-hg=`which hg` --- $TESTTMP/test-failure.t (glob) +++ $TESTTMP/test-failure.t.err (glob) @@ -1,4 +1,4 @@ $ echo babar - rataxes + babar This is a noop statement so that this test is still more bytes than success. ERROR: test-failure.t output changed !. Failed test-failure.t: output changed # Ran 2 tests, 0 skipped, 0 warned, 1 failed. python hash seed: * (glob) [1] test --xunit support $ $TESTDIR/run-tests.py --with-hg=`which hg` --xunit=xunit.xml --- $TESTTMP/test-failure.t +++ $TESTTMP/test-failure.t.err @@ -1,4 +1,4 @@ $ echo babar - rataxes + babar This is a noop statement so that this test is still more bytes than success. ERROR: test-failure.t output changed !. Failed test-failure.t: output changed # Ran 2 tests, 0 skipped, 0 warned, 1 failed. python hash seed: * (glob) [1] $ cat xunit.xml <?xml version="1.0" encoding="utf-8"?> <testsuite errors="0" failures="1" name="run-tests" skipped="0" tests="2"> <testcase name="test-success.t" time="*"/> (glob) <testcase name="test-failure.t" time="*"> (glob) <![CDATA[--- $TESTTMP/test-failure.t +++ $TESTTMP/test-failure.t.err @@ -1,4 +1,4 @@ $ echo babar - rataxes + babar This is a noop statement so that this test is still more bytes than success. ]]> </testcase> </testsuite> test for --retest ==================== $ $TESTDIR/run-tests.py --with-hg=`which hg` --retest --- $TESTTMP/test-failure.t (glob) +++ $TESTTMP/test-failure.t.err (glob) @@ -1,4 +1,4 @@ $ echo babar - rataxes + babar This is a noop statement so that this test is still more bytes than success. ERROR: test-failure.t output changed ! Failed test-failure.t: output changed # Ran 2 tests, 1 skipped, 0 warned, 1 failed. python hash seed: * (glob) [1] Selecting Tests To Run ====================== successful $ $TESTDIR/run-tests.py --with-hg=`which hg` test-success.t . # Ran 1 tests, 0 skipped, 0 warned, 0 failed. success w/ keyword $ $TESTDIR/run-tests.py --with-hg=`which hg` -k xyzzy . # Ran 2 tests, 1 skipped, 0 warned, 0 failed. failed $ $TESTDIR/run-tests.py --with-hg=`which hg` test-failure.t --- $TESTTMP/test-failure.t (glob) +++ $TESTTMP/test-failure.t.err (glob) @@ -1,4 +1,4 @@ $ echo babar - rataxes + babar This is a noop statement so that this test is still more bytes than success. ERROR: test-failure.t output changed ! Failed test-failure.t: output changed # Ran 1 tests, 0 skipped, 0 warned, 1 failed. python hash seed: * (glob) [1] failure w/ keyword $ $TESTDIR/run-tests.py --with-hg=`which hg` -k rataxes --- $TESTTMP/test-failure.t +++ $TESTTMP/test-failure.t.err @@ -1,4 +1,4 @@ $ echo babar - rataxes + babar This is a noop statement so that this test is still more bytes than success. ERROR: test-failure.t output changed ! Failed test-failure.t: output changed # Ran 2 tests, 1 skipped, 0 warned, 1 failed. python hash seed: * (glob) [1] Verify that when a process fails to start we show a useful message ================================================================== NOTE: there is currently a bug where this shows "2 failed" even though it's actually the same test being reported for failure twice. $ cat > test-serve-fail.t <<EOF > $ echo 'abort: child process failed to start blah' > EOF $ $TESTDIR/run-tests.py --with-hg=`which hg` test-serve-fail.t ERROR: test-serve-fail.t output changed ! ERROR: test-serve-fail.t output changed ! Failed test-serve-fail.t: server failed to start (HGPORT=*) (glob) Failed test-serve-fail.t: output changed # Ran 1 tests, 0 skipped, 0 warned, 2 failed. python hash seed: * (glob) [1] $ rm test-serve-fail.t Running In Debug Mode ====================== $ $TESTDIR/run-tests.py --with-hg=`which hg` --debug 2>&1 | grep -v pwd + echo SALT* 0 0 (glob) SALT* 0 0 (glob) + echo babar babar + echo SALT* 4 0 (glob) SALT* 4 0 (glob) .+ echo SALT* 0 0 (glob) SALT* 0 0 (glob) + echo babar babar + echo SALT* 2 0 (glob) SALT* 2 0 (glob) + echo xyzzy xyzzy + echo SALT* 4 0 (glob) SALT* 4 0 (glob) . # Ran 2 tests, 0 skipped, 0 warned, 0 failed. Parallel runs ============== (duplicate the failing test to get predictable output) $ cp test-failure.t test-failure-copy.t $ $TESTDIR/run-tests.py --with-hg=`which hg` --jobs 2 test-failure*.t --- $TESTTMP/test-failure*.t (glob) +++ $TESTTMP/test-failure*.t.err (glob) @@ -1,4 +1,4 @@ $ echo babar - rataxes + babar This is a noop statement so that this test is still more bytes than success. ERROR: test-failure*.t output changed (glob) ! --- $TESTTMP/test-failure*.t (glob) +++ $TESTTMP/test-failure*.t.err (glob) @@ -1,4 +1,4 @@ $ echo babar - rataxes + babar This is a noop statement so that this test is still more bytes than success. ERROR: test-failure*.t output changed (glob) ! Failed test-failure*.t: output changed (glob) Failed test-failure*.t: output changed (glob) # Ran 2 tests, 0 skipped, 0 warned, 2 failed. python hash seed: * (glob) [1] failures in parallel with --first should only print one failure >>> f = open('test-nothing.t', 'w') >>> f.write('foo\n' * 1024) >>> f.write(' $ sleep 1') $ $TESTDIR/run-tests.py --with-hg=`which hg` --jobs 2 --first --- $TESTTMP/test-failure*.t (glob) +++ $TESTTMP/test-failure*.t.err (glob) @@ -1,4 +1,4 @@ $ echo babar - rataxes + babar This is a noop statement so that this test is still more bytes than success. Failed test-failure*.t: output changed (glob) # Ran 2 tests, 0 skipped, 0 warned, 1 failed. python hash seed: * (glob) [1] (delete the duplicated test file) $ rm test-failure-copy.t test-nothing.t Interactive run =============== (backup the failing test) $ cp test-failure.t backup Refuse the fix $ echo 'n' | $TESTDIR/run-tests.py --with-hg=`which hg` -i --- $TESTTMP/test-failure.t +++ $TESTTMP/test-failure.t.err @@ -1,4 +1,4 @@ $ echo babar - rataxes + babar This is a noop statement so that this test is still more bytes than success. Accept this change? [n] ERROR: test-failure.t output changed !. Failed test-failure.t: output changed # Ran 2 tests, 0 skipped, 0 warned, 1 failed. python hash seed: * (glob) [1] $ cat test-failure.t $ echo babar rataxes This is a noop statement so that this test is still more bytes than success. Interactive with custom view $ echo 'n' | $TESTDIR/run-tests.py --with-hg=`which hg` -i --view echo $TESTTMP/test-failure.t $TESTTMP/test-failure.t.err Accept this change? [n]* (glob) ERROR: test-failure.t output changed !. Failed test-failure.t: output changed # Ran 2 tests, 0 skipped, 0 warned, 1 failed. python hash seed: * (glob) [1] View the fix $ echo 'y' | $TESTDIR/run-tests.py --with-hg=`which hg` --view echo $TESTTMP/test-failure.t $TESTTMP/test-failure.t.err ERROR: test-failure.t output changed !. Failed test-failure.t: output changed # Ran 2 tests, 0 skipped, 0 warned, 1 failed. python hash seed: * (glob) [1] Accept the fix $ echo 'y' | $TESTDIR/run-tests.py --with-hg=`which hg` -i --- $TESTTMP/test-failure.t +++ $TESTTMP/test-failure.t.err @@ -1,4 +1,4 @@ $ echo babar - rataxes + babar This is a noop statement so that this test is still more bytes than success. Accept this change? [n] .. # Ran 2 tests, 0 skipped, 0 warned, 0 failed. $ cat test-failure.t $ echo babar babar This is a noop statement so that this test is still more bytes than success. (reinstall) $ mv backup test-failure.t No Diff =============== $ $TESTDIR/run-tests.py --with-hg=`which hg` --nodiff !. Failed test-failure.t: output changed # Ran 2 tests, 0 skipped, 0 warned, 1 failed. python hash seed: * (glob) [1] test for --time ================== $ $TESTDIR/run-tests.py --with-hg=`which hg` test-success.t --time . # Ran 1 tests, 0 skipped, 0 warned, 0 failed. # Producing time report cuser csys real Test \s*[\d\.]{5} \s*[\d\.]{5} \s*[\d\.]{5} test-success.t (re) test for --time with --job enabled ==================================== $ $TESTDIR/run-tests.py --with-hg=`which hg` test-success.t --time --jobs 2 . # Ran 1 tests, 0 skipped, 0 warned, 0 failed. # Producing time report cuser csys real Test \s*[\d\.]{5} \s*[\d\.]{5} \s*[\d\.]{5} test-success.t (re) Skips ================ $ cat > test-skip.t <<EOF > $ echo xyzzy > #require false > EOF $ $TESTDIR/run-tests.py --with-hg=`which hg` --nodiff !.s Skipped test-skip.t: skipped Failed test-failure.t: output changed # Ran 2 tests, 1 skipped, 0 warned, 1 failed. python hash seed: * (glob) [1] $ $TESTDIR/run-tests.py --with-hg=`which hg` --keyword xyzzy .s Skipped test-skip.t: skipped # Ran 2 tests, 2 skipped, 0 warned, 0 failed. Skips with xml $ $TESTDIR/run-tests.py --with-hg=`which hg` --keyword xyzzy \ > --xunit=xunit.xml .s Skipped test-skip.t: skipped # Ran 2 tests, 2 skipped, 0 warned, 0 failed. $ cat xunit.xml <?xml version="1.0" encoding="utf-8"?> <testsuite errors="0" failures="0" name="run-tests" skipped="2" tests="2"> <testcase name="test-success.t" time="*"/> (glob) </testsuite> Missing skips or blacklisted skips don't count as executed: $ echo test-failure.t > blacklist $ $TESTDIR/run-tests.py --with-hg=`which hg` --blacklist=blacklist \ > test-failure.t test-bogus.t ss Skipped test-bogus.t: Doesn't exist Skipped test-failure.t: blacklisted # Ran 0 tests, 2 skipped, 0 warned, 0 failed. #if json test for --json ================== $ $TESTDIR/run-tests.py --with-hg=`which hg` --json --- $TESTTMP/test-failure.t +++ $TESTTMP/test-failure.t.err @@ -1,4 +1,4 @@ $ echo babar - rataxes + babar This is a noop statement so that this test is still more bytes than success. ERROR: test-failure.t output changed !.s Skipped test-skip.t: skipped Failed test-failure.t: output changed # Ran 2 tests, 1 skipped, 0 warned, 1 failed. python hash seed: * (glob) [1] $ cat report.json testreport ={ "test-failure.t": [\{] (re) "csys": "\s*[\d\.]{5}", (re) "cuser": "\s*[\d\.]{5}", (re) "result": "failure", "time": "\s*[\d\.]{5}" (re) }, "test-skip.t": { "csys": "\s*[\d\.]{5}", (re) "cuser": "\s*[\d\.]{5}", (re) "result": "skip", "time": "\s*[\d\.]{5}" (re) }, "test-success.t": [\{] (re) "csys": "\s*[\d\.]{5}", (re) "cuser": "\s*[\d\.]{5}", (re) "result": "success", "time": "\s*[\d\.]{5}" (re) } } (no-eol) #endif