Tasty progress reporting #311

coot · 2021-09-12T09:30:46Z

This PR is an updated and cleaned version of #245.

The upstream version introduced a bug which prevented quickcheck properties to
be shrinked. The approach in this PR avoids that by using QuickCheck
facilities to print its own progress using tasty progress callback.

Progress reporting ability.
quickcheck: print progress
Added --no-progress option
clean code

UnkindPartition · 2021-09-13T09:12:47Z

That's so cool! I'll try to take a look this week.

UnkindPartition · 2021-09-15T16:59:28Z

Thanks again for doing this. FYI, I rebased your branch and added some changes at try-adding-progress-rpt in this repo, so please use that as a base for any future work.

Unfortunately, with this implementation the performance seems to suffer. As a benchmark, I used the example program from the readme, which I run with ./example -p '/QuickCheck/&&/Fermat'\''s little theorem/' --quickcheck-tests=1000000.

Here's what I observe:

Version	Time
master	1.25s
try-adding-progress-rpt	1.7s
try-adding-progress-rpt --no-progress	1.7s

This is especially acute since long-running tests are exactly those where you want to see the progress but also care about how long they take. (This is after I fixed a spinning loop — the original slowdown was over 2x.)

In order for --no-progress be more effective, we should move the check earlier, e.g. to the executeTest, so that the progress is never updated in the first place I think.

But even with progress, we should try to optimize this, as this will be the default behavior.

It'd be also interesting to measure whether raw QuickCheck itself has a comparable slowdown from printing the progress.

coot · 2022-01-20T19:48:53Z

I don't see much difference when I remove --no-progress. On my system both take roughly the same 1.41s plus minus 0.01s. I checked with ghc-8.10.7 and ghc-9.2.1.

coot · 2022-01-20T20:19:03Z

I was comparing to a wrong commit, I can reproduce similar results.

coot · 2022-01-20T21:17:47Z

I made a profile build of the example and it looks like the difference in performance is coming from showTestCount function (in QuickCheck). In both try-adding-progress-rpt with and without --no-progress it accounts for ~3.4% time and ~8.5% of allocations, when running on master branch it does not show up at all.

master

	Thu Jan 20 21:39 2022 Time and Allocation Profiling Report  (Final)

	   example +RTS -p -RTS -p /QuickCheck/&&/Fermat's little theorem/ --quickcheck-tests=1000000

	total time  =        2.99 secs   (2993 ticks @ 1000 us, 1 processor)
	total alloc = 7,312,010,960 bytes  (excludes profiling overheads)

COST CENTRE             MODULE                     SRC                                               %time %alloc

runATest                Test.QuickCheck.Test       src/Test/QuickCheck/Test.hs:(335,1)-(410,37)       25.3   15.3
mapProp                 Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:351:1-55           11.0   19.6
qcProps.\               Main                       /tmp/example.hs:32:13-47                            7.9    2.4
shrinking               Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:(368,1)-(371,73)    5.8    9.0
protect                 Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:190:1-48            4.6    3.8
tryEvaluateIO           Test.QuickCheck.Exception  src/Test/QuickCheck/Exception.hs:(60,1)-(66,47)     4.4    3.6
promote                 Test.QuickCheck.Gen.Unsafe src/Test/QuickCheck/Gen/Unsafe.hs:(28,1)-(30,23)    4.1    3.3
joinRose                Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:(206,1)-(210,35)    4.0    8.4
reduceRose              Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:(232,1)-(233,40)    3.4    1.5
protectRose             Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:243:1-54            2.9    1.3
counterexample          Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:(384,1)-(388,28)    2.5    4.5
chooseInt64             Test.QuickCheck.Gen        src/Test/QuickCheck/Gen.hs:(209,1)-(216,49)         2.3    2.3
sized                   Test.QuickCheck.Gen        src/Test/QuickCheck/Gen.hs:114:1-52                 1.8    1.4
splitSMGen              System.Random.SplitMix     src/System/Random/SplitMix.hs:(225,1)-(229,31)      1.7    7.2
bitmaskWithRejection64' System.Random.SplitMix     src/System/Random/SplitMix.hs:(338,1)-(344,27)      1.6    1.6
suchThatMaybe           Test.QuickCheck.Gen        src/Test/QuickCheck/Gen.hs:(262,1)-(268,52)         1.6    2.0
delay                   Test.QuickCheck.Gen.Unsafe src/Test/QuickCheck/Gen/Unsafe.hs:36:1-37           1.5    1.3
test                    Test.QuickCheck.Test       src/Test/QuickCheck/Test.hs:(278,1)-(284,17)        1.4    0.3
protectResults          Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:(251,1)-(254,45)    1.3    0.9
computeSize             Test.QuickCheck.State      src/Test/QuickCheck/State.hs:25:5-15                1.2    0.2
protectProp             Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:247:1-67            1.1    1.1
suchThat                Test.QuickCheck.Gen        src/Test/QuickCheck/Gen.hs:(247,1)-(251,63)         1.1    0.9
chooseBoundedIntegral   Test.QuickCheck.Gen        src/Test/QuickCheck/Gen.hs:(168,1)-(182,31)         1.1    1.3
callback                Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:380:1-76            0.8    2.4
nextWord64              System.Random.SplitMix     src/System/Random/SplitMix.hs:(121,1)-(123,29)      0.1    1.3

