doctests take extraordinarily long with doctest-0.12 on GHC 8.2.1

[RyanGlScott]

After commit 378261d, which bumped the doctest upper version bounds to allow doctest-0.12, the Travis GHC 8.2.1 build began to time out when running the doctests test suite. Curiously, this doesn't appear to happen with any other version of GHC.

[RyanGlScott]

The same problem appears to be affecting heaps.

Edit: Never mind, I'm guessing this was a Travis glitch, since restarting the GHC 8.2.1 build for heaps made it work again (thankfully, since the heaps doctests only have 30 examples).

[RyanGlScott]

Actually, the lens doctests don't loop forever, but they take about three hours to complete.

[RyanGlScott]

I'm guessing that there's some sort of quadratic slowdown occurring, since when I run the lens doctests by hand, they proceed quickly enough until about example 300/865, at which point they start going noticeably slower.

[RyanGlScott]

So this is interesting. I came up with a script that generates a single file with a configurable number of doctests examples:

-- GenExample.hs
module Main where

import Control.Monad

import System.Environment
import System.Exit
import System.IO

main :: IO ()
main = do
  args <- getArgs
  case args of
    n:_ -> genExamples (read n)
    _ -> do hPutStrLn stderr "usage: runghc GenExamples.hs <num-examples>"
            exitWith $ ExitFailure 1

genExamples :: Int -> IO ()
genExamples nExamples = do
  putStrLn "module Example where"
  ireplicateA_ nExamples genExample

genExample :: Int -> IO ()
genExample i = putStrLn $ unlines
  [ "-- | Simple " ++ exampleName
  , "-- >>> " ++ exampleName
  , "-- 'a'"
  , exampleName ++ " :: Char"
  , exampleName ++ " = 'a'"
  ]
  where
    exampleName :: String
    exampleName = "example" ++ show i

ireplicateA_ :: Applicative m => Int -> (Int -> m a) -> m ()
ireplicateA_ cnt0 f =
    loop cnt0 0
  where
    loop cnt n
        | cnt <= 0  = pure ()
        | otherwise = f n *> (loop (cnt - 1) $! (n + 1))

You can create a file with an equal number of tests to lens by running runghc GenExample.hs 865 > Example.hs. Interestingly, the performance is much worse with --fast than without.

Without --fast:

$ time doctest Example.hs 
Examples: 865  Tried: 865  Errors: 0  Failures: 0

real    0m7.946s
user    0m8.096s
sys     0m0.632s

But if you run doctest Example.hs --fast, you experience the quadratic slowdown mentioned before.

Keep in mind both of these tests were run with doctest-0.12. With doctest-0.11.4, I get these timings:

$ time doctest Example.hs 
Examples: 865  Tried: 865  Errors: 0  Failures: 0

real    0m5.498s
user    0m5.556s
sys     0m0.496s

$ time doctest Example.hs --fast
Examples: 865  Tried: 865  Errors: 0  Failures: 0

real    0m5.677s
user    0m5.764s
sys     0m0.276s

It's not clear to me what changed in doctest-0.12 to cause the regression with --fast.

[RyanGlScott]

I've opened a corresponding doctest issue at sol/doctest#170.

[RyanGlScott]

Unfortunately, I suspect that a GHC 8.2.1-specific bug may be contributing here. See https://ghc.haskell.org/trac/ghc/ticket/14052.

[phadej]

Oh dear, I had no idea preserving it may cause such problems

[phadej]

The short term workaround would be to make it preserving configurable (if there aren't something else simple)

[phadej]

Note: the it change is only in doctest-0.12!

[RyanGlScott]

To be fair, it's GHC 8.2.1 that's at fault, not you ;)

I think making it configurable is the most feasible hack we could pursue for now. I've requested this ability in sol/doctest#170 (comment).

[RyanGlScott]

sol/doctest#171 implements the --no-preserve-it flag. Let's hope it lands soon so that we can adopt it in lens as a workaround.

[RyanGlScott]

doctest-0.13 has been released, which disables the it preserving behavior by default. I've added support for doctest-0.13 in d561c44 (and ruled out doctest-0.12 via version bonds).

This is fixed on lens's end, so I'm closing this issue.