Merge lp:~ian-clatworthy/bzr/log-show-custom into lp:~bzr/bzr/trunk-old

[Ian Clatworthy]

[Ian Clatworthy (ian-clatworthy)]

It turns out that checking for custom properties when logging, particularly checking for foreign VCS properties, is pretty expensive. This patch switches their display off by default and introduces a new option to enable them: --show-custom. If that's considered heavy-handed, we could find a smarter way to skip foreign VCS property calculation (I couldn't see a way given the current algorithm) or make the option --show-foreign, leaving non-foreign custom properties on by default.

On OpenOffice.org with 260K revisions, this patch reduces the time by 10% from 50 seconds to 45 seconds. This improvement complements my faster-log branch: together they reduce the overall time from 50+ seconds to 41 seconds.

[Martin Pool (mbp)]

2009/5/25 Ian Clatworthy <email address hidden>:
> Ian Clatworthy has proposed merging lp:~ian-clatworthy/bzr/log-show-custom into lp:bzr.
>
> Requested reviews:
>    bzr-core (bzr-core)
>
> It turns out that checking for custom properties when logging, particularly checking for foreign VCS properties, is pretty expensive. This patch switches their display off by default and introduces a new option to enable them: --show-custom. If that's considered heavy-handed, we could find a smarter way to skip foreign VCS property calculation (I couldn't see a way given the current algorithm) or make the option --show-foreign, leaving non-foreign custom properties on by default.

I think that's reasonable.

It's the kind of case where it might be nice for people to be able to
set the option on other than by aliasing the command. (Though
aliasing it is an adequate standby.)

--
Martin <http://launchpad.net/~mbp/>

[John A Meinel (jameinel)]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Martin Pool wrote:
> 2009/5/25 Ian Clatworthy <email address hidden>:
>> Ian Clatworthy has proposed merging lp:~ian-clatworthy/bzr/log-show-custom into lp:bzr.
>>
>> Requested reviews:
>> bzr-core (bzr-core)
>>
>> It turns out that checking for custom properties when logging, particularly checking for foreign VCS properties, is pretty expensive. This patch switches their display off by default and introduces a new option to enable them: --show-custom. If that's considered heavy-handed, we could find a smarter way to skip foreign VCS property calculation (I couldn't see a way given the current algorithm) or make the option --show-foreign, leaving non-foreign custom properties on by default.
>
> I think that's reasonable.
>
> It's the kind of case where it might be nice for people to be able to
> set the option on other than by aliasing the command. (Though
> aliasing it is an adequate standby.)
>

I think it would be worthwhile to figure out why this is so expensive.
In general, it seems like it should just be a single dict lookup to see
if a given property exists, which doesn't seem particularly expensive.

Is it just an inefficient check in bzr-svn, or is it something about the
API that makes it inefficient? (Such as passing the revision id, rather
than the Revision object, etc.)

John
=:->

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iEYEARECAAYFAkoaSUQACgkQJdeBCYSNAANo1gCgkBu6/3hvodqv1B58Hb2rG3RN
24oAoKAFUkMLGQs3/AVnT3Ed6End04EM
=+5+n
-----END PGP SIGNATURE-----

[Ian Clatworthy (ian-clatworthy)]

John A Meinel wrote:
> I think it would be worthwhile to figure out why this is so expensive.
> In general, it seems like it should just be a single dict lookup to see
> if a given property exists, which doesn't seem particularly expensive.
>
> Is it just an inefficient check in bzr-svn, or is it something about the
> API that makes it inefficient? (Such as passing the revision id, rather
> than the Revision object, etc.)
>
It's slow for 2 reasons:

1. a custom property handler is *always* registered for calculating
    foreign properties. So simply testing if the registry is empty isn't
   good enough to short-circuit the normal processing loop.

2. bzrlib/foreign.show_foreign_properties() tries to pull apart
    *every* revision-id to see if it came from a foreign source.

Over 250K revisions, these effects add up with the second one being
particularly expensive. It would be nice if there was a single check we
could do (per branch or repo say) to decide whether to do the above but
I can't see how we can, given the possibility that just a few revisions
here or there (in a merge say) came from a foreign source. Hence my
suggestion that they be switched off by default, so only users
interested in them pay the cost.

BTW, hg has a nice feature where options can be configured per command
per branch (by adding sections to their branch-specific config file). I
think that sort of flexibility is useful in case like this (so that
those working with foreign branches can enable --show-custom by default
when they care without going as far as a per user alias). Just a thought.

