[Xenomai] rtdm_nrtsig_pend FAQ

[Xenomai] rtdm_nrtsig_pend FAQ

[Johann Obermayr]

Hello,

we use rtdm_nrtsig_pend follow.

static rtdm_nrtsig_t wait_domain_nrt;
static DECLARE_WAIT_QUEUE_HEAD(wait_domain_wq);

void period_update()
{
         wait_domain_pend_count++;
         rtdm_nrtsig_pend(&wait_domain_nrt);
}

static void wait_domain_nrt_handler(rtdm_nrtsig_t nrt_sig, void *arg)
{
     wait_domain_call_count++;
     //wakeup wait_domain
     wait_domain_wakeup = 1;
     wake_up_interruptible(&wait_domain_wq);
}


period_update is called every millisecond.
this is on imx6 hardware with kernel 3.0.x and xenomai 2.6.2.1.

Why wait_domain_call_count can be smaller that wait_domain_pend_count.
The difference between the counters is growing.

Why ?

Best Regards
   Johann

Re: [Xenomai] rtdm_nrtsig_pend FAQ

[Philippe Gerum]

On 11/12/2014 09:47 AM, Johann Obermayr wrote:
> Hello,
> 
> we use rtdm_nrtsig_pend follow.
> 
> static rtdm_nrtsig_t wait_domain_nrt;
> static DECLARE_WAIT_QUEUE_HEAD(wait_domain_wq);
> 
> void period_update()
> {
>         wait_domain_pend_count++;
>         rtdm_nrtsig_pend(&wait_domain_nrt);
> }
> 
> static void wait_domain_nrt_handler(rtdm_nrtsig_t nrt_sig, void *arg)
> {
>     wait_domain_call_count++;
>     //wakeup wait_domain
>     wait_domain_wakeup = 1;
>     wake_up_interruptible(&wait_domain_wq);
> }
> 
> 
> period_update is called every millisecond.
> this is on imx6 hardware with kernel 3.0.x and xenomai 2.6.2.1.
> 
> Why wait_domain_call_count can be smaller that wait_domain_pend_count.
> The difference between the counters is growing.
> 
> Why ?
> 

nrt signals are based on I-pipe virtual irqs, which do not pile up:
there is a single signal pending until the irq can be delivered to the
handler, regardless of how many times it has been triggered.

-- 
Philippe.

Re: [Xenomai] rtdm_nrtsig_pend FAQ

[Johann Obermayr]

Am 12.11.2014 um 10:10 schrieb Philippe Gerum:
> nrt signals are based on I-pipe virtual irqs, which do not pile up:
> there is a single signal pending until the irq can be delivered to the
> handler, regardless of how many times it has been triggered.
i know, if there is a big cpu load some virtual irqs can be lost, but we 
have cpu load smaller that 10 percent.

Re: [Xenomai] rtdm_nrtsig_pend FAQ

[Philippe Gerum]

On 11/12/2014 10:20 AM, Johann Obermayr wrote:
> Am 12.11.2014 um 10:10 schrieb Philippe Gerum:
>> nrt signals are based on I-pipe virtual irqs, which do not pile up:
>> there is a single signal pending until the irq can be delivered to the
>> handler, regardless of how many times it has been triggered.
> i know, if there is a big cpu load some virtual irqs can be lost, but we
> have cpu load smaller that 10 percent.
> 

Did you try running vmstat with a one second delay while your
application runs?

-- 
Philippe.

Re: [Xenomai] rtdm_nrtsig_pend FAQ

[Johann Obermayr]

Am 12.11.2014 um 10:50 schrieb Philippe Gerum:
> On 11/12/2014 10:20 AM, Johann Obermayr wrote:
>> Am 12.11.2014 um 10:10 schrieb Philippe Gerum:
>>> nrt signals are based on I-pipe virtual irqs, which do not pile up:
>>> there is a single signal pending until the irq can be delivered to the
>>> handler, regardless of how many times it has been triggered.
>> i know, if there is a big cpu load some virtual irqs can be lost, but we
>> have cpu load smaller that 10 percent.
>>
> Did you try running vmstat with a one second delay while your
> application runs?
>
vmstat is not running.
we have a own proc_create("company/lrtdrv_timing", 0, NULL, &proc_fops); 
to show
the counters.

Re: [Xenomai] rtdm_nrtsig_pend FAQ

[Philippe Gerum]

On 11/12/2014 11:53 AM, Johann Obermayr wrote:
> Am 12.11.2014 um 10:50 schrieb Philippe Gerum:
>> On 11/12/2014 10:20 AM, Johann Obermayr wrote:
>>> Am 12.11.2014 um 10:10 schrieb Philippe Gerum:
>>>> nrt signals are based on I-pipe virtual irqs, which do not pile up:
>>>> there is a single signal pending until the irq can be delivered to the
>>>> handler, regardless of how many times it has been triggered.
>>> i know, if there is a big cpu load some virtual irqs can be lost, but we
>>> have cpu load smaller that 10 percent.
>>>
>> Did you try running vmstat with a one second delay while your
>> application runs?
>>
> vmstat is not running.
> we have a own proc_create("company/lrtdrv_timing", 0, NULL, &proc_fops);
> to show
> the counters.
> 
> 

I mean that relying on the load average won't get you much information
about potential high load spikes occurring regularly, but on large
intervals. Since your reasoning seems to be based on the load average
for assuming that virqs might be lost, I would recommend to check this
assumption first. Analyzing a vmstat log would give you a finer information.

Bottom line is that either the regular kernel is starved from IRQs long
enough to make a sequence of several virq triggers appear as a single
shot, or some virqs get lost in space.

Since virqs on the root domain are no different from regular linux IRQs
with respect to the way the pipeline handles them, option #2 would also
mean that device IRQs could be lost the same way, which is not the most
likely outcome. FWIW, a quick look at the legacy pipeline code for
kernel 3.0 did not reveal any arm-specific issue that might cause a virq
trigger to be lost.

Typically, I would inspect the system status when
(wait_domain_pend_count - wait_domain_call_count) >= 1, on entry to
period_update(). For this you can trigger a pipeline trace with a
backlog large enough to find out what the regular kernel was doing prior
to being preempted by the rt activity which called period_update().

-- 
Philippe.

Re: [Xenomai] rtdm_nrtsig_pend FAQ

[Gilles Chanteperdrix]

