[PATCH 1 of 2 V2] log: flush stdout/err for the first log entries

[Matt Mackall]

On Thu, 2015-09-24 at 13:02 -0700, Durham Goode wrote:
> 
> On 9/24/15 12:49 PM, Matt Mackall wrote:
> > On Thu, 2015-09-24 at 12:20 -0700, Durham Goode wrote:
> >> # HG changeset patch
> >> # User Durham Goode <durham at fb.com>
> >> # Date 1443118388 25200
> >> #      Thu Sep 24 11:13:08 2015 -0700
> >> # Node ID 7a9aaaadaed9887a956cb6a1e79be527e6f4a20f
> >> # Parent  a0eff7ebc2aebb32cf4c8da276104102ff37d786
> >> log: flush stdout/err for the first log entries
> >>
> >> There have been problems with the pager where we get no results until the python
> >> buffer has been filled. Let's fix that by manually flushing the buffer for the
> >> first 50 commits from log. 50 was chosen because it will likely fill the users
> >> screen and doesn't introduce a significant overhead.
> >>
> >> The overhead of this is negiligble. I see no perf difference when running log on
> >> 100,000 commits.
> > Still confused as to why this isn't in the ui code.
> This is in addition to the ui code.  I have a patch that adjusts the ui 
> code to flush every N seconds, but it causes some tests to fail (since 
> they didn't on the timing of the progress bar output) so I sent these 
> patches first.
>
> We still need these 2 patches though.  Imagine a scenario where you run 
> hg log on a directory that has only had one commit total (and it was 
> recent). Immediately one commit is printed into the buffer (before the 
> flush time limit is hit).  Then half an hour goes buy while we scan the 
> rest of the repository for another commit in that directory.  We end up 
> not showing the user that commit until the command is completely 
> finished.  Printing the first N units prevents this experience.

Right. You can't make the timer thing really work without a thread or
something. So given that's known to be somewhat broken and that this
flushing problem isn't in any way log-specific, why don't we just put a
counter and a flush in ui.write()?

I just did this, saw a pretty repeatable 7.2->7.3s change for hg log on
the hg repo:

diff -r b80b2ee71a08 mercurial/ui.py
--- a/mercurial/ui.py	Thu Sep 24 00:34:15 2015 -0700
+++ b/mercurial/ui.py	Thu Sep 24 17:45:42 2015 -0500
@@ -104,6 +104,7 @@
         self._ucfg = config.config() # untrusted
         self._trustusers = set()
         self._trustgroups = set()
+        self._outcount = 0
         self.callhooks = True
 
         if src:
@@ -617,6 +618,9 @@
         else:
             for a in args:
                 self.fout.write(str(a))
+            if self._outcount < 50:
+                self.fout.flush()
+                self._outcount += 1
 
     def write_err(self, *args, **opts):
         self._progclear()

("hg log -k sullivan -T." is a pretty good behavior test here.) 

-- 
Mathematics is the supreme nostalgia of our time.