[ejabberd] ejabberd cpu consumption

Alexey Nezhdanov snakeru at gmail.com
Thu Aug 23 21:13:17 MSD 2007


Hello. My ejabberd is constantly consuming about 40% CPU on quite powerful box 
(AMD Athlon(tm) 64 Processor 2800+, 1G of RAM).
There are about 400 http-bind users connected plus couple dozens of different bots.
some of http-bind users are subscribed to pubsub that one of bots keep running
plus atm most of such users are subscribed but are offline.
pubsub updates with the rate of roughly one-two nodes publish/retract per second.

I have tried measuring ejabberd with etop utility to find out why it takes so much CPU.
log is attached. The most interesting to me is why 'error_logger' listed as second to
top time consumer. I have disabled extensive and unhelpful http binding logs this way:
-ejabberd config \"/etc/ejabberd/ejabberd.cfg\" log_path \"/dev/null\"
May be it have troubles writing to /dev/null ?

Please share your opinion on this matter. I am especially interested how much dead
pubsub subscribers can abuse cpu and why error logger can be such a hog.

-- 
Respectfully
Alexey Nezhdanov
-------------- next part --------------
========================================================================================
 'ejabberd at xxxxxxx.com'                                                    15:57:55
 Load:  cpu        20               Memory:  total      235645    binary       3299
        procs   93549                        processes      12    code          426
        runq     6021                        atom         3936    ets        113082

Pid            Name or Initial Func    Time    Reds  Memory    MsgQ Current Function
----------------------------------------------------------------------------------------
<4138.4.0>     error_logger          114193  816832   13276       0 gen_event:loop/4
<4138.386.0>   ejabberd_mod_pubsub_   93545 1242430  486032       0 gen_server:loop/6
<4138.28.0>    user                   60915  119806    8356       0 user:server_loop/2
<4138.258.0>   proc_lib:init_p/5      21162   35428    2324       0 prim_inet:accept0/2
<4138.250.0>   ejabberd_http_sup      20847   80134  178232       0 gen_server:loop/6
<4138.107.0>   proc_lib:init_p/5      14718    6247  900760       0 dets:open_file_loop2
<4138.750.0>   proc_lib:init_p/5      14709   61219   34108       0 gen_fsm:loop/7
<4138.109.0>   proc_lib:init_p/5      12988   51230    7364       0 dets:open_file_loop2
<4138.31392.8> proc_lib:init_p/5      11813    4059    9268       0 ejabberd_http_bind:r
<4138.4454.5>  proc_lib:init_p/5      10859     973   17616       0 gen_fsm:loop/7
========================================================================================


========================================================================================
 'ejabberd at xxxxxxx.com'                                                    15:58:01
 Load:  cpu        14               Memory:  total      237114    binary       3250
        procs   95174                        processes       4    code          426
        runq     5863                        atom         3936    ets        113083

Pid            Name or Initial Func    Time    Reds  Memory    MsgQ Current Function
----------------------------------------------------------------------------------------
<4138.4.0>     error_logger          146776  718950    8396       0 gen_event:loop/4
<4138.386.0>   ejabberd_mod_pubsub_  141487  578510 2172004       0 gen_server:loop/6
<4138.28.0>    user                   95659  102920    8356       0 user:server_loop/2
<4138.250.0>   ejabberd_http_sup      24926  104077  160548       0 gen_server:loop/6
<4138.258.0>   proc_lib:init_p/5      21379   30484    2324       0 prim_inet:accept0/2
<4138.750.0>   proc_lib:init_p/5      14081   38572   27720       0 gen_fsm:loop/7
<4138.31653.4> proc_lib:init_p/5      12112    1037   13668       0 gen_fsm:loop/7
<4138.21227.8> proc_lib:init_p/5      12068    1029   27956       0 gen_fsm:loop/7
<4138.17400.2> proc_lib:init_p/5      11499     932    8788       0 gen_fsm:loop/7
<4138.109.0>   proc_lib:init_p/5       8134   23929    6848       0 dets:open_file_loop2
========================================================================================


========================================================================================
 'ejabberd at xxxxxxx.com'                                                    15:58:07
 Load:  cpu        19               Memory:  total      237547    binary       3204
        procs   96099                        processes      22    code          426
        runq     5363                        atom         3936    ets        113092