Ian C.

[Jelmer Vernooij (jelmer)]

> It turns out that checking for custom properties when logging, particularly
> checking for foreign VCS properties, is pretty expensive. This patch switches
> their display off by default and introduces a new option to enable them:
> --show-custom. If that's considered heavy-handed, we could find a smarter way
> to skip foreign VCS property calculation (I couldn't see a way given the
> current algorithm) or make the option --show-foreign, leaving non-foreign
> custom properties on by default.
>
> On OpenOffice.org with 260K revisions, this patch reduces the time by 10% from
> 50 seconds to 45 seconds. This improvement complements my faster-log branch:
> together they reduce the overall time from 50+ seconds to 41 seconds.
At least when run against a foreign repository itself, we know directly which function to use. This would mean we need some extra state in log so we couldn't just use a "standard" custom revision property display hook but we should be able to at least show foreign ids when run directly against a foreign repo.

[Jelmer Vernooij (jelmer)]

I think we can improve the performance of this without introducing a new argument.

I've discussed this on IRC with igc; I'll have a look at providing an alternative implementation that is faster.

review: Needs Fixing

[Ian Clatworthy (ian-clatworthy)]

> I think we can improve the performance of this without introducing a new
> argument.
>
> I've discussed this on IRC with igc; I'll have a look at providing an
> alternative implementation that is faster.

Cool. I'll mark this merge proposal as 'work in progress' accordingly. After you're done, we can see whether the option still has value or not in forcing a particular behaviour.

[Jelmer Vernooij (jelmer)]

> > I think we can improve the performance of this without introducing a new
> > argument.
> >
> > I've discussed this on IRC with igc; I'll have a look at providing an
> > alternative implementation that is faster.
>
> Cool. I'll mark this merge proposal as 'work in progress' accordingly. After
> you're done, we can see whether the option still has value or not in forcing a
> particular behaviour.
The performance improvements for foreign vcs fields in log have landed. Is this still a problem for log, or can this review be marked superseded?

[Jelmer Vernooij (jelmer)]

> > I think we can improve the performance of this without introducing a new
> > argument.
> >
> > I've discussed this on IRC with igc; I'll have a look at providing an
> > alternative implementation that is faster.
>
> Cool. I'll mark this merge proposal as 'work in progress' accordingly. After
> you're done, we can see whether the option still has value or not in forcing a
> particular behaviour.
The performance improvements for foreign vcs fields in log have landed. Is this still a problem for log, or can this review be marked superseded?

Unmerged revisions

4380. By Ian Clatworthy on 2009-05-25

log --show-custom

4379. By Canonical.com Patch Queue Manager <email address hidden> on 2009-05-23

(tanner) merge 1.15final back to trunk

4378. By Canonical.com Patch Queue Manager <email address hidden> on 2009-05-22

(igc) faster branch in a shared repo for dev6rr format (Ian
 Clatworthy)

4377. By Canonical.com Patch Queue Manager <email address hidden> on 2009-05-22

(igc) make branch --no-tree faster (Ian Clatworthy)

4376. By Canonical.com Patch Queue Manager <email address hidden> on 2009-05-21

(Jelmer) Return BranchPushResult from InterBranch.lossy_push().

4375. By Canonical.com Patch Queue Manager <email address hidden> on 2009-05-21

(Jelmer) Add child_submit_format option used by 'bzr send'.

4374. By Canonical.com Patch Queue Manager <email address hidden> on 2009-05-20

(abentley) Enable committing from a PreviewTree.

4373. By Canonical.com Patch Queue Manager <email address hidden> on 2009-05-20

(Jelmer) Mention --default-rich-root rather than a particular format
 in the user guide.

4372. By Canonical.com Patch Queue Manager <email address hidden> on 2009-05-18

(igc) added osutils.parent_directories() (Ian Clatworthy)

4371. By Canonical.com Patch Queue Manager <email address hidden> on 2009-05-17

(Jelmer) Make dpush help/error a bit more generic.

=== modified file 'NEWS'
--- NEWS	2009-08-04 17:52:34 +0000
+++ NEWS	2009-08-04 20:40:40 +0000
@@ -13,6 +13,10 @@
 Compatibility Breaks
 ********************
 
