<div dir="ltr">Hello again!<div><div class="gmail_extra"><br><div class="gmail_quote">On Sun, Jul 31, 2016 at 12:45 PM, Lukas Larsson <span dir="ltr"><<a href="mailto:garazdawi@gmail.com" target="_blank">garazdawi@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-style:solid;border-left-color:rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div class="gmail_extra"><div class="gmail_quote">On Tue, Jul 26, 2016 at 12:11 PM, Danil Zagoskin <span dir="ltr"><<a href="mailto:z@gosk.in" target="_blank">z@gosk.in</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-style:solid;border-left-color:rgb(204,204,204);padding-left:1ex"><div dir="ltr">Hello!</div></blockquote><div> </div><div>Hello!</div><span class=""><div> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-style:solid;border-left-color:rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div></div><div>Inspecting the process gives me<br></div><div><div><font face="monospace, monospace"> lock id #tries #collisions collisions [%] time [us] duration [%] histogram [log2(us)]</font></div><div><font face="monospace, monospace"> ----- --- ------- ------------ --------------- ---------- ------------- ---------------------</font></div><div><font face="monospace, monospace"> flu_pulsedb proc_main 6989 4242 60.6954 1161759 11.5906 | ...........XX... |</font></div><div><font face="monospace, monospace"> flu_pulsedb proc_msgq 7934 3754 47.3154 669383 6.6783 | .xXXxxXxx..xXX... |</font></div><div><font face="monospace, monospace"> flu_pulsedb proc_status 5489 521 9.4917 287153 2.8649 | ..xxxxxxxxxxxXX.. |</font></div><div><font face="monospace, monospace"> flu_pulsedb proc_link 864 44 5.0926 566 0.0056 | ...XxX..... |</font></div><div><font face="monospace, monospace"> flu_pulsedb proc_btm 0 0 0.0000 0 0.0000 | |</font></div><div><font face="monospace, monospace"> flu_pulsedb proc_trace 201 0 0.0000 0 0.0000 | |</font></div><div><font face="monospace, monospace"><br></font></div><div>Context: this process is a data receiver. Each sender first checks its message queue length and then sends a message</div><div> if queue is not very long. This happens about 220 times a second. Then this process accumulates some data and</div><div> writes it to disk periodically.</div>What do proc_main, proc_msgq and proc_status locks mean?</div></div></blockquote><div><br></div></span><div>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. </div><span class=""><div> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-style:solid;border-left-color:rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div>Why at all are collisions possible here?</div></div></blockquote><div><br></div></span><div>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. </div><span class=""><div> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-style:solid;border-left-color:rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div>What should I see next to optimise this bottleneck?</div></div></blockquote><div><br></div></span><div>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.</div></div></div></div></blockquote><div><br></div><div>Thank you for explaining this. Removing message queue length check mostly fixed process locking issue in this process.</div><div><br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-style:solid;border-left-color:rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div class="gmail_extra"><div class="gmail_quote"><span class=""><div> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-style:solid;border-left-color:rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div><br></div><div>Next, inspecting db_hash_slot gives me 20 rows all alike (only top few shown):<br></div><div><div><font face="monospace, monospace"> lock id #tries #collisions collisions [%] time [us] duration [%] histogram [log2(us)]</font></div><div><font face="monospace, monospace"> ----- --- ------- ------------ --------------- ---------- ------------- ---------------------</font></div><div><font face="monospace, monospace"> db_hash_slot 0 492 299 60.7724 107552 1.0730 | ...XX. . |</font></div><div><font face="monospace, monospace"> db_hash_slot 1 492 287 58.3333 101951 1.0171 | . ..XX. . |</font></div><div><font face="monospace, monospace"> db_hash_slot 48 480 248 51.6667 99486 0.9925 | ...xXx. |</font></div><div><font face="monospace, monospace"> db_hash_slot 47 480 248 51.6667 96443 0.9622 | ...XXx |</font></div><div><font face="monospace, monospace"> db_hash_slot 2 574 304 52.9617 92952 0.9274 | . ....XX. . |</font></div></div><div><font face="monospace, monospace"><br></font></div>How do I see what ETS tables are causing this high collision rate?<div>Is there any way to map lock id (here: 0, 1, 48, 47, 2) to a table id?</div></div></blockquote><div><br></div></span><div>iirc the id used in the lock checker should be the same as the table id.</div></div></div></div></blockquote><div><br></div><div>Unfortunately, the lock equals a table's hash lock id: <a href="https://github.com/erlang/otp/blob/maint/erts/emulator/beam/erl_db_hash.c#L687">https://github.com/erlang/otp/blob/maint/erts/emulator/beam/erl_db_hash.c#L687</a></div><div>After changing make_small(i) to tb->common.the_name we were able to see the table name causing locking:</div><div><pre style="margin:1em 1em 1em 1.6em;padding:8px;border:1px solid rgb(226,226,226);width:auto;background-color:rgb(250,250,250)"><font color="#484848">(<a href="mailto:flussonic@127.0.0.1">flussonic@127.0.0.1</a>)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<br></font></pre></div><div><br></div><div><br></div><div>Should I create a PR for that?</div><div>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.</div><div><br></div><div><br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-style:solid;border-left-color:rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div class="gmail_extra"><div class="gmail_quote"><span class=""><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-style:solid;border-left-color:rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div>Or maybe there is a better tool for ETS profiling?</div></div></blockquote><div><br></div></span><div>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. </div><span class=""><font color="#888888"><div><br></div><div>Lukas</div></font></span></div></div></div>
</blockquote></div><div class="gmail_extra"><br></div><div class="gmail_extra"><br></div>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.</div><div class="gmail_extra"><br></div><div class="gmail_extra">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.</div><div class="gmail_extra">After splitting the table into 16 chunks the obvious ETS locking problems seems to go away.</div><div class="gmail_extra"><br></div><div class="gmail_extra"><br></div><div class="gmail_extra"><br></div><div class="gmail_extra">But.</div><div class="gmail_extra"><br></div><div class="gmail_extra"><br></div><div class="gmail_extra">There are process locks again, now in ranch connections supervisor (it is registered by hand for readability):</div><div class="gmail_extra"><pre style="margin:1em 1em 1em 1.6em;padding:8px;border:1px solid rgb(226,226,226);width:auto;color:rgb(72,72,72);font-size:12px;background-color:rgb(250,250,250)">(<a href="mailto:flussonic@127.0.0.1">flussonic@127.0.0.1</a>)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</pre><p style="color:rgb(72,72,72);font-family:Verdana,sans-serif;font-size:12px"></p></div><div class="gmail_extra">And this happened under half of load which caused initial issue.</div><div class="gmail_extra"><br></div><div class="gmail_extra">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).</div><div class="gmail_extra"><br></div><div class="gmail_extra">Now we still have long process locks in ranch. Here is lcnt locations with zero lines omitted:</div><div class="gmail_extra"><font face="monospace, monospace">(<a href="mailto:flussonic@127.0.0.1">flussonic@127.0.0.1</a>)52> lcnt:inspect(pid(0,6991,0), [{locations, true}]).<br></font></div><div class="gmail_extra"><font face="monospace, monospace">id: proc_status<br></font></div><div class="gmail_extra"><div class="gmail_extra"><font face="monospace, monospace"> 'beam/erl_process_lock.c':761 9 0 0.0000 1057841 20.9704 </font></div><div class="gmail_extra"><font face="monospace, monospace"> 'beam/bif.c':1156 24 3 12.5000 84 0.0017 </font></div><div class="gmail_extra"><font face="monospace, monospace"><br></font></div><div class="gmail_extra"><font face="monospace, monospace">id: proc_msgq<br></font></div><div class="gmail_extra"><font face="monospace, monospace"> 'beam/erl_message.c':414 4 2 50.0000 344029 6.8200 <br></font></div><div class="gmail_extra"><font face="monospace, monospace"><br></font></div><div class="gmail_extra"><font face="monospace, monospace">id: proc_link<br></font></div><div class="gmail_extra"><div class="gmail_extra"><font face="monospace, monospace"> 'beam/erl_process_lock.c':761 9 0 0.0000 1057837 20.9703</font></div><div class="gmail_extra"><font face="monospace, monospace"> 'beam/bif.c':1156 24 3 12.5000 157 0.0031</font></div></div></div><div class="gmail_extra"><br></div><div class="gmail_extra"><br></div><div class="gmail_extra">Thing still unclear:</div><div class="gmail_extra"> - Why does ETS usage pattern affect processes which do not use ETS?</div><div class="gmail_extra"> - Are there more hidden ETS tuning options?</div><div class="gmail_extra"> - What else can we do to make this system faster? Free system resources are enough for doing 4—5 times more job.</div><div class="gmail_extra"><br></div><div class="gmail_extra">-- <br><div class="gmail_signature" data-smartmail="gmail_signature"><div dir="ltr"><div><font face="'courier new', monospace">Danil Zagoskin | <a href="mailto:z@gosk.in" target="_blank">z@gosk.in</a></font></div></div></div>
</div></div></div>