Test elapsed times being significantly under-reported when run in parallel (via Django's --parallel option)
#229
Comments
|
I've just seen #228, which looks somewhat related in that it fixes an issue with test times being under-reported. However the fix there doesn't seem to resolve this issue, when I use that branch from my project I still see test runtimes that are too low when I use |
bobwhitelock
changed the title
--parallel option)--parallel option)
|
I've had a chance to investigate this issue a bit more, here's some brief notes on what I found:
from django_slowtests.testrunner import DiscoverSlowestTestsRunner
from xmlrunner import XMLTestRunner
from xmlrunner.extra.djangotestrunner \
import XMLTestRunner as DjangoXMLTestRunner
from xmlrunner.result import _XMLTestResult, _TestInfo
class CustomXMLTestRunner(XMLTestRunner):
def __init__(self, *args, get_timings, **kwargs):
super().__init__(*args, **kwargs)
self.get_timings = get_timings
self.resultclass = CustomTestResult
class CustomTestResult(_XMLTestResult):
def __init__(self, *args, **kwargs):
super().__init__(*args, **kwargs)
self.infoclass = CustomTestInfo
def generate_reports(self, test_runner):
timings = dict(test_runner.get_timings())
# This section is borrowed from
# `xmlrunner.result._XMLTestResult._get_info_by_testcase`, with just
# `elapsed_time =` line added.
for tests in (
self.successes,
self.failures,
self.errors,
self.skipped,
self.expectedFailures,
self.unexpectedSuccesses
):
for test_info in tests:
if isinstance(test_info, tuple):
# This is a skipped, error or a failure test case
test_info = test_info[0]
test_info.elapsed_time = timings[test_info.test_method_name]
return super().generate_reports(test_runner)
class CustomTestInfo(_TestInfo):
def __init__(self, test_result, test_method, *args, **kwargs):
super().__init__(test_result, test_method, *args, **kwargs)
self.test_method_name = str(test_method)
class CustomTestRunner(DjangoXMLTestRunner, DiscoverSlowestTestsRunner):
test_runner = CustomXMLTestRunner
def get_test_runner_kwargs(self):
super_kwargs = super().get_test_runner_kwargs()
super_kwargs['get_timings'] = self.get_timings
return super_kwargs |
|
I've logged a Django bug report for the underlying issue here: https://code.djangoproject.com/ticket/32140 |
|
Hi @bobwhitelock , it's unclear to me if this is just for tracking or if you are looking for a fix to happen in |
|
@dnozay From my investigation above and the discussion in https://code.djangoproject.com/ticket/32140, I believe this is a bug with the elapsed time reporting of This can be worked around by installing another library ( It seems to me like it would be best to fix this in this library so it works as expected without workarounds and for all versions of Django. However since a workaround is possible I don't think this is a crucial issue to prioritise, for me at least. |
I have an existing Django project with many tests, and which uses
xmlrunner.extra.djangotestrunner.XMLTestRunnerfrom this project as the test runner. I'm using version 3.0.4 of this library on Python 3.7.4.If I create a file like this in this project:
And then run all the tests for this app in serial, I see this result:
I.e. the test is recorded as taking just over 3 seconds, as expected.
If I run the tests in parallel via Django's
--paralleloption, which will run the tests across all 8 cores of my laptop by default, I see this result:I.e. the test is recorded as having run significantly, and impossibly, faster. I see similar behaviour across almost every test in my test suite when I run them using
--parallel.I need to investigate more, but my current guess is that this is due to some interaction between different tests running in parallel, and the start and end times from different tests often end up being used to calculate the elapsed time for tests.
Would be happy to help with a fix, but would be interested if anyone can reproduce/if you know why this is happening/if you have any suggestions for how best to fix? Thanks!
The text was updated successfully, but these errors were encountered: