view tests/test-contrib-perf.t @ 44950:f9734b2d59cc

py3: make stdout line-buffered if connected to a TTY

Status messages that are to be shown on the terminal should be written to the
file descriptor before anything further is done, to keep the user updated.

One common way to achieve this is to make stdout line-buffered if it is
connected to a TTY. This is done on Python 2 (except on Windows, where libc,
which the CPython 2 streams depend on, does not properly support this).

Python 3 rolls it own I/O streams. On Python 3, buffered binary streams can't be
set line-buffered. The previous code (added in 227ba1afcb65) incorrectly
assumed that on Python 3, pycompat.stdout (sys.stdout.buffer) is already
line-buffered. However the interpreter initializes it with a block-buffered
stream or an unbuffered stream (when the -u option or the PYTHONUNBUFFERED
environment variable is set), never with a line-buffered stream.

One example where the current behavior is unacceptable is when running
`hg pull https://www.mercurial-scm.org/repo/hg` on Python 3, where the line
"pulling from https://www.mercurial-scm.org/repo/hg" does not appear on the
terminal before the hg process blocks while waiting for the server.

Various approaches to fix this problem are possible, including:

1. Weaken the contract of procutil.stdout to not give any guarantees about
   buffering behavior. In this case, users of procutil.stdout need to be
   changed to do enough flushes. In particular,
  1. either ui must insert enough flushes for ui.write() and friends, or
  2. ui.write() and friends get split into flushing and fully buffered
     methods, or
  3. users of ui.write() and friends must flush explicitly.
2. Make stdout unbuffered.
3. Make stdout line-buffered. Since Python 3 does not natively support that for
   binary streams, we must implement it ourselves.

(2.) is problematic because using unbuffered I/O changes the performance
characteristics significantly compared to line-buffered (which is used on
Python 2) and this would be a regression.

(1.2.) and (1.3) are a substantial amount of work. It’s unclear whether the
added complexity would be justified, given that raw performance doesn’t matter
that much when writing to a terminal much faster than the user could read it.

(1.1.) pushes complexity into the ui class instead of separating the concern of
how stdout is buffered. Other users of procutil.stdout would still need to take
care of the flushes.

This patch implements (3.). The general performance considerations are very
similar to (1.1.). The extra method invocation and method forwarding add a
little more overhead if the class is used. In exchange, it doesn’t add overhead
if not used.


For the benchmarks, I compared the previous implementation (incorrect on Python
3), (1.1.), (3.) and (2.). The command was chosen so that the streams were
configured as if they were writing to a TTY, but actually write to a pager,
which is also the default:
HGRCPATH=/dev/null python3 ./hg --cwd ~/vcs/mozilla-central --time --pager yes --config pager.pager='cat > /dev/null' status --all

previous:
time: real 7.880 secs (user 7.290+0.050 sys 0.580+0.170)
time: real 7.830 secs (user 7.220+0.070 sys 0.590+0.140)
time: real 7.800 secs (user 7.210+0.050 sys 0.570+0.170)

(1.1.) using Yuya Nishihara’s patch:
time: real 9.860 secs (user 8.670+0.350 sys 1.160+0.830)
time: real 9.540 secs (user 8.430+0.370 sys 1.100+0.770)
time: real 9.830 secs (user 8.630+0.370 sys 1.180+0.840)

(3.) using this patch:
time: real 9.580 secs (user 8.480+0.350 sys 1.090+0.770)
time: real 9.670 secs (user 8.480+0.330 sys 1.170+0.860)
time: real 9.640 secs (user 8.500+0.350 sys 1.130+0.810)

(2.) using a previous patch by me:
time: real 10.480 secs (user 8.850+0.720 sys 1.590+1.500)
time: real 10.490 secs (user 8.750+0.750 sys 1.710+1.470)
time: real 10.240 secs (user 8.600+0.700 sys 1.590+1.510)


As expected, there’s no difference on Python 2, as exactly the same code paths
are used:

previous:
time: real 6.950 secs (user 5.870+0.330 sys 1.070+0.770)
time: real 7.040 secs (user 6.040+0.360 sys 0.980+0.750)
time: real 7.070 secs (user 5.950+0.360 sys 1.100+0.760)

this patch:
time: real 7.010 secs (user 5.900+0.390 sys 1.070+0.730)
time: real 7.000 secs (user 5.850+0.350 sys 1.120+0.760)
time: real 7.000 secs (user 5.790+0.380 sys 1.170+0.710)

#require test-repo