+* ``bzr log`` now hides custom/foreign properties by default.
+  To display them, use the new ``--show-custom`` option.
+  (Ian Clatworthy)
+
 New Features
 ************
 
 
=== modified file 'bzrlib/builtins.py'
--- bzrlib/builtins.py	2009-07-27 06:22:57 +0000
+++ bzrlib/builtins.py	2009-08-04 20:40:40 +0000
@@ -2221,6 +2221,8 @@
                    help='Show changes made in each revision as a patch.'),
             Option('include-merges',
                    help='Show merged revisions like --levels 0 does.'),
+            Option('show-custom',
+                   help='Show custom/foreign properties.'),
             ]
     encoding_type = 'replace'
 
@@ -2236,7 +2238,8 @@
             message=None,
             limit=None,
             show_diff=False,
-            include_merges=False):
+            include_merges=False,
+            show_custom=False):
         from bzrlib.log import (
             Logger,
             make_log_request_dict,
@@ -2312,7 +2315,8 @@
                             show_timezone=timezone,
                             delta_format=get_verbosity_level(),
                             levels=levels,
-                            show_advice=levels is None)
+                            show_advice=levels is None,
+                            show_custom=show_custom)
 
             # Choose the algorithm for doing the logging. It's annoying
             # having multiple code paths like this but necessary until
 
=== modified file 'bzrlib/log.py'
--- bzrlib/log.py	2009-06-10 03:56:49 +0000
+++ bzrlib/log.py	2009-08-04 20:40:40 +0000
@@ -1291,7 +1291,8 @@
     preferred_levels = 0
 
     def __init__(self, to_file, show_ids=False, show_timezone='original',
-                 delta_format=None, levels=None, show_advice=False):
+                 delta_format=None, levels=None, show_advice=False,
+                 show_custom=True):
         """Create a LogFormatter.
 
         :param to_file: the file to output to
@@ -1303,6 +1304,8 @@
           let the log formatter decide.
         :param show_advice: whether to show advice at the end of the
           log or not
+        :param show_custom: whether to show custom properties like
+          foreign VCS revision ids
         """
         self.to_file = to_file
         # 'exact' stream used to show diff, it should print content 'as is'
@@ -1317,6 +1320,7 @@
         self.levels = levels
         self._show_advice = show_advice
         self._merge_count = 0
+        self._show_custom = show_custom
 
     def get_levels(self):
         """Get the number of levels to display or 0 for all."""
