[Haskell-cafe] Interpreting profiling results

[Jean-Marie Gaillourdet]

Hi,

Daniel Fischer wrote:
>>        total alloc =     165,728 bytes  (excludes profiling overheads)
>>
>> COST CENTRE                    MODULE               %time %alloc
>>
>> CAF                            GHC.Handle             0.0   10.7
>> CAF                            Text.Read.Lex          0.0    2.1
>> CAF                            GHC.Read               0.0    1.2
>> square                         Main                   0.0    2.8
>> solve                          Main                   0.0    1.3
>> show_aVx                       Main                   0.0    3.7
>> readsPrec_aYF                  Main                   0.0   60.6
>> main                           Main                   0.0    9.6
>> genNums                        Main                   0.0    5.0
>> cell                           Main                   0.0    1.2
>>
>>
>>
>>                        individual    inherited
>> COST CENTRE              MODULE
>>       no.    entries  %time %alloc   %time %alloc
>>
>> MAIN                     MAIN
>>         1           0   0.0    0.3     0.0  100.0
>>  main                    Main
>>       186           1   0.0    9.6     0.0   85.6
>>  show_aVx               Main
>>       196           2   0.0    3.7     0.0    3.7
>>   cell                  Main
>>       197          16   0.0    0.0     0.0    0.0
>>  solve                  Main
>>       188           5   0.0    1.3     0.0   11.8
>>   genNums               Main
>>       189           8   0.0    5.0     0.0   10.4
>>    square               Main
>>       194          88   0.0    2.8     0.0    3.2
>>     cell                Main
>>       195          16   0.0    0.4     0.0    0.4
>>    col                  Main
>>       192           4   0.0    0.7     0.0    1.1
>>     cell                Main
>>       193          16   0.0    0.4     0.0    0.4
>>    row                  Main
>>       190           4   0.0    0.7     0.0    1.1
>>     cell                Main
>>       191          16   0.0    0.4     0.0    0.4
>>  readsPrec_aYF          Main
>>       187           3   0.0   60.6     0.0   60.6
>>  CAF                     GHC.Read
>>       151           1   0.0    1.2     0.0    1.2
>>  CAF                     Text.Read.Lex
>>       144           8   0.0    2.1     0.0    2.1
>>  CAF                     GHC.Handle
>>       128           4   0.0   10.7     0.0   10.7
>>  CAF                     GHC.Conc
>>       127           1   0.0    0.0     0.0    0.0
>>
>> Does the column 'entries' represent the number of times the function
>> was called?
> 
> Number of times it was 'entered', not quite the same as the number of times it was called.
> I think (Warning: speculation ahead, I don't *know* how the profiles are generated) it's 
> thus:
> Say you call a function returning a list. One call, first entry. It finds the beginning of 
> the list, the first k elements and hands them to the caller. Caller processes these, asks 
> "can I have more, or was that it?". Same call, second entry: f looks for more, finds the 
> next m elements, hands them to caller. Caller processes. Repeat until whatever happens 
> first, caller doesn't ask whether there's more or callee finds there's nothing more (or 
> hits bottom).
> 

Warning: speculation ahead, but is based on my knowledge on other profilers.

Many profilers work statistically, they interrupt a program at more less
random (or equal) intervals and inspect the stack, whick is of course
quite difficult in Haskell as far as I understand it. I have interpreted
the entries column as an indication for the amount of "profile
interrupts" which happened when a function f was on top of the stack,
whatever that means in Haskell.

The manual of GHC 6.10.4, chapter 5 states:

>The actual meaning of the various columns in the output is:
>
>entries
>
>    The number of times this particular point in the call graph was
>    entered.


So for me the question remains open, is "entries" a precisely counted
value or a statistically determined one?


Best regards,
Jean