search

mahmoudimus / nose-timer

A timer plugin for nosetests (how much time does every test take?)
MIT License
126 stars 33 forks source link

Benchmark results change formatting mid-run #75

Closed DavidCsordas closed 8 years ago

DavidCsordas commented 8 years ago

Found that running a test suite with verbose=3 outputs the benchmark results in two different ways (regardless if evaluated as ok/warning/error), switching between them halfway through (even including an empty newline):

`test_some.Test.test ... ok (0.0001s)

test_other.Test.test: 0.4821s`

I haven't found anything about output formatting options in the README.

skudriashev commented 8 years ago

@DavidCsordas, please specify command you run. Thanks.

DavidCsordas commented 8 years ago

--with-timer

skudriashev commented 8 years ago

I have this:

nosetests --verbosity=3 --with-timer tests
nose.config: INFO: Ignoring files matching ['^\\.', '^_', '^setup\\.py$']
test_colored_time_0 (tests.test_plugin.TestTimerPlugin) ... ok (0.0007s)
test_colored_time_1 (tests.test_plugin.TestTimerPlugin) ... ok (0.0006s)
test_colored_time_2 (tests.test_plugin.TestTimerPlugin) ... ok (0.0006s)
test_colored_time_3 (tests.test_plugin.TestTimerPlugin) ... ok (0.0008s)
test_colored_time_4 (tests.test_plugin.TestTimerPlugin) ... ok (0.0006s)
test_configure (tests.test_plugin.TestTimerPlugin) ... ok (0.0022s)
test_no_color_option (tests.test_plugin.TestTimerPlugin) ... ok (0.0005s)
test_options (tests.test_plugin.TestTimerPlugin) ... ok (0.0008s)
test_parse_time_0_1 (tests.test_plugin.TestTimerPlugin) ... ok (0.0005s)
test_parse_time_1_2s (tests.test_plugin.TestTimerPlugin) ... ok (0.0005s)
test_parse_time_2_500ms (tests.test_plugin.TestTimerPlugin) ... ok (0.0003s)
test_parse_time_called_0_timer_ok (tests.test_plugin.TestTimerPlugin) ... ok (0.0020s)
test_parse_time_called_1_timer_warning (tests.test_plugin.TestTimerPlugin) ... ok (0.0027s)
test_parse_time_error (tests.test_plugin.TestTimerPlugin) ... ok (0.0003s)
test_time_taken (tests.test_plugin.TestTimerPlugin) ... ok (0.0004s)

tests.test_plugin.TestTimerPlugin.test_parse_time_called_1_timer_warning: 0.0027s
tests.test_plugin.TestTimerPlugin.test_configure: 0.0022s
tests.test_plugin.TestTimerPlugin.test_parse_time_called_0_timer_ok: 0.0020s
tests.test_plugin.TestTimerPlugin.test_options: 0.0008s
tests.test_plugin.TestTimerPlugin.test_colored_time_3: 0.0008s
tests.test_plugin.TestTimerPlugin.test_colored_time_0: 0.0007s
tests.test_plugin.TestTimerPlugin.test_colored_time_2: 0.0006s
tests.test_plugin.TestTimerPlugin.test_colored_time_4: 0.0006s
tests.test_plugin.TestTimerPlugin.test_colored_time_1: 0.0006s
tests.test_plugin.TestTimerPlugin.test_parse_time_1_2s: 0.0005s
tests.test_plugin.TestTimerPlugin.test_no_color_option: 0.0005s
tests.test_plugin.TestTimerPlugin.test_parse_time_0_1: 0.0005s
tests.test_plugin.TestTimerPlugin.test_time_taken: 0.0004s
tests.test_plugin.TestTimerPlugin.test_parse_time_error: 0.0003s
tests.test_plugin.TestTimerPlugin.test_parse_time_2_500ms: 0.0003s
----------------------------------------------------------------------
Ran 15 tests in 0.015s

OK

This doesn't look wrong.

DavidCsordas commented 8 years ago

Thanks, you've actually reproduced the issue there:

`test_time_taken (tests.test_plugin.TestTimerPlugin) ... ok (0.0004s)

tests.test_plugin.TestTimerPlugin.test_parse_time_called_1_timer_warning: 0.0027s`

If you say this is normal behavior, could you drop any hint on why this actually happens? Documentations has not a single word on this.

skudriashev commented 8 years ago

@DavidCsordas, first block is output from normal nosetests command run (with times). Second block is output from the timer plugin itself (sorted by times).

DavidCsordas commented 8 years ago

@skudriashev I see, thanks. This is a non-issue then.