On Wed, Nov 12, 2014 at 09:47:45AM +0100, Johann Obermayr wrote:
> Hello,
> 
> we use rtdm_nrtsig_pend follow.
> 
> static rtdm_nrtsig_t wait_domain_nrt;
> static DECLARE_WAIT_QUEUE_HEAD(wait_domain_wq);
> 
> void period_update()
> {
>         wait_domain_pend_count++;
>         rtdm_nrtsig_pend(&wait_domain_nrt);
> }
> 
> static void wait_domain_nrt_handler(rtdm_nrtsig_t nrt_sig, void *arg)
> {
>     wait_domain_call_count++;
>     //wakeup wait_domain
>     wait_domain_wakeup = 1;
>     wake_up_interruptible(&wait_domain_wq);
> }
> 
> 
> period_update is called every millisecond.
> this is on imx6 hardware with kernel 3.0.x and xenomai 2.6.2.1.

>From what Thierry said, I suspect the patch for this kernel has a
missing call to irq_exit. So, I would ask you to do the same as
Thierry, please enable the I-pipe tracer, set a sufficient number of
back trace points such as 10000, and trigger a trace when you detect
that you have "lost" a notification (wait_dommain_pend_count > wait_domain_call_count + 1)

Then send the trace to the mailing list.

-- 
					    Gilles.

Re: [Xenomai] rtdm_nrtsig_pend FAQ

[Johann Obermayr]

Am 12.11.2014 um 17:44 schrieb Gilles Chanteperdrix:
> On Wed, Nov 12, 2014 at 09:47:45AM +0100, Johann Obermayr wrote:
>> Hello,
>>
>> we use rtdm_nrtsig_pend follow.
>>
>> static rtdm_nrtsig_t wait_domain_nrt;
>> static DECLARE_WAIT_QUEUE_HEAD(wait_domain_wq);
>>
>> void period_update()
>> {
>>          wait_domain_pend_count++;
>>          rtdm_nrtsig_pend(&wait_domain_nrt);
>> }
>>
>> static void wait_domain_nrt_handler(rtdm_nrtsig_t nrt_sig, void *arg)
>> {
>>      wait_domain_call_count++;
>>      //wakeup wait_domain
>>      wait_domain_wakeup = 1;
>>      wake_up_interruptible(&wait_domain_wq);
>> }
>>
>>
>> period_update is called every millisecond.
>> this is on imx6 hardware with kernel 3.0.x and xenomai 2.6.2.1.
> >From what Thierry said, I suspect the patch for this kernel has a
> missing call to irq_exit. So, I would ask you to do the same as
> Thierry, please enable the I-pipe tracer, set a sufficient number of
> back trace points such as 10000, and trigger a trace when you detect
> that you have "lost" a notification (wait_dommain_pend_count > wait_domain_call_count + 1)
>
> Then send the trace to the mailing list.
>
Hi,

witch function i must use to make a i-pipe trace ?
here i am in a xenomai irq handle

void period_update()
{
     ......
     else if (wait_domain_pend_count > 100000 && wait_domain_pend_count 
!= wait_domain_call_count) {
             // dotrace

      }
}

Thanks for help
  Johann

Re: [Xenomai] rtdm_nrtsig_pend FAQ

[Gilles Chanteperdrix]

On Thu, Nov 13, 2014 at 05:30:34PM +0100, Johann Obermayr wrote:
> Am 12.11.2014 um 17:44 schrieb Gilles Chanteperdrix:
> >On Wed, Nov 12, 2014 at 09:47:45AM +0100, Johann Obermayr wrote:
> >>Hello,
> >>
> >>we use rtdm_nrtsig_pend follow.
> >>
> >>static rtdm_nrtsig_t wait_domain_nrt;
> >>static DECLARE_WAIT_QUEUE_HEAD(wait_domain_wq);
> >>
> >>void period_update()
> >>{
> >>         wait_domain_pend_count++;
> >>         rtdm_nrtsig_pend(&wait_domain_nrt);
> >>}
> >>
> >>static void wait_domain_nrt_handler(rtdm_nrtsig_t nrt_sig, void *arg)
> >>{
> >>     wait_domain_call_count++;
> >>     //wakeup wait_domain
> >>     wait_domain_wakeup = 1;
> >>     wake_up_interruptible(&wait_domain_wq);
> >>}
> >>
> >>
> >>period_update is called every millisecond.
> >>this is on imx6 hardware with kernel 3.0.x and xenomai 2.6.2.1.
> >>From what Thierry said, I suspect the patch for this kernel has a
> >missing call to irq_exit. So, I would ask you to do the same as
> >Thierry, please enable the I-pipe tracer, set a sufficient number of
> >back trace points such as 10000, and trigger a trace when you detect
> >that you have "lost" a notification (wait_dommain_pend_count > wait_domain_call_count + 1)
> >
> >Then send the trace to the mailing list.
> >
> Hi,
> 
> witch function i must use to make a i-pipe trace ?
> here i am in a xenomai irq handle
> 
> void period_update()
> {
>     ......
>     else if (wait_domain_pend_count > 100000 &&
> wait_domain_pend_count != wait_domain_call_count) {
>             // dotrace
> 
>      }
> }

ipipe_trace_freeze. Requires a numeric argument, which has no
particular meaning, it just gets printed in the trace.

The I-pipe tracer is documented here:
http://xenomai.org/2014/06/using-the-i-pipe-tracer/

-- 
					    Gilles.

Re: [Xenomai] rtdm_nrtsig_pend FAQ

[Johann Obermayr]

Am 13.11.2014 um 17:33 schrieb Gilles Chanteperdrix:
> On Thu, Nov 13, 2014 at 05:30:34PM +0100, Johann Obermayr wrote:
>> Am 12.11.2014 um 17:44 schrieb Gilles Chanteperdrix:
>>> On Wed, Nov 12, 2014 at 09:47:45AM +0100, Johann Obermayr wrote:
>>>> Hello,
>>>>
>>>> we use rtdm_nrtsig_pend follow.
>>>>
>>>> static rtdm_nrtsig_t wait_domain_nrt;
>>>> static DECLARE_WAIT_QUEUE_HEAD(wait_domain_wq);
>>>>
>>>> void period_update()
>>>> {
>>>>          wait_domain_pend_count++;
>>>>          rtdm_nrtsig_pend(&wait_domain_nrt);
>>>> }
>>>>
>>>> static void wait_domain_nrt_handler(rtdm_nrtsig_t nrt_sig, void *arg)
>>>> {
>>>>      wait_domain_call_count++;
>>>>      //wakeup wait_domain
>>>>      wait_domain_wakeup = 1;
>>>>      wake_up_interruptible(&wait_domain_wq);
>>>> }
>>>>
>>>>
>>>> period_update is called every millisecond.
>>>> this is on imx6 hardware with kernel 3.0.x and xenomai 2.6.2.1.
>>> >From what Thierry said, I suspect the patch for this kernel has a
>>> missing call to irq_exit. So, I would ask you to do the same as
>>> Thierry, please enable the I-pipe tracer, set a sufficient number of
>>> back trace points such as 10000, and trigger a trace when you detect
>>> that you have "lost" a notification (wait_dommain_pend_count > wait_domain_call_count + 1)
>>>
>>> Then send the trace to the mailing list.
>>>
>> Hi,
>>
>> witch function i must use to make a i-pipe trace ?
>> here i am in a xenomai irq handle
>>
>> void period_update()
>> {
>>      ......
>>      else if (wait_domain_pend_count > 100000 &&
>> wait_domain_pend_count != wait_domain_call_count) {
>>              // dotrace
>>
>>       }
>> }
> ipipe_trace_freeze. Requires a numeric argument, which has no
> particular meaning, it just gets printed in the trace.
>
> The I-pipe tracer is documented here:
> http://xenomai.org/2014/06/using-the-i-pipe-tracer/
>
Hello,

