[MERGE] Add -Dtimes debug flag

Andrew Bennetts andrew at canonical.com
Wed Jan 9 07:11:24 GMT 2008


The NEWS entry in this change sums it up:

+   * Add -Dtimes debug flag, which records a timestamp against each mutter to
+     the trace file, relative to the first mutter.  (Andrew Bennetts)

This patch is a bit inflated, because it also includes some trivial resyncing of
the contents of the global-options help topic and the debug.py docstring, as
well as cosmetic re-formatting of part of the NEWS file.

With this flag, the .bzr.log output looks like:

"""
bzr arguments: [u'-Dtimes', u'rocks']
0.000 looking for plugins in /home/andrew/.bazaar/plugins
0.084 looking for plugins in /home/andrew/warthogs/bzr/debug-timestamps/bzrlib/plugins
0.084 Plugin name __init__ already loaded
0.084 Plugin name __init__ already loaded
0.088 encoding stdout as sys.stdout encoding 'UTF-8'
0.088 return code 0
"""

Note that clock starts at the first mutter call (because that's the least
intrusive way to implement this so that the debug flag has minimal cost when not
used), so “0.000” is really about 150ms after process start on my laptop.  But
it's more than adequate for getting a sense of how long it takes to reach
various points in a given operation.

-Andrew.

-------------- next part --------------
# Bazaar merge directive format 2 (Bazaar 0.90)
# revision_id: andrew.bennetts at canonical.com-20080109070423-\
#   kfmpx0s8mcb8sy8p
# target_branch: http://bazaar-vcs.org/bzr/bzr.dev
# testament_sha1: 1e2f7b49dc6bd6208b3836850cb76e6d9a79641f
# timestamp: 2008-01-09 18:10:34 +1100
# source_branch: http://people.ubuntu.com/~andrew/bzr/debug-timestamps
# base_revision_id: pqm at pqm.ubuntu.com-20080107174938-hvwo399dzshh3cod
# 
# Begin patch
=== modified file 'NEWS'
--- NEWS	2008-01-07 16:47:46 +0000
+++ NEWS	2008-01-09 07:04:23 +0000
@@ -141,23 +141,26 @@
 
   INTERNALS:
 
-    * find_* methods available for BzrDirs, Branches and WorkingTrees.
-      (Aaron Bentley)
-
-    * Help topics can now be loaded from files. 
-      (Ian Clatworthy, Alexander Belchenko)
-
-    * get_parent_map now always provides tuples as its output.  (Aaron Bentley)
-
-    * Parent Providers should now implement ``get_parent_map`` returning a
-      dictionary instead of ``get_parents`` returning a list.
-      ``get_parents`` is now considered deprecated.  (John Arbash Meinel)
-
-    * Patience Diff now supports arbitrary python objects, as long as they
-      support ``hash()``. (John Arbash Meinel)
-
-    * Reduce selftest overhead to establish test names by memoization.
-      (Vincent Ladeuil)
+   * Add -Dtimes debug flag, which records a timestamp against each mutter to
+     the trace file, relative to the first mutter.  (Andrew Bennetts)
+    
+   * find_* methods available for BzrDirs, Branches and WorkingTrees.
+     (Aaron Bentley)
+
+   * Help topics can now be loaded from files. 
+     (Ian Clatworthy, Alexander Belchenko)
+
+   * get_parent_map now always provides tuples as its output.  (Aaron Bentley)
+
+   * Parent Providers should now implement ``get_parent_map`` returning a
+     dictionary instead of ``get_parents`` returning a list.
+     ``get_parents`` is now considered deprecated.  (John Arbash Meinel)
+
+   * Patience Diff now supports arbitrary python objects, as long as they
+     support ``hash()``. (John Arbash Meinel)
+
+   * Reduce selftest overhead to establish test names by memoization.
+     (Vincent Ladeuil)
 
   API BREAKS:
 

