subunit

Merge lp:~jameinel/subunit/omit-times-623654 into lp:~subunit/subunit/trunk

  1. omit-times-623654
  2. Merge into trunk
Proposed by John A Meinel
Status: Merged
Merge reported by: Jonathan Lange
Merged at revision: not available
Proposed branch: lp:~jameinel/subunit/omit-times-623654
Merge into: lp:~subunit/subunit/trunk
Diff against target: 209 lines (+124/-0)
3 files modified
NEWS (+8/-0)
python/subunit/test_results.py (+34/-0)
python/subunit/tests/test_test_results.py (+82/-0)
To merge this branch: bzr merge lp:~jameinel/subunit/omit-times-623654
Reviewer Review Type Date Requested Status
Jonathan Lange Needs Fixing
Review via email: mp+33601@code.launchpad.net

Commit message

Emit only the first and last time statements for a long stream of time calls.

Description of the change

This adds filtering for the 'time' commands while processing.

The motivation was that 'zcat pqm-stdout.gz | subunit-filter' ends up generating a ton of 'time' calls after it has filtered out all of the actual test runs.

However, it made sense to me that you only need a time call if it is 'next to' a non-time call.

This just adds a single level of buffering, such that if you call .time() repeatedly, only 2 will be emitted.

To post a comment you must log in.
Revision history for this message
Jonathan Lange (jml) wrote :

Thanks for doing this John. I'm sorry it took us so long to get around to your patch. I like the approach of only including 'time:' statements that are relevant to the filtered output, but I think this patch gets it slightly wrong.

For example, given the events::

time: 2010-10-17 20:40:05.577960Z
test: foo
time: 2010-10-17 20:41:05.672960Z
success: foo
time: 2010-10-17 21:29:21.727029Z
test: canonical.testing.layers.ZopelessLayer:tearDown
tags: zope:layer
time: 2010-10-17 21:29:21.727397Z
skip: canonical.testing.layers.ZopelessLayer:tearDown [
tearDown not supported
]

where we are filtering out success and want to see skips. The output should be::

time: 2010-10-17 21:29:21.727029Z
test: canonical.testing.layers.ZopelessLayer:tearDown
time: 2010-10-17 21:29:21.727397Z
skip: canonical.testing.layers.ZopelessLayer:tearDown [ multipart
Content-Type: text/plain
reason
17
tearDown not supported
0
]

Where the output with this patch is::

time: 2010-10-17 20:40:05.577960Z
time: 2010-10-17 21:29:21.727397Z
test: canonical.testing.layers.ZopelessLayer:tearDown
skip: canonical.testing.layers.ZopelessLayer:tearDown [ multipart
Content-Type: text/plain
reason
17
tearDown not supported
0
]

The differences being that the output from this branch includes the first 'time:' statement ever, which is not relevant to the displayed events, and that it excludes the 'time:' statement from between 'test' and 'skip'. There may be a significant chunk of time between a test starting and a test getting its result, and I think we want to show that as long as we're showing time.

As a reminder, a 'time:' statement in a subunit stream means that all subsequent statements can be thought of as occurring at that time, one after the other until the next 'time:' statement.

On a simpler level:
 * there are two tests named test_timing_filtered_w_add_unexpected_success
 * stopTestRun is defined twice

review: Needs Fixing
Revision history for this message
Robert Collins (lifeless) wrote :

I think keeping the first time is actually ok and quite interesting.
The rest I agree with.

Revision history for this message
Jonathan Lange (jml) wrote :

On Tue, Oct 19, 2010 at 10:26 AM, Robert Collins
<email address hidden> wrote:
> I think keeping the first time is actually ok and quite interesting.
> The rest I agree with.

FWIW, the way the branch behaves now it keeps the first timestamp
after the last interesting event and the first timestamp before the
next interesting event. So....

<BEGINNING>
time: 1
time: N
test: event
error: event
time: N + A
time: N + A + B
test: event2
error: event2
time: N + A + B + C
<END>

jml

Revision history for this message
Robert Collins (lifeless) wrote :

Right, thats clearly bong.
I'd like to see, I think:
time:
time:
test: event
time:
error: event
time:
time:
test: event2
time:
error: event2
time:

That is, collapse N>2 time: sequences in the first, last events.

Revision history for this message
Jonathan Lange (jml) wrote :

