branchmap: log events related to branch cache

The blackblox log will now contain log events when the branch caches are
updated and written.

mercurial/branchmap.py

@@ -1,274 +1,285 b''
 # branchmap.py - logic to computes, maintain and stores branchmap for local repo
 #
 # Copyright 2005-2007 Matt Mackall <[e-mail]>
 #
 # This software may be used and distributed according to the terms of the
 # GNU General Public License version 2 or any later version.
 
 from node import bin, hex, nullid, nullrev
 import encoding
 import util
+import time
 
 def _filename(repo):
     """name of a branchcache file for a given repo or repoview"""
     filename = "cache/branch2"
     if repo.filtername:
         filename = '%s-%s' % (filename, repo.filtername)
     return filename
 
 def read(repo):
     try:
         f = repo.opener(_filename(repo))
         lines = f.read().split('\n')
         f.close()
     except (IOError, OSError):
         return None
 
     try:
         cachekey = lines.pop(0).split(" ", 2)
         last, lrev = cachekey[:2]
         last, lrev = bin(last), int(lrev)
         filteredhash = None
         if len(cachekey) > 2:
             filteredhash = bin(cachekey[2])
         partial = branchcache(tipnode=last, tiprev=lrev,
                               filteredhash=filteredhash)
         if not partial.validfor(repo):
             # invalidate the cache
             raise ValueError('tip differs')
         for l in lines:
             if not l:
                 continue
             node, state, label = l.split(" ", 2)
             if state not in 'oc':
                 raise ValueError('invalid branch state')
             label = encoding.tolocal(label.strip())
             if not node in repo:
                 raise ValueError('node %s does not exist' % node)
             node = bin(node)
             partial.setdefault(label, []).append(node)
             if state == 'c':
                 partial._closednodes.add(node)
     except KeyboardInterrupt:
         raise
     except Exception, inst:
         if repo.ui.debugflag:
             msg = 'invalid branchheads cache'
             if repo.filtername is not None:
                 msg += ' (%s)' % repo.filtername
             msg += ': %s\n'
             repo.ui.warn(msg % inst)
         partial = None
     return partial
 
 
 
 ### Nearest subset relation
 # Nearest subset of filter X is a filter Y so that:
 # * Y is included in X,
 # * X - Y is as small as possible.
 # This create and ordering used for branchmap purpose.
 # the ordering may be partial
 subsettable = {None: 'visible',
                'visible': 'served',
                'served': 'immutable',
                'immutable': 'base'}
 
 def updatecache(repo):
     cl = repo.changelog
     filtername = repo.filtername
     partial = repo._branchcaches.get(filtername)
 
     revs = []
     if partial is None or not partial.validfor(repo):
         partial = read(repo)
         if partial is None:
             subsetname = subsettable.get(filtername)
             if subsetname is None:
                 partial = branchcache()
             else:
                 subset = repo.filtered(subsetname)
                 partial = subset.branchmap().copy()
                 extrarevs = subset.changelog.filteredrevs - cl.filteredrevs
                 revs.extend(r for  r in extrarevs if r <= partial.tiprev)
     revs.extend(cl.revs(start=partial.tiprev + 1))
     if revs:
         partial.update(repo, revs)
         partial.write(repo)
     assert partial.validfor(repo), filtername
     repo._branchcaches[repo.filtername] = partial
 
 class branchcache(dict):
     """A dict like object that hold branches heads cache.
 
     This cache is used to avoid costly computations to determine all the
     branch heads of a repo.
 
     The cache is serialized on disk in the following format:
 
     <tip hex node> <tip rev number> [optional filtered repo hex hash]
     <branch head hex node> <open/closed state> <branch name>
     <branch head hex node> <open/closed state> <branch name>
     ...
 
     The first line is used to check if the cache is still valid. If the
     branch cache is for a filtered repo view, an optional third hash is
     included that hashes the hashes of all filtered revisions.
 
     The open/closed state is represented by a single letter 'o' or 'c'.
     This field can be used to avoid changelog reads when determining if a
     branch head closes a branch or not.
     """
 
     def __init__(self, entries=(), tipnode=nullid, tiprev=nullrev,
                  filteredhash=None, closednodes=None):
         super(branchcache, self).__init__(entries)
         self.tipnode = tipnode
         self.tiprev = tiprev
         self.filteredhash = filteredhash
         # closednodes is a set of nodes that close their branch. If the branch
         # cache has been updated, it may contain nodes that are no longer
         # heads.
         if closednodes is None:
             self._closednodes = set()
         else:
             self._closednodes = closednodes
 
     def _hashfiltered(self, repo):
         """build hash of revision filtered in the current cache
 
         Tracking tipnode and tiprev is not enough to ensure validity of the
         cache as they do not help to distinct cache that ignored various
         revision bellow tiprev.
 
         To detect such difference, we build a cache of all ignored revisions.
         """
         cl = repo.changelog
         if not cl.filteredrevs:
             return None
         key = None
         revs = sorted(r for r in cl.filteredrevs if r <= self.tiprev)
         if revs:
             s = util.sha1()
             for rev in revs:
                 s.update('%s;' % rev)
             key = s.digest()
         return key
 
     def validfor(self, repo):
         """Is the cache content valid regarding a repo
 
         - False when cached tipnode is unknown or if we detect a strip.
         - True when cache is up to date or a subset of current repo."""
         try:
             return ((self.tipnode == repo.changelog.node(self.tiprev))
                     and (self.filteredhash == self._hashfiltered(repo)))
         except IndexError:
             return False
 
     def _branchtip(self, heads):
         '''Return tuple with last open head in heads and false,
         otherwise return last closed head and true.'''
         tip = heads[-1]
         closed = True
         for h in reversed(heads):
             if h not in self._closednodes:
                 tip = h
                 closed = False
                 break
         return tip, closed
 
     def branchtip(self, branch):
         '''Return the tipmost open head on branch head, otherwise return the
         tipmost closed head on branch.
         Raise KeyError for unknown branch.'''
         return self._branchtip(self[branch])[0]
 
     def branchheads(self, branch, closed=False):
         heads = self[branch]
         if not closed:
             heads = [h for h in heads if h not in self._closednodes]
         return heads
 
     def iterbranches(self):
         for bn, heads in self.iteritems():
             yield (bn, heads) + self._branchtip(heads)
 
     def copy(self):
         """return an deep copy of the branchcache object"""
         return branchcache(self, self.tipnode, self.tiprev, self.filteredhash,
                            self._closednodes)
 
     def write(self, repo):
         try:
             f = repo.opener(_filename(repo), "w", atomictemp=True)
             cachekey = [hex(self.tipnode), str(self.tiprev)]
             if self.filteredhash is not None:
                 cachekey.append(hex(self.filteredhash))
             f.write(" ".join(cachekey) + '\n')
