Rev 3197: (andrew) Always include timestamps in the trace file. in file:///home/pqm/archives/thelove/bzr/%2Btrunk/

Canonical.com Patch Queue Manager pqm at pqm.ubuntu.com
Wed Jan 23 00:26:08 GMT 2008


At file:///home/pqm/archives/thelove/bzr/%2Btrunk/

------------------------------------------------------------
revno: 3197
revision-id:pqm at pqm.ubuntu.com-20080123002558-oeppeqc0v0etytb5
parent: pqm at pqm.ubuntu.com-20080122225027-vp7xsc3kue1uw2r5
parent: andrew.bennetts at canonical.com-20080122050450-yxa7ohko0y745zg7
committer: Canonical.com Patch Queue Manager <pqm at pqm.ubuntu.com>
branch nick: +trunk
timestamp: Wed 2008-01-23 00:25:58 +0000
message:
  (andrew) Always include timestamps in the trace file.
modified:
  NEWS                           NEWS-20050323055033-4e00b5db738777ff
  bzrlib/__init__.py             __init__.py-20050309040759-33e65acf91bbcd5d
  bzrlib/debug.py                debug.py-20061102062349-vdhrw9qdpck8cl35-1
  bzrlib/help_topics/__init__.py help_topics.py-20060920210027-rnim90q9e0bwxvy4-1
  bzrlib/tests/test_osutils.py   test_osutils.py-20051201224856-e48ee24c12182989
  bzrlib/tests/test_trace.py     testtrace.py-20051110225523-a21117fc7a07eeff
  bzrlib/trace.py                trace.py-20050309040759-c8ed824bdcd4748a
    ------------------------------------------------------------
    revno: 3195.1.3
    revision-id:andrew.bennetts at canonical.com-20080122050450-yxa7ohko0y745zg7
    parent: andrew.bennetts at canonical.com-20080122050307-pvw5qdwtqpmponui
    committer: Andrew Bennetts <andrew.bennetts at canonical.com>
    branch nick: always-trace-times
    timestamp: Tue 2008-01-22 16:04:50 +1100
    message:
      Remove accidentally added blank line.
    modified:
      bzrlib/__init__.py             __init__.py-20050309040759-33e65acf91bbcd5d
    ------------------------------------------------------------
    revno: 3195.1.2
    revision-id:andrew.bennetts at canonical.com-20080122050307-pvw5qdwtqpmponui
    parent: andrew.bennetts at canonical.com-20080122050042-hh98dtixpfem8dbe
    committer: Andrew Bennetts <andrew.bennetts at canonical.com>
    branch nick: always-trace-times
    timestamp: Tue 2008-01-22 16:03:07 +1100
    message:
      Move NEWS entry to right place.
    modified:
      NEWS                           NEWS-20050323055033-4e00b5db738777ff
    ------------------------------------------------------------
    revno: 3195.1.1
    revision-id:andrew.bennetts at canonical.com-20080122050042-hh98dtixpfem8dbe
    parent: pqm at pqm.ubuntu.com-20080122004623-p8kb5y8dehs5cmho
    committer: Andrew Bennetts <andrew.bennetts at canonical.com>
    branch nick: always-trace-times
    timestamp: Tue 2008-01-22 16:00:42 +1100
    message:
      Always include timestamps in the trace file (i.e. remove -Dtimes in favour of having it switched on permanently)
    modified:
      NEWS                           NEWS-20050323055033-4e00b5db738777ff
      bzrlib/__init__.py             __init__.py-20050309040759-33e65acf91bbcd5d
      bzrlib/debug.py                debug.py-20061102062349-vdhrw9qdpck8cl35-1
      bzrlib/help_topics/__init__.py help_topics.py-20060920210027-rnim90q9e0bwxvy4-1
      bzrlib/tests/test_osutils.py   test_osutils.py-20051201224856-e48ee24c12182989
      bzrlib/tests/test_trace.py     testtrace.py-20051110225523-a21117fc7a07eeff
      bzrlib/trace.py                trace.py-20050309040759-c8ed824bdcd4748a
=== modified file 'NEWS'
--- a/NEWS	2008-01-22 22:50:27 +0000
+++ b/NEWS	2008-01-23 00:25:58 +0000
@@ -60,9 +60,6 @@
 
   INTERNALS:
 
-    * Add -Dtimes debug flag, which records a timestamp against each mutter to
-      the trace file, relative to the first mutter.  (Andrew Bennetts)
-     
     * Add a new method ``get_result`` to graph search objects. The resulting
       ``SearchResult`` can be used to recreate the search later, which will
       be useful in reducing network traffic. (Robert Collins)
