[erlang-questions] LCNT: understanding proc_* and db_hash_slot collisions

Danil Zagoskin <>
Tue Aug 16 12:28:57 CEST 2016


Hello again!

On Sun, Jul 31, 2016 at 12:45 PM, Lukas Larsson <> wrote:

> On Tue, Jul 26, 2016 at 12:11 PM, Danil Zagoskin <> wrote:
>
>> Hello!
>>
>
> Hello!
>
>
>> Inspecting the process gives me
>>         lock          id  #tries  #collisions  collisions [%]  time [us]
>>  duration [%] histogram [log2(us)]
>>        -----         --- ------- ------------ --------------- ----------
>> ------------- ---------------------
>>  flu_pulsedb   proc_main    6989         4242         60.6954    1161759
>>       11.5906 |       ...........XX...       |
>>  flu_pulsedb   proc_msgq    7934         3754         47.3154     669383
>>        6.6783 |      .xXXxxXxx..xXX...       |
>>  flu_pulsedb proc_status    5489          521          9.4917     287153
>>        2.8649 |     ..xxxxxxxxxxxXX..        |
>>  flu_pulsedb   proc_link     864           44          5.0926        566
>>        0.0056 |      ...XxX.....             |
>>  flu_pulsedb    proc_btm       0            0          0.0000          0
>>        0.0000 |                              |
>>  flu_pulsedb  proc_trace     201            0          0.0000          0
>>        0.0000 |                              |
>>
>> Context: this process is a data receiver. Each sender first checks its
>> message queue length and then sends a message
>>    if queue is not very long. This happens about 220 times a second. Then
>> this process accumulates some data and
>>    writes it to disk periodically.
>> What do proc_main, proc_msgq and proc_status locks mean?
>>
>
> proc_main is the main execution lock, proc_msgq is the lock protecting the
> external message queue, and proc_status is the lock protecting the process
> status ans various other things.
>
>
>> Why at all are collisions possible here?
>>
>
> When doing various operations, different locks are needed in order to
> guarantee the order of events. For instance when sending a message the
> proc_msgq lock is needed. However when checking the size of the message
> queue both the proc_main, proc_msgq are needed. So if many processes
> continually check the message queue size of a single other process you will
> get a lot of conflict on both the main and msgq lock.
>
>
>> What should I see next to optimise this bottleneck?
>>
>
> Don't check the message queue length of another process unless you really
> have to, and if you do have to, do it as seldom as you can. Checking the
> length of a message queue is a deceptively expensive operation.
>

Thank you for explaining this. Removing message queue length check mostly
fixed process locking issue in this process.


>
>>
>> Next, inspecting db_hash_slot gives me 20 rows all alike (only top few
>> shown):
>>          lock  id  #tries  #collisions  collisions [%]  time [us]
>>  duration [%] histogram [log2(us)]
>>         ----- --- ------- ------------ --------------- ----------
>> ------------- ---------------------
>>  db_hash_slot   0     492          299         60.7724     107552
>>  1.0730 |              ...XX. .        |
>>  db_hash_slot   1     492          287         58.3333     101951
>>  1.0171 |            .  ..XX. .        |
>>  db_hash_slot  48     480          248         51.6667      99486
>>  0.9925 |              ...xXx.         |
>>  db_hash_slot  47     480          248         51.6667      96443
>>  0.9622 |              ...XXx          |
>>  db_hash_slot   2     574          304         52.9617      92952
>>  0.9274 |           . ....XX. .        |
>>
>> How do I see what ETS tables are causing this high collision rate?
>> Is there any way to map lock id (here: 0, 1, 48, 47, 2) to a table id?
>>
>
> iirc the id used in the lock checker should be the same as the table id.
>

Unfortunately, the lock equals a table's hash lock id:
https://github.com/erlang/otp/blob/maint/erts/emulator/beam/erl_db_hash.c#L687
After changing make_small(i) to tb->common.the_name we were able to see the
table name causing locking:

()22> lcnt:inspect(db_hash_slot, [{max_locks, 10}]).
         lock                   id  #tries  #collisions  collisions
[%]  time [us]  duration [%] histogram [log2(us)]
        -----                  --- ------- ------------
