Add test run duration #1038

fearphage · 2016-09-14T18:02:54Z

Changes

This does 2 new things:

Send test run duration to reporters
Show test duration in mini reporter (I added a utility to calculate this)

I added 2 properties to the runStatus:

testRunStart
testRunElapsed

Duration Utility

hrtimeToDuration - converts process.hrtime() to duration
httimeToDuration.duration - converts milliseconds to duration

Mini Reporter

In the mini reporter, I convert the hrtime back to a human-readable duration to show the end user. This could be added to any reporter, but I started with just this one.

Notes

Currently I'm calculating the elapsed time in two places (cli and watcher). The best place to calculate this was in the logger (Logger.prototype.finish). However the lgoger seems to be logic-less and a complete pass-through so I didn't want to add functionality there.

* Added test run start to cli * Added test run elapsed calculation to cli and watcher

fearphage · 2016-09-17T15:57:30Z

Restarting tests.

fearphage · 2016-09-17T15:59:48Z

Test failures are due to a change in Node v6.5 as outlined in #1028.

sotojuan · 2016-09-17T20:49:04Z

That PR has been merged! PS can I have some screenshots of this in action?

…un-duration

fearphage · 2016-09-17T21:24:58Z

Picture and text format:

➜  ava git:(add-test-run-duration) node cli.js --watch test/fixture/watcher/tap-in-conf/test.js test/fixture/watcher/tap-in-conf                                                                                                                               

  1 passed [16:21:22] (598.783ms)
  1 failed

  test › fails
  Test failed via t.fail()
    Test.fn (test.js:8:4)
    _combinedTickCallback (internal/process/next_tick.js:67:7)
    process._tickCallback (internal/process/next_tick.js:98:9)


───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────

  1 passed [16:21:22] (235.709ms)
  1 failed

  test › fails
  Test failed via t.fail()
    Test.fn (test.js:8:4)
    _combinedTickCallback (internal/process/next_tick.js:67:7)
    process._tickCallback (internal/process/next_tick.js:98:9)


───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────

  1 passed [16:21:32] (209.869ms)


^C%                                                                                                                                                                                                                                                            ➜  ava git:(add-test-run-duration) node cli.js test/fixture/pkg-conf/defaults                                                                                                                                                                                  

  1 passed (199.979ms)

➜  ava git:(add-test-run-duration) node cli.js test/fixture/long-running.js          

  2 passed (5.202s)

sindresorhus · 2016-09-17T21:33:42Z

@fearphage Why do you need this? What problem does it solve? Why not just run $ time ava when you want to know the total test run time?

fearphage · 2016-09-17T21:49:31Z

What problem does it solve?

It shows you the total duration of a test run.

Why not just $ time ava when you want to know the total test run time?

How do you use that with --watch exactly?
time works horribly in windows (read: not at all).

Another problem with time is it includes the timings of the scaffolding and setup for ava itself as well as any tear down or waiting for file descriptors to close or whatever the case may be. I've tried to make this time measurement as close to the tests themselves running and finishing.

sindresorhus · 2016-09-17T22:02:54Z

It shows you the total duration of a test run.

That's the solution, not the problem. What will you do with the knowledge of the time it takes to run the test suite? Why do you need it on every run? I'm just trying to figure out why this is essential.

fearphage · 2016-09-17T22:15:23Z

That's the solution, not the problem.

The problem then is prior to this PR, I had no idea how long all the tests took to run together. There was information that is easily captured that was not being presented to me.

What will you do with the knowledge of the time it takes to run the test suite?

I don't fully understand what you're asking. I will do the same thing I do with the knowledge of the time it takes to run individual tests. That's currently a feature in ava today right now. Do you have a problem with that functionality as well? What's the difference between individual test times and suite run times?

Why do you need it on every run?

It's beneficial to be able to see at a glance the length of time a test suite takes to run.

I have a few questions for you. Why would you not want to see how long your tests take to run? What is it detracting from your code, tests, and/or life?

novemberborn · 2016-09-20T12:16:03Z

I will do the same thing I do with the knowledge of the time it takes to run individual tests. That's currently a feature in ava today right now.

It's been a summer without much AVA work for me so I might have forgotten, but IIRC we don't show individual test duration, do we?

I would be interested in surfacing which tests are exceedingly slow, in order to help users optimize their test suits. I'm not convinced outputting raw numbers is a sufficient solution, especially given the variability in host machine activity, process scheduling, and test concurrency.

