Merge lp:~ian-clatworthy/bzr/faster-log.old into lp:~bzr/bzr/trunk-old

[Ian Clatworthy]

[Ian Clatworthy (ian-clatworthy)]

This patch makes log --long faster by around 10%. For OpenOffice.org with 260K revisions, the time drops from 50 seconds to 46 seconds.

[John A Meinel (jameinel)]

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

Ian Clatworthy wrote:
> Ian Clatworthy has proposed merging lp:~ian-clatworthy/bzr/faster-log into lp:bzr.
>
> Requested reviews:
> bzr-core (bzr-core)
>
> This patch makes log --long faster by around 10%. For OpenOffice.org with 260K revisions, the time drops from 50 seconds to 46 seconds.
>

I'll try to give a bit of a summary as to why I think this is faster,
though it would be nice if you would give a similar summary when submitting.

1) Pull things like
+ levels = rqst.get('levels')
+ limit = rqst.get('limit')
+ diff_type = rqst.get('diff_type')

Out of the inner loops, and set the variable once at the outside. This
also handles stuff like using an if in the inner loop rather than a
function call:

+ if diff_type is None:
+ diff = None
+ else:
+ diff = self._format_diff(rev, rev_id, diff_type)

2) Factor out "custom_properties" into a re-used helper function.

3) Add a new function: format_date_with_offset_in_original_timezone

4) Change log_revision(self, revision)

so that rather than calling outfile.write() for every line of the
revision, batching it up into a list, and then using ('\n' +
indent).join(lines) and writing that out as a single string.

IMO the batching of everything for one revision seems just about right.

I'm a bit concerned, though, about handling Unicode Author names and
UTF-8 'diff' strings. My guess is that this actually breaks it, and we
just don't know it yet.

Can you please ensure that we have a test with non-ascii file content
(even better if it isn't even UTF-8 since we don't assert anything about
file content encoding), and then also include a non-ascii Author name.
That ensures that we want to output Unicode for the name, and something
random for the diff content.

5) I'm a bit curious about this:
=== modified file 'bzrlib/osutils.py'
- --- bzrlib/osutils.py 2009-05-23 04:55:52 +0000
+++ bzrlib/osutils.py 2009-05-25 05:46:01 +0000
@@ -686,6 +686,8 @@
     return offset.days * 86400 + offset.seconds

 weekdays = ['Mon', 'Tue', 'Wed', 'Thu', 'Fri', 'Sat', 'Sun']
+_default_format_by_weekday_num = [wd + " %Y-%m-%d %H:%M:%S" for wd in
weekdays]
+

^- Does this mean that we are skipping localization? So someone with
de_DE.UTF-8 will no longer see the German short-names for days of the week?

+def format_date_with_offset_in_original_timezone(t, offset=0,
+ _cache=_offset_cache):
+ """Return a formatted date string in the original timezone.
+
+ This routine may be faster then format_date.
+
+ :param t: Seconds since the epoch.
+ :param offset: Timezone offset in seconds east of utc.
+ """
+ if offset is None:
+ offset = 0
+ tt = time.gmtime(t + offset)
+ date_fmt = _default_format_by_weekday_num[tt[6]]
+ date_str = time.strftime(date_fmt, tt)
+ offset_str = _cache.get(offset, None)
+ if offset_str is None:
+ offset_str = ' %+03d%02d' % (offset / 3600, (offset / 60) % 60)
+ _cache[offset] = offset_str
+ return date_str + offset_str
+

^- I wonder if it might be faster to include the offset_str inside the
'date_fm...

[John A Meinel (jameinel)]

Ian Clatworthy wrote:
> Ian Clatworthy has proposed merging lp:~ian-clatworthy/bzr/faster-log into lp:bzr.
>
> Requested reviews:
> bzr-core (bzr-core)
>
> This patch makes log --long faster by around 10%. For OpenOffice.org with 260K revisions, the time drops from 50 seconds to 46 seconds.
>

I'll try to give a bit of a summary as to why I think this is faster,
though it would be nice if you would give a similar summary when submitting.

1) Pull things like
+ levels = rqst.get('levels')
+ limit = rqst.get('limit')
+ diff_type = rqst.get('diff_type')

Out of the inner loops, and set the variable once at the outside. This
also handles stuff like using an if in the inner loop rather than a
function call:

+ if diff_type is None:
+ diff = None
+ else:
+ diff = self._format_diff(rev, rev_id, diff_type)

2) Factor out "custom_properties" into a re-used helper function.