here is the trace

-------------- next part --------------
A non-text attachment was scrubbed...
Name: frozen.zip
Type: application/zip
Size: 10590 bytes
Desc: not available
URL: <http://www.xenomai.org/pipermail/xenomai/attachments/20141114/36700ef8/attachment.zip>

Re: [Xenomai] rtdm_nrtsig_pend FAQ

[Gilles Chanteperdrix]

On Fri, Nov 14, 2014 at 10:53:31AM +0100, Johann Obermayr wrote:
> Am 13.11.2014 um 17:33 schrieb Gilles Chanteperdrix:
> >On Thu, Nov 13, 2014 at 05:30:34PM +0100, Johann Obermayr wrote:
> >>Am 12.11.2014 um 17:44 schrieb Gilles Chanteperdrix:
> >>>On Wed, Nov 12, 2014 at 09:47:45AM +0100, Johann Obermayr wrote:
> >>>>Hello,
> >>>>
> >>>>we use rtdm_nrtsig_pend follow.
> >>>>
> >>>>static rtdm_nrtsig_t wait_domain_nrt;
> >>>>static DECLARE_WAIT_QUEUE_HEAD(wait_domain_wq);
> >>>>
> >>>>void period_update()
> >>>>{
> >>>>         wait_domain_pend_count++;
> >>>>         rtdm_nrtsig_pend(&wait_domain_nrt);
> >>>>}
> >>>>
> >>>>static void wait_domain_nrt_handler(rtdm_nrtsig_t nrt_sig, void *arg)
> >>>>{
> >>>>     wait_domain_call_count++;
> >>>>     //wakeup wait_domain
> >>>>     wait_domain_wakeup = 1;
> >>>>     wake_up_interruptible(&wait_domain_wq);
> >>>>}
> >>>>
> >>>>
> >>>>period_update is called every millisecond.
> >>>>this is on imx6 hardware with kernel 3.0.x and xenomai 2.6.2.1.
> >>>>From what Thierry said, I suspect the patch for this kernel has a
> >>>missing call to irq_exit. So, I would ask you to do the same as
> >>>Thierry, please enable the I-pipe tracer, set a sufficient number of
> >>>back trace points such as 10000, and trigger a trace when you detect
> >>>that you have "lost" a notification (wait_dommain_pend_count > wait_domain_call_count + 1)
> >>>
> >>>Then send the trace to the mailing list.
> >>>
> >>Hi,
> >>
> >>witch function i must use to make a i-pipe trace ?
> >>here i am in a xenomai irq handle
> >>
> >>void period_update()
> >>{
> >>     ......
> >>     else if (wait_domain_pend_count > 100000 &&
> >>wait_domain_pend_count != wait_domain_call_count) {
> >>             // dotrace
> >>
> >>      }
> >>}
> >ipipe_trace_freeze. Requires a numeric argument, which has no
> >particular meaning, it just gets printed in the trace.
> >
> >The I-pipe tracer is documented here:
> >http://xenomai.org/2014/06/using-the-i-pipe-tracer/
> >
> Hello,
> 
> here is the trace

Your trace show several things: 
- period_update in your program does not correspond to the sources
you showed:

:   +*func                -759    0.500  period_update+0x10 [sigmatek_lrt] (timer+0xb0 [sigmatek_lrt])
:   +*func                -759    1.000  lrtdrv_monitoring_start_timed+0x10 [sigmatek_lrt] (period_update+0x34 [sigmatek_lrt])
:   +*func                -758    0.750  rtdm_event_signal+0x10 (period_update+0x180 [sigmatek_lrt])
:|  #*func                -757    0.500  xnsynch_flush+0x10 (rtdm_event_signal+0x50)
:|  #*func                -756    0.500  __ipipe_restore_pipeline_head+0x10 (rtdm_event_signal+0xa8)
:   +*func                -756    0.500  __rtdm_synch_flush+0x10 (period_update+0x18c [sigmatek_lrt])
:|  #*func                -755    0.500  xnsynch_flush+0x10 (__rtdm_synch_flush+0x54)
:|  #*func                -755    0.750  __ipipe_restore_pipeline_head+0x10 (__rtdm_synch_flush+0xc8)
:   +*func                -754    0.500  rtdm_event_signal+0x10 (period_update+0x180 [sigmatek_lrt])
:|  #*func                -754    0.500  xnsynch_flush+0x10 (rtdm_event_signal+0x50)
:|  #*func                -753    0.500  __ipipe_restore_pipeline_head+0x10 (rtdm_event_signal+0xa8)
:   +*func                -753    0.250  __rtdm_synch_flush+0x10 (period_update+0x18c [sigmatek_lrt])
:|  #*func                -752    1.000  xnsynch_flush+0x10 (__rtdm_synch_flush+0x54)
:|  #*func                -751    0.250  xnpod_resume_thread+0x10 (xnsynch_flush+0xa4)
:|  #*[ 1065] WD-Trigg 1  -751    0.750  xnpod_resume_thread+0x54 (xnsynch_flush+0xa4)
:|  #*func                -750    0.500  __xnpod_schedule+0x14 (__rtdm_synch_flush+0x84)
:|  #*[   -1] -<?>-   99  -750    0.250  __xnpod_schedule+0x50 (__rtdm_synch_flush+0x84)
:|  #*func                -750    0.750  xnsched_pick_next+0x10 (__xnpod_schedule+0xa0)
:|  #*func                -749    0.500  __ipipe_restore_pipeline_head+0x10 (__rtdm_synch_flush+0xc8)
:   +*func                -748    0.750  ipipe_trigger_irq+0x10 (period_update+0x224 [sigmatek_lrt])
:|  +*func                -748    0.500  __ipipe_handle_irq+0x14 (ipipe_trigger_irq+0x64)


Before calling nrt_pend, period_update calls rtdm_event_signal,
which could reschedule and cause the nrt_pend to be delayed (but
that does not happen in that case).

- period update is called more often than every millisecond:

:   +*func                -759    0.500  period_update+0x10 [sigmatek_lrt] (timer+0xb0 [sigmatek_lrt])