example-master.prof

try-adding-progress-rpt

	Thu Jan 20 21:36 2022 Time and Allocation Profiling Report  (Final)

	   example +RTS -p -RTS -p /QuickCheck/&&/Fermat's little theorem/ --quickcheck-tests=1000000

	total time  =        3.48 secs   (3475 ticks @ 1000 us, 1 processor)
	total alloc = 9,956,148,768 bytes  (excludes profiling overheads)

COST CENTRE             MODULE                     SRC                                               %time %alloc

runATest                Test.QuickCheck.Test       src/Test/QuickCheck/Test.hs:(335,1)-(410,37)       24.9   18.3
mapProp                 Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:351:1-55            8.1   14.4
qcProps.\               Main                       /tmp/example.hs:32:13-47                            6.6    1.8
shrinking               Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:(368,1)-(371,73)    4.9    6.6
tryEvaluateIO           Test.QuickCheck.Exception  src/Test/QuickCheck/Exception.hs:(60,1)-(66,47)     4.2    2.3
joinRose                Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:(206,1)-(210,35)    4.2    6.2
number                  Test.QuickCheck.Text       src/Test/QuickCheck/Text.hs:67:1-61                 4.0    9.5
showTestCount           Test.QuickCheck.Test       src/Test/QuickCheck/Test.hs:(328,1)-(332,13)        3.4    8.5
promote                 Test.QuickCheck.Gen.Unsafe src/Test/QuickCheck/Gen/Unsafe.hs:(28,1)-(30,23)    3.2    2.4
newTerminal             Test.QuickCheck.Text       src/Test/QuickCheck/Text.hs:(166,1)-(169,40)        3.1    1.3
protect                 Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:190:1-48            2.6    2.4
reduceRose              Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:(232,1)-(233,40)    2.3    1.0
counterexample          Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:(384,1)-(388,28)    2.2    3.3
putTemp                 Test.QuickCheck.Text       src/Test/QuickCheck/Text.hs:(224,1)-(229,30)        2.2    2.0
protectRose             Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:243:1-54            2.0    0.8
chooseInt64             Test.QuickCheck.Gen        src/Test/QuickCheck/Gen.hs:(209,1)-(216,49)         2.0    1.7
delay                   Test.QuickCheck.Gen.Unsafe src/Test/QuickCheck/Gen/Unsafe.hs:36:1-37           1.7    1.0
suchThatMaybe           Test.QuickCheck.Gen        src/Test/QuickCheck/Gen.hs:(262,1)-(268,52)         1.7    1.4
bitmaskWithRejection64' System.Random.SplitMix     src/System/Random/SplitMix.hs:(338,1)-(344,27)      1.5    1.2
sized                   Test.QuickCheck.Gen        src/Test/QuickCheck/Gen.hs:114:1-52                 1.5    1.0
test                    Test.QuickCheck.Test       src/Test/QuickCheck/Test.hs:(278,1)-(284,17)        1.4    0.2
chooseBoundedIntegral   Test.QuickCheck.Gen        src/Test/QuickCheck/Gen.hs:(168,1)-(182,31)         1.3    1.0
suchThat                Test.QuickCheck.Gen        src/Test/QuickCheck/Gen.hs:(247,1)-(251,63)         1.3    0.6
splitSMGen              System.Random.SplitMix     src/System/Random/SplitMix.hs:(225,1)-(229,31)      1.2    5.3
callback                Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:380:1-76            0.9    1.8

example-progress.prof

try-adding-progress-rpt --no-progress

	Thu Jan 20 22:07 2022 Time and Allocation Profiling Report  (Final)

	   example +RTS -p -RTS -p /QuickCheck/&&/Fermat's little theorem/ --quickcheck-tests=1000000 --no-progress

	total time  =        3.54 secs   (3543 ticks @ 1000 us, 1 processor)
	total alloc = 9,952,403,952 bytes  (excludes profiling overheads)