Set vars:

  $ . "$TESTDIR/helpers-testrepo.sh"
  $ CONTRIBDIR="$TESTDIR/../contrib"

Prepare repo:

  $ hg init

  $ echo this is file a > a
  $ hg add a
  $ hg commit -m first

  $ echo adding to file a >> a
  $ hg commit -m second

  $ echo adding more to file a >> a
  $ hg commit -m third

  $ hg up -r 0
  1 files updated, 0 files merged, 0 files removed, 0 files unresolved
  $ echo merge-this >> a
  $ hg commit -m merge-able
  created new head

  $ hg up -r 2
  1 files updated, 0 files merged, 0 files removed, 0 files unresolved

perfstatus

  $ cat >> $HGRCPATH << EOF
  > [extensions]
  > perf=$CONTRIBDIR/perf.py
  > [perf]
  > presleep=0
  > stub=on
  > parentscount=1
  > EOF
  $ hg help -e perf
  perf extension - helper extension to measure performance
  
  Configurations
  ==============
  
  "perf"
  ------
  
  "all-timing"
      When set, additional statistics will be reported for each benchmark: best,
      worst, median average. If not set only the best timing is reported
      (default: off).
  
  "presleep"
    number of second to wait before any group of runs (default: 1)
  
  "pre-run"
    number of run to perform before starting measurement.
  
  "profile-benchmark"
    Enable profiling for the benchmarked section. (The first iteration is
    benchmarked)
  
  "run-limits"
    Control the number of runs each benchmark will perform. The option value
    should be a list of '<time>-<numberofrun>' pairs. After each run the
    conditions are considered in order with the following logic:
  
        If benchmark has been running for <time> seconds, and we have performed
        <numberofrun> iterations, stop the benchmark,
  
    The default value is: '3.0-100, 10.0-3'
  
  "stub"
      When set, benchmarks will only be run once, useful for testing (default:
      off)
  
  list of commands:
  
   perfaddremove
                 (no help text available)
   perfancestors
                 (no help text available)
   perfancestorset
                 (no help text available)
   perfannotate  (no help text available)
   perfbdiff     benchmark a bdiff between revisions
   perfbookmarks
                 benchmark parsing bookmarks from disk to memory
   perfbranchmap
                 benchmark the update of a branchmap
   perfbranchmapload
                 benchmark reading the branchmap
   perfbranchmapupdate
                 benchmark branchmap update from for <base> revs to <target>
                 revs
   perfbundleread
                 Benchmark reading of bundle files.
   perfcca       (no help text available)
   perfchangegroupchangelog
                 Benchmark producing a changelog group for a changegroup.
   perfchangeset
                 (no help text available)
   perfctxfiles  (no help text available)
   perfdiffwd    Profile diff of working directory changes
   perfdirfoldmap
                 benchmap a 'dirstate._map.dirfoldmap.get()' request
   perfdirs      (no help text available)
   perfdirstate  benchmap the time of various distate operations
   perfdirstatedirs
                 benchmap a 'dirstate.hasdir' call from an empty 'dirs' cache
   perfdirstatefoldmap
                 benchmap a 'dirstate._map.filefoldmap.get()' request
   perfdirstatewrite
                 benchmap the time it take to write a dirstate on disk
   perfdiscovery
                 benchmark discovery between local repo and the peer at given
                 path
   perffncacheencode
                 (no help text available)
   perffncacheload
                 (no help text available)
   perffncachewrite
                 (no help text available)
   perfheads     benchmark the computation of a changelog heads
   perfhelper-mergecopies
                 find statistics about potential parameters for
                 'perfmergecopies'
   perfhelper-pathcopies
                 find statistic about potential parameters for the
                 'perftracecopies'
   perfignore    benchmark operation related to computing ignore
   perfindex     benchmark index creation time followed by a lookup
   perflinelogedits
                 (no help text available)
   perfloadmarkers
                 benchmark the time to parse the on-disk markers for a repo
   perflog       (no help text available)
   perflookup    (no help text available)
   perflrucachedict
                 (no help text available)
   perfmanifest  benchmark the time to read a manifest from disk and return a
                 usable
   perfmergecalculate
                 (no help text available)
   perfmergecopies
                 measure runtime of 'copies.mergecopies'
   perfmoonwalk  benchmark walking the changelog backwards
   perfnodelookup
                 (no help text available)
   perfnodemap   benchmark the time necessary to look up revision from a cold
                 nodemap
   perfparents   benchmark the time necessary to fetch one changeset's parents.
   perfpathcopies
                 benchmark the copy tracing logic
   perfphases    benchmark phasesets computation
   perfphasesremote
                 benchmark time needed to analyse phases of the remote server
   perfprogress  printing of progress bars
   perfrawfiles  (no help text available)
   perfrevlogchunks
                 Benchmark operations on revlog chunks.
   perfrevlogindex
                 Benchmark operations against a revlog index.
   perfrevlogrevision
                 Benchmark obtaining a revlog revision.
   perfrevlogrevisions
                 Benchmark reading a series of revisions from a revlog.
   perfrevlogwrite
                 Benchmark writing a series of revisions to a revlog.
   perfrevrange  (no help text available)
   perfrevset    benchmark the execution time of a revset
   perfstartup   (no help text available)
   perfstatus    benchmark the performance of a single status call
   perftags      (no help text available)
   perftemplating
                 test the rendering time of a given template
   perfunidiff   benchmark a unified diff between revisions
   perfvolatilesets
                 benchmark the computation of various volatile set
   perfwalk      (no help text available)
   perfwrite     microbenchmark ui.write
  
  (use 'hg help -v perf' to show built-in aliases and global options)
  $ hg perfaddremove
  $ hg perfancestors
  $ hg perfancestorset 2
  $ hg perfannotate a
  $ hg perfbdiff -c 1
  $ hg perfbdiff --alldata 1
  $ hg perfunidiff -c 1
  $ hg perfunidiff --alldata 1
  $ hg perfbookmarks
  $ hg perfbranchmap
  $ hg perfbranchmapload
  $ hg perfbranchmapupdate --base "not tip" --target "tip"
  benchmark of branchmap with 3 revisions with 1 new ones
  $ hg perfcca
  $ hg perfchangegroupchangelog
  $ hg perfchangegroupchangelog --cgversion 01
  $ hg perfchangeset 2
  $ hg perfctxfiles 2
  $ hg perfdiffwd
  $ hg perfdirfoldmap
  $ hg perfdirs
  $ hg perfdirstate
  $ hg perfdirstate --contains
  $ hg perfdirstate --iteration
  $ hg perfdirstatedirs
  $ hg perfdirstatefoldmap
  $ hg perfdirstatewrite
