annotate tests/test-narrow-exchange-merges.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)

  $ . "$TESTDIR/narrow-library.sh"

create full repo

  $ hg init master
  $ cd master
  $ cat >> .hg/hgrc <<EOF
  > [narrow]
  > serveellipses=True
  > EOF

  $ mkdir inside
  $ echo 1 > inside/f
  $ hg commit -Aqm 'initial inside'

  $ mkdir outside
  $ echo 1 > outside/f
  $ hg commit -Aqm 'initial outside'

  $ echo 2a > outside/f
  $ hg commit -Aqm 'outside 2a'
  $ echo 3 > inside/f
  $ hg commit -Aqm 'inside 3'
  $ echo 4a > outside/f
  $ hg commit -Aqm 'outside 4a'
  $ hg update '.~3'
  2 files updated, 0 files merged, 0 files removed, 0 files unresolved

  $ echo 2b > outside/f
  $ hg commit -Aqm 'outside 2b'
  $ echo 3 > inside/f
  $ hg commit -Aqm 'inside 3'
  $ echo 4b > outside/f
  $ hg commit -Aqm 'outside 4b'
  $ hg update '.~3'
  2 files updated, 0 files merged, 0 files removed, 0 files unresolved

  $ echo 2c > outside/f
  $ hg commit -Aqm 'outside 2c'
  $ echo 3 > inside/f
  $ hg commit -Aqm 'inside 3'
  $ echo 4c > outside/f
  $ hg commit -Aqm 'outside 4c'
  $ hg update '.~3'
  2 files updated, 0 files merged, 0 files removed, 0 files unresolved

  $ echo 2d > outside/f
  $ hg commit -Aqm 'outside 2d'
  $ echo 3 > inside/f
  $ hg commit -Aqm 'inside 3'
  $ echo 4d > outside/f
  $ hg commit -Aqm 'outside 4d'

  $ hg update -r 'desc("outside 4a")'
  1 files updated, 0 files merged, 0 files removed, 0 files unresolved
  $ hg merge -r 'desc("outside 4b")' 2>&1 | egrep -v '(warning:|incomplete!)'
  merging outside/f
  0 files updated, 0 files merged, 0 files removed, 1 files unresolved
  use 'hg resolve' to retry unresolved file merges or 'hg merge --abort' to abandon
  $ echo 5 > outside/f
  $ rm outside/f.orig
  $ hg resolve --mark outside/f
  (no more unresolved files)
  $ hg commit -m 'merge a/b 5'
  $ echo 6 > outside/f
  $ hg commit -Aqm 'outside 6'

  $ hg merge -r 'desc("outside 4c")' 2>&1 | egrep -v '(warning:|incomplete!)'
  merging outside/f
  0 files updated, 0 files merged, 0 files removed, 1 files unresolved
  use 'hg resolve' to retry unresolved file merges or 'hg merge --abort' to abandon
  $ echo 7 > outside/f
  $ rm outside/f.orig
  $ hg resolve --mark outside/f
  (no more unresolved files)
  $ hg commit -Aqm 'merge a/b/c 7'
  $ echo 8 > outside/f
  $ hg commit -Aqm 'outside 8'

  $ hg merge -r 'desc("outside 4d")' 2>&1 | egrep -v '(warning:|incomplete!)'
  merging outside/f
  0 files updated, 0 files merged, 0 files removed, 1 files unresolved
  use 'hg resolve' to retry unresolved file merges or 'hg merge --abort' to abandon
  $ echo 9 > outside/f
  $ rm outside/f.orig
  $ hg resolve --mark outside/f
  (no more unresolved files)
  $ hg commit -Aqm 'merge a/b/c/d 9'
  $ echo 10 > outside/f
  $ hg commit -Aqm 'outside 10'

  $ echo 11 > inside/f
  $ hg commit -Aqm 'inside 11'
  $ echo 12 > outside/f
  $ hg commit -Aqm 'outside 12'

  $ hg log -G -T '{rev} {node|short} {desc}\n'
  @  21 8d874d57adea outside 12
  |
  o  20 7ef88b4dd4fa inside 11
  |
  o  19 2a20009de83e outside 10
  |
  o    18 3ac1f5779de3 merge a/b/c/d 9
  |\
  | o  17 38a9c2f7e546 outside 8
  | |
  | o    16 094aa62fc898 merge a/b/c 7
  | |\
  | | o  15 f29d083d32e4 outside 6
  | | |
  | | o    14 2dc11382541d merge a/b 5
  | | |\
  o | | |  13 27d07ef97221 outside 4d
  | | | |
  o | | |  12 465567bdfb2d inside 3
  | | | |
  o | | |  11 d1c61993ec83 outside 2d
  | | | |
  | o | |  10 56859a8e33b9 outside 4c
  | | | |
  | o | |  9 bb96a08b062a inside 3
  | | | |
  | o | |  8 b844052e7b3b outside 2c
  |/ / /
  | | o  7 9db2d8fcc2a6 outside 4b
  | | |
  | | o  6 6418167787a6 inside 3
  | | |
  +---o  5 77344f344d83 outside 2b
  | |
  | o  4 9cadde08dc9f outside 4a
  | |
  | o  3 019ef06f125b inside 3
  | |
  | o  2 75e40c075a19 outside 2a
  |/
  o  1 906d6c682641 initial outside
  |
  o  0 9f8e82b51004 initial inside
  

