[Xenomai-help] Interrupt latency greater than 250ms. Question.

[Xenomai-help] Interrupt latency greater than 250ms. Question.

[Makarand Pradhan]

[-- Attachment #1.1: Type: text/plain, Size: 2747 bytes --]

Hi All,

I am working with MPC8360, Linux 3.0.0, Xenomai 2.6.

I am experiencing delays as high as 250ms in processing interrupt 43 
(2b). Interrupt 43 indicates that the power quicc engine has 
transmitted/received a frame. This interrupt is being handled in Xenomai.

The ipipe trace indicates that ipipe has kept the interrupt masked which 
may be the cause of the problem.

The problem is seen intermittently after upgrading to Xenomai 2.6. This 
problem was never seen in Xenomai 2.4.10.
*
Normal operation:*
Under normal operation, the irq is unmasked roughly within 300usecs. 
after it is masked on receipt of an int: e.g.

 From attached file: *good_int2b_ipipe_frozen*

Int masked for 647 - 370 = 277 usec
Int received:
:|   +begin   0x0000002b *-647 *   0.590  __ipipe_qe_ic_cascade_irq+0x2c 
(qe_ic_cascade_low_ipic+0x5c)
:|   +func                -646    0.575  __ipipe_handle_irq+0x8 
(__ipipe_qe_ic_cascade_irq+0x38)
:|   +func                -646    0.787  __ipipe_ack_level_irq+0x8 
(__ipipe_handle_irq+0xbc)
:|   +func                -645    0.666  qe_ic_mask_irq+0x8 
(__ipipe_ack_level_irq+0x40)

Int unmasked:
:|   +end     0x0000002b *-370*+   1.151  __ipipe_qe_ic_cascade_irq+0x40 
(qe_ic_cascade_low_ipic+0x5c)
:|   +func                -369    0.742  ipic_unmask_irq+0x8 
(qe_ic_cascade_low_ipic+0x70)

*Problem scenario:*
The ipipe trace indicates that the irq stayed masked for a long time:

From: bad_int2b_ipipe_frozen

The int stayed masked for more than 50ms after which it was unmasked:

Int received: No begin 0x0000002b for more than 50ms. So the int has 
occurred more than 50ms ago.

Int unmasked:
:|   #end     0x0000002b  -434+   2.272  __ipipe_qe_ic_cascade_irq+0x40 
(qe_ic_cascade_low_ipic+0x5c)
:|   #func                -432+   1.212  ipic_unmask_irq+0x8 
(qe_ic_cascade_low_ipic+0x70)


The ipipe traces are attached to this email for reference.

Can you please help me understand the cause for this behavior? Any 
pointers would be appreciated.

The interrupt is being handled in user space thorugh rt_intr_wait. Do I 
need to invoke a rt call to tell ipipe to unmask the intr?

Please feel free to correct me if the traces are being interpreted wrongly.

Warm Rgds,
Mak.



-- 
___________________________________________________________________________
NOTICE OF CONFIDENTIALITY:
This e-mail and any attachments may contain confidential and privileged information.  If you are
not the intended recipient, please notify the sender immediately by return e-mail and delete this
e-mail and any copies.  Any dissemination or use of this information by a person other than the
intended recipient is unauthorized and may be illegal.
_____________________________________________________________________

  


[-- Attachment #1.2: Type: text/html, Size: 4202 bytes --]

[-- Attachment #2: bad_int2b_ipipe_frozen.gz --]
[-- Type: application/gzip, Size: 324735 bytes --]

[-- Attachment #3: good_int2b_ipipe_frozen.gz --]
[-- Type: application/gzip, Size: 296468 bytes --]

Re: [Xenomai-help] Interrupt latency greater than 250ms. Question.

[Philippe Gerum]

On 03/28/2012 05:53 PM, Makarand Pradhan wrote:
> Hi All,
>
> I am working with MPC8360, Linux 3.0.0, Xenomai 2.6.
>
> I am experiencing delays as high as 250ms in processing interrupt 43
> (2b). Interrupt 43 indicates that the power quicc engine has
> transmitted/received a frame. This interrupt is being handled in Xenomai.
>
> The ipipe trace indicates that ipipe has kept the interrupt masked which
> may be the cause of the problem.
>
> The problem is seen intermittently after upgrading to Xenomai 2.6. This
> problem was never seen in Xenomai 2.4.10.
> *
> Normal operation:*
> Under normal operation, the irq is unmasked roughly within 300usecs.
> after it is masked on receipt of an int: e.g.
>
>  From attached file: *good_int2b_ipipe_frozen*

The log says your code wants to control when the IRQ is enabled again, 
by calling rt_intr_enable() from userland. I guess you are setting 
I_NOAUTOENA too. Correct?

>
> Int masked for 647 - 370 = 277 usec
> Int received:
> :| +begin 0x0000002b *-647 * 0.590 __ipipe_qe_ic_cascade_irq+0x2c
> (qe_ic_cascade_low_ipic+0x5c)
> :| +func -646 0.575 __ipipe_handle_irq+0x8 (__ipipe_qe_ic_cascade_irq+0x38)
> :| +func -646 0.787 __ipipe_ack_level_irq+0x8 (__ipipe_handle_irq+0xbc)
> :| +func -645 0.666 qe_ic_mask_irq+0x8 (__ipipe_ack_level_irq+0x40)
>
> Int unmasked:
> :| +end 0x0000002b *-370*+ 1.151 __ipipe_qe_ic_cascade_irq+0x40
> (qe_ic_cascade_low_ipic+0x5c)
> :| +func -369 0.742 ipic_unmask_irq+0x8 (qe_ic_cascade_low_ipic+0x70)
>
> *Problem scenario:*
> The ipipe trace indicates that the irq stayed masked for a long time:
>
> From: bad_int2b_ipipe_frozen
>
> The int stayed masked for more than 50ms after which it was unmasked:
>
> Int received: No begin 0x0000002b for more than 50ms. So the int has
> occurred more than 50ms ago.
>
> Int unmasked:
> :| #end 0x0000002b -434+ 2.272 __ipipe_qe_ic_cascade_irq+0x40
> (qe_ic_cascade_low_ipic+0x5c)
> :| #func -432+ 1.212 ipic_unmask_irq+0x8 (qe_ic_cascade_low_ipic+0x70)
>
>
> The ipipe traces are attached to this email for reference.
>
> Can you please help me understand the cause for this behavior? Any
> pointers would be appreciated.
>
> The interrupt is being handled in user space thorugh rt_intr_wait. Do I
> need to invoke a rt call to tell ipipe to unmask the intr?
>
> Please feel free to correct me if the traces are being interpreted wrongly.
>
> Warm Rgds,
> Mak.
>
>
>
> --
> ___________________________________________________________________________
> NOTICE OF CONFIDENTIALITY:
> This e-mail and any attachments may contain confidential and privileged information.  If you are
> not the intended recipient, please notify the sender immediately by return e-mail and delete this
> e-mail and any copies.  Any dissemination or use of this information by a person other than the
> intended recipient is unauthorized and may be illegal.
> _____________________________________________________________________
>
>
>
>
>
> _______________________________________________
> Xenomai-help mailing list
> Xenomai-help@domain.hid
> https://mail.gna.org/listinfo/xenomai-help


-- 
Philippe.

Re: [Xenomai-help] Interrupt latency greater than 250ms. Question.

[Makarand Pradhan]

Hi Philippe,

On 28/03/12 12:17 PM, Philippe Gerum wrote:
> The log says your code wants to control when the IRQ is enabled again,
> by calling rt_intr_enable() from userland. I guess you are setting
> I_NOAUTOENA too. Correct?

That is correct. I_NOAUTOENA is used in rt_intr_create. Otherwise the 
level trigerred interrupt will not allow the userland processing of the 
int. The userland handler is very small and it unconditionally 
rt_intr_enables the intr.

Testing indicates that the interrupt is always enabled from user space 
within 250 usec after kernel gets the interrupt.

I have noted that unless I see "#end 0x0000002b" and a hit to the 
ipic_unmask_irq, the next interrupt is not processed.

And this is getting delayed once in a while which causes a delay in 
processing the next interrupt.

So the sequence of events leading to the problem is:

1. Get interrupt: #begin   0x0000002b noted in ipipe trace
2. Intr enabled from user space. Always happens roughly within 250usec.
3. #end 0x0000002b noted in ipipe trace where the int is unmasked by ipipe.

When I see the problem, step 3 is delayed. I am trying to capture a 
trace where the begin, int enable and end are captured.

Your thoughts on what might cause this delay would be appreciated.

Rgds,
Mak.





-- 
___________________________________________________________________________
NOTICE OF CONFIDENTIALITY:
This e-mail and any attachments may contain confidential and privileged information.  If you are
not the intended recipient, please notify the sender immediately by return e-mail and delete this
e-mail and any copies.  Any dissemination or use of this information by a person other than the
intended recipient is unauthorized and may be illegal.
_____________________________________________________________________

  

Re: [Xenomai-help] Interrupt latency greater than 250ms. Question.

[Philippe Gerum]

On 03/28/2012 08:23 PM, Makarand Pradhan wrote:
> Hi Philippe,
>
> On 28/03/12 12:17 PM, Philippe Gerum wrote:
>> The log says your code wants to control when the IRQ is enabled again,
>> by calling rt_intr_enable() from userland. I guess you are setting
>> I_NOAUTOENA too. Correct?
>
> That is correct. I_NOAUTOENA is used in rt_intr_create. Otherwise the
> level trigerred interrupt will not allow the userland processing of the
> int. The userland handler is very small and it unconditionally
> rt_intr_enables the intr.
>
> Testing indicates that the interrupt is always enabled from user space
> within 250 usec after kernel gets the interrupt.
>
> I have noted that unless I see "#end 0x0000002b" and a hit to the
> ipic_unmask_irq, the next interrupt is not processed.
>
> And this is getting delayed once in a while which causes a delay in
> processing the next interrupt.
>
> So the sequence of events leading to the problem is:
>
> 1. Get interrupt: #begin 0x0000002b noted in ipipe trace
> 2. Intr enabled from user space. Always happens roughly within 250usec.
> 3. #end 0x0000002b noted in ipipe trace where the int is unmasked by ipipe.
>
> When I see the problem, step 3 is delayed. I am trying to capture a
> trace where the begin, int enable and end are captured.
>
> Your thoughts on what might cause this delay would be appreciated.
>

Which IRQ are you re-enabling from user-space, the multiplexed IRQ 33, 
or the cascaded one you receive?

> Rgds,
> Mak.
>
>
>
>
>


-- 
Philippe.

Re: [Xenomai-help] Interrupt latency greater than 250ms. Question.

[Makarand Pradhan]

[-- Attachment #1: Type: text/plain, Size: 4305 bytes --]

Hi Philippe,

We have found that the problem is that the interrupt is unexpectedly 
held masked at the IPIC level for a long time. Please find the trace below:

  2552 :|  + func               -54413    0.590  
qe_ic_cascade_low_ipic+0x8 (__ipipe_ack_irq+0x2c)
  2553 :|  + func               -54412    0.696  qe_ic_get_low_irq+0x8 
(qe_ic_cascade_low_ipic+0x30)
  2554 :|  + func               -54411    0.666  irq_linear_revmap+0x8 
(qe_ic_get_low_irq+0x5c)

*MASK in IPIC (SIMSR_H register bit 1)*
  2555 :|  + func               -54411    0.606  ipic_mask_irq+0x8 
(qe_ic_cascade_low_ipic+0x48)
  2556 :|  + func               -54410    0.590  irqd_to_hwirq+0x8 
(ipic_mask_irq+0x30)
  2557 :|  + func               -54410    0.909  
__ipipe_spin_lock_irqsave+0x8 (ipic_mask_irq+0x40)
  2558 :|  # func               -54409    0.727  
__ipipe_spin_unlock_irqrestore+0x8 (ipic_mask_irq+0xa8      )
  2559 :|  + func               -54408    0.560  
__ipipe_qe_ic_cascade_irq+0x8 (qe_ic_cascade_low_ipic+      0x5c)
  2560 :|  + begin   0x0000002b -54407    0.530  
__ipipe_qe_ic_cascade_irq+0x2c (qe_ic_cascade_low_ipic      +0x5c)
  2561 :|  + func               -54407    0.651  __ipipe_handle_irq+0x8 
(__ipipe_qe_ic_cascade_irq+0x38      )
  2562 :|  + func               -54406    0.939  
__ipipe_ack_level_irq+0x8 (__ipipe_handle_irq+0xbc)

*MASK in QUICC (CIMR register bit 11)*
  2563 :|  + func               -54405    0.787  qe_ic_mask_irq+0x8 
(__ipipe_ack_level_irq+0x40)

*XENOMAI SCHEDULER IS INVOKED*
  2576 :|  # func               -54393    0.590  __xnpod_schedule+0x8 
(xnintr_irq_handler+0x1f8)
*
UNMASK in QUICC (done by our user space handler)*
  2595 :   + func               -54377    0.621  __rt_intr_enable+0x8 
[xeno_native] (hisyscall_event+0x      1e4)

*UNMASK in IPIC (after 50ms, i.e. only after the scheduler returns):*
31637 :|   #end     0x0000002b  -518+   2.272  
__ipipe_qe_ic_cascade_irq+0x40 (qe_ic_cascade_low_ipic+      0x5c)
31638 :|   #func                -516+   1.090  ipic_unmask_irq+0x8 
(qe_ic_cascade_low_ipic+0x70)


**

As you can see from the trace above, the interrupt is held masked at the 
IPIC level all the time until the Xenomai scheduler returns and is only 
unmasked after that.

Is it really the way it should be? Shouldn't the interrupt be unmasked 
at the IPIC level right after masking it at the QUICC engine level?

Rgds,
Mak.



On 28/03/12 02:23 PM, Makarand Pradhan wrote:
> Hi Philippe,
>
> On 28/03/12 12:17 PM, Philippe Gerum wrote:
>> The log says your code wants to control when the IRQ is enabled again,
>> by calling rt_intr_enable() from userland. I guess you are setting
>> I_NOAUTOENA too. Correct?
> That is correct. I_NOAUTOENA is used in rt_intr_create. Otherwise the
> level trigerred interrupt will not allow the userland processing of the
> int. The userland handler is very small and it unconditionally
> rt_intr_enables the intr.
>
> Testing indicates that the interrupt is always enabled from user space
> within 250 usec after kernel gets the interrupt.
>
> I have noted that unless I see "#end 0x0000002b" and a hit to the
> ipic_unmask_irq, the next interrupt is not processed.
>
> And this is getting delayed once in a while which causes a delay in
> processing the next interrupt.
>
> So the sequence of events leading to the problem is:
>
> 1. Get interrupt: #begin   0x0000002b noted in ipipe trace
> 2. Intr enabled from user space. Always happens roughly within 250usec.
> 3. #end 0x0000002b noted in ipipe trace where the int is unmasked by ipipe.
>
> When I see the problem, step 3 is delayed. I am trying to capture a
> trace where the begin, int enable and end are captured.
>
> Your thoughts on what might cause this delay would be appreciated.
>
> Rgds,
> Mak.
>
>
>
>
>


-- 
___________________________________________________________________________
NOTICE OF CONFIDENTIALITY:
This e-mail and any attachments may contain confidential and privileged information.  If you are
not the intended recipient, please notify the sender immediately by return e-mail and delete this
e-mail and any copies.  Any dissemination or use of this information by a person other than the
intended recipient is unauthorized and may be illegal.
_____________________________________________________________________

  


[-- Attachment #2: Type: text/html, Size: 8480 bytes --]

Re: [Xenomai-help] Interrupt latency greater than 250ms

[Michael Pustylnik]

[-- Attachment #1.1: Type: text/plain, Size: 5632 bytes --]

The code masking the interrupt in IPIC (call for ipipe_pre_cascade_noeoi())  initially showed up in the patch you recommended (see your email attached).
Later on it was integrated in Xenomai commit "9a5e42df8bccc59620c08caeb4b9fe92dbf94a1b".

As shown in the trail below, it keeps interrupts all the time until the scheduler returns, thus breaking real-time responsiveness.
A solution to this is probably to remove calling ipipe_pre_cascade_noeoi() and let the cascading handler mask the interrupt. Am I missing something? Do you think it is safe to use this solution?


Michael Pustylnik, P.Eng.
Senior Software Engineer
RuggedCom Inc.
www.ruggedcom.com<http://www.ruggedcom.com/>
300 Applewood Crescent
Concord, Ontario, L4K 5C7
Tel:  (905)482-4523
Fax: (905)856-1995



________________________________
From: xenomai-help-bounces@domain.hid [mailto:xenomai-help-bounces@domain.hid] On Behalf Of Makarand Pradhan
Sent: Wednesday, April 04, 2012 12:59 PM
To: Philippe Gerum
Cc: xenomai@xenomai.org
Subject: Re: [Xenomai-help] Interrupt latency greater than 250ms. Question.

Hi Philippe,

We have found that the problem is that the interrupt is unexpectedly held masked at the IPIC level for a long time. Please find the trace below:

 2552 :|  + func               -54413    0.590  qe_ic_cascade_low_ipic+0x8 (__ipipe_ack_irq+0x2c)
 2553 :|  + func               -54412    0.696  qe_ic_get_low_irq+0x8 (qe_ic_cascade_low_ipic+0x30)
 2554 :|  + func               -54411    0.666  irq_linear_revmap+0x8 (qe_ic_get_low_irq+0x5c)

MASK in IPIC (SIMSR_H register bit 1)
 2555 :|  + func               -54411    0.606  ipic_mask_irq+0x8 (qe_ic_cascade_low_ipic+0x48)
 2556 :|  + func               -54410    0.590  irqd_to_hwirq+0x8 (ipic_mask_irq+0x30)
 2557 :|  + func               -54410    0.909  __ipipe_spin_lock_irqsave+0x8 (ipic_mask_irq+0x40)
 2558 :|  # func               -54409    0.727  __ipipe_spin_unlock_irqrestore+0x8 (ipic_mask_irq+0xa8      )
 2559 :|  + func               -54408    0.560  __ipipe_qe_ic_cascade_irq+0x8 (qe_ic_cascade_low_ipic+      0x5c)
 2560 :|  + begin   0x0000002b -54407    0.530  __ipipe_qe_ic_cascade_irq+0x2c (qe_ic_cascade_low_ipic      +0x5c)
 2561 :|  + func               -54407    0.651  __ipipe_handle_irq+0x8 (__ipipe_qe_ic_cascade_irq+0x38      )
 2562 :|  + func               -54406    0.939  __ipipe_ack_level_irq+0x8 (__ipipe_handle_irq+0xbc)

MASK in QUICC (CIMR register bit 11)
 2563 :|  + func               -54405    0.787  qe_ic_mask_irq+0x8 (__ipipe_ack_level_irq+0x40)

XENOMAI SCHEDULER IS INVOKED
 2576 :|  # func               -54393    0.590  __xnpod_schedule+0x8 (xnintr_irq_handler+0x1f8)

UNMASK in QUICC (done by our user space handler)
 2595 :   + func               -54377    0.621  __rt_intr_enable+0x8 [xeno_native] (hisyscall_event+0x      1e4)

UNMASK in IPIC (after 50ms, i.e. only after the scheduler returns):
31637 :|   #end     0x0000002b  -518+   2.272  __ipipe_qe_ic_cascade_irq+0x40 (qe_ic_cascade_low_ipic+      0x5c)
31638 :|   #func                -516+   1.090  ipic_unmask_irq+0x8 (qe_ic_cascade_low_ipic+0x70)

As you can see from the trace above, the interrupt is held masked at the IPIC level all the time until the Xenomai scheduler returns and is only unmasked after that.
Is it really the way it should be? Shouldn't the interrupt be unmasked at the IPIC level right after masking it at the QUICC engine level?
Rgds,
Mak.


On 28/03/12 02:23 PM, Makarand Pradhan wrote:

Hi Philippe,



On 28/03/12 12:17 PM, Philippe Gerum wrote:

The log says your code wants to control when the IRQ is enabled again,

by calling rt_intr_enable() from userland. I guess you are setting

I_NOAUTOENA too. Correct?



That is correct. I_NOAUTOENA is used in rt_intr_create. Otherwise the

level trigerred interrupt will not allow the userland processing of the

int. The userland handler is very small and it unconditionally

rt_intr_enables the intr.



Testing indicates that the interrupt is always enabled from user space

within 250 usec after kernel gets the interrupt.



I have noted that unless I see "#end 0x0000002b" and a hit to the

ipic_unmask_irq, the next interrupt is not processed.



And this is getting delayed once in a while which causes a delay in

processing the next interrupt.



So the sequence of events leading to the problem is:



1. Get interrupt: #begin   0x0000002b noted in ipipe trace

2. Intr enabled from user space. Always happens roughly within 250usec.

3. #end 0x0000002b noted in ipipe trace where the int is unmasked by ipipe.



When I see the problem, step 3 is delayed. I am trying to capture a

trace where the begin, int enable and end are captured.



Your thoughts on what might cause this delay would be appreciated.



Rgds,

Mak.














--

___________________________________________________________________________

NOTICE OF CONFIDENTIALITY:

This e-mail and any attachments may contain confidential and privileged information.  If you are

not the intended recipient, please notify the sender immediately by return e-mail and delete this

e-mail and any copies.  Any dissemination or use of this information by a person other than the

intended recipient is unauthorized and may be illegal.

_____________________________________________________________________





No virus found in this incoming message.
Checked by AVG - www.avg.com
Version: 8.5.455 / Virus Database: 271.1.1/4175 - Release Date: 04/03/12 18:35:00

[-- Attachment #1.2: Type: text/html, Size: 19845 bytes --]

[-- Attachment #2: Type: message/rfc822, Size: 4134 bytes --]

From: Philippe Gerum <rpm@xenomai.org>
To: Lennart Sorensen <lsorense@domain.hid>
Cc: "adeos-main@gna.org" <adeos-main@gna.org>
Subject: Re: [Adeos-main] irq related kernel crash with adeos 3.0.4 powerpc.
Date: Thu, 3 Nov 2011 11:38:55 -0400
Message-ID: <4EB2B58F.3070600@domain.hid>

On 11/03/2011 04:13 PM, Lennart Sorensen wrote:
> On Wed, Nov 02, 2011 at 10:30:57PM +0100, Philippe Gerum wrote:
>> Does this help? If not, then your .config would be welcome.
>>
>> diff --git a/arch/powerpc/sysdev/qe_lib/qe_ic.c b/arch/powerpc/sysdev/qe_lib/qe_ic.c
>> index 707d297..c1e0b7e 100644
>> --- a/arch/powerpc/sysdev/qe_lib/qe_ic.c
>> +++ b/arch/powerpc/sysdev/qe_lib/qe_ic.c
>> @@ -257,6 +257,9 @@ static struct irq_chip qe_ic_irq_chip = {
>>   	.irq_unmask = qe_ic_unmask_irq,
>>   	.irq_mask = qe_ic_mask_irq,
>>   	.irq_mask_ack = qe_ic_mask_irq,
>> +#ifdef CONFIG_IPIPE
>> +	.irq_eoi = qe_ic_mask_irq,
>> +#endif
>>   };
>>
>>   static int qe_ic_host_match(struct irq_host *h, struct device_node *node)
> 
> No, that unfortunately didn't help.
> 
> So here is the capture of the entire boot, and the .config file I am using.
> 

Thanks. Meanwhile you may want to try this one. This is aimed at fixing an issue with acking
cascaded IPIC irqs over the pipeline.

http://download.gna.org/adeos/patches/v3.x/powerpc/adeos-ipipe-3.0.8-powerpc-2.13-04.patch

> 
> 
> 
> _______________________________________________
> Adeos-main mailing list
> Adeos-main@domain.hid
> https://mail.gna.org/listinfo/adeos-main


-- 
Philippe.

No virus found in this incoming message.
Checked by AVG - www.avg.com 
Version: 8.5.455 / Virus Database: 271.1.1/4327 - Release Date: 04/10/12 19:55:00

Re: [Xenomai-help] Interrupt latency greater than 250ms

[Philippe Gerum]

On 04/12/2012 05:45 PM, Michael Pustylnik wrote:
> The code masking the interrupt in IPIC (call for
> ipipe_pre_cascade_noeoi()) initially showed up in the patch you
> recommended (see your email attached).
>
> Later on it was integrated in Xenomai commit
> "9a5e42df8bccc59620c08caeb4b9fe92dbf94a1b".
>
> As shown in the trail below, it keeps interrupts all the time until the
> scheduler returns, thus breaking real-time responsiveness.
>
> A solution to this is probably to remove calling
> ipipe_pre_cascade_noeoi() and let the cascading handler mask the
> interrupt. Am I missing something? Do you think it is safe to use this
> solution?

No, as interrupts could be re-enabled before invoking the handler, you 
would get an IRQ storm.

The solution is to rework the cascaded IRQ handling in the generic 
pipeline core, so that all decoded IRQs are acked/masked, then the 
multiplex IRQ unmasked, then all the decoded IRQ handlers fired when 
syncing the relevant pipeline stage.

A fix for this will follow when enough testing will have been done on 
arm and ppc, to check whether that logic does not raise other issue.

>
> Michael Pustylnik, P.Eng.
> Senior Software Engineer
> *RuggedCom Inc.*
> www.ruggedcom.com <http://www.ruggedcom.com/>
> 300 Applewood Crescent
> Concord, Ontario, L4K 5C7
> Tel: (905)482-4523
> Fax: (905)856-1995
>
> ------------------------------------------------------------------------
>
> *From:*xenomai-help-bounces@domain.hid
> [mailto:xenomai-help-bounces@domain.hid] *On Behalf Of *Makarand Pradhan
> *Sent:* Wednesday, April 04, 2012 12:59 PM
> *To:* Philippe Gerum
> *Cc:* xenomai@xenomai.org
> *Subject:* Re: [Xenomai-help] Interrupt latency greater than 250ms.
> Question.
>
> Hi Philippe,
>
> We have found that the problem is that the interrupt is unexpectedly
> held masked at the IPIC level for a long time. Please find the trace below:
>
> 2552 :| + func -54413 0.590 qe_ic_cascade_low_ipic+0x8
> (__ipipe_ack_irq+0x2c)
> 2553 :| + func -54412 0.696 qe_ic_get_low_irq+0x8
> (qe_ic_cascade_low_ipic+0x30)
> 2554 :| + func -54411 0.666 irq_linear_revmap+0x8 (qe_ic_get_low_irq+0x5c)
>
> *MASK in IPIC (SIMSR_H register bit 1)*
> 2555 :| + func -54411 0.606 ipic_mask_irq+0x8 (qe_ic_cascade_low_ipic+0x48)
> 2556 :| + func -54410 0.590 irqd_to_hwirq+0x8 (ipic_mask_irq+0x30)
> 2557 :| + func -54410 0.909 __ipipe_spin_lock_irqsave+0x8
> (ipic_mask_irq+0x40)
> 2558 :| # func -54409 0.727 __ipipe_spin_unlock_irqrestore+0x8
> (ipic_mask_irq+0xa8 )
> 2559 :| + func -54408 0.560 __ipipe_qe_ic_cascade_irq+0x8
> (qe_ic_cascade_low_ipic+ 0x5c)
> 2560 :| + begin 0x0000002b -54407 0.530 __ipipe_qe_ic_cascade_irq+0x2c
> (qe_ic_cascade_low_ipic +0x5c)
> 2561 :| + func -54407 0.651 __ipipe_handle_irq+0x8
> (__ipipe_qe_ic_cascade_irq+0x38 )
> 2562 :| + func -54406 0.939 __ipipe_ack_level_irq+0x8
> (__ipipe_handle_irq+0xbc)
>
> *MASK in QUICC (CIMR register bit 11)*
> 2563 :| + func -54405 0.787 qe_ic_mask_irq+0x8 (__ipipe_ack_level_irq+0x40)
>
> *XENOMAI SCHEDULER IS INVOKED*
> 2576 :| # func -54393 0.590 __xnpod_schedule+0x8 (xnintr_irq_handler+0x1f8)
> *
> UNMASK in QUICC (done by our user space handler)*
> 2595 : + func -54377 0.621 __rt_intr_enable+0x8 [xeno_native]
> (hisyscall_event+0x 1e4)
>
> *UNMASK in IPIC (after 50ms, i.e. only after the scheduler returns):*
> 31637 :| #end 0x0000002b -518+ 2.272 __ipipe_qe_ic_cascade_irq+0x40
> (qe_ic_cascade_low_ipic+ 0x5c)
> 31638 :| #func -516+ 1.090 ipic_unmask_irq+0x8 (qe_ic_cascade_low_ipic+0x70)
>
> As you can see from the trace above, the interrupt is held masked at the
> IPIC level all the time until the Xenomai scheduler returns and is only
> unmasked after that.
>
> Is it really the way it should be? Shouldn’t the interrupt be unmasked
> at the IPIC level right after masking it at the QUICC engine level?
>
> Rgds,
> Mak.
>
>
>
> On 28/03/12 02:23 PM, Makarand Pradhan wrote:
>
> Hi Philippe,
>
>
>
> On 28/03/12 12:17 PM, Philippe Gerum wrote:
>
>> The log says your code wants to control when the IRQ is enabled again,
>> by calling rt_intr_enable() from userland. I guess you are setting
>> I_NOAUTOENA too. Correct?
>
>
> That is correct. I_NOAUTOENA is used in rt_intr_create. Otherwise the
>
> level trigerred interrupt will not allow the userland processing of the
>
> int. The userland handler is very small and it unconditionally
>
> rt_intr_enables the intr.
>
>
>
> Testing indicates that the interrupt is always enabled from user space
>
> within 250 usec after kernel gets the interrupt.
>
>
>
> I have noted that unless I see"#end 0x0000002b"  and a hit to the
>
> ipic_unmask_irq, the next interrupt is not processed.
>
>
>
> And this is getting delayed once in a while which causes a delay in
>
> processing the next interrupt.
>
>
>
> So the sequence of events leading to the problem is:
>
>
>
> 1. Get interrupt: #begin      0x0000002b noted in ipipe trace
>
> 2. Intr enabled from user space. Always happens roughly within 250usec.
>
> 3. #end 0x0000002b noted in ipipe trace where the int is unmasked by ipipe.
>
>
>
> When I see the problem, step 3 is delayed. I am trying to capture a
>
> trace where the begin, int enable and end are captured.
>
>
>
> Your thoughts on what might cause this delay would be appreciated.
>
>
>
> Rgds,
>
> Mak.
>
>
>
>
>
>
>
>
>
>
>
>
>
>
> --
>
> ___________________________________________________________________________
>
> NOTICE OF CONFIDENTIALITY:
>
> This e-mail and any attachments may contain confidential and privileged information.  If you are
>
> not the intended recipient, please notify the sender immediately by return e-mail and delete this
>
> e-mail and any copies.    Any dissemination or use of this information by a person other than the
>
> intended recipient is unauthorized and may be illegal.
>
> _____________________________________________________________________
>
>
>
>
>
> No virus found in this incoming message.
> Checked by AVG - www.avg.com
> Version: 8.5.455 / Virus Database: 271.1.1/4175 - Release Date: 04/03/12
> 18:35:00
>


-- 
Philippe.

Re: [Xenomai-help] Interrupt latency greater than 250ms

[Philippe Gerum]

On 04/12/2012 05:57 PM, Philippe Gerum wrote:
> On 04/12/2012 05:45 PM, Michael Pustylnik wrote:
>> The code masking the interrupt in IPIC (call for
>> ipipe_pre_cascade_noeoi()) initially showed up in the patch you
>> recommended (see your email attached).
>>
>> Later on it was integrated in Xenomai commit
>> "9a5e42df8bccc59620c08caeb4b9fe92dbf94a1b".
>>
>> As shown in the trail below, it keeps interrupts all the time until the
>> scheduler returns, thus breaking real-time responsiveness.
>>
>> A solution to this is probably to remove calling
>> ipipe_pre_cascade_noeoi() and let the cascading handler mask the
>> interrupt. Am I missing something? Do you think it is safe to use this
>> solution?
> 
> No, as interrupts could be re-enabled before invoking the handler, you 
> would get an IRQ storm.
> 
> The solution is to rework the cascaded IRQ handling in the generic 
> pipeline core, so that all decoded IRQs are acked/masked, then the 
> multiplex IRQ unmasked, then all the decoded IRQ handlers fired when 
> syncing the relevant pipeline stage.
> 
> A fix for this will follow when enough testing will have been done on 
> arm and ppc, to check whether that logic does not raise other issue.
> 

This is the patch series fixing the issue in the newest pipeline "core"
implementation, currently for kernel 3.2. Something along these lines would work for
earlier kernels as well.

http://git.denx.de/?p=ipipe-2.6.git;a=commit;h=0a9a7b4e4ce9f4196a574471ad58f4389820c438
http://git.denx.de/?p=ipipe-2.6.git;a=commit;h=f2ca3c2baf58bf43f4c00fb05b91b16da9fd77f2
http://git.denx.de/?p=ipipe-2.6.git;a=commit;h=a4b909ccf80c5afa132aa7a9ccf0022cb8a6e6f2
http://git.denx.de/?p=ipipe-2.6.git;a=commit;h=b47bc773ff07ce886aaf490921ac59e98ed9575a

>>
>> Michael Pustylnik, P.Eng.
>> Senior Software Engineer
>> *RuggedCom Inc.*
>> www.ruggedcom.com <http://www.ruggedcom.com/>
>> 300 Applewood Crescent
>> Concord, Ontario, L4K 5C7
>> Tel: (905)482-4523
>> Fax: (905)856-1995
>>
>> ------------------------------------------------------------------------
>>
>> *From:*xenomai-help-bounces@domain.hid
>> [mailto:xenomai-help-bounces@domain.hid] *On Behalf Of *Makarand Pradhan
>> *Sent:* Wednesday, April 04, 2012 12:59 PM
>> *To:* Philippe Gerum
>> *Cc:* xenomai@xenomai.org
>> *Subject:* Re: [Xenomai-help] Interrupt latency greater than 250ms.
>> Question.
>>
>> Hi Philippe,
>>
>> We have found that the problem is that the interrupt is unexpectedly
>> held masked at the IPIC level for a long time. Please find the trace 
>> below:
>>
>> 2552 :| + func -54413 0.590 qe_ic_cascade_low_ipic+0x8
>> (__ipipe_ack_irq+0x2c)
>> 2553 :| + func -54412 0.696 qe_ic_get_low_irq+0x8
>> (qe_ic_cascade_low_ipic+0x30)
>> 2554 :| + func -54411 0.666 irq_linear_revmap+0x8 
>> (qe_ic_get_low_irq+0x5c)
>>
>> *MASK in IPIC (SIMSR_H register bit 1)*
>> 2555 :| + func -54411 0.606 ipic_mask_irq+0x8 
>> (qe_ic_cascade_low_ipic+0x48)
>> 2556 :| + func -54410 0.590 irqd_to_hwirq+0x8 (ipic_mask_irq+0x30)
>> 2557 :| + func -54410 0.909 __ipipe_spin_lock_irqsave+0x8
>> (ipic_mask_irq+0x40)
>> 2558 :| # func -54409 0.727 __ipipe_spin_unlock_irqrestore+0x8
>> (ipic_mask_irq+0xa8 )
>> 2559 :| + func -54408 0.560 __ipipe_qe_ic_cascade_irq+0x8
>> (qe_ic_cascade_low_ipic+ 0x5c)
>> 2560 :| + begin 0x0000002b -54407 0.530 __ipipe_qe_ic_cascade_irq+0x2c
>> (qe_ic_cascade_low_ipic +0x5c)
>> 2561 :| + func -54407 0.651 __ipipe_handle_irq+0x8
>> (__ipipe_qe_ic_cascade_irq+0x38 )
>> 2562 :| + func -54406 0.939 __ipipe_ack_level_irq+0x8
>> (__ipipe_handle_irq+0xbc)
>>
>> *MASK in QUICC (CIMR register bit 11)*
>> 2563 :| + func -54405 0.787 qe_ic_mask_irq+0x8 
>> (__ipipe_ack_level_irq+0x40)
>>
>> *XENOMAI SCHEDULER IS INVOKED*
>> 2576 :| # func -54393 0.590 __xnpod_schedule+0x8 
>> (xnintr_irq_handler+0x1f8)
>> *
>> UNMASK in QUICC (done by our user space handler)*
>> 2595 : + func -54377 0.621 __rt_intr_enable+0x8 [xeno_native]
>> (hisyscall_event+0x 1e4)
>>
>> *UNMASK in IPIC (after 50ms, i.e. only after the scheduler returns):*
>> 31637 :| #end 0x0000002b -518+ 2.272 __ipipe_qe_ic_cascade_irq+0x40
>> (qe_ic_cascade_low_ipic+ 0x5c)
>> 31638 :| #func -516+ 1.090 ipic_unmask_irq+0x8 
>> (qe_ic_cascade_low_ipic+0x70)
>>
>> As you can see from the trace above, the interrupt is held masked at the
>> IPIC level all the time until the Xenomai scheduler returns and is only
>> unmasked after that.
>>
>> Is it really the way it should be? Shouldn’t the interrupt be unmasked
>> at the IPIC level right after masking it at the QUICC engine level?
>>
>> Rgds,
>> Mak.
>>
>>
>>
>> On 28/03/12 02:23 PM, Makarand Pradhan wrote:
>>
>> Hi Philippe,
>>
>>
>>
>> On 28/03/12 12:17 PM, Philippe Gerum wrote:
>>
>>> The log says your code wants to control when the IRQ is enabled again,
>>> by calling rt_intr_enable() from userland. I guess you are setting
>>> I_NOAUTOENA too. Correct?
>>
>>
>> That is correct. I_NOAUTOENA is used in rt_intr_create. Otherwise the
>>
>> level trigerred interrupt will not allow the userland processing of the
>>
>> int. The userland handler is very small and it unconditionally
>>
>> rt_intr_enables the intr.
>>
>>
>>
>> Testing indicates that the interrupt is always enabled from user space
>>
>> within 250 usec after kernel gets the interrupt.
>>
>>
>>
>> I have noted that unless I see"#end 0x0000002b" and a hit to the
>>
>> ipic_unmask_irq, the next interrupt is not processed.
>>
>>
>>
>> And this is getting delayed once in a while which causes a delay in
>>
>> processing the next interrupt.
>>
>>
>>
>> So the sequence of events leading to the problem is:
>>
>>
>>
>> 1. Get interrupt: #begin 0x0000002b noted in ipipe trace
>>
>> 2. Intr enabled from user space. Always happens roughly within 250usec.
>>
>> 3. #end 0x0000002b noted in ipipe trace where the int is unmasked by 
>> ipipe.
>>
>>
>>
>> When I see the problem, step 3 is delayed. I am trying to capture a
>>
>> trace where the begin, int enable and end are captured.
>>
>>
>>
>> Your thoughts on what might cause this delay would be appreciated.
>>
>>
>>
>> Rgds,
>>
>> Mak.
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>
>> -- 
>>
>> ___________________________________________________________________________ 
>>
>>
>> NOTICE OF CONFIDENTIALITY:
>>
>> This e-mail and any attachments may contain confidential and 
>> privileged information. If you are
>>
>> not the intended recipient, please notify the sender immediately by 
>> return e-mail and delete this
>>
>> e-mail and any copies. Any dissemination or use of this information by 
>> a person other than the
>>
>> intended recipient is unauthorized and may be illegal.
>>
>> _____________________________________________________________________
>>
>>
>>
>>
>>
>> No virus found in this incoming message.
>> Checked by AVG - www.avg.com
>> Version: 8.5.455 / Virus Database: 271.1.1/4175 - Release Date: 04/03/12
>> 18:35:00
>>
> 
> 


-- 
Philippe.

Re: [Xenomai-help] Interrupt latency greater than 250ms

[Gilles Chanteperdrix]

On 04/26/2012 12:39 PM, Philippe Gerum wrote:
> On 04/12/2012 05:57 PM, Philippe Gerum wrote:
>> On 04/12/2012 05:45 PM, Michael Pustylnik wrote:
>>> The code masking the interrupt in IPIC (call for
>>> ipipe_pre_cascade_noeoi()) initially showed up in the patch you
>>> recommended (see your email attached).
>>>
>>> Later on it was integrated in Xenomai commit
>>> "9a5e42df8bccc59620c08caeb4b9fe92dbf94a1b".
>>>
>>> As shown in the trail below, it keeps interrupts all the time until the
>>> scheduler returns, thus breaking real-time responsiveness.
>>>
>>> A solution to this is probably to remove calling
>>> ipipe_pre_cascade_noeoi() and let the cascading handler mask the
>>> interrupt. Am I missing something? Do you think it is safe to use this
>>> solution?
>>
>> No, as interrupts could be re-enabled before invoking the handler, you 
>> would get an IRQ storm.
>>
>> The solution is to rework the cascaded IRQ handling in the generic 
>> pipeline core, so that all decoded IRQs are acked/masked, then the 
>> multiplex IRQ unmasked, then all the decoded IRQ handlers fired when 
>> syncing the relevant pipeline stage.
>>
>> A fix for this will follow when enough testing will have been done on 
>> arm and ppc, to check whether that logic does not raise other issue.
>>
> 
> This is the patch series fixing the issue in the newest pipeline "core"
> implementation, currently for kernel 3.2. Something along these lines would work for
> earlier kernels as well.
> 
> http://git.denx.de/?p=ipipe-2.6.git;a=commit;h=0a9a7b4e4ce9f4196a574471ad58f4389820c438
> http://git.denx.de/?p=ipipe-2.6.git;a=commit;h=f2ca3c2baf58bf43f4c00fb05b91b16da9fd77f2
> http://git.denx.de/?p=ipipe-2.6.git;a=commit;h=a4b909ccf80c5afa132aa7a9ccf0022cb8a6e6f2
> http://git.denx.de/?p=ipipe-2.6.git;a=commit;h=b47bc773ff07ce886aaf490921ac59e98ed9575a

I have done a backport of this change for a pre ipipe-core (ARM) I-pipe. The diff is here:
http://git.xenomai.org/?p=ipipe-gch.git;a=commitdiff;h=81bfc05c4716b76e79f5e486baf4c52015a3b92c;hp=7d31a77f62acb57eb83409c8f514d0f2dacf7fe5

-- 
                                                                Gilles.