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

[Raimo Niskanen]

On Thu, Sep 06, 2012 at 12:28:13AM -0500, Rich Neswold wrote:
> Hello,
> 
> 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?

> 
> Is anyone familiar enough with fprof to know what this is telling me?
> 
> Thank you!
> 
> --
> Rich
> _______________________________________________
> erlang-questions mailing list
> erlang-questions@REDACTED
> http://erlang.org/mailman/listinfo/erlang-questions

-- 

/ Raimo Niskanen, Erlang/OTP, Ericsson AB