How to debug diverging test using QuickCheck

Question

I have some parsing code using Megaparsec that I've written a simple property to test (it generates a random expression tree, pretty-prints it, and then checks that the result parses back to the original tree).

Unfortunately, there seems to be a bug and if I run the tests without any limits, I see the GHC process allocating more and more memory until either I kill it or the OOM killer gets there first.

Not a problem, I thought... but I can't for the life of me figure out what's causing the divergence. The property itself looks like this: (I've ripped out the proper testing and the shrinking code to try to minimise the code that actually runs)

prop_parse_expr :: Property
prop_parse_expr =
  forAll arbitrary $
  (\ pe ->
     let str = prettyParExpr 0 pe in
       counterexample ("Rendered to: " ++ show str) $
       trace ("STARTING TEST: " ++ show str) $
       case parse (expr <* eof) "" str of
         Left _ -> trace "NOPE" $ False
         Right _ -> trace "GOOD" $ True)

If I compile with profiling (using stack test --profile), I can run the resulting binary with RTS options. Ahah, I thought, and ran with -xc, thinking that I'd get a helpful stack trace when I sent a SIGINT to the stuck job. It seems not. Running with

./long/path/to/foo-test -j1 --test-seed 1 +RTS -xc

I see this output:

STARTING TEST: "0"
GOOD
STARTING TEST: "(x [( !0 )]) "
STARTING TEST: "({ 2 {( !0 )}} ) "
STARTING TEST: "{ 2{ ( x[0? {( 0) ,( x ) } :((0 )? (x ):0) -: ( -(^( x  )) ) ]), 0**( x )} } "
STARTING TEST: "| (0? (x[({ 1{ (0)? x : ( 0 ) }} ) ]) :(~&( 0) ?( x):( (x ) ^( x ) )))"
STARTING TEST: "(0 )"
STARTING TEST: "0"
^C*** Exception (reporting due to +RTS -xc): (THUNK_STATIC), stack trace: 
  Test.Framework.Improving.runImprovingIO,
  called from Test.Framework.Providers.QuickCheck2.runProperty,
  called from Test.Framework.Providers.QuickCheck2.runTest,
  called from Test.Framework.Runners.Core.runSimpleTest,
  called from Test.Framework.Runners.Core.runTestTree.go,
  called from Test.Framework.Runners.Core.runTestTree,
  called from Test.Framework.Runners.Core.runTests',
  called from Test.Framework.Runners.Core.runTests,
  called from Test.Framework.Runners.Console.defaultMainWithOpts,
  called from Test.Framework.Runners.Console.defaultMainWithArgs,
  called from Test.Framework.Runners.Console.defaultMain,
  called from Main.main
<snip: 2 more identical backtraces>
*** Exception (reporting due to +RTS -xc): (THUNK_STATIC), stack trace: 
  Test.Framework.Runners.Console.Utilities.hideCursorDuring,
  called from Test.Framework.Runners.Console.Run.showRunTestsTop,
  called from Test.Framework.Improving.runImprovingIO,
  called from Test.Framework.Providers.QuickCheck2.runProperty,
  called from Test.Framework.Providers.QuickCheck2.runTest,
  called from Test.Framework.Runners.Core.runSimpleTest,
  called from Test.Framework.Runners.Core.runTestTree.go,
  called from Test.Framework.Runners.Core.runTestTree,
  called from Test.Framework.Runners.Core.runTests',
  called from Test.Framework.Runners.Core.runTests,
  called from Test.Framework.Runners.Console.defaultMainWithOpts,
  called from Test.Framework.Runners.Console.defaultMainWithArgs,
  called from Test.Framework.Runners.Console.defaultMain,
  called from Main.main

Can anyone tell me:

Why I see multiple STARTING TEST lines without GOOD or NOPE between them, despite the -j1?
How I get an actual stack trace that shows where the test is allocating all its memory?

Thanks for any ideas!

trace "GOOD" True has no free variables; it is most likely getting optimized and redefined as a global constant so you will see it print at most once. — Li-yao Xia
It is kind of suspicious that there is no mention of your library in the stack trace. Now that you have a counterexample you might want to try isolating it in a standalone executable. — Li-yao Xia
Duh... Thanks for spotting the trace problem. I'll have a proper stare at this again this evening. — Rupert Swarbrick

Rupert Swarbrick Rupert Swarbrick · Accepted Answer · 2019-11-23T11:12:07

For anyone who finds this question, the problem with my code was that my arbitrary instance for expressions didn't constrain sizes properly, so sometimes tried to make enormous trees. See the "Generating Recursive Data Types" section of the QuickCheck manual for what I should have been doing!

I found that running commands like:

./long/path/to/foo-test -o3 +RTS -xc

helped me figure out what was going on. Strangely, the backtrace still shows several threads of execution. I don't really understand why, but at least I could then see that I was spending time in my "makeAnExpr" function. The trick is to tune the timeout (3 seconds above) so that it doesn't kill a test until it's well and truly stuck, but does stop it before it starts eating all your RAM!

How to debug diverging test using QuickCheck

1 Answers