branchmap: log events related to branch cache

branchmap: log events related to branch cache

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

--- a/mercurial/branchmap.py	Mon Apr 14 11:50:05 2014 -0700
+++ b/mercurial/branchmap.py	Sat Mar 22 17:14:37 2014 -0700
@@ -8,6 +8,7 @@
 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"""
@@ -206,8 +207,10 @@
             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:
@@ -215,6 +218,9 @@
                     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
@@ -224,6 +230,7 @@
         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 = {}
@@ -272,3 +279,7 @@
                     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)

--- a/tests/test-blackbox.t	Mon Apr 14 11:50:05 2014 -0700
+++ b/tests/test-blackbox.t	Sat Mar 22 17:14:37 2014 -0700
@@ -55,8 +55,10 @@
   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)
 
@@ -115,9 +117,11 @@
   $ 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