:   +*func                 -16    0.500  period_update+0x10 [sigmatek_lrt] (timer+0xb0 [sigmatek_lrt])
<   +*freeze  0x00023b12     0    0.750  period_update+0x1f4 [sigmatek_lrt] (timer+0xb0 [sigmatek_lrt])

- you have a massive latency, which is causing your real-time job to
occupy the CPU all the time, and never let Linux run.

:|  #*[ 1065] WD-Trigg 1  -722    0.500  __xnpod_schedule+0x50 (xnpod_suspend_thread+0x220)
:|  #*func                -722    0.750  xnsched_pick_next+0x10 (__xnpod_schedule+0xa0)
:|  #*func                -721    0.250  ipipe_unmute_pic+0x10 (__xnpod_schedule+0x1e4)
:|  #*func                -721    1.000  gic_unmute+0x10 (ipipe_unmute_pic+0x18)
:|  #*func                -720+   1.250  ipipe_unstall_pipeline_head+0x10 (__xnpod_schedule+0x270)
:   +*func                -719    0.500  xnsched_finish_unlocked_switch+0x10 (__xnpod_schedule+0x38c)
:|  #*[  700] mmcqd/0 -1  -718    0.750  __xnpod_schedule+0x3b0 (xnintr_clock_handler+0x118)
:|  #*func                -717    0.500  xnpod_fire_callouts+0x10 (__xnpod_schedule+0x5fc)
:|  #*func                -717    0.750  taskSwitchXenomai+0x14 [sigmatek_lrt] (xnpod_fire_callouts+0x54)
:|  #*func                -716    0.750  measureIdleTime+0x10 [sigmatek_lrt] (taskSwitchXenomai+0x6c [sigmatek_lrt])
:|  #*func                -715    1.000  xnarch_tsc_to_ns+0x10 (measureIdleTime+0xac [sigmatek_lrt])
:|   #func                -714    0.750  __ipipe_walk_pipeline+0x10 (__ipipe_dispatch_wired_nocheck+0xa4)
:|   #func                -714! 674.750  __ipipe_exit_irq+0x10 (__ipipe_grab_irq+0x60)
:|   #func                 -39    0.500  __ipipe_grab_irq+0x10 (__irq_svc+0x40)

I believe this latency issue is due to the L2 cache write-allocate
bit that was fixed in the latest I-pipe patch. Please upgrade the
I-pipe patch, check/fix the issues above, and post another trace if
you still have the issue.

-- 
					    Gilles.

Re: [Xenomai] rtdm_nrtsig_pend FAQ

[Johann Obermayr]

Am 14.11.2014 um 11:20 schrieb Gilles Chanteperdrix:
> On Fri, Nov 14, 2014 at 10:53:31AM +0100, Johann Obermayr wrote:
>> Am 13.11.2014 um 17:33 schrieb Gilles Chanteperdrix:
>>> On Thu, Nov 13, 2014 at 05:30:34PM +0100, Johann Obermayr wrote:
>>>> Am 12.11.2014 um 17:44 schrieb Gilles Chanteperdrix:
>>>>> On Wed, Nov 12, 2014 at 09:47:45AM +0100, Johann Obermayr wrote:
>>>>>> Hello,
>>>>>>
>>>>>> we use rtdm_nrtsig_pend follow.
>>>>>>
>>>>>> static rtdm_nrtsig_t wait_domain_nrt;
>>>>>> static DECLARE_WAIT_QUEUE_HEAD(wait_domain_wq);
>>>>>>
>>>>>> void period_update()
>>>>>> {
>>>>>>          wait_domain_pend_count++;
>>>>>>          rtdm_nrtsig_pend(&wait_domain_nrt);
>>>>>> }
>>>>>>
>>>>>> static void wait_domain_nrt_handler(rtdm_nrtsig_t nrt_sig, void *arg)
>>>>>> {
>>>>>>      wait_domain_call_count++;
>>>>>>      //wakeup wait_domain
>>>>>>      wait_domain_wakeup = 1;
>>>>>>      wake_up_interruptible(&wait_domain_wq);
>>>>>> }
>>>>>>
>>>>>>
>>>>>> period_update is called every millisecond.
>>>>>> this is on imx6 hardware with kernel 3.0.x and xenomai 2.6.2.1.
>>>>> >From what Thierry said, I suspect the patch for this kernel has a
>>>>> missing call to irq_exit. So, I would ask you to do the same as
>>>>> Thierry, please enable the I-pipe tracer, set a sufficient number of
>>>>> back trace points such as 10000, and trigger a trace when you detect
>>>>> that you have "lost" a notification (wait_dommain_pend_count > wait_domain_call_count + 1)
>>>>>
>>>>> Then send the trace to the mailing list.
>>>>>
>>>> Hi,
>>>>
>>>> witch function i must use to make a i-pipe trace ?
>>>> here i am in a xenomai irq handle
>>>>
>>>> void period_update()
>>>> {
>>>>      ......
>>>>      else if (wait_domain_pend_count > 100000 &&
>>>> wait_domain_pend_count != wait_domain_call_count) {
>>>>              // dotrace
>>>>
>>>>       }
>>>> }
>>> ipipe_trace_freeze. Requires a numeric argument, which has no
>>> particular meaning, it just gets printed in the trace.
>>>
>>> The I-pipe tracer is documented here:
>>> http://xenomai.org/2014/06/using-the-i-pipe-tracer/
>>>
>> Hello,
>>
>> here is the trace
> Your trace show several things:
> - period_update in your program does not correspond to the sources
> you showed:
>
> :   +*func                -759    0.500  period_update+0x10 [sigmatek_lrt] (timer+0xb0 [sigmatek_lrt])
> :   +*func                -759    1.000  lrtdrv_monitoring_start_timed+0x10 [sigmatek_lrt] (period_update+0x34 [sigmatek_lrt])
> :   +*func                -758    0.750  rtdm_event_signal+0x10 (period_update+0x180 [sigmatek_lrt])
> :|  #*func                -757    0.500  xnsynch_flush+0x10 (rtdm_event_signal+0x50)
> :|  #*func                -756    0.500  __ipipe_restore_pipeline_head+0x10 (rtdm_event_signal+0xa8)
> :   +*func                -756    0.500  __rtdm_synch_flush+0x10 (period_update+0x18c [sigmatek_lrt])
> :|  #*func                -755    0.500  xnsynch_flush+0x10 (__rtdm_synch_flush+0x54)
> :|  #*func                -755    0.750  __ipipe_restore_pipeline_head+0x10 (__rtdm_synch_flush+0xc8)
> :   +*func                -754    0.500  rtdm_event_signal+0x10 (period_update+0x180 [sigmatek_lrt])
> :|  #*func                -754    0.500  xnsynch_flush+0x10 (rtdm_event_signal+0x50)
> :|  #*func                -753    0.500  __ipipe_restore_pipeline_head+0x10 (rtdm_event_signal+0xa8)
> :   +*func                -753    0.250  __rtdm_synch_flush+0x10 (period_update+0x18c [sigmatek_lrt])
> :|  #*func                -752    1.000  xnsynch_flush+0x10 (__rtdm_synch_flush+0x54)
> :|  #*func                -751    0.250  xnpod_resume_thread+0x10 (xnsynch_flush+0xa4)
> :|  #*[ 1065] WD-Trigg 1  -751    0.750  xnpod_resume_thread+0x54 (xnsynch_flush+0xa4)
> :|  #*func                -750    0.500  __xnpod_schedule+0x14 (__rtdm_synch_flush+0x84)
> :|  #*[   -1] -<?>-   99  -750    0.250  __xnpod_schedule+0x50 (__rtdm_synch_flush+0x84)
> :|  #*func                -750    0.750  xnsched_pick_next+0x10 (__xnpod_schedule+0xa0)
> :|  #*func                -749    0.500  __ipipe_restore_pipeline_head+0x10 (__rtdm_synch_flush+0xc8)
> :   +*func                -748    0.750  ipipe_trigger_irq+0x10 (period_update+0x224 [sigmatek_lrt])
> :|  +*func                -748    0.500  __ipipe_handle_irq+0x14 (ipipe_trigger_irq+0x64)
>
>
> Before calling nrt_pend, period_update calls rtdm_event_signal,
> which could reschedule and cause the nrt_pend to be delayed (but
> that does not happen in that case).
Yes, it starts some RT tasks. This tasks need 30-100 us.