3) Add a new function: format_date_with_offset_in_original_timezone

4) Change log_revision(self, revision)

so that rather than calling outfile.write() for every line of the
revision, batching it up into a list, and then using ('\n' +
indent).join(lines) and writing that out as a single string.

IMO the batching of everything for one revision seems just about right.

I'm a bit concerned, though, about handling Unicode Author names and
UTF-8 'diff' strings. My guess is that this actually breaks it, and we
just don't know it yet.

Can you please ensure that we have a test with non-ascii file content
(even better if it isn't even UTF-8 since we don't assert anything about
file content encoding), and then also include a non-ascii Author name.
That ensures that we want to output Unicode for the name, and something
random for the diff content.

5) I'm a bit curious about this:
=== modified file 'bzrlib/osutils.py'
--- bzrlib/osutils.py 2009-05-23 04:55:52 +0000
+++ bzrlib/osutils.py 2009-05-25 05:46:01 +0000
@@ -686,6 +686,8 @@
     return offset.days * 86400 + offset.seconds

 weekdays = ['Mon', 'Tue', 'Wed', 'Thu', 'Fri', 'Sat', 'Sun']
+_default_format_by_weekday_num = [wd + " %Y-%m-%d %H:%M:%S" for wd in
weekdays]
+

^- Does this mean that we are skipping localization? So someone with
de_DE.UTF-8 will no longer see the German short-names for days of the week?

+def format_date_with_offset_in_original_timezone(t, offset=0,
+ _cache=_offset_cache):
+ """Return a formatted date string in the original timezone.
+
+ This routine may be faster then format_date.
+
+ :param t: Seconds since the epoch.
+ :param offset: Timezone offset in seconds east of utc.
+ """
+ if offset is None:
+ offset = 0
+ tt = time.gmtime(t + offset)
+ date_fmt = _default_format_by_weekday_num[tt[6]]
+ date_str = time.strftime(date_fmt, tt)
+ offset_str = _cache.get(offset, None)
+ if offset_str is None:
+ offset_str = ' %+03d%02d' % (offset / 3600, (offset / 60) % 60)
+ _cache[offset] = offset_str
+ return date_str + offset_str
+

^- I wonder if it might be faster to include the offset_str inside the
'date_fmt' string, since it would require one less string...

[Ian Clatworthy (ian-clatworthy)]

John A Meinel wrote:
> I'll try to give a bit of a summary as to why I think this is faster,
> though it would be nice if you would give a similar summary when submitting.
>
>
[snip]
That's an excellent summary - thanks.
> IMO the batching of everything for one revision seems just about right.
>
> I'm a bit concerned, though, about handling Unicode Author names and
> UTF-8 'diff' strings. My guess is that this actually breaks it, and we
> just don't know it yet.
>
> Can you please ensure that we have a test with non-ascii file content
> (even better if it isn't even UTF-8 since we don't assert anything about
> file content encoding), and then also include a non-ascii Author name.
> That ensures that we want to output Unicode for the name, and something
> random for the diff content.
>
I'm confident diff strings are handled correctly because Alexander
submitted a bug fixing this for 1.13. Note that diff strings aren't
written to self.to_file (in the code), but to a wrapped version thereof.

I suspect we do have tests for Unicode authors but I'll confirm that
(probably tomorrow).
> 5) I'm a bit curious about this:
> === modified file 'bzrlib/osutils.py'
> --- bzrlib/osutils.py 2009-05-23 04:55:52 +0000
> +++ bzrlib/osutils.py 2009-05-25 05:46:01 +0000
> @@ -686,6 +686,8 @@
> return offset.days * 86400 + offset.seconds
>
> weekdays = ['Mon', 'Tue', 'Wed', 'Thu', 'Fri', 'Sat', 'Sun']
> +_default_format_by_weekday_num = [wd + " %Y-%m-%d %H:%M:%S" for wd in
> weekdays]
> +
>
> ^- Does this mean that we are skipping localization? So someone with
> de_DE.UTF-8 will no longer see the German short-names for days of the week?
>
Yes it does. There's a separate function - format_local_date IIRC - that
doesn't use English day names. I'll run annotate and find out why we're
doing this but, at a wild guess, it might be related to ensuring tests
pass regardless of locale?

FWIW, I'm *not* changing current behaviour here. If we what to
change/fix the code, I'd like to make that a separate patch if that's OK.

Ian C.

[Ian Clatworthy (ian-clatworthy)]

