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

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