Progress feedback to user

[jmid]

Currently, an interactive counter in the UI counts up the number of generated inputs. This works beautifully for succeeding tests and fast shrinkers.
For occasional slow tests (complex properties and exponential(?) shrinkers) the UI provides less feedback. For example, for the check-fun tests when they hang on fold_left fold_right I just get this:

generated; error;  fail; pass / total -     time -- test name
[✗] (   1)    0 ;    1 ;    0 / 1000 --     0.0s -- false bool
[✓] (1000)    0 ;    0 ; 1000 / 1000 --     0.0s -- thrice bool
[✗] (   1)    0 ;    1 ;    0 / 1000 --     0.0s -- map filter

Because of the order of the tests I know that fold_left fold_right is next, and hence that it must be causing it, but from the UI alone I do not know

• that this is the case
• that it found a counterexample immediately and now is taking a long time shrinking.

Perhaps the first can simply be addressed by a suitable flush of the output channel.
For the second just printing Found counterexample, shrinking (or something like) would be nice to get a feel for the framework's progress. A fancier version could even display some progress measure (or bar) of the shrinking phase.

[c-cube]

This makes sense indeed, although it's on a per-runner basis. I'll probably need to modify a bit the callbacks because the test events would become more fine grained.

[c-cube]

This should not block 0.6, actually.

[c-cube]

I think @Gbury might want to help on this :-)

[Gbury]

Sure, i'll have a look as soon as possible. But from what I remember, it would probably require to add some hooks to the existing test functions.

[c-cube]

Don't worry, 0.6 is not even merged in opam yet, it's not urgent :-)
More hooks are needed indeed, but it should be possible to maintain compatibility, I think.

[Gbury]

I proposed an upgrade for progress feedback in PR #35. @jmid , what's your impression about it, as a user ?

[jmid]

Sorry for the delay. I had some other hard deadlines that have stressed me. I just downloaded the upgrade and it is very nice - Thanks!
Question: as a user, what is the meaning of the number printed during shrinking? In principle it could either count all shrinking attempts (the number of times we retest a property after the first failure), or it could count only the succesful attempts (the number of times we retest a property and it still fails).

[jmid]

I have tried it out both by running individual tests from the top-level and by simply #load'ing the function tester into the top-level. The little timer (updated underway) is very cool.
Sometimes I hit what seems like worst case behaviour of the function shrinker. On my last top-level #load for example, it counted up to 137 shrinking steps and then just hangs:

# #use "../qcheck-6448c-fungen2/fun.ml";;                            
val prop_false_bool : QCheck.Test.t = QCheck.Test.Test <abstr>
val prop_thrice_bool : QCheck.Test.t = QCheck.Test.Test <abstr>
val prop_map_filter : QCheck.Test.t = QCheck.Test.Test <abstr>
val prop_foldleft_foldright : QCheck.Test.t = QCheck.Test.Test <abstr>
val prop_foldleft_foldright' : QCheck.Test.t = QCheck.Test.Test <abstr>
val prop_pred_string : QCheck.Test.t = QCheck.Test.Test <abstr>
val prop_member : QCheck.Test.t = QCheck.Test.Test <abstr>
val prop_silly : QCheck.Test.t = QCheck.Test.Test <abstr>
type move = Take2 | Take3
val move_gen : move QCheck.arbitrary =
  {gen = <fun>; print = Some <fun>; small = None; shrink = None;
   collect = None; stats = []}
val play : int -> 'a * (int -> move) -> 'a * (int -> move) -> 'a = <fun>
val prop_winning : string -> int -> (int -> move) -> QCheck.Test.t = <fun>
generated; error;  fail; pass / total -     time -- test name
[✗] (   1)    0 ;    1 ;    0 / 1000 --     0.0s -- false bool                                      
[✓] (1000)    0 ;    0 ; 1000 / 1000 --     0.1s -- thrice bool                                     
[✗] (   1)    0 ;    1 ;    0 / 1000 --     0.0s -- map filter                                      
[✗] (   2)    0 ;    1 ;    1 / 1000 --     0.0s -- fold_left fold_right                            
[ ] (   0)    0 ;    0 ;    0 / 1000 --     2.0s -- fold_left fold_right' (shrinking:  137)

