* [Xenomai] High CPU load using q_send under pSOS skin
@ 2014-02-06 16:25 Marcel van Mierlo
2014-02-06 16:35 ` Gilles Chanteperdrix
2014-02-06 17:26 ` Philippe Gerum
0 siblings, 2 replies; 18+ messages in thread
From: Marcel van Mierlo @ 2014-02-06 16:25 UTC (permalink / raw)
To: xenomai
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.
^ permalink raw reply [flat|nested] 18+ messages in thread
* Re: [Xenomai] High CPU load using q_send under pSOS skin
2014-02-06 16:25 [Xenomai] High CPU load using q_send under pSOS skin Marcel van Mierlo
@ 2014-02-06 16:35 ` Gilles Chanteperdrix
2014-02-06 16:57 ` Marcel van Mierlo
2014-02-06 17:26 ` Philippe Gerum
1 sibling, 1 reply; 18+ messages in thread
From: Gilles Chanteperdrix @ 2014-02-06 16:35 UTC (permalink / raw)
To: Marcel van Mierlo; +Cc: xenomai
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.
^ permalink raw reply [flat|nested] 18+ messages in thread
* Re: [Xenomai] High CPU load using q_send under pSOS skin
2014-02-06 16:35 ` Gilles Chanteperdrix
@ 2014-02-06 16:57 ` Marcel van Mierlo
0 siblings, 0 replies; 18+ messages in thread
From: Marcel van Mierlo @ 2014-02-06 16:57 UTC (permalink / raw)
To: Gilles Chanteperdrix; +Cc: xenomai
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 ?
>
^ permalink raw reply [flat|nested] 18+ messages in thread
* Re: [Xenomai] High CPU load using q_send under pSOS skin
2014-02-06 16:25 [Xenomai] High CPU load using q_send under pSOS skin Marcel van Mierlo
2014-02-06 16:35 ` Gilles Chanteperdrix
@ 2014-02-06 17:26 ` Philippe Gerum
2014-02-06 17:28 ` Philippe Gerum
2014-02-06 19:00 ` Gilles Chanteperdrix
1 sibling, 2 replies; 18+ messages in thread
From: Philippe Gerum @ 2014-02-06 17:26 UTC (permalink / raw)
To: Marcel van Mierlo, xenomai
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.
^ permalink raw reply [flat|nested] 18+ messages in thread
* Re: [Xenomai] High CPU load using q_send under pSOS skin
2014-02-06 17:26 ` Philippe Gerum
@ 2014-02-06 17:28 ` Philippe Gerum
2014-02-06 19:00 ` Gilles Chanteperdrix
1 sibling, 0 replies; 18+ messages in thread
From: Philippe Gerum @ 2014-02-06 17:28 UTC (permalink / raw)
To: Marcel van Mierlo, xenomai
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.
^ permalink raw reply [flat|nested] 18+ messages in thread
* Re: [Xenomai] High CPU load using q_send under pSOS skin
2014-02-06 17:26 ` Philippe Gerum
2014-02-06 17:28 ` Philippe Gerum
@ 2014-02-06 19:00 ` Gilles Chanteperdrix
2014-02-07 8:53 ` Philippe Gerum
1 sibling, 1 reply; 18+ messages in thread
From: Gilles Chanteperdrix @ 2014-02-06 19:00 UTC (permalink / raw)
To: Philippe Gerum; +Cc: xenomai
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.
^ permalink raw reply [flat|nested] 18+ messages in thread
* Re: [Xenomai] High CPU load using q_send under pSOS skin
2014-02-06 19:00 ` Gilles Chanteperdrix
@ 2014-02-07 8:53 ` Philippe Gerum
2014-02-07 13:32 ` Marcel van Mierlo
0 siblings, 1 reply; 18+ messages in thread
From: Philippe Gerum @ 2014-02-07 8:53 UTC (permalink / raw)
To: Gilles Chanteperdrix; +Cc: xenomai
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.
^ permalink raw reply [flat|nested] 18+ messages in thread
* Re: [Xenomai] High CPU load using q_send under pSOS skin
2014-02-07 8:53 ` Philippe Gerum
@ 2014-02-07 13:32 ` Marcel van Mierlo
2014-02-07 13:57 ` Philippe Gerum
` (3 more replies)
0 siblings, 4 replies; 18+ messages in thread
From: Marcel van Mierlo @ 2014-02-07 13:32 UTC (permalink / raw)
To: Philippe Gerum, Gilles Chanteperdrix; +Cc: xenomai
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.
^ permalink raw reply [flat|nested] 18+ messages in thread
* Re: [Xenomai] High CPU load using q_send under pSOS skin
2014-02-07 13:32 ` Marcel van Mierlo
@ 2014-02-07 13:57 ` Philippe Gerum
2014-02-07 14:03 ` Philippe Gerum
` (2 subsequent siblings)
3 siblings, 0 replies; 18+ messages in thread
From: Philippe Gerum @ 2014-02-07 13:57 UTC (permalink / raw)
To: Marcel van Mierlo, Gilles Chanteperdrix; +Cc: xenomai
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.
^ permalink raw reply [flat|nested] 18+ messages in thread
* Re: [Xenomai] High CPU load using q_send under pSOS skin
2014-02-07 13:32 ` Marcel van Mierlo
2014-02-07 13:57 ` Philippe Gerum
@ 2014-02-07 14:03 ` Philippe Gerum
2014-02-07 14:06 ` Philippe Gerum
2014-02-07 14:08 ` Gilles Chanteperdrix
3 siblings, 0 replies; 18+ messages in thread
From: Philippe Gerum @ 2014-02-07 14:03 UTC (permalink / raw)
To: Marcel van Mierlo, Gilles Chanteperdrix; +Cc: xenomai
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.
^ permalink raw reply [flat|nested] 18+ messages in thread
* Re: [Xenomai] High CPU load using q_send under pSOS skin
2014-02-07 13:32 ` Marcel van Mierlo
2014-02-07 13:57 ` Philippe Gerum
2014-02-07 14:03 ` Philippe Gerum
@ 2014-02-07 14:06 ` Philippe Gerum
2014-02-07 14:32 ` Marcel van Mierlo
2014-02-07 14:08 ` Gilles Chanteperdrix
3 siblings, 1 reply; 18+ messages in thread
From: Philippe Gerum @ 2014-02-07 14:06 UTC (permalink / raw)
To: Marcel van Mierlo, Gilles Chanteperdrix; +Cc: xenomai
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.
^ permalink raw reply [flat|nested] 18+ messages in thread
* Re: [Xenomai] High CPU load using q_send under pSOS skin
2014-02-07 13:32 ` Marcel van Mierlo
` (2 preceding siblings ...)
2014-02-07 14:06 ` Philippe Gerum
@ 2014-02-07 14:08 ` Gilles Chanteperdrix
3 siblings, 0 replies; 18+ messages in thread
From: Gilles Chanteperdrix @ 2014-02-07 14:08 UTC (permalink / raw)
To: Marcel van Mierlo; +Cc: xenomai
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.
^ permalink raw reply [flat|nested] 18+ messages in thread
* Re: [Xenomai] High CPU load using q_send under pSOS skin
2014-02-07 14:06 ` Philippe Gerum
@ 2014-02-07 14:32 ` Marcel van Mierlo
2014-02-07 14:38 ` Gilles Chanteperdrix
0 siblings, 1 reply; 18+ messages in thread
From: Marcel van Mierlo @ 2014-02-07 14:32 UTC (permalink / raw)
To: Philippe Gerum, Gilles Chanteperdrix; +Cc: xenomai
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.
^ permalink raw reply [flat|nested] 18+ messages in thread
* Re: [Xenomai] High CPU load using q_send under pSOS skin
2014-02-07 14:32 ` Marcel van Mierlo
@ 2014-02-07 14:38 ` Gilles Chanteperdrix
2014-02-07 15:07 ` Marcel van Mierlo
0 siblings, 1 reply; 18+ messages in thread
From: Gilles Chanteperdrix @ 2014-02-07 14:38 UTC (permalink / raw)
To: Marcel van Mierlo; +Cc: xenomai
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.
^ permalink raw reply [flat|nested] 18+ messages in thread
* Re: [Xenomai] High CPU load using q_send under pSOS skin
2014-02-07 14:38 ` Gilles Chanteperdrix
@ 2014-02-07 15:07 ` Marcel van Mierlo
2014-02-07 15:10 ` Gilles Chanteperdrix
0 siblings, 1 reply; 18+ messages in thread
From: Marcel van Mierlo @ 2014-02-07 15:07 UTC (permalink / raw)
To: Gilles Chanteperdrix; +Cc: xenomai
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;
}
^ permalink raw reply [flat|nested] 18+ messages in thread
* Re: [Xenomai] High CPU load using q_send under pSOS skin
2014-02-07 15:07 ` Marcel van Mierlo
@ 2014-02-07 15:10 ` Gilles Chanteperdrix
2014-02-07 15:22 ` Marcel van Mierlo
0 siblings, 1 reply; 18+ messages in thread
From: Gilles Chanteperdrix @ 2014-02-07 15:10 UTC (permalink / raw)
To: Marcel van Mierlo; +Cc: xenomai
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.
^ permalink raw reply [flat|nested] 18+ messages in thread
* Re: [Xenomai] High CPU load using q_send under pSOS skin
2014-02-07 15:10 ` Gilles Chanteperdrix
@ 2014-02-07 15:22 ` Marcel van Mierlo
2014-02-07 19:23 ` Gilles Chanteperdrix
0 siblings, 1 reply; 18+ messages in thread
From: Marcel van Mierlo @ 2014-02-07 15:22 UTC (permalink / raw)
To: Gilles Chanteperdrix; +Cc: xenomai
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);
}
}
}
}
^ permalink raw reply [flat|nested] 18+ messages in thread
* Re: [Xenomai] High CPU load using q_send under pSOS skin
2014-02-07 15:22 ` Marcel van Mierlo
@ 2014-02-07 19:23 ` Gilles Chanteperdrix
0 siblings, 0 replies; 18+ messages in thread
From: Gilles Chanteperdrix @ 2014-02-07 19:23 UTC (permalink / raw)
To: Marcel van Mierlo; +Cc: xenomai
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.
^ permalink raw reply [flat|nested] 18+ messages in thread
end of thread, other threads:[~2014-02-07 19:23 UTC | newest]
Thread overview: 18+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2014-02-06 16:25 [Xenomai] High CPU load using q_send under pSOS skin Marcel van Mierlo
2014-02-06 16:35 ` Gilles Chanteperdrix
2014-02-06 16:57 ` Marcel van Mierlo
2014-02-06 17:26 ` Philippe Gerum
2014-02-06 17:28 ` Philippe Gerum
2014-02-06 19:00 ` Gilles Chanteperdrix
2014-02-07 8:53 ` Philippe Gerum
2014-02-07 13:32 ` Marcel van Mierlo
2014-02-07 13:57 ` Philippe Gerum
2014-02-07 14:03 ` Philippe Gerum
2014-02-07 14:06 ` Philippe Gerum
2014-02-07 14:32 ` Marcel van Mierlo
2014-02-07 14:38 ` Gilles Chanteperdrix
2014-02-07 15:07 ` Marcel van Mierlo
2014-02-07 15:10 ` Gilles Chanteperdrix
2014-02-07 15:22 ` Marcel van Mierlo
2014-02-07 19:23 ` Gilles Chanteperdrix
2014-02-07 14:08 ` Gilles Chanteperdrix
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.