=== modified file 'bzrlib/debug.py'
--- bzrlib/debug.py	2007-12-06 17:52:30 +0000
+++ bzrlib/debug.py	2008-01-09 07:04:23 +0000
@@ -16,7 +16,7 @@
 
 
 # NOTE: If update these, please also update the help for global-options in
-#       bzrlib/help_topics.py.
+#       bzrlib/help_topics/__init__.py
 
 debug_flags = set()
 """Set of flags that enable different debug behaviour.
@@ -29,11 +29,13 @@
  * error - show stack traces for all top level exceptions
  * evil - capture call sites that do expensive or badly-scaling operations.
  * fetch - trace history copying between repositories
+ * hashcache - log every time a working file is read to determine its hash
  * hooks - trace hook execution
  * hpss - trace smart protocol requests and responses
  * http - trace http connections, requests and responses
  * index - trace major index operations
  * lock - trace when lockdir locks are taken or released
  * merge - emit information for debugging merges
+ * times - record timestamps from program start in trace file
 
 """

=== modified file 'bzrlib/help_topics/__init__.py'
--- bzrlib/help_topics/__init__.py	2008-01-03 02:17:12 +0000
+++ bzrlib/help_topics/__init__.py	2008-01-09 07:04:23 +0000
@@ -281,13 +281,15 @@
                error.
 -Devil         Capture call sites that do expensive or badly-scaling
                operations.
+-Dfetch        Trace history copying between repositories.
 -Dhashcache    Log every time a working file is read to determine its hash.
 -Dhooks        Trace hook execution.
+-Dhpss         Trace smart protocol requests and responses.
 -Dhttp         Trace http connections, requests and responses
--Dhpss         Trace smart protocol requests and responses.
 -Dindex        Trace major index operations.
 -Dlock         Trace when lockdir locks are taken or released.
 -Dmerge        Emit information for debugging merges.
+-Dtimes        Record timestamps from program start in trace file.
 """
 
 _standard_options = \

=== modified file 'bzrlib/trace.py'
--- bzrlib/trace.py	2007-12-27 11:46:11 +0000
+++ bzrlib/trace.py	2008-01-09 07:04:23 +0000
@@ -55,6 +55,7 @@
 import os
 import sys
 import re
+import time
 
 from bzrlib.lazy_import import lazy_import
 lazy_import(globals(), """
@@ -82,6 +83,7 @@
 _trace_depth = 0
 _bzr_log_file = None
 _bzr_log_filename = None
+_bzr_log_opened = None
 
 
 # configure convenient aliases for output routines
@@ -127,6 +129,14 @@
     else:
         out = fmt
     out += '\n'
+    if 'times' in debug.debug_flags:
+        global _bzr_log_opened
+        if _bzr_log_opened is None:
+            # This is the first mutter since the process started.  Start the
+            # clock from now.
+            _bzr_log_opened = time.time()
+        timestamp = '%0.3f' % (time.time() - _bzr_log_opened,)
+        out = '%s %s' % (timestamp, out)
     _trace_file.write(out)
     # TODO: jam 20051227 Consider flushing the trace file to help debugging
     #_trace_file.flush()