It still says 2.0 seconds in the last line even though it has now taken something like 10min. This is a side-effect of the function shrinker's behaviour I believe. It seems it has taken 2.0s to shrink 137 steps before we hit this point. As such it is hard to blame on the visualization, unless we want to include some form of scheduler that can pause shrinking, update the timer, and resume shrinking (probably overkill).
I will try to find a seed from which prop_foldleft_foldright or prop_foldleft_foldright' hits such behaviour in order for you guys to be able to (hopefully) recreate it.

[Gbury]

Indeed the current code updates the timer at each successful shrink step, so if at one point, finding the next smaller counter-example takes a lot of time, nothing will be updated for a while. I think it's a reasonable compromise: it is possible to add another hook to update the timer for each potential counter-example tried, but maybe that might be a bit too much ? Also, that could degrade performances, though I haven't tried it yet. @c-cube do you think it might be worth adding an event for each value tried during shrinking ?

Finally, note that this lack of update can also happen at almost every step (though it might be less frequent); I personally have some code where testing the property actually takes a lot of time. With the current code, there's not much that can be done about that since most time is spent in the user's code.

[c-cube]

Such an event (at each shrink attempt) might be possible, yeah, as long as we don't change the 'a Shrink.t type. It can be done in the handler itself, I think. If you add this, you probably want to display both values, e.g. "(shrinking: 137, steps 2455)" to indicate that we have done 2455 steps since last successful shrink.

[Gbury]

That was my idea, I'll try that and see what happens.

[Gbury]

Ok, so I just implemented the new event, and happened upon a seed for which single shrink steps of fold_left fold_right uncurried takes a long time: 137528834.

[jmid]

If I #use "../../ocaml-examples/qcheck-fun/fun.ml";;
to load my local copy of the function testers I get interesting behaviour for the seed 233030413:

(lines cut)
random seed: 233030413
generated; error;  fail; pass / total -     time -- test name
[✗] (   1)    0 ;    1 ;    0 / 1000 --     0.0s -- false bool                                      
[✓] (1000)    0 ;    0 ; 1000 / 1000 --     0.1s -- thrice bool                                     
[✗] (   1)    0 ;    1 ;    0 / 1000 --     0.0s -- map filter                                      
[✗] (   1)    0 ;    1 ;    0 / 1000 --   663.0s -- fold_left fold_right                            
[✗] (   1)    0 ;    1 ;    0 / 1000 --   134.8s -- fold_left fold_right'                           
[✗] (   1)    0 ;    1 ;    0 / 1000 --     0.0s -- pred string                                     
[✓] (1200)    0 ;    0 ;  605 / 1000 --     0.4s -- member                                          
[✗] (   1)    0 ;    1 ;    0 / 1000 --     0.0s -- silly                                           
[✗] (   2)    0 ;    1 ;    1 / 1000 --     0.0s -- nim: always take2 
(more lines cut)

