Re: Hunting mode switches

[Philippe Gerum <rpm@xenomai.org>]

François Legal via Xenomai <xenomai@xenomai.org> writes:

> Le Lundi, Mai 31, 2021 20:57 CEST, François Legal via Xenomai <xenomai@xenomai.org> a écrit: 
>  
>> Le Lundi, Mai 31, 2021 18:14 CEST, Jan Kiszka <jan.kiszka@siemens.com> a écrit: 
>>  
>> > On 31.05.21 18:06, François Legal via Xenomai wrote:
>> > > Hello,
>> > > 
>> > > I'm having trouble hunting mode switches on an arm embedded application.
>> > > 
>> > > When I look at cat /proc/xenomai/sched/stat
>> > > 
>> > > CPU  PID    MSW        CSW        XSC        PF    STAT       %CPU  NAME
>> > >   0  0      0          476986     0          0     00218000   84.5  [ROOT/0]
>> > >   1  0      0          137743     0          0     00218000   99.3  [ROOT/1]
>> > >   1  667    0          137550     0          0     00200042    0.7  [rtnet-stack]
>> > >   0  669    0          2          0          0     00220042    0.0  [rtnet-rtpc]
>> > >   1  901    110        218        203        0     00264044    0.0  APP_Main
>> > >   0  911    1          1216       3524       0     00240046    0.0  ThreadPar
>> > >   0  912    3          56683      3531       0     00240046    0.2  ThreadMessage
>> > >   0  913    309702     470522     2152301    0     00240046    8.9  ThreadExec
>> > >   0  914    7          62         71         0     00240042    0.0  TheadGO
>> > >   0  915    3          647        1190       0     00248046    0.0  ThreadDbg
>> > >   0  916    1          2024       3087       0     00248046    0.0  ThreadCt
>> > >   0  917    1          35801      320489     0     00248046    0.8  ThreadSupInv
>> > >   0  918    1          1231       3596       0     00248046    0.0  ThreadMessage2
>> > >   0  919    1          161554     479305     0     00248042    1.4  ThreadSched
>> > >   0  0      0          247850     0          0     00000000    0.4  [IRQ18: [timer]]
>> > >   1  0      0          15419      0          0     00000000    0.0  [IRQ18: [timer]]
>> > >   0  0      0          137548     0          0     00000000    1.5  [IRQ31: rteth0]
>> > >   1  0      0          0          0          0     00000000    0.0  [IRQ31: rteth0]
>> > >   0  0      0          1          0          0     00000000    0.0  [IRQ118: rteth1-tx]
>> > >   1  0      0          0          0          0     00000000    0.0  [IRQ118: rteth1-tx]
>> > >   0  0      0          0          0          0     00000000    0.0  [IRQ119: rteth1-rx]
>> > >   1  0      0          0          0          0     00000000    0.0  [IRQ119: rteth1-rx]
>> > > 
>> > > But when following the procedure in [1], I get 
>> > > no slacker
>> > > 
>> > > I can however see that Thread 913 seem to switch to secondary more than once out of 2 cycles !
>> > > What am I doing wrong.
>> > > 
>> > 
>> > CONFIG_XENO_OPT_DEBUG_TRACE_RELAX is on?
>> > 
>> 
>> Yes, it is.
>> 
>> > Did you also try the in-app instrumentation via SIGDEBUG, maybe
>> > attaching gdb to the process to catch the unwanted cases?
>> > 
>> 
>> No, not yet. It seems mode switches happen hundreds of time every seconds, so I was willing to try the slackspot.
>> I'll try that tomorrow and report back to the list 
>> 
>
> So trying the manual way, there seem to be something happening, but I could not tell exactly what, and I not sure how to track this.
>
> On thread ThreadExec, I get execution halted with SIGXCPU, and a backtrace indicating getpid(), then __pthread_kill() which I'm 100% sure I never call !
>
> Moreover, when being halted at that point, all threads are not created, and all of which are created seem to have done 3 or 4 MSW each, and without triggering any break.
>
> Moreover, in the stats capture below, the APP_Main (the main program entry), is looping on a 1s nanosleep, and it seems the MSW number increases once per second.
>
> I'm really confused now.
>

You may be receiving a SIGDEBUG signal from the Cobalt core which is not
handled by cobalt_sigdebug_handler() in lib/cobalt (internal.c) and
therefore passed on to the original handler, likely SIG_DFL. So first
thing is to run the app over gdb, breakpoint into
cobalt_sigdebug_handler(), then inspect the cause code in siginfo and
the backtrace at this point (bt).

-- 
Philippe.