On 18/06/2010 08:29, Evan Laforge wrote:

...

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.

Ok... so a (g x) closure is constructed, and it will keep 'x' alive when it shouldn't, but what's the actual data constructor here? If 'x' is [1, 2], will these two cons cells be counted as being in LAG stage? Or is it just the closure, which will show up as a sat_something?

I think it depends whether the [1,2] has been "used" or not. If it has been used, then the closures are in the USE state until the last use, otherwise they are in the LAG state.

...

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>>=.

So I copied Writer/Strict.hs and made a new one with a slightly stricter>>=, note the ! on w':

m>>= k = WriterT $ do (a, w)<- runWriterT m (b, !w')<- runWriterT (k a) let ws = w `mappend` w' return (b, ws)

Initially this had no effect. I put a ! on the first 'w', and now the StricterWriter.sat_* closure is replaced by the #2 consumer, which is PAP. What *is* PAP? Memory usage is exactly the same, I just have more PAP now. So I tried switching from DList and DList.append to [] and (++) and now... the lag is gone! Only the ! on w' is needed.

The quadratic behaviour of (++) is not a practical worry in my case, since I log rarely so most of the appends are with []s on one side or both, but this is a bit troubling. Writer + DList was specifically recommended as an efficient way to log things, but if a giant space leak is the result, then it's not such a great idea after all. I'm guessing it has something to do with how DList is implemented in terms of function compositions, but since I can't see inside PAP I have to guess.

Right, I wouldn't use DList for this. Here's an alternative I use: data AList a = ANil | ASing a | Append (AList a) (AList a) lenA :: AList a -> Int lenA ANil = 0 lenA (ASing _) = 1 lenA (Append l r) = lenA l + lenA r appendA ANil r = r appendA l ANil = l appendA l r = Append l r Note how appendA is strict(ish) and eliminates ANils, so in a writer monad it shouldn't build up a space leak. I'm sure you can write toList (don't use (++) though). I'd put the bang on ws: m>>= k = WriterT $ do (a, w) <- runWriterT m (b, w') <- runWriterT (k a) let !ws = w `mappend` w' return (b, ws) The problem with this monad is that >>= isn't tail-recursive, so it will cause stack overflows on recursive monadic functions. I suspect that a better alternative to the strict writer monad is the strict state monad in most cases, because its bind is tail-recursive.

To try to get a better picture of what was going on, I created a simpler profile with a simplified monad stack: just logging and state and doing some stylized actions... and now the results are the reverse! The stricter version on lists produces an enormous amount of lag, the stock Writer.Strict is much better, but still produces quite a bit of garbage (perhaps from the State, though I can't see what I'm doing wrong there). The dlist + normal strictness version is so fast the gc can't even measure it! But if I bump the 'depth' from 9 to 10 (which means factorially more calls), suddenly I'm getting stack overflows... but initially only in hb mode.

So the more I look at it, the less I understand. Clearly something is different from my production profile and the test profile, but it seems baffling that it makes such a difference as to reverse the results. I will try to reduce the production version element by element until the results switch around.

I put the simple version at http://hpaste.org/fastcgi/hpaste.fcgi/view?id=26329#a26329

This one displays much better performance with DList + Writer.Strict than List + StrictWriter so I guess it's not too surprising. However, *something* is still generating a lot of lag and -hb causes a stack trace, so I'm still doing it wrong somehow.

I also have a situation where -hb shows about 4mb of drag at the most, but when I run with '-hc -hbdrag', I only see 10k peaks. Shouldn't filtering the graph by drag add up to as much drag as when the graph isn't filtered?

That sounds suspicious. If you can make a self-contained example that demonstrates it and create a ticket, that would be a great help. Cheers, Simon

...

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.

Well, it's eating a lot of space... so it must be something. I guess if it's impossible to tell what it is, then it's just being needlessly confusing there.

And thanks so much for the responses... space usage gets more confusing the more I look at it, but I hope it will come clear eventually given enough time.

I put the simple version at http://hpaste.org/fastcgi/hpaste.fcgi/view?id=26329#a26329

This one displays much better performance with DList + Writer.Strict than List + StrictWriter so I guess it's not too surprising. However, *something* is still generating a lot of lag

Some lag is to be expected: logging is about creating and recording data for later use. You'd need to annotate your code to measure which parts of lag are not attributable to the log (for instance, your "m" is passed around a lot before it gets used). Then you can use "-hblag -hc -L40" to get lag attributed to cost centers. Btw, you probably want to be more strict about things like that sum in the simple version ("return $! (1+x1+..)"), even a stricter base case ("return $! 1") helps a little, suggesting that you might want to think about the strictness of your logging tools before you put that in production. Hth, Claus

On Sat, Jun 19, 2010 at 8:46 AM, Claus Reinke wrote:

...

...

I put the simple version at http://hpaste.org/fastcgi/hpaste.fcgi/view?id=26329#a26329

This one displays much better performance with DList + Writer.Strict than List + StrictWriter so I guess it's not too surprising. However, *something* is still generating a lot of lag

Some lag is to be expected: logging is about creating and recording data for later use. You'd need to annotate

Indeed, though I don't think this is the case, because I get lots of lag even when no logs are written.

In the part you deleted I mentioned one source of lag that does not disappear when no logs are written, and a way of using profiling cost centers to track down other sources (the ones I mentioned accounted for 2/3 of lag in the "profile_logging" profile, according to "-hblag -hc -L40" on SCC-annotated source).

My conclusion is that my contrived tests are not useful because the whole point is to get a controlled situation by simplifying it, but even the simple version displays mysterious behaviour.

It is sometimes difficult to produce a simplified version that has strictly fewer problems than the full version, especially if the simple version is not derived from the full version but from simplifying assumptions. Nevertheless, the simpler version has less code, and it is therefore helpful to try and understand its behaviour before returning to full complexity. In particular, it is important to figure out which problematic aspects of the simple version also apply to the full version and which problems can be ignored because they cannot occur in the full version.

I should go back to poking at the production version. Even if I don't understand the changes I'm making, at least when I get a speedup I'm more sure it translates to a real speed up in the application.

That way lies madness. Not recommended unless you are producing code that noone is ever going to look at again, and even then you'll be writing similar code in the future, so it is better to put in the energy once to puzzle out those mysterious details!-) Claus

...

...

Indeed, though I don't think this is the case, because I get lots of lag even when no logs are written. In the part you deleted I mentioned one source of lag that does not disappear when no logs are written, and a way of using profiling cost centers to track down other sources (the ones I mentioned accounted for 2/3 of lag in the "profile_logging" profile, according to "-hblag -hc -L40" on SCC-annotated source).

You mean !s on the intermediate numbers?

No, I wrote about your 'm' parameter to 'runprof', which gets passed all the way through the recursion tree of run_lots before it finally gets used at the leaf level. If I recall correctly, I put one SCC on the log constructors and another on the actual parameter passed to runprof. The comments on strictness were less about lag than about total memory usage - unevaluated computations piling up in logs or recursion parameters are a frequent source of out of memory issues (from dramatic slowdown to termination). Even for your simple test, that changes the profile (the graphic is scaled, but the numbers matter).

I could have sworn I tried that but no luck. Thanks for reminding me about manual SCC pragmas, somehow I totally forgot you could add your own. Just out of curiosity, what affect could "return $! 1" have? A constant should never be a thunk, so 'seq' on it should have no effect, right?

I was surprised by that myself. In principle, numeric constants translate to calls to fromInteger (Haskell 98 report, 3.2), and can return anything with a Num instance (such as the literal '1' translating into an infinite list of ones), so they can't simply be pre-evaluated. But you did specify the type to be Int, so the compiler could have avoided the thunk (one would need to look at GHC's output to check). Then again, we were looking at lag, not at heap size, and those 1s (small, but lots of them) were built before they are used.

Yes, you are right of course, and thank you for the help. It's just frustrating when every step toward simpler instead brings new problems out of the woodwork... but I suppose with enough experience I can begin to understand those too. I will resume my testing when I get some time again!

Understood. You don't have to understand everything at once, and simplified test setups often have issues that don't occur in the real application. But analyzing real applications needs some intuition about what might be going on, and that is easier to acquire in simple test setups. There, you can apply the old Holmes maxime of debugging: once you've excluded everything that can't be the problem, what is left, however unlikely or hard to understand, has to be it (with apologies to Doyle;-). Claus

On 16/06/2010 14:04, Jesper Louis Andersen wrote:

Finally, you can tune the eden/nursery generation by providing +RTS -A5m for instance. The default is 0.5 megabytes which I think is way too low for most work. Increasing it blindly will hurt though as you will hit L1/L2 cache limits and get worse performance.

Not sure I follow here - you say that 0.5MB is too low, and yet increasing it will hurt performance (I agree with you on the last point: in my experience most of the time increasing it does tend to make things worse). OTOH there are programs where the 0.5MB default really hurts - the binary-trees benchmark on the shootout, for example. If we could identify a useful set of heuristics to decide when it's a good idea to increase the nursery size, that would help. I think the only way to get a real handle on this is to put together a comprehensive benchmark suite and test lots of different programs with different heap requirements, and on lots of different machines with different cache sizes. Incedentally, GHC HEAD has a new flag +RTS -H, which increases the nursery size but without increasing the overall memory use (basically it uses the space left over after a copying major collection for the nursery). This sometimes helps with programs that have large heaps, but not always. Cheers, Simon

My application has had problems with both retainer profiling and (especially) biographical profiling - but whenever I try to make a watered-down reproducible example the problem disappears. If you do manage the get a reproducible bug going, I am interested in that ticket.

...

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.

I would look at retainers. Or if you hold on to things you don't use anymore rather than dropping the reference. In general, the heap profiler is the way to go for removing space leak problems -