[qmtest] TET result stream

Nathaniel Smith njs at pobox.com
Fri Feb 20 09:22:47 UTC 2004


On Thu, Feb 19, 2004 at 12:01:44PM -0800, Mark Mitchell wrote:
> Nathaniel Smith wrote:
> >                        "%i %s 00:00:00"
> 
> As I mentioned on IRC, I'd like to see us use a valid time here.  I 
> suggest extending QMTest to collect start/stop time for tests; I can see 
> that being useful to other people as well.

Hmm, okay.  The thought had occurred to me, but I figured you wouldn't
like the size increase in results files -- a bit over 40 bytes per
result -- based on some conversations we had a while ago when I was
hacking on the pickle format.  This adds more functionality, of
course...

Patch attached for review.

Question: current patch assumes that dejagnu subtests all start and
end simultaneously with their containing test.  I know this is true
for the compiler tests, where subtests are basically different ways
of scanning compiler output, but if it's not true in general than I'd
rather lie obviously then lie subtly... (i.e., switch back to using
00:00:00 for purpose start/end times, so it's obvious that the times
can't be trusted).

> >        # I don't know what completion status means; it is zero in all of 
> >        the
> >        # documented examples.
> 
> Let's not have the first person singular appear in comments.  One always 
> wonders "who was I?" later.

Gah, someday, I (Nathaniel Smith <njs at pobox.com>) will remember this
rule.

-- Nathaniel

-- 
"But in Middle-earth, the distinct accusative case disappeared from
the speech of the Noldor (such things happen when you are busy
fighting Orcs, Balrogs, and Dragons)."
-------------- next part --------------
? results.qmr
? qm/external/__init__.pyc
? tests/regress/QMTest/regression_database.pyc
? tests/regress/QMTest/selftest.pyc
? tests/regress/tuple1/QMTest/tuple_test.pyc
? tests/results_files/QMTest/results_file_database.pyc
? tests/results_files/QMTest/results_file_test.pyc
Index: ChangeLog
===================================================================
RCS file: /home/qm/Repository/qm/ChangeLog,v
retrieving revision 1.607
diff -u -r1.607 ChangeLog
--- ChangeLog	20 Feb 2004 07:51:31 -0000	1.607
+++ ChangeLog	20 Feb 2004 09:22:19 -0000
@@ -1,3 +1,20 @@
+2004-02-20  Nathaniel Smith  <njs at codesourcery.com>
+
+	* qm/common.py (format_time_iso): Make argument default to
+	current time.
+	* qm/test/execution_engine.py (ExecutionEngine.Run): Don't pass
+	explicit argument to 'format_time_iso'.
+	(ExecutionEngine._WriteInitialAnnotations): Likewise.
+	
+	* qm/test/target.py (qm.common): Import.
+	(Target.RunTest): Record start and end times.
+
+	* qm/test/classes/tet_stream.py (TETStream._ExtractTime): New
+	function.
+	(TETStream._WriteTCStart): Use it.
+	(TETStream._WriteDejaGNUResult): Likewise.
+	(TETStream._WriteTestResult): Likewise.
+
 2004-02-19  Nathaniel Smith  <njs at codesourcery.com>
 
 	* qm/common.py (parse_time_iso): New function.
Index: qm/common.py
===================================================================
RCS file: /home/qm/Repository/qm/qm/common.py,v
retrieving revision 1.85
diff -u -r1.85 common.py
--- qm/common.py	20 Feb 2004 07:48:56 -0000	1.85
+++ qm/common.py	20 Feb 2004 09:22:19 -0000
@@ -556,7 +556,7 @@
            "%(hour)02d:%(minute)02d %(time_zone)s" % locals()
 
 
-def format_time_iso(time_secs):
+def format_time_iso(time_secs=None):
     """Generate a ISO8601-compliant formatted date and time.
 
     The output is in the format "YYYY-MM-DDThh:mm:ss+TZ", where TZ is
@@ -565,10 +565,13 @@
     sorting behaviour.
 
     'time_secs' -- The time to be formatted, as returned by
-    e.g. 'time.time()'.
+    e.g. 'time.time()'.  If 'None' (the default), uses the current
+    time.
 
     returns -- The formatted time as a string."""
 
+    if time_secs is None:
+        time_secs = time.time()
     return time.strftime("%Y-%m-%dT%H:%M:%SZ", time.gmtime(time_secs))
 
 
Index: qm/test/execution_engine.py
===================================================================
RCS file: /home/qm/Repository/qm/qm/test/execution_engine.py,v
retrieving revision 1.26
diff -u -r1.26 execution_engine.py
--- qm/test/execution_engine.py	12 Feb 2004 06:19:08 -0000	1.26
+++ qm/test/execution_engine.py	20 Feb 2004 09:22:20 -0000
@@ -294,7 +294,7 @@
             
             # Let all of the result streams know that the test run is
             # complete.
-            end_time_str = qm.common.format_time_iso(time.time())
+            end_time_str = qm.common.format_time_iso()
             for rs in self.__result_streams:
                 rs.WriteAnnotation("qmtest.run.end_time", end_time_str)
                 rs.Summarize()
@@ -814,7 +814,7 @@
     def _WriteInitialAnnotations(self):
 
         # Calculate annotations.
-        start_time_str = qm.common.format_time_iso(time.time())
+        start_time_str = qm.common.format_time_iso()
 
         try:
             username = qm.common.get_username()
Index: qm/test/result.py
===================================================================
RCS file: /home/qm/Repository/qm/qm/test/result.py,v
retrieving revision 1.24
diff -u -r1.24 result.py
--- qm/test/result.py	12 Feb 2004 07:44:49 -0000	1.24
+++ qm/test/result.py	20 Feb 2004 09:22:20 -0000
@@ -106,6 +106,8 @@
     RESOURCE = "qmtest.resource"
     TARGET = "qmtest.target"
     TRACEBACK = "qmtest.traceback"
+    START_TIME = "qmtest.start_time"
+    END_TIME = "qmtest.end_time"
     
     # Other class variables.
 
Index: qm/test/target.py
===================================================================
RCS file: /home/qm/Repository/qm/qm/test/target.py,v
retrieving revision 1.23
diff -u -r1.23 target.py
--- qm/test/target.py	13 Nov 2003 04:24:43 -0000	1.23
+++ qm/test/target.py	20 Feb 2004 09:22:20 -0000
@@ -18,6 +18,7 @@
 ########################################################################
 
 import qm
+import qm.common
 import qm.extension
 import qm.platform
 from   qm.test.context import *
@@ -211,8 +212,14 @@
             self.__SetUpResources(descriptor, context)
             # Make the ID of the test available.
             context[context.ID_CONTEXT_PROPERTY] = descriptor.GetId()
+            # Note the start time.
+            result[Result.START_TIME] = qm.common.format_time_iso()
             # Run the test.
-            descriptor.Run(context, result)
+            try:
+                descriptor.Run(context, result)
+            finally:
+                # Note the end time.
+                result[Result.END_TIME] = qm.common.format_time_iso()
         except KeyboardInterrupt:
             result.NoteException(cause = "Interrupted by user.")
             # We received a KeyboardInterrupt, indicating that the
Index: qm/test/classes/tet_stream.py
===================================================================
RCS file: /home/qm/Repository/qm/qm/test/classes/tet_stream.py,v
retrieving revision 1.1
diff -u -r1.1 tet_stream.py
--- qm/test/classes/tet_stream.py	20 Feb 2004 07:48:57 -0000	1.1
+++ qm/test/classes/tet_stream.py	20 Feb 2004 09:22:20 -0000
@@ -93,6 +93,15 @@
                 time.strftime("%Y%m%d", t))
 
 
