<div dir="ltr">After reducing ETS load I see a new lock coming up — now it's one of 1024 pix_lock's:<div><br><div><div><font face="monospace, monospace">(<a href="mailto:flussonic@127.0.0.1">flussonic@127.0.0.1</a>)3> lcnt:apply(timer, sleep, [5000]), lcnt:swap_pid_keys(), lcnt:conflicts([{max_locks, 5}]).</font></div><div><font face="monospace, monospace">                         lock   id  #tries  #collisions  collisions [%]  time [us]  duration [%]</font></div><div><font face="monospace, monospace">                        -----  --- ------- ------------ --------------- ---------- -------------</font></div><div><font face="monospace, monospace"> <flussonic@127.0.0.1.7221.0>    6    6403          686         10.7137    5550663      109.9727</font></div><div><font face="monospace, monospace">                     pix_lock 1024    1330            1          0.0752    1481334       29.3490</font></div><div><font face="monospace, monospace">                    run_queue   42 3394894        82843          2.4402     171155        3.3910</font></div><div><font face="monospace, monospace">                      pollset    1  162867        10714          6.5784      88266        1.7488</font></div><div><font face="monospace, monospace">                       db_tab  181  135250          759          0.5612      62164        1.2316</font></div><div><font face="monospace, monospace">ok</font></div></div><div><font face="monospace, monospace"><br></font></div><div><font face="monospace, monospace"><div>(<a href="mailto:flussonic@127.0.0.1">flussonic@127.0.0.1</a>)5> lcnt:inspect(pix_lock, [{max_locks, 5}]).</div><div>     lock  id  #tries  #collisions  collisions [%]  time [us]  duration [%] histogram [log2(us)]</div><div>    ----- --- ------- ------------ --------------- ---------- ------------- ---------------------</div><div> pix_lock  53    1284            1          0.0779    1480359       29.3297 |              XX.  ........   |</div><div> pix_lock 895       4            0          0.0000        121        0.0024 |               X              |</div><div> pix_lock 862       4            0          0.0000         92        0.0018 |              X X             |</div><div> pix_lock 270       2            0          0.0000         83        0.0016 |                X             |</div><div> pix_lock 949       2            0          0.0000         70        0.0014 |                X             |</div><div>ok</div><div><br></div><div><div>(<a href="mailto:flussonic@127.0.0.1">flussonic@127.0.0.1</a>)8> lcnt:inspect(pix_lock, [{locations, true}, {combine, true}]).</div><div>lock: pix_lock</div><div>id:   1024</div><div>type: mutex</div><div>                      location  #tries  #collisions  collisions [%]  time [us]  duration [%] </div><div>                     --------- ------- ------------ --------------- ---------- ------------- </div><div> 'beam/erl_process_lock.h':422    1330            1          0.0752    1481334       29.3490 </div><div>                   undefined:0       0            0          0.0000          0        0.0000 </div><div>ok</div></div><div><br></div><div><br></div></font><div><br></div>The previously described proc_link/proc_status lock is still here.</div></div><div><br></div>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.<div>The lock id is not constant — it changes over time.</div><div><br></div><div><br></div><div>May long pix_lock be a same problem as proc_link/proc_status?</div><div>Why can this happen?</div><div>What should we see next?<br><div><br></div></div></div><div class="gmail_extra"><br><div class="gmail_quote">On Tue, Aug 16, 2016 at 1:28 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:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Hello again!<div><div class="gmail_extra"><br><div class="gmail_quote"><span class="">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><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><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><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></span><div>Thank you for explaining this. Removing message queue length check mostly fixed process locking issue in this process.</div><span class=""><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><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></span><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" target="_blank">https://github.com/erlang/otp/<wbr>blob/maint/erts/emulator/beam/<wbr>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" target="_blank">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><span class=""><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><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><font color="#888888"><div><br></div><div>Lukas</div></font></span></div></div></div>
</blockquote></span></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" target="_blank">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" target="_blank">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><span class="HOEnZb"><font color="#888888"><div class="gmail_extra"><br></div><div class="gmail_extra">-- <br><div 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></font></span></div></div>
</blockquote></div><br><br clear="all"><div><br></div>-- <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>