On Fri, Oct 22, 2010 at 7:02 PM, Robert Collins
<email address hidden> wrote:
> Right, thats clearly bong.
> I'd like to see, I think:
> time:
> time:
> test: event
> time:
> error: event
> time:
> time:

I don't see at all what having two "time:" statements here would mean.
In subunit protocol terms it means exactly the same as having only the
second time statement.

jml

Revision history for this message
Jonathan Lange (jml) wrote :

On Sat, Oct 23, 2010 at 3:11 PM, John Arbash Meinel
<email address hidden> wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA1
>
> On 10/23/2010 5:29 AM, Jonathan Lange wrote:
>> On Fri, Oct 22, 2010 at 7:02 PM, Robert Collins
>> <email address hidden> wrote:
>>> Right, thats clearly bong.
>>> I'd like to see, I think:
>>> time:
>>> time:
>>> test: event
>>> time:
>>> error: event
>>> time:
>>> time:
>>
>> I don't see at all what having two "time:" statements here would mean.
>> In subunit protocol terms it means exactly the same as having only the
>> second time statement.
>>
>> jml
>>
>
> Not entirely. I believe there are test runners that tell you how *long*
> an event took. (bzr selftest -v). In which case doesn't it subtract the
> known time from the next time it sees?
>

From the README:
"The time directive acts as a clock event - it sets the time for all future
events. The value should be a valid ISO8601 time."

time: A
test: X
time: B
success: X
time: C
time: D

Thus, the net effect of two consecutive time events is to set the time
for all future events to whatever value was provided with the second
time event. The first is ignored.

jml

Revision history for this message
Jonathan Lange (jml) wrote :

On Sat, Oct 23, 2010 at 7:23 PM, John Arbash Meinel
<email address hidden> wrote:
...
>> From the README:
>> "The time directive acts as a clock event - it sets the time for all future
>> events. The value should be a valid ISO8601 time."
>>
>> time: A
>> test: X
>> time: B
>> success: X
>> time: C
>> time: D
>>
>> Thus, the net effect of two consecutive time events is to set the time
>> for all future events to whatever value was provided with the second
>> time event. The first is ignored.
>>
>
> If you were computing "how long did success: X" take, wouldn't you
> subtract C from B?
>

Why would I compute how long "success: X" took? If I wanted to know
the amount of time between the test X starting and it completing, I'd
calculate B - A.

Also, and perhaps I'm being too pedantic here, but unless the subunit
protocol is being used in a non-standard way, time C does not mean
"when success: X finished", it means "when the first event after
success: X happened".

jml

Revision history for this message
Robert Collins (lifeless) wrote :

On Sun, Oct 24, 2010 at 11:58 AM, Jonathan Lange <email address hidden> wrote:
>>> Thus, the net effect of two consecutive time events is to set the time
>>> for all future events to whatever value was provided with the second
>>> time event. The first is ignored.

Yes, but we're altering the stream and stripping other things. While
its ignored we could use to use it.

>>
>> If you were computing "how long did success: X" take, wouldn't you
>> subtract C from B?
>>
>
> Why would I compute how long "success: X" took? If I wanted to know
> the amount of time between the test X starting and it completing, I'd
> calculate B - A.

Yes.

> Also, and perhaps I'm being too pedantic here, but unless the subunit
> protocol is being used in a non-standard way, time C does not mean
> "when success: X finished", it means "when the first event after
> success: X happened".

Thats right, it means 'first event after success: X', which for
figuring out stuff in slow test runners may (or may not) be
interesting.

-Rob

Revision history for this message
Jonathan Lange (jml) wrote :

On Sun, Oct 24, 2010 at 5:52 PM, Robert Collins
<email address hidden> wrote:
...
>> Also, and perhaps I'm being too pedantic here, but unless the subunit
>> protocol is being used in a non-standard way, time C does not mean
>> "when success: X finished", it means "when the first event after
>> success: X happened".
>
> Thats right, it means 'first event after success: X', which for
> figuring out stuff in slow test runners may (or may not) be
> interesting.

As might the second or third. If you are interested in the first event
after success: X, include it in the filter.

jml

Revision history for this message
Jonathan Lange (jml) wrote :

I've been working on this branch, trying to make the tests a bit clearer and making sure that the behaviour is "correct" as Rob determines it (although I still hold to my point that two consecutive time: statements are meaningless).

Anyway, I came across bug 716554, which means that my comment dated 2010-10-19 isn't entirely appropriate -- this branch just keeps up an existing bug.

