[Haskell-cafe] Trashing of memory: How to troubleshoot and fix?

[Simon Marlow]

On 05 November 2005 10:10, Joel Reymont wrote:

> This is a I came up with a "scripting" environment for poker server
> people to excercise their server. All it basically does is compose
> and parse binary packets and let scripters send and receive them.
> 
> The issue I have is that the "script" runs fine on Mac OSX (1Gb of
> memory, though 6Gb VM) and runs out of memory on a Windows machine
> with 512Mb of memory and 768Mb of VM. The memory error is from malloc
> which leads me to believe memory fragmentation could be an issue.
> Running on Windows is a customer requirement.

GHC very rarely calls malloc(), so this is likely to be caused by heavy
memory use in the C++ part of your app.  It would be interesting to find
out though: you can run gdb on the binary and get a backtrace when the
memory error occurs (compiling the Haskell app with -debug will help).

> I was wondering if peak memory usage was the issue but jugding from
> the GC stats it does not seem to be that high. Maybe I'm wrong. What
> do you guys make of this?
> 
> ./logon +RTS -p -sblah
> 
> GC summary:
> --
> 5,695,379,620 bytes allocated in the heap
> 1,274,038,800 bytes copied during GC
> 69,790,544 bytes maximum residency (53 sample(s))
> 
>        20433 collections in generation 0 (230.29s)
>           53 collections in generation 1 (  5.15s)
> 
>          152 Mb total memory in use
> 
>    INIT  time    0.00s  (  0.04s elapsed)
>    MUT   time   91.13s  (250.79s elapsed)
>    GC    time  235.44s  (607.31s elapsed)
>    RP    time    0.00s  (  0.00s elapsed)
>    PROF  time    0.00s  (  0.00s elapsed)
>    EXIT  time    0.00s  (  0.00s elapsed)
>    Total time  326.57s  (858.14s elapsed)

GC load is *very* high.  But as you can see, GHC's storage manager is
only using 152Mb peak - if you're running out with 512Mb, then something
else is using the rest.

To improve performance, I would first try to optimise the program to
reduce the allocation rate, get any low-hanging fruit, and then tweak
the GC settings.  Most of your GC is generation 0 collections, which
suggests that your program is allocating a lot of temporary memory and
not getting much work done.

Also, note that you got these figures from a version of the program
compiled for profiling, which will have higher memory requirements than
normal due to the profiling overheads.

> ---
> Time allocation and profiling report:
> ----
>          total time  =       85.58 secs   (4279 ticks @ 20 ms)
>          total alloc = 2,941,143,704 bytes  (excludes profiling
> overheads)
> 
> COST CENTRE                    MODULE               %time %alloc
> 
> exp/evalU/cmd                  Script.Engine         50.0   66.4
> connect                        Main                  14.1   11.1
> CAF                            Script.Engine         10.3    5.4
> exp/if                         Script.Engine          8.8    4.8
> send                           Main                   6.4    6.7
> expect                         Main                   5.8    2.7
> exp/evalU/sz                   Script.Engine          1.4    1.4
> startSSL                       Script.Engine          1.3    0.1
> ---

Seems like you need to look at evalU:

>         cmd' <- {-# SCC "exp/evalU/cmd" #-}return $ evalU packet appU
> -- unpickle command

this is where most of the time/alloc seems to be going.

Also, just looking at this line of code reminds me of SimonM's 203rd law
of Haskell optimisation: when writing 'return $ E', consider writing
'return $! E' instead.

Cheers,
	Simon