[Xenomai] High CPU load using q_send under pSOS skin

[Xenomai] High CPU load using q_send under pSOS skin

[Marcel van Mierlo]

Hi,

I've been investigating this for a couple of days and would really 
appreciate some insight
on what might be going on or what I can do to progress this...

I am porting a legacy pSOS application - to Xenomai on BeagleBoard Black 
3.8 kernel
and have noticed %CPU (via. top) of MAIN around 40% when using q_send, 
and doing no "work".

Surprisingly,  if I add a printf() and fflush() to the task body then 
the CPU drops down to < 1%.

I've checked compile options, nothing obviously wrong. Here is the 
(abridged) body of the task.
It just provides a periodic message for watchdog purposes.


[%CPU ~%40]
while{1}
{
     q_send(ulCanTQid, (INT32 *)&oCanMsg);
     tm_wkafter(100);  // ~100ms
}


[%CPU < %1]
while{1}
{
     q_send(ulCanTQid, (INT32 *)&oCanMsg);
     tm_wkafter(100);  // ~100ms

     printf("WAKING");
     fflush(stdout);
}

there is a task calling q_receive on the queue, but I have stubbed out 
any work to keep it as simple as possible.


root@arm:~# cat /proc/xenomai/version
2.6.3

Here is xenomai/stat when running at ~40 %CPUfrom top. I presume that 
ROOT/0 represents the
Xenomai/I-PIPE kernel. Nothing is reported as hogging the CPU....

Every 2.0s: cat /proc/xenomai/stat                      Sat Jan  1 
00:09:03 2000

CPU  PID    MSW        CSW        PF    STAT       %CPU  NAME
   0  0      0          186436     0     00500080   94.2  ROOT/0
   0  2882   16         427        0     00300380    0.0  MAIN
   0  2883   0          54128      0     00300184    1.0 onemsscheduler
   0  2884   0          542        0     00300184    0.0  FREE
   0  2885   0          1499       0     00300184    0.0  flsh
   0  2886   0          1          0     00300182    0.0  EWRN
   0  2887   0          45158      0     00300186    0.8  EEDT
   0  2888   0          53921      0     00300184    1.4  RESP
   0  2889   1          1          0     00300380    0.0  SERV
   0  2890   0          10784      0     00300184    0.4  CMND
   0  2891   2          1370       0     00300186    0.1  SERP
   0  2896   0          53080      0     00300184    0.8  SERO
   0  2899   0          536        0     00300186    0.0  CANP
   0  2900   0          1          0     00300182    0.0  CANG
   0  2901   0          1          0     00300182    0.0  CANE
   0  2902   0          315        0     00300182    0.0  CANT
   0  2903   1          1          0     00300380    0.0  CNMN
   0  2904   236        628        0     00300184    0.0  CIOW
   0  0      0          699350     0     00000000    1.0  IRQ83: [timer]


So questions are:

- Why does the %CPU under xenomai/stat not reflect whats reported by top 
(where is the 40% going)?
- How can I track down the high CPU load?
- Why would using printf and fflush make such a massive difference to 
%CPU? The application is not busy waiting or doing any CPU intensive work...



Any pointers greatly appreciated...happy to provide any further 
information....

Cheers,
Marcel.

Re: [Xenomai] High CPU load using q_send under pSOS skin

[Gilles Chanteperdrix]