Personally, I would rather fix the bug first, then land this branch (or my version with clearer tests, lp:~jml/subunit/omit-times-623654). I don't think the order matters too much though.

Revision history for this message
Jonathan Lange (jml) wrote :

That branch is up for review: https://code.launchpad.net/~jml/subunit/unmangle-time-716554/+merge/49439

Will definitely conflict with this.

Revision history for this message
Jonathan Lange (jml) wrote :

http://bazaar.launchpad.net/~subunit/subunit/trunk/revision/141 has landed that branch and fixes the bug.

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'NEWS'
2--- NEWS 2010-07-02 12:51:46 +0000
3+++ NEWS 2010-08-25 00:31:41 +0000
4@@ -5,6 +5,14 @@
5 NEXT (In development)
6 ---------------------
7
8+IMPROVEMENTS
9+~~~~~~~~~~~~
10+
11+* 'subunit-filter' now only emits time statements if they come just before or
12+ just after another action. That way, went filtering out 1k tests, we don't
13+ end up with 2k time statements doing nothing.
14+ (John Arbash Meinel, #623654)
15+
16 0.0.6
17 -----
18
19
20=== modified file 'python/subunit/test_results.py'
21--- python/subunit/test_results.py 2010-08-04 17:05:18 +0000
22+++ python/subunit/test_results.py 2010-08-25 00:31:41 +0000
23@@ -87,6 +87,10 @@
24 def time(self, a_datetime):
25 return self.decorated.time(a_datetime)
26
27+ def stopTestRun(self):
28+ return self.decorated.stopTestRun()
29+
30+
31
32 class HookedTestResultDecorator(TestResultDecorator):
33 """A TestResult which calls a hook on every event."""
34@@ -236,10 +240,13 @@
35 self._current_test_filtered = None
36 # The (new, gone) tags for the current test.
37 self._current_test_tags = None
38+ self._last_was_time = False
39+ self._buffered_time = None
40
41 def addError(self, test, err=None, details=None):
42 if (not self._filter_error and
43 self.filter_predicate(test, 'error', err, details)):
44+ self._emitBufferedTime()
45 self.decorated.startTest(test)
46 self.decorated.addError(test, err, details=details)
47 else:
48@@ -248,6 +255,7 @@
49 def addFailure(self, test, err=None, details=None):
50 if (not self._filter_failure and
51 self.filter_predicate(test, 'failure', err, details)):
52+ self._emitBufferedTime()
53 self.decorated.startTest(test)
54 self.decorated.addFailure(test, err, details=details)
55 else:
56@@ -256,6 +264,7 @@
57 def addSkip(self, test, reason=None, details=None):
58 if (not self._filter_skip and
59 self.filter_predicate(test, 'skip', reason, details)):
60+ self._emitBufferedTime()
61 self.decorated.startTest(test)
62 self.decorated.addSkip(test, reason, details=details)
63 else:
64@@ -264,6 +273,7 @@
65 def addSuccess(self, test, details=None):
66 if (not self._filter_success and
67 self.filter_predicate(test, 'success', None, details)):
68+ self._emitBufferedTime()
69 self.decorated.startTest(test)
70 self.decorated.addSuccess(test, details=details)
71 else:
72@@ -271,6 +281,7 @@
73
74 def addExpectedFailure(self, test, err=None, details=None):
75 if self.filter_predicate(test, 'expectedfailure', err, details):
76+ self._emitBufferedTime()
77 self.decorated.startTest(test)
78 return self.decorated.addExpectedFailure(test, err,
79 details=details)
80@@ -278,6 +289,7 @@
81 self._filtered()
82
83 def addUnexpectedSuccess(self, test, details=None):
84+ self._emitBufferedTime()
85 self.decorated.startTest(test)
86 return self.decorated.addUnexpectedSuccess(test, details=details)
87
88@@ -330,6 +342,28 @@
89 if id.startswith("subunit.RemotedTestCase."):
90 return id[len("subunit.RemotedTestCase."):]
91 return id
92+
93+ def time(self, a_datetime):
94+ if self._last_was_time:
95+ self._buffered_time = a_datetime
96+ return
97+ self._last_was_time = True
98+ super(TestResultFilter, self).time(a_datetime)
99+
100+ def _emitBufferedTime(self):
101+ """Called before an action call.
102+
103+ If we have a time call that was buffered, waiting for output, we go
104+ ahead and emit it now, and clear the buffers.
105+ """
106+ self._last_was_time = False
107+ if self._buffered_time is not None:
108+ super(TestResultFilter, self).time(self._buffered_time)
109+ self._buffered_time = None
110+
111+ def stopTestRun(self):
112+ self._emitBufferedTime()
113+ super(TestResultFilter, self).stopTestRun()
114
115
116 class TestIdPrintingResult(testtools.TestResult):
117
118=== modified file 'python/subunit/tests/test_test_results.py'
119--- python/subunit/tests/test_test_results.py 2009-12-13 01:59:07 +0000
120+++ python/subunit/tests/test_test_results.py 2010-08-25 00:31:41 +0000
121@@ -193,6 +193,88 @@
122 self.assertNotEqual(None, self.decorated._calls[2])
123
124
125+class TestTestResultFilter(unittest.TestCase):
126+
127+ def make_result(self, filter_success=True, filter_failure=False,
128+ filter_error=False, filter_skip=False):
129+
130+ terminal = TimeCapturingResult()
131+ # The result object under test.
132+ self.result = subunit.test_results.TestResultFilter(terminal,
133+ filter_skip=filter_skip, filter_error=filter_error,
134+ filter_failure=filter_failure, filter_success=filter_success)
135+ self.decorated = terminal
136+ self.cur_time = 0
137+
138+ def addTime(self):
139+ dt = datetime.datetime(2009,10,11,12,13,14,self.cur_time,
140+ iso8601.Utc())
141+ self.result.time(dt)
142+ self.cur_time += 1
143+
144+ def make_simple_timing(self, center_call, *args, **kwargs):
145+ self.result.startTestRun()
146+ self.addTime()
147+ self.addTime()
148+ center_call(*args, **kwargs)
149+ self.addTime()
150+ self.addTime()
151+ self.result.stopTestRun()
152+
153+ def test_timing_filtered(self):
154+ self.make_result()
155+ self.result.startTestRun()
156+ for i in xrange(4):
157+ self.addTime()
158+ self.result.stopTestRun()
159+ self.assertEqual(2, len(self.decorated._calls))
160+
161+ def test_timing_filtered_w_add_success_filtered(self):
162+ self.make_result()
163+ self.make_simple_timing(self.result.addSuccess, self)
164+ # addSuccess defaults to being filtered, so we hide the extra time
165+ # calls
166+ self.assertEqual(2, len(self.decorated._calls))
167+
168+ def test_timing_filtered_w_add_success_not_filtered(self):
169+ self.make_result(filter_success=False)
170+ self.make_simple_timing(self.result.addSuccess, self)
171+ # When not filtered, we include the start time, the time before and
172+ # after the run, and the stop time.
173+ self.assertEqual(4, len(self.decorated._calls))
174+
175+ def test_timing_filtered_w_add_failure(self):
176+ self.make_result()
177+ self.make_simple_timing(self.result.addFailure, self, details={})
178+ self.assertEqual(4, len(self.decorated._calls))
179+
180+ def test_timing_filtered_w_add_error(self):
181+ self.make_result()
182+ self.make_simple_timing(self.result.addError, self, details={})
183+ self.assertEqual(4, len(self.decorated._calls))
184+
185+ def test_timing_filtered_w_add_skip(self):
186+ self.make_result(filter_skip=False)
187+ self.make_simple_timing(self.result.addSkip, self, 'foo')
188+ self.assertEqual(4, len(self.decorated._calls))
189+
190+ def test_timing_filtered_w_add_expected_failure(self):
191+ self.make_result()
192+ self.make_simple_timing(self.result.addExpectedFailure, self, 'xfail')
193+ self.assertEqual(4, len(self.decorated._calls))
194+
195+ def test_timing_filtered_w_add_unexpected_success(self):
196+ self.make_result()
197+ self.make_simple_timing(self.result.addUnexpectedSuccess, self)
198+ self.assertEqual(4, len(self.decorated._calls))
199+
200+ def test_timing_filtered_w_add_unexpected_success(self):
201+ self.make_result()
202+ self.make_simple_timing(self.result.addUnexpectedSuccess, self)
203+ self.assertEqual(4, len(self.decorated._calls))
204+
205+
206+
207 def test_suite():
208 loader = subunit.tests.TestUtil.TestLoader()
209 result = loader.loadTestsFromName(__name__)

Subscribers

People subscribed via source and target branches