sotojuan · 2016-09-20T12:59:22Z

We show individual test time and the actual time all tests finished in verbose mode.

novemberborn · 2016-09-20T13:10:25Z

I don't see individual test time in my verbose output.

sindresorhus · 2016-09-20T13:15:01Z

I don't fully understand what you're asking. I will do the same thing I do with the knowledge of the time it takes to run individual tests. That's currently a feature in ava today right now. Do you have a problem with that functionality as well? What's the difference between individual test times and suite run times?

That feature is there to expose slow tests. We only show it when the tests crosses a set threshold, which currently is 100ms. That's different from showing the total time. You can't do much about the total time unless you know the time of the individual tests.

I have a few questions for you. Why would you not want to see how long your tests take to run? What is it detracting from your code, tests, and/or life?

Because everything we add to the output creates noise and distracts from the other information. We are very conservative about adding things. The default AVA output is intentionally minimal. But we're happy to consider adding things if they have practical usefulness. Convince us ;)

sindresorhus · 2016-09-20T13:15:20Z

I don't see individual test time in my verbose output.

Only for slow tests. >100ms.

sindresorhus · 2016-09-20T13:16:47Z

lib/watcher.js

@@ -61,6 +61,8 @@ function Watcher(logger, api, files, sources) {
 		this.busy = api.run(specificFiles || files, {
 			runOnlyExclusive: runOnlyExclusive
 		}).then(function (runStatus) {
+			runStatus.testRunElapsed = runStatus.testRunStart && process.hrtime(runStatus.testRunStart);


No point in using process.hrtime(). Date.now() is more than accurate enough for this purpose.

Is this suggestion due to process not being supported in the browser or is there another reason? I'm just asking, because I'm curious.

My rationale for choosing hrtime over Date was providing the most amount of information to the reporters. One can always get milliseconds from nanoseconds, but the reverse is not true.

I think @sindresorhus is saying that Date.now() is accurate enough. I think that's true for this use case, no point optimizing test runs down to the nanosecond, and there is more cognitive overhead with hrtime.

That said I don't think there's much value in tracking test duration when in watch mode, especially since the number of test files run can vary greatly.

Updated.

That said I don't think there's much value in tracking test duration when in watch mode, especially since the number of test files run can vary greatly.

In that case, it's not very useful. When you're doing TDD or just updating a single test in general, it makes a lot more sense.

fearphage · 2016-09-20T18:39:37Z

You can't do much about the total time unless you know the time of the individual tests.

Fair enough. I feel like can do something with the deltas though. If before PR X, tests ran in 1 minute faster, that's a big deal.

Also do you want me to add duration to the other reporters?

novemberborn · 2016-09-21T09:40:48Z

I feel like can do something with the deltas though. If before PR X, tests ran in 1 minute faster, that's a big deal.

That's true. @avajs/core ?

I don't think there's much value in tracking test duration when in watch mode, especially since the number of test files run can vary greatly.

replaced process.hrtime() with Date.now()

sindresorhus · 2016-10-03T15:46:32Z

lib/duration.js

+	return round(ms) + 'ms';
+}
+
+module.exports = duration;


This could just be pretty-ms instead.

sindresorhus · 2016-10-03T15:51:36Z

I'm open to adding the test time to the verbose and TAP reporter, but I'm hesitant to add it to the mini-reporter. The mini-reporter is meant to be as simple as possible, and I personally don't see much value in the test time. And I agree with @novemberborn, no point in having it in watch mode.

fearphage · 2016-10-04T04:16:03Z

no point in having it in watch mode

What about adding an option for it? It's inconvenient to have to leave watch mode just to see how long the tests are taking.

What's the point of printing the timestamp in watch mode? Is it so you can see that things are changing at a glance? If that is the sole purpose, could this replace the timestamp? It's more useful in terms of testing than showing the time.

sindresorhus · 2016-10-06T04:15:04Z

What about adding an option for it? It's inconvenient to have to leave watch mode just to see how long the tests are taking.

@novemberborn already commented why showing total test time in watch mode is not useful.

What's the point of printing the timestamp in watch mode? Is it so you can see that things are changing at a glance? If that is the sole purpose, could this replace the timestamp? It's more useful in terms of testing than showing the time.

Yes, it's to see if something has changed, and no, total test time could not replace it for the same reason as above and the fact that the test time could be the same as previous and you would have to remember the previous test time to be sure it's different.

fearphage · 2016-10-06T05:50:59Z

@novemberborn already commented why showing total test time in watch mode is not useful.

Unless I'm missing it, @novemberborn only said s/he didn't find it useful. S/he did not elaborate on the why. Much like novermberborn, I have an opinion too. I believe it is useful. That's the reason I added it and the reason I expressed how inconvenient it would be to have to leave watch mode to figure out how long the tests were taking to run. I'm trying to see if there's a compromise that would allow it to remain in some form or another.

the fact that the test time could be the same as previous

This is a possibility. The lack of precision in the timing adds to that factor. Hitting the same millisecond is definitely possible. The same nanosecond is less probable.

and you would have to remember the previous test time to be sure it's different.

How does this differ from printing the timestamp? By printing the time, you have to remember the time it displayed last time you saw it or know what time it is now including seconds. Neither one of them let you know the tests just ran without using your memory or external factors.

sindresorhus · 2016-10-06T06:00:33Z

Unless I'm missing it, @novemberborn only said s/he didn't find it useful.

No, he said why it's objectively useless:

especially since the number of test files run can vary greatly.

This is a possibility. The lack of precision in the timing adds to that factor. Hitting the same millisecond is definitely possible. The same nanosecond is less probable.

This has nothing to do with precision. Even if we used nanosecond precision we would only show a prettified output to the user. Let's say a test takes 1.4243242 seconds to run the first time and 1.45435353 the second time, we would only show 1.4 second for each.

fearphage · 2016-10-06T06:26:36Z

objectively useless

I have a use for this "objectively useless" thing.

Even if we used nanosecond precision we would only show a prettified output to the user. Let's say a test takes 1.4243242 seconds to run the first time and 1.45435353 the second time, we would only show 1.4 second for each.

I had it setup for 3 decimal places so the output in your examples would be 1.424s and 1.454s respectively I believe.

sindresorhus · 2016-10-06T06:39:12Z

I have a use for this "objectively useless" thing.

Either you're not understanding how it's useless or you have a use-case you haven't being able to explain, but I feel this discussion is going nowhere. I would recommend focusing on what we're willing to do and not push this anymore unless you can actually come up with some convincing arguments not already exhausted ;)

I had it setup for 3 decimal places so the output in your examples would be 1.424s and 1.454s respectively I believe.

pretty-ms converts it to 1.4, which is what we want.

fearphage · 2016-10-06T08:34:55Z

pretty-ms converts it to 1.4, which is what we want.

the fact that the test time could be the same as previous

This has nothing to do with precision.

pretty-ms in its current configuration increases the likelihood of repeated output. You cited repetitious output as a problem. You also said this has nothing to do with precision. However as you increase the precision, repeated output becomes less likely. So it directly addresses one of the problems that you cited. I don't understand why you're saying it has nothing to do with this.

Either you're not understanding how it's useless or you have a use-case you haven't being able to explain

Really?! Since I already explained the use case a few weeks ago, I guess it's the former in this false dichotomy. Are you going to elaborate on the uselessness of my use case? Help me understand how useless it really is.

sindresorhus · 2016-10-06T08:46:58Z

pretty-ms in its current configuration increases the likelihood of repeated output. You cited repetitious output as a problem. You also said this has nothing to do with precision. However as you increase the precision, repeated output becomes less likely. So it directly addresses one of the problems that you cited. I don't understand why you're saying it has nothing to do with this.

Already said this, but I guess I can repeat myself again, we want it to be 1.4, not 1.424s. I do realize more precise output would make one of my arguments less relevant, but that's irrelevant as it's not something we want.

Really?! Since I already explained the use case a few weeks ago, I guess it's the former in this false dichotomy. Are you going to elaborate on the uselessness of my use case? Help me understand how useless it really is.

You want the total test run time so you can use the deltas to see if it became faster or slower, but watch mode only runs tests that changed or had their source change, so the delta is not constant, making it useless for this use-case, as the time will vary greatly depending on what tests/sources changed.

fearphage · 2016-10-06T08:56:35Z

I do realize more precise output would make one of my arguments less relevant, but that's irrelevant as it's not something we want.

So it seems you do see what precision has to do with this. You prefer the opportunity for repetition more than you want precision. I understand. It seems unfair to complain about a situation that you requested.

watch mode only runs tests that changed or had their source change

That's precisely what I want. Imagine I'm writing useless-use-case.js and I'm writing a test and then writing the code to make the test pass. Then I refactor and my test time increases 30 seconds. That's a good time to revert the refactor, find the bug, or at a minimum mark the test as slow to remove it from the tdd flow. Do you understand now or is this equally useless in your objective opinion?

novemberborn · 2016-10-06T09:01:40Z

@fearphage given how watch mode functions I'm sceptical whether it'll actually deliver the information as reliably as you're expecting it to. I'm also wary it encourages micro-optimization of test runs.

Again, we're happy to have this in regular output since large performance regressions will surface that way, but at this point we don't want this for watch mode.

fearphage · 2016-10-06T09:05:10Z

I'm sceptical whether it'll actually deliver the information as reliably as you're expecting it to

Understandably so. I've been using it currently and it's delivering the expected results thus far.

Does ava support external reporters currently?

sindresorhus · 2016-10-06T09:07:16Z

Does ava support external reporters currently?

$ ava --tap and you can use any TAP-reporter, but it does not apply during watch mode, neither will it ever.

fearphage added 2 commits September 10, 2016 16:59

send test run duration to logger

856ac9a

* Added test run start to cli * Added test run elapsed calculation to cli and watcher

updated mini reporter to display test run duration

3cd32ab

fearphage closed this Sep 17, 2016

fearphage reopened this Sep 17, 2016

Merge branch 'master' of https://github.com/avajs/ava into add-test-r…

78962bb

…un-duration

sindresorhus requested changes Sep 20, 2016

View reviewed changes

decreased precision from nanoseconds to milliseconds

c870629

replaced process.hrtime() with Date.now()

sindresorhus requested changes Oct 3, 2016

View reviewed changes

sindresorhus force-pushed the master branch 2 times, most recently from 4bc021e to 476c653 Compare October 18, 2016 03:23

sindresorhus force-pushed the master branch 4 times, most recently from 8610723 to 4acb78f Compare November 22, 2016 17:46

novemberborn closed this Jan 17, 2017

sindresorhus mentioned this pull request Oct 2, 2017

update verbose.js to show total duration #1539

Closed

Add test run duration #1038

Add test run duration #1038

Uh oh!

Conversation

fearphage commented Sep 14, 2016

Changes

Duration Utility

Mini Reporter

Notes

Uh oh!

fearphage commented Sep 17, 2016

Uh oh!

fearphage commented Sep 17, 2016

Uh oh!

sotojuan commented Sep 17, 2016

Uh oh!

fearphage commented Sep 17, 2016

Uh oh!

sindresorhus commented Sep 17, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

fearphage commented Sep 17, 2016

Uh oh!

sindresorhus commented Sep 17, 2016

Uh oh!

fearphage commented Sep 17, 2016

Uh oh!

novemberborn commented Sep 20, 2016

Uh oh!

sotojuan commented Sep 20, 2016

Uh oh!

novemberborn commented Sep 20, 2016

Uh oh!

sindresorhus commented Sep 20, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

sindresorhus commented Sep 20, 2016

Uh oh!

sindresorhus Sep 20, 2016

Choose a reason for hiding this comment

Uh oh!

fearphage Sep 20, 2016

Choose a reason for hiding this comment

Uh oh!

fearphage Sep 26, 2016

Choose a reason for hiding this comment

Uh oh!

novemberborn Sep 26, 2016

Choose a reason for hiding this comment

Uh oh!

fearphage Sep 29, 2016

Choose a reason for hiding this comment

Uh oh!

fearphage commented Sep 20, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

novemberborn commented Sep 21, 2016

Uh oh!

sindresorhus Oct 3, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

sindresorhus commented Oct 3, 2016

Uh oh!

fearphage commented Oct 4, 2016

Uh oh!

sindresorhus commented Oct 6, 2016

Uh oh!

fearphage commented Oct 6, 2016

Uh oh!

sindresorhus commented Oct 6, 2016

Uh oh!

fearphage commented Oct 6, 2016

Uh oh!

sindresorhus commented Oct 6, 2016

Uh oh!

fearphage commented Oct 6, 2016

Uh oh!

sindresorhus commented Oct 6, 2016

Uh oh!

sindresorhus commented Sep 17, 2016 •

edited

Loading

sindresorhus commented Sep 20, 2016 •

edited

Loading

fearphage commented Sep 20, 2016 •

edited

Loading

sindresorhus Oct 3, 2016 •

edited

Loading

fearphage commented Oct 6, 2016 •

edited

Loading