strange space usage

[igloo]

This program:

module Main (main) where

import System.IO.Unsafe

main :: IO ()
main = do writeFile "wibbleflibble" (replicate 100 'z')
          bs <- getCs $ g $ replicate 1000000 "flibble"
          print $ last bs

getCs :: [FilePath] -> IO String
getCs [] = return ""
getCs (c : cs) = do x <- readFile c
                    xs <- unsafeInterleaveIO $ getCs cs
                    return (x ++ xs)

g :: [FilePath] -> [FilePath]
g is = map f is

f :: FilePath -> FilePath 
f fn = "wibble" ++ fn

when run:

$ ghc -fforce-recomp -Wall --make -O2 -prof -auto-all z.hs -o z
$ ./z +RTS -h -p

shows that around 100k is used by f (h.png). Running with

$ ./z +RTS -hcf -hy -p

shows that it is all of type [] (hcf_hy.png). That seems like a large amount of space for a 13 character filename, so it smells to me like something is wrong somewhere.

If we inline g:

module Main (main) where

import System.IO.Unsafe

main :: IO ()
main = do writeFile "wibbleflibble" (replicate 100 'z')
          bs <- getCs $ map f $ replicate 1000000 "flibble"
          print $ last bs

getCs :: [FilePath] -> IO String
getCs [] = return ""
getCs (c : cs) = do x <- readFile c
                    xs <- unsafeInterleaveIO $ getCs cs
                    return (x ++ xs)

f :: FilePath -> FilePath 
f fn = "wibble" ++ fn

then it all disappears (h2.png).

[igloo]

A biography profile shows that all the f usage is VOID.

[simonmar]

Running the two versions of the program with +RTS -hT (no profiling) show identical heap profiles. Most of the stuff in the heap is Handles and Handle-related things. It looks like we're retaining quite a few Handles, perhaps because the finalizers take a while to run (the Handles are closed, but still in memory until the finalizer has run). The reason we have lots of retained list data that belongs to f is because each Handle contains its filename, and the filename was generated by f.

Why it apparently goes away when inlining g, I've no idea. Could just random scheduling behaviour, perhaps all the finalizers are running earlier. Or it could be a profiling bug.

[igloo]

One thing here that I think is a profiling bug is the biographical profile output. One odd thing is that the amount of memory shown on the graph is only half that shown on the -hy graph. The other thing is that it is shown as all VOID, but if this is the filename then surely it should all be DRAG?

Memory use drops by a factor of 10 when using -C0, and runtime drops a little too:

./base +RTS -t 
'z'
<<ghc: 35419752392 bytes, 43721 GCs, 445058/578064 avg/max bytes residency (867 samples), 3M in use, 0.00 INIT (0.00 elapsed), 13.90 MUT (17.42 elapsed), 3.47 GC (3.40 elapsed) :ghc>>
./base +RTS -t  17.37s user 3.46s system 100% cpu 20.821 total

./base +RTS -t -C0 
'z'
<<ghc: 35413940264 bytes, 43716 GCs, 45837/46328 avg/max bytes residency (20 samples), 4M in use, 0.00 INIT (0.00 elapsed), 13.85 MUT (17.17 elapsed), 1.92 GC (1.89 elapsed) :ghc>>
./base +RTS -t -C0  15.78s user 3.28s system 99% cpu 19.062 total

[simonmar]

I found bugs in the biographical profiler and fixed them:

Tue Mar 17 14:49:39 GMT 2009  Simon Marlow <marlowsd@gmail.com>
  * FIX biographical profiling (#3039, probably #2297)
  Since we introduced pointer tagging, we no longer always enter a
  closure to evaluate it.  However, the biographical profiler relies on
  closures being entered in order to mark them as "used", so we were
  getting spurious amounts of data attributed to VOID.  It turns out
  there are various places that need to be fixed, and I think at least
  one of them was also wrong before pointer tagging (CgCon.cgReturnDataCon).

[igloo]

Merged.