profiling usage

[Simon Marlow]

On 24 January 2005 09:11, Serge D. Mechveliani wrote:

> ---------------------------------------------------------------------
> 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?

You removed the indentation, which was there to indicate the call
nesting.  A cost centre that appears more than once indicates that it
was called in two places in your program (or called with two different
lexical call stacks, to be precise).

> 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?

The first column is the new one.  It is just an integer identifier for
each cost centre stack.  I can't remember why we added it to the profile
(probably something to do with relating this output to heap profiles).

> 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 ?

entered 183 times, I think.

> (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?

Yes

> 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?

Yes, I think so (but you removed the indentation, so I can't tell for
sure).

Cheers,
	Simon