[Haskell-cafe] Interpreting profiling results

[Johan Tibell]

On Tue, Feb 16, 2010 at 3:45 PM, Jean-Marie Gaillourdet <jmg at gaillourdet.net
> wrote:

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


I believe it's the latter. I think the RTS uses a periodic SIGALRM to figure
out which function is currently executing and to record that in the profile.
Simon Marlow would know.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://www.haskell.org/pipermail/haskell-cafe/attachments/20100216/c1de31e8/attachment.html