> - period update is called more often than every millisecond:
>
> :   +*func                -759    0.500  period_update+0x10 [sigmatek_lrt] (timer+0xb0 [sigmatek_lrt])
>
> :   +*func                 -16    0.500  period_update+0x10 [sigmatek_lrt] (timer+0xb0 [sigmatek_lrt])
> <   +*freeze  0x00023b12     0    0.750  period_update+0x1f4 [sigmatek_lrt] (timer+0xb0 [sigmatek_lrt])

which can not be, because it is triggerd by a FPGA hardware IRQ every 
millisecond.

> - you have a massive latency, which is causing your real-time job to
> occupy the CPU all the time, and never let Linux run.
It looks as if a mmcqd task (micro SD card) will stop calling software irq.

> :|  #*[ 1065] WD-Trigg 1  -722    0.500  __xnpod_schedule+0x50 (xnpod_suspend_thread+0x220)
> :|  #*func                -722    0.750  xnsched_pick_next+0x10 (__xnpod_schedule+0xa0)
> :|  #*func                -721    0.250  ipipe_unmute_pic+0x10 (__xnpod_schedule+0x1e4)
> :|  #*func                -721    1.000  gic_unmute+0x10 (ipipe_unmute_pic+0x18)
> :|  #*func                -720+   1.250  ipipe_unstall_pipeline_head+0x10 (__xnpod_schedule+0x270)
> :   +*func                -719    0.500  xnsched_finish_unlocked_switch+0x10 (__xnpod_schedule+0x38c)
> :|  #*[  700] mmcqd/0 -1  -718    0.750  __xnpod_schedule+0x3b0 (xnintr_clock_handler+0x118)
> :|  #*func                -717    0.500  xnpod_fire_callouts+0x10 (__xnpod_schedule+0x5fc)
> :|  #*func                -717    0.750  taskSwitchXenomai+0x14 [sigmatek_lrt] (xnpod_fire_callouts+0x54)
> :|  #*func                -716    0.750  measureIdleTime+0x10 [sigmatek_lrt] (taskSwitchXenomai+0x6c [sigmatek_lrt])
> :|  #*func                -715    1.000  xnarch_tsc_to_ns+0x10 (measureIdleTime+0xac [sigmatek_lrt])
> :|   #func                -714    0.750  __ipipe_walk_pipeline+0x10 (__ipipe_dispatch_wired_nocheck+0xa4)
> :|   #func                -714! 674.750  __ipipe_exit_irq+0x10 (__ipipe_grab_irq+0x60)
> :|   #func                 -39    0.500  __ipipe_grab_irq+0x10 (__irq_svc+0x40)
>
> I believe this latency issue is due to the L2 cache write-allocate
> bit that was fixed in the latest I-pipe patch. Please upgrade the
> I-pipe patch, check/fix the issues above, and post another trace if
> you still have the issue.
>

i test it with the new patches.



Here is the period_update function

void period_update(unsigned long ovr)
{
     struct list_head *lh;

     timer_overruns += ovr;
     timer_ticks++;

     lrtdrv_monitoring_start_timed(timer_ticks);

     /* we don't need to lock the list, we are the highest priority task
      * and if other ctx are added to/removed from the list, the list is 
locked there
      */
     list_for_each(lh, &lrtdrv_opendev_list) {
         lrtdrv_context_t *ctx = list_entry(lh, lrtdrv_context_t, 
opendev_entry);

         if (WATCHDOG_CHECK(ctx, 0) || WATCHDOG_CHECK(ctx, 1)) {
             // Watch DOG aufgetretten, also brauch ich nichts mehr machen
         } else {
             rtdm_event_signal(&ctx->rtt_timer_wait);
             rtdm_event_pulse(&ctx->timer_wait);
         }
     }
     if (wait_domain_pend_count == 100000)
         wait_domain_call_count = wait_domain_pend_count;
     else if (wait_domain_pend_count > 100000 && wait_domain_pend_count 
!= wait_domain_call_count) {
static int trace_count = 0;
         if (trace_count == 0) {
             trace_count++;
             // dotrace
             printk(KERN_INFO "IPIPE-Trace");
             ipipe_trace_freeze(wait_domain_pend_count);
         }
     }
     // NRT IRQ - start background
     if(wait_domain_nrt_setup) {
         wait_domain_pend_count++;
         rtdm_nrtsig_pend(&wait_domain_nrt);
     } else {
         wait_domain_nopend_count++;
     }
}

best regards
  Johann

Re: [Xenomai] rtdm_nrtsig_pend FAQ

[Gilles Chanteperdrix]