So checking our existing test coverage, we have log tests for unicode messages and unicode diff content but not for unicode committer/authors. Do I need to add those before landing this? My preference is to put that task on my list but not do it immediately, given all I'm doing is replacing "multiple outf.write()" calls with "collecting lines & calling outf.write() once". I can't see how that can break things or how it reduces test coverage?

Otherwise, your suggested tweaks are fine by me.

[Martin Pool (mbp)]

2009/5/29 Ian Clatworthy <email address hidden>:
> So checking our existing test coverage, we have log tests for unicode messages and unicode diff content but not for unicode committer/authors. Do I need to add those before landing this? My preference is to put that task on my list but not do it immediately, given all I'm doing is replacing "multiple outf.write()" calls with "collecting lines & calling outf.write() once". I can't see how that can break things or how it reduces test coverage?

It's down to you, but I think those tests will be fairly easy to
write, and it's probably better not to have it hanging around.

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

=== modified file 'NEWS'
--- NEWS	2009-08-30 23:51:10 +0000
+++ NEWS	2009-08-31 04:38:13 +0000
@@ -972,6 +972,8 @@
   (Alexander Belchenko, Jelmer Vernooij, John Arbash Meinel)
 
 
+* ``bzr log`` is now faster. (Ian Clatworthy)
+
 Bug Fixes
 *********
 
 