On 02/06/2014 05:25 PM, Marcel van Mierlo wrote:
> Hi,
>
> I've been investigating this for a couple of days and would really
> appreciate some insight
> on what might be going on or what I can do to progress this...
>
> I am porting a legacy pSOS application - to Xenomai on BeagleBoard Black
> 3.8 kernel
> and have noticed %CPU (via. top) of MAIN around 40% when using q_send,
> and doing no "work".
>
> Surprisingly,  if I add a printf() and fflush() to the task body then
> the CPU drops down to < 1%.
>
> I've checked compile options, nothing obviously wrong. Here is the
> (abridged) body of the task.
> It just provides a periodic message for watchdog purposes.
>
>
> [%CPU ~%40]
> while{1}
> {
>       q_send(ulCanTQid, (INT32 *)&oCanMsg);
>       tm_wkafter(100);  // ~100ms

Have you checked that the comment is right? Are you sure you are not 
sleeping 100ns ?

-- 
					    Gilles.

Re: [Xenomai] High CPU load using q_send under pSOS skin

[Marcel van Mierlo]

Hi Gilles, I appreciate the input:

By observation, it is 100ms (using a trace function it looks nice and 
stable):

common_io.c cio_watchdog_kick +280 036.726273s: "WAKING"
common_io.c cio_watchdog_kick +280 036.826273s: "WAKING"
common_io.c cio_watchdog_kick +280 036.926272s: "WAKING"
common_io.c cio_watchdog_kick +280 037.026272s: "WAKING"
common_io.c cio_watchdog_kick +280 037.126272s: "WAKING"

so I am confident it is running at 100ms. The pSOS documentation refers 
to kc_ticks2sec to verify frequency, but I am not sure where to look 
under Xenomai to double check...not sure if this is relevant from 
.config, but anyway the trace comes every 100ms.

/CONFIG_XENO_OPT_TIMING_VIRTICK/=1000.

Marcel.


On 06/02/14 16:35, Gilles Chanteperdrix wrote:
> On 02/06/2014 05:25 PM, Marcel van Mierlo wrote:
>> Hi,
>>
>> I've been investigating this for a couple of days and would really
>> appreciate some insight
>> on what might be going on or what I can do to progress this...
>>
>> I am porting a legacy pSOS application - to Xenomai on BeagleBoard Black
>> 3.8 kernel
>> and have noticed %CPU (via. top) of MAIN around 40% when using q_send,
>> and doing no "work".
>>
>> Surprisingly,  if I add a printf() and fflush() to the task body then
>> the CPU drops down to < 1%.
>>
>> I've checked compile options, nothing obviously wrong. Here is the
>> (abridged) body of the task.
>> It just provides a periodic message for watchdog purposes.
>>
>>
>> [%CPU ~%40]
>> while{1}
>> {
>>       q_send(ulCanTQid, (INT32 *)&oCanMsg);
>>       tm_wkafter(100);  // ~100ms
>
> Have you checked that the comment is right? Are you sure you are not 
> sleeping 100ns ?
>

Re: [Xenomai] High CPU load using q_send under pSOS skin

[Philippe Gerum]

On 02/06/2014 05:25 PM, Marcel van Mierlo wrote:
> Hi,
>
> I've been investigating this for a couple of days and would really
> appreciate some insight
> on what might be going on or what I can do to progress this...
>
> I am porting a legacy pSOS application - to Xenomai on BeagleBoard Black
> 3.8 kernel
> and have noticed %CPU (via. top) of MAIN around 40% when using q_send,
> and doing no "work".
>
> Surprisingly,  if I add a printf() and fflush() to the task body then
> the CPU drops down to < 1%.
>
> I've checked compile options, nothing obviously wrong. Here is the
> (abridged) body of the task.
> It just provides a periodic message for watchdog purposes.
>
>
> [%CPU ~%40]
> while{1}
> {
>      q_send(ulCanTQid, (INT32 *)&oCanMsg);
>      tm_wkafter(100);  // ~100ms
> }
>
>
> [%CPU < %1]
> while{1}
> {
>      q_send(ulCanTQid, (INT32 *)&oCanMsg);
>      tm_wkafter(100);  // ~100ms
>
>      printf("WAKING");
>      fflush(stdout);
> }
>
> there is a task calling q_receive on the queue, but I have stubbed out
> any work to keep it as simple as possible.
>
>
> root@arm:~# cat /proc/xenomai/version
> 2.6.3
>
> Here is xenomai/stat when running at ~40 %CPUfrom top. I presume that
> ROOT/0 represents the
> Xenomai/I-PIPE kernel. Nothing is reported as hogging the CPU....
>
> Every 2.0s: cat /proc/xenomai/stat                      Sat Jan  1
> 00:09:03 2000
>
> CPU  PID    MSW        CSW        PF    STAT       %CPU  NAME
>    0  0      0          186436     0     00500080   94.2  ROOT/0
>    0  2882   16         427        0     00300380    0.0  MAIN
>    0  2883   0          54128      0     00300184    1.0 onemsscheduler
>    0  2884   0          542        0     00300184    0.0  FREE
>    0  2885   0          1499       0     00300184    0.0  flsh
>    0  2886   0          1          0     00300182    0.0  EWRN
>    0  2887   0          45158      0     00300186    0.8  EEDT
>    0  2888   0          53921      0     00300184    1.4  RESP
>    0  2889   1          1          0     00300380    0.0  SERV
>    0  2890   0          10784      0     00300184    0.4  CMND
>    0  2891   2          1370       0     00300186    0.1  SERP
>    0  2896   0          53080      0     00300184    0.8  SERO
>    0  2899   0          536        0     00300186    0.0  CANP
>    0  2900   0          1          0     00300182    0.0  CANG
>    0  2901   0          1          0     00300182    0.0  CANE
>    0  2902   0          315        0     00300182    0.0  CANT
>    0  2903   1          1          0     00300380    0.0  CNMN
>    0  2904   236        628        0     00300184    0.0  CIOW
>    0  0      0          699350     0     00000000    1.0  IRQ83: [timer]
>
>
> So questions are:
>
> - Why does the %CPU under xenomai/stat not reflect whats reported by top

Because top reports the CPU consumed when Linux is active, which 
excludes Xenomai activity.

> (where is the 40% going)?

Good question.

> - How can I track down the high CPU load?

Could you obtain a report from Xenomai's rtps command? This one reports 
real-time cycles.

> - Why would using printf and fflush make such a massive difference to
> %CPU? The application is not busy waiting or doing any CPU intensive
> work...

Which kernel version, I-pipe release and CPU architecture are you 
running on?

-- 
Philippe.

Re: [Xenomai] High CPU load using q_send under pSOS skin

[Philippe Gerum]

On 02/06/2014 06:26 PM, Philippe Gerum wrote:
> On 02/06/2014 05:25 PM, Marcel van Mierlo wrote:
>> Hi,
>>
>> I've been investigating this for a couple of days and would really
>> appreciate some insight
>> on what might be going on or what I can do to progress this...
>>
>> I am porting a legacy pSOS application - to Xenomai on BeagleBoard Black
>> 3.8 kernel
>> and have noticed %CPU (via. top) of MAIN around 40% when using q_send,
>> and doing no "work".
>>
>> Surprisingly,  if I add a printf() and fflush() to the task body then
>> the CPU drops down to < 1%.
>>
>> I've checked compile options, nothing obviously wrong. Here is the
>> (abridged) body of the task.
>> It just provides a periodic message for watchdog purposes.
>>
>>
>> [%CPU ~%40]
>> while{1}
>> {
>>      q_send(ulCanTQid, (INT32 *)&oCanMsg);
>>      tm_wkafter(100);  // ~100ms
>> }
>>
>>
>> [%CPU < %1]
>> while{1}
>> {
>>      q_send(ulCanTQid, (INT32 *)&oCanMsg);
>>      tm_wkafter(100);  // ~100ms
>>
>>      printf("WAKING");
>>      fflush(stdout);
>> }
>>
>> there is a task calling q_receive on the queue, but I have stubbed out
>> any work to keep it as simple as possible.
>>
>>
>> root@arm:~# cat /proc/xenomai/version
>> 2.6.3
>>
>> Here is xenomai/stat when running at ~40 %CPUfrom top. I presume that
>> ROOT/0 represents the
>> Xenomai/I-PIPE kernel. Nothing is reported as hogging the CPU....
>>
>> Every 2.0s: cat /proc/xenomai/stat                      Sat Jan  1
>> 00:09:03 2000
>>
>> CPU  PID    MSW        CSW        PF    STAT       %CPU  NAME
>>    0  0      0          186436     0     00500080   94.2  ROOT/0
>>    0  2882   16         427        0     00300380    0.0  MAIN
>>    0  2883   0          54128      0     00300184    1.0 onemsscheduler
>>    0  2884   0          542        0     00300184    0.0  FREE
>>    0  2885   0          1499       0     00300184    0.0  flsh
>>    0  2886   0          1          0     00300182    0.0  EWRN
>>    0  2887   0          45158      0     00300186    0.8  EEDT
>>    0  2888   0          53921      0     00300184    1.4  RESP
>>    0  2889   1          1          0     00300380    0.0  SERV
>>    0  2890   0          10784      0     00300184    0.4  CMND
>>    0  2891   2          1370       0     00300186    0.1  SERP
>>    0  2896   0          53080      0     00300184    0.8  SERO
>>    0  2899   0          536        0     00300186    0.0  CANP
>>    0  2900   0          1          0     00300182    0.0  CANG
>>    0  2901   0          1          0     00300182    0.0  CANE
>>    0  2902   0          315        0     00300182    0.0  CANT
>>    0  2903   1          1          0     00300380    0.0  CNMN
>>    0  2904   236        628        0     00300184    0.0  CIOW
>>    0  0      0          699350     0     00000000    1.0  IRQ83: [timer]
>>
>>
>> So questions are:
>>
>> - Why does the %CPU under xenomai/stat not reflect whats reported by top
>
> Because top reports the CPU consumed when Linux is active, which
> excludes Xenomai activity.
>
>> (where is the 40% going)?
>
> Good question.
>
>> - How can I track down the high CPU load?
>
> Could you obtain a report from Xenomai's rtps command? This one reports
> real-time cycles.
>
>> - Why would using printf and fflush make such a massive difference to
>> %CPU? The application is not busy waiting or doing any CPU intensive
>> work...
>
> Which kernel version, I-pipe release and CPU architecture are you
> running on?
>

Please ignore this question. I missed this info from your past mail, so 
ARM and 3.8 it seems.

-- 
Philippe.

Re: [Xenomai] High CPU load using q_send under pSOS skin

[Gilles Chanteperdrix]

On 02/06/2014 06:26 PM, Philippe Gerum wrote:
>> Every 2.0s: cat /proc/xenomai/stat                      Sat Jan  1
>> 00:09:03 2000
>>
>> CPU  PID    MSW        CSW        PF    STAT       %CPU  NAME
>>     0  0      0          186436     0     00500080   94.2  ROOT/0
>>     0  2882   16         427        0     00300380    0.0  MAIN
>>     0  2883   0          54128      0     00300184    1.0 onemsscheduler
>>     0  2884   0          542        0     00300184    0.0  FREE
>>     0  2885   0          1499       0     00300184    0.0  flsh
>>     0  2886   0          1          0     00300182    0.0  EWRN
>>     0  2887   0          45158      0     00300186    0.8  EEDT
>>     0  2888   0          53921      0     00300184    1.4  RESP
>>     0  2889   1          1          0     00300380    0.0  SERV
>>     0  2890   0          10784      0     00300184    0.4  CMND
>>     0  2891   2          1370       0     00300186    0.1  SERP
>>     0  2896   0          53080      0     00300184    0.8  SERO
>>     0  2899   0          536        0     00300186    0.0  CANP
>>     0  2900   0          1          0     00300182    0.0  CANG
>>     0  2901   0          1          0     00300182    0.0  CANE
>>     0  2902   0          315        0     00300182    0.0  CANT
>>     0  2903   1          1          0     00300380    0.0  CNMN
>>     0  2904   236        628        0     00300184    0.0  CIOW
>>     0  0      0          699350     0     00000000    1.0  IRQ83: [timer]
>>
>>
>> So questions are:
>>
>> - Why does the %CPU under xenomai/stat not reflect whats reported by top
>
> Because top reports the CPU consumed when Linux is active, which
> excludes Xenomai activity.
>
>> (where is the 40% going)?
>
> Good question.

I think we have a known issue: the registers passed to Linux timer tick 
are the ones of the last timer tick, which may very well happen to 
always hit the same task. Could this be the cause?

Is the MAIN task the one which does the tm_wkafter ?

Is the hardware timer of the beaglebone black shared with Linux (like 
omap4) or do linux and xenomai have different timers (like omap3)?

Could you arm the T_WARNSW bit to see if the MAIN task experiences mode 
switches?

-- 
					    Gilles.

Re: [Xenomai] High CPU load using q_send under pSOS skin

[Philippe Gerum]

On 02/06/2014 08:00 PM, Gilles Chanteperdrix wrote:
> On 02/06/2014 06:26 PM, Philippe Gerum wrote:
>>> Every 2.0s: cat /proc/xenomai/stat                      Sat Jan  1
>>> 00:09:03 2000
>>>
>>> CPU  PID    MSW        CSW        PF    STAT       %CPU  NAME
>>>     0  0      0          186436     0     00500080   94.2  ROOT/0
>>>     0  2882   16         427        0     00300380    0.0  MAIN
>>>     0  2883   0          54128      0     00300184    1.0 onemsscheduler
>>>     0  2884   0          542        0     00300184    0.0  FREE
>>>     0  2885   0          1499       0     00300184    0.0  flsh
>>>     0  2886   0          1          0     00300182    0.0  EWRN
>>>     0  2887   0          45158      0     00300186    0.8  EEDT
>>>     0  2888   0          53921      0     00300184    1.4  RESP
>>>     0  2889   1          1          0     00300380    0.0  SERV
>>>     0  2890   0          10784      0     00300184    0.4  CMND
>>>     0  2891   2          1370       0     00300186    0.1  SERP
>>>     0  2896   0          53080      0     00300184    0.8  SERO
>>>     0  2899   0          536        0     00300186    0.0  CANP
>>>     0  2900   0          1          0     00300182    0.0  CANG
>>>     0  2901   0          1          0     00300182    0.0  CANE
>>>     0  2902   0          315        0     00300182    0.0  CANT
>>>     0  2903   1          1          0     00300380    0.0  CNMN
>>>     0  2904   236        628        0     00300184    0.0  CIOW
>>>     0  0      0          699350     0     00000000    1.0  IRQ83:
>>> [timer]
>>>
>>>
>>> So questions are:
>>>
>>> - Why does the %CPU under xenomai/stat not reflect whats reported by top
>>
>> Because top reports the CPU consumed when Linux is active, which
>> excludes Xenomai activity.
>>
>>> (where is the 40% going)?
>>
>> Good question.
>
> I think we have a known issue: the registers passed to Linux timer tick
> are the ones of the last timer tick, which may very well happen to
> always hit the same task. Could this be the cause?
>

I checked your arm-side pipeline implementation yesterday, I believe the 
saved CPSR value does exhibit PSR_I_BIT as expected when the timer 
preempts the Xenomai domain, so there should not be any accounting issue 
(i.e. __ipipe_root_tick_p would prevent update_process_times() to charge 
the last active linux task). This said, the adverse side-effect which is 
solved by the code I just mentioned would rather happen when a Xenomai 
task does frequent relax/harden transitions, not when it runs 
exclusively in real-time mode.

> Is the MAIN task the one which does the tm_wkafter ?
>
> Is the hardware timer of the beaglebone black shared with Linux (like
> omap4) or do linux and xenomai have different timers (like omap3)?
>
> Could you arm the T_WARNSW bit to see if the MAIN task experiences mode
> switches?
>

It would also be interesting to check that commenting out q_send() still 
produces the same result.

-- 
Philippe.

Re: [Xenomai] High CPU load using q_send under pSOS skin

[Marcel van Mierlo]

On 07/02/14 08:53, Philippe Gerum wrote:
> On 02/06/2014 08:00 PM, Gilles Chanteperdrix wrote:
>> On 02/06/2014 06:26 PM, Philippe Gerum wrote:
>>>> Every 2.0s: cat /proc/xenomai/stat                      Sat Jan  1
>>>> 00:09:03 2000
>>>>
>>>> CPU  PID    MSW        CSW        PF    STAT       %CPU NAME
>>>>     0  0      0          186436     0     00500080   94.2 ROOT/0
>>>>     0  2882   16         427        0     00300380    0.0 MAIN
>>>>     0  2883   0          54128      0     00300184    1.0 
>>>> onemsscheduler
>>>>     0  2884   0          542        0     00300184    0.0 FREE
>>>>     0  2885   0          1499       0     00300184    0.0 flsh
>>>>     0  2886   0          1          0     00300182    0.0 EWRN
>>>>     0  2887   0          45158      0     00300186    0.8 EEDT
>>>>     0  2888   0          53921      0     00300184    1.4 RESP
>>>>     0  2889   1          1          0     00300380    0.0 SERV
>>>>     0  2890   0          10784      0     00300184    0.4 CMND
>>>>     0  2891   2          1370       0     00300186    0.1 SERP
>>>>     0  2896   0          53080      0     00300184    0.8 SERO
>>>>     0  2899   0          536        0     00300186    0.0 CANP
>>>>     0  2900   0          1          0     00300182    0.0 CANG
>>>>     0  2901   0          1          0     00300182    0.0 CANE
>>>>     0  2902   0          315        0     00300182    0.0 CANT
>>>>     0  2903   1          1          0     00300380    0.0 CNMN
>>>>     0  2904   236        628        0     00300184    0.0 CIOW
>>>>     0  0      0          699350     0     00000000    1.0 IRQ83:
>>>> [timer]
>>>>
>>>>
>>>> So questions are:
>>>>
>>>> - Why does the %CPU under xenomai/stat not reflect whats reported 
>>>> by top
>>>
>>> Because top reports the CPU consumed when Linux is active, which
>>> excludes Xenomai activity.
>>>
>>>> (where is the 40% going)?
>>>
>>> Good question.
>>
>> I think we have a known issue: the registers passed to Linux timer tick
>> are the ones of the last timer tick, which may very well happen to
>> always hit the same task. Could this be the cause?
>>
>
> I checked your arm-side pipeline implementation yesterday, I believe 
> the saved CPSR value does exhibit PSR_I_BIT as expected when the timer 
> preempts the Xenomai domain, so there should not be any accounting 
> issue (i.e. __ipipe_root_tick_p would prevent update_process_times() 
> to charge the last active linux task). This said, the adverse 
> side-effect which is solved by the code I just mentioned would rather 
> happen when a Xenomai task does frequent relax/harden transitions, not 
> when it runs exclusively in real-time mode.
>
>> Is the MAIN task the one which does the tm_wkafter ?
>>
>> Is the hardware timer of the beaglebone black shared with Linux (like
>> omap4) or do linux and xenomai have different timers (like omap3)?
>>
>> Could you arm the T_WARNSW bit to see if the MAIN task experiences mode
>> switches?
>>
>
> It would also be interesting to check that commenting out q_send() 
> still produces the same result.
>

- When I set top to show threads I see "CIOW" taking up the CPU.
     - This is the pSOS task which invokes q_send, as per the sample code.
     - If I understand correctly
         - xenomai/stat confirms this task is not using much CPU time in 
Xenomai domain
         - top tells me the time is being taken up in Linux domain.
         *** Why would q_send/tm_wkafter be in linux domain?

- I cannot reproduce the problem when I comment out q_send()
     *** q_send appears to trigger the high %CPU.

- MSW increases by ~5 every seconds under xenomai/stat for CIOW.
     - It is the only task with increasing MSW.
     - This happens whether or not I am printing to screen...so when I 
sit in a tight loop calling only q_send and tm_wakeafter, MSW still 
increases. I dont understand this.
     - When I comment out q_send (so only call tm_wakeafter) MSW does 
not increase and stays on zero.
     *** Why does q_send cause mode switches?

- I cant see how to set T_WARNSW using the pSOS skin.
     - I get warning that "T_FPU" redefined when including native/task.h 
and psos+/psos.h
     - If I hack the mask by using "0x00040000" explicitly I get 
SIGXCPU: CPU time limit exceeded when calling rt_task_set_mode at runtime.
     - But I think xenomai/stat gives the required information anyway, 
right?

- When the high CPU load is reported the system exhibits poor 
responsiveness in a separate interactive shell - indicating this is not 
only an accounting anomaly(?)

- rtps after one minute with high CPU load:

PID    TIME                THREAD                   CMD

0      000:41:02.977,660   ROOT/0                   -
2675   000:00:00.037,676   MAIN                     .
2679   000:00:00.654,322   onemsscheduler           .
2680   000:00:00.013,614   flsh                     .
2681   000:00:00.000,046   EWRN                     .
2682   000:00:00.248,698   EEDT                     .
2683   000:00:00.779,498   RESP                     .
2684   000:00:00.000,049   SERV                     .
2685   000:00:00.177,563   CMND                     .
2692   000:00:00.071,832   SERP                     .
2699   000:00:00.410,424   SERO                     .
2703   000:00:00.015,994   CANP                     .
2704   000:00:00.000,041   CANG                     .
2705   000:00:00.000,021   CANE                     .
2706   000:00:00.005,955   CANT                     .
2707   000:00:00.000,023   CNMN                     .
2708   000:00:00.012,894   CIOW                     .
0      000:00:15.380,873   IRQ83: [timer]           -


- rtps after one minute low CPU load:

PID    TIME                THREAD                   CMD

0      000:44:27.327,181   ROOT/0                   -
3248   000:00:00.038,278   MAIN                     .
3252   000:00:00.679,777   onemsscheduler           .
3253   000:00:00.014,136   flsh                     .
3254   000:00:00.000,048   EWRN                     .
3255   000:00:00.249,896   EEDT                     .
3256   000:00:00.822,868   RESP                     .
3257   000:00:00.000,052   SERV                     .
3258   000:00:00.183,185   CMND                     .
3265   000:00:00.072,530   SERP                     .
3272   000:00:00.423,205   SERO                     .
3276   000:00:00.024,839   CANP                     .
3277   000:00:00.000,055   CANG                     .
3278   000:00:00.000,022   CANE                     .
3279   000:00:00.010,050   CANT                     .
3280   000:00:00.000,023   CNMN                     .
3281   000:00:00.023,130   CIOW                     .
0      000:00:17.034,773   IRQ83: [timer]           -

-    CIOW and CANT are ~double...these are the sender and listener tasks 
on the q.
-    I added further tracing.
     -    with low %CPU 100 messages are sent & received every 10s as 
expected
     -    with high %CPU (no printf/fflush in CIOW) then 100 messages 
are sent and received every ~17s

*** It seems high %CPU severely impacts time taken to post messages.

I added further tracing around q_send.
/High %CPU:
q_send: 93.687ms,
tm_wkafter: 99.360ms
total: 193.055ms

Low %CPU:
/////q_send/: 0.068ms///
tm_wkafter:/ 99.665ms
total: 99.737ms
/
- Why is printf/fflush impacting time taken to invoke q_send?


I'll implement a simple test harness to try and further isolate this 
behaviour...of course any input greatly appreciated!



Marcel.

Re: [Xenomai] High CPU load using q_send under pSOS skin

[Philippe Gerum]

On 02/07/2014 02:32 PM, Marcel van Mierlo wrote:
> - I cant see how to set T_WARNSW using the pSOS skin.
>      - I get warning that "T_FPU" redefined when including native/task.h
> and psos+/psos.h
>      - If I hack the mask by using "0x00040000" explicitly I get
> SIGXCPU: CPU time limit exceeded when calling rt_task_set_mode at runtime.

At first sight, qsend() in your test case seems to trigger a migration 
to linux mode, that might explain (part of) the overhead. Use t_mode(0, 
T_TRAPSW, &oldmode) to enable SIGXCPU.

-- 
Philippe.

Re: [Xenomai] High CPU load using q_send under pSOS skin

[Philippe Gerum]

On 02/07/2014 02:32 PM, Marcel van Mierlo wrote:

> - Why is printf/fflush impacting time taken to invoke q_send?
>

Depending on how you measure this, but since printf/fflush will turn 
your thread to secondary mode, qsend() won't be charged for the same 
transition it (unexpectedly) requires since your thread will be in that 
mode already.

-- 
Philippe.

Re: [Xenomai] High CPU load using q_send under pSOS skin

[Philippe Gerum]

On 02/07/2014 02:32 PM, Marcel van Mierlo wrote:

>      - When I comment out q_send (so only call tm_wakeafter) MSW does
> not increase and stays on zero.
>      *** Why does q_send cause mode switches?

Where do the data words passed to qsend() come from? Plain regular memory?

Also, what does /proc/xenomai/faults show after runtime?

-- 
Philippe.

Re: [Xenomai] High CPU load using q_send under pSOS skin

[Marcel van Mierlo]

On 07/02/14 14:06, Philippe Gerum wrote:
> On 02/07/2014 02:32 PM, Marcel van Mierlo wrote:
>
>>      - When I comment out q_send (so only call tm_wakeafter) MSW does
>> not increase and stays on zero.
>>      *** Why does q_send cause mode switches?
>
> Where do the data words passed to qsend() come from? Plain regular 
> memory?
>
> Also, what does /proc/xenomai/faults show after runtime?
>

The data words are created on the task stack (struct instance created as 
automatic variable on stack)

I see increasing TRAP 8 (Unaligned access exception) when application is 
running.

TRAP         CPU0
   0:          732    (Data or instruction access)
   1:            0    (Section fault)
   2:            0    (Generic data abort)
   3:            0    (Unknown exception)
   4:            0    (Instruction breakpoint)
   5:            0    (Floating point exception)
   6:            0    (VFP Floating point exception)
   7:            3    (Undefined instruction)
   8:        10067    (Unaligned access exception)

If I comment out q_send TRAP 8 dosent occur. If I pass NULL as data 
words to q_send, TRAP 8 stops... and %CPU remains low....hmmm do I need 
to ensure stack alignment somehow?

Marcel.

Re: [Xenomai] High CPU load using q_send under pSOS skin

[Gilles Chanteperdrix]

On 02/07/2014 03:32 PM, Marcel van Mierlo wrote:
> If I comment out q_send TRAP 8 dosent occur. If I pass NULL as data
> words to q_send, TRAP 8 stops... and %CPU remains low....hmmm do I need
> to ensure stack alignment somehow?

The stack alignment is ensured by the compiler. Starting with ARM EABI, 
the stack is aligned on 8 bytes, so, if you do not use special tricks 
(like casting a char * pointer to a u_long *pointer, or using 
__attribute__((packed))), everything should be aligned properly. Could 
you show us the declaration of the buffer passed to q_send ? In fact, 
posting a self-contained, minimal example allowing to reproduce the 
problem would help.

-- 
					    Gilles.

Re: [Xenomai] High CPU load using q_send under pSOS skin

[Marcel van Mierlo]

On 07/02/14 14:38, Gilles Chanteperdrix wrote:
> On 02/07/2014 03:32 PM, Marcel van Mierlo wrote:
>> If I comment out q_send TRAP 8 dosent occur. If I pass NULL as data
>> words to q_send, TRAP 8 stops... and %CPU remains low....hmmm do I need
>> to ensure stack alignment somehow?
>
> The stack alignment is ensured by the compiler. Starting with ARM 
> EABI, the stack is aligned on 8 bytes, so, if you do not use special 
> tricks (like casting a char * pointer to a u_long *pointer, or using 
> __attribute__((packed))), everything should be aligned properly. Could 
> you show us the declaration of the buffer passed to q_send ? In fact, 
> posting a self-contained, minimal example allowing to reproduce the 
> problem would help.
>

I will put together a self-contained minimal example (might be next 
week), but here is a complete working task function which exhibits high 
CPU. MSW still increases if I pass NULL but no messages are received....

Marcel.


TASK cio_watchdog_kick(void)
{
     u_long cantmsg[4];
     UL ulCanTQid;

     if (q_ident("cant", 0, (INT32 *)&ulCanTQid) != 0)
     {
         t_suspend(0);
     }

     while(1)
     {
         q_send(ulCanTQid, cantmsg);
         //q_send(ulCanTQid, NULL);
         tm_wkafter(100);
     }
}

LOCAL UL start_cio_watchdog_kick(void)
{
     UL ulRetval;
     UL ulTid;


     if ((ulRetval = t_create(   "CIOW",
                                 150,
                                 512,
                                 512,
                                 T_LOCAL,
                                 (INT32 *)&ulTid)) != 0)
     {
         return ulRetval;
     }

     if ((ulRetval = t_start( ulTid,
                             T_PREEMPT,
                             (void*)cio_watchdog_kick, 0)) != 0)
     {
         return ulRetval;
     }

     return 0;
}

Re: [Xenomai] High CPU load using q_send under pSOS skin

[Gilles Chanteperdrix]

On 02/07/2014 04:07 PM, Marcel van Mierlo wrote:
> TASK cio_watchdog_kick(void)
> {
>       u_long cantmsg[4];

This one should be properly aligned, what about the buffer you use for 
q_recv?


-- 
					    Gilles.

Re: [Xenomai] High CPU load using q_send under pSOS skin

[Marcel van Mierlo]

On 07/02/14 15:10, Gilles Chanteperdrix wrote:
> On 02/07/2014 04:07 PM, Marcel van Mierlo wrote:
>> TASK cio_watchdog_kick(void)
>> {
>>       u_long cantmsg[4];
>
> This one should be properly aligned, what about the buffer you use for 
> q_recv?
>
>
Hmmm, again, created on the stack. Here is the code for task function 
which invokes q_recv. Will put together a self-contained example.

static int can_transmitter()
{
     u_long tmpmsg[4];
     int count;
     u_long cant_qid;

     while(1)
     {
         if (q_ident("cant", 0, &cant_qid) == 0)
             break;
         tm_wkafter(10);
     }

     while(1)
     {
         if (q_receive(cant_qid, Q_WAIT, Q_WAIT_FOREVER, tmpmsg) == 0)
         {
             count++;
             if ((count % 100) == 0)
             {
                 printf("RECEIVED 100 messages\n");
                 fflush(stdout);
             }
         }
     }
}

Re: [Xenomai] High CPU load using q_send under pSOS skin

[Gilles Chanteperdrix]

On 02/07/2014 04:22 PM, Marcel van Mierlo wrote:
>
> On 07/02/14 15:10, Gilles Chanteperdrix wrote:
>> On 02/07/2014 04:07 PM, Marcel van Mierlo wrote:
>>> TASK cio_watchdog_kick(void)
>>> {
>>>        u_long cantmsg[4];
>>
>> This one should be properly aligned, what about the buffer you use for
>> q_recv?
>>
>>
> Hmmm, again, created on the stack. Here is the code for task function
> which invokes q_recv. Will put together a self-contained example.

It probably means that the unaligned access happens in kernel-space. 
What version of gcc are you using?

-- 
					    Gilles.

Re: [Xenomai] High CPU load using q_send under pSOS skin

[Gilles Chanteperdrix]

On 02/07/2014 02:32 PM, Marcel van Mierlo wrote:
> - I cant see how to set T_WARNSW using the pSOS skin.
>      - I get warning that "T_FPU" redefined when including native/task.h
> and psos+/psos.h
>      - If I hack the mask by using "0x00040000" explicitly I get
> SIGXCPU: CPU time limit exceeded when calling rt_task_set_mode at runtime.

The SIGXCPU is the indication that the problem occurs. You can:
- catch it with gdbserver/gdb and show us the result of the "backtrace" 
command;
- use glibc backtrace functionality to show the point where the problem 
happens as is demonstrated in examples/native/sigdebug.c

-- 
					    Gilles.