@@ -86,6 +83,9 @@
       useful for code which needs to be aware of ghosts (e.g. fetching data
       cares about ghosts during revision selection). (Robert Collins)
  
+    * Record a timestamp against each mutter to the trace file, relative to the
+      first import of bzrlib.  (Andrew Bennetts)
+     
     * ``Repository.get_data_stream`` is now deprecated in favour of
       ``Repository.get_data_stream_for_search`` which allows less network
       traffic when requesting data streams over a smart server. (Robert Collins)

=== modified file 'bzrlib/__init__.py'
--- a/bzrlib/__init__.py	2008-01-15 11:13:19 +0000
+++ b/bzrlib/__init__.py	2008-01-22 05:04:50 +0000
@@ -16,6 +16,12 @@
 
 """bzr library"""
 
+import time
+
+# Keep track of when bzrlib was first imported, so that we can give rough
+# timestamps relative to program start in the log file kept by bzrlib.trace.
+_start_time = time.time()
+
 from bzrlib.osutils import get_user_encoding
 
 

=== modified file 'bzrlib/debug.py'
--- a/bzrlib/debug.py	2008-01-11 04:55:53 +0000
+++ b/bzrlib/debug.py	2008-01-22 05:00:42 +0000
@@ -37,6 +37,5 @@
  * knit - trace knit 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'
--- a/bzrlib/help_topics/__init__.py	2008-01-21 00:46:32 +0000
+++ b/bzrlib/help_topics/__init__.py	2008-01-22 05:00:42 +0000
@@ -291,7 +291,6 @@
 -Dknit         Trace knit 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/tests/test_osutils.py'
--- a/bzrlib/tests/test_osutils.py	2008-01-11 04:55:53 +0000
+++ b/bzrlib/tests/test_osutils.py	2008-01-22 05:00:42 +0000
@@ -1117,7 +1117,6 @@
  * knit - trace knit 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/tests/test_trace.py'
--- a/bzrlib/tests/test_trace.py	2007-09-24 06:00:49 +0000
+++ b/bzrlib/tests/test_trace.py	2008-01-22 05:00:42 +0000
@@ -21,6 +21,7 @@
 from cStringIO import StringIO
 import errno
 import os
+import re
 import sys
 
 from bzrlib import (
@@ -117,15 +118,20 @@
         else:
             self.fail("expected error not raised")
 
+    def assertLogStartsWith(self, log, string):
+        """Like assertStartsWith, but skips the log timestamp."""
+        self.assertContainsRe(log,
+            '^\\d+\\.\\d+  ' + re.escape(string))
+
     def test_mutter_callsite_1(self):
         """mutter_callsite can capture 1 level of stack frame."""
         mutter_callsite(1, "foo %s", "a string")
         log = self._get_log(keep_log_file=True)
         # begin with the message
-        self.assertStartsWith(log, 'foo a string\nCalled from:\n')
+        self.assertLogStartsWith(log, 'foo a string\nCalled from:\n')
         # should show two frame: this frame and the one above
         self.assertContainsRe(log,
-            'test_trace\.py", line \d+, in test_mutter_callsite_1\n')
+            'test_trace\\.py", line \\d+, in test_mutter_callsite_1\n')
         # this frame should be the final one
         self.assertEndsWith(log, ' "a string")\n')
 
@@ -134,7 +140,7 @@
         mutter_callsite(2, "foo %s", "a string")
         log = self._get_log(keep_log_file=True)
         # begin with the message
-        self.assertStartsWith(log, 'foo a string\nCalled from:\n')
+        self.assertLogStartsWith(log, 'foo a string\nCalled from:\n')
         # should show two frame: this frame and the one above
         self.assertContainsRe(log,
             'test_trace.py", line \d+, in test_mutter_callsite_2\n')

=== modified file 'bzrlib/trace.py'
--- a/bzrlib/trace.py	2008-01-09 07:04:23 +0000
+++ b/bzrlib/trace.py	2008-01-22 05:00:42 +0000
@@ -83,7 +83,7 @@
 _trace_depth = 0
 _bzr_log_file = None
 _bzr_log_filename = None
-_bzr_log_opened = None
+_start_time = bzrlib._start_time
 
 
 # configure convenient aliases for output routines
@@ -128,15 +128,8 @@
         out = fmt % tuple(real_args)
     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)
+    timestamp = '%0.3f  ' % (time.time() - _start_time,)
+    out = timestamp + out + '\n'
     _trace_file.write(out)
     # TODO: jam 20051227 Consider flushing the trace file to help debugging
     #_trace_file.flush()




More information about the bazaar-commits mailing list