Efficiency of frequent tasks

[martinsumner]

Looking at an eprof profile of a counter update test:

FUNCTION                               CALLS        %   TIME  [uS / CALLS]
--------                               -----  -------   ----  [----------]
riak_core_vnode_proxy:reg_name/2         576     0.35    165  [      0.29]
riak_object:fold_meta_to_bin/3          1152     0.36    170  [      0.15]
riak_kv_put_fsm:get_option/3            2304     0.38    181  [      0.08]
gen:do_call/4                             97     0.40    188  [      1.94]
application_controller:get_env/2        2400     0.49    231  [      0.10]
ets:insert/2                             672     0.52    247  [      0.37]
erlang:send/3                            576     0.52    249  [      0.43]
lists:sublist_2/2                       4032     0.53    250  [      0.06]
erlang:send/2                            485     0.54    257  [      0.53]
erts_internal:port_command/3              96     0.61    291  [      3.03]
erlang:integer_to_list/1                 672     0.63    300  [      0.45]
vclock:descends/2                       4948     0.71    337  [      0.07]
erlang:term_to_binary/1                 1248     0.78    369  [      0.30]
ets:lookup_element/4                    2592     0.90    425  [      0.16]
gen_fsm:dispatch/4                      1788     0.95    451  [      0.25]
gen_fsm:send_event/2                     938     1.00    477  [      0.51]
lists:keyfind/3                         9238     1.22    579  [      0.06]
riak_core_vnode_proxy:handle_proxy/2     288     1.23    584  [      2.03]
ets:lookup/2                            2400     1.49    707  [      0.29]
proplists:get_value/3                  40608     2.98   1413  [      0.03]
erts_internal:trace_pattern/3              2     4.25   2018  [   1009.00]
riak_core_vnode_proxy:loop/2             581     6.28   2980  [      5.13]
gen_server:loop/7                        385     7.70   3656  [      9.50]
gen_fsm:handle_msg/8                    1788    11.11   5273  [      2.95]
gen_fsm:loop/8                          1789    27.45  13033  [      7.29]
------------------------------------  ------  -------  -----  [----------]
Total:                                272560  100.00%  47483  [      0.17]

Hypothesis is that loop/handle_msg reports are false measurements (i.e. it is measuring the wait in a receive loop for a message to arrive, rather than actual CPU work). The erts_internal:trace_pattern/3 calls are as a result of eprof. So other calls, even when only 1% of the load, may be actually relatively more significant than reported.

Two functions are of particular concern:

• vclock:descends/2 which also uses heavily lists:keyfind\3;
• riak_core_vnode_master:vmaster_to_vmod/1 which uses lists:sublist/2;
• riak_core_vnode_proxy:reg_name/2 which uses integer_to_list/1 on an integer inflated with lots of trailing zeros.

These functions do not seem optimised for common uses cases:

• with vclock:descends/2 when the two vclocks are already sorted lists with the same members (just different counts);
• with riak_core_vnode_master:vmaster_to_vmod/1 when the vnode is riak_kv_vnode.
• with riak_core_vnode_proxy:reg_name/2 for the riak_kv_vnode Module for the expected range of values for Index.

[martinsumner]

Note - the profile was taken after disabling stats, and AAE