testtools

Merge lp:~gz/testtools/result_timings_forwarding_625594 into lp:~testtools-committers/testtools/trunk

  1. result_timings_forwarding_625594
  2. Merge into trunk
Proposed by Martin Packman
Status: Merged
Merged at revision: 101
Proposed branch: lp:~gz/testtools/result_timings_forwarding_625594
Merge into: lp:~testtools-committers/testtools/trunk
Diff against target: 170 lines (+59/-43)
4 files modified
NEWS (+4/-0)
testtools/testresult/real.py (+36/-42)
testtools/tests/helpers.py (+4/-0)
testtools/tests/test_testresult.py (+15/-1)
To merge this branch: bzr merge lp:~gz/testtools/result_timings_forwarding_625594
Reviewer Review Type Date Requested Status
Robert Collins Approve
Vincent Ladeuil Approve
Review via email: mp+36786@code.launchpad.net

Description of the change

The testtools half of the fix for bug 625594, see <lp:~gz/bzr/use_testtools_timings_625594> for the bzr part.

ThreadsafeForwardingResult was simulating a test run from startTest to add<Result> to stopTest all in one go, so that concurrent tests don't interfere with each other in the reporting. This mostly doesn't matter as subunit doesn't flush its output stream so you get buffer-sized chunks from child processes, but does mean that the test result class doing the actual reporting thinks every test is nearly instant.

What we want to do is record and forward the relevant times subunit reports to the wrapped result, but I don't see a particularly pretty way of doing this. This change stashes the current stamp on the test case (which should be thread-local) when startTest is run, then retrieves it and reports it before startTest is forwarded, then forwards the now-current stamp before calling the add<Result> method.

Haven't really added sufficient test suite coverage here, and make the implementation tolerant of timestamps being given as the tests tend to call result methods out of sequence and expect sanity.

I welcome suggestions to make all this less horrid, and hope to dream some tonight.

To post a comment you must log in.
Revision history for this message
Robert Collins (lifeless) wrote :

thanks for poking at this.

Some random thoughts:
 - an associative lookup (self.tests.setdefault(test), self._now()),
and pop that at the end
 - self._test_started = (test, self._now)

-Rob

Revision history for this message
Martin Packman (gz) wrote :

You mean rather than smuggling the start time on the test instance? I considered a test.id() -> start_time map on the forwarding result as well, but I'm not sure I quite understand what you're suggesting.

Revision history for this message
Vincent Ladeuil (vila) wrote :

I change looks fine and remove duplication (good)
Also, I've deployed it on babune when it was proposed here and it's a good thing to not see 0 for all times anymore :)

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

So, I've tweaked and landed. please look at what I did, but for reference:
 - timestamping can be used everywhere - OriginalToExtended strips it when a downlevel class is encountered

review: Approve
Revision history for this message
Martin Packman (gz) wrote :

Thanks for that Robert. Just to make certain on a key change from the merge:

- test._testtools_time_of_startTest = self._now()
+ self._test_start = self._now()

So a ThreadsafeForwardingResult *is* always thread local, never used by more than one child stream? I wasn't certain on that.

> - timestamping can be used everywhere - OriginalToExtended strips it when a downlevel class is encountered