On Fri, Nov 14, 2014 at 01:37:46PM +0100, Johann Obermayr wrote:
> Am 14.11.2014 um 11:20 schrieb Gilles Chanteperdrix:
> >On Fri, Nov 14, 2014 at 10:53:31AM +0100, Johann Obermayr wrote:
> >>Am 13.11.2014 um 17:33 schrieb Gilles Chanteperdrix:
> >>>On Thu, Nov 13, 2014 at 05:30:34PM +0100, Johann Obermayr wrote:
> >>>>Am 12.11.2014 um 17:44 schrieb Gilles Chanteperdrix:
> >>>>>On Wed, Nov 12, 2014 at 09:47:45AM +0100, Johann Obermayr wrote:
> >>>>>>Hello,
> >>>>>>
> >>>>>>we use rtdm_nrtsig_pend follow.
> >>>>>>
> >>>>>>static rtdm_nrtsig_t wait_domain_nrt;
> >>>>>>static DECLARE_WAIT_QUEUE_HEAD(wait_domain_wq);
> >>>>>>
> >>>>>>void period_update()
> >>>>>>{
> >>>>>>         wait_domain_pend_count++;
> >>>>>>         rtdm_nrtsig_pend(&wait_domain_nrt);
> >>>>>>}
> >>>>>>
> >>>>>>static void wait_domain_nrt_handler(rtdm_nrtsig_t nrt_sig, void *arg)
> >>>>>>{
> >>>>>>     wait_domain_call_count++;
> >>>>>>     //wakeup wait_domain
> >>>>>>     wait_domain_wakeup = 1;
> >>>>>>     wake_up_interruptible(&wait_domain_wq);
> >>>>>>}
> >>>>>>
> >>>>>>
> >>>>>>period_update is called every millisecond.
> >>>>>>this is on imx6 hardware with kernel 3.0.x and xenomai 2.6.2.1.
> >>>>>>From what Thierry said, I suspect the patch for this kernel has a
> >>>>>missing call to irq_exit. So, I would ask you to do the same as
> >>>>>Thierry, please enable the I-pipe tracer, set a sufficient number of
> >>>>>back trace points such as 10000, and trigger a trace when you detect
> >>>>>that you have "lost" a notification (wait_dommain_pend_count > wait_domain_call_count + 1)
> >>>>>
> >>>>>Then send the trace to the mailing list.
> >>>>>
> >>>>Hi,
> >>>>
> >>>>witch function i must use to make a i-pipe trace ?
> >>>>here i am in a xenomai irq handle
> >>>>
> >>>>void period_update()
> >>>>{
> >>>>     ......
> >>>>     else if (wait_domain_pend_count > 100000 &&
> >>>>wait_domain_pend_count != wait_domain_call_count) {
> >>>>             // dotrace
> >>>>
> >>>>      }
> >>>>}
> >>>ipipe_trace_freeze. Requires a numeric argument, which has no
> >>>particular meaning, it just gets printed in the trace.
> >>>
> >>>The I-pipe tracer is documented here:
> >>>http://xenomai.org/2014/06/using-the-i-pipe-tracer/
> >>>
> >>Hello,
> >>
> >>here is the trace
> >Your trace show several things:
> >- period_update in your program does not correspond to the sources
> >you showed:
> >
> >:   +*func                -759    0.500  period_update+0x10 [sigmatek_lrt] (timer+0xb0 [sigmatek_lrt])
> >:   +*func                -759    1.000  lrtdrv_monitoring_start_timed+0x10 [sigmatek_lrt] (period_update+0x34 [sigmatek_lrt])
> >:   +*func                -758    0.750  rtdm_event_signal+0x10 (period_update+0x180 [sigmatek_lrt])
> >:|  #*func                -757    0.500  xnsynch_flush+0x10 (rtdm_event_signal+0x50)
> >:|  #*func                -756    0.500  __ipipe_restore_pipeline_head+0x10 (rtdm_event_signal+0xa8)
> >:   +*func                -756    0.500  __rtdm_synch_flush+0x10 (period_update+0x18c [sigmatek_lrt])
> >:|  #*func                -755    0.500  xnsynch_flush+0x10 (__rtdm_synch_flush+0x54)
> >:|  #*func                -755    0.750  __ipipe_restore_pipeline_head+0x10 (__rtdm_synch_flush+0xc8)
> >:   +*func                -754    0.500  rtdm_event_signal+0x10 (period_update+0x180 [sigmatek_lrt])
> >:|  #*func                -754    0.500  xnsynch_flush+0x10 (rtdm_event_signal+0x50)
> >:|  #*func                -753    0.500  __ipipe_restore_pipeline_head+0x10 (rtdm_event_signal+0xa8)
> >:   +*func                -753    0.250  __rtdm_synch_flush+0x10 (period_update+0x18c [sigmatek_lrt])
> >:|  #*func                -752    1.000  xnsynch_flush+0x10 (__rtdm_synch_flush+0x54)
> >:|  #*func                -751    0.250  xnpod_resume_thread+0x10 (xnsynch_flush+0xa4)
> >:|  #*[ 1065] WD-Trigg 1  -751    0.750  xnpod_resume_thread+0x54 (xnsynch_flush+0xa4)
> >:|  #*func                -750    0.500  __xnpod_schedule+0x14 (__rtdm_synch_flush+0x84)
> >:|  #*[   -1] -<?>-   99  -750    0.250  __xnpod_schedule+0x50 (__rtdm_synch_flush+0x84)
> >:|  #*func                -750    0.750  xnsched_pick_next+0x10 (__xnpod_schedule+0xa0)
> >:|  #*func                -749    0.500  __ipipe_restore_pipeline_head+0x10 (__rtdm_synch_flush+0xc8)
> >:   +*func                -748    0.750  ipipe_trigger_irq+0x10 (period_update+0x224 [sigmatek_lrt])
> >:|  +*func                -748    0.500  __ipipe_handle_irq+0x14 (ipipe_trigger_irq+0x64)
> >
> >
> >Before calling nrt_pend, period_update calls rtdm_event_signal,
> >which could reschedule and cause the nrt_pend to be delayed (but
> >that does not happen in that case).
> Yes, it starts some RT tasks. This tasks need 30-100 us.
> 
> >- period update is called more often than every millisecond:
> >
> >:   +*func                -759    0.500  period_update+0x10 [sigmatek_lrt] (timer+0xb0 [sigmatek_lrt])
> >
> >:   +*func                 -16    0.500  period_update+0x10 [sigmatek_lrt] (timer+0xb0 [sigmatek_lrt])
> ><   +*freeze  0x00023b12     0    0.750  period_update+0x1f4 [sigmatek_lrt] (timer+0xb0 [sigmatek_lrt])
> 
> which can not be, because it is triggerd by a FPGA hardware IRQ
> every millisecond.
> 
> >- you have a massive latency, which is causing your real-time job to
> >occupy the CPU all the time, and never let Linux run.
> It looks as if a mmcqd task (micro SD card) will stop calling software irq.
> 
> >:|  #*[ 1065] WD-Trigg 1  -722    0.500  __xnpod_schedule+0x50 (xnpod_suspend_thread+0x220)
> >:|  #*func                -722    0.750  xnsched_pick_next+0x10 (__xnpod_schedule+0xa0)
> >:|  #*func                -721    0.250  ipipe_unmute_pic+0x10 (__xnpod_schedule+0x1e4)
> >:|  #*func                -721    1.000  gic_unmute+0x10 (ipipe_unmute_pic+0x18)
> >:|  #*func                -720+   1.250  ipipe_unstall_pipeline_head+0x10 (__xnpod_schedule+0x270)
> >:   +*func                -719    0.500  xnsched_finish_unlocked_switch+0x10 (__xnpod_schedule+0x38c)
> >:|  #*[  700] mmcqd/0 -1  -718    0.750  __xnpod_schedule+0x3b0 (xnintr_clock_handler+0x118)
> >:|  #*func                -717    0.500  xnpod_fire_callouts+0x10 (__xnpod_schedule+0x5fc)
> >:|  #*func                -717    0.750  taskSwitchXenomai+0x14 [sigmatek_lrt] (xnpod_fire_callouts+0x54)
> >:|  #*func                -716    0.750  measureIdleTime+0x10 [sigmatek_lrt] (taskSwitchXenomai+0x6c [sigmatek_lrt])
> >:|  #*func                -715    1.000  xnarch_tsc_to_ns+0x10 (measureIdleTime+0xac [sigmatek_lrt])
> >:|   #func                -714    0.750  __ipipe_walk_pipeline+0x10 (__ipipe_dispatch_wired_nocheck+0xa4)
> >:|   #func                -714! 674.750  __ipipe_exit_irq+0x10 (__ipipe_grab_irq+0x60)
> >:|   #func                 -39    0.500  __ipipe_grab_irq+0x10 (__irq_svc+0x40)
> >
> >I believe this latency issue is due to the L2 cache write-allocate
> >bit that was fixed in the latest I-pipe patch. Please upgrade the
> >I-pipe patch, check/fix the issues above, and post another trace if
> >you still have the issue.
> >
> 
> i test it with the new patches.
> 
> 
> 
> Here is the period_update function