@@ -1397,12 +1401,19 @@
 
         If a registered handler raises an error it is propagated.
         """
+<<<<<<< TREE
         for key, handler in properties_handler_registry.iteritems():
             self._write_properties(indent, handler(revision))
 
     def _write_properties(self, indent, properties):
         for key, value in properties.items():
             self.to_file.write(indent + key + ': ' + value + '\n')
+=======
+        if self._show_custom:
+            for key, handler in properties_handler_registry.iteritems():
+                for key, value in handler(revision).items():
+                    self.to_file.write(indent + key + ': ' + value + '\n')
+>>>>>>> MERGE-SOURCE
 
     def show_diff(self, to_file, diff, indent):
         for l in diff.rstrip().split('\n'):
 
=== modified file 'bzrlib/tests/blackbox/test_log.py'
--- bzrlib/tests/blackbox/test_log.py	2009-06-10 03:56:49 +0000
+++ bzrlib/tests/blackbox/test_log.py	2009-08-04 20:40:40 +0000
@@ -329,6 +329,15 @@
                            ['log', '--timezone', 'foo'])
 
 
+class TestLogCustomProperties(TestLog):
+
+    def test_log_custom_properties(self):
+        # Test --show-custom is legal. Actually formatting tested elsewhere
+        self.make_minimal_branch()
+        out, err = self.run_bzr(['log', '--show-custom'])
+        self.assertEqual('', err)
+
+
 class TestLogVerbose(TestLog):
 
     def setUp(self):
 
=== modified file 'bzrlib/tests/test_log.py'
--- bzrlib/tests/test_log.py	2009-05-08 13:39:32 +0000
+++ bzrlib/tests/test_log.py	2009-08-04 20:40:40 +0000
@@ -685,34 +685,37 @@
 ''',
                              sio.getvalue())
 
+    def get_log_with_properties(self, formatter):
+        wt = self.make_branch_and_tree('.')
+        b = wt.branch
+        self.build_tree(['a'])
+        wt.add('a')
+        b.nick = 'test_properties_in_log'
+        wt.commit(message='add a',
+                  timestamp=1132711707,
+                  timezone=36000,
+                  committer='Lorem Ipsum <[e-mail]>',
+                  authors=['John Doe <[e-mail]>'])
+        try:
+            def trivial_custom_prop_handler(revision):
+                return {'test_prop':'test_value'}
+
+            log.properties_handler_registry.register(
+                'trivial_custom_prop_handler',
+                trivial_custom_prop_handler)
+            log.show_log(b, formatter)
+        finally:
+            log.properties_handler_registry.remove(
+                'trivial_custom_prop_handler')
+
     def test_properties_in_log(self):
         """Log includes the custom properties returned by the registered
         handlers.
         """
-        wt = self.make_branch_and_tree('.')
-        b = wt.branch
-        self.build_tree(['a'])
-        wt.add('a')
-        b.nick = 'test_properties_in_log'
-        wt.commit(message='add a',
-                  timestamp=1132711707,
-                  timezone=36000,
-                  committer='Lorem Ipsum <[e-mail]>',
-                  authors=['John Doe <[e-mail]>'])
         sio = StringIO()
         formatter = log.LongLogFormatter(to_file=sio)
-        try:
-            def trivial_custom_prop_handler(revision):
-                return {'test_prop':'test_value'}
-
-            log.properties_handler_registry.register(
-                'trivial_custom_prop_handler',
-                trivial_custom_prop_handler)
-            log.show_log(b, formatter)
-        finally:
-            log.properties_handler_registry.remove(
-                'trivial_custom_prop_handler')
-            self.assertEqualDiff('''\
+        self.get_log_with_properties(formatter)
+        self.assertEqualDiff('''\
 ------------------------------------------------------------
 revno: 1
 test_prop: test_value
@@ -722,43 +725,52 @@
 timestamp: Wed 2005-11-23 12:08:27 +1000
 message:
   add a
-''',
-                                 sio.getvalue())
+''', sio.getvalue())
 
     def test_properties_in_short_log(self):
         """Log includes the custom properties returned by the registered
         handlers.
         """
-        wt = self.make_branch_and_tree('.')
-        b = wt.branch
-        self.build_tree(['a'])
-        wt.add('a')
-        b.nick = 'test_properties_in_short_log'
-        wt.commit(message='add a',
-                  timestamp=1132711707,
-                  timezone=36000,
-                  committer='Lorem Ipsum <[e-mail]>',
-                  authors=['John Doe <[e-mail]>'])
         sio = StringIO()
         formatter = log.ShortLogFormatter(to_file=sio)
-        try:
-            def trivial_custom_prop_handler(revision):
-                return {'test_prop':'test_value'}
-
-            log.properties_handler_registry.register(
-                'trivial_custom_prop_handler',
-                trivial_custom_prop_handler)
-            log.show_log(b, formatter)
-        finally:
-            log.properties_handler_registry.remove(
-                'trivial_custom_prop_handler')
-            self.assertEqualDiff('''\
+        self.get_log_with_properties(formatter)
+        self.assertEqualDiff('''\
     1 John Doe\t2005-11-23
       test_prop: test_value
       add a
 
-''',
-                                 sio.getvalue())
+''', sio.getvalue())
+
+    def test_properties_in_log_off(self):
+        """Log excludes the custom properties returned by the registered
+        handlers.
+        """
+        sio = StringIO()
+        formatter = log.LongLogFormatter(to_file=sio, show_custom=False)
+        self.get_log_with_properties(formatter)
+        self.assertEqualDiff('''\
+------------------------------------------------------------
+revno: 1
+author: John Doe <[e-mail]>
+committer: Lorem Ipsum <[e-mail]>
+branch nick: test_properties_in_log
+timestamp: Wed 2005-11-23 12:08:27 +1000
+message:
+  add a
+''', sio.getvalue())
+
+    def test_properties_in_short_log_off(self):
+        """Log excludes the custom properties returned by the registered
+        handlers.
+        """
+        sio = StringIO()
+        formatter = log.ShortLogFormatter(to_file=sio, show_custom=False)
+        self.get_log_with_properties(formatter)
+        self.assertEqualDiff('''\
+    1 John Doe\t2005-11-23
+      add a
+
+''', sio.getvalue())
 
     def test_error_in_properties_handler(self):
         """Log includes the custom properties returned by the registered