#if repofncache
  $ hg perffncacheencode
  $ hg perffncacheload
  $ hg debugrebuildfncache
  fncache already up to date
  $ hg perffncachewrite
  $ hg debugrebuildfncache
  fncache already up to date
#endif
  $ hg perfheads
  $ hg perfignore
  $ hg perfindex
  $ hg perflinelogedits -n 1
  $ hg perfloadmarkers
  $ hg perflog
  $ hg perflookup 2
  $ hg perflrucache
  $ hg perfmanifest 2
  $ hg perfmanifest -m 44fe2c8352bb3a478ffd7d8350bbc721920134d1
  $ hg perfmanifest -m 44fe2c8352bb
  abort: manifest revision must be integer or full node
  [255]
  $ hg perfmergecalculate -r 3
  $ hg perfmoonwalk
  $ hg perfnodelookup 2
  $ hg perfpathcopies 1 2
  $ hg perfprogress --total 1000
  $ hg perfrawfiles 2
  $ hg perfrevlogindex -c
#if reporevlogstore
  $ hg perfrevlogrevisions .hg/store/data/a.i
#endif
  $ hg perfrevlogrevision -m 0
  $ hg perfrevlogchunks -c
  $ hg perfrevrange
  $ hg perfrevset 'all()'
  $ hg perfstartup
  $ hg perfstatus
  $ hg perfstatus --dirstate
  $ hg perftags
  $ hg perftemplating
  $ hg perfvolatilesets
  $ hg perfwalk
  $ hg perfparents
  $ hg perfdiscovery -q .

Test run control
----------------

Simple single entry

  $ hg perfparents --config perf.stub=no --config perf.run-limits='0.000000001-15'
  ! wall * comb * user * sys * (best of 15) (glob)

Multiple entries

  $ hg perfparents --config perf.stub=no --config perf.run-limits='500000-1, 0.000000001-5'
  ! wall * comb * user * sys * (best of 5) (glob)

