[erlang-questions] fprof analysis question

[Mike Oxford]

Am I reading this correctly?
0 calls of proc_lib:init_p_do_apply/3 but taking up sometimes, 30 seconds?
Calling into gen_server:loop/6 which actually does the work (buy why 0
calls, above, if it's in the trace?)
Which then calls into gen_server:decode_msg/8

Correct?  I'm new at this... :)

(and, not shown here, further into gen_server:handle_msg/8 ->
gen_server:handle_msg/5 ->gen_server:handle_common_reply/6 calling into
gen_server:loop/6...)

If I am correct, what's the recommended way to debug those gen_server
messages to find out why they are taking so darn long, besides just being
large?  (When we start pushing 380kB+ sized messages through the system it
starts crying.)

Thanks!

-mox




{[{{proc_lib,init_p_do_apply,3},                  0,30283.167,    0.007},

  {{proc_lib,init_p_do_apply,3},                  0,29494.168,    0.007},

  {{proc_lib,init_p_do_apply,3},                  0,29484.167,    0.006},

  {{proc_lib,init_p_do_apply,3},                  0,29479.170,    0.007},

  {{proc_lib,init_p_do_apply,3},                  0,29370.168,    0.005},

  {{proc_lib,init_p_do_apply,3},                  0,29359.169,    0.006},

  {{proc_lib,init_p_do_apply,3},                  0,29356.220,    0.006},

  {{proc_lib,init_p_do_apply,3},                  0,24698.223,    0.061},

  {{proc_lib,init_p_do_apply,3},                  0,24698.040,    0.003},

  {{proc_lib,init_p_do_apply,3},                  0,17498.139,    0.005},

  {{proc_lib,init_p_do_apply,3},                  0,12391.071,    0.003},

  {{proc_lib,init_p_do_apply,3},                  0,12389.865,    0.004},

  {{proc_lib,init_p_do_apply,3},                  0,12389.406,    0.003},

  {{proc_lib,init_p_do_apply,3},                  0,12389.060,    0.006},

  {undefined,                                     0,12388.011,    0.003},

  {{gen_server,handle_common_reply,6},            3,12357.349,    0.014},

  {{proc_lib,init_p_do_apply,3},                  0,   31.961,    0.004},

  {{gen_server,handle_msg,5},                     2,    0.000,    0.031},

  {{gen_server,handle_msg,5},                     1,    0.000,    0.009},

  {{gen_server,handle_msg,5},                     1,    0.000,    0.007},

  {{gen_server,handle_msg,5},                     1,    0.000,    0.003},

  {{gen_server,handle_common_reply,6},          497,    0.000,    5.803},

  {{gen_server,handle_common_reply,6},           30,    0.000,    0.333},

  {{gen_server,handle_common_reply,6},           30,    0.000,    0.307},

  {{gen_server,handle_common_reply,6},           30,    0.000,    0.306},

  {{gen_server,handle_common_reply,6},           30,    0.000,    0.290},

  {{gen_server,handle_common_reply,6},           30,    0.000,    0.285},

  {{gen_server,handle_common_reply,6},           30,    0.000,    0.277},

  {{gen_server,handle_common_reply,6},            6,    0.000,    0.039},

  {{gen_server,handle_common_reply,6},            4,    0.000,    0.018},

  {{gen_server,handle_common_reply,6},            3,    0.000,    0.081},

  {{gen_server,handle_common_reply,6},            2,    0.000,    0.009},

  {{gen_server,handle_common_reply,6},            2,    0.000,    0.008},

  {{gen_server,handle_common_reply,6},            1,    0.000,    0.003}],

 { {gen_server,loop,6},                         703,348057.354,    7.959},
    %
 [{{gen_server,decode_msg,8},                   497,30283.160,    4.056},

  {suspend,                                     497,30151.291,    0.000},

  {{gen_server,decode_msg,8},                    30,29494.161,    0.167},

  {suspend,                                      30,29492.573,    0.000},

  {{gen_server,decode_msg,8},                    30,29484.161,    0.219},

  {suspend,                                      30,29482.507,    0.000},

  {{gen_server,decode_msg,8},                    30,29479.163,    0.163},

  {suspend,                                      30,29477.584,    0.000},

  {{gen_server,decode_msg,8},                    30,29370.163,    0.166},

  {suspend,                                      30,29368.534,    0.000},

  {{gen_server,decode_msg,8},                    30,29359.163,    0.146},

  {suspend,                                      30,29357.584,    0.000},

  {{gen_server,decode_msg,8},                    30,29356.214,    0.202},

  {suspend,                                      30,29354.670,    0.000},

  {{gen_server,decode_msg,8},                     3,24698.162,    0.012},

  {{gen_server,decode_msg,8},                     4,24698.037,    0.014},

  {suspend,                                       3,24697.710,    0.000},

  {suspend,                                       3,24697.567,    0.000},

  {{gen_server,decode_msg,8},                     7,17498.134,    0.036},

  {suspend,                                       7,17497.461,    0.000},

  {{gen_server,decode_msg,8},                     1,12391.068,    0.003},

  {suspend,                                       1,12391.030,    0.000},

  {{gen_server,decode_msg,8},                     2,12389.861,    0.007},

  {suspend,                                       2,12389.754,    0.000},

  {{gen_server,decode_msg,8},                     2,12389.403,    0.006},

  {suspend,                                       2,12389.338,    0.000},

  {{gen_server,decode_msg,8},                     2,12389.054,    0.007},

  {suspend,                                       3,12388.945,    0.000},

  {suspend,                                       2,12388.932,    0.000},

  {{gen_server,decode_msg,8},                     2,12388.008,    0.032},

  {suspend,                                       2,12387.777,    0.000},

  {{gen_server,decode_msg,8},                     3,   31.957,    0.037},

  {garbage_collect,                              10,    0.100,    0.100}]}.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://erlang.org/pipermail/erlang-questions/attachments/20120409/ca6092be/attachment.htm>