#15143 closed bug (invalid)

Passing an IO value through several functions results in program hanging.

Reported by: Burtannia Owned by:
Priority: normal Milestone: 8.6.1
Component: Compiler Version: 8.4.2
Keywords: Cc:
Operating System: Unknown/Multiple Architecture: Unknown/Multiple
Type of failure: Runtime performance bug Test Case:
Blocked By: Blocking:
Related Tickets: Differential Rev(s):
Wiki Page:

Description (last modified by Burtannia)

I came across this rather interesting bug while writing my dissertation.

The following function takes an IO Obs and if it is an observable of time (ObsTime) it increments the contained Int. Otherwise it leaves it unchanged:

incTime :: IO Obs -> IO Obs
incTime o = do
    obs <- o
    case obs of
        ObsTime t -> return $ ObsTime (t+1)
        _         -> o

The case for ObsTime works as expected however, the wildcard case gets progressively slower the more times a value is passed through. At 30 iterations I waited 10 seconds before aborting execution, the function had still not returned.

This issue does not occur with the following change to the wildcard case:

_ -> return obs

This issue occurs both in GHCi and after compiling with GHC (with and without -O2).

It might also be worth mentioning that I've had the issue on Ubuntu (GHC 8.4.2 & 7.10.3) and Windows 7 (GHC 8.0.2). So it doesn't seem to be OS specific or caused by a recent change to GHC.

I have attached a file with the necessary code to demonstrate the issue.

Attachments (1)

Bug.hs (765 bytes) - added by Burtannia 19 months ago.
Data structure and functions to demonstrate the bug.

Download all attachments as: .zip

Change History (12)

Changed 19 months ago by Burtannia

Attachment: Bug.hs added

Data structure and functions to demonstrate the bug.

comment:1 Changed 19 months ago by Burtannia

Description: modified (diff)

comment:2 Changed 19 months ago by Burtannia

Description: modified (diff)

comment:3 Changed 19 months ago by osa1

Reproduced with HEAD as well.

Only differences in STG between the two versions are:

--- Fast.dump-stg	2018-05-12 10:47:41.827648570 +0300
+++ Slow.dump-stg	2018-05-12 10:47:47.415771391 +0300
@@ -1,6 +1,6 @@
 
 ==================== Pre unarise: ====================
