RE: Confused by profiling

I am confused by the GHC profiling output. I have put some abstracts below to illustrate my confusion.
I compiled my code with: HFLAGS="-Wall -package lang -prof -auto-all" hmake -ghc main and then ran it with: ./main -t +RTS -p < test5.hs
Here is some of main.prof: individual inherited COST CENTRE MODULE entries %time %alloc %time %alloc
[...] parse Parser 1 0.0 0.0 81.4 62.3 p_module Parser 0 0.0 0.0 81.4 62.3 <|> PC_base 69517 20.3 5.7 81.4 62.3 [...] p_aexp_list Parser 0 0.0 0.0 0.0 0.3 con2tag_Token# Tokens 880 0.0 0.0 0.0 0.0 pIfThing PC_base 896 0.0 0.0 0.0 0.0 <$ PC 0 0.0 0.0 0.0 0.3 <$> PC 0 0.0 0.0 0.0 0.3 pSucceed PC_base 896 0.0 0.3 0.0 0.3 <*> PC_base 896 0.0 0.0 0.0 0.0 <*> PC_base 896 0.0 0.0 0.0 0.0 p_aexp_tuple Parser 0 0.0 0.0 0.0 0.3 [...]
and here is the code for p_aexp_list:
p_aexp_list :: Parser Token Aexp p_aexp_list = (Aexp_list . get_rights) <$ pIfThing ((==) (Special '[')) <*> pSList False p_comma p_exp <* pIfThing ((==) (Special ']'))
Now basically my problem is how things under p_aexp_list can be entered 896 times if p_aexp_list is entered 0 times - am I reading it wrong?
Hmmm. I suspect it may be to do with the fact that p_aexp_list isn't a function, it's a CAF (constant applicative form - basically a top-level expression). The "entries" field counts the number of times an SCC annotation is executed, which corresponds more to "calls" than entries. I must admit I haven't thought too hard about this. It might be helpful to see what happens to the code inside the compiler: p_aexp_list = {-# SCC "p_aexp_list" #-} ... this SCC annotation gets executed once, when p_aexp_list is first entered, and you'll probably find it elsewhere on the profile under one of the CAF entries. The first time it is entered, p_aexp_list reduces to a function closure with the SCC annotation attached to it, so subsequent enters don't actually execute the SCC they just append it to the current cost-centre-stack. Perhaps the act of appending an SCC annotation when entering a function closure should bump the entry counts for all the cost centres in the stack. That might yield more reasonable-looking figures. Cheers, Simon

On Fri, Sep 14, 2001 at 04:53:27PM +0100, Simon Marlow wrote:
p_aexp_list Parser 0 0.0 0.0 con2tag_Token# Tokens 880 0.0 0.0 pIfThing PC_base 896 0.0 0.0
Now basically my problem is how things under p_aexp_list can be entered 896 times if p_aexp_list is entered 0 times - am I reading it wrong?
Hmmm. I suspect it may be to do with the fact that p_aexp_list isn't a function, it's a CAF (constant applicative form - basically a top-level expression). The "entries" field counts the number of times an SCC annotation is executed, which corresponds more to "calls" than entries. I must admit I haven't thought too hard about this.
It might be helpful to see what happens to the code inside the compiler:
[...] OK, I think I see why the output being generated is what it is. However, it doesn't actually seem very useful to me.
Perhaps the act of appending an SCC annotation when entering a function closure should bump the entry counts for all the cost centres in the stack. That might yield more reasonable-looking figures.
If that means what I think it might mean then I agree, but I don't get the "in the stack" bit. Thanks Ian
participants (2)
-
Ian Lynagh
-
Simon Marlow