[erlang-questions] LCNT: understanding proc_* and db_hash_slot collisions
Danil Zagoskin
z@REDACTED
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:
(flussonic@REDACTED)3> lcnt:apply(timer, sleep, [5000]),
lcnt:swap_pid_keys(), lcnt:conflicts([{max_locks, 5}]).
lock id #tries #collisions collisions [%]
time [us] duration [%]
----- --- ------- ------------ ---------------
---------- -------------
<flussonic@REDACTED> 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
(flussonic@REDACTED)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
(flussonic@REDACTED)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 <z@REDACTED> wrote:
> Hello again!
>
> On Sun, Jul 31, 2016 at 12:45 PM, Lukas Larsson <garazdawi@REDACTED>
> wrote:
>
>> On Tue, Jul 26, 2016 at 12:11 PM, Danil Zagoskin <z@REDACTED> 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:
>
> (flussonic@REDACTED)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):
>
> (flussonic@REDACTED)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:
> (flussonic@REDACTED)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 | z@REDACTED
>
--
Danil Zagoskin | z@REDACTED
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://erlang.org/pipermail/erlang-questions/attachments/20160817/61561938/attachment.htm>
More information about the erlang-questions
mailing list