unittest: display time used by each test case

[pprokop]

BPO	4080
Nosy	@rhettinger, @giampaolo, @ezio-melotti, @merwok, @voidspace
PRs	bpo-4080: unittest durations #12271
Files	pyunit_time.patch: display time of each unit test - patch unittest_runTime.patch: test case run time measure patch

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = None
created_at = <Date 2008-10-08.20:28:15.274>
labels = ['tests', 'type-feature', 'library', '3.9']
title = 'unittest: display time used by each test case'
updated_at = <Date 2020-02-16.12:49:33.700>
user = 'https://bugs.python.org/pprokop'

bugs.python.org fields:

activity = <Date 2020-02-16.12:49:33.700>
actor = 'giampaolo.rodola'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['Library (Lib)', 'Tests']
creation = <Date 2008-10-08.20:28:15.274>
creator = 'pprokop'
dependencies = []
files = ['11751', '15332']
hgrepos = []
issue_num = 4080
keywords = ['patch']
message_count = 17.0
messages = ['74545', '87989', '95253', '109448', '110692', '110800', '110883', '154650', '154678', '154687', '154769', '154771', '154776', '155721', '176157', '337648', '362067']
nosy_count = 8.0
nosy_names = ['rhettinger', 'techtonik', 'giampaolo.rodola', 'ezio.melotti', 'eric.araujo', 'pprokop', 'michael.foord', 'piotr.dobrogost']
pr_nums = ['12271']
priority = 'normal'
resolution = None
stage = 'patch review'
status = 'open'
superseder = None
type = 'enhancement'
url = 'https://bugs.python.org/issue4080'
versions = ['Python 3.9']

Linked PRs

• gh-48330: assert warning is emitted on unittest.TestResult with no addDuration #103309
• gh-48330: address review comments to PR-12271 #103209

[pprokop]

I've needed to measure each unit test running time
to measure the performance changing of each functionality
that every test case tests.
Latest version of pyunit has only displayed summary running time of the
suite, so I've implemented small enhancement to unittest.py that
(in verbose mode) shows time of each test case run.
Maybe that would be usefull for anybody else?

[voidspace]

Needs test and documentation. Otherwise looks good.

[pprokop]

Repack of unittest was good idea. It is a patch against trunk, one test
case is provided and documentation update.

[ezio-melotti]

The idea is interesting, but I would prefer to have a way to enable/disable this feature (and maybe even specify its format, e.g. the number of decimals). Moving the logic to an external function (possibly used as a decorator) might avoid some code duplication, but OTOH it would probably slow down the execution and the timing a little (I'm not sure that matters though).

[BreamoreBoy]

Pawel, could you please provide an update wrt Ezio's comment on msg109448, thanks.

[pprokop]

I think that a delay time of calling a decorator is not important, because this should be constant in each test execution, so no matter.
I shall be able to provide a patch in few days.
Thanks

[voidspace]

I am in the process of creating an extension mechanism for unittest which will make adding this sort of use case to unittest much easier. *Even* if it is added to the core it should be in the form of an extension (plugin) so please don't update the patch until this is in place.

[piotrdobrogost]

@michael Foord

I am in the process of creating an extension mechanism for unittest
which will make adding this sort of use case to unittest much easier

How is it going?

[rhettinger]

I think this would be a useful feature.

[voidspace]

Yes, it would definitely be useful (as would a count of how far through the test run we are [27/129] style). Getting to completing (even for testing) the "extensible" unittest is something I will still do (and nose2 is being built off the prototype work I did), but isn't going to happen immediately - so it's not a good reason to hold up these improvements.

I'll be sprinting at PyCon and look at this issue then.

I'm keen to avoid proliferating command line parameters to the unittest test runner. Ezio - why would you want to disable this feature?

[ezio-melotti]

Because it looks like line noise and doesn't provide an useful information in most of the cases (at least for me), see e.g.:

+ test_format (main.MyTestCase) ... [0.000612s] skipped 'not supported in this library version'
+ test_nothing (main.MyTestCase) ... [0.000486s] skipped 'demonstrating skipping'
+ test_windows_support (main.MyTestCase) ... [0.000090s] skipped 'requires Windows'

It might still be useful to find the slowest test(s), or for test suites that take a long time (so I'm not opposed to having it as an option that can be enabled if needed), but for most of the tests it will just show an almost meaningless fraction of second.