[erlang-questions] LCNT: understanding proc_* and db_hash_slot collisions
Danil Zagoskin
z@REDACTED
Tue Aug 16 12:28:57 CEST 2016
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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://erlang.org/pipermail/erlang-questions/attachments/20160816/555923f0/attachment.htm>
More information about the erlang-questions
mailing list