[erlang-questions] Understanding a record generated by fprof:analyse/*

[Rich Neswold]

On Fri, Sep 7, 2012 at 5:00 AM, Raimo Niskanen
<raimo+erlang-questions@REDACTED> wrote:
>
> On Thu, Sep 06, 2012 at 12:28:13AM -0500, Rich Neswold wrote:
> > I'm running the fprof profiler on our newly developed system and found
> > a record in the profiler output that I don't understand. The record in
> > question is:
> >
> > {[{{gen_server,loop,6},                        1630,   84.765,   26.450}],
> >  { {gen_server,decode_msg,8},                  1630,   84.765,   26.450},
> >  [{{gen_server,handle_msg,5},                  1630,    0.018,   25.549}]}.
> >
> > The second column of numbers is the accumulated time used by the
> > function and the last column is the time taken in the function itself
> > (not functions it has called.) In 99% of the records, the accumulated
> > time is greater than the function's time, which makes sense. In the
> > case of genserver:handle_msg/5, however, the accumulated time is 18 uS
> > (!) and the function took 25 mS. How can this be?
>
> Sometimes fprof can not figure out which way functions are called and
> hence fails to charge the right caller with accumulated time.
>
> In this case I see handle_msg() calls loop() that calls decode_msg()
> that calls handle_msg(); it is an infinite loop and when fprof
> sees cykles in the call stack it tries to collaps them
> before charging the caller, thus a guilty function might evade charging.
>
> What does the record for gen_server:handle_msg/5 say?

Thanks for your reply! The entry for gen_server:handle_msg/5 shows this:

{[{{proc_lib,init_p_do_apply,3},                  0,100977.905,   27.831},
  {undefined,                                     0,    0.247,    0.000},
  {{gen_server,decode_msg,8},                  1630,    0.018,   25.549}],
 { {gen_server,handle_msg,5},                  1630,100978.170,   53.380},    %
 [{{gen_server,handle_common_reply,6},         1624,100890.803,   26.477},
  {{gen_server,loop,6},                           6,   59.271,    0.168},
  {{gen_server,dispatch,3},                    1624,   31.442,   30.702},
  {{gen_server,reply,2},                          6,    0.284,    0.284}]}.

When I built the run-time, I chose the "native-libs" option so all the
libraries are native (with which, I found, fprof doesn't do well.)
Maybe fprof is getting confused because there's not enough information
to do a proper analysis. I rebuilt our project without native code
because, with native code enabled, very few of our functions showed up
in the report.

Thanks for your help.

--
Rich