+            nodecount = 0
             for label, nodes in sorted(self.iteritems()):
                 for node in nodes:
+                    nodecount += 1
                     if node in self._closednodes:
                         state = 'c'
                     else:
                         state = 'o'
                     f.write("%s %s %s\n" % (hex(node), state,
                                             encoding.fromlocal(label)))
             f.close()
+            repo.ui.log('branchcache',
+                        'wrote %s branch cache with %d labels and %d nodes\n',
+                        repo.filtername, len(self), nodecount)
         except (IOError, OSError, util.Abort):
             # Abort may be raise by read only opener
             pass
 
     def update(self, repo, revgen):
         """Given a branchhead cache, self, that may have extra nodes or be
         missing heads, and a generator of nodes that are strictly a superset of
         heads missing, this function updates self to be correct.
         """
+        starttime = time.time()
         cl = repo.changelog
         # collect new branch entries
         newbranches = {}
         getbranchinfo = cl.branchinfo
         for r in revgen:
             branch, closesbranch = getbranchinfo(r)
             newbranches.setdefault(branch, []).append(r)
             if closesbranch:
                 self._closednodes.add(cl.node(r))
         # if older branchheads are reachable from new ones, they aren't
         # really branchheads. Note checking parents is insufficient:
         # 1 (branch a) -> 2 (branch b) -> 3 (branch a)
         for branch, newheadrevs in newbranches.iteritems():
             bheads = self.setdefault(branch, [])
             bheadset = set(cl.rev(node) for node in bheads)
 
             # This have been tested True on all internal usage of this function.
             # run it again in case of doubt
             # assert not (set(bheadrevs) & set(newheadrevs))
             newheadrevs.sort()
             bheadset.update(newheadrevs)
 
             # This loop prunes out two kinds of heads - heads that are
             # superseded by a head in newheadrevs, and newheadrevs that are not
             # heads because an existing head is their descendant.
             while newheadrevs:
                 latest = newheadrevs.pop()
                 if latest not in bheadset:
                     continue
                 ancestors = set(cl.ancestors([latest], min(bheadset)))
                 bheadset -= ancestors
             bheadrevs = sorted(bheadset)
             self[branch] = [cl.node(rev) for rev in bheadrevs]
             tiprev = bheadrevs[-1]
             if tiprev > self.tiprev:
                 self.tipnode = cl.node(tiprev)
                 self.tiprev = tiprev
 
         if not self.validfor(repo):
             # cache key are not valid anymore
             self.tipnode = nullid
             self.tiprev = nullrev
             for heads in self.values():
                 tiprev = max(cl.rev(node) for node in heads)
                 if tiprev > self.tiprev:
                     self.tipnode = cl.node(tiprev)
                     self.tiprev = tiprev
         self.filteredhash = self._hashfiltered(repo)