Now narrow clone this and get a hopefully correct graph

  $ cd ..
  $ hg clone --narrow ssh://user@dummy/master narrow --include inside
  requesting all changes
  adding changesets
  adding manifests
  adding file changes
  added 14 changesets with 3 changes to 1 files
  new changesets *:* (glob)
  updating to branch default
  1 files updated, 0 files merged, 0 files removed, 0 files unresolved
  $ cd narrow

To make updating the tests easier, we print the emitted nodes
sorted. This makes it easier to identify when the same node structure
has been emitted, just in a different order.

  $ hg log -T '{if(ellipsis,"...")}{node|short} {p1node|short} {p2node|short} {desc}\n' | sort
  ...094aa62fc898 6418167787a6 bb96a08b062a merge a/b/c 7
  ...2a20009de83e 019ef06f125b 3ac1f5779de3 outside 10
  ...3ac1f5779de3 465567bdfb2d 094aa62fc898 merge a/b/c/d 9
  ...75e40c075a19 9f8e82b51004 000000000000 outside 2a
  ...77344f344d83 9f8e82b51004 000000000000 outside 2b
  ...8d874d57adea 7ef88b4dd4fa 000000000000 outside 12
  ...b844052e7b3b 9f8e82b51004 000000000000 outside 2c
  ...d1c61993ec83 9f8e82b51004 000000000000 outside 2d
  019ef06f125b 75e40c075a19 000000000000 inside 3
  465567bdfb2d d1c61993ec83 000000000000 inside 3
  6418167787a6 77344f344d83 000000000000 inside 3
  7ef88b4dd4fa 2a20009de83e 000000000000 inside 11
  9f8e82b51004 000000000000 000000000000 initial inside
  bb96a08b062a b844052e7b3b 000000000000 inside 3

But seeing the graph is also nice:
  $ hg log -G -T '{if(ellipsis,"...")}{node|short} {desc}\n'
  @  ...8d874d57adea outside 12
  |
  o  7ef88b4dd4fa inside 11
  |
  o    ...2a20009de83e outside 10
  |\
  | o    ...3ac1f5779de3 merge a/b/c/d 9
  | |\
  | | o    ...094aa62fc898 merge a/b/c 7
  | | |\
  | o | |  465567bdfb2d inside 3
  | | | |
  | o | |  ...d1c61993ec83 outside 2d
  | | | |
  | | | o  bb96a08b062a inside 3
  | | | |
  | +---o  ...b844052e7b3b outside 2c
  | | |
  | | o  6418167787a6 inside 3
  | | |
  | | o  ...77344f344d83 outside 2b
  | |/
  o |  019ef06f125b inside 3
  | |
  o |  ...75e40c075a19 outside 2a
  |/
  o  9f8e82b51004 initial inside