COST CENTRE             MODULE                     SRC                                               %time %alloc

runATest                Test.QuickCheck.Test       src/Test/QuickCheck/Test.hs:(335,1)-(410,37)       22.7   18.3
mapProp                 Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:351:1-55            9.0   14.4
qcProps.\               Main                       /tmp/example.hs:32:13-47                            6.6    1.8
shrinking               Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:(368,1)-(371,73)    5.2    6.6
number                  Test.QuickCheck.Text       src/Test/QuickCheck/Text.hs:67:1-61                 4.1    9.5
joinRose                Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:(206,1)-(210,35)    4.1    6.2
tryEvaluateIO           Test.QuickCheck.Exception  src/Test/QuickCheck/Exception.hs:(60,1)-(66,47)     4.0    2.3
protect                 Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:190:1-48            3.8    2.4
promote                 Test.QuickCheck.Gen.Unsafe src/Test/QuickCheck/Gen/Unsafe.hs:(28,1)-(30,23)    3.8    2.4
showTestCount           Test.QuickCheck.Test       src/Test/QuickCheck/Test.hs:(328,1)-(332,13)        3.2    8.5
reduceRose              Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:(232,1)-(233,40)    2.7    1.0
newTerminal             Test.QuickCheck.Text       src/Test/QuickCheck/Text.hs:(166,1)-(169,40)        2.5    1.3
chooseInt64             Test.QuickCheck.Gen        src/Test/QuickCheck/Gen.hs:(209,1)-(216,49)         2.3    1.7
counterexample          Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:(384,1)-(388,28)    2.2    3.3
putTemp                 Test.QuickCheck.Text       src/Test/QuickCheck/Text.hs:(224,1)-(229,30)        2.1    2.0
splitSMGen              System.Random.SplitMix     src/System/Random/SplitMix.hs:(225,1)-(229,31)      1.9    5.3
protectRose             Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:243:1-54            1.7    0.8
sized                   Test.QuickCheck.Gen        src/Test/QuickCheck/Gen.hs:114:1-52                 1.7    1.0
test                    Test.QuickCheck.Test       src/Test/QuickCheck/Test.hs:(278,1)-(284,17)        1.4    0.2
delay                   Test.QuickCheck.Gen.Unsafe src/Test/QuickCheck/Gen/Unsafe.hs:36:1-37           1.4    1.0
bitmaskWithRejection64' System.Random.SplitMix     src/System/Random/SplitMix.hs:(338,1)-(344,27)      1.3    1.2
protectResults          Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:(251,1)-(254,45)    1.3    0.6
suchThatMaybe           Test.QuickCheck.Gen        src/Test/QuickCheck/Gen.hs:(262,1)-(268,52)         1.2    1.4
computeSize             Test.QuickCheck.State      src/Test/QuickCheck/State.hs:25:5-15                1.1    0.2
suchThat                Test.QuickCheck.Gen        src/Test/QuickCheck/Gen.hs:(247,1)-(251,63)         1.1    0.6
chooseBoundedIntegral   Test.QuickCheck.Gen        src/Test/QuickCheck/Gen.hs:(168,1)-(182,31)         1.1    1.0
callback                Test.QuickCheck.Property   src/Test/QuickCheck/Property.hs:380:1-76            0.7    1.8

example-no-progress.prof

coot · 2022-01-20T22:37:22Z

Version	showTestCount (time / alloc)	putTemp (time / alloc)	newTerminal (time / alloc)
master	0.0 / 0.0	0.3 / 0.8	0.1 / 0.0
try-adding-progress-rpt	3.4 / 8.5	2.2 / 2.0	3.1 / 1.3
try-adding-progress-rpt --no-progress	3.2 / 8.5	2.1 / 2.0	2.5 / 1.3

From the flamegraphs:

it's clear that showTestCount and putTemp are responsible for 11% regression.

coot · 2023-04-30T09:07:50Z

Moving the no progress check to executeTest fixed the performance regression. Using progress is still 30/40% slower.

quickcheck/Test/Tasty/QuickCheck.hs

core/Test/Tasty/Core.hs

core/Test/Tasty/Ingredients/ConsoleReporter.hs

core/Test/Tasty/Options/Core.hs

core/Test/Tasty/Ingredients/ConsoleReporter.hs

core/Test/Tasty/Run.hs

core/Test/Tasty/Ingredients/ConsoleReporter.hs

