Profiling trouble
Ferenc Wagner
wferi@afavant.elte.hu
Fri, 24 Jan 2003 18:16:15 +0100
Hello,
Please help me understanding GHC 5.02.2 profiling output!
Here is the root of my program (Show.hs):
\begin{code}
showData :: BaseVector a => Params -> Operator a -> String
showData params pot = unlines ["Version 3.1",
"",
showParams pot params,
"tcsdim: " ++ tcsDim,
"",
"conformal energies:",
diagonals,
"perturbation matrix:"] ++
matrixElements
where
cutStates = {-# SCC "showData1" #-} getStates params
tcsDim = {-# SCC "showData2" #-} show (length cutStates)
diagonals = {-# SCC "showData3" #-} unlines $ map (show . energy) cutStates
matrixElements = {-# SCC "showData4" #-} unlines $ map unwords off
off = {-# SCC "showData5" #-} [map (myShow . pot outV) (take i cutStates)
| (outV,i) <- zip cutStates [1..]]
main = do params <- option
putStr $ showData params (superPot params)
\end{code}
If I compile it via
ghc -package util -o show --make Show.hs -prof -auto-all
I get in show.prof:
Fri Jan 24 17:46 2003 Time and Allocation Profiling Report (Final)
show +RTS -p -RTS -c 5 -s R -p 0 -t 0 -r 3
total time = 94.54 secs (4727 ticks @ 20 ms)
total alloc = 2,313,980,136 bytes (excludes profiling overheads)
COST CENTRE MODULE %time %alloc
showData1 Main 86.1 88.5
cutAbove4 Tcsa 3.6 1.5
ncEps Epsilon 3.3 3.1
GC GC 2.2 0.0
vopMode Boson 1.5 1.1
ncVop Boson 1.2 1.0
getStates Tcsa 0.6 1.2
individual inherited
COST CENTRE MODULE entries %time %alloc %time %alloc
MAIN MAIN 0 0.0 0.0 100.0 100.0
main Main 0 0.1 0.0 100.0 100.0
[...]
showData Main 1 0.0 0.0 91.1 91.9
showData5 Main 1 0.0 0.0 0.3 0.4
myShow Main 9453 0.3 0.3 0.3 0.3
showData4 Main 1 0.0 0.1 0.0 0.1
showData3 Main 1 0.1 0.1 0.1 0.1
showData1 Main 1 86.1 88.5 90.8 91.4
cutAbove Tcsa 28 0.0 0.0 3.6 1.5
cutAbove2 Tcsa 1 0.0 0.0 0.0 0.0
cutAbove3 Tcsa 27 0.0 0.0 0.0 0.0
cutAbove4 Tcsa 28 3.6 1.5 3.6 1.5
spinSelect Tcsa 1 0.0 0.0 0.0 0.0
getStates Tcsa 1 0.6 1.2 1.0 1.4
incrementalBase Fermion 1 0.3 0.2 0.4 0.2
fermionNumber Fermion 77664 0.1 0.0 0.1 0.0
allTowers Boson 1 0.0 0.0 0.0 0.0
inModule Boson 17 0.0 0.0 0.0 0.0
mergeUp Boson 6 0.0 0.0 0.0 0.0
showData2 Main 1 0.0 0.0 0.0 0.0
[...]
My question: showData1 is a single function call, how can it
still have such a big individual share? Where is the
program spending its time? Sorry if it is a trivial
question, functional profiling is new to me.
Thanks: Feri.