What does scheduler/aux mean in msacc?

[Lukas Larsson]

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>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://erlang.org/pipermail/erlang-questions/attachments/20200703/a4f6ca24/attachment.htm>