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

Danil Zagoskin <>
Wed Aug 17 17:03:26 CEST 2016


After reducing ETS load I see a new lock coming up — now it's one of 1024
pix_lock's:

()3> lcnt:apply(timer, sleep, [5000]),
lcnt:swap_pid_keys(), lcnt:conflicts([{max_locks, 5}]).
                         lock   id  #tries  #collisions  collisions [%]
 time [us]  duration [%]
                        -----  --- ------- ------------ ---------------
---------- -------------
 <>    6    6403          686         10.7137
 5550663      109.9727
                     pix_lock 1024    1330            1          0.0752
 1481334       29.3490
                    run_queue   42 3394894        82843          2.4402
171155        3.3910
                      pollset    1  162867        10714          6.5784
 88266        1.7488
                       db_tab  181  135250          759          0.5612
 62164        1.2316
ok

()5> lcnt:inspect(pix_lock, [{max_locks, 5}]).
     lock  id  #tries  #collisions  collisions [%]  time [us]  duration [%]
histogram [log2(us)]
    ----- --- ------- ------------ --------------- ---------- -------------
---------------------
 pix_lock  53    1284            1          0.0779    1480359       29.3297
|              XX.  ........   |
 pix_lock 895       4            0          0.0000        121        0.0024
|               X              |
 pix_lock 862       4            0          0.0000         92        0.0018
|              X X             |
 pix_lock 270       2            0          0.0000         83        0.0016
|                X             |
 pix_lock 949       2            0          0.0000         70        0.0014
|                X             |
ok

()8> lcnt:inspect(pix_lock, [{locations, true},
{combine, true}]).
lock: pix_lock
id:   1024
type: mutex
                      location  #tries  #collisions  collisions [%]  time
[us]  duration [%]
                     --------- ------- ------------ ---------------
---------- -------------
 'beam/erl_process_lock.h':422    1330            1          0.0752
 1481334       29.3490
                   undefined:0       0            0          0.0000
 0        0.0000
ok



The previously described proc_link/proc_status lock is still here.

The thing i find strange about pix_lock is that only one lock of 1024 is
used and has a significant duration. Other ones have almost zero tries and
duration.
The lock id is not constant — it changes over time.


May long pix_lock be a same problem as proc_link/proc_status?
Why can this happen?
What should we see next?


On Tue, Aug 16, 2016 at 1:28 PM, Danil Zagoskin <> wrote:

> 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 | 
>



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


More information about the erlang-questions mailing list