What does scheduler/aux mean in msacc?
Fernando Benavides
elbrujohalcon@REDACTED
Mon Jul 6 14:02:19 CEST 2020
So, I tested with extended msacc and this is what I got…
Thread alloc aux bifbusy_wait check_io emulator
ets gc gc_full nif other port send sleep timers
OTP 21:
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%
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%
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%
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%
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%
scheduler *8.89%* *0.86%* *23.93%* 0.04% 0.31% *38.18%*
6.15% 4.81% 0.67% 3.29% 1.35% 1.09% 1.58% 8.74%
0.12%
OTP 22:
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%
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%
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%
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%
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%
scheduler *10.83%* *1.82%* *21.74%* 0.04% 0.34% *36.14%*
6.44% 4.91% 0.79% 3.82% 1.57% 1.13% 1.71% 8.63%
0.12%
I highlighted the *important* pieces, but in a nutshell…
- Scheduler allocation increased 2%
- Time handling auxiliary jobs increased 1%. In other words: it more
than doubled.
- Time spent by the scheduler in BIFs is 2% less
- Time spent by the scheduler executing erlang processes is 2% less
- GC, NIfs, port, send and other times also increased but the increase
is far smaller (less than 1%).
So, OTP22 (when compared to OTP21) in my system is shifting time previously
spent on the emulator or BIFs to other tasks… particularly *managing
memory* and
*auxiliary jobs*. 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?
Thanks again.
On Fri, Jul 3, 2020 at 4:57 PM Lukas Larsson <lukas@REDACTED> wrote:
>
>
> On Fri, Jul 3, 2020 at 4:27 PM Fernando Benavides <elbrujohalcon@REDACTED>
> wrote:
>
>> Hi Lukas,
>>
>> 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?
>>
>
> Parts of what is normally the aux state will be moved to other new states
> when you enable the extra states.
>
>
>>
>> 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?
>>
>
> If you don't feel like coding some C you might want to try perf and see
> what it can tell you.
>
> 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.
>
> You add new states here:
> https://github.com/erlang/otp/blob/master/erts/emulator/beam/erl_msacc.h#L59
> The different aux actions can be found here:
> https://github.com/erlang/otp/blob/master/erts/emulator/beam/erl_process.h#L299-L319
> And the calls to them can be found here:
> https://github.com/erlang/otp/blob/master/erts/emulator/beam/erl_process.c#L2588-L2663
>
> It should be enough to add a ERTS_MSACC_SET_STATE_M call before each of
> the clauses.
>
> Lukas
>
>
>>
> Cheers!
>>
>>
>> On Fri, Jul 3, 2020 at 4:22 PM Lukas Larsson <lukas@REDACTED> wrote:
>>
>>> Hello,
>>>
>>> On Fri, Jul 3, 2020 at 4:14 PM Fernando Benavides <
>>> elbrujohalcon@REDACTED> wrote:
>>>
>>>> Hi Erlangers,
>>>>
>>>> It's me again… still trying to understand why my system behaves worse
>>>> in OTP22 than OTP21.
>>>> The last thing I tried was running MicroStateAccounting
>>>> <http://erlang.org/doc/man/msacc.html> on it and the results showed
>>>> something *odd*…
>>>>
>>>> These are two of my summaries for OTP21:
>>>> Stats per type:
>>>> Thread *aux* check_io *emulator* gc other
>>>> port sleep
>>>> async 0.00% 0.00% 0.00% 0.00% 0.00% 0.00%
>>>> 100.00%
>>>> aux 0.23% 0.06% 0.00% 0.00% 0.09% 0.00%
>>>> 99.62%
>>>> dirty_cpu_sche 0.00% 0.00% 0.01% 0.20% 0.00% 0.00%
>>>> 99.79%
>>>> dirty_io_sched 0.00% 0.00% 0.00% 0.00% 0.00% 0.00%
>>>> 100.00%
>>>> poll 0.00% 0.58% 0.00% 0.00% 0.00% 0.00%
>>>> 99.42%
>>>> scheduler *2.05%* 0.56% *71.29%* 13.25% 3.00%
>>>> 1.89% 7.96%
>>>> ok
>>>>
>>>> Stats per type:
>>>> async 0.00% 0.00% 0.00% 0.00% 0.00% 0.00%
>>>> 100.00%
>>>> aux 0.23% 0.07% 0.00% 0.00% 0.08% 0.00%
>>>> 99.62%
>>>> dirty_cpu_sche 0.00% 0.00% 0.01% 0.29% 0.00% 0.00%
>>>> 99.70%
>>>> dirty_io_sched 0.00% 0.00% 0.00% 0.00% 0.00% 0.00%
>>>> 100.00%
>>>> poll 0.00% 0.61% 0.00% 0.00% 0.00% 0.00%
>>>> 99.39%
>>>> *scheduler* *2.26%* 0.56% *68.70%* 12.69% 3.42%
>>>> 1.89% 10.48%
>>>> ok
>>>>
>>>> These are the corresponding two summaries for OTP22 (same period of
>>>> time, same code, running the same things):
>>>> Stats per type:
>>>> Thread *aux* check_io *emulator* gc other
>>>> port sleep
>>>> async 0.00% 0.00% 0.00% 0.00% 0.00% 0.00%
>>>> 100.00%
>>>> aux 0.49% 0.06% 0.00% 0.00% 0.28% 0.00%
>>>> 99.16%
>>>> dirty_cpu_sche 0.00% 0.00% 0.00% 0.19% 0.00% 0.00%
>>>> 99.80%
>>>> dirty_io_sched 0.00% 0.00% 0.00% 0.00% 0.00% 0.00%
>>>> 99.99%
>>>> poll 0.00% 0.53% 0.00% 0.00% 0.00% 0.00%
>>>> 99.47%
>>>> *scheduler* *6.26%* 0.52% *63.83%* 14.41% 3.05%
>>>> 1.72% 10.20%
>>>> ok
>>>>
>>>> Stats per type:
>>>> async 0.00% 0.00% 0.00% 0.00% 0.00% 0.00%
>>>> 100.00%
>>>> aux 0.39% 0.07% 0.00% 0.00% 0.18% 0.00%
>>>> 99.36%
>>>> dirty_cpu_sche 0.00% 0.00% 0.00% 0.22% 0.00% 0.00%
>>>> 99.78%
>>>> dirty_io_sched 0.00% 0.00% 0.00% 0.00% 0.00% 0.00%
>>>> 99.99%
>>>> poll 0.00% 0.51% 0.00% 0.00% 0.00% 0.00%
>>>> 99.49%
>>>> *scheduler* *6.97%* 0.54% *63.88%* 13.73% 3.19%
>>>> 1.74% 9.96%
>>>> ok
>>>>
>>>> I highlighted the strange/different parts there, but in a nutshell:
>>>> The scheduler is spending more time *handling **auxiliary jobs *and
>>>> less time *executing Erlang processes *(for context
>>>> <http://erlang.org/doc/man/erlang.html#statistics_microstate_accounting>
>>>> ).
>>>> Can anybody give me a clue as to what to check next? How can I
>>>> determine what are those *auxiliary jobs* that the scheduler is
>>>> working on now?
>>>>
>>>>
>>> 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
>>>
>>> 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.
>>>
>>> Lukas
>>>
>>>
>>>> Thanks in advance :)
>>>>
>>>>
>>>> --
>>>>
>>>> <https://about.me/elbrujohalcon?promo=email_sig&utm_source=product&utm_medium=email_sig&utm_campaign=gmail_api&utm_content=thumb>
>>>> Brujo Benavides
>>>> about.me/elbrujohalcon
>>>> <https://about.me/elbrujohalcon?promo=email_sig&utm_source=product&utm_medium=email_sig&utm_campaign=gmail_api&utm_content=thumb>
>>>>
>>>
>>
>> --
>>
>> <https://about.me/elbrujohalcon?promo=email_sig&utm_source=product&utm_medium=email_sig&utm_campaign=gmail_api&utm_content=thumb>
>> Brujo Benavides
>> about.me/elbrujohalcon
>> <https://about.me/elbrujohalcon?promo=email_sig&utm_source=product&utm_medium=email_sig&utm_campaign=gmail_api&utm_content=thumb>
>>
>
--
<https://about.me/elbrujohalcon?promo=email_sig&utm_source=product&utm_medium=email_sig&utm_campaign=gmail_api&utm_content=thumb>
Brujo Benavides
about.me/elbrujohalcon
<https://about.me/elbrujohalcon?promo=email_sig&utm_source=product&utm_medium=email_sig&utm_campaign=gmail_api&utm_content=thumb>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://erlang.org/pipermail/erlang-questions/attachments/20200706/bbb06636/attachment.htm>
More information about the erlang-questions
mailing list