Rev 4502: More debug timing. in http://bazaar.launchpad.net/~jameinel/bzr/1.17-rework-annotate
John Arbash Meinel
john at arbash-meinel.com
Tue Jun 23 23:21:40 BST 2009
At http://bazaar.launchpad.net/~jameinel/bzr/1.17-rework-annotate
------------------------------------------------------------
revno: 4502
revision-id: john at arbash-meinel.com-20090623222135-ldbtuclia1zfmvuy
parent: john at arbash-meinel.com-20090623220308-mk4j9fgj2tsbmqpo
committer: John Arbash Meinel <john at arbash-meinel.com>
branch nick: 1.17-rework-annotate
timestamp: Tue 2009-06-23 17:21:35 -0500
message:
More debug timing.
{'_process_pending': 0.31604861791095284,
'_read_records_iter': 1.493346989631362,
'annotate one': 5.0270826320105231,
'annotate time': 7.4366645760843912,
'expand_record': 0.4893973954790547,
'first ann': 8498,
'get build graph': 0.24679763768858889,
'get_matching_blocks()': 3.7303522514733056,
'heads time': 0.1828461438535145,
'known blocks': 4389,
'left parents': 4560,
'multi heads': 30,
'multi source': 8649,
'one head': 8619,
'one source': 973,
'overall': 7.6605459632439326,
'resolve annotations': 0.2150744019142099,
'right parents': 2094,
'unknown blocks': 2265,
'update left': 0.9340078138422363,
'update other match': 3.3286844417377002,
'update other resolve': 0.34835153629861293,
'update rest': 3.7008640064589233}
proc_pending + expand + read_raw gives about 2s to get the texts.
and then we spend 5s annotating, 3.5s of that is get_matching_blocks().
So there is about 400ms left to trim out of _update_from_other_parents,
which really isn't much.
The next *biggest* time would be to improve the PatienceSequence information.
-------------- next part --------------
=== modified file 'bzrlib/_annotator_pyx.pyx'
--- a/bzrlib/_annotator_pyx.pyx 2009-06-23 22:03:08 +0000
+++ b/bzrlib/_annotator_pyx.pyx 2009-06-23 22:21:35 +0000
@@ -57,6 +57,9 @@
cdef _update_counter(name, value):
_counters[name] = value + _counters.setdefault(name, 0)
+def update_counter(name, value):
+ _update_counter(name, value)
+
cdef object c
c = time.clock
@@ -244,9 +247,11 @@
parent_lines = self._text_cache[parent_key]
parent_annotations = self._annotations_cache[parent_key]
# PatienceSequenceMatcher should probably be part of Policy
+ t = c()
matcher = patiencediff.PatienceSequenceMatcher(None,
parent_lines, text)
matching_blocks = matcher.get_matching_blocks()
+ _update_counter('get_matching_blocks()', c() - t)
return parent_annotations, matching_blocks
def _pyx_update_from_one_parent(self, key, annotations, lines, parent_key):
@@ -349,10 +354,12 @@
if parent_keys:
t1 = c()
self._update_from_one_parent(key, annotations, text, parent_keys[0])
+ _update_counter('left parents', 1)
t2 = c()
for parent in parent_keys[1:]:
self._update_from_other_parents(key, annotations, text,
this_annotation, parent)
+ _update_counter('right parents', 1)
t3 = c()
_update_counter('update left', t2 - t1)
_update_counter('update rest', t3 - t2)
=== modified file 'bzrlib/annotate.py'
--- a/bzrlib/annotate.py 2009-06-23 20:20:39 +0000
+++ b/bzrlib/annotate.py 2009-06-23 22:21:35 +0000
@@ -447,6 +447,6 @@
try:
- from bzrlib._annotator_pyx import Annotator
+ from bzrlib._annotator_pyx import Annotator, update_counter
except ImportError:
from bzrlib._annotator_py import Annotator
=== modified file 'bzrlib/knit.py'
--- a/bzrlib/knit.py 2009-06-23 20:20:39 +0000
+++ b/bzrlib/knit.py 2009-06-23 22:21:35 +0000
@@ -58,6 +58,8 @@
import os
import sys
+from time import clock
+
from bzrlib.lazy_import import lazy_import
lazy_import(globals(), """
from bzrlib import (
@@ -3425,7 +3427,9 @@
return
while True:
try:
+ t = clock()
records = self._get_build_graph(key)
+ annotate.update_counter('get build graph', clock() - t)
for idx, (key, text, num_lines) in enumerate(
self._extract_texts(records)):
if pb is not None:
@@ -3494,9 +3498,11 @@
"""
block_key = (key, parent_key)
if block_key in self._matching_blocks:
+ annotate.update_counter('known blocks', 1)
blocks = self._matching_blocks.pop(block_key)
parent_annotations = self._annotations_cache[parent_key]
return parent_annotations, blocks
+ annotate.update_counter('unknown blocks', 1)
return annotate.Annotator._get_parent_annotations_and_matches(self,
key, text, parent_key)
@@ -3510,9 +3516,11 @@
compression_parent = key
children = self._pending_deltas.pop(key)
for child_key, parent_keys, record, record_details in children:
+ t = clock()
lines = self._expand_record(child_key, parent_keys,
compression_parent,
record, record_details)
+ annotate.update_counter('expand_record', clock() - t)
assert lines is not None
if self._check_ready_for_annotations(child_key, parent_keys):
to_return.append(child_key)
@@ -3572,15 +3580,21 @@
# Children that are missing their compression parent
pending_deltas = {}
+ t_read = clock()
for (key, record, digest) in self._vf._read_records_iter(records):
+ annotate.update_counter('_read_records_iter', clock() - t_read)
+
# ghosts?
details = self._all_build_details[key]
(_, compression_parent, parent_keys, record_details) = details
assert parent_keys == self._parent_map[key]
+ t = clock()
lines = self._expand_record(key, parent_keys, compression_parent,
record, record_details)
+ annotate.update_counter('expand_record', clock() - t)
if lines is None:
# Pending delta should be queued up
+ t_read = clock()
continue
# At this point, we may be able to yield this content, if all
# parents are also finished
@@ -3589,14 +3603,19 @@
if yield_this_text:
# All parents present
yield key, lines, len(lines)
+ t = clock()
to_process = self._process_pending(key)
+ annotate.update_counter('_process_pending', clock() - t)
while to_process:
this_process = to_process
to_process = []
for key in this_process:
lines = self._text_cache[key]
yield key, lines, len(lines)
+ t = clock()
to_process.extend(self._process_pending(key))
+ annotate.update_counter('_process_pending', clock() - t)
+ t_read = clock()
try:
from bzrlib._knit_load_data_c import _load_data_c as _load_data
More information about the bazaar-commits
mailing list