=== modified file 'bzrlib/log.py'
--- bzrlib/log.py	2009-06-10 03:56:49 +0000
+++ bzrlib/log.py	2009-08-31 04:38:13 +0000
@@ -83,6 +83,7 @@
     )
 from bzrlib.osutils import (
     format_date,
+    format_date_with_offset_in_original_timezone,
     get_terminal_encoding,
     re_compile_checked,
     terminal_width,
@@ -384,27 +385,28 @@
         :return: An iterator yielding LogRevision objects.
         """
         rqst = self.rqst
+        levels = rqst.get('levels')
+        limit = rqst.get('limit')
+        diff_type = rqst.get('diff_type')
         log_count = 0
         revision_iterator = self._create_log_revision_iterator()
         for revs in revision_iterator:
             for (rev_id, revno, merge_depth), rev, delta in revs:
                 # 0 levels means show everything; merge_depth counts from 0
-                levels = rqst.get('levels')
                 if levels != 0 and merge_depth >= levels:
                     continue
-                diff = self._format_diff(rev, rev_id)
+                if diff_type is None:
+                    diff = None
+                else:
+                    diff = self._format_diff(rev, rev_id, diff_type)
                 yield LogRevision(rev, revno, merge_depth, delta,
                     self.rev_tag_dict.get(rev_id), diff)
-                limit = rqst.get('limit')
                 if limit:
                     log_count += 1
                     if log_count >= limit:
                         return
 
-    def _format_diff(self, rev, rev_id):
-        diff_type = self.rqst.get('diff_type')
-        if diff_type is None:
-            return None
+    def _format_diff(self, rev, rev_id, diff_type):
         repo = self.branch.repository
         if len(rev.parent_ids) == 0:
             ancestor_id = _mod_revision.NULL_REVISION
@@ -1291,7 +1293,7 @@
     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):
         """Create a LogFormatter.
 
         :param to_file: the file to output to
@@ -1367,48 +1369,64 @@
         else:
             return ''
 
-    def show_foreign_info(self, rev, indent):
+    def show_properties(self, revision, indent):
+        """Displays the custom properties returned by each registered handler.
+
+        If a registered handler raises an error it is propagated.
+        """
+        for line in self.custom_properties(revision):
+            self.to_file.write("%s%s\n" % (indent, line))
+
+    def custom_properties(self, revision):
+        """Format the custom properties returned by each registered handler.
+
+        If a registered handler raises an error it is propagated.
+
+        :return: a list of formatted lines (excluding trailing newlines)
+        """
+        lines = self._foreign_info_properties(revision)
+        for key, handler in properties_handler_registry.iteritems():
+            lines.extend(self._format_properties(handler(revision)))
+        return lines
+
+    def _foreign_info_properties(self, rev):
         """Custom log displayer for foreign revision identifiers.
 
         :param rev: Revision object.
         """
         # Revision comes directly from a foreign repository
         if isinstance(rev, foreign.ForeignRevision):
-            self._write_properties(indent, rev.mapping.vcs.show_foreign_revid(
-                rev.foreign_revid))
-            return
+            return rev.mapping.vcs.show_foreign_revid(rev.foreign_revid)
 
         # Imported foreign revision revision ids always contain :
         if not ":" in rev.revision_id:
-            return
+            return []
 
         # Revision was once imported from a foreign repository
         try:
             foreign_revid, mapping = \
                 foreign.foreign_vcs_registry.parse_revision_id(rev.revision_id)
         except errors.InvalidRevisionId:
-            return
+            return []
 
-        self._write_properties(indent, 
+        return self._format_properties(
             mapping.vcs.show_foreign_revid(foreign_revid))
 
-    def show_properties(self, revision, indent):
-        """Displays the custom properties returned by each registered handler.
-
-        If a registered handler raises an error it is propagated.
-        """
-        for key, handler in properties_handler_registry.iteritems():
-            self._write_properties(indent, handler(revision))
-
-    def _write_properties(self, indent, properties):
+    def _format_properties(self, properties):
+        lines = []
         for key, value in properties.items():
-            self.to_file.write(indent + key + ': ' + value + '\n')
+            lines.append(key + ': ' + value)
+        return lines
 
     def show_diff(self, to_file, diff, indent):
         for l in diff.rstrip().split('\n'):
             to_file.write(indent + '%s\n' % (l,))
 
 
+# Separator between revisions in long format
+_LONG_SEP = '-' * 60
+
+
 class LongLogFormatter(LogFormatter):
 
     supports_merge_revisions = True
@@ -1417,46 +1435,59 @@
     supports_tags = True
     supports_diff = True
 
+    def __init__(self, *args, **kwargs):
+        super(LongLogFormatter, self).__init__(*args, **kwargs)
+        if self.show_timezone == 'original':
+            self.date_string = self._date_string_original_timezone
+        else:
+            self.date_string = self._date_string_with_timezone
+
+    def _date_string_with_timezone(self, rev):
+        return format_date(rev.timestamp, rev.timezone or 0,
+                           self.show_timezone)
+
+    def _date_string_original_timezone(self, rev):
+        return format_date_with_offset_in_original_timezone(rev.timestamp,
+            rev.timezone or 0)
+
     def log_revision(self, revision):
         """Log a revision, either merged or not."""
         indent = '    ' * revision.merge_depth
-        to_file = self.to_file
-        to_file.write(indent + '-' * 60 + '\n')
+        lines = [_LONG_SEP]
         if revision.revno is not None:
-            to_file.write(indent + 'revno: %s%s\n' % (revision.revno,
+            lines.append('revno: %s%s' % (revision.revno,
                 self.merge_marker(revision)))
         if revision.tags:
-            to_file.write(indent + 'tags: %s\n' % (', '.join(revision.tags)))
+            lines.append('tags: %s' % (', '.join(revision.tags)))
         if self.show_ids:
-            to_file.write(indent + 'revision-id: ' + revision.rev.revision_id)
-            to_file.write('\n')
+            lines.append('revision-id: %s' % (revision.rev.revision_id,))
             for parent_id in revision.rev.parent_ids:
-                to_file.write(indent + 'parent: %s\n' % (parent_id,))
-        self.show_foreign_info(revision.rev, indent)
-        self.show_properties(revision.rev, indent)
+                lines.append('parent: %s' % (parent_id,))
+        lines.extend(self.custom_properties(revision.rev))
 
         committer = revision.rev.committer
         authors = revision.rev.get_apparent_authors()
         if authors != [committer]:
-            to_file.write(indent + 'author: %s\n' % (", ".join(authors),))
-        to_file.write(indent + 'committer: %s\n' % (committer,))
+            lines.append('author: %s' % (", ".join(authors),))
+        lines.append('committer: %s' % (committer,))
 
         branch_nick = revision.rev.properties.get('branch-nick', None)
         if branch_nick is not None:
-            to_file.write(indent + 'branch nick: %s\n' % (branch_nick,))
-
-        date_str = format_date(revision.rev.timestamp,
-                               revision.rev.timezone or 0,
-                               self.show_timezone)
-        to_file.write(indent + 'timestamp: %s\n' % (date_str,))
-
-        to_file.write(indent + 'message:\n')
+            lines.append('branch nick: %s' % (branch_nick,))
+
+        lines.append('timestamp: %s' % (self.date_string(revision.rev),))
+
+        lines.append('message:')
         if not revision.rev.message:
-            to_file.write(indent + '  (no message)\n')
+            lines.append('  (no message)')
         else:
             message = revision.rev.message.rstrip('\r\n')
             for l in message.split('\n'):
-                to_file.write(indent + '  %s\n' % (l,))
+                lines.append('  %s' % (l,))
+
+        # Dump the output, appending the delta and diff if requested
+        to_file = self.to_file
+        to_file.write("%s%s\n" % (indent, ('\n' + indent).join(lines)))
         if revision.delta is not None:
             # We don't respect delta_format for compatibility
             revision.delta.show(to_file, self.show_ids, indent=indent,
@@ -1515,7 +1546,6 @@
                             self.show_timezone, date_fmt="%Y-%m-%d",
                             show_offset=False),
                 tags, self.merge_marker(revision)))
-        self.show_foreign_info(revision.rev, indent+offset)
         self.show_properties(revision.rev, indent+offset)
         if self.show_ids:
             to_file.write(indent + offset + 'revision-id:%s\n'
 
=== modified file 'bzrlib/osutils.py'
--- bzrlib/osutils.py	2009-07-23 16:01:17 +0000
+++ bzrlib/osutils.py	2009-08-31 04:38:13 +0000
@@ -687,6 +687,8 @@
     return offset.days * 86400 + offset.seconds
 
 weekdays = ['Mon', 'Tue', 'Wed', 'Thu', 'Fri', 'Sat', 'Sun']
+_default_format_by_weekday_num = [wd + " %Y-%m-%d %H:%M:%S" for wd in weekdays]
+
 
 def format_date(t, offset=0, timezone='original', date_fmt=None,
                 show_offset=True):
@@ -706,6 +708,32 @@
     date_str = time.strftime(date_fmt, tt)
     return date_str + offset_str
 
+
+# Cache of formatted offset strings
+_offset_cache = {}
+
+
+def format_date_with_offset_in_original_timezone(t, offset=0,
+    _cache=_offset_cache):
+    """Return a formatted date string in the original timezone.
+
+    This routine may be faster then format_date.
+
+    :param t: Seconds since the epoch.
+    :param offset: Timezone offset in seconds east of utc.
+    """
+    if offset is None:
+        offset = 0
+    tt = time.gmtime(t + offset)
+    date_fmt = _default_format_by_weekday_num[tt[6]]
+    date_str = time.strftime(date_fmt, tt)
+    offset_str = _cache.get(offset, None)
+    if offset_str is None:
+        offset_str = ' %+03d%02d' % (offset / 3600, (offset / 60) % 60)
+        _cache[offset] = offset_str
+    return date_str + offset_str
+
+
 def format_local_date(t, offset=0, timezone='original', date_fmt=None,
                       show_offset=True):
     """Return an unicode date string formatted according to the current locale.
@@ -725,6 +753,7 @@
         date_str = date_str.decode(get_user_encoding(), 'replace')
     return date_str + offset_str
 
+
 def _format_date(t, offset, timezone, date_fmt, show_offset):
     if timezone == 'utc':
         tt = time.gmtime(t)
 
=== modified file 'bzrlib/revision.py'
--- bzrlib/revision.py	2009-06-30 16:16:55 +0000
+++ bzrlib/revision.py	2009-08-31 04:38:14 +0000
@@ -54,8 +54,11 @@
 
     def __init__(self, revision_id, properties=None, **args):
         self.revision_id = revision_id
-        self.properties = properties or {}
-        self._check_properties()
+        if properties is None:
+            self.properties = {}
+        else:
+            self.properties = properties
+            self._check_properties()
         self.committer = None
         self.parent_ids = []
         self.parent_sha1s = []
 
=== modified file 'bzrlib/tests/test_osutils.py'
--- bzrlib/tests/test_osutils.py	2009-07-23 16:01:17 +0000
+++ bzrlib/tests/test_osutils.py	2009-08-31 04:38:14 +0000
@@ -365,6 +365,14 @@
         # Instead blackbox.test_locale should check for localized
         # dates once they do occur in output strings.
 
+    def test_format_date_with_offset_in_original_timezone(self):
+        self.assertEqual("Thu 1970-01-01 00:00:00 +0000",
+            osutils.format_date_with_offset_in_original_timezone(0))
+        self.assertEqual("Fri 1970-01-02 03:46:40 +0000",
+            osutils.format_date_with_offset_in_original_timezone(100000))
+        self.assertEqual("Fri 1970-01-02 05:46:40 +0200",
+            osutils.format_date_with_offset_in_original_timezone(100000, 7200))
+
     def test_local_time_offset(self):
         """Test that local_time_offset() returns a sane value."""
         offset = osutils.local_time_offset()