UnkindPartition
Tasty progress reporting
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
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.
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.
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
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
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
| 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.
Moving the no progress check to executeTest fixed the performance regression. Using progress is still 30/40% slower.
@Bodigrim I addressed your review remarks. I left a few unresolved, please check my comments.
@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.
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.