classification
Title: unittest: display time used by each test case
Type: enhancement Stage: patch review
Components: Library (Lib), Tests Versions: Python 3.9
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: eric.araujo, ezio.melotti, giampaolo.rodola, michael.foord, piotr.dobrogost, pprokop, rhettinger, techtonik
Priority: normal Keywords: patch

Created on 2008-10-08 20:28 by pprokop, last changed 2020-02-16 12:49 by giampaolo.rodola.

Files
File name Uploaded Description Edit
pyunit_time.patch pprokop, 2008-10-08 20:28 display time of each unit test - patch
unittest_runTime.patch pprokop, 2009-11-14 19:00 test case run time measure patch review
Pull Requests
URL Status Linked Edit
PR 12271 open giampaolo.rodola, 2019-03-11 05:22
Messages (17)
msg74545 - (view) Author: Pawel Prokop (pprokop) Date: 2008-10-08 20:28
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?
msg87989 - (view) Author: Michael Foord (michael.foord) * (Python committer) Date: 2009-05-17 11:28
Needs test and documentation. Otherwise looks good.
msg95253 - (view) Author: Pawel Prokop (pprokop) Date: 2009-11-14 19:00
Repack of unittest was good idea. It is a patch against trunk, one test
case is provided and documentation update.
msg109448 - (view) Author: Ezio Melotti (ezio.melotti) * (Python committer) Date: 2010-07-07 01:57
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).
msg110692 - (view) Author: Mark Lawrence (BreamoreBoy) * Date: 2010-07-18 21:46
Pawel, could you please provide an update wrt Ezio's comment on msg109448, thanks.
msg110800 - (view) Author: Pawel Prokop (pprokop) Date: 2010-07-19 19:13
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
msg110883 - (view) Author: Michael Foord (michael.foord) * (Python committer) Date: 2010-07-20 11:01
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.
msg154650 - (view) Author: Piotr Dobrogost (piotr.dobrogost) Date: 2012-02-29 16:53
@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?
msg154678 - (view) Author: Raymond Hettinger (rhettinger) * (Python committer) Date: 2012-03-01 07:47
I think this would be a useful feature.
msg154687 - (view) Author: Michael Foord (michael.foord) * (Python committer) Date: 2012-03-01 11:11
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?
msg154769 - (view) Author: Ezio Melotti (ezio.melotti) * (Python committer) Date: 2012-03-02 15:27
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.
msg154771 - (view) Author: Éric Araujo (eric.araujo) * (Python committer) Date: 2012-03-02 15:36
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.

Nite 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”).
msg154776 - (view) Author: Pawel Prokop (pprokop) Date: 2012-03-02 16:23
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.
msg155721 - (view) Author: Michael Foord (michael.foord) * (Python committer) Date: 2012-03-14 05:33
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.
msg176157 - (view) Author: anatoly techtonik (techtonik) Date: 2012-11-23 09:10
pyunit_time.patch is invalid - missing space on the last line.
msg337648 - (view) Author: Giampaolo Rodola' (giampaolo.rodola) * (Python committer) Date: 2019-03-11 05:24
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: https://github.com/python/cpython/pull/12271
msg362067 - (view) Author: Giampaolo Rodola' (giampaolo.rodola) * (Python committer) Date: 2020-02-16 12:49
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?
History
Date User Action Args
2020-02-16 12:49:33giampaolo.rodolasetmessages: + msg362067
2020-02-15 15:45:30giampaolo.rodolasetversions: + Python 3.9, - Python 3.8
2019-03-11 05:24:21giampaolo.rodolasetmessages: + msg337648
versions: + Python 3.8, - Python 3.3
2019-03-11 05:22:40giampaolo.rodolasetpull_requests: + pull_request12254
2014-02-03 15:51:18BreamoreBoysetnosy: - BreamoreBoy
2013-09-17 07:43:10giampaolo.rodolasetnosy: + giampaolo.rodola
2012-11-23 09:10:57techtoniksetnosy: + techtonik
messages: + msg176157
2012-03-14 05:33:46michael.foordsetmessages: + msg155721
2012-03-02 16:23:08pprokopsetmessages: + msg154776
2012-03-02 15:36:39eric.araujosettitle: unittest: display time of each test case -> unittest: display time used by each test case
messages: + msg154771
versions: + Python 3.3, - Python 3.2
2012-03-02 15:27:34ezio.melottisetmessages: + msg154769
2012-03-01 11:11:34michael.foordsetmessages: + msg154687
2012-03-01 07:47:20rhettingersetnosy: + rhettinger
messages: + msg154678
2012-03-01 07:40:28eric.araujosetnosy: + eric.araujo

title: pyunit - display time of each test case - patch -> unittest: display time of each test case
2012-02-29 16:53:35piotr.dobrogostsetnosy: + piotr.dobrogost
messages: + msg154650
2010-07-20 11:01:22michael.foordsetmessages: + msg110883
2010-07-19 19:13:07pprokopsetmessages: + msg110800
2010-07-18 21:46:27BreamoreBoysetnosy: + BreamoreBoy
messages: + msg110692
2010-07-07 01:57:49ezio.melottisetversions: - 3rd party, Python 2.7
nosy: + ezio.melotti

messages: + msg109448

stage: test needed -> patch review
2009-11-14 19:00:30pprokopsetfiles: + unittest_runTime.patch

messages: + msg95253
2009-05-17 11:28:46michael.foordsetmessages: + msg87989
2009-05-17 02:43:18ajaksu2setversions: + Python 2.7, Python 3.2
nosy: + michael.foord

priority: normal
components: + Library (Lib), Tests, - None
stage: test needed
2008-10-08 20:28:15pprokopcreate