[ejabberd] Identifying pubsub performance bottlenecks

Matthias Rieber ml-erlang at zu-con.org
Fri Oct 12 13:31:30 MSK 2012


Hi,

Am 12.10.2012 03:12, schrieb Evgeniy Khramtsov:
> On 12.10.2012 07:18, Matthias Rieber wrote:
>> ... how can I find the bottleneck.
>
> p1_prof is your friend here.
> Recompile ejabberd with debugtools=true and type p1_prof:help() from
> the remsh (`ejabberdctl debug`).
> You likely need p1_prof:reds(), p1_prof:q() and p1_prof:fprof_* 
> functions.

thanks! I'm not sure how to interpret the results, may be mnesia's 
write speed is the limit? These outputs seem to be interesting:

(ejabberd at europe01)52> p1_prof:queue().
** pid(0,284,0)
** registered name: 'ejabberd_mod_pubsub_events.<snip>'
** memory: 307022504
** reductions: 934269352
** message queue len: 28647
** current_function: {mnesia_tm,get_dirty_reply,2}
** dictionary: [{server_host,"events.<snip>"},
                 {mnesia_activity_state,
                     
{mnesia,{sync_dirty,<5526.284.0>},non_transaction}},
                 {'$ancestors',[ejabberd_sup,<5526.37.0>]},
                 {'$initial_call',{mod_pubsub,init,1}}]

** pid(0,294,0)
** registered name: 'ejabberd_mod_pubsub_loop_events.<snip>'
** memory: 16094328
** reductions: 8274170007
** message queue len: 2757
** current_function: {ets,select_trap,1}
** dictionary: [{mnesia_activity_state,
                     
{mnesia,{sync_dirty,<5526.294.0>},non_transaction}}]

ok

and:

(ejabberd at europe01)64> p1_prof:fprof_start(2).
Searching for processes to profile...
Found 14128 processes
Profiling started
ok
(ejabberd at europe01)65> p1_prof:fprof_analyze().
Reading trace data...
..................................................
<snip>
.................................................,
........
End of trace!
Processing data...
Creating output...
Done!
=== Sorted by OWN:
ets:match_object/2            13.07%
mnesia_tm:get_dirty_reply/2   13.02%
mnesia:has_var/1              7.64%
lists:do_flatten/2            3.01%
io_lib_format:collect_cseq/2  2.02%
io_lib_format:build/3         1.81%
ets:select_trap/1             1.55%
io_lib_format:collect/2       1.46%
ets:lookup/2                  1.37%
io_lib_format:term/5          1.32%
ets:lookup_element/3          1.12%
ejabberd_router:do_route/3    1.02%
ejabberd_c2s:handle_info/3    0.99%
jlib:jid_to_string/1          0.99%
lists:flatlength/2            0.93%
jlib:string_to_jid1/2         0.88%
io_lib_format:field_value/2   0.81%
io_lib_format:field_value/3   0.80%
io_lib_format:field_width/2   0.76%
io_lib_format:control/8       0.76%
erlang:port_control/3         0.73%
io_lib_format:pcount/2        0.68%
ets:insert/2                  0.65%
stringprep:control/2          0.63%
mnesia:dirty_rpc/4            0.62%
erlang:++/2                   0.61%
xml:get_attr_s/2              0.60%
mnesia_lib:db_get/2           0.59%
io_lib:write/2                0.58%
lists:any/2                   0.57%
rpc:local_call/3              0.54%
ejabberd_hooks:run/3          0.53%
p1_fsm:collect_messages/3     0.53%
mnesia:val/1                  0.53%
mnesia_lib:db_get/3           0.53%
mnesia:e_has_var/2            0.53%
mnesia:do_dirty_rpc/5         0.52%
mnesia_lib:val/1              0.51%
lists:keydelete3/3            0.51%

