<div dir="ltr"><div class="gmail_default" style="font-family:trebuchet ms,sans-serif">So, I tested with extended msacc and this is what I got…</div><div class="gmail_default" style="font-family:trebuchet ms,sans-serif"><br></div><div class="gmail_default" style=""><font face="monospace"> Thread alloc aux bifbusy_wait check_io emulator ets gc gc_full nif other port send sleep timers<br>OTP 21:<br> async 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 100.00% 0.00%<br> aux 0.01% 0.28% 0.00% 0.00% 0.05% 0.00% 0.00% 0.00% 0.00% 0.00% 0.01% 0.00% 0.00% 99.65% 0.00%<br>dirty_cpu_sche 0.10% 0.00% 0.00% 0.00% 0.00% 0.01% 0.00% 0.21% 0.13% 0.00% 0.00% 0.00% 0.00% 99.55% 0.00%<br>dirty_io_sched 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 100.00% 0.00%<br> poll 0.07% 0.00% 0.00% 0.00% 0.35% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 99.58% 0.00%<br> scheduler <b>8.89%</b> <b>0.86%</b> <b>23.93%</b> 0.04% 0.31% <b>38.18%</b> 6.15% 4.81% 0.67% 3.29% 1.35% 1.09% 1.58% 8.74% 0.12%<br>OTP 22:<br> async 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 100.00% 0.00%<br> aux 0.00% 0.08% 0.00% 0.00% 0.01% 0.00% 0.00% 0.00% 0.00% 0.00% 0.02% 0.00% 0.00% 99.88% 0.00%<br>dirty_cpu_sche 0.02% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.09% 0.04% 0.00% 0.00% 0.00% 0.00% 99.84% 0.00%<br>dirty_io_sched 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 100.00% 0.00%<br> poll 0.07% 0.00% 0.00% 0.00% 0.33% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 99.59% 0.00%<br> scheduler <b>10.83%</b> <b>1.82%</b> <b>21.74%</b> 0.04% 0.34% <b>36.14%</b> 6.44% 4.91% 0.79% 3.82% 1.57% 1.13% 1.71% 8.63% 0.12%<br></font><br></div><div class="gmail_default" style="font-family:trebuchet ms,sans-serif">I highlighted the <b>important</b> pieces, but in a nutshell…</div><div class="gmail_default" style="font-family:trebuchet ms,sans-serif"><ul><li>Scheduler allocation increased 2%</li><li>Time handling auxiliary jobs increased 1%. In other words: it more than doubled.</li><li>Time spent by the scheduler in BIFs is 2% less</li><li>Time spent by the scheduler executing erlang processes is 2% less</li><li>GC, NIfs, port, send and other times also increased but the increase is far smaller (less than 1%).</li></ul><div>So, OTP22 (when compared to OTP21) in my system is shifting time previously spent on the emulator or BIFs to other tasks… particularly <i>managing memory</i> and <i>auxiliary jobs</i>. Besides messing with C, which we might end up doing if there is no other way… anybody has any idea of what might be causing this?</div><div><br></div><div>Thanks again.</div></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Fri, Jul 3, 2020 at 4:57 PM Lukas Larsson <<a href="mailto:lukas@erlang.org">lukas@erlang.org</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div dir="ltr"><br></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Fri, Jul 3, 2020 at 4:27 PM Fernando Benavides <<a href="mailto:elbrujohalcon@gmail.com" target="_blank">elbrujohalcon@gmail.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div style="font-family:"trebuchet ms",sans-serif">Hi Lukas,</div><div style="font-family:"trebuchet ms",sans-serif"><br></div><div style="font-family:"trebuchet ms",sans-serif">Thanks for the tip! We actually use those extended stats from time to time to profile our systems but I don't have them turned on in the machines I'm using now. In any case, hey might tell me which specific parts of the emulator the scheduler is spending less time on, but… they won't tell me what extra auxiliary tasks it is handling, right?</div></div></blockquote><div><br></div><div>Parts of what is normally the aux state will be moved to other new states when you enable the extra states.</div><div> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div style="font-family:"trebuchet ms",sans-serif"><br></div><div style="font-family:"trebuchet ms",sans-serif">I'll run a test with extended microaccounting, probably next week, but do you know a way to figure out what the extra auxiliary jobs that my scheduler is running are?</div></div></blockquote><div><br></div><div>If you don't feel like coding some C you might want to try perf and see what it can tell you.</div><div><br></div><div>If you feel like coding some C you can add the extra states to msacc for each of the aux jobs that are done and then check which one it is.</div><div><br></div><div>You add new states here: <a href="https://github.com/erlang/otp/blob/master/erts/emulator/beam/erl_msacc.h#L59" target="_blank">https://github.com/erlang/otp/blob/master/erts/emulator/beam/erl_msacc.h#L59</a></div><div>The different aux actions can be found here: <a href="https://github.com/erlang/otp/blob/master/erts/emulator/beam/erl_process.h#L299-L319" target="_blank">https://github.com/erlang/otp/blob/master/erts/emulator/beam/erl_process.h#L299-L319</a></div><div>And the calls to them can be found here: <a href="https://github.com/erlang/otp/blob/master/erts/emulator/beam/erl_process.c#L2588-L2663" target="_blank">https://github.com/erlang/otp/blob/master/erts/emulator/beam/erl_process.c#L2588-L2663</a></div><div><br></div><div>It should be enough to add a ERTS_MSACC_SET_STATE_M call before each of the clauses.</div><div><br></div><div>Lukas</div><div><br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div style="font-family:"trebuchet ms",sans-serif"><span style="font-family:Arial,Helvetica,sans-serif"> </span><br></div></div></blockquote><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div style="font-family:"trebuchet ms",sans-serif"></div><div style="font-family:"trebuchet ms",sans-serif">Cheers!</div><div style="font-family:"trebuchet ms",sans-serif"><br></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Fri, Jul 3, 2020 at 4:22 PM Lukas Larsson <<a href="mailto:lukas@erlang.org" target="_blank">lukas@erlang.org</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div>Hello,</div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Fri, Jul 3, 2020 at 4:14 PM Fernando Benavides <<a href="mailto:elbrujohalcon@gmail.com" target="_blank">elbrujohalcon@gmail.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div style="font-family:"trebuchet ms",sans-serif">Hi Erlangers,</div><div style="font-family:"trebuchet ms",sans-serif"><br></div><div style="font-family:"trebuchet ms",sans-serif">It's me again… still trying to understand why my system behaves worse in OTP22 than OTP21.</div><div style="font-family:"trebuchet ms",sans-serif">The last thing I tried was running <a href="http://erlang.org/doc/man/msacc.html" target="_blank">MicroStateAccounting</a> on it and the results showed something <i>odd</i>…</div><div style="font-family:"trebuchet ms",sans-serif"><br></div><div style="font-family:"trebuchet ms",sans-serif">These are two of my summaries for OTP21:</div><div><font size="1" face="monospace">Stats per type:<br> Thread <b>aux</b> check_io <b>emulator</b> gc other port sleep<br> async 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 100.00%<br> aux 0.23% 0.06% 0.00% 0.00% 0.09% 0.00% 99.62%<br>dirty_cpu_sche 0.00% 0.00% 0.01% 0.20% 0.00% 0.00% 99.79%<br>dirty_io_sched 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 100.00%<br> poll 0.00% 0.58% 0.00% 0.00% 0.00% 0.00% 99.42%<br> scheduler <b>2.05%</b> 0.56% <b>71.29%</b> 13.25% 3.00% 1.89% 7.96%<br>ok<br><br>Stats per type:<br> async 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 100.00%<br> aux 0.23% 0.07% 0.00% 0.00% 0.08% 0.00% 99.62%<br>dirty_cpu_sche 0.00% 0.00% 0.01% 0.29% 0.00% 0.00% 99.70%<br>dirty_io_sched 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 100.00%<br> poll 0.00% 0.61% 0.00% 0.00% 0.00% 0.00% 99.39%<br> <b>scheduler</b> <b>2.26%</b> 0.56% <b>68.70%</b> 12.69% 3.42% 1.89% 10.48%<br>ok</font><br></div><div style="font-family:"trebuchet ms",sans-serif"><br></div><div><div style="font-family:"trebuchet ms",sans-serif">These are the corresponding two summaries for OTP22 (same period of time, same code, running the same things):</div><div><font size="1" face="monospace">Stats per type:<br> Thread <b>aux</b> check_io <b>emulator</b> gc other port sleep<br> async 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 100.00%<br> aux 0.49% 0.06% 0.00% 0.00% 0.28% 0.00% 99.16%<br>dirty_cpu_sche 0.00% 0.00% 0.00% 0.19% 0.00% 0.00% 99.80%<br>dirty_io_sched 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 99.99%<br> poll 0.00% 0.53% 0.00% 0.00% 0.00% 0.00% 99.47%<br> <b>scheduler</b> <b>6.26%</b> 0.52% <b>63.83%</b> 14.41% 3.05% 1.72% 10.20%<br>ok</font></div><div><font size="1" face="monospace"><br>Stats per type:<br> async 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 100.00%<br> aux 0.39% 0.07% 0.00% 0.00% 0.18% 0.00% 99.36%<br>dirty_cpu_sche 0.00% 0.00% 0.00% 0.22% 0.00% 0.00% 99.78%<br>dirty_io_sched 0.00% 0.00% 0.00% 0.00% 0.00% 0.00% 99.99%<br> poll 0.00% 0.51% 0.00% 0.00% 0.00% 0.00% 99.49%<br> <b>scheduler</b> <b>6.97%</b> 0.54% <b>63.88%</b> 13.73% 3.19% 1.74% 9.96%<br>ok</font><br></div></div><div><br></div><div><div style="font-family:"trebuchet ms",sans-serif">I highlighted the strange/different parts there, but in a nutshell:</div><div style="font-family:"trebuchet ms",sans-serif">The scheduler is spending more time <i>handling </i><b><i>auxiliary jobs</i> </b>and less time <i>executing Erlang processes </i>(<a href="http://erlang.org/doc/man/erlang.html#statistics_microstate_accounting" target="_blank">for context</a>).</div><div style="font-family:"trebuchet ms",sans-serif">Can anybody give me a clue as to what to check next? How can I determine what are those <i><b>auxiliary jobs</b></i> that the scheduler is working on now?</div><div style="font-family:"trebuchet ms",sans-serif"><br></div></div></div></blockquote><div><br></div><div>You can enable more msacc stats by turning on extra states. This is a compile-time flag that you pass to configure: ./configure --with-microstate-accounting=extra</div><div><br></div><div>My guess would be that the extra time ends up in the alloc state, which means that it for some reason extra memory allocation is happening which is slowing down the system.</div><div><br></div><div>Lukas</div><div> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div><div style="font-family:"trebuchet ms",sans-serif"></div><div style="font-family:"trebuchet ms",sans-serif">Thanks in advance :)</div><br></div><div><br></div>-- <br><div dir="ltr"><table border="0" cellpadding="0" cellspacing="0">
<tbody>
<tr>
<td align="left" valign="bottom" width="107" style="line-height:0;vertical-align:bottom;padding-right:10px;padding-top:20px;padding-bottom:20px">
<a href="https://about.me/elbrujohalcon?promo=email_sig&utm_source=product&utm_medium=email_sig&utm_campaign=gmail_api&utm_content=thumb" style="text-decoration:none" target="_blank">
<img alt="" width="105" height="70" style="margin: 0px; padding: 0px; display: block; border: 1px solid rgb(238, 238, 238);">
</a>
</td>
<td align="left" valign="bottom" style="line-height:1.1;vertical-align:bottom;padding-top:20px;padding-bottom:20px">
<img width="1" height="1" style="border: 0px; margin: 0px; padding: 0px; overflow: hidden;">
<div style="font-size:18px;font-weight:bold;color:rgb(51,51,51);font-family:"Proxima Nova",Helvetica,Arial,sans-serif">Brujo Benavides</div>
<a href="https://about.me/elbrujohalcon?promo=email_sig&utm_source=product&utm_medium=email_sig&utm_campaign=gmail_api&utm_content=thumb" style="text-decoration:none;font-size:12px;color:rgb(43,130,173);font-family:"Proxima Nova",Helvetica,Arial,sans-serif" target="_blank">about.me/elbrujohalcon
</a>
</td>
</tr>
</tbody>
</table>
</div></div>
</blockquote></div></div>
</blockquote></div><br clear="all"><div><br></div>-- <br><div dir="ltr"><table border="0" cellpadding="0" cellspacing="0">
<tbody>
<tr>
<td align="left" valign="bottom" width="107" style="line-height:0;vertical-align:bottom;padding-right:10px;padding-top:20px;padding-bottom:20px">
<a href="https://about.me/elbrujohalcon?promo=email_sig&utm_source=product&utm_medium=email_sig&utm_campaign=gmail_api&utm_content=thumb" style="text-decoration:none" target="_blank">
<img alt="" width="105" height="70" style="margin: 0px; padding: 0px; display: block; border: 1px solid rgb(238, 238, 238);">
</a>
</td>
<td align="left" valign="bottom" style="line-height:1.1;vertical-align:bottom;padding-top:20px;padding-bottom:20px">
<img width="1" height="1" style="border: 0px; margin: 0px; padding: 0px; overflow: hidden;">
<div style="font-size:18px;font-weight:bold;color:rgb(51,51,51);font-family:"Proxima Nova",Helvetica,Arial,sans-serif">Brujo Benavides</div>
<a href="https://about.me/elbrujohalcon?promo=email_sig&utm_source=product&utm_medium=email_sig&utm_campaign=gmail_api&utm_content=thumb" style="text-decoration:none;font-size:12px;color:rgb(43,130,173);font-family:"Proxima Nova",Helvetica,Arial,sans-serif" target="_blank">about.me/elbrujohalcon
</a>
</td>
</tr>
</tbody>
</table>
</div>
</blockquote></div></div>
</blockquote></div><br clear="all"><div><br></div>-- <br><div dir="ltr" class="gmail_signature"><table border="0" cellpadding="0" cellspacing="0">
<tbody>
<tr>
<td align="left" valign="bottom" width="107" style="line-height:0;vertical-align:bottom;padding-right:10px;padding-top:20px;padding-bottom:20px">
<a href="https://about.me/elbrujohalcon?promo=email_sig&utm_source=product&utm_medium=email_sig&utm_campaign=gmail_api&utm_content=thumb" style="text-decoration:none" target="_blank">
<img src="https://thumbs.about.me/thumbnail/users/e/l/b/elbrujohalcon_emailsig.jpg?_1498084031_146" alt="" width="105" height="70" style="margin: 0px; padding: 0px; display: block; border: 1px solid rgb(238, 238, 238);">
</a>
</td>
<td align="left" valign="bottom" style="line-height:1.1;vertical-align:bottom;padding-top:20px;padding-bottom:20px">
<img src="https://about.me/t/sig?u=elbrujohalcon" width="1" height="1" style="border: 0px; margin: 0px; padding: 0px; overflow: hidden;">
<div style="font-size:18px;font-weight:bold;color:rgb(51,51,51);font-family:"Proxima Nova",Helvetica,Arial,sans-serif">Brujo Benavides</div>
<a href="https://about.me/elbrujohalcon?promo=email_sig&utm_source=product&utm_medium=email_sig&utm_campaign=gmail_api&utm_content=thumb" style="text-decoration:none;font-size:12px;color:rgb(43,130,173);font-family:"Proxima Nova",Helvetica,Arial,sans-serif" target="_blank">about.me/elbrujohalcon
</a>
</td>
</tr>
</tbody>
</table>
</div>