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.

[merwok]

Also, when you’re tracking down slow tests, you may want to run your tests with the time needed by each test file and then each test method.

Note that I don’t know of a way to have unittest print each test file to stdout now (i.e. a level of verbosity between “just one dot” and “each method”).

[pprokop]

I agree with Ezio,
this feature should have an option to enable/disable.

Anyway, I use it in different way.

Since 2008, I've used this feature for performance comparision, whether some implementation changes in application code did not slow down application. Tests run after each commit. I compare execution time of particular test before and after commit.

With additional scripts, I create metrics and charts using gnuplot to visualize how execution time of each test changed during the development.
I can ensure the performance stability of the application.

[voidspace]

I'm working on a modified version of the patch that is switched on with a command line option --timer=0.1 (or similar). Only tests that take longer than the threshold have the time printed. --timer=0 is valid, but it still only works when unittest is running with with verbose.

[techtonik]

pyunit_time.patch is invalid - missing space on the last line.

[giampaolo]

Hello. This is something I needed so I decided to implement it by taking inspiration from pytest's --durations=N argument, which basically does the same (except that it uses 0.XX precision instead of 0.XXX). PR at: #12271

[giampaolo]

I updated the PR for Python 3.9. I think it's ready to be merged. Can someone involved in unittest take a look at it?

[hugovk]

Closing, the PR has been merged: #12271 👍