=== Sorted by ACC:
erlang:hibernate/3                        15.37%
ejabberd_receiver:handle_info/2           8.07%
mod_pubsub:handle_info/2                  2.12%
mod_pubsub:do_route/7                     2.11%
lists:foreach/2                           2.05%
mnesia_tm:doit_loop/1                     2.03%
mnesia_sp:init_proc/4                     2.03%
mnesia:sync_dirty/1                       1.91%
mnesia:sync_dirty/2                       1.91%
mnesia_tm:non_transaction/5               1.91%
mnesia:non_transaction/5                  1.91%
mod_pubsub:transaction/2                  1.90%
mod_pubsub:iq_pubsub/8                    1.87%
mod_pubsub:node_call/3                    1.82%
mod_pubsub:send_items/6                   1.80%
mod_pubsub:subscribe_node/5               1.79%
mod_pubsub:send_loop/1                    1.40%
mod_pubsub:-send_loop/1-fun-0-/3          1.36%
mod_pubsub:transaction/4                  1.32%
mod_pubsub:-transaction/4-fun-0-/3        1.31%
mod_pubsub:-subscribe_node/5-fun-0-/5     1.23%
node_hometree:subscribe_node/8            1.20%
node_flat:subscribe_node/8                1.20%
mnesia:write/1                            1.01%
mnesia:dirty_rpc/4                        1.01%
mnesia:write/3                            1.01%
mnesia:write/5                            1.01%
mnesia:do_dirty_write/3                   1.01%
mnesia_tm:dirty/2                         1.00%
mnesia:do_dirty_rpc/5                     0.94%
mod_pubsub:event_stanza_with_delay/3      0.93%
rpc:call/4                                0.92%
rpc:local_call/3                          0.90%
ejabberd_router:route/3                   0.90%
ejabberd_router:do_route/3                0.89%
mnesia_tm:rec_dirty/2                     0.88%
mnesia_tm:get_dirty_reply/2               0.87%
jlib:timestamp_to_xml/4                   0.84%
jlib:timestamp_to_iso/2                   0.82%
io_lib:format/2                           0.76%
io_lib_format:fwrite/2                    0.76%
node_hometree:get_entity_subscriptions/2  0.67%
ejabberd_local:route/3                    0.67%
mnesia:match_object/1                     0.67%
mnesia:match_object/3                     0.67%
mnesia:match_object/5                     0.67%
mnesia_lib:db_match_object/3              0.67%
mnesia:dirty_match_object/2               0.67%
mnesia:remote_dirty_match_object/2        0.67%
mnesia:remote_dirty_match_object/3        0.67%
mnesia_lib:db_match_object/2              0.67%
mnesia_lib:catch_match_object/3           0.67%
ets:match_object/2                        0.67%
pubsub_subscription:add_subscription/3    0.66%
ejabberd_local:do_route/3                 0.66%
ejabberd_sm:route/3                       0.65%
ejabberd_sm:do_route/3                    0.64%
mnesia:dirty_index_read/3                 0.60%
mod_pubsub:-send_loop/1-fun-1-/5          0.59%
mod_pubsub:node_action/4                  0.58%
mod_pubsub:-node_action/4-fun-0-/3        0.58%
node_flat:get_entity_subscriptions/2      0.58%
ok

and

(ejabberd at europe01)69> p1_prof:reds(3).
** pid(0,294,0)
** registered name: 'ejabberd_mod_pubsub_loop_events.<snip>'
** memory: 2914360
** reductions: 10417179395
** message queue len: 0
** current_function: {mod_pubsub,send_loop,1}
** dictionary: []

** pid(0,284,0)
** registered name: 'ejabberd_mod_pubsub_events.<snip>'
** memory: 849621088
** reductions: 1224262019
** message queue len: 62181
** current_function: {io_lib_format,precision,2}
** dictionary: [{server_host,"events.<snip>"},
                 {'$ancestors',[ejabberd_sup,<5526.37.0>]},
                 {'$initial_call',{mod_pubsub,init,1}}]

** pid(0,0,0)
** registered name: init
** memory: 47168
** reductions: 5280660
** message queue len: 0
** current_function: {init,loop,1}
** dictionary: []

ok

Matthias




More information about the ejabberd mailing list