ets:update_counter/3 taking a looooong time!

[Peter-Henry Mander]

.... and to follow up, yes indeed, a staggered start does make the setup 
time run consistently around 33 to 35 calls per second. But that's not 
brilliant. The 1500 calls per second burst makes me want to improve that 
considerably!

/grumble/ I'm going home!  )-:

Pete.

Peter-Henry Mander wrote:
> Hi Gurus,
> 
> I'm puzzled.
> 
> I'm trying to build a stressor tool using the Megaco stack provided with 
> Erlang/OTP R9B, and using fprof I seem to have isolated where the 
> bottleneck is, except I don't believe it's in ets:update_counter/3.
> 
> The stressor creates a bunch of processes which run through a standard 
> add modify and subtract Megaco message sequence. It runs wonderfully 
> fast as long as there are no more than 16 or 17 processes started 
> concurrently, each sending the message sequences. Below this threshold I 
> manage to get 1500 calls setup per second, above I only get a pitiful 4 
> to 6 call setups a second. If I increase the process count gradually to 
> 2000, I can start 16 new processes and still get a high rate, but any 
> more than 16 at once kills the setup rate again.
> 
> I get the impression that some sort of staggered process startup is 
> required, it's as if there's a process being starved somewhere.
> 
> The attached gives the output of fprof, and the last line indicates that 
> all the time is spent waiting for ets:update_counter/3 to return a new 
> transaction ID to megaco_config:incr_trans_id_counter/1. The functions 
> above in the deleted lines creates a Megaco ActionRequest record.
> 
> What have I done wrong? I feel as if there's a solution staring me in 
> the face, but I just don't see it!
> 
> Pete.
> 
> 
> ------------------------------------------------------------------------
> 
> 
>  ... calling processes deleted ...
> 
> {[{{transaction,action_request_single,3},                                 3,        12602.531,            0.030}],     
>  { {megaco,call,3},                                                       3,        12602.531,            0.030},     %
>  [{{megaco_messenger,call,3},                                             3,        12602.521,            0.025}]}.    
> 
> {[{{megaco,call,3},                                                       3,        12602.521,            0.025}],     
>  { {megaco_messenger,call,3},                                             3,        12602.521,            0.025},     %
>  [{{megaco_messenger,call_or_cast,4},                                     3,        12602.513,           11.633}]}.    
> 
> {[{{megaco_messenger,call,3},                                             3,        12602.513,           11.633},      
>   {{megaco_messenger,prepare_send_options,2},                             1,            0.000,         1222.965}],     
>  { {megaco_messenger,call_or_cast,4},                                     4,        12602.513,         1234.598},     %
>  [{{megaco_messenger,prepare_send_options,2},                             3,        12602.502,            0.408},      
>   {{megaco_messenger,encode_request,2},                                   3,         1231.677,            0.029},      
>   {{megaco_messenger,wait_for_reply,1},                                   2,          270.899,          270.862},      
>   {{megaco_messenger,send_request,5},                                     3,            2.205,            2.316},      
>   {{megaco_messenger,override_send_options,2},                            1,            0.034,            0.036},      
>   {{megaco_messenger,to_local_trans_id,1},                                3,            0.029,            0.000},      
>   {{transaction,action_request_single,3},                                 1,            0.000,         7011.844}]}.    
> 
> {[{{megaco_messenger,call_or_cast,4},                                     3,        12602.502,            0.408},      
>   {{ets,update_counter,3},                                                1,            0.000,         2104.955}],     
>  { {megaco_messenger,prepare_send_options,2},                             4,        12602.502,         2105.363},     %
>  [{{megaco_config,incr_trans_id_counter,1},                               3,        12602.484,            0.435},      
>   {{megaco_config,reset_trans_id_counter,4},                              1,         2104.947,            0.049},      
>   {{megaco_messenger,override_send_options,2},                            2,            0.074,            0.076},      
>   {{megaco_messenger,call_or_cast,4},                                     1,            0.000,         1222.965}]}.    
> 
> {[{{megaco_messenger,prepare_send_options,2},                             3,        12602.484,            0.435}],     
>  { {megaco_config,incr_trans_id_counter,1},                               3,        12602.484,            0.435},     %
>  [{{ets,update_counter,3},                                                3,        12602.424,            0.034},      
>   {{megaco_config,lookup_local_conn,1},                                   3,            0.257,            0.258},      
>   {{erlang,setelement,3},                                                 2,            0.016,            0.000}]}.