Help with analysing JIT perf report

[Lukas Larsson]

Hello!

erts_schedule is the function that is responsible to selecting which thing
to run next (port, process, etc). When trying to figure out what it should
run it takes a bunch of locks, some of them are spinlocks. You should not
really be spending all that much time in this function, so something is
fishy.

It could be that the lcnt emulator has a bug/feature that could explain
this, so (as you say) try running without it and see if you get the same
problem.
It could be that lcnt+perf has some bug.
Or it could be something completely different that I can't think of.

Lukas


On Wed, Jun 23, 2021 at 11:00 AM Max Lapshin <max.lapshin@REDACTED> wrote:

> I've clicked 'a' on this erts_schedule and see following:
>
>
> Percent│        mov    erts_msacc_enabled,%eax
>        │        movq   $0x0,0x20(%rsp)
>        │        test   %eax,%eax
>        │      ↓ je     7e3
>        │        mov    erts_msacc_key,%edi
>        │      → callq  ethr_tsd_get
>        │        mov    %rax,0x20(%rsp)
>        │ 7e3:   test   %ebx,%ebx
>        │        movl   $0x1,0x18(%rsp)
>        │      ↓ jne    1702
>        │ 7f3:   mov    0xb0(%r14),%eax
>        │        test   %eax,%eax
>        │      ↓ je     1660
>        │        movabs $0x7fffffffffffffff,%r13
>        │        xor    %ebx,%ebx
>        │ 80e:   mov    $0x64,%edx
>        │      ↓ jmp    826
>   4.73 │ 815:   subl   $0x1,0x2c(%rsp)
>   1.64 │        mov    0x2c(%rsp),%eax
>   1.31 │     ┌──test   %eax,%eax
>        │     ├──jle    15a0
>   0.03 │ 826:│  mov    0x18(%rbp),%r12d
>   0.01 │     │  mov    %r12d,%eax
>        │     │  and    $0x9,%eax
>   0.67 │     │  cmp    $0x9,%eax
>        │     │↓ jne    15a0
>  86.62 │     │  pause
>   0.06 │     │  sub    $0x1,%edx
>   3.92 │     │↑ jne    815
>   0.16 │     │→ callq  sched_yield@REDACTED
>   0.00 │     │  test   %eax,%eax
>        │     │  mov    $0x64,%edx
>
>
>
>
> 82% on some instruction pause
>
> I will try to run this again on non-lcnt beam, but seems that this is
> somewhere around spinlock?
>
> On Wed, Jun 23, 2021 at 11:39 AM Max Lapshin <max.lapshin@REDACTED>
> wrote:
> >
> > Perf report shows me things that I cannot analyse:
> >
> >
> > +   63.85%    51.25%  streamer  beam.lcnt.smp           [.] erts_schedule
> > +   59.99%     0.02%  streamer  beam.lcnt.smp           [.]
> > erts_dirty_process_main
> > +   29.50%     0.04%  streamer  jitted-881027-8664.so   [.]
> > gen_server:handle_msg/6
> > +   25.66%     0.04%  streamer  jitted-881027-34178.so  [.]
> > mpts_reader:handle_info/2
> >
> >
> > mpts_reader is my code and thanks for pointing out to me that it seems
> > to be the CPU eater.
> >
> > I cannot understand what means that erts_schedule takes 63 / 51% of time.
> > Is erts_schedule a container to all functions below?
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://erlang.org/pipermail/erlang-questions/attachments/20210623/910d9fe6/attachment.htm>