
<div dir="ltr">Hello!<div><br></div><div>I am inspecting performance issues in an Erlang/OTP system.</div><div><br></div><div>I've run LCNT and I see results I cannot interpret.</div><div><br></div><div>AfterÂ lcnt:swap_pid_keys(), I see these conflicts (only top of the table):</div><div><div><font face="monospace, monospace">Â  Â  Â  Â  Â  Â  Â  Â lock Â  id Â #tries Â #collisions Â collisions [%] Â time [us] Â duration [%]</font></div><div><font face="monospace, monospace">Â  Â  Â  Â  Â  Â  Â  ----- Â --- ------- ------------ --------------- ---------- -------------</font></div><div><span style="font-family:monospace,monospace">Â  Â  Â  Â db_hash_slot Â 896 Â 192708 Â  Â  Â  Â 28684 Â  Â  Â  Â  14.8847 Â  Â 8164589 Â  Â  Â  81.4562</span></div><div><font face="monospace, monospace">Â  Â  Â  Â  flu_pulsedb Â  Â 6 Â  21477 Â  Â  Â  Â  8561 Â  Â  Â  Â  39.8612 Â  Â 2118861 Â  Â  Â  21.1394</font></div><div><font face="monospace, monospace">Â  Â  Â  Â  Â  run_queue Â  42 6427021 Â  Â  Â  169979 Â  Â  Â  Â  Â 2.6448 Â  Â  339177 Â  Â  Â  Â 3.3839</font></div><div><font face="monospace, monospace">Â  Â  Â  Â  Â  Â pix_lock 1024 Â  Â 4384 Â  Â  Â  Â  Â 229 Â  Â  Â  Â  Â 5.2235 Â  Â  209468 Â  Â  Â  Â 2.0898</font></div><div><font face="monospace, monospace">Â  Â  Â  Â  Â  Â  pollset Â  Â 1 Â 303839 Â  Â  Â  Â 16477 Â  Â  Â  Â  Â 5.4229 Â  Â  134808 Â  Â  Â  Â 1.3449</font></div><div><font face="monospace, monospace">Â  Â  Â  Â  Â  Â  Â db_tab Â 146 Â 261929 Â  Â  Â  Â  Â 926 Â  Â  Â  Â  Â 0.3535 Â  Â  107955 Â  Â  Â  Â 1.0770</font></div><div><br></div>Here I see two problems: lots of ETS locking (db_hash_slot) and something with a particular process (flu_pulsedb).</div><div><br></div><div><br></div><div><br></div><div>Inspecting the process gives me</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? Why at all are collisions possible here?</div><div>What should I see next to optimise this bottleneck?</div><div><br></div><div><br></div><div><br></div><div>Next, inspecting db_hash_slot gives me 20 rows all alike (only top few shown):</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>Or maybe there is a better tool for ETS profiling?<br><div><br>Â  <div><font face="monospace, monospace">-- <br></font><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></div>