Patchwork [4,of,5] branchcache: add debug output whenever cache files use truncate

login
register
mail settings
Submitter Mads Kiilerich
Date Jan. 14, 2015, 11:24 p.m.
Message ID <563e3b1a9c9f5efc7d07.1421277879@localhost.localdomain>
Download mbox | patch
Permalink /patch/7458/
State Accepted
Commit 7aa1405528a389e70aa23b0cbc5d677e1bb3c78a
Headers show

Comments

Mads Kiilerich - Jan. 14, 2015, 11:24 p.m.
# HG changeset patch
# User Mads Kiilerich <madski@unity3d.com>
# Date 1421194526 -3600
#      Wed Jan 14 01:15:26 2015 +0100
# Node ID 563e3b1a9c9f5efc7d07b1ae60cc45f700176989
# Parent  82624926786279b4c2ada666151015a82608b0b3
branchcache: add debug output whenever cache files use truncate

The cache files are usually append only but will automatically be truncated and
recover in exceptional situations. Add a debug notice when such exceptional
situations are encountered.
Gregory Szorc - Jan. 15, 2015, 3:13 a.m.
On Wed, Jan 14, 2015 at 3:24 PM, Mads Kiilerich <mads@kiilerich.com> wrote:

> # HG changeset patch
> # User Mads Kiilerich <madski@unity3d.com>
> # Date 1421194526 -3600
> #      Wed Jan 14 01:15:26 2015 +0100
> # Node ID 563e3b1a9c9f5efc7d07b1ae60cc45f700176989
> # Parent  82624926786279b4c2ada666151015a82608b0b3
> branchcache: add debug output whenever cache files use truncate
>
> The cache files are usually append only but will automatically be
> truncated and
> recover in exceptional situations. Add a debug notice when such exceptional
> situations are encountered.
>
>
What do you think about adding blackbox logging, similar to branch and tags
caches? See 9ea132aee96c and  05cfcecb3aef. I've found these after-the-fact
blackbox log events to be invaluable when debugging "random hangs" because
cache operations are (by their very nature) hard to catch in the act.
Mads Kiilerich - Jan. 15, 2015, 3:48 p.m.
On 01/15/2015 04:13 AM, Gregory Szorc wrote:
> On Wed, Jan 14, 2015 at 3:24 PM, Mads Kiilerich <mads@kiilerich.com 
> <mailto:mads@kiilerich.com>> wrote:
>
>     # HG changeset patch
>     # User Mads Kiilerich <madski@unity3d.com <mailto:madski@unity3d.com>>
>     # Date 1421194526 -3600
>     #      Wed Jan 14 01:15:26 2015 +0100
>     # Node ID 563e3b1a9c9f5efc7d07b1ae60cc45f700176989
>     # Parent  82624926786279b4c2ada666151015a82608b0b3
>     branchcache: add debug output whenever cache files use truncate
>
>     The cache files are usually append only but will automatically be
>     truncated and
>     recover in exceptional situations. Add a debug notice when such
>     exceptional
>     situations are encountered.
>
>
> What do you think about adding blackbox logging,

Basically, I just didn't think about it ;-)

> similar to branch and tags caches? See 9ea132aee96c and  05cfcecb3aef. 
> I've found these after-the-fact blackbox log events to be invaluable 
> when debugging "random hangs" because cache operations are (by their 
> very nature) hard to catch in the act.

If so, it should be in revbranchcache.branchinfo when "populate all 
missing revs". (Where Marmoute suggested a more on-demand approach while 
I preferred keeping the amortized cost low and do everything at once.)

I don't have an overview of exactly what did/do make it expensive to 
rebuild the branch and tag caches. But it seems like most of it was 
caused by bugs / insufficient design/implementation. Is the branchmap 
logging still that relevant?

The revbranchcache is more low level than the other caches and less 
likely to be invalidated. I figure it thus pretty much will be 
uninteresting information. The time spent in updating the revbranchcache 
will also mostly be covered by the logging you added. (It will however 
not cover the case where the cache is used elsewhere and is outdated and 
has to be recalculated but cannot be written back. But that will 
probably just be a bug.)

So I guess I'm +0. Not a big fan, but also no objections.

/Mads

Patch

diff --git a/mercurial/branchmap.py b/mercurial/branchmap.py
--- a/mercurial/branchmap.py
+++ b/mercurial/branchmap.py
@@ -414,6 +414,7 @@  class revbranchcache(object):
                         f.write('\0')
                     else:
                         f.close()
+                        repo.ui.debug("%s changed - rewriting it\n" % _rbcnames)
                         self._rbcnamescount = 0
                         self._rbcrevslen = 0
                 if self._rbcnamescount == 0:
@@ -438,6 +439,7 @@  class revbranchcache(object):
                 # see issue3543.  SEEK_END was added in 2.5
                 f.seek(0, 2) #os.SEEK_END
                 if f.tell() != start:
+                    repo.ui.debug("truncating %s to %s\n" % (_rbcrevs, start))
                     f.seek(start)
                     f.truncate()
                 end = self._rbcrevslen * _rbcrecsize
diff --git a/tests/test-branches.t b/tests/test-branches.t
--- a/tests/test-branches.t
+++ b/tests/test-branches.t
@@ -550,6 +550,7 @@  revision branch cache is created when bu
 recovery from invalid cache revs file with trailing data
   $ echo >> .hg/cache/rbc-revs-v1
   $ rm -f .hg/cache/branch* && hg head a -T '{rev}\n' --debug
+  truncating cache/rbc-revs-v1 to 120
   5
   $ f --size .hg/cache/rbc-revs*
   .hg/cache/rbc-revs-v1: size=120
@@ -559,6 +560,7 @@  recovery from invalid cache file with pa
   $ f --size .hg/cache/rbc-revs*
   .hg/cache/rbc-revs-v1: size=119
   $ rm -f .hg/cache/branch* && hg head a -T '{rev}\n' --debug
+  truncating cache/rbc-revs-v1 to 112
   5
   $ f --size .hg/cache/rbc-revs*
   .hg/cache/rbc-revs-v1: size=120
@@ -580,6 +582,7 @@  recovery from invalid cache file with so
   $ hg log -r 'branch(.)' -T '{rev} '
   3 4 8 9 10 11 12 13  (no-eol)
   $ rm -f .hg/cache/branch* && hg head a -T '{rev}\n' --debug
+  truncating cache/rbc-revs-v1 to 8
   5
   $ f --size --hexdump --bytes=16 .hg/cache/rbc-revs*
   .hg/cache/rbc-revs-v1: size=120
diff --git a/tests/test-rebase-conflicts.t b/tests/test-rebase-conflicts.t
--- a/tests/test-rebase-conflicts.t
+++ b/tests/test-rebase-conflicts.t
@@ -322,5 +322,6 @@  Check that the right ancestors is used w
   files: 1/1 chunks (100.00%)
   added 2 changesets with 2 changes to 1 files
   invalid branchheads cache (served): tip differs
+  truncating cache/rbc-revs-v1 to 72
   rebase completed
   updating the branch cache