coot · 2023-06-03T16:41:27Z

@Bodigrim I addressed your review remarks. I left a few unresolved, please check my comments.

core/CHANGELOG.md

quickcheck/CHANGELOG.md

core/Test/Tasty/Ingredients/ConsoleReporter.hs

Bodigrim · 2023-07-02T10:52:19Z

@coot I appreciate that this was a long haul, and you demonstrated incredible amount of patience. Do you think you might get time to finish this up soon? Or may I take over? I'm looking to make a release of tasty-1.5 in 2-3 weeks.

coot · 2023-07-03T07:39:42Z

I can address outstanding comments this week.

coot · 2023-07-08T08:54:31Z

@Bodigrim I addressed your review remarks.

Bodigrim

Almost there!

README.md

core/CHANGELOG.md

core/Test/Tasty/Ingredients/ConsoleReporter.hs

core/Test/Tasty/Options/Core.hs

Bodigrim · 2023-07-08T10:44:57Z

CC @martijnbastiaan for review.

martijnbastiaan

Very cool! I've got some minor suggestions.

core/Test/Tasty/Ingredients/ConsoleReporter.hs

quickcheck/CHANGELOG.md

Bodigrim · 2023-07-18T20:25:36Z

Unless there are any substantial objections, I'm going to merge this somewhere next week as is and fix outstanding issues in a subsequent PR.

andreasabel

I fixed CI after breaking it with modern haddock (needs haddock for GHC 8.6 or higher).

I suggest a short migration instruction for PrintTest (see comment).

core/CHANGELOG.md

There are bits that are still not very clever but it seems to work. I'm concerned about a performance hit from constantly thrashing the TVars and checking them all the time.

QuickCheck has its own progress information which shows number of test cases done so far and if a test fails also reports the number of shrinks. Tasty disables QuickCheck's output by setting 'chatty' option to 'False'. We can now feed this information to tasty progress reporting by defining how 'QuickCheck's speaks to a terminal.

Without these changes, I get multiple dots from QuickCheck on the terminal with --quickcheck-tests=1000000 Either of them suffices for a fix, but they both make sense.

And bumped version to 0.10.3.

This haddock is too old for parsing constructor field documentation.

Bodigrim · 2023-07-29T22:36:05Z

Thanks @coot and @mankyKitty!

andreasabel · 2023-09-10T16:33:31Z

quickcheck/Test/Tasty/QuickCheck.hs

+import qualified Test.QuickCheck.Test as QC
+import qualified Test.QuickCheck.State as QC
+import qualified Test.QuickCheck.Text as QC
+import Test.Tasty.Runners (formatMessage, emptyProgress)


Requires tasty >= 1.5.

This is reflected in the tasty-quickcheck.cabal file.

For the test-suite, yes, but if I understood #386 correctly it is also needed for the library.

coot mentioned this pull request Sep 12, 2021

Added quickcheck-chatty option #307

Closed

coot force-pushed the coot/try-adding-progress-rpt branch from 8bbea9e to ddc9e38 Compare September 12, 2021 12:04

coot force-pushed the coot/try-adding-progress-rpt branch from ddc9e38 to 7450612 Compare January 20, 2022 21:19

coot force-pushed the coot/try-adding-progress-rpt branch from 7450612 to b81d877 Compare April 30, 2023 08:27

coot mentioned this pull request Apr 30, 2023

Restore progress reporting ability. #245

Closed

3 tasks

Bodigrim reviewed May 1, 2023

View reviewed changes

quickcheck/Test/Tasty/QuickCheck.hs Show resolved Hide resolved

quickcheck/Test/Tasty/QuickCheck.hs Outdated Show resolved Hide resolved

quickcheck/Test/Tasty/QuickCheck.hs Show resolved Hide resolved

coot force-pushed the coot/try-adding-progress-rpt branch from 25f5e36 to 035bf29 Compare May 3, 2023 08:30

Bodigrim mentioned this pull request Jun 1, 2023

Add exact dependency matching #343

Merged

Bodigrim reviewed Jun 2, 2023

View reviewed changes

coot force-pushed the coot/try-adding-progress-rpt branch from 035bf29 to ce6a2e5 Compare June 3, 2023 16:39

coot force-pushed the coot/try-adding-progress-rpt branch from ce6a2e5 to ad6d91b Compare June 3, 2023 16:43

Bodigrim reviewed Jun 3, 2023

View reviewed changes

coot force-pushed the coot/try-adding-progress-rpt branch from ad6d91b to 749c4a7 Compare June 18, 2023 21:05

