Profiling monadic code

[pestrada]

The problem

I have been trying to profile some code using the Eff monad from effectful but have been having trouble with the costs not being attributed properly to the effectful action. Any SCC annotation I add to an effectful action like so:

do
  foo <- {-# SCC "foo" #-} someEffectfulAction x

doesn’t seem to capture the cost of the effectful action. If I use ghc-debug-brick to look at a thunk, in most cases, instead of seeing “foo” somewhere in the CCS, I will only see runEff and unsafeEff followed by high-level functions near the top of my program. Similarly, looking at the profile via speedscope shows a distinct lack of foo. Looking at the prof file from -- +RTS -p shows that the cost-centre “foo” is there, but it has a neglibible cost. However, based on traceEventIO and ghc-events-analyzer, I am certain that someEffectfulAction x is what’s contributing to a significant portion of the runtime, and that blocking IO calls are not the problem.

My current hypothesis for why this is the case is that because a value of type Eff es a is nothing but a function Env es -> IO a, the cost that the cost-centre foo is measuring is not the price of the IO action, but instead the cost of evaluating the function Env es -> IO a to weak head normal form, which is basically nothing in most cases.

This doesn’t seem to be a problem with code in the IO action directly. For example, attached to the runEff action, I have an SCC annotation defined in basically an identical manner:

do
  bar <- {-# SCC "bar" #-} runEff theEffectfulAction

and the total cost of the effectful action does seem to be counted under the cost-centre “bar”.

I tried looking at the generated core and even stg of these two examples to see what differentiates the foo and bar case. What I saw in the bar case looks roughly like this:

case (scctick<bar> \s -> blah) s0 of ...

where s0 is the state token of type State# RealWorld from earlier code. Meanwhile, for foo, I typically saw something like this:

let {foo :: Eff [State Int] Bool
     foo = scctick<foo> someEffValue) } in ...

Some things I’ve tried

• Using >>= instead of do-notation
• Using withRunInIO to “run” the effectful action in IO, and attaching the SCC annotation to the IO
• Using unsafeEff and unEff to run the action in IO, adding an SCC annotation to the IO action
  • In a similar vein, importing the constructor of IO, attaching the SCC annotation to the (\s → …) function
  • Even further, attaching the SCC annotation to the evaluation (in a case expression) of the unwrapped IO action against a State# RealWorld token. E.g., case {-# SCC "foo" #-} f s of

None of these approaches have worked, whether it be because of optimizations or otherwise.

What I’d like to know is how I should profile effectful code in a way that I can take advantage of tools like ghc-debug-brick and speedscope. Given that Eff es a is just a newtype for Env es -> IO a, I suspect that if a method to do this is found, it should also work for code using the monad ReaderT r IO, and vice versa.

[pestrada]

I do find it slightly interesting that the scctick<foo> annotation in the working code (for the IO do block) is attached to the function State# RealWorld -> (# State# RealWorld, a #) rather than the evaluation of said function against the state token. Is there perhaps a special case for State# tokens and/or other 0-bit types?
Edit: Perhaps it would more accurate to say that I find it interesting how even though the scctick annotation is attached to a function rather than the evaluation of said function against arguments, the costs are still properly attributed.
Edit 2: Based on what ghc generates for the core of pure functions that have an SCC annotation, it seems like an scctick at the beginning of the function definition should mean that the cost-centre foo is pushed to the cost-centre stack and thus costs should be properly registered. Some testing with a simple program suggests that the effectful computation has its costs properly attributed. The question is then how/why are the costs not being properly attributed in the program I am trying to profile.

[pestrada]

I’ve done some further testing to figure out the cause so that I can try to come up with a solution, but am still stumped. I have made at least progress. The GHC.Stack.CCS module in particular has been quite helpful for allowing a quick visualization of the cost-centre stack (CCS) at a point in the code.

Using functions from that module, I’ve managed to track down where the CCS seems to “lose track” of previous code, at least according to how I interpret it. It seems that the portion of the CCS that seems to be lost is the part between the top-level runners (e.g., runEff) and the runner of an effect within an Eff es context, and in particular the runEff used in that runner.

To given an idea of what I mean, here’s a sketch of the situation that I’ve come up with:

main :: IO ()
main = do
  opts <- initOpts
  runEff . runErrorNoCallStack $ initAppState opts

initAppState :: (IOE :> es, Error String :> es) => AppOpts -> Eff es AppState

initAppState opts = do
  persistentState <- {-# SCC "testInitPersistentState" #-} initPersistentState opts
  constructAppState persistentState opts
-- constructAppState is irrelevant here

-- passing args to printCCSInfo is to make sure that printCCSInfo is not floated out
{-# SCC initPersistentState #-}
initPersistentState :: (Error String :> es, IOE :> es) => AppOpts -> Eff es PersistentState
initPersistentState opts = do
  unsafeEff_ $ printCCSInfo opts
 -- doWork is responsible for the vast majority of work I'm interested in
  (PersistentState warnings x) <- runWarn $ do
    otherState <- initOtherState opts
    unsafeEff_ $ printCCS otherState
    doWork opts otherState
  let newPersistentState = mkNew warnings x
  pure $ newPersistentState
-- initOtherState should be largely irrelevant


runWarn :: Eff (Warn w : es) a -> Eff es (a, [w])
runWarn action = do
  unsafeEff_ $ printCCSInfo action >> printCCSInfoOf action
  (a, Warn warnings) <- testRunStaticRep (Warn []) action
  unsafeEff_ $ printCCSInfo action
  pure (a, reverse warnings)

-- Function I created for the purposes of figuring out this problem
-- omits the mask just to make sure it's not the source of the problem
testRunStaticRep :: forall w es a. StaticRep (Warn w) -> Eff (Warn w : es) a -> Eff es (a, StaticRep (Warn w))
testRunStaticRep rep action = unsafeEff $ \es0 ->
  printCCSInfo es0
  printCCSInfoOf es0
  printCCSInfoOf action
  es <- consEnv rep dummyRelinker es0
  (a, ws) <- liftA2 (,) (unEff action es) (getEnv es :: IO (StaticRep (Warn w))
  printCCSInfo es
  unconsEnv es
  pure (a, ws)

The printCCSInfo and printCCSInfoOf lines were added for debugging. The printCCSInfo function pretty-prints the current cost-centre stack while the printCCSInfoOf function pretty-prints the current cost-centre stack stored within the value (relevant for thunks and possibly closures).

In the sketch given above, what I’m trying to achieve is have the cost of doWork opts be counted against the cost-centre testInitPersistentState, which I think is reasonable to expect. What I’ve observed is that in the first line of initPersistentState, the printed cost-centre stack does indeed contain testInitPersistentState. The cost-centre testInitPersistentState likewise appears in the both the cost-centre stack at the point where runWarn starts and in the action passed to runWarn. It also appears in the cost-centre stack stored in action inside of testRunStaticRep and the cost-centre stack printed immediately after the testRunStaticRep call.

However, inside the runWarn $ block, testInitPersistentState does not appear. Instead, the most recent part of the call-stack that is still tracked looks like this: initAppState -> runEff -> runErrorNoCallStack -> unsafeEff. In particular, what’s between this last unsafeEff and the current cost-centre stack at the point is missing testInitPersistentState unlike the previous scenarios. The cost-centre testInitPersistentState is also missing from the cost-centre stack printed in the first line of testRunStaticRep.

I’ve been reading the rules of attributing costs to cost-centres documented in the GHC user’s guide very carefully to determine exactly why testInitPersistentState seems to be missing in some cases, but am still unable to figure out what’s causing the problem. Does anyone here have any ideas regarding this issue?