Program that runs slower with optimizations on

[clanehin]

This program runs significantly slower with optimization than without.

I need two modules to manifest this bug.

Is this a duplicate of 917/1945? Using -fno-full-laziness does not mitigate the problem.

This seems to be the opposite of 1945. Without optimizations, there is a long delay and then all 10 results print at once. With optimizations, there is a shorter delay between each print statement.

module Main

(main) where

import NaiveFib? import Control.Monad

main :: IO () main = replicateM_ 10 (printFib 37)

module NaiveFib?

(printFib,naiveFib) where

printFib :: Integer -> IO () printFib = print . naiveFib

naiveFib :: Integer -> Integer naiveFib 0 = 0 naiveFib 1 = 1 naiveFib n = naiveFib (n-1) + naiveFib (n-2)

lane@wired:~/test/optimizer-bug$ make main-O0 ghc-6.8.1 -O0 --make Main.hs -o main-O0 [1 of 2] Compiling NaiveFib? ( NaiveFib?.hs, NaiveFib?.o ) [2 of 2] Compiling Main ( Main.hs, Main.o ) Linking main-O0 ... lane@wired:~/test/optimizer-bug$ time ./main-O0 24157817 24157817 24157817 24157817 24157817 24157817 24157817 24157817 24157817 24157817

real 0m34.491s user 0m25.982s sys 0m0.564s

lane@wired:~/test/optimizer-bug$ make main-O2 ghc-6.8.1 -O2 --make Main.hs -o main-O2 [1 of 2] Compiling NaiveFib? ( NaiveFib?.hs, NaiveFib?.o ) [2 of 2] Compiling Main ( Main.hs, Main.o ) Linking main-O2 ... lane@wired:~/test/optimizer-bug$ time ./main-O2 24157817 24157817 24157817 24157817 24157817 24157817 24157817 24157817 24157817 24157817

real 1m50.331s user 1m23.641s sys 0m1.008s

[clanehin]

Forgot to preview. Sorry.

lane@wired:~/test/optimizer-bug$ more Main.hs NaiveFib.hs
::::::::::::::
Main.hs
::::::::::::::
module Main
    (main)
    where

import NaiveFib
import Control.Monad

main :: IO ()
main = replicateM_ 10 (printFib 37)
::::::::::::::
NaiveFib.hs
::::::::::::::
module NaiveFib
    (printFib,naiveFib)
    where

printFib :: Integer -> IO ()
printFib = print . naiveFib

naiveFib :: Integer -> Integer
naiveFib 0 = 0
naiveFib 1 = 1
naiveFib n = naiveFib (n-1) + naiveFib (n-2)



lane@wired:~/test/optimizer-bug$ make main-O0
ghc-6.8.1 -O0 --make Main.hs -o main-O0
[1 of 2] Compiling NaiveFib         ( NaiveFib.hs, NaiveFib.o )
[2 of 2] Compiling Main             ( Main.hs, Main.o )
Linking main-O0 ...
lane@wired:~/test/optimizer-bug$ time ./main-O0
24157817
24157817
24157817
24157817
24157817
24157817
24157817
24157817
24157817
24157817

real    0m34.491s
user    0m25.982s
sys     0m0.564s
lane@wired:~/test/optimizer-bug$ make clean
rm -f *.hi
rm -f *.o
rm -f main-O2
rm -f main-O0
lane@wired:~/test/optimizer-bug$ make main-O2
ghc-6.8.1 -O2 --make Main.hs -o main-O2
[1 of 2] Compiling NaiveFib         ( NaiveFib.hs, NaiveFib.o )
[2 of 2] Compiling Main             ( Main.hs, Main.o )
Linking main-O2 ...
lane@wired:~/test/optimizer-bug$ time ./main-O2
24157817
24157817
24157817
24157817
24157817
24157817
24157817
24157817
24157817
24157817

real    1m50.331s
user    1m23.641s
sys     0m1.008s

[dons]

Looks like the printFib is messing with the inlining:

Across 2 modules, -O2 and -O are 5x slower than -Onot. In a single module, -O2 wins easily.

Something fishy going on.

Looking at the unfolding in the .hi file for NaiveFib?.hs:

interface main:NaiveFib 3 608120071117 where
export main:NaiveFib naiveFib printFib
module dependencies:
package dependencies: base
orphans: base:GHC.Base
family instance modules:
3 printFib :: GHC.Num.Integer -> GHC.IOBase.IO ()
    {- Arity: 2 Strictness: LL
       Unfolding: (NaiveFib.a
                     `cast`
                   (GHC.Num.Integer -> sym ((GHC.IOBase.:CoIO) ()))) -}
3 naiveFib :: GHC.Num.Integer -> GHC.Num.Integer
    {- Arity: 1 HasNoCafRefs Strictness: S -}
3 a :: GHC.Num.Integer
       -> GHC.Prim.State# GHC.Prim.RealWorld
       -> (# GHC.Prim.State# GHC.Prim.RealWorld, () #)
    {- Arity: 2 Strictness: LL
       Unfolding: (\ x :: GHC.Num.Integer eta :: GHC.Prim.State# GHC.Prim.RealWorld ->
                   case @ (# GHC.Prim.State# GHC.Prim.RealWorld, () #) GHC.IO.a24
                                                                         GHC.Handle.stdout
                                                                         (GHC.Num.$wshowsPrec
                                                                            0
                                                                            (NaiveFib.naiveFib x)
                                                                            (GHC.Base.[] @ GHC.Base.Char))
                                                                         eta of wild { (# new_s, a59 #) ->
                   GHC.IO.$wa9 GHC.Handle.stdout '\n' new_s }) -}
vectorised variables:
vectorised tycons:
vectorised reused tycons:

Looks like the print is mucking up the optimiser a bit? Let's try moving the printFib line into Main.hs:

$ time ./Main-O2                              
24157817
24157817
24157817
24157817
24157817
24157817
24157817
24157817
24157817
24157817
./Main-O2  2.99s user 0.01s system 99% cpu 3.028 total

And, its fixed if we inline printFib too:

 printFib = print . naiveFib
 {-# INLINE printFib #-}

Simon, what's going on with the optimiser here?

[simonmar]

This is the same as #1168 (but I'll add an xref from there, more examples are always useful).

[simonpj]

Trying with -fno-state-hack (a static flag) would tell you if this was the same as #1168. Does that cure it?

Simon

[igloo]

-fno-state-hack does cure it:

-O0:                 15.91s
-O2:                 60.95s
-O2 -fno-state-hack: 6.23s