heap profiling

[Simon Marlow]

On 16/06/2010 01:52, Evan Laforge wrote:
> I've been trying to profile my program and having some trouble.  I
> imagine other people have stumbled across these same issues, so
> hopefully I can benefit from someone else's experience.  In return, if
> I can figure out some of these things, I'll put it up at
> http://www.haskell.org/haskellwiki/How_to_profile_a_Haskell_program or
> maybe make make a heap profiling page linked from that.
>
> Firstly a few miscellaneous questions:
>
> When running '-hc -hblag,drag' it works for a little while and then
> stops.  The app is still hung, but cpu has gone to 0%.  The disk is
> also idle, so I don't think it's swapping.  According to -S, all
> garbage collection has stopped too.  It's apparently due to something
> about this particular profile, since reducing the amount of data it
> handles just results in a sooner hang.  This same combination works
> with other profiles, so apparently something the code is doing is
> locking up.  Has anyone else seen this?  Any tips on how to
> troubleshoot where it's getting stuck, doing what?  If it sounds like
> a ghc bug I can try to trim down the size and submit a ticket.  GHC
> 6.12.1 on OSX.

Please submit a ticket, and try 6.12.3 if you can (we did fix some 
deadlock bugs in 6.12.2 and 6.12.3).

> The image link from
> http://www.haskell.org/ghc/docs/6.12.2/html/users_guide/profiling.html
> is broken, which makes it a little harder to understand the
> documentation.
>
> -s stats say GC time is 46%, productivity is 32%.  That's pretty bad,
> right?  And where is the remaining 22% going?
>
> The ghc manual says lag is "time between creation and first use" and
> drag is "time between last use and last reference is dropped".  I
> think I understand drag: it means you haven't touched the data for a
> while before it goes out of scope or its retainer goes out of scope.
> So for instance:
>
> stuff = do
>    st<- get
>    x1 st
>    x2
>
> Does this mean that 'st' will be dragging through 'x2' as it would in
> an imperative language?

Probably not.  It depends on what x1 does with st of course, but 
assuming when x1 returns all references to st have been dropped, then st 
is no longer reachable and will not be retained by the GC.

> I gather the usual haskell use is when
> combined with laziness: 'Map.insertWith (+) "a" 42' will keep the old
> value of "a" around until you look "a" up and force it, since the (+)
> won't be applied until then.  Same with foldl.  Are there some other
> classic examples of drag?  Searching for "haskell dragging problem"
> doesn't yield much to do with memory use.

The original paper about this should help:

http://citeseerx.ist.psu.edu/viewdoc/summary?doi=10.1.1.30.1219

> Lag I'm not so sure about.  How is something created before it's used?

oh, that happens a lot.  e.g. in  f (g x), if f doesn't demand the value 
of its argument for a long time, then the heap closure for (g x) is 
lagging.  If the value of (g x) is never demanded, but is nevertheless 
stored in some data structure for a while, then it is VOID.

> And... what's INHERENT_USE?

Primitive objects like arrays and mutable variables, where we don't 
record the use time so we consider them to be implicitly used.

> So, the main question:
>
> I have a program that runs some computation in a monad stack before
> extracting the final result, a list, and passing it on.  When run
> under the heap profiler, there's a huge spike in that phase, which I
> think should be mostly bogus usage, since the final output is so
> relatively small.  When I run under -hb I see big bands for LAG and
> DRAG.
>
> According to -hd the top 3 users are:
>
> <mtl-1.1.0.2:Control.Monad.Writer.Lazy.sat_sltc>
> (,)
> D:Monad
>
> This is kind of puzzling to me... first of all I've never seen an
> explanation for sat_* closure descriptors, and second of all, why does
> it not show up in the .prof file at all?

sat_sltc is just a compiler-generated name for a thunk (a suspended 
computation).  It doesn't show up in the .prof file because it isn't a 
cost centre, it's the name for a closure and is only shown by -hd.

> I switched to Writer.Strict
> and the drag disappeared, which helped, but the lag is still there,
> and the top -hd is now
>
> <mtl-1.1.0.2:Control.Monad.Writer.Strict.sat_soa1>
> State
> stg_ap_2_upd_info

The Monad instance for Writer looks like this:

instance (Monoid w) => Monad (Writer w) where
     return a = Writer (a, mempty)
     m >>= k  = Writer $ case runWriter m of
                             (a, w) -> case runWriter (k a) of
                                 (b, w') -> (b, w `mappend` w')

I expect sat_s0a1 is the closure for (w `mappend` w').  If that is 
causing your space leak, then maybe you need a 
Control.Monad.Writer.Stricter in which the written value is forced 
strictly by >>=.

> (the top -hy is "*", which I gather means "don't know").  And what's
> "stg_ap_2_upd_info"?  The top item accounts for 70% of the memory
> usage.

You see "*" when the type of a closure is polymorphic (as it would be in 
the case of w `mappend` w').  stg_ap_2_upd_info is a generic thunk 
implementation in the RTS - perhaps when profiling we should avoid using 
these to give you more information.

Cheers,
	Simon



> One obvious candidate for the lag is Writer's data (DList Log.Msg) is
> collecting and only being forced at the end of the computation, but
> there is no logging in this section and in any case should never be
> 30M of it!  -hc is not helpful since every monadic operation is
> charged a little bit, -hr is similarly unhelpful (top retainer is
> MANY... hah).
>
> So what exactly is this sat_*?  Where is the memory going?  I guess it
> doesn't have an SCC since it doesn't show up in the .prof output.  Is
> there some place I can manually put an SCC?  I was able to fix the
> drag just by guessing at a strict writer, but the lag is still around.
>   Is there another spot in Writer's>>= that could be accumulating?
> What's *in* that giant mountain of lag?
> _______________________________________________
> Glasgow-haskell-users mailing list
> Glasgow-haskell-users at haskell.org
> http://www.haskell.org/mailman/listinfo/glasgow-haskell-users