--------------- ---------- ------------- ---------------------
 db_hash_slot pulsedb_seconds_data     523           78
14.9140      26329        0.5265 |         ..    .XXX ..        |
 db_hash_slot pulsedb_seconds_data     498           77
15.4618      24210        0.4841 |             ...xXX. .        |
 db_hash_slot pulsedb_seconds_data     524           62
11.8321      23082        0.4616 |            .  ..XX. ..       |
 db_hash_slot pulsedb_seconds_data     489           74
15.1329      21425        0.4284 |              ...XX.  .       |
 db_hash_slot pulsedb_seconds_data     493           79
16.0243      19918        0.3983 |          ...  .xXX.          |
 db_hash_slot pulsedb_seconds_data     518           67
12.9344      19298        0.3859 |             ....XX..         |
 db_hash_slot pulsedb_seconds_data     595           70
11.7647      18947        0.3789 |           .   ..XX.          |
 db_hash_slot pulsedb_seconds_data     571           74
12.9597      18638        0.3727 |             ....XX.          |
 db_hash_slot pulsedb_seconds_data     470           61
12.9787      17818        0.3563 |            .....XX...        |
 db_hash_slot pulsedb_seconds_data     475           75
15.7895      17582        0.3516 |                xXX.          |
ok



Should I create a PR for that?
The result is not perfect — it could be better to see {TableName, LockID}
there, but I failed to create a new tuple in that function.


Or maybe there is a better tool for ETS profiling?
>>
>
> for detection of ETS conflicts there is no better tool. For general ETS
> performance, I would use the same tools as for all erlang code, i.e. cprof,
> eprof, fprof and friends.
>
> Lukas
>


The problem with this table was about very concurrent writes — over 200
processes inserting about 5 rows a second. Despite write_concurrency option
this did not work well.

We changed the way we write into the table to single writer process. This
removed the db_hash_slot locking but brought up locking in db_tab.
After splitting the table into 16 chunks the obvious ETS locking problems
seems to go away.



But.


There are process locks again, now in ranch connections supervisor (it is
registered by hand for readability):

()72> lcnt:inspect(ranch_conns_sup).
            lock          id  #tries  #collisions  collisions [%]
time [us]  duration [%] histogram [log2(us)]
           -----         --- ------- ------------ ---------------
---------- ------------- ---------------------
 ranch_conns_sup   proc_link      59            0          0.0000
3766719       71.2297 |              .  ..   . ..x. X|
 ranch_conns_sup proc_status      50            0          0.0000
3766093       71.2179 |                      . ..x. X|
 ranch_conns_sup   proc_msgq      63            2          3.1746
59220        1.1199 |                         X    |
 ranch_conns_sup   proc_main      93           11         11.8280
    4        0.0001 |            X                 |
 ranch_conns_sup    proc_btm      16            0          0.0000
    0        0.0000 |                              |
 ranch_conns_sup  proc_trace      17            0          0.0000
    0        0.0000 |                              |
ok

And this happened under half of load which caused initial issue.

Reading the erl_db.c and friends I found an option to affect ETS mutex
spincount option. Specifying undocumented erl "+zebwt short" option seems
to make thing better (but still not perfect).

Now we still have long process locks in ranch. Here is lcnt locations with
zero lines omitted:
()52> lcnt:inspect(pid(0,6991,0), [{locations, true}]).
id:   proc_status
 'beam/erl_process_lock.c':761       9            0          0.0000
 1057841       20.9704
             'beam/bif.c':1156      24            3         12.5000
84        0.0017

id:   proc_msgq
      'beam/erl_message.c':414       4            2         50.0000
344029        6.8200

id:   proc_link
 'beam/erl_process_lock.c':761       9            0          0.0000
 1057837       20.9703
             'beam/bif.c':1156      24            3         12.5000
 157        0.0031


Thing still unclear:
  - Why does ETS usage pattern affect processes which do not use ETS?
  - Are there more hidden ETS tuning options?
  - What else can we do to make this system faster? Free system resources
are enough for doing 4—5 times more job.

-- 
Danil Zagoskin | 
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://erlang.org/pipermail/erlang-questions/attachments/20160816/555923f0/attachment.html>


More information about the erlang-questions mailing list