Performance review (eprof) - WIP

[martinsumner]

Some notes and potential performance-related issues to be based on eprof analysis.

Method:

• Run isolated perf_SUITE profiles to confirm performance profiles of certain functions at a vnode level.
• Run the [general_api_perf)[https://github.com/OpenRiak/riak_test/blob/openriak-3.4/tests/general_api_perf.erl] riak_test test, but with a more balanced load (more GETs), and as a multi-node cluster. Point all clients at the same node in the cluster.
• Periodically check eprof profiles on the client-connected node, and on a sample other node - to distinguish between API and object FSM load and backend load.
• Repeat with different settings to try and understand the profile.

[martinsumner]

perf_SUITE results, using block version 3 change

Focus just on profiles relevant to the general_api_perf test.

LOAD:

FUNCTION                                       CALLS        %      TIME  [uS / CALLS]
--------                                       -----  -------      ----  [----------]
leveled_codec:strip_to_statusonly/1          5055000     0.52    202010  [      0.04]
leveled_sstblock:serialise_block_aslist/2      28614     0.54    210338  [      7.35]
leveled_sst:update_buildtimings/2             226644     0.55    216003  [      0.95]
erlang:setelement/3                          3028245     0.56    217311  [      0.07]
leveled_ebloom:add_hashlist/5                4708659     0.59    230072  [      0.05]
leveled_sstblock:decompress_block/2           248238     0.64    250318  [      1.01]
testutil:new_v1/2                             120000     0.72    279817  [      2.33]
leveled_sstblock:compress_block/2             261783     0.78    304690  [      1.16]
leveled_codec:to_lookup/1                    8670771     0.83    324155  [      0.04]
ets:match_object/2                               215     0.92    359681  [   1672.93]
leveled_codec:maybe_reap_expiredkey/2        5055000     0.95    370330  [      0.07]
prim_file:sync_nif/2                             239     1.01    396092  [   1657.29]
gen:do_call/4                                 365816     1.07    417566  [      1.14]
leveled_codec:count_tombs/2                 11079465     1.07    419539  [      0.04]
leveled_sst:hmac/1                            794399     1.09    426021  [      0.54]
leveled_sst:key_dominates_comparison/2       5097923     1.16    453630  [      0.09]
leveled_util:hash1/2                        12240000     1.25    489202  [      0.04]
lists:split/3                               11259933     1.27    496554  [      0.04]
prim_file:pwrite_nif/3                        120000     1.58    618157  [      5.15]
leveled_sst:accumulate_positions/2           3131245     1.80    705221  [      0.23]
leveled_ebloom:map_hashes/3                  2492921     1.92    749512  [      0.30]
leveled_sstblock:serialise_block/3            290373     1.96    765616  [      2.64]
leveled_sstblock:get_all_block/3              308637     1.96    765781  [      2.48]
lists:ukeymerge2_1/7                         5812633     2.02    789529  [      0.14]
ets:insert/2                                  240000     2.51    981404  [      4.09]
leveled_sst:form_slot/7                     11218495     2.96   1155942  [      0.10]
leveled_sst:key_dominates/3                 11169801     3.09   1209301  [      0.11]
erlang:term_to_binary/2                       240193     4.13   1613298  [      6.72]
zstd:quick_decompress/1                       248238     4.54   1775281  [      7.15]
erlang:term_to_binary/1                      1368078     7.61   2974264  [      2.17]
erlang:binary_to_term/1                       918269     8.87   3469080  [      3.78]
zstd:quick_compress/2                         381783    16.93   6619281  [     17.34]
-----------------------------------------  ---------  -------  --------  [----------]
Total:                                     197829279  100.00%  39104617  [      0.20]

HEAD:

FUNCTION                                    CALLS        %      TIME  [uS / CALLS]
--------                                    -----  -------      ----  [----------]
leveled_bookie:fetch_head/4                600000     0.51    204363  [      0.34]
dict:find/2                               1755339     0.52    206309  [      0.12]
leveled_monitor:maybe_time/1              1865158     0.55    216706  [      0.12]
leveled_ebloom:check_hash/2               1733823     0.55    220023  [      0.13]
leveled_pmanifest:key_lookup_level/3      2979590     0.58    228770  [      0.08]
leveled_sst:spawn_check_block/3            600970     0.60    237335  [      0.39]
leveled_sst:key_dominates/3               2366116     0.60    237820  [      0.10]
leveled_sstblock:get_all_block/3            55296     0.64    253001  [      4.58]
os:timestamp/0                            3583419     0.66    260443  [      0.07]
rand:seed_put/1                           3065258     0.72    287756  [      0.09]
ets:lookup/2                               600000     0.73    289785  [      0.48]
leveled_penciller:fetch/5                 2375738     0.74    293496  [      0.12]
lists:foldl_1/3                           4255700     0.76    301200  [      0.07]
leveled_sst:form_slot/7                   2374761     0.76    301342  [      0.13]
gen_statem:loop_receive/3                  665960     0.76    303706  [      0.46]
dict:find_val/2                           7887150     0.80    319393  [      0.04]
leveled_bookie:handle_call/3               600000     0.83    329278  [      0.55]
gen_server:loop/7                         1206335     0.83    329587  [      0.27]
crypto:hash_nif/2                          600000     0.84    333075  [      0.56]
erlang:demonitor/2                        1872127     0.88    351197  [      0.19]
prim_file:read_nif/2                        10794     0.90    359210  [     33.28]
leveled_ebloom:match_hash/3               2573174     0.93    370724  [      0.14]
array:get/2                               7844511     0.94    375600  [      0.05]
erlang:spawn_link/3                        600970     0.99    392306  [      0.65]
leveled_tree:search/3                     1834682     1.12    446905  [      0.24]
leveled_sst:fetch/12                       658944     1.19    473753  [      0.72]
rand:uniform/1                            3065218     1.26    500045  [      0.16]
zstd:quick_compress/2                       46205     1.29    513010  [     11.10]
leveled_pmem:'-check_index/2-fun-0-'/4    4200000     1.29    514033  [      0.12]
erlang:term_to_binary/1                    166340     1.33    530636  [      3.19]
gen:reply/2                               1872002     1.36    539637  [      0.29]
leveled_tree:iterator_from/3              6563277     1.39    551805  [      0.08]
array:get_1/3                            18180151     1.92    761635  [      0.04]
leveled_tree:lookup_best/2               11662105     2.36    937164  [      0.08]
leveled_pmem:find_pos/2                  13270612     2.40    955844  [      0.07]
prim_file:pread_nif/3                      601572     3.51   1394531  [      2.32]
gen:do_call/4                             1872106     3.55   1411511  [      0.75]
erlang:binary_to_term/1                    720799     6.68   2656231  [      3.69]
leveled_sst:find_posint/4                83524978     7.91   3146100  [      0.04]
zstd:quick_decompress/1                    647050    18.01   7160656  [     11.07]
--------------------------------------  ---------  -------  --------  [----------]
Total:                                  340380353  100.00%  39761989  [      0.12]

GET:

FUNCTION                                    CALLS        %      TIME  [uS / CALLS]
--------                                    -----  -------      ----  [----------]
ets:lookup/2                               300000     0.39    152379  [      0.51]
leveled_bookie:handle_call/3               300000     0.40    153091  [      0.51]
erlang:monitor/2                          1529736     0.40    154024  [      0.10]
leveled_cdb:calc_crc/2                     300000     0.40    154796  [      0.52]
leveled_cdb:get/7                          300000     0.40    154951  [      0.52]
dict:find_val/2                           3942488     0.41    156912  [      0.04]
prim_file:position_1/3                    1220894     0.42    162854  [      0.13]
crypto:hash_nif/2                          300000     0.43    165722  [      0.55]
os:timestamp/0                            2465289     0.45    171994  [      0.07]
erlang:spawn_link/3                        300494     0.47    181371  [      0.60]
leveled_ebloom:match_hash/3               1287106     0.47    181585  [      0.14]
array:get/2                               3917910     0.49    190503  [      0.05]
leveled_tree:search/3                      917663     0.58    224082  [      0.24]
leveled_sst:fetch/12                       329735     0.61    235643  [      0.71]
prim_file:read/2                          1567388     0.63    243017  [      0.16]
leveled_pmem:'-check_index/2-fun-0-'/4    2100000     0.65    250950  [      0.12]
rand:uniform/1                            1529758     0.65    252085  [      0.16]
gen_server:loop/7                          900046     0.66    255369  [      0.28]
gen_statem:loop_receive/3                  629764     0.72    276845  [      0.44]
erlang:demonitor/2                        1529736     0.72    278071  [      0.18]
leveled_tree:iterator_from/3              3282096     0.76    292530  [      0.09]
array:get_1/3                             9076863     0.99    383085  [      0.04]
gen:reply/2                               1529735     1.07    411024  [      0.27]
leveled_tree:lookup_best/2                5822281     1.26    484945  [      0.08]
leveled_pmem:find_pos/2                   6634349     1.35    521316  [      0.08]
prim_file:pread_nif/3                      300494     1.80    693447  [      2.31]
prim_file:seek_nif/3                      1220894     2.41    928203  [      0.76]
gen:do_call/4                             1529736     2.59    998197  [      0.65]
erlang:binary_to_term/1                    646988     2.87   1107883  [      1.71]
leveled_util:hash1/2                     30599970     2.92   1128460  [      0.04]
leveled_sst:find_posint/4                41788372     4.03   1554667  [      0.04]
zstd:quick_decompress/1                    600494    13.03   5029590  [      8.38]
prim_file:read_nif/2                      1567388    33.82  13050003  [      8.33]
--------------------------------------  ---------  -------  --------  [----------]
Total:                                  238254139  100.00%  38589518  [      0.16]

MINI_QUERY

FUNCTION                                               CALLS        %      TIME  [uS / CALLS]
--------                                               -----  -------      ----  [----------]
gen_server:loop/7                                     597692     1.00    110627  [      0.19]
lists:foldl_1/3                                      1693421     1.00    111277  [      0.07]
leveled_tree:idxtlookup_range_end/5                   417522     1.01    111514  [      0.27]
lists:map/2                                          1453706     1.01    111730  [      0.08]
lists:takewhile_1/2                                  1202431     1.01    112099  [      0.09]
leveled_tree:iterator_from/3                         1411631     1.19    131920  [      0.09]
leveled_penciller:find_nextkeys/6                    1754869     1.31    145593  [      0.08]
lists:reverse/1                                      3581102     1.48    163653  [      0.05]
erlang:demonitor/2                                    834767     1.52    168915  [      0.20]
leveled_tree:'-idxtlookup_range_start/4-fun-0-'/2    1708960     1.58    175598  [      0.10]
leveled_tree:skpllookup_to_range/4                    796904     2.12    235220  [      0.30]
lists:splitwith_1/3                                  2526987     2.16    239252  [      0.09]
gen:reply/2                                           735153     2.36    261287  [      0.36]
prim_file:pread_nif/3                                 118544     2.43    269756  [      2.28]
leveled_tree:'-skpllookup_to_range/4-fun-0-'/2       3211075     2.62    290487  [      0.09]
lists:dropwhile_1/2                                  3888664     2.65    293431  [      0.08]
zstd:quick_decompress/1                               130269     3.54    392185  [      3.01]
leveled_codec:endkey_passed/2                        4578796     3.82    423564  [      0.09]
gen:do_call/4                                         735154     4.19    463935  [      0.63]
leveled_tree:skplfold_range/4                        7160044     5.89    653303  [      0.09]
erlang:binary_to_term/1                               511424     8.78    972691  [      1.90]
-------------------------------------------------  ---------  -------  --------  [----------]
Total:                                             110119867  100.00%  11083451  [      0.10]

UPDATE

FUNCTION                                CALLS        %      TIME  [uS / CALLS]
--------                                -----  -------      ----  [----------]
prim_file:pread_nif/3                   42038     0.74    154406  [      3.67]
leveled_codec:count_tombs/2           4059757     0.79    165068  [      0.04]
io_lib:write/2                         720195     0.80    166030  [      0.23]
lists:keyfind/3                       3397539     0.82    169935  [      0.05]
leveled_pmem:find_pos/2               1936073     0.87    181211  [      0.09]
lists:split/3                         4081286     0.89    185282  [      0.05]
io_lib_format:collect_cseq/2           720202     1.03    213323  [      0.30]
leveled_sst:find_posint/4             5419996     1.04    216314  [      0.04]
io_lib:get_option/3                   2880780     1.11    231279  [      0.08]
lists:ukeymerge2_1/7                  2111410     1.22    253291  [      0.12]
leveled_ebloom:map_hashes/3            810137     1.23    254735  [      0.31]
leveled_sst:accumulate_positions/2    1021081     1.23    255036  [      0.25]
leveled_sstblock:serialise_block/3     103708     1.31    271626  [      2.62]
lists:do_flatten/2                    4272355     1.32    274914  [      0.06]
leveled_pclerk:do_merge/10                 72     1.39    288048  [   4000.67]
gen:do_call/4                          344921     1.46    302486  [      0.88]
prim_file:pwrite_nif/3                  60000     1.57    325176  [      5.42]
leveled_sstblock:get_all_block/3       112215     1.64    340984  [      3.04]
leveled_sst:key_dominates/3           4126819     1.99    412523  [      0.10]
ets:insert/2                           120000     2.10    436305  [      3.64]
leveled_sst:form_slot/7               4144247     2.20    457326  [      0.11]
erlang:term_to_binary/2                120555     3.26    677281  [      5.62]
zstd:quick_decompress/1                128779     4.70    975292  [      7.57]
erlang:term_to_binary/1                539244     5.31   1101932  [      2.04]
erlang:binary_to_term/1                480447     7.03   1459790  [      3.04]
zstd:quick_compress/2                  153737    11.46   2379359  [     15.48]
----------------------------------  ---------  -------  --------  [----------]
Total:                              135520689  100.00%  20767408  [      0.15]

Common themes are, the presence of these functions:

• erlang:term_to_binary/2 (2-arity variant used when converting keys for hashing, which needs to be backwards compatible)
• zstd:quick_decompress/1 (decompress small binary - quick_decompress is used only for small binaries, and uses a NIF not a dirty-NIF)
• erlang:term_to_binary/1
• erlang:binary_to_term/1
• zstd:quick_compress/2 (compress small binary - quick_compress is used only for small binaries, and uses a NIF not a dirty-NIF)
• leveled_sst:find_posint/4 (used to check for a hash in a slot - one call required for each member of the slot i.e. up to 128 calls to lookup a single key)

[martinsumner]

Running general_api_perf, random profiles from non-client-facing-node, but under light load (only a single client):

FUNCTION                             CALLS        %     TIME  [uS / CALLS]
--------                             -----  -------     ----  [----------]
crypto:hash_nif/2                     8478     0.92    10229  [      1.21]
gen:reply/2                          20715     1.06    11801  [      0.57]
prim_file:pwrite_nif/3                 686     1.06    11855  [     17.28]
zstd:quick_compress/2                  686     1.10    12222  [     17.82]
exometer_probe:loop/1                24014     1.10    12278  [      0.51]
exometer_shallowtree:meld/2          92844     1.17    13063  [      0.14]
string:'-to_lower/1-lc$^0/1-0-'/1   108556     1.20    13357  [      0.12]
leveled_sst:find_posint/4           367694     1.33    14784  [      0.04]
erlang:term_to_binary/2               3754     1.34    14940  [      3.98]
ets:insert/2                          9252     1.58    17631  [      1.91]
erlang:send/2                         9981     1.74    19389  [      1.94]
prim_file:read_nif/2                  7074     1.95    21726  [      3.07]
gen_server:loop/7                    25762     2.12    23575  [      0.92]
exometer_proc:cast/2                 24008     2.28    25383  [      1.06]
zstd:quick_decompress/1               3890     2.29    25536  [      6.56]
erlang:send/3                         5831     2.47    27538  [      4.72]
ets:lookup/2                         36934     2.67    29790  [      0.81]
erlang:binary_to_term/1              17992     3.18    35427  [      1.97]
gen:do_call/4                        20029     3.21    35792  [      1.79]
---------------------------------  -------  -------  -------  [----------]
Total:                             5118861  100.00%  1113715  [      0.22]

FUNCTION                             CALLS        %     TIME  [uS / CALLS]
--------                             -----  -------     ----  [----------]
gen:reply/2                          19308     1.03    10484  [      0.54]
exometer_shallowtree:meld/2          78330     1.04    10569  [      0.13]
exometer_probe:loop/1                21486     1.06    10844  [      0.50]
zstd:quick_compress/2                  609     1.08    10975  [     18.02]
prim_file:pwrite_nif/3                 609     1.16    11825  [     19.42]
string:'-to_lower/1-lc$^0/1-0-'/1    96348     1.16    11881  [      0.12]
erlang:term_to_binary/2               3350     1.30    13267  [      3.96]
ets:insert/2                          8241     1.59    16266  [      1.97]
leveled_sst:find_posint/4           424286     1.66    16961  [      0.04]
erlang:send/2                         8984     1.72    17556  [      1.95]
prim_file:read_nif/2                  6324     1.84    18753  [      2.97]
gen_server:loop/7                    23122     2.15    21970  [      0.95]
exometer_proc:cast/2                 21482     2.28    23285  [      1.08]
erlang:send/3                         5211     2.40    24438  [      4.69]
ets:lookup/2                         32959     2.60    26525  [      0.80]
zstd:quick_decompress/1               3801     2.73    27837  [      7.32]
gen:do_call/4                        18699     2.99    30479  [      1.63]
erlang:binary_to_term/1              16431     3.56    36257  [      2.21]
---------------------------------  -------  -------  -------  [----------]
Total:                             4739810  100.00%  1019836  [      0.22]

FUNCTION                                  CALLS        %     TIME  [uS / CALLS]
--------                                  -----  -------     ----  [----------]
prim_file:sync_nif/2                          9     0.76    10096  [   1121.78]
exometer_shallowtree:meld/2               75045     0.78    10379  [      0.14]
exometer_probe:loop/1                     20909     0.78    10419  [      0.50]
gen:reply/2                               19081     0.80    10683  [      0.56]
prim_file:pwrite_nif/3                      596     0.81    10781  [     18.09]
leveled_sst:deserialise_checkedblock/2     5522     0.81    10889  [      1.97]
prim_file:pread_nif/3                      1726     0.85    11325  [      6.56]
string:'-to_lower/1-lc$^0/1-0-'/1         93944     0.86    11520  [      0.12]
leveled_codec:maybe_reap_expiredkey/2    163786     0.90    12069  [      0.07]
erlang:term_to_binary/2                    3260     1.09    14573  [      4.47]
leveled_sst:serialise_block/2              4208     1.12    15034  [      3.57]
leveled_sst:key_dominates_comparison/2   164287     1.13    15091  [      0.09]
ets:insert/2                               8038     1.18    15713  [      1.95]
leveled_sst:find_posint/4                437067     1.30    17410  [      0.04]
leveled_sst:form_slot/7                  164963     1.36    18120  [      0.11]
leveled_sst:key_dominates/3              164339     1.38    18477  [      0.11]
gen_server:loop/7                         22599     1.41    18801  [      0.83]
erlang:send/2                              8808     1.42    18949  [      2.15]
exometer_proc:cast/2                      20905     1.65    22120  [      1.06]
erlang:send/3                              5073     1.81    24157  [      4.76]
ets:lookup/2                              32171     1.93    25753  [      0.80]
gen:do_call/4                             18485     2.36    31533  [      1.71]
erlang:term_to_binary/1                    8381     2.60    34729  [      4.14]
prim_file:read_nif/2                       6126     2.61    34953  [      5.71]
zstd:quick_decompress/1                    6728     3.24    43312  [      6.44]
zstd:quick_compress/2                      3974     3.39    45393  [     11.42]
erlang:binary_to_term/1                   19819     5.45    72905  [      3.68]
--------------------------------------  -------  -------  -------  [----------]
Total:                                  6724556  100.00%  1337216  [      0.20]

FUNCTION                             CALLS        %    TIME  [uS / CALLS]
--------                             -----  -------    ----  [----------]
gen:reply/2                          18190     1.02   10102  [      0.56]
zstd:quick_compress/2                  575     1.07   10601  [     18.44]
exometer_probe:loop/1                19772     1.08   10669  [      0.54]
exometer_shallowtree:meld/2          84552     1.12   11016  [      0.13]
string:'-to_lower/1-lc$^0/1-0-'/1    90416     1.14   11212  [      0.12]
erlang:term_to_binary/2               3072     1.46   14395  [      4.69]
ets:insert/2                          7673     1.61   15924  [      2.08]
erlang:send/2                         8491     1.61   15940  [      1.88]
prim_file:pwrite_nif/3                 575     1.68   16540  [     28.77]
leveled_sst:find_posint/4           446959     1.82   17945  [      0.04]
prim_file:read_nif/2                  6342     1.87   18439  [      2.91]
gen_server:loop/7                    21549     2.06   20361  [      0.94]
exometer_proc:cast/2                 19768     2.21   21805  [      1.10]
erlang:send/3                         4798     2.36   23252  [      4.85]
ets:lookup/2                         30562     2.53   25018  [      0.82]
zstd:quick_decompress/1               3686     2.97   29359  [      7.97]
gen:do_call/4                        17612     3.37   33305  [      1.89]
erlang:binary_to_term/1              15167     3.78   37264  [      2.46]
---------------------------------  -------  -------  ------  [----------]
Total:                             4408974  100.00%  987006  [      0.22]

FUNCTION                                  CALLS        %     TIME  [uS / CALLS]
--------                                  -----  -------     ----  [----------]
exometer_probe:loop/1                     20919     0.67    10351  [      0.49]
leveled_codec:strip_to_statusonly/1      258004     0.68    10570  [      0.04]
lists:split/3                            253532     0.73    11225  [      0.04]
gen:reply/2                               19290     0.73    11302  [      0.59]
prim_file:pread_nif/3                      1838     0.75    11585  [      6.30]
string:'-to_lower/1-lc$^0/1-0-'/1         98300     0.78    12118  [      0.12]
prim_file:pwrite_nif/3                      621     0.82    12681  [     20.42]
prim_file:sync_nif/2                         13     0.83    12863  [    989.46]
exometer_shallowtree:meld/2              111544     0.94    14442  [      0.13]
erlang:term_to_binary/2                    3292     1.05    16145  [      4.90]
ets:insert/2                               8157     1.07    16477  [      2.02]
leveled_sst:find_posint/4                459474     1.18    18205  [      0.04]
erlang:send/2                              9054     1.21    18626  [      2.06]
leveled_codec:maybe_reap_expiredkey/2    258004     1.24    19167  [      0.07]
gen_server:loop/7                         22871     1.37    21222  [      0.93]
exometer_proc:cast/2                      20915     1.39    21474  [      1.03]
prim_file:read_nif/2                       8633     1.45    22441  [      2.60]
leveled_sst:key_dominates_comparison/2   258533     1.52    23429  [      0.09]
erlang:send/3                              5063     1.56    24144  [      4.77]
leveled_sst:deserialise_checkedblock/2     7538     1.59    24561  [      3.26]
leveled_sst:serialise_block/2              6127     1.63    25152  [      4.11]
ets:lookup/2                              32510     1.74    26815  [      0.82]
leveled_sst:form_slot/7                  259597     1.85    28614  [      0.11]
leveled_sst:key_dominates/3              258611     1.87    28853  [      0.11]
gen:do_call/4                             18669     2.37    36548  [      1.96]
erlang:term_to_binary/1                   10476     3.34    51575  [      4.92]
zstd:quick_decompress/1                    8752     3.59    55413  [      6.33]
zstd:quick_compress/2                      5942     4.27    65898  [     11.09]
erlang:binary_to_term/1                   21704     6.24    96436  [      4.44]
--------------------------------------  -------  -------  -------  [----------]
Total:                                  7948663  100.00%  1544388  [      0.19]

[martinsumner]

Same test - looking at the profile of the client-connected node:

FUNCTION                                   CALLS        %     TIME  [uS / CALLS]
--------                                   -----  -------     ----  [----------]
erlang:term_to_binary/2                     5602     0.57    10051  [      1.79]
leveled_codec:maybe_reap/2                267760     0.57    10105  [      0.04]
leveled_codec:count_tombs/2               268864     0.59    10315  [      0.04]
lists:ukeymerge2_1/7                      108646     0.59    10388  [      0.10]
lists:sublist_2/2                          93083     0.63    11037  [      0.12]
ets:insert/2                               15491     0.63    11039  [      0.71]
leveled_codec:strip_to_statusonly/1       267760     0.66    11658  [      0.04]
lists:split/3                             266995     0.67    11773  [      0.04]
riak_kv_pb_object:process/2                 4156     0.68    11989  [      2.88]
lists:keyfind/3                           146272     0.70    12244  [      0.08]
riak_kv_pb:encode_msg_rpbpair/3            59182     0.72    12587  [      0.21]
prim_file:sync_nif/2                          12     0.74    13026  [   1085.50]
erlang:send/2                               9245     0.74    13089  [      1.42]
riak_kv_pb:e_type_bytes/3                 129112     0.80    14060  [      0.11]
exometer_probe:loop/1                      24680     0.80    14139  [      0.57]
erts_internal:port_control/3                4219     0.83    14647  [      3.47]
riak_kv_pb:e_varint/2                     222520     0.84    14802  [      0.07]
gen_fsm:dispatch/4                         29101     0.98    17238  [      0.59]
zlib:deflate_nif/4                          3116     1.03    18050  [      5.79]
ets:lookup_element/4                       29784     1.04    18317  [      0.61]
erlang:phash/2                             44620     1.09    19096  [      0.43]
leveled_codec:maybe_reap_expiredkey/2     267760     1.16    20338  [      0.08]
exometer_proc:cast/2                       24678     1.17    20526  [      0.83]
gen:do_call/4                              12434     1.26    22190  [      1.78]
ets:lookup/2                               70135     1.32    23306  [      0.33]
leveled_sst:deserialise_checkedblock/2      6827     1.36    23940  [      3.51]
leveled_sst:key_dominates_comparison/2    268381     1.37    24081  [      0.09]
leveled_sst:serialise_block/2               6509     1.59    28065  [      4.31]
leveled_sst:key_dominates/3               268462     1.69    29791  [      0.11]
leveled_sst:form_slot/7                   269485     1.70    29981  [      0.11]
erts_internal:port_command/3                4167     2.14    37717  [      9.05]
zstd:quick_decompress/1                     6723     2.20    38669  [      5.75]
gen_fsm:loop/8                             29101     2.42    42530  [      1.46]
gen_server:loop/7                          22052     3.44    60607  [      2.75]
erlang:term_to_binary/1                    24757     3.45    60645  [      2.45]
zstd:quick_compress/2                       5793     3.52    62000  [     10.70]
erlang:binary_to_term/1                    13682     4.25    74747  [      5.46]
--------------------------------------  --------  -------  -------  [----------]
Total:                                  11444417  100.00%  1759688  [      0.15]

FUNCTION                        CALLS        %    TIME  [uS / CALLS]
--------                        -----  -------    ----  [----------]
riak_kv_pb:e_type_bytes/3      105520     1.16   11393  [      0.11]
exometer_probe:loop/1           20240     1.17   11472  [      0.57]
riak_kv_pb:e_varint/2          181876     1.20   11746  [      0.06]
erts_internal:port_control/3     3446     1.23   12078  [      3.50]
erlang:binary_to_term/1          6253     1.24   12149  [      1.94]
gen_fsm:dispatch/4              23858     1.38   13509  [      0.57]
zlib:deflate_nif/4               2552     1.43   13977  [      5.48]
ets:lookup_element/4            24316     1.46   14306  [      0.59]
erlang:phash/2                  36401     1.57   15326  [      0.42]
exometer_proc:cast/2            20245     1.73   16918  [      0.84]
gen:do_call/4                    9988     1.73   16931  [      1.70]
gen_fsm:loop/8                  23857     1.83   17864  [      0.75]
ets:lookup/2                    57409     1.84   17988  [      0.31]
gen_fsm:handle_msg/8            23858     2.13   20842  [      0.87]
erts_internal:port_command/3     3410     3.13   30607  [      8.98]
gen_server:loop/7               17996     5.26   51488  [      2.86]
----------------------------  -------  -------  ------  [----------]
Total:                        6709290  100.00%  978442  [      0.15]

FUNCTION                                  CALLS        %     TIME  [uS / CALLS]
--------                                  -----  -------     ----  [----------]
erlang:send/2                              7623     0.75    10095  [      1.32]
lists:keyfind/3                          117863     0.75    10108  [      0.09]
exometer_probe:loop/1                     20438     0.79    10657  [      0.52]
riak_kv_pb:e_type_bytes/3                104073     0.82    11172  [      0.11]
erts_internal:port_control/3               3391     0.87    11784  [      3.48]
riak_kv_pb:e_varint/2                    179324     0.88    11853  [      0.07]
gen_fsm:dispatch/4                        23654     1.01    13737  [      0.58]
zlib:deflate_nif/4                         2511     1.02    13872  [      5.52]
ets:lookup_element/4                      24126     1.07    14439  [      0.60]
erlang:phash/2                            36661     1.13    15248  [      0.42]
gen_fsm:loop/8                            23654     1.27    17211  [      0.73]
exometer_proc:cast/2                      20436     1.35    18295  [      0.90]
ets:lookup/2                              57293     1.38    18659  [      0.33]
gen:do_call/4                             10453     1.41    19117  [      1.83]
leveled_sst:deserialise_checkedblock/2     5715     1.42    19179  [      3.36]
leveled_sst:key_dominates/3              219719     1.47    19856  [      0.09]
gen_fsm:handle_msg/8                      23654     1.52    20579  [      0.87]
leveled_sst:serialise_block/2              5422     1.73    23395  [      4.31]
leveled_sst:form_slot/7                  220567     1.76    23855  [      0.11]
erts_internal:port_command/3               3359     2.22    30011  [      8.93]
zstd:quick_decompress/1                    5639     2.38    32278  [      5.72]
gen_server:loop/7                         18231     3.34    45265  [      2.48]
erlang:term_to_binary/1                   20183     3.61    48877  [      2.42]
zstd:quick_compress/2                      4817     4.01    54274  [     11.27]
erlang:binary_to_term/1                   11610     4.63    62721  [      5.40]
--------------------------------------  -------  -------  -------  [----------]
Total:                                  8522947  100.00%  1354208  [      0.16]

FUNCTION                        CALLS        %    TIME  [uS / CALLS]
--------                        -----  -------    ----  [----------]
erts_internal:port_control/3     3374     1.13   10687  [      3.17]
exometer_probe:loop/1           19467     1.18   11163  [      0.57]
riak_kv_pb:e_type_bytes/3      103657     1.18   11230  [      0.11]
riak_kv_pb:e_varint/2          178579     1.25   11885  [      0.07]
erlang:binary_to_term/1          5933     1.29   12248  [      2.06]
gen_fsm:dispatch/4              23143     1.44   13650  [      0.59]
zlib:deflate_nif/4               2499     1.48   13987  [      5.60]
ets:lookup_element/4            23557     1.51   14269  [      0.61]
erlang:phash/2                  35113     1.61   15224  [      0.43]
gen:do_call/4                    9535     1.66   15706  [      1.65]
exometer_proc:cast/2            19465     1.73   16363  [      0.84]
ets:lookup/2                    55676     1.91   18129  [      0.33]
erts_internal:port_command/3     3342     3.06   28957  [      8.66]
gen_fsm:loop/8                  23143     3.66   34703  [      1.50]
gen_server:loop/7               17237     5.21   49342  [      2.86]
----------------------------  -------  -------  ------  [----------]
Total:                        6483177  100.00%  947781  [      0.15]

FUNCTION                        CALLS        %    TIME  [uS / CALLS]
--------                        -----  -------    ----  [----------]
zstd:quick_decompress/1          1358     1.10   10300  [      7.58]
exometer_probe:loop/1           19762     1.13   10652  [      0.54]
riak_kv_pb:e_type_bytes/3      104723     1.19   11219  [      0.11]
riak_kv_pb:e_varint/2          180513     1.24   11633  [      0.06]
erts_internal:port_control/3     3422     1.27   11932  [      3.49]
erlang:binary_to_term/1          6046     1.31   12366  [      2.05]
gen_fsm:dispatch/4              23500     1.40   13182  [      0.56]
ets:lookup_element/4            23953     1.48   13915  [      0.58]
zlib:deflate_nif/4               2533     1.49   14039  [      5.54]
gen:do_call/4                    9726     1.59   14948  [      1.54]
erlang:phash/2                  35760     1.61   15147  [      0.42]
exometer_proc:cast/2            19758     1.76   16545  [      0.84]
gen_fsm:loop/8                  23499     1.87   17545  [      0.75]
ets:lookup/2                    56497     1.90   17823  [      0.32]
gen_fsm:handle_msg/8            23500     2.17   20407  [      0.87]
erts_internal:port_command/3     3386     3.21   30209  [      8.92]
gen_server:loop/7               17515     4.85   45609  [      2.60]
----------------------------  -------  -------  ------  [----------]
Total:                        6570343  100.00%  940471  [      0.14]

[martinsumner]

Analysing the top outputs, and the CPU used by the client-connected node, as opposed to the other nodes - indicates about 2/3rds of the CPU spend is in backend.

[martinsumner]

Rerunning the test with 4 clients to make the client-facing node busier. Sample profiles:

FUNCTION                           CALLS        %     TIME  [uS / CALLS]
--------                           -----  -------     ----  [----------]
erlang:demonitor/2                 15269     0.73    10181  [      0.67]
zstd:quick_decompress/1             1284     0.73    10260  [      7.99]
lists:sublist_2/2                  67708     0.76    10582  [      0.16]
riak_kv_pb_object:process/2         3054     0.79    11087  [      3.63]
lists:keyfind/3                   106262     0.82    11443  [      0.11]
gen_fsm:send_event/2                6543     0.82    11537  [      1.76]
riak_kv_pb:encode_msg_rpbpair/3    42950     0.86    12041  [      0.28]
erlang:binary_to_term/1             5834     0.95    13318  [      2.28]
riak_kv_pb:e_type_bytes/3          93576     1.00    13961  [      0.15]
riak_kv_pb:e_varint/2             161697     1.02    14274  [      0.09]
zlib:deflate_nif/4                  2292     1.11    15556  [      6.79]
gen_server:handle_msg/6            15919     1.12    15648  [      0.98]
gen_fsm:dispatch/4                 21263     1.12    15687  [      0.74]
ets:lookup_element/4               21693     1.15    16152  [      0.74]
erlang:phash/2                     32733     1.16    16198  [      0.49]
exometer_proc:cast/2               18243     1.40    19609  [      1.07]
prim_file:read_nif/2                2032     1.47    20604  [     10.14]
gen:do_call/4                       9121     1.54    21541  [      2.36]
ets:lookup/2                       51425     1.59    22284  [      0.43]
erts_internal:port_command/3        3059     1.77    24853  [      8.12]
exometer_probe:loop/1              18243     1.86    26073  [      1.43]
gen_fsm:handle_msg/8               21263     3.09    43302  [      2.04]
gen_fsm:loop/8                     21266     4.51    63112  [      2.97]
gen_server:loop/7                  15917    13.42   188021  [     11.81]
-------------------------------  -------  -------  -------  [----------]
Total:                           5927879  100.00%  1400907  [      0.24]

FUNCTION                           CALLS        %     TIME  [uS / CALLS]
--------                           -----  -------     ----  [----------]
gen_fsm:send_event/2                6269     0.81    10343  [      1.65]
lists:keyfind/3                   100398     0.81    10383  [      0.10]
riak_kv_pb:encode_msg_rpbpair/3    40628     0.85    10890  [      0.27]
erlang:binary_to_term/1             5127     0.89    11337  [      2.21]
riak_kv_pb:e_varint/2             153048     0.96    12287  [      0.08]
riak_kv_pb:e_type_bytes/3          88730     0.98    12522  [      0.14]
zlib:deflate_nif/4                  2158     1.12    14241  [      6.60]
gen_fsm:dispatch/4                 20098     1.13    14352  [      0.71]
erlang:phash/2                     30466     1.18    15022  [      0.49]
prim_file:read_nif/2                2306     1.23    15643  [      6.78]
ets:lookup_element/4               20452     1.23    15680  [      0.77]
exometer_proc:cast/2               16937     1.47    18785  [      1.11]
ets:lookup/2                       48311     1.59    20336  [      0.42]
gen:do_call/4                       8353     1.67    21288  [      2.55]
erts_internal:port_command/3        2883     1.84    23441  [      8.13]
exometer_probe:loop/1              16937     1.93    24609  [      1.45]
gen_fsm:loop/8                     20101     3.44    43882  [      2.18]
gen_fsm:handle_msg/8               20098     4.23    53984  [      2.69]
gen_server:loop/7                  14832    14.73   187947  [     12.67]
-------------------------------  -------  -------  -------  [----------]
Total:                           5568072  100.00%  1275588  [      0.23]

FUNCTION                                  CALLS        %     TIME  [uS / CALLS]
--------                                  -----  -------     ----  [----------]
gen_fsm:send_event/2                       6181     0.58    10351  [      1.67]
lists:keyfind/3                          100302     0.58    10466  [      0.10]
riak_kv_pb:encode_msg_rpbpair/3           40598     0.59    10555  [      0.26]
erlang:send/2                              6218     0.62    11070  [      1.78]
leveled_codec:to_lookup/1                257048     0.66    11798  [      0.05]
riak_kv_pb:e_type_bytes/3                 88449     0.67    12042  [      0.14]
riak_kv_pb:e_varint/2                    152671     0.68    12267  [      0.08]
leveled_codec:count_tombs/2              260608     0.70    12510  [      0.05]
zlib:deflate_nif/4                         2151     0.78    13912  [      6.47]
gen_fsm:dispatch/4                        19989     0.80    14313  [      0.72]
erlang:phash/2                            31021     0.81    14516  [      0.47]
ets:lookup_element/4                      20438     0.81    14597  [      0.71]
lists:split/3                            255612     0.88    15707  [      0.06]
exometer_proc:cast/2                      17063     0.92    16531  [      0.97]
leveled_pclerk:do_merge/10                    4     1.04    18716  [   4679.00]
ets:lookup/2                              48253     1.11    19963  [      0.41]
leveled_sst:deserialise_checkedblock/2     6172     1.17    20995  [      3.40]
erts_internal:port_command/3               2871     1.31    23447  [      8.17]
exometer_probe:loop/1                     17063     1.37    24652  [      1.44]
gen:do_call/4                              8649     1.45    25984  [      3.00]
leveled_sst:key_dominates/3              259704     1.53    27458  [      0.11]
leveled_sst:serialise_block/2              5979     1.67    29977  [      5.01]
zstd:quick_decompress/1                    5925     1.85    33212  [      5.61]
leveled_sst:form_slot/7                  260653     1.96    35089  [      0.13]
gen_fsm:loop/8                            19989     2.34    41953  [      2.10]
zstd:quick_compress/2                      5298     2.78    49913  [      9.42]
gen_fsm:handle_msg/8                      19990     2.96    53167  [      2.66]
erlang:term_to_binary/1                   18517     3.12    56030  [      3.03]
erlang:binary_to_term/1                   10967     4.11    73713  [      6.72]
gen_server:handle_msg/6                   14899     6.00   107639  [      7.22]
gen_server:loop/7                         14900     9.80   175743  [     11.79]
--------------------------------------  -------  -------  -------  [----------]
Total:                                  7329758  100.00%  1793702  [      0.24]

FUNCTION                           CALLS        %     TIME  [uS / CALLS]
--------                           -----  -------     ----  [----------]
zstd:quick_decompress/1             1249     0.83    10211  [      8.18]
lists:keyfind/3                   100062     0.83    10255  [      0.10]
riak_kv_pb:encode_msg_rpbpair/3    40846     0.84    10348  [      0.25]
gen_fsm:send_event/2                6196     0.86    10588  [      1.71]
riak_kv_pb:e_type_bytes/3          89157     0.97    11999  [      0.13]
riak_kv_pb:e_varint/2             153674     1.00    12303  [      0.08]
erlang:binary_to_term/1             5437     1.05    12888  [      2.37]
zlib:deflate_nif/4                  2155     1.12    13830  [      6.42]
gen_fsm:dispatch/4                 20052     1.14    14073  [      0.70]
erlang:phash/2                     31103     1.17    14452  [      0.46]
ets:lookup_element/4               20425     1.18    14576  [      0.71]
exometer_proc:cast/2               17057     1.45    17887  [      1.05]
ets:lookup/2                       48356     1.62    19966  [      0.41]
gen:do_call/4                       8626     1.76    21645  [      2.51]
erts_internal:port_command/3        2877     1.89    23287  [      8.09]
exometer_probe:loop/1              17057     2.00    24687  [      1.45]
gen_fsm:loop/8                     20052     3.19    39322  [      1.96]
gen_fsm:handle_msg/8               20052     4.06    49977  [      2.49]
gen_server:loop/7                  14967    13.54   166860  [     11.15]
-------------------------------  -------  -------  -------  [----------]
Total:                           5610815  100.00%  1231921  [      0.22]

[martinsumner]

Some observations of potential issues:

gen_server_loop/7

The busier we make the client-facing node, the higher the cost of each call to gen_server_loop/7. There is a riak_api_pb_listener process which is an implementation of gen_nb_server, which in turn uses a gen_server. This is a potential gen_server that might be prominent on a client-facing node not, but not other nodes. This then starts a riak_api_pb_server for each connection which is a gen_fsm. the gen_fsm:loop/8 calls are presumably some combination of these FSMs and the individual GET/PUT FSMs. so in theory the listener, should only be woken from gen_server:loop/7 for new connection requests - and so this should not be getting frequent loop calls.

The gen_server_loop is just a receive statement, and it is not a selective receive - so it should not be variable even with the size of the message queue.

This an eprof profile with 6 clients (the profile stops working by 8 clients):

FUNCTION                        CALLS        %     TIME  [uS / CALLS]
--------                        -----  -------     ----  [----------]
prim_file:read_nif/2             1272     0.86    10145  [      7.98]
riak_kv_pb:e_type_bytes/3       64989     0.87    10234  [      0.16]
riak_kv_pb:e_varint/2          111902     0.87    10292  [      0.09]
zlib:deflate_nif/4               1583     0.93    10911  [      6.89]
gen_fsm:dispatch/4              14795     0.95    11223  [      0.76]
erlang:phash/2                  22185     0.96    11319  [      0.51]
ets:lookup_element/4            14965     0.96    11360  [      0.76]
exometer_proc:cast/2            12348     1.01    11867  [      0.96]
gen_statem:loop_receive/3        1367     1.07    12571  [      9.20]
gen:do_call/4                    6091     1.19    14011  [      2.30]
ets:lookup/2                    35440     1.33    15699  [      0.44]
erts_internal:port_command/3     2116     1.58    18575  [      8.78]
exometer_probe:loop/1           12352     2.41    28399  [      2.30]
gen_fsm:loop/8                  14793     3.65    42964  [      2.90]
gen_fsm:handle_msg/8            14795     6.70    78977  [      5.34]
gen_server:loop/7               10892    20.34   239649  [     22.00]
----------------------------  -------  -------  -------  [----------]
Total:                        4123398  100.00%  1178154  [      0.29]

The use of gen_nb_server is a potential item of technical debt. It is included, with a reference to its use in other IO intensive projects (e.g. RabbitMQ) - but it is unclear if this is fixing a problem from early OTP implementations which is now resolved in get_tcp/inet. RabbitMQ still have references to it in erlang.mk files - but no references in the code.

Looking at the same test, run with light load and the HTTP API - the gen_server:loop/7 calls appear to be present here as well:

FUNCTION                                      CALLS        %     TIME  [uS / CALLS]
--------                                      -----  -------     ----  [----------]
webmachine_request:call/2                    104727     0.53    12589  [      0.12]
prim_file:read_nif/2                           1770     0.54    12746  [      7.20]
io_lib_format:collect/2                      139344     0.55    13144  [      0.09]
mochiweb_http:request/3                        2793     0.56    13242  [      4.74]
zlib:deflate_nif/4                             2091     0.57    13559  [      6.48]
erlang:'++'/2                                136882     0.57    13560  [      0.10]
gen_fsm:loop/8                                13866     0.57    13617  [      0.98]
io_lib_format:build_limited/5                139344     0.58    13751  [      0.10]
gen_fsm:dispatch/4                            13866     0.59    14086  [      1.02]
webmachine_dispatcher:try_path_binding/7     226249     0.59    14105  [      0.06]
io_lib_format:collect_cseq/2                  38433     0.61    14385  [      0.37]
ets:lookup_element/4                          38786     0.61    14480  [      0.37]
webmachine_dispatcher:bind/4                 270945     0.61    14619  [      0.05]
lists:do_flatten/2                           219517     0.63    14869  [      0.07]
mochiweb_headers:trim_and_reverse/2          263892     0.63    14952  [      0.06]
webmachine_decision_core:resource_call/1      75408     0.63    15032  [      0.20]
erlang:phash/2                                64017     0.66    15744  [      0.25]
lists:foldl_1/3                              237409     0.67    16017  [      0.07]
webmachine_resource:resource_call/3           53036     0.73    17268  [      0.33]
string:strip_right/2                         243451     0.73    17418  [      0.07]
lists:keyfind/3                              317550     0.82    19598  [      0.06]
string:tokens_single_2/4                     543651     0.84    20060  [      0.04]
exometer_proc:cast/2                          16500     0.86    20542  [      1.24]
gb_trees:lookup_1/2                          382886     0.87    20773  [      0.05]
erlang:put/2                                 417635     0.97    22992  [      0.06]
gen:do_call/4                                 13398     1.05    25010  [      1.87]
webmachine_dispatcher:try_host_binding1/6    114521     1.08    25572  [      0.22]
lists:reverse/2                              335402     1.14    27088  [      0.08]
webmachine_resource:do/3                      75408     1.14    27215  [      0.36]
gb_trees:insert_1/4                          267882     1.15    27308  [      0.10]
lists:reverse/1                              477931     1.43    34011  [      0.07]
erts_internal:port_control/3                  38207     1.53    36362  [      0.95]
erts_internal:port_command/3                   5658     1.59    37766  [      6.67]
gen_server:loop/7                             17502     1.60    38138  [      2.18]
ets:lookup/2                                  55212     3.09    73367  [      1.33]
string:to_lower_char/1                      2570124     4.45   105693  [      0.04]
string:'-to_lower/1-lc$^0/1-0-'/1           2784857    12.33   293263  [      0.11]
-----------------------------------------  --------  -------  -------  [----------]
Total:                                     23076939  100.00%  2377647  [      0.10]

Though now they are relatively less significant because of all the strings/gb_trees overhead.

So it seems likely that the gen_server:loop/7 calls are not API related.

exometer

Gathering stats has a cost, but statistics are important. the two most common function calls are the exometer_proc:cast/2 and exometer_probe:loop/1, but the other call that is slightly lower is exometer_shallowtree:meld/2.

Perhaps the one thing is took at the use of histograms for vnode-level stats. The vnode-level stats drive the volume, and the histograms drive the complexity - are they all worth it.

It looks at the moment that 4-5% of CPU is exometer_core related.

ets:lookup/2 and ets:lookup_element/4

There are multiple ets lookup calls in Riak:

• One for each HEAD request in leveled.
• Capability checks.
• Lookups for supported dispatching in PB are implemented as ETS lookups in the registrar.
• ETS tables are used extensively within exometer_core (one per scheduler).
• Fetches of the ring (which is the known use of ets:lookup_element/4).

The capability checks are largely wasteful, and this is a known issue - OpenRiak/riak_kv#57. The backend requests are unavoidable, and part of a broader efficiency saving.

It does seem likely there's a more efficient way of remembering where to dispatch PB requests, perhaps the registrar should use persisted_term instead?

The ring lookup is interesting, because of the variation in size of the ring. Does this cost increase, as the ring gets bigger (a ring size of 16 was used in the initial profile)? [edit - checking with a Ring-Size 0f 64 not 16 doesn't appear to increase the cost of this call]. [edit2 - the lookup_element/2 calls are generally for the chashbin, not the ring, and this is a binary, so it may be there is no size-related cost to copy out of the ets table - not though the chashbin is 10 x larger than it needs to be, so there may be some potential minor efficiencies there].

phash/2 (not phash2)

The existence of the deprecated erlang:phash/2 function in eprof profiles is interesting, as one would not expect it to be used in Riak.

Looking in the Erlang/OTP code, it exists with the deprecation warning suppressed in dict, sets (version 1) and dets/mnesia.

The most plausible cause of elrang:phash/2 activity is therefore within riak_object metadata.

[martinsumner]

Comparing HTTP

HTTP API profile on the client-facing node:

FUNCTION                                      CALLS        %     TIME  [uS / CALLS]
--------                                      -----  -------     ----  [----------]
webmachine_request:call/2                    104727     0.53    12589  [      0.12]
prim_file:read_nif/2                           1770     0.54    12746  [      7.20]
io_lib_format:collect/2                      139344     0.55    13144  [      0.09]
mochiweb_http:request/3                        2793     0.56    13242  [      4.74]
zlib:deflate_nif/4                             2091     0.57    13559  [      6.48]
erlang:'++'/2                                136882     0.57    13560  [      0.10]
gen_fsm:loop/8                                13866     0.57    13617  [      0.98]
io_lib_format:build_limited/5                139344     0.58    13751  [      0.10]
gen_fsm:dispatch/4                            13866     0.59    14086  [      1.02]
webmachine_dispatcher:try_path_binding/7     226249     0.59    14105  [      0.06]
io_lib_format:collect_cseq/2                  38433     0.61    14385  [      0.37]
ets:lookup_element/4                          38786     0.61    14480  [      0.37]
webmachine_dispatcher:bind/4                 270945     0.61    14619  [      0.05]
lists:do_flatten/2                           219517     0.63    14869  [      0.07]
mochiweb_headers:trim_and_reverse/2          263892     0.63    14952  [      0.06]
webmachine_decision_core:resource_call/1      75408     0.63    15032  [      0.20]
erlang:phash/2                                64017     0.66    15744  [      0.25]
lists:foldl_1/3                              237409     0.67    16017  [      0.07]
webmachine_resource:resource_call/3           53036     0.73    17268  [      0.33]
string:strip_right/2                         243451     0.73    17418  [      0.07]
lists:keyfind/3                              317550     0.82    19598  [      0.06]
string:tokens_single_2/4                     543651     0.84    20060  [      0.04]
exometer_proc:cast/2                          16500     0.86    20542  [      1.24]
gb_trees:lookup_1/2                          382886     0.87    20773  [      0.05]
erlang:put/2                                 417635     0.97    22992  [      0.06]
gen:do_call/4                                 13398     1.05    25010  [      1.87]
webmachine_dispatcher:try_host_binding1/6    114521     1.08    25572  [      0.22]
lists:reverse/2                              335402     1.14    27088  [      0.08]
webmachine_resource:do/3                      75408     1.14    27215  [      0.36]
gb_trees:insert_1/4                          267882     1.15    27308  [      0.10]
lists:reverse/1                              477931     1.43    34011  [      0.07]
erts_internal:port_control/3                  38207     1.53    36362  [      0.95]
erts_internal:port_command/3                   5658     1.59    37766  [      6.67]
gen_server:loop/7                             17502     1.60    38138  [      2.18]
ets:lookup/2                                  55212     3.09    73367  [      1.33]
string:to_lower_char/1                      2570124     4.45   105693  [      0.04]
string:'-to_lower/1-lc$^0/1-0-'/1           2784857    12.33   293263  [      0.11]
-----------------------------------------  --------  -------  -------  [----------]
Total:                                     23076939  100.00%  2377647  [      0.10]

Alternate implementation of http using only non-deprecated string functions, and not doing repeated lower-casing for comparison - https://github.com/OpenRiak/riak_kv/tree/nhse-o34-nhskv.i30-getputapi:

FUNCTION                                      CALLS        %     TIME  [uS / CALLS]
--------                                      -----  -------     ----  [----------]
webmachine_dispatcher:try_path_binding/7     190285     0.65    12035  [      0.06]
webmachine_dispatcher:bind/4                 227877     0.65    12053  [      0.05]
mochiweb_headers:trim_and_reverse/2          221448     0.66    12324  [      0.06]
webmachine_decision_core:resource_call/1      63445     0.67    12552  [      0.20]
erlang:phash/2                                53627     0.68    12754  [      0.24]
lists:foldl_1/3                              200537     0.72    13332  [      0.07]
lists:do_flatten/2                           198645     0.72    13398  [      0.07]
gb_trees:lookup_1/2                          251981     0.74    13779  [      0.05]
unicode_util:lowercase/1                     116439     0.78    14513  [      0.12]
webmachine_resource:resource_call/3           44619     0.81    15082  [      0.34]
mochiweb_http:request/3                        2350     0.84    15591  [      6.63]
lists:keyfind/3                              262662     0.84    15664  [      0.06]
webmachine_resource:do/3                      63445     0.93    17241  [      0.27]
erlang:put/2                                 351236     1.00    18661  [      0.05]
gen:do_call/4                                 11157     1.06    19656  [      1.76]
webmachine_dispatcher:try_host_binding1/6     96317     1.11    20716  [      0.22]
string:trim_t/3                              204768     1.25    23284  [      0.11]
gb_trees:insert_1/4                          224593     1.31    24404  [      0.11]
lists:reverse/2                              292375     1.44    26878  [      0.09]
string:lexeme_pick/3                         343274     1.57    29202  [      0.09]
lists:reverse/1                              436271     1.58    29463  [      0.07]
erts_internal:port_control/3                  32124     1.62    30219  [      0.94]
lists:member/2                               629687     1.63    30357  [      0.05]
erts_internal:port_command/3                   4773     1.64    30559  [      6.40]
string:search_cp/1                           382036     1.81    33756  [      0.09]
gen_server:loop/7                             14617     1.88    35031  [      2.40]
ets:lookup/2                                  46418     3.12    58159  [      1.25]
string:lowercase_list/2                     1506408     4.61    85919  [      0.06]
-----------------------------------------  --------  -------  -------  [----------]
Total:                                     17957477  100.00%  1862680  [      0.10]

Not that webmachine makes heavy use of ETS, hence why ets:lookup/2 is more prominent. However, it is strange that the cost per call increases, rather than the volume of calls

[martinsumner]

gen_server_loop/7

The problem process may be the eprof analyser!!! the busier the node, the busier its gen_server_loop is when analysing the processes - and I didn't exclude this process from the analysed processes.

[martinsumner]

gen_server_loop/7

Eliminating the eprof server from the calculation, made little difference to the overall numbers.

It looks like sidejob is playing a role here. The sidejob workers are gen_servers, so any process started by sidejob will have a gen_server loop, even if it is a gen_fsm.

More than a third of this work appears to be related to riak_kv_stat. When there is a call to riak_kv_stat:update/1, by default it launches a riak_kv_stat_worker under sidejob (or uses an existing worker). Sidejob runs multiple workers (one per scheduler?), and tries to find one that isn't busy.

One consequence is that stat updates are asynchronous, in that stats will be cast to this pool, and so API requests are not delayed by stats updates. But it does make it very hard to measure the true cost of gathering all the stats.

[martinsumner]

There are some potential changes proposed:

OpenRiak/riak_kv#25 - allows direct_fetch and direct_stat (bypassing sidejob and its gen_server), and makes them the default

https://github.com/OpenRiak/riak_api/pull/2 - avoid ETS lookup for PB registrar (expected to be a very marginal gain)

Other potential changes:

• Refactor chashbin to be 2-bytes per RingSize not 162-bytes per RingSize, and promote as a persistent_term, and ensure the fetch of a preflist uses the most efficient path (currently it always does ets:lookup_element even when promoted using riak_core_mochiglobal).
• Reduce stats. In particular per-vnode index stats. Maybe an option to disable further stats.
• Remove exometer_core, and use OTP counters and more efficient histogram.
• Switch riak object metadata to use a map not a dict, and avoid phash/2 calls.
• an option for zstd not zlib compression of vector clcoks.