This does not help much. This does not show how period_update is
activated, and notably, you do not answer my question of how
period_update can be called 3 times in the same millisecond whereas
it is supposed to be called only once. We do not see your complete
application sources, which can make us doubt about it.

So, please write a simple example, doing what your original
period_update did, triggered by a periodic thread, or a kernel
timer. A simple example that we can run on our machines if need be,
without any reference to code we do not have.

Run only that, and only that on the system, and tell us if you still
observe the problem. 

-- 
					    Gilles.

Re: [Xenomai] rtdm_nrtsig_pend FAQ

[Gilles Chanteperdrix]

On Fri, Nov 14, 2014 at 01:37:46PM +0100, Johann Obermayr wrote:
> >- period update is called more often than every millisecond:
> >
> >:   +*func                -759    0.500  period_update+0x10 [sigmatek_lrt] (timer+0xb0 [sigmatek_lrt])
> >
> >:   +*func                 -16    0.500  period_update+0x10 [sigmatek_lrt] (timer+0xb0 [sigmatek_lrt])
> ><   +*freeze  0x00023b12     0    0.750  period_update+0x1f4 [sigmatek_lrt] (timer+0xb0 [sigmatek_lrt])
> 
> which can not be, because it is triggerd by a FPGA hardware IRQ
> every millisecond.

So, bugs in FPGA never happen? As far as I know the P in
FPGA means "programmable". I do not see how the trace could be wrong
on this. You can read a counter in your FPGA every time
period_update is called, if you do not trust the processor clock.

> 
> >- you have a massive latency, which is causing your real-time job to
> >occupy the CPU all the time, and never let Linux run.
> It looks as if a mmcqd task (micro SD card) will stop calling software irq.

I am not sure there is a big latency here, the system maybe just
returns to user-space which does its job, and the time spent in
user-space gets accounted before the last function which was called
before the return to user-space. I need to read this part of the
trace again to see where the virq should have been triggered.

> 
> >:|  #*[ 1065] WD-Trigg 1  -722    0.500  __xnpod_schedule+0x50 (xnpod_suspend_thread+0x220)
> >:|  #*func                -722    0.750  xnsched_pick_next+0x10 (__xnpod_schedule+0xa0)
> >:|  #*func                -721    0.250  ipipe_unmute_pic+0x10 (__xnpod_schedule+0x1e4)
> >:|  #*func                -721    1.000  gic_unmute+0x10 (ipipe_unmute_pic+0x18)
> >:|  #*func                -720+   1.250  ipipe_unstall_pipeline_head+0x10 (__xnpod_schedule+0x270)
> >:   +*func                -719    0.500  xnsched_finish_unlocked_switch+0x10 (__xnpod_schedule+0x38c)
> >:|  #*[  700] mmcqd/0 -1  -718    0.750  __xnpod_schedule+0x3b0 (xnintr_clock_handler+0x118)
> >:|  #*func                -717    0.500  xnpod_fire_callouts+0x10 (__xnpod_schedule+0x5fc)
> >:|  #*func                -717    0.750  taskSwitchXenomai+0x14 [sigmatek_lrt] (xnpod_fire_callouts+0x54)
> >:|  #*func                -716    0.750  measureIdleTime+0x10 [sigmatek_lrt] (taskSwitchXenomai+0x6c [sigmatek_lrt])
> >:|  #*func                -715    1.000  xnarch_tsc_to_ns+0x10 (measureIdleTime+0xac [sigmatek_lrt])
> >:|   #func                -714    0.750  __ipipe_walk_pipeline+0x10 (__ipipe_dispatch_wired_nocheck+0xa4)
> >:|   #func                -714! 674.750  __ipipe_exit_irq+0x10 (__ipipe_grab_irq+0x60)
> >:|   #func                 -39    0.500  __ipipe_grab_irq+0x10 (__irq_svc+0x40)

> _______________________________________________
> Xenomai mailing list
> Xenomai@xenomai.org
> http://www.xenomai.org/mailman/listinfo/xenomai

-- 
					    Gilles.

Re: [Xenomai] rtdm_nrtsig_pend FAQ

[Gilles Chanteperdrix]

Ok, we leave root here:

:    #func                -864    0.500  esdhc_readl_le+0x10 (esdhc_set_clock+0x178)
:    #func                -863    0.500  esdhc_writel_le+0x10 (esdhc_set_clock+0x1b8)
:    #func                -863    0.500  l2x0_cache_sync+0x10 (esdhc_writel_le+0x188)
:    #func                -862    0.500  __ipipe_spin_lock_irqsave+0x10 (l2x0_cache_sync+0x24)
:|   #func                -862!  74.000  __ipipe_spin_unlock_irqrestore+0x10 (l2x0_cache_sync+0x3c)
:|   #func                -788    0.750  __ipipe_grab_irq+0x10 (__irq_svc+0x40)