# Begin bundle
IyBCYXphYXIgcmV2aXNpb24gYnVuZGxlIHY0CiMKQlpoOTFBWSZTWZI2vHkABLnfgG5QW////3//
/+D////wYApOfXvDe9tjQADaBk2ARsqts1rJIwkkjQEGmSp7NEeqn+hMqPT0mKeo9G0mmKNp6mKe
piZqbRBqaCnp6qfplNT02lAaA2kNB6gAAAAA00ARU21Mp6gDQMgAAAYQDQAAAAASIoEyEzRJmEp+
k8hT9NTU0Pap6gB6gA0aGgZBw0MmmhpkaGmRkGRkaGQGJoyaAMmRiGEkgJoAmITJqnphPSExoU2U
ep5TR6j1Gg9RoNB6kZSmTJklfRuLJY7HoHn3rXdtezDfLt+a75y7Oap77FmK32/zsIxV5NAZ3jWO
PolXpoal93ZQb8UU6FFYJsAuIz2dsdsuaeDrgoxzZFnhJpegEZmAitBu/roeDmERUUm7yBqfZEya
VfMnBKht4Q6Tmj+YbgZNttpNh6vSC0P1f3VyOnshsG3016pHQdD6HWxFA6AyEyNTFaCUyJythIDe
O5SCwqkHn4BAESJ0THwTAlxR0CwLBN7EZlU2Cqs0lfDxNNGKxAhFqVpSH0Lraxdmt5G8iCM+hKFE
zBdlNThIRNezTMSGu+0yLZTSprjiQmcGEFRnkfTaWqljbZosyBbHFZgbsWWcShEHyuTAoBVD6TAE
jGzkxS8NduiIOYFBIi0rSSd1RB1XLtx3HextEHQi8PJdtd4X1eaJnmSI4bpEjz/IbzsHud+khYTb
xlNjYYTUb+h33l/PpsbQ0wH1aSGeQxX3fpm9ApUwL3rGrP2G0fkXHcMHG5t2ThB3czuLlid0DoDy
yEqdTuZu51HkxNLty90xh1HuYrjNp8LUlds4P1gxK/J7Ko3OiILySDKGRH+/TTwSRzWuB5n2odm3
tzTbDfQmZK1gMu672P3jtLEAegxHgiFoxEpWVKDiIFsi0HCUBPmfAYeMMPWVRMSgnIwJDHxfAESI
g8SsHkkWBDdMoMXlQ8dcYeU+MTwEvrN8/5N4G5IxtxkbKxl7qWXbykK+kaLGJdttTOUxSfHkwULO
36JshSRgw8quLnfCslXk+1D6owOMIDVxKOL2C7A4k+Po3vLJ3xZHhsMA6SRN5U5tmmEIb0AROgzj
YDaDrHpiIlusN5AjuheZF5uYawk4vIKBfAeFGKFbwLfLaYEiIw4x/3dKvJ1lStEr3ucwXDhTizi3
IgON8BrCZUsCUlRwSDQ0Hzi7PPmGDuN5ibg4XleZ3EH5AyNah4k/DRtShnshKGVCuZmxQqcGJvR3
9BwtJFAzORIidB8p3ZYZT6CJGs1FqcQwjDhbGReSkXGZqG7A7X2H2bDUrMh/jeQPPUdNl5fa5YVM
a1hrFxNoXlOgga0o52bEG1DpA8zywfyK9PW/C4rvtatz9kVplESkSiXwTrh0Bg2TGTiQMVuctrx5
YWFp0Bkl2WzMcCZYXl9oStxo0673RMJSE4EWYjiRgXF6oykMoD9rzWsdEs+WRHwL8j0CXaJYCVJt
YzjQrWgxHMQbSo6CrInOZkc3EAwIloVZ3uCI7IiTMJh9Ts7PWfXbX6vLnepGYpawswwORUk4KkRA
RNaaOYvsg7WPxnDTVkYPAPfN7nOEksblqHg5/SjdjmqCxxMJK6lZg17JcW06SnC3ndhgL1CZmQzM
dZr6npeXPv2wvvbLc3MRWOVPvaiXiMH2gXg3h7aDyWOFX2ss4bz/L19ESqJvPd1wH/YJ9Oly11E5
hbTG0mKGQ3nL2wKvS5S73s+3o619I+xZHBT/jo8VRBJ9e7BHlq7TPvZtlCu6ttveXDLbHc+Lin+N
hIOZnNKMBnRCPQwP2a+eEDYHiD3N43OVh4epyG6+0rLiR0HVue6KIeYT4HpIvVV0mMCP4bndAqvB
3nM4aGslAgm4NFk9ySl8q6HUjFnOA985QJHw/vzT+InBNJa4n0JeWAB7C8kxhdNeLYN+xpq2zlpW
xTv+fwt2qtxwPGdZ3HoO46yGA7x5KJSEOnEcfieMRVMWH9pJoIS6SzPO7PwJc4VE37oeeWAEVFBG
XhjjN91d4rKDRlSVHmkqouoSg1Go1m24OdwNTM6Mhiyut0uNs9810xvKDZfzhN6EPWKqExiMVsFl
j/sHFIrj1HE2nsORuLBa1JUKECRgkel+JQnyPMVGOIZn0bs87bpQudgnuPUe3pR3k0Bwzv2N9esO
XZV3Gr2UAemc0N0IRZOwbl1RKi26pQL4h0lx1Q667KzdyxPEMcfbKyWzLvLDZmPPNTM2+kGmjtM6
Mc2Zt4QArPFHfiQLknuG+jfjcnR2PKjgX1TodGHhAh/UrH+r8/3ZBprf1eNEajxJLSyoZECHYngt
rNtBuDnQwen/W0I1luDiTF9MIvLcJFpwZwHhn0hvujBAUM4FHoStrEYOVVLjm7BvDaTwNRJuMhtI
Puk6id4znLjCiPRdyNo5f5BrvBiPh+sS1Sjye/4SGjzlQaX0s0wiHKJ/RiK/FfjblrKvZ09fMxpj
1yE+aiEjDhcbqGLl6s3H4m6irjYHIbZ+yojIjNrPyw9IRGZJM1NNisSVtY+DjRcmziL/gRuqY/91
7K0Vdpmd6AvKIRu0YJnr6gJ6eonQ/XKptDddbz/D5/bbGsyZIbTJQ4sreAJn5FXqkaRr6pBVvyQ4
4BcvBaJcWMC0ouVz7pwkDMJct0iS+T+TGapZJHbJozZI5jfLcpZLCfB1B3usdohqvqwS9nEp57dw
PGQjsDkpHBmqbBQZJl1CUiU06KcDoRmXLqcA9sMad1KQRxRMcukSoj2w8ZUSZ7nVPHD2BSE2UYqk
GgeYaSpllCINnlQEKhm5kJKOQJKhA6MAmFEPT0DMJmSN0PnAF+1HD8eYLSe66XZiy0jKQnGpu6Zw
BkI7WcYUY2sC+h+qy5Jc6U60MGKH6OAk9O2fjEKr2gMRBuikfbqnlgu0NTW8kihhx3zQimzi1mOz
sg60vAwIyiWaNvtcss3UK4PfWoXq+8ZxRbrXCXUIvj8jh95iBb7eXk4Qr3uXuiggXubRxMildIyl
A4huD+YeMnerM+LCxeou54ZUAyOW0cHJk/sQFCdyzTA/eYDr8mMAvKPR/FpHnbVpUDbJGM6SCSYH
1f5d20WZCKBw+53FFNo42RZbFNdrrqcYGDW0S6LqKRsQWnk6+GFYmSjToh+8Jk4uN1SxZBpQJ2pT
xvwZRonFGESULwIQ/CMPtEsb6lTJkyGcw+kHfPPqqP3/HAsRWHpAsBcXjooJwY86KbIy7GgxjFmd
Wuw57YKV3D8fGH63xkoa63Z5XlUouewMwHM6VZrqXfvddXNZfQTipISUHIKBFtEA8K73pjrmVB6Z
/ftDvPh4JWF+vI80QtzTLfI72+5GHk1w14GElViwwLDKxwdhAiJkltJdmV56wZw/Q4ZiX5e+zzaU
eI9xN16ri4goGThQXisSi6Io4rJO2u7BhOeAyCl9dAG6H/i7kinChISRtePI


More information about the bazaar mailing list