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