The timer used (imx timer and not cortex a9 local timer) seem
consistent with the fact that this is an uniprocessor.

period_update does not seem to be triggered by an external IRQ, but
by the timer. A periodic task using rt_task_wait_period in fact.

We can see that the root domain is stalled, so a function is in a
loop, probably in the SD card driver, doing some polling, with local
irqs off. With a masking section of about 74us. Eeek.

In later versions of the I-pipe patch, I have added code to entry.S,
to trace the function which __irq_svc interrupted, if you want, I
can backport these changes. This should be easy.

The complete sequence corresponding to the execution of
period_update can be seen here:

:   +*func                -748    0.750  ipipe_trigger_irq+0x10 (period_update+0x224 [sigmatek_lrt])
:|  +*func                -748    0.500  __ipipe_handle_irq+0x14 (ipipe_trigger_irq+0x64)
:|  +*func                -747    1.000  __ipipe_set_irq_pending+0x10 (__ipipe_handle_irq+0x138)
:   +*func                -746    0.500  rt_task_wait_period+0x10 (timer+0x3c [sigmatek_lrt])
:   +*func                -746    0.750  xnpod_wait_thread_period+0x14 (rt_task_wait_period+0x48)
:|  #*func                -745    0.750  xnpod_suspend_thread+0x14 (xnpod_wait_thread_period+0x94)
:|  #*func                -744    0.500  __xnpod_schedule+0x14 (xnpod_suspend_thread+0x220)
:|  #*[   -1] -<?>-   99  -744    0.250  __xnpod_schedule+0x50 (xnpod_suspend_thread+0x220)
:|  #*func                -743+   1.250  xnsched_pick_next+0x10 (__xnpod_schedule+0xa0)
:|  #*func                -742    1.000  ipipe_unstall_pipeline_head+0x10 (__xnpod_schedule+0x270)
:   +*func                -741    0.500  xnsched_finish_unlocked_switch+0x10 (__xnpod_schedule+0x38c)
:|  #*[ 1065] WD-Trigg 1  -741+   1.500  __xnpod_schedule+0x3b0 (xnpod_suspend_thread+0x220)
:|  #*func                -739    0.500  xnpod_fire_callouts+0x10 (__xnpod_schedule+0x5fc)
:|  #*func                -739    0.500  taskSwitchXenomai+0x14 [sigmatek_lrt] (xnpod_fire_callouts+0x54)
:|  #*func                -738+   1.250  measureIdleTime+0x10 [sigmatek_lrt] (taskSwitchXenomai+0x6c [sigmatek_lrt])
:|  #*func                -737+   4.500  __ipipe_restore_pipeline_head+0x10 (rtdm_event_timedwait+0x15c)
:   +*func                -732    0.750  __ipipe_syscall_root+0x10 (vector_swi+0x44)
:   +*func                -732    0.500  __ipipe_dispatch_event+0x14 (__ipipe_syscall_root+0xdc)
:|  +*func                -731    1.000  lrtdrv_exception_handler+0x14 [sigmatek_lrt] (__ipipe_dispatch_event+0x40)
:   +*func                -730+   1.250  hisyscall_event+0x14 (__ipipe_dispatch_event+0x110)
:   +*func                -729    0.500  sys_rtdm_ioctl+0x10 (hisyscall_event+0x178)
:   +*func                -728    0.500  __rt_dev_ioctl+0x18 (sys_rtdm_ioctl+0x30)
:   +*func                -728    0.500  rtdm_context_get+0x10 (__rt_dev_ioctl+0x38)
:|  #*func                -727    0.750  __ipipe_restore_pipeline_head+0x10 (rtdm_context_get+0xd8)
:   +*func                -727    0.250  lrt_ioctl+0x10 [sigmatek_lrt] (__rt_dev_ioctl+0x6c)
:   +*func                -726    1.000  lrt_ioctl_work+0x14 [sigmatek_lrt] (lrt_ioctl+0x18 [sigmatek_lrt])
:   +*func                -725    0.500  lrtdrv_timing_wait+0x10 [sigmatek_lrt] (lrt_ioctl_work+0x45c [sigmatek_lrt])
:   +*func                -725    0.500  rtdm_event_wait+0x14 (lrtdrv_timing_wait+0x8c [sigmatek_lrt])
:   +*func                -724    0.500  rtdm_event_timedwait+0x14 (rtdm_event_wait+0x2c)
:|  #*func                -724    0.500  xnsynch_sleep_on+0x14 (rtdm_event_timedwait+0xc4)
:|  #*func                -723    0.500  xnpod_suspend_thread+0x14 (xnsynch_sleep_on+0xd4)
:|  #*func                -723    0.500  __xnpod_schedule+0x14 (xnpod_suspend_thread+0x220)
:|  #*[ 1065] WD-Trigg 1  -722    0.500  __xnpod_schedule+0x50 (xnpod_suspend_thread+0x220)
:|  #*func                -722    0.750  xnsched_pick_next+0x10 (__xnpod_schedule+0xa0)
:|  #*func                -721    0.250  ipipe_unmute_pic+0x10 (__xnpod_schedule+0x1e4)
:|  #*func                -721    1.000  gic_unmute+0x10 (ipipe_unmute_pic+0x18)
:|  #*func                -720+   1.250  ipipe_unstall_pipeline_head+0x10 (__xnpod_schedule+0x270)
:   +*func                -719    0.500  xnsched_finish_unlocked_switch+0x10 (__xnpod_schedule+0x38c)
:|  #*[  700] mmcqd/0 -1  -718    0.750  __xnpod_schedule+0x3b0 (xnintr_clock_handler+0x118)
:|  #*func                -717    0.500  xnpod_fire_callouts+0x10 (__xnpod_schedule+0x5fc)
:|  #*func                -717    0.750  taskSwitchXenomai+0x14 [sigmatek_lrt] (xnpod_fire_callouts+0x54)
:|  #*func                -716    0.750  measureIdleTime+0x10 [sigmatek_lrt] (taskSwitchXenomai+0x6c [sigmatek_lrt])
:|  #*func                -715    1.000  xnarch_tsc_to_ns+0x10 (measureIdleTime+0xac [sigmatek_lrt])
:|   #func                -714    0.750  __ipipe_walk_pipeline+0x10 (__ipipe_dispatch_wired_nocheck+0xa4)
:|   #func                -714! 674.750  __ipipe_exit_irq+0x10 (__ipipe_grab_irq+0x60)
:|   #func                 -39    0.500  __ipipe_grab_irq+0x10 (__irq_svc+0x40)

And here we finally return to root, which continues its polling,
with local irqs off for 674us!. No wonder why  the virq can not be
executed, Linux irqs are disabled. There is no I-pipe bug involved.

-- 
					    Gilles.