Great. I tried that out but lots of tests started falling over, thanks for going through the suite and sorting the mess out.

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'NEWS'
2--- NEWS 2010-09-18 02:10:58 +0000
3+++ NEWS 2010-09-27 20:41:03 +0000
4@@ -16,6 +16,10 @@
5 * In normal circumstances, a TestCase will no longer share details with clones
6 of itself. (Andrew Bennetts, bug #637725)
7
8+* Timestamps as produced by subunit protocol clients are now forwarded in the
9+ ThreadsafeForwardingResult so correct test durations can be reported.
10+ (Martin [gz], #625594)
11+
12
13 0.9.6
14 ~~~~~
15
16=== modified file 'testtools/testresult/real.py'
17--- testtools/testresult/real.py 2010-08-04 14:59:59 +0000
18+++ testtools/testresult/real.py 2010-09-27 20:41:03 +0000
19@@ -299,60 +299,45 @@
20 TestResult.__init__(self)
21 self.result = ExtendedToOriginalDecorator(target)
22 self.semaphore = semaphore
23+ self._use_timings = False
24+
25+ def _add_result_with_semaphore(self, method, test, *args, **kwargs):
26+ self.semaphore.acquire()
27+ try:
28+ if self._use_timings:
29+ self.result.time(test._testtools_time_of_startTest)
30+ self.result.startTest(test)
31+ self.result.time(self._now())
32+ else:
33+ self.result.startTest(test)
34+ method(test, *args, **kwargs)
35+ self.result.stopTest(test)
36+ finally:
37+ self.semaphore.release()
38
39 def addError(self, test, err=None, details=None):
40- self.semaphore.acquire()
41- try:
42- self.result.startTest(test)
43- self.result.addError(test, err, details=details)
44- self.result.stopTest(test)
45- finally:
46- self.semaphore.release()
47+ self._add_result_with_semaphore(self.result.addError,
48+ test, err, details=details)
49
50 def addExpectedFailure(self, test, err=None, details=None):
51- self.semaphore.acquire()
52- try:
53- self.result.startTest(test)
54- self.result.addExpectedFailure(test, err, details=details)
55- self.result.stopTest(test)
56- finally:
57- self.semaphore.release()
58+ self._add_result_with_semaphore(self.result.addExpectedFailure,
59+ test, err, details=details)
60
61 def addFailure(self, test, err=None, details=None):
62- self.semaphore.acquire()
63- try:
64- self.result.startTest(test)
65- self.result.addFailure(test, err, details=details)
66- self.result.stopTest(test)
67- finally:
68- self.semaphore.release()
69+ self._add_result_with_semaphore(self.result.addFailure,
70+ test, err, details=details)
71
72 def addSkip(self, test, reason=None, details=None):
73- self.semaphore.acquire()
74- try:
75- self.result.startTest(test)
76- self.result.addSkip(test, reason, details=details)
77- self.result.stopTest(test)
78- finally:
79- self.semaphore.release()
80+ self._add_result_with_semaphore(self.result.addSkip,
81+ test, reason, details=details)
82
83 def addSuccess(self, test, details=None):
84- self.semaphore.acquire()
85- try:
86- self.result.startTest(test)
87- self.result.addSuccess(test, details=details)
88- self.result.stopTest(test)
89- finally:
90- self.semaphore.release()
91+ self._add_result_with_semaphore(self.result.addSuccess,
92+ test, details=details)
93
94 def addUnexpectedSuccess(self, test, details=None):
95- self.semaphore.acquire()
96- try:
97- self.result.startTest(test)
98- self.result.addUnexpectedSuccess(test, details=details)
99- self.result.stopTest(test)
100- finally:
101- self.semaphore.release()
102+ self._add_result_with_semaphore(self.result.addUnexpectedSuccess,
103+ test, details=details)
104
105 def startTestRun(self):
106 self.semaphore.acquire()
107@@ -375,6 +360,15 @@
108 finally:
109 self.semaphore.release()
110
111+ def startTest(self, test):
112+ test._testtools_time_of_startTest = self._now()
113+ super(ThreadsafeForwardingResult, self).startTest(test)
114+
115+ def time(self, a_datetime):
116+ self._use_timings = True
117+ self.time = super(ThreadsafeForwardingResult, self).time
118+ self.time(a_datetime)
119+
120
121 class ExtendedToOriginalDecorator(object):
122 """Permit new TestResult API code to degrade gracefully with old results.
123
124=== modified file 'testtools/tests/helpers.py'
125--- testtools/tests/helpers.py 2009-12-31 03:15:19 +0000
126+++ testtools/tests/helpers.py 2010-09-27 20:41:03 +0000
127@@ -62,6 +62,10 @@
128 self._events.append('done')
129 super(LoggingResult, self).done()
130
131+ def time(self, a_datetime):
132+ self._events.append(('time', a_datetime))
133+ super(LoggingResult, self).time(a_datetime)
134+
135 # Note, the following three classes are different to LoggingResult by
136 # being fully defined exact matches rather than supersets.
137 from testtools.testresult.doubles import *
138
139=== modified file 'testtools/tests/test_testresult.py'
140--- testtools/tests/test_testresult.py 2010-08-04 14:59:32 +0000
141+++ testtools/tests/test_testresult.py 2010-09-27 20:41:03 +0000
142@@ -419,7 +419,7 @@
143
144
145 class TestThreadSafeForwardingResult(TestWithFakeExceptions):
146- """Tests for `MultiTestResult`."""
147+ """Tests for `TestThreadSafeForwardingResult`."""
148
149 def setUp(self):
150 TestWithFakeExceptions.setUp(self)
151@@ -472,6 +472,20 @@
152 ('stopTest', self),
153 ], self.target._events)
154
155+ def test_times(self):
156+ starttime = datetime.datetime.utcfromtimestamp(1.489)
157+ endtime = datetime.datetime.utcfromtimestamp(51.476)
158+ self.result1.time(starttime)
159+ self.result1.startTest(self)
160+ self.result1.time(endtime)
161+ self.result1.addSuccess(self)
162+ self.assertEqual([("time", starttime),
163+ ("startTest", self),
164+ ("time", endtime),
165+ ("addSuccess", self),
166+ ("stopTest", self),
167+ ], self.target._events)
168+
169
170 class TestExtendedToOriginalResultDecoratorBase(TestCase):
171

Subscribers

People subscribed via source and target branches