profiling usage

[Serge D. Mechveliani]

Dear GHC experts,

I have questions about the profiling usage in ghc-6.2.2.

I have set {-# SCC .. #-} at several points in my large program. 
The report in  a.out.prof  is 
(I have re-formatted it, for the lines were too long)

---------------------------------------------------------------------
Mon Jan 24 10:30 2005 Time and Allocation Profiling Report  (Final)

	   a.out +RTS -M40m -p -RTS

total time  =        9.04 secs   (452 ticks @ 20 ms)
total alloc = 1,047,303,220 bytes  (excludes profiling overheads)

COST CENTRE         MODULE               %time %alloc

nubCommut           Prelude5              90.0   88.8
isReducibleAtTop    Reduce                 9.1    9.8

                                          individual    inherited
COST CENTRE       MODULE  no.    entries  %time %alloc   %time %alloc

MAIN              MAIN    1           0   0.0    0.0   100.0  100.0
CAF               Main    242         3   0.0    0.0     0.0    0.0
...
...
operatorOccurs           Prelude3  250 19526   0.0  0.2   0.0  0.2
concat in nextTermLevel  Prelude5  249   183   0.0  0.2  98.7 98.1
isReducibleAtTop         Reduce    257  4525   8.4  9.0   8.4  9.0
orderIfCommut            Prelude5  256  7052   0.2  0.1   0.2  0.1
nubCommut                Prelude5  255  4582  90.0 88.8  90.0 88.8
vectorsOfDepthOfSorts    Prelude5  251   379   0.0  0.0   0.0  0.0
vectorsUnderDepthOfSorts Prelude5  254   260   0.0  0.0   0.0  0.0
isReducibleAtTop         Reduce    248   314   0.6  0.8   0.6  0.8
-------------------------------------------------------------------------

1. There was set a single point of {-# SCC "isReducibleAtTop" #-}.
   Why the report prints the two different lines for it?
   What is the meaning of such duplication?

2. It prints six number columns instead of 5 explained in the 
   User Guide 5.00 (I am looking into now).
   The second column looks new. What does it mean?

3. Consider the line 
   "concat in nextTermLevel"  Prelude5  249 183  0.0 0.2  98.7 98.1

This center was set in the following style:
  ...
  Just class_s -> {-# SCC "concat in nextTermLevel" #-}
                  concat
                  [ofTop f | f <- ops,  coarity f == s .. ]
                  where
                  ofTop f = ...
                  ...
                  nubCommut (t:ts) = {-# SCC "nubCommut" #-} ...

Now, the line meaning is as follows.
(a) This center was entered 249 times. 
(b) What does this mean  183 ?
(c) This very point itself takes almost zero time.
(d) The computation tree below this point (caused by this call)
    takes  98.7%  of the total time.
Right?
The `nubCommut' call is the part of the tree below 
"concat in nextTermLevel". And its line shows that it takes 90%
by itself.
So, the main expense is by  nubCommut,  and the rest of 
"concat in nextTermLevel" adds about 9% to it. These 9% include,
in particular, the cost of the (++) calls.
Right? 

Thank you in advance for the explanation.

-----------------
Serge Mechveliani
mechvel at botik.ru