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@haskell.org http://www.haskell.org/mailman/listinfo/glasgow-haskell-users