<div dir="ltr"><div>Yielding means that the process running the ++ BIF will save state and self-suspend trying to find another process to share the CPU with, there's extra work involved (Erlang process switching) when working on a big list, even if it is a clean empty VM running, there will be time lost on scheduling out and in.<br></div><div><br></div><div>The 1st list has to be fully copied for ++ operation to continue with the 2nd list.<br></div><div>Length of 2nd list is irrelevant as it's just appended on build.</div><div><br></div><div>
<div>If this particular BIF is important for your project, please modify that threshold value and rebuild the VM.</div><div>The entry point is `erl_bif_lists.c:230` in master branch, see `static Eterm append/2` then proceeds to `int append_start/4` and from there to `int append_continue/2` and to `BIF_RETTYPE lists_append_alloc/2`<br></div>
</div><div><br></div><div>The threshold at which the switch is happening can be found from the C source code for ++ BIF. The threshold value is <b>60 list cells</b> per reduction (erl_bif_lists.c:150 CELLS_PER_RED) and the value is multiplied by remaining reductions ERTS_BIF_REDS_LEFT. Max reductions value is 4000 but your test process might have less remaining which causes process scheduling out early.<br></div><div><br></div><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Thu, 2 Jul 2020 at 10:34, 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 Dániel,</div><div style="font-family:trebuchet ms,sans-serif"><br></div><div style="font-family:trebuchet ms,sans-serif">Thanks for checking!</div><div style="font-family:trebuchet ms,sans-serif">I can definitely tell it's not that OTP21 bug. In all my test environments (being those in my machine or in the servers), this returns <b>1</b> everytime: <span style="font-family:monospace">erlang:convert_time_</span><span style="font-family:monospace">unit(1000, native, microsecond).</span></div><div style="font-family:trebuchet ms,sans-serif"><span style="font-family:monospace"><br></span></div><div style="font-family:trebuchet ms,sans-serif">You got your results with smaller samples… So, I tried with smaller samples, too… And you're right! OTP22 seems faster with those.</div><div style="font-family:trebuchet ms,sans-serif">For instance,</div><div style="font-family:trebuchet ms,sans-serif"><br></div><div style="font-family:trebuchet ms,sans-serif">test:bench({test, rec}, 2500, 500, 25). % reports avg times over 100µs in OTP21, but under 70µs in OTP22…</div><div style="font-family:trebuchet ms,sans-serif"><br></div><div style="font-family:trebuchet ms,sans-serif">…but if I increase the size of the individual lists to concat…</div><div style="font-family:trebuchet ms,sans-serif"><br></div><div style="font-family:trebuchet ms,sans-serif">test:bench({test, rec}, 2500, 500, 200). % reports ~550µs in OTP21 / ~1300µs in OTP22<br></div><div style="font-family:trebuchet ms,sans-serif"><br></div><div style="font-family:trebuchet ms,sans-serif">…and if I increase the # of lists…</div><div style="font-family:trebuchet ms,sans-serif"><br></div><div style="font-family:trebuchet ms,sans-serif">test:bench({test, rec}, 2500, 5000, 25). % reports ~600µs in OTP21 and it <b>jumps between</b> 700µs and 1400µs in OTP22 <b>(O_O)!!</b><br></div><div style="font-family:trebuchet ms,sans-serif"><b><br></b></div><div style="font-family:trebuchet ms,sans-serif">This is OTP22… and it happened multiple times…</div><div style="font-family:trebuchet ms,sans-serif">72> [test:bench({test, rec}, 2500, 5000, 25) || _ <- lists:seq(1,10)].<br>[1296.7716,<b>700.2968</b>,1317.4632,<b>698.1416</b>,1316.9648,<b>696.0352</b>,<br> 1294.4548,<b>706.8484</b>,1304.8368,<b>697.4452</b>]<br></div><div style="font-family:trebuchet ms,sans-serif">How is that <i>shaking </i>even possible?</div><div style="font-family:trebuchet ms,sans-serif">Aaanyway… if I only run the code 250 times (instead of 2500)… OTP22 is consistently in <b>~1800µs</b>.</div><div style="font-family:trebuchet ms,sans-serif"><br></div><div style="font-family:trebuchet ms,sans-serif">So, extrapolating wildly from very incomplete data… the problem seems to present itself when applying ++ to either larger lists or to a large # of lists (which, in time, results in ++'ing larger lists too… although AFAICT the time it takes to run ++ is more affected by the length of the first list and not the second one).</div><div style="font-family:trebuchet ms,sans-serif"><br></div><div style="font-family:trebuchet ms,sans-serif">I'm still puzzled…</div><div style="font-family:trebuchet ms,sans-serif"><br></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Thu, Jul 2, 2020 at 1:43 AM Dániel Szoboszlay <<a href="mailto:dszoboszlay@gmail.com" target="_blank">dszoboszlay@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">Hi Brujo,<div><br></div><div>I tried to reproduce your results, and for me OTP 22 seems to be consistently faster for rec and about the same for lrec:</div><div><br></div><div><font face="monospace">Test case Min Max Median Average<br>rec / OTP 21 124.170us 305.990us 127.120us 128.688us<br>rec / OTP 22 62.570us 289.190us 67.610us 68.976us<br>lrec / OTP 21 16.110us 22.570us 17.790us 17.881us<br>lrec / OTP 22 15.390us 22.710us 17.170us 17.441us<br></font></div><div><br></div><div>(These are times for single invocation of the functions for much smaller inputs than in your example.)</div><div><br></div><div>However, there are some OTP 21 versions where due to a configuration bug the resolution of the native clock was much lower. For example <font face="monospace">erlang:convert_time_unit(1000, native, microsecond).</font> normally gives 1 on my machine (so the native clock has nanosecond resolution), and on the buggy OTP 21 versions I get 610. On these OTP 21 versions I see that your rec benchmark seems to run ~6% faster than with OTP 22, but this is measurement error due to the lower clock resolution.</div><div><br></div><div>Could you please check you have the same clock resolution on both OTP versions?</div><div><br></div><div>Cheers,</div><div>Daniel</div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Wed, 1 Jul 2020 at 12:56, 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"><div>(Sorry if you receive this email twice, I sent it from another account and it seems like it didn't reach the mailing list then)</div><div><br></div><div>Hi erlangers,</div><div><br></div><div>Yeah! It's me talking about performance, you read that subject right 🤦♂️</div><div>Anyway… At NextRoll we're in the process of migrating our systems from OTP21 to OTP22 (not 23, yet) and our tests showed a <b>huge</b> impact on performance in general, that was not associated to anything in particular.</div><div><br></div><div>While trying to figure out what was causing it, we came up with a very very basic example of things that are consistently slower in OTP22.</div><div><br></div><div>I created this gist to show it: <a href="https://gist.github.com/elbrujohalcon/d4e995fbc4b93fadddfd1f0d6b9f8121" style="font-family:Arial,Helvetica,sans-serif" target="_blank">https://gist.github.com/elbrujohalcon/d4e995fbc4b93fadddfd1f0d6b9f8121</a></div><div><br></div><div>I'm aware that these kinds of micro-benchmarks are treacherous and they may vary wildly depending on context. Nevertheless, on both on one of our servers in AWS and on my machine (A MacOS Pro running Catalina 10.15.5) and using kerl to install multiple versions of OTP 21 and 22… every single time I run the tests I found the same results…</div><div><br></div><div>Always starting the nodes with <i>erl -boot start_clean </i>then running the following in both OTP21 and OTP22…</div><div style="font-family:Arial,Helvetica,sans-serif"><font face="monospace"><br></font></div><div style="font-family:Arial,Helvetica,sans-serif"><font face="monospace">c(test), test:bench({test, lrec}, 250, 5000, 2000).</font><br></div><div><br></div><div>…generates very similar numbers in both versions, regardless of the numbers used for the different parameters. But…</div><div style="font-family:Arial,Helvetica,sans-serif"><font face="monospace"><br></font></div><div style="font-family:Arial,Helvetica,sans-serif"><font face="monospace">c(test), test:bench({test, rec}, 250, 5000, 2000).</font><br></div><div><br></div><div>…consistently generates larger results in OTP22 than OTP21. I tried with different values for the number of tests, the number of lists and their length and sometimes the difference is more evident, sometimes less… but OTP22 times are <b>always</b> larger.</div><div><br></div><div>I found this in the OTP22 readme…</div><div><br></div><div style="font-family:Arial,Helvetica,sans-serif"><font face="monospace"> OTP-15427 Application(s): erts<br> Appending lists (The ++ operator) will now yield<br> properly on large inputs.</font><br></div><div><br></div><div>So… questions…</div><div>1. Has anybody experienced (and hopefully solved) this problem before when migrating to OTP22?</div><div>2. Do you think OTP-15427 can be related to what I'm seeing?</div><div>3. Can someone confirm if you also experience the same difference in performance when running the same benchmarks that I pasted on that gist?</div><div>4. Is there anything else I should try/test/use to check?</div><div>5. Am I going slightly mad?</div><div><br></div><div>Thanks in advance, cheers :)</div><font style="font-family:Arial,Helvetica,sans-serif" color="#888888"><br></font></div><div><br></div>-- <br><div dir="ltr"><table cellspacing="0" cellpadding="0" border="0">
<tbody>
<tr>
<td style="line-height:0;vertical-align:bottom;padding-right:10px;padding-top:20px;padding-bottom:20px" width="107" valign="bottom" align="left">
<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="" style="margin:0px;padding:0px;display:block;border:1px solid rgb(238,238,238)" width="105" height="70">
</a>
</td>
<td style="line-height:1.1;vertical-align:bottom;padding-top:20px;padding-bottom:20px" valign="bottom" align="left">
<img src="https://about.me/t/sig?u=elbrujohalcon" style="border:0px none;margin:0px;padding:0px;overflow:hidden" width="1" height="1">
<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>
</blockquote></div><br clear="all"><div><br></div>-- <br><div dir="ltr"><table cellspacing="0" cellpadding="0" border="0">
<tbody>
<tr>
<td style="line-height:0;vertical-align:bottom;padding-right:10px;padding-top:20px;padding-bottom:20px" width="107" valign="bottom" align="left">
<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="" style="margin:0px;padding:0px;display:block;border:1px solid rgb(238,238,238)" width="105" height="70">
</a>
</td>
<td style="line-height:1.1;vertical-align:bottom;padding-top:20px;padding-bottom:20px" valign="bottom" align="left">
<img src="https://about.me/t/sig?u=elbrujohalcon" style="border:0px none;margin:0px;padding:0px;overflow:hidden" width="1" height="1">
<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>