[PATCH 2 of 2] branchmap: log events related to branch cache

[Gregory Szorc]

# HG changeset patch
# User Gregory Szorc <gregory.szorc at gmail.com>
# Date 1395533677 25200
#      Sat Mar 22 17:14:37 2014 -0700
# Node ID 9b587d73252ba742157d420b2f011de7e9a19bf7
# Parent  952eba9f19300bbf7e4d7cf85f277bec7d37472d
branchmap: log events related to branch cache

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

diff --git a/mercurial/branchmap.py b/mercurial/branchmap.py
--- a/mercurial/branchmap.py
+++ b/mercurial/branchmap.py
@@ -3,16 +3,17 @@
 # Copyright 2005-2007 Matt Mackall <mpm at selenic.com>
 #
 # 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
 
@@ -201,34 +202,40 @@ class branchcache(dict):
 
     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:
@@ -267,8 +274,12 @@ class branchcache(dict):
             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 %.2f seconds\n',
+                    repo.filtername, duration)
diff --git a/tests/test-blackbox.t b/tests/test-blackbox.t
--- a/tests/test-blackbox.t
+++ b/tests/test-blackbox.t
@@ -50,18 +50,20 @@ clone, commit, pull
   $ 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)
 
@@ -110,19 +112,21 @@ 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