Pid            Name or Initial Func    Time    Reds  Memory    MsgQ Current Function
----------------------------------------------------------------------------------------
<4138.386.0>   ejabberd_mod_pubsub_  350373 1640577 3328620       0 gen_server:loop/6
<4138.4.0>     error_logger          162472  606108   13276       0 gen_event:loop/4
<4138.28.0>    user                   61057   87887    8356       0 user:server_loop/2
<4138.107.0>   proc_lib:init_p/5      33417    7947 1572280       0 dets:open_file_loop2
<4138.109.0>   proc_lib:init_p/5      22676   50557    6848       0 dets:open_file_loop2
<4138.7541.7>  proc_lib:init_p/5      21078    1025   17616       0 gen_fsm:loop/7
<4138.3379.6>  proc_lib:init_p/5      20823    2729  131772       0 gen_fsm:loop/7
<4138.250.0>   ejabberd_http_sup      19106   70329  203532       0 gen_server:loop/6
<4138.750.0>   proc_lib:init_p/5      18614   54205   23140       0 gen_fsm:loop/7
<4138.258.0>   proc_lib:init_p/5      18524   26065    2324       0 prim_inet:accept0/2
========================================================================================


========================================================================================
 'ejabberd at xxxxxxx.com'                                                    15:58:12
 Load:  cpu        17               Memory:  total      236665    binary       3178
        procs   95527                        processes       0    code          426
        runq     5052                        atom         3936    ets        113092

Pid            Name or Initial Func    Time    Reds  Memory    MsgQ Current Function
----------------------------------------------------------------------------------------
<4138.4.0>     error_logger          152759  665809    8396       0 gen_event:loop/4
<4138.386.0>   ejabberd_mod_pubsub_  126402  582534 2843048       0 gen_server:loop/6
<4138.28.0>    user                  120513   96783    8356       0 user:server_loop/2
<4138.109.0>   proc_lib:init_p/5      30375   21416    7364       0 dets:open_file_loop2
<4138.258.0>   proc_lib:init_p/5      20761   28545    2324       0 prim_inet:accept0/2
<4138.751.0>   proc_lib:init_p/5      19909    9122   21132       0 gen_server:loop/6
<4138.107.0>   proc_lib:init_p/5      18534    2470 1572324       0 dets:open_file_loop2
<4138.250.0>   ejabberd_http_sup      15438   63542  159168       0 gen_server:loop/6
<4138.750.0>   proc_lib:init_p/5      14111   48055   34108       0 gen_fsm:loop/7
<4138.782.4>   proc_lib:init_p/5      11346     833   18092       0 gen_fsm:loop/7
========================================================================================


========================================================================================
 'ejabberd at xxxxxxx.com'                                                    15:58:17
 Load:  cpu        16               Memory:  total      236954    binary       3190
        procs   95726                        processes      51    code          426
        runq     5140                        atom         3936    ets        113094

Pid            Name or Initial Func    Time    Reds  Memory    MsgQ Current Function
----------------------------------------------------------------------------------------
<4138.4.0>     error_logger          164181  628811    8396       0 gen_event:loop/4
<4138.28.0>    user                  130555   91309    8356       0 user:server_loop/2
<4138.386.0>   ejabberd_mod_pubsub_  129409  550005 2843048       0 gen_server:loop/6
<4138.258.0>   proc_lib:init_p/5      26158   27146    2324       0 prim_inet:accept0/2
<4138.519.0>   proc_lib:init_p/5      22106    193113174600       0 gen_server:loop/6
<4138.181.0>   proc_lib:init_p/5      17109     544   55580       0 dets:open_file_loop2
<4138.31875.8> proc_lib:init_p/5      14349   12891   54540       0 gen_fsm:loop/7
<4138.31509.8> proc_lib:init_p/5      13944    4302    8336       0 ejabberd_http_bind:r
<4138.750.0>   proc_lib:init_p/5      13415   47714   34108       0 gen_fsm:loop/7
<4138.250.0>   ejabberd_http_sup      13093   42933  149072       0 gen_server:loop/6
========================================================================================


========================================================================================
 'ejabberd at xxxxxxx.com'                                                    15:58:22
 Load:  cpu        19               Memory:  total      236033    binary       3113
        procs   94771                        processes      80    code          426
        runq     4700                        atom         3936    ets        113568

