Patchwork [1,of,2] tags: log events related to tags cache

diff --git a/mercurial/tags.py b/mercurial/tags.py
--- a/mercurial/tags.py
+++ b/mercurial/tags.py
@@ -10,16 +10,17 @@ 
 # Eventually, it could take care of updating (adding/removing/moving)
 # tags too.
 
 from node import nullid, bin, hex, short
 from i18n import _
 import encoding
 import error
 import errno
+import time
 
 def findglobaltags(ui, repo, alltags, tagtypes):
     '''Find global tags in repo by reading .hgtags from every head that
     has a distinct version of it, using a cache to avoid excess work.
     Updates the dicts alltags, tagtypes in place: alltags maps tag name
     to (node, hist) pair (see _readtags() below), and tagtypes maps tag
     name to tag type ("global" in this case).'''
     # This is so we can be lazy and assume alltags contains only global
@@ -229,16 +230,18 @@  def _readtagcache(ui, repo):
 
     # N.B. in case 4 (nodes destroyed), "new head" really means "newly
     # exposed".
     if not len(repo.file('.hgtags')):
         # No tags have ever been committed, so we can avoid a
         # potentially expensive search.
         return (repoheads, cachefnode, None, True)
 
+    starttime = time.time()
+
     newheads = [head
                 for head in repoheads
                 if head not in set(cacheheads)]
 
     # Now we have to lookup the .hgtags filenode for every new head.
     # This is the most expensive part of finding tags, so performance
     # depends primarily on the size of newheads.  Worst case: no cache
     # file, so newheads == repoheads.
@@ -246,27 +249,36 @@  def _readtagcache(ui, repo):
         cctx = repo[head]
         try:
             fnode = cctx.filenode('.hgtags')
             cachefnode[head] = fnode
         except error.LookupError:
             # no .hgtags file on this head
             pass
 
+    duration = time.time() - starttime
+    ui.log('tagscache',
+           'resolved %d tags cache entries from %d manifests in %0.2f '
+           'seconds\n',
+           len(cachefnode), len(newheads), duration)
+
     # Caller has to iterate over all heads, but can use the filenodes in
     # cachefnode to get to each .hgtags revision quickly.
     return (repoheads, cachefnode, None, True)
 
 def _writetagcache(ui, repo, heads, tagfnode, cachetags):
 
     try:
         cachefile = repo.opener('cache/tags', 'w', atomictemp=True)
     except (OSError, IOError):
         return
 
+    ui.log('tagscache', 'writing tags cache file with %d heads and %d tags\n',
+            len(heads), len(cachetags))
+
     realheads = repo.heads()            # for sanity checks below
     for head in heads:
         # temporary sanity checks; these can probably be removed
         # once this code has been in crew for a few weeks
         assert head in repo.changelog.nodemap, \
                'trying to write non-existent node %s to tag cache' % short(head)
         assert head in realheads, \
                'trying to write non-head %s to tag cache' % short(head)
diff --git a/tests/test-blackbox.t b/tests/test-blackbox.t
--- a/tests/test-blackbox.t
+++ b/tests/test-blackbox.t
@@ -115,40 +115,52 @@  backup bundles get logged
   $ 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
   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> 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
-  1 files updated, 0 files merged, 0 files removed, 0 files unresolved
+  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
-  2:d02f48003e62
+  3:5b5562c08298
   $ ls .hg/blackbox.log*
   .hg/blackbox.log
   .hg/blackbox.log.1
   .hg/blackbox.log.2
 
 cleanup
   $ cd ..