+
+        duration = time.time() - starttime
+        repo.ui.log('branchcache', 'updated %s branch cache in %.4f seconds\n',
+                    repo.filtername, duration)

tests/test-blackbox.t

@@ -1,166 +1,170 b''
 setup
   $ cat > mock.py <<EOF
   > from mercurial import util
   > 
   > def makedate():
   >     return 0, 0
   > def getuser():
   >     return 'bob'
   > # mock the date and user apis so the output is always the same
   > def uisetup(ui):
   >     util.makedate = makedate
   >     util.getuser = getuser
   > EOF
   $ cat >> $HGRCPATH <<EOF
   > [extensions]
   > blackbox=
   > mock=`pwd`/mock.py
   > mq=
   > EOF
   $ hg init blackboxtest
   $ cd blackboxtest
 
 command, exit codes, and duration
 
   $ echo a > a
   $ hg add a
   $ hg blackbox
   1970/01/01 00:00:00 bob> add a
   1970/01/01 00:00:00 bob> add a exited 0 after * seconds (glob)
 
 incoming change tracking
 
 create two heads to verify that we only see one change in the log later
   $ hg commit -ma
   $ hg up null
   0 files updated, 0 files merged, 1 files removed, 0 files unresolved
   $ echo b > b
   $ hg commit -Amb
   adding b
   created new head
 
 clone, commit, pull
   $ hg clone . ../blackboxtest2
   updating to branch default
   1 files updated, 0 files merged, 0 files removed, 0 files unresolved
   $ echo c > c
   $ hg commit -Amc
   adding c
   $ cd ../blackboxtest2
   $ hg pull
   pulling from $TESTTMP/blackboxtest (glob)
   searching for changes
   adding changesets
   adding manifests
   adding file changes
   added 1 changesets with 1 changes to 1 files
   (run 'hg update' to get a working copy)
-  $ hg blackbox -l 3
+  $ hg blackbox -l 5
   1970/01/01 00:00:00 bob> pull