-2018-05-12 07:47:41.816039401 UTC
+2018-05-12 07:47:47.404211898 UTC
 
 Main.$WObsTime [InlPrag=INLINE[2]] :: GHC.Types.Int -> Main.Obs
 [GblId[DataConWrapper],
@@ -42,7 +42,7 @@
 [GblId,
  Arity=4,
  Caf=NoCafRefs,
- Str=<S,U><L,U><S,1*U><C(S),1*C1(U(U,U))>,
+ Str=<S,U><L,U><S,1*U><C(S),C(U(U,U))>,
  Unf=OtherCon []] =
     [] \r [sc sg sc1 sc2]
         case sc1 of ds {
@@ -51,8 +51,8 @@
                 sat [Occ=Once] :: GHC.Types.IO Main.Obs
                 [LclId] =
                     [sc2] \r [s]
-                        case sc2 s of ds1 {
-                          (#,#) ipv [Occ=Once] ipv1 [Occ=Once!] ->
+                        case sc2 s of {
+                          (#,#) ipv [Occ=Once*] ipv1 [Occ=Once!] ->
                               case ipv1 of {
                                 Main.ObsTime dt [Occ=Once] ->
                                     case +# [dt 1#] of sat {
@@ -63,7 +63,7 @@
                                                 CCCS Main.ObsTime! [sat];
                                           } in  (#,#) [ipv sat];
                                     };
-                                Main.ObsTemp _ [Occ=Dead] -> ds1;
+                                Main.ObsTemp _ [Occ=Dead] -> sc2 ipv;
                               };
                         };
               } in 

So I guess sc2 ipv is causing the slowness? This is the argument passed as sc2:

Main.main2
  :: GHC.Prim.State# GHC.Prim.RealWorld
     -> (# GHC.Prim.State# GHC.Prim.RealWorld, Main.Obs #)
[GblId, Arity=1, Caf=NoCafRefs, Str=<S,U>, Unf=OtherCon []] =
    [] \r [void] Unit# [Main.main3];

comment:4 Changed 19 months ago by osa1

I made the slow program parametric on number of iterations. Seems like an exponential behavior in the generated code:

$ for n ({20..30}); do time ./Slow $n; done
ObsTemp 1
./Slow $n  0,05s user 0,00s system 85% cpu 0,064 total
ObsTemp 1
./Slow $n  0,08s user 0,00s system 91% cpu 0,092 total
ObsTemp 1
./Slow $n  0,16s user 0,00s system 98% cpu 0,162 total
ObsTemp 1
./Slow $n  0,31s user 0,00s system 99% cpu 0,312 total
ObsTemp 1
./Slow $n  0,62s user 0,00s system 99% cpu 0,622 total
ObsTemp 1
./Slow $n  1,23s user 0,00s system 99% cpu 1,242 total
ObsTemp 1
./Slow $n  2,47s user 0,00s system 99% cpu 2,472 total
ObsTemp 1
./Slow $n  5,11s user 0,00s system 99% cpu 5,112 total
ObsTemp 1
./Slow $n  9,85s user 0,00s system 99% cpu 9,862 total
ObsTemp 1
./Slow $n  19,92s user 0,01s system 100% cpu 19,922 total
^C^C

Increasing the iteration count by one causes time it takes to double.5

comment:5 Changed 18 months ago by danilo2

Hi! I think I might get similar problem. However, no minimal example here (unless you will need some). The code is pretty simple, I'm building a "fold-like" function with type classes:

class Monad m => FoldableLayer t m layer where
    buildLayerFold :: ∀ layout. Layer.Cons layer layout -> m (Result t) -> m (Result t)

class Monad m => LayerFoldableBuilder__ (active :: Bool) t m layer where
    buildLayerFold__ :: SomePtr -> m (Result t) -> m (Result t)

instance {-# OVERLAPPABLE #-} Monad m
      => LayerFoldableBuilder__ 'False t m layer where
    buildLayerFold__ = \(!_) (!a) -> !a ; {-# INLINE buildLayerFold__ #-}

instance (Monad m, Layer.StorableLayer layer m, FoldableLayer t m layer)
      => LayerFoldableBuilder__ 'True t m layer where
    buildLayerFold__ = \(!ptr) (!mr) -> do
        !layer <- Layer.unsafePeekWrapped @layer ptr
        !r     <- mr -- | Performance
        buildLayerFold @t @m @layer layer $! pure r
    {-# INLINE buildLayerFold__ #-}

The problem is that if I change the last two lines to

buildLayerFold @t @m @layer layer mr -- mr instead of pure r

The performance is 2 times slower while evaluating it. The m is a State over IO. Basically I am building here an action and this code change should not affect anything - because this action is just a function composition and will be evaluated eventually. I was initially thinking this might be related to strictness on the result, but that is apparently not the case. Even if I change the code to:

!_ <- mr
buildLayerFold @t @m @layer layer mr

I get the same slow results (2 times slower than the fast version). I don't see any reason why would it happen and this bug could be related. Thanks @iamrecursion for showing it to me!

comment:6 Changed 18 months ago by simonpj

Why do you think this is a bug?

You are compputing

incTime (incTime ( ... (incTime testObs) ... ))

where

incTime :: IO Obs -> IO Obs
incTime o = do obs <- o
               case obs of
                 ObsTime t -> return $ ObsTime (t+1)
                 _         -> o

Each call of incTime invokes its argument o twice. Since o is passed in as an argument, GHC must call it twice in case it has side effects. The alternative code

incTime' o = do obs <- o
                case obs of
                  ObsTime t -> return $ ObsTime (t+1)
                  _         -> return obs

is not semantically equivalent. Imagine called

incTime (do { updRef r (+ 1); return ObsTemp })

then I expect the reference r to be incremented twice. But incTime' will only increment it once.

So each call to incTime o calls o twice. But in the call incTime (incTime o), we call incTime o twice; and each call calls o twice. Result: four calls to o. If the nest is 3 deep we get eigth calls and so on.

In short, this program has exponential runtime by design, and GHC faithfully does what you ask.

In short, it looks fine to me. Do you agree?

comment:7 in reply to:  6 Changed 18 months ago by Burtannia

Replying to simonpj:

First of all I'm very excited that you replied to this. Your financial contracts paper was of great interest and your talk(s) on writing a good dissertation / paper were a huge help! So thank you for those.

Anyway, back to the issue at hand...

Each call of incTime invokes its argument o twice.

After thinking through this for a while I think I understand what's happening. o is being evaluated both in obs <- o and with _ -> o? I wasn't thinking of o as a monadic computation and therefore I thought of _ -> o as just returning the input unchanged rather than evaluating it again.

incTime (do { updRef r (+ 1); return ObsTemp })

I don't understand this example. What is updRef and what value is ObsTemp wrapping? Not that it matters because I agree that the observed behaviour with incTime is not a bug.

comment:8 in reply to:  5 Changed 18 months ago by Burtannia

Replying to danilo2:

I think you were right that it's to do with the strictness of the value. I don't know a huge amount but here is my interpretation.

!r     <- mr -- | Performance
buildLayerFold @t @m @layer layer $! pure r

This performs the monadic action mr, binds the result to r and forces that value to be fully evaluated.

$! pure r forces pure r to be fully evaluated. Note that pure r isn't a value, it's a monadic computation that returns a value.

From what I understand, your test:

!_ <- mr
buildLayerFold @t @m @layer layer mr

isn't doing what you think it's doing. !_ <- mr says perform the monadic action mr and strictly evaluate its result. You then pass the monadic action mr as an argument to the function on the next line. Note that the computation mr is not strictly evaluated here. Later during the execution, that computation will be performed again but must first be evaluated. I'm presuming this "second evaluation" is why it runs two times slower. Again I'm not 100% sure that I'm correct on this.

comment:9 Changed 18 months ago by danilo2

@Burtannia, thanks for the reply! Why do you think mr is not strictly evaluated there? It is a strict function argument, so it have to be evaluated at least to WHNF. This is State over IO, so probably there could be some unevaluated parts, like the inner tuple (not the tuple values, because this is a strict state) in the state monad definition, but in such case I don't see (yet) how it could affect the performance and why !r <- mr and !_ <- mr behave differently – they both force evaluation of all intermediate structures of the monadic stack.

comment:10 Changed 18 months ago by simonpj

It is nothing to do with strictness! Consider

foo :: IO Int -> IO Int
foo a = do { i1 <- a
           ; i2 <- a
           ; return (i1+i2) }

This function must perform a twice. It is not ok to "optimise" it to

foo a = do { i1 <- a
           ; return (i1+i1) }

Reason: a might have side effects (which must be performed twice) and it might return different values on its successive calls.

In the example of this ticket, in incTime the action o must be called twice. And in the particular example, the action is another call to incTime which calls its o twice; and so on. Result: 2n calls of the final action, hence exponential behaviour.

Strictness and bangs have no effect on this story

comment:11 Changed 18 months ago by RyanGlScott

Resolution: invalid
Status: newclosed

As explained above, this is expected behavior. Closing.

Note: See TracTickets for help on using tickets.