Pid            Name or Initial Func    Time    Reds  Memory    MsgQ Current Function
----------------------------------------------------------------------------------------
<4138.386.0>   ejabberd_mod_pubsub_  269301 1410802 1271704       0 gen_server:loop/6
<4138.4.0>     error_logger          188204  780483    8396       0 gen_event:loop/4
<4138.28.0>    user                  117491  113284    8356       0 user:server_loop/2
<4138.107.0>   proc_lib:init_p/5      63231   10975 1272180       0 dets:open_file_loop2
<4138.258.0>   proc_lib:init_p/5      32346   33229    2324       0 prim_inet:accept0/2
<4138.250.0>   ejabberd_http_sup      24114   87219  147632       0 gen_server:loop/6
<4138.750.0>   proc_lib:init_p/5      16986   42146   34108       0 gen_fsm:loop/7
<4138.14726.0> proc_lib:init_p/5      13073     837   12164       0 gen_fsm:loop/7
<4138.109.0>   proc_lib:init_p/5      12911   44849    7364       0 dets:open_file_loop2
<4138.32198.8> proc_lib:init_p/5      11291    3029   13216       0 prim_inet:recv0/3
========================================================================================


========================================================================================
 'ejabberd at xxxxxxx.com'                                                    15:58:27
 Load:  cpu        19               Memory:  total      242176    binary       3082
        procs  101226                        processes       4    code          426
        runq     4863                        atom         3936    ets        113093

Pid            Name or Initial Func    Time    Reds  Memory    MsgQ Current Function
----------------------------------------------------------------------------------------
<4138.386.0>   ejabberd_mod_pubsub_  362864 1711583 8713696       0 gen_server:loop/6
<4138.28.0>    user                  200098   98071    8356       0 user:server_loop/2
<4138.4.0>     error_logger          172429  679463    9060       0 gen_event:loop/4
<4138.250.0>   ejabberd_http_sup      26944   61413  157268       0 gen_server:loop/6
<4138.751.0>   proc_lib:init_p/5      24982   12433   27520       0 gen_server:loop/6
<4138.109.0>   proc_lib:init_p/5      24581   50473    6848       0 dets:open_file_loop2
<4138.32296.8> proc_lib:init_p/5      21341    4711    9268       0 ejabberd_http_bind:r
<4138.258.0>   proc_lib:init_p/5      20949   29220    2324       0 prim_inet:accept0/2
<4138.107.0>   proc_lib:init_p/5      20624   12266 2938484       0 dets:open_file_loop2
<4138.750.0>   proc_lib:init_p/5      14388   54855   34108       0 gen_fsm:loop/7
========================================================================================

etop:stop().
========================================================================================
 'ejabberd at xxxxxxx.com'                                                    15:58:32
 Load:  cpu        20               Memory:  total      240282    binary       3079
        procs   99851                        processes       1    code          426
        runq     4321                        atom         3936    ets        113115

Pid            Name or Initial Func    Time    Reds  Memory    MsgQ Current Function
----------------------------------------------------------------------------------------
<4138.386.0>   ejabberd_mod_pubsub_  396481 2033496 8717968     355 dict:fold_bucket/3
<4138.4.0>     error_logger          166942  658814   13276       0 gen_event:loop/4
<4138.28.0>    user                  113660   96806    8356       0 user:server_loop/2
<4138.258.0>   proc_lib:init_p/5      41989   28297    2376       1 gen:wait_resp_mon/3
<4138.750.0>   proc_lib:init_p/5      33458   49788   27720       0 gen_fsm:loop/7
<4138.107.0>   proc_lib:init_p/5      29279    8441 1572280       0 dets:open_file_loop2
<4138.519.0>   proc_lib:init_p/5      26430    158813164264       0 gen_server:loop/6
<4138.250.0>   ejabberd_http_sup      21841   45561  157248       0 gen_server:loop/6
<4138.5975.3>  proc_lib:init_p/5      19367     819   44676       0 gen_fsm:loop/7
<4138.109.0>   proc_lib:init_p/5      16332   40175    6848       0 dets:open_file_loop2
========================================================================================


More information about the ejabberd mailing list