coot force-pushed the coot/try-adding-progress-rpt branch 2 times, most recently from ec5d7b5 to 1db3408 Compare July 8, 2023 08:53

coot force-pushed the coot/try-adding-progress-rpt branch from 1db3408 to 5e17fb1 Compare July 8, 2023 08:55

Bodigrim reviewed Jul 8, 2023

View reviewed changes

Bodigrim requested review from andreasabel and VictorCMiraldo July 8, 2023 10:44

martijnbastiaan reviewed Jul 13, 2023

View reviewed changes

core/Test/Tasty/Ingredients/ConsoleReporter.hs Outdated Show resolved Hide resolved

quickcheck/CHANGELOG.md Outdated Show resolved Hide resolved

andreasabel approved these changes Jul 19, 2023

View reviewed changes

core/CHANGELOG.md Outdated Show resolved Hide resolved

mankyKitty and others added 13 commits July 29, 2023 21:22

Progress reporting ability.

c6def8f

There are bits that are still not very clever but it seems to work. I'm concerned about a performance hit from constantly thrashing the TVars and checking them all the time.

Added --hide-progress option

22cc6c2

clean code

7b8c2c5

Misc cleanup

f3282b9

Avoid potential multi-line progress lines

417e9ad

Without these changes, I get multiple dots from QuickCheck on the terminal with --quickcheck-tests=1000000 Either of them suffices for a fix, but they both make sense.

Improve the performance by avoiding spinning in ppProgressOrResult

f0fcf30

Fixed performance regression when using --no-progress

bc4a788

Modify progress percent to cover the previous progress.

611b716

Updated tasty-quickcheck CHANGELOG.md file

1e488fb

And bumped version to 0.10.3.

Fix haddocks for Test.Tasty.Ingredients.ConsoleReporter.TestOutput

2b6ac07

Fix CI: turn off haddock step for GHC 8.4

7035f76

This haddock is too old for parsing constructor field documentation.

Final polishing

29f43a4

Bodigrim force-pushed the coot/try-adding-progress-rpt branch from cfbd282 to 29f43a4 Compare July 29, 2023 22:24

Bodigrim merged commit 959fe91 into UnkindPartition:master Jul 29, 2023
13 checks passed

coot deleted the coot/try-adding-progress-rpt branch July 30, 2023 08:01

Bodigrim mentioned this pull request Sep 10, 2023

tasty-quickcheck now requires tasty >= 1.5 #386

Merged

andreasabel reviewed Sep 10, 2023

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Tasty progress reporting #311

Tasty progress reporting #311

coot commented Sep 12, 2021

UnkindPartition commented Sep 13, 2021

UnkindPartition commented Sep 15, 2021

coot commented Jan 20, 2022

coot commented Jan 20, 2022

coot commented Jan 20, 2022

coot commented Jan 20, 2022 •

edited

coot commented Apr 30, 2023

coot commented Jun 3, 2023

Bodigrim commented Jul 2, 2023

coot commented Jul 3, 2023

coot commented Jul 8, 2023

Bodigrim left a comment

Bodigrim commented Jul 8, 2023

martijnbastiaan left a comment

Bodigrim commented Jul 18, 2023

andreasabel left a comment

Bodigrim commented Jul 29, 2023

andreasabel Sep 10, 2023

coot Sep 11, 2023

andreasabel Sep 11, 2023

Tasty progress reporting #311

Tasty progress reporting #311

Conversation

coot commented Sep 12, 2021

UnkindPartition commented Sep 13, 2021

UnkindPartition commented Sep 15, 2021

coot commented Jan 20, 2022

coot commented Jan 20, 2022

coot commented Jan 20, 2022

master

try-adding-progress-rpt

try-adding-progress-rpt --no-progress

coot commented Jan 20, 2022 • edited

coot commented Apr 30, 2023

coot commented Jun 3, 2023

Bodigrim commented Jul 2, 2023

coot commented Jul 3, 2023

coot commented Jul 8, 2023

Bodigrim left a comment

Choose a reason for hiding this comment

Bodigrim commented Jul 8, 2023

martijnbastiaan left a comment

Choose a reason for hiding this comment

Bodigrim commented Jul 18, 2023

andreasabel left a comment

Choose a reason for hiding this comment

Bodigrim commented Jul 29, 2023

andreasabel Sep 10, 2023

Choose a reason for hiding this comment

coot Sep 11, 2023

Choose a reason for hiding this comment

andreasabel Sep 11, 2023

Choose a reason for hiding this comment

coot commented Jan 20, 2022 •

edited