error case are ignored

  $ hg perfparents --config perf.stub=no --config perf.run-limits='500, 0.000000001-5'
  malformatted run limit entry, missing "-": 500
  ! wall * comb * user * sys * (best of 5) (glob)
  $ hg perfparents --config perf.stub=no --config perf.run-limits='aaa-12, 0.000000001-5'
  malformatted run limit entry, could not convert string to float: aaa: aaa-12 (no-py3 !)
  malformatted run limit entry, could not convert string to float: 'aaa': aaa-12 (py3 !)
  ! wall * comb * user * sys * (best of 5) (glob)
  $ hg perfparents --config perf.stub=no --config perf.run-limits='12-aaaaaa, 0.000000001-5'
  malformatted run limit entry, invalid literal for int() with base 10: 'aaaaaa': 12-aaaaaa
  ! wall * comb * user * sys * (best of 5) (glob)

test actual output
------------------

normal output:

  $ hg perfheads --config perf.stub=no
  ! wall * comb * user * sys * (best of *) (glob)

detailed output:

  $ hg perfheads --config perf.all-timing=yes --config perf.stub=no
  ! wall * comb * user * sys * (best of *) (glob)
  ! wall * comb * user * sys * (max of *) (glob)
  ! wall * comb * user * sys * (avg of *) (glob)
  ! wall * comb * user * sys * (median of *) (glob)

test json output
----------------

normal output:

  $ hg perfheads --template json --config perf.stub=no
  [
   {
    "comb": *, (glob)
    "count": *, (glob)
    "sys": *, (glob)
    "user": *, (glob)
    "wall": * (glob)
   }
  ]

detailed output:

  $ hg perfheads --template json --config perf.all-timing=yes --config perf.stub=no
  [
   {
    "avg.comb": *, (glob)
    "avg.count": *, (glob)
    "avg.sys": *, (glob)
    "avg.user": *, (glob)
    "avg.wall": *, (glob)
    "comb": *, (glob)
    "count": *, (glob)
    "max.comb": *, (glob)
    "max.count": *, (glob)
    "max.sys": *, (glob)
    "max.user": *, (glob)
    "max.wall": *, (glob)
    "median.comb": *, (glob)
    "median.count": *, (glob)
    "median.sys": *, (glob)
    "median.user": *, (glob)
    "median.wall": *, (glob)
    "sys": *, (glob)
    "user": *, (glob)
    "wall": * (glob)
   }
  ]

Test pre-run feature
--------------------

(perf discovery has some spurious output)

  $ hg perfdiscovery . --config perf.stub=no --config perf.run-limits='0.000000001-1' --config perf.pre-run=0
  ! wall * comb * user * sys * (best of 1) (glob)
  searching for changes
  $ hg perfdiscovery . --config perf.stub=no --config perf.run-limits='0.000000001-1' --config perf.pre-run=1
  ! wall * comb * user * sys * (best of 1) (glob)
  searching for changes
  searching for changes
  $ hg perfdiscovery . --config perf.stub=no --config perf.run-limits='0.000000001-1' --config perf.pre-run=3
  ! wall * comb * user * sys * (best of 1) (glob)
  searching for changes
  searching for changes
  searching for changes
  searching for changes

test  profile-benchmark option
------------------------------

Function to check that statprof ran
  $ statprofran () {
  >   egrep 'Sample count:|No samples recorded' > /dev/null
  > }
  $ hg perfdiscovery . --config perf.stub=no --config perf.run-limits='0.000000001-1' --config perf.profile-benchmark=yes 2>&1 | statprofran

Check perf.py for historical portability
----------------------------------------

  $ cd "$TESTDIR/.."

  $ (testrepohg files -r 1.2 glob:mercurial/*.c glob:mercurial/*.py;
  >  testrepohg files -r tip glob:mercurial/*.c glob:mercurial/*.py) |
  > "$TESTDIR"/check-perf-code.py contrib/perf.py
  contrib/perf.py:\d+: (re)
   >     from mercurial import (
   import newer module separately in try clause for early Mercurial
  contrib/perf.py:\d+: (re)
   >     from mercurial import (
   import newer module separately in try clause for early Mercurial
  contrib/perf.py:\d+: (re)
   >     origindexpath = orig.opener.join(orig.indexfile)
   use getvfs()/getsvfs() for early Mercurial
  contrib/perf.py:\d+: (re)
   >     origdatapath = orig.opener.join(orig.datafile)
   use getvfs()/getsvfs() for early Mercurial
  contrib/perf.py:\d+: (re)
   >         vfs = vfsmod.vfs(tmpdir)
   use getvfs()/getsvfs() for early Mercurial
  contrib/perf.py:\d+: (re)
   >         vfs.options = getattr(orig.opener, 'options', None)
   use getvfs()/getsvfs() for early Mercurial
  [1]