+    def _ExtractTime(self, result, key):
+        """Extracts the start time from a result."""
+
+        if result.has_key(key):
+            return self._TETFormatTime(result[key])[0]
+        else:
+            return "00:00:00"
+
+
     def WriteAnnotation(self, key, value):
 
         if key == "qmtest.run.start_time":
@@ -164,10 +173,10 @@
 
         # Test case start
         # 10 | activity_number testcase_path time | invocable_components
-        self._WriteLine(10,
-                        "%i %s 00:00:00"
-                        % (self._tcc_number, result.GetId()),
-                        "")
+        started = self._ExtractTime(result, Result.START_TIME)
+        data = "%i %s %s" % (self._tcc_number, result.GetId(), started)
+        self._WriteLine(10, data, "")
+
 
     def _WriteResultAnnotations(self, result, seq_start=1):
         """Writes out annotations for a 'result' in TET format.
@@ -216,6 +225,9 @@
 
         self._WriteResultAnnotations(result)
                 
+        start_time = self._ExtractTime(result, Result.START_TIME)
+        end_time = self._ExtractTime(result, Result.END_TIME)
+
         purpose = 1
         for k in keys:
             r = result[k]
@@ -223,8 +235,8 @@
             # Test purpose start
             # 200 | activity_number test_purpose_number time | text
             self._WriteLine(200,
-                            "%i %i 00:00:00"
-                            % (self._tcc_number, purpose),
+                            "%i %i %s"
+                            % (self._tcc_number, purpose, start_time),
                             "")
             outcome_num, outcome_name \
                          = { DejaGNUTest.PASS: self.PASS,
@@ -239,10 +251,12 @@
                            }[outcome]
             # Test purpose result
             # 220 | activity_number tp_number result time | result-name
-            self._WriteLine(220,
-                            "%i %i %i 00:00:00"
-                            % (self._tcc_number, purpose, outcome_num),
-                            outcome_name)
+            data = "%i %i %i %s" % (self._tcc_number,
+                                    purpose,
+                                    outcome_num,
+                                    end_time)
+            self._WriteLine(220, data, outcome_name)
+            
             if outcome == DejaGNUTest.WARNING:
                 # Test case information
                 # 520 | activity_num tp_num context block sequence | text
@@ -267,7 +281,7 @@
         # "completion status" appears undocumented; it is zero in all of
         # the documented examples.
         self._WriteLine(80,
-                        "%i 0 00:00:00" % self._tcc_number,
+                        "%i 0 %s" % (self._tcc_number, end_time),
                         "")
 
             
@@ -277,7 +291,9 @@
         self._WriteTCStart(result)
         # Test purpose start
         # 200 | activity_number test_purpose_number time | text
-        self._WriteLine(200, "%i 0 00:00:00" % self._tcc_number, "")
+        start_time = self._ExtractTime(result, Result.START_TIME)
+        data = "%i 0 %s" % (self._tcc_number, start_time)
+        self._WriteLine(200, data, "")
 
         outcome_num, outcome_name = { Result.FAIL: self.FAIL,
                                       Result.PASS: self.PASS,
@@ -286,10 +302,9 @@
                                     }[result.GetOutcome()]
         # Test purpose result
         # 220 | activity_number tp_number result time | result-name
-        self._WriteLine(220,
-                        "%i 0 %i 00:00:00"
-                        % (self._tcc_number, outcome_num),
-                        outcome_name)
+        end_time = self._ExtractTime(result, Result.END_TIME)
+        data = "%i 0 %i %s" % (self._tcc_number, outcome_num, end_time)
+        self._WriteLine(220, data, outcome_name)
 
         if result.GetOutcome() == Result.ERROR:
             # Test case controller message
@@ -307,7 +322,7 @@
         # "completion status" appears undocumented; it is zero in all of
         # the documented examples.
         self._WriteLine(80,
-                        "%i 0 00:00:00" % self._tcc_number,
+                        "%i 0 %s" % (self._tcc_number, end_time),
                         "")
 
 


More information about the qmtest mailing list