+  1970/01/01 00:00:00 bob> updated served branch cache in ?.???? seconds (glob)
+  1970/01/01 00:00:00 bob> wrote served branch cache with 1 labels and 2 nodes
   1970/01/01 00:00:00 bob> 1 incoming changes - new heads: d02f48003e62
   1970/01/01 00:00:00 bob> pull exited 0 after * seconds (glob)
 
 we must not cause a failure if we cannot write to the log
 
   $ hg rollback
   repository tip rolled back to revision 1 (undo pull)
 
 #if unix-permissions no-root
   $ chmod 000 .hg/blackbox.log
   $ hg --debug incoming
   warning: cannot write to blackbox.log: Permission denied
   comparing with $TESTTMP/blackboxtest (glob)
   query 1; heads
   searching for changes
   all local heads known remotely
   changeset:   2:d02f48003e62c24e2659d97d30f2a83abe5d5d51
   tag:         tip
   phase:       draft
   parent:      1:6563da9dcf87b1949716e38ff3e3dfaa3198eb06
   parent:      -1:0000000000000000000000000000000000000000
   manifest:    2:ab9d46b053ebf45b7996f2922b9893ff4b63d892
   user:        test
   date:        Thu Jan 01 00:00:00 1970 +0000
   files+:      c
   extra:       branch=default
   description:
   c
   
   
 #endif
   $ hg pull
   pulling from $TESTTMP/blackboxtest (glob)
   searching for changes
   adding changesets
   adding manifests
   adding file changes
   added 1 changesets with 1 changes to 1 files
   (run 'hg update' to get a working copy)
 
 a failure reading from the log is fine
 #if unix-permissions no-root
   $ hg blackbox -l 3
   abort: Permission denied: $TESTTMP/blackboxtest2/.hg/blackbox.log
   [255]
 
   $ chmod 600 .hg/blackbox.log
 #endif
 
 backup bundles get logged
 
   $ touch d
   $ hg commit -Amd
   adding d
   created new head
   $ hg strip tip
   0 files updated, 0 files merged, 1 files removed, 0 files unresolved
   saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/*-backup.hg (glob)
-  $ hg blackbox -l 3
+  $ hg blackbox -l 5
   1970/01/01 00:00:00 bob> strip tip
   1970/01/01 00:00:00 bob> saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/*-backup.hg (glob)
+  1970/01/01 00:00:00 bob> updated base branch cache in ?.???? seconds (glob)
+  1970/01/01 00:00:00 bob> wrote base branch cache with 1 labels and 2 nodes
   1970/01/01 00:00:00 bob> strip tip exited 0 after * seconds (glob)
 
 tags cache gets logged
   $ hg up tip
   1 files updated, 0 files merged, 0 files removed, 0 files unresolved
   $ hg tag -m 'create test tag' test-tag
   $ hg tags
   tip                                3:5b5562c08298
   test-tag                           2:d02f48003e62
   $ hg blackbox -l 3
   1970/01/01 00:00:00 bob> resolved 1 tags cache entries from 1 manifests in ?.???? seconds (glob)
   1970/01/01 00:00:00 bob> writing tags cache file with 2 heads and 1 tags
   1970/01/01 00:00:00 bob> tags exited 0 after ?.?? seconds (glob)
 
 extension and python hooks - use the eol extension for a pythonhook
 
   $ echo '[extensions]' >> .hg/hgrc
   $ echo 'eol=' >> .hg/hgrc
   $ echo '[hooks]' >> .hg/hgrc
   $ echo 'update = echo hooked' >> .hg/hgrc
   $ hg update
   hooked
   0 files updated, 0 files merged, 0 files removed, 0 files unresolved
   $ hg blackbox -l 4
   1970/01/01 00:00:00 bob> update
   1970/01/01 00:00:00 bob> pythonhook-preupdate: hgext.eol.preupdate finished in * seconds (glob)
   1970/01/01 00:00:00 bob> exthook-update: echo hooked finished in * seconds (glob)
   1970/01/01 00:00:00 bob> update exited 0 after * seconds (glob)
 
 log rotation
 
   $ echo '[blackbox]' >> .hg/hgrc
   $ echo 'maxsize = 20 b' >> .hg/hgrc
   $ echo 'maxfiles = 3' >> .hg/hgrc
   $ hg status
   $ hg status
   $ hg status
   $ hg tip -q
   3:5b5562c08298
   $ ls .hg/blackbox.log*
   .hg/blackbox.log
   .hg/blackbox.log.1
   .hg/blackbox.log.2
 
 cleanup
   $ cd ..