With this seed fold_left_fold_right counts, slowly towards 140 shrink steps or so, for a total of 663 seconds. As such it is not quite the behaviour I described above (one particular step taking long). If you can recreate this (I'm on OCaml version 4.04.0 on a 64-bit Macbook), this seed should nevertheless be an interesting test case for both the printer and the function shrinker.

Finally: Printing both numbers would be welcome from here.

[Gbury]

During shrinking is printed <#steps>.<#tries> where <#steps> is the number of successful shrink steps performed and <#tries> is the number of potential counter-examples tried during the current shrink step.

[jmid]

This is wonderful, thanks!

• It is quite informative: I'm currently at 240 seconds and 16000 unsuccesful shrinking attempts for fold_left fold_right - no wonder it is taking time!
• May I suggest alpha-renaming Shrinked to Shrunk? (no, I'm not a native English speaker either) :-)
• I get unusually many newlines printed though (perhaps 100) - and I didn't for the last version. Is my terminal's handling of the (curses?)-interface screwed up, or does the last patch print needless ones to clear lines?

[Gbury]

Just tried the check-fun/fun.ml example with the seed 299930921 for which the first shrink step of fold_left fold_right takes about 450s, and it is indeed a lot nicer with the last commit of the PR.

About the newlines printed: the only relevant change I can think of is that in verbose mode, when printing the definitive results of a test, we first clear the line using a string like \r followed by about 140 spaces. This is necessary to clear the shrink steps printed previously, but that really shouldn't print new lines. Also I don't see any extra newline on my laptop, could you paste the affected output (or a screenshot) somewhere ?

Lastly, I agree that the two names for the shrinking events are not ideal currently, @c-cube do you agree on Shrunk and Shrinking, or do you have another idea ?

[c-cube]

I don't really have an idea on that, sorry. "shrunk" indeed sounds correct.

@jmid if your terminal is not wide enough, it might print newlines…

[Gbury]

Renaming done and pushed.

[jmid]

I cannot recreate the issue with single tests such as

# QCheck_runner.run_tests ~verbose:true [prop_foldleft_foldright'];; 

However it happens consistently when I #use "../../ocaml-examples/qcheck-fun/fun.ml";; that runs a series of tests. Below I tried to copy-paste the last lines before the counterexamples are printed. In my terminal it displays as 15-20 blank lines before the checkmark (there were at least 200 above these). It is not rendered the same by github though:

                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                        [✓] (1200)    0 ;    0 ;  657 / 1000 --     0.4s -- member
                                                                                                              [✗] (   1)    0 ;    1 ;    0 / 1000 --     0.9s -- silly
                                                                                                              [✗] (   1)    0 ;    1 ;    0 / 1000 --     0.0s -- nim: always take2

--- Failure --------------------------------------------------------------------

The thing is I didn't experience this behaviour with the previous version. Perhaps the many events are stress testing my terminal unintentionally. I tried running it under tcsh instead of bash with the same behaviour. I also tried invoking the ocaml top-level directly, without my usual ledit-prefixing bash alias

alias ocaml='$OPAMPREFIX/bin/ledit -x -h ~/.ocaml_history $OPAMPREFIX/bin/ocaml'

In all cases I still get the same behaviour when I #use "../../ocaml-examples/qcheck-fun/fun.ml";;

[Gbury]

As @c-cube said, the problem might be terminal width. Indeed the new output need more width, since we print more information, also there is then a need to clear a line of these information before printing the definitive line of a test, so if any of these lines exceed the width of your terminal, I don't really know what happens, but if lines are wrapped, then they may not be cleared by a \r (since the terminal may have introduced a line break, hypothetically).
In short, what's the width of the terminal you're using ?

[jmid]

@c-cube is right indeed. My width was 110 characters. I tried to bump it up (it is only an 13" laptop) so I had to reduce the font size. I can now recreate the behaviour up to width 139. As such, the patch requires console width 140 or more. We may consider whether this is a reasonable demand.

(insert grandpa-story about how terminals were 80 characters wide when I was young) :-)

[Gbury]

I put 140 space in the clearing line simply because with the last commit, 100 was not enonugh anymore (because of the additional numbers printed). Actually, this may be a symptom of a greater problem, namely the unknown length of the test name (indeed, for tests with a sufficiently long name, the clearing line would not be enough anymore).

The question then becomes: do we try and implement a smart function to adjust printing based on the terminal width, so that we correctly handle test name of any length and terminal of any width, (but that would probably require some work and adding a dependency on a terminal lib, which might not be very practical), or do we simply try and adjust the current printer to work well under reasonable conditions ?

[jmid]

First of all: I'm very happy with this new shrinking feedback. From this alone we now have an understanding of why shrinking functions may take long (many failed shrinking attempts). So many thanks again for this!

I thought a bit more about it. I believe we can use the column width more wisely. Here I am influenced by Edward Tufte who proposed to increase the data-ink ratio ("spend less ink showing more") in tables, charts, etc.

Looking at, e.g.,

generated; error;  fail; pass / total -     time -- test name
[✗] (   1)    0 ;    1 ;    0 / 1000 --     0.0s -- false bool                                      
[✓] (1000)    0 ;    0 ; 1000 / 1000 --     0.1s -- thrice bool                                     
[✗] (   1)    0 ;    1 ;    0 / 1000 --     0.0s -- map filter                                      
[✗] (   1)    0 ;    1 ;    0 / 1000 --   663.0s -- fold_left fold_right                            
[✗] (   1)    0 ;    1 ;    0 / 1000 --   134.8s -- fold_left fold_right'                           
[✗] (   1)    0 ;    1 ;    0 / 1000 --     0.0s -- pred string                                     
[✓] (1200)    0 ;    0 ;  605 / 1000 --     0.4s -- member                                          
[✗] (   1)    0 ;    1 ;    0 / 1000 --     0.0s -- silly                                           
[✗] (   2)    0 ;    1 ;    1 / 1000 --     0.0s -- nim: always take2 

there are several opportunities for removing needless characters (parens, semicolons, dashes, ...) to increase the "data-character ratio". Here's the outcome of an attempt at doing so:

generated error  fail pass / total  time(s) name
[✗]    2    0     1      1 / 1000      0.0  false bool                                              
[✓] 1000    0     0   1000 / 1000      0.1  thrice bool                                             
[✗]    1    0     1      0 / 1000      0.0  map filter                                              
[✗]    1    0     1      0 / 1000      0.0  fold_left fold_right                                    
[✗]    1    0     1      0 / 1000      0.0  fold_left fold_right'                                   
[✗]    3    0     1      2 / 1000      0.0  pred string                                             
[✓] 1200    0     0    598 / 1000      0.5  member                                                  
[✗]    2    0     1      1 / 1000      0.0  silly                                                   
[✗]    2    0     1      1 / 1000      0.0  nim: always take2                                       

We could even go further and remove the square brackets around the colored unicode character.
With the following changes I could make do with a width of only 100 characters to clear. Caveat: this was a quick hack that seems to work for the present situation. I'm likely to have messed up somewhere :-)

$ diff src/QCheck_runner.ml{,~}
396c396
<   Printf.fprintf out "%*d %*d  %*d   %*d / %*d  %7.1f"
---
>   Printf.fprintf out "(%*d) %*d ; %*d ; %*d / %*d -- %7.1fs"
412c412
<     Printf.fprintf out "\r[ ] %a  %s (%s)%!"
---
>     Printf.fprintf out "\r[ ] %a -- %s (%s)%!"
417c417
<   let empty_line = String.make 100 ' ' in
---
>   let empty_line = String.make 140 ' ' in
429c429
<     Printf.fprintf out "\r%s\r[ ] %a  %s%!"
---
>     Printf.fprintf out "\r%s\r[ ] %a -- %s%!"
436c436
<     Printf.fprintf out "\r[%a] %a  %s\n%!"
---
>     Printf.fprintf out "\r[%a] %a -- %s\n%!"
491c491
<       "%*s %*s %*s %*s / %*s  time(s) name\n%!"
---
>       "%*s; %*s; %*s; %*s / %*s -     time -- test name\n%!"
502c502
<       Printf.fprintf out "\r[ ] %a  %s%!"
---
>       Printf.fprintf out "\r[ ] %a -- %s%!"

[c-cube]

This is done, I merged the PR and updated it a bit. For reference, the current output:

It's colorful, readable, and informative! ;-)