Re: [Xenomai] A possible mis-interaction between CONFIG_PREEMPT and GPIO IRQ handling for ARM, leading to extreme latency

[Gilles Chanteperdrix <gilles.chanteperdrix@xenomai.org>]

On 05/22/2012 02:31 AM, Mitchell Tasman wrote:
> Hi.  I'm running an OMAP DM3725-based board with a 2.6.38.8 kernel, a 
> mid-May 2012 git snapshot of xenomai-2.6, and a backport (really just 
> application) of the patch that Gilles referenced in the "IRQ latency" 
> thread last week:
> 
> http://git.xenomai.org/?p=ipipe-gch.git;a=commit;h=81bfc05c4716b76e79f5e486baf4c52015a3b92c
> 
> Of perhaps critical note is that I'm building Linux with CONFIG_PREEMPT. 
>   The possible problem that I'm about to describe appears specific to 
> CONFIG_PREEMPT being defined.  To date, I have not been able to trigger 
> the problem if I rebuild the kernel with CONFIG_NONE.
> 
> Almost exactly as with last week's "IRQ latency" thread, I have a GPIO 
> (164 in my case) configured as an input, and configured to trigger a 
> real-time interrupt upon a falling edge of the signal.  The virtual 
> interrupt number assigned by Xenomai for that GPIO is 324 (0x144 hex).
> 
> What I have found via I-Pipe tracing is that sometimes many, many 
> milliseconds elapse within the call to __ipipe_handle_irq() from the 
> inlined function ipipe_handle_chained_irq() in gpio_demux_inner(), e.g.:
> 
>> :|   +begin   0x00000144 -33547    0.925  gpio_demux_inner+0x74 (gpio_irq_handler+0x178)
>> :|   +end     0x00000144  -196+   1.370  gpio_demux_inner+0x88 (gpio_irq_handler+0x178)
> 
> The present I-Pipe for 2.6.38.8 for ARM patch set patches the 
> plat-omap-specific implementation of gpio_irq_handler() to 
> unconditionally disable unmasking of the GPIO bank interrupt until just 
> before that function returns.  So, if we somehow get "stuck" in 
> gpio_demux_inner() for an extended period, the bank interrupt remains 
> masked, and new GPIO line state transitions will go unhandled during 
> that period.
> 
> I find that the GPIO interrupt is processed as would be expected, and 
> any RT tasks that have work to do are scheduled to do that work.
> 
> What appears to be going awry is that when it becomes time to return to 
> Linux domain, the I-Pipe machinery finds that there is an interrupt 
> pending for that domain.  Rather than gpio_demux_inner() running to 
> completion, and winding back to gpio_handle_irq(), the new interrupt is 
> processed, and it can be many, many milliseconds before 
> gpio_demux_inner() gets a chance to run and finish its work.
> 
> As it happens, my code is the source of that new (virtual) interrupt, 
> and it's possible that I'm exercising a use case that hasn't been 
> considered.  On the other hand, I could easily imagine other cases where 
> interrupts happen to appear at arbitrary points along the timeline.
> 
> The sequence of events is as follows:
> 
> 1. The interrupt fires while the system is running in the Linux domain, 
> and the real-time interrupt handler for GPIO 164 calls rt_sem_v() to 
> wake up a native Xenomai kernel task that is blocked on rt_sem_p().
> I can see that from Xenomai's perspective, processing of the interrupt 
> finishes just after that point, e.g. around -33527 in this sample:
> 
>> :|   +func               -33558    0.814  __ipipe_grab_irq+0x10 (__irq_svc+0x3c)
>> :|   +begin   0xffffffff -33557    0.851  __ipipe_grab_irq+0x60 (__irq_svc+0x3c)
>> :|   +func               -33556+   1.481  __ipipe_handle_irq+0x14 (__ipipe_grab_irq+0x6c)
>> :|   +func               -33555+   1.037  __ipipe_set_irq_pending+0x10 (__ipipe_handle_irq+0x120)
>> :|   +func               -33554    0.925  gpio_irq_handler+0x10 (__ipipe_handle_irq+0x150)
>> :|   +func               -33553+   1.333  omap_mask_ack_irq+0x10 (gpio_irq_handler+0x2c)
>> :|   +func               -33552    1.000  irq_get_irq_data+0x10 (gpio_irq_handler+0x34)
>> :|   +(0x01)  0xfb058018 -33551+   1.777  gpio_irq_handler+0x1b0 (__ipipe_handle_irq+0x150) /* custom trace point */
>> :|   +(0x02)  0x00000010 -33549    0.629  gpio_irq_handler+0x15c (__ipipe_handle_irq+0x150) /* custom trace point */
>> :|   +func               -33548    0.740  gpio_demux_inner+0x10 (gpio_irq_handler+0x178)
>> :|   +begin   0x00000144 -33547    0.925  gpio_demux_inner+0x74 (gpio_irq_handler+0x178)
>> :|   +func               -33547    0.740  __ipipe_handle_irq+0x14 (gpio_demux_inner+0x80)
>> :|   +func               -33546    0.925  __ipipe_set_irq_pending+0x10 (__ipipe_handle_irq+0x120)
>> :|   +func               -33545    0.925  __ipipe_ack_edge_irq+0x10 (__ipipe_handle_irq+0x150)
>> :|   +func               -33544    0.962  gpio_ack_irq+0x10 (__ipipe_ack_edge_irq+0x24)
>> :|   +func               -33543+   1.444  __ipipe_walk_pipeline+0x10 (__ipipe_handle_irq+0x1a0)
>> :|  + func               -33542    0.962  ipipe_suspend_domain+0x10 (__ipipe_walk_pipeline+0x68)
>> :|  + func               -33541+   1.037  __ipipe_sync_stage+0x14 (ipipe_suspend_domain+0x9c)
>> :|  # func               -33540+   1.592  xnintr_irq_handler+0x14 (__ipipe_sync_stage+0x124)
>> :|  # func               -33538    1.000  my_isr_rt+0x10 [phy_srv] (xnintr_irq_handler+0x60)
> /* do a bit of work */
>> :|  # func               -33533    0.703  rt_sem_v+0x10 (physrv_htm_isr_rt+0x24 [phy_srv])
>> :|  # func               -33532    1.000  xnsynch_wakeup_one_sleeper+0x10 (rt_sem_v+0x64)
>> :|  # func               -33531    0.925  xnpod_resume_thread+0x10 (xnsynch_wakeup_one_sleeper+0xac)
>> :|  # [   -1] -<?>-   60 -33530+   1.851  xnpod_resume_thread+0x64 (xnsynch_wakeup_one_sleeper+0xac)
>> :|  # func               -33528+   1.222  rthal_irq_end+0x10 (xnintr_irq_handler+0x138)
>> :|  # func               -33527+   1.333  __ipipe_end_edge_irq+0x10 (rthal_irq_end+0x3c)
>> :|  # func               -33526+   1.037  __xnpod_schedule+0x14 (xnintr_irq_handler+0x1cc)
>> :|  # [ 1633] -<?>-   -1 -33525    0.777  __xnpod_schedule+0x9c (xnintr_irq_handler+0x1cc)
>> :|  # func               -33524+   1.555  xnsched_pick_next+0x10 (__xnpod_schedule+0xd4)
>> :|  # func               -33523    0.888  ipipe_mute_pic+0x10 (__xnpod_schedule+0x17c)
>> :|  # func               -33522+   2.111  omap3_intc_mute+0x10 (ipipe_mute_pic+0x1c)
>> :|  # func               -33520    0.703  ipipe_unstall_pipeline_head+0x10 (__xnpod_schedule+0x2ac)
>> :|  + end     0x80000000 -33519+   1.851  ipipe_unstall_pipeline_head+0x88 (__xnpod_schedule+0x2ac)
> 
> 
> 2.  That task that had been waiting on rt_sem_p() awakens and collects 
> the data signaled by the GPIO transition, and in turn wakes up another 
> native Xenomai kernel task via rt_sem_v().
> 
> 3.  The second task invokes a write entry point on an RTDM driver.
> 
> 4.  The RTDM driver may decide to place a copy of the data in a known 
> location in kernel memory, and call rtdm_nrtsig_pend() to invoke a 
> non-realtime handler in Linux kernel space.  This results in a virtual 
> interrupt being generated for the Linux domain, e.g.:
> 
>> :   + func               -33238+   1.037  ipipe_trigger_irq+0x10 (my_write+0x84 [my_rtdm_driver])
>> :|  + begin   0x80000001 -33237    0.925  ipipe_trigger_irq+0x74 (my_write+0x84 [my_rtdm_driver])
>> :|  + func               -33236+   1.481  __ipipe_handle_irq+0x14 (ipipe_trigger_irq+0x80)
>> :|  + func               -33235+   1.370  __ipipe_set_irq_pending+0x10 (__ipipe_handle_irq+0x120)
>> :|  + end     0x80000001 -33233+   1.555  ipipe_trigger_irq+0x90 (my_write+0x84 [my_rtdm_driver])
> 
> 5.  The non-realtime handler schedules a softint via tasklet_schedule()
> 
> 6.  The tasklet retrieves the data posted by the real-time task.
> 
> My hope would be that steps 5 and 6 would only run after 
> gpio_demux_inner() had a chance to unwind back to gpio_handle_irq(). 
> Instead, upon transition back to the Linux domain, the new interrupt is 
> processed instead, followed by the soft IRQ, and then Linux does various 
> housekeeping tasks, here's an example snippet:
> 
>> :   + func               -33119    1.000  xnsched_finish_unlocked_switch+0x10 (__xnpod_schedule+0x4c0)
>> :|  + begin   0x80000000 -33118+   1.037  xnsched_finish_unlocked_switch+0x30 (__xnpod_schedule+0x4c0)
>> :|  # [ 1633] -<?>-   -1 -33116+   1.481  __xnpod_schedule+0x4e4 (xnintr_irq_handler+0x1cc)
>> :|   +func               -33115+   1.222  __ipipe_sync_stage+0x14 (ipipe_suspend_domain+0x9c)
>> :|   #end     0x80000000 -33114    0.851  __ipipe_sync_stage+0xf8 (ipipe_suspend_domain+0x9c)
>> :    #func               -33113    0.666  __ipipe_do_IRQ+0x10 (__ipipe_sync_stage+0x1bc)
>> :    #func               -33112+   1.111  asm_do_IRQ+0x10 (__ipipe_do_IRQ+0x1c)
>> :    #func               -33111    0.851  irq_enter+0x10 (asm_do_IRQ+0x28)
>> :    #func               -33110    0.925  rcu_exit_nohz+0x10 (irq_enter+0x18)
>> :    #func               -33109+   1.407  idle_cpu+0x10 (irq_enter+0x20)
>> :    #func               -33108    0.814  ipipe_check_context+0x10 (irq_enter+0x60)
>> :    #func               -33107+   1.074  __ipipe_noack_irq+0x10 (asm_do_IRQ+0x84)
>> :    #func               -33106    0.888  irq_exit+0x10 (asm_do_IRQ+0x88)
>> :    #func               -33105+   1.111  ipipe_check_context+0x10 (irq_exit+0x1c)
>> :    #func               -33104    1.000  rcu_enter_nohz+0x10 (irq_exit+0x60)
>> :    #func               -33103    0.703  idle_cpu+0x10 (irq_exit+0x68)
>> :    #func               -33102    0.740  ipipe_check_context+0x10 (irq_exit+0xa8)
>> :|   #begin   0x80000000 -33102    0.888  __ipipe_sync_stage+0x1d4 (ipipe_suspend_domain+0x9c)
>> :|   #end     0x80000000 -33101    0.592  __ipipe_sync_stage+0xf8 (ipipe_suspend_domain+0x9c)
>> :    #func               -33100    0.888  irq_enter+0x10 (__ipipe_sync_stage+0x14c)
>> :    #func               -33099    0.666  rcu_exit_nohz+0x10 (irq_enter+0x18)
>> :    #func               -33099    0.629  idle_cpu+0x10 (irq_enter+0x20)
>> :    #func               -33098+   1.148  ipipe_check_context+0x10 (irq_enter+0x60)
> /* __tasklet_schedule */
> ...
>> :    #func               -33091    0.592  __ipipe_restore_root+0x10 (__tasklet_schedule+0x12c)
>> :    #func               -33090    0.962  ipipe_check_context+0x10 (__ipipe_restore_root+0x20)
>> :|   #begin   0x80000001 -33089    0.666  __ipipe_restore_root+0x40 (__tasklet_schedule+0x12c)
>> :|   #end     0x80000001 -33088    0.666  __ipipe_restore_root+0x60 (__tasklet_schedule+0x12c)
>> :    #func               -33088    0.851  irq_exit+0x10 (__ipipe_sync_stage+0x168)
>> :    #func               -33087    0.740  ipipe_check_context+0x10 (irq_exit+0x1c)
>> :    #func               -33086+   1.111  __do_softirq+0x14 (irq_exit+0x5c)
> ...
> 
> We don't seem to get around to finishing gpio_demux_inner() until time -196.
> 
>> :|   +begin   0x80000000  -219+   1.481  schedule+0x5ac (schedule_timeout+0x2ec)
>> :|   +func                -218    1.000  __ipipe_switch_to_notifier_call_chain+0x10 (__switch_to+0x2c)
>> :|   #func                -217    0.666  atomic_notifier_call_chain+0x14 (__ipipe_switch_to_notifier_call_chain+0x6c)
>> :|   #func                -216    0.629  __atomic_notifier_call_chain+0x14 (atomic_notifier_call_chain+0x28)
>> :|   #func                -216    0.962  ipipe_check_context+0x10 (__atomic_notifier_call_chain+0x3c)
>> :|   #func                -215    0.703  notifier_call_chain+0x10 (__atomic_notifier_call_chain+0x64)
>> :|   #func                -214    0.851  vfp_notifier+0x10 (notifier_call_chain+0x3c)
>> :|   #func                -213+   1.111  thumbee_notifier+0x10 (notifier_call_chain+0x3c)
>> :|   #func                -212+   1.666  ipipe_check_context+0x10 (__atomic_notifier_call_chain+0x70
>> :|   +end     0x80000000  -210+   1.111  schedule+0x5d4 (preempt_schedule_irq+0x64)
>> :    +func                -209    0.666  finish_task_switch+0x10 (schedule+0x60c)
>> :|   +begin   0x80000001  -209    0.703  finish_task_switch+0x40 (schedule+0x60c)
>> :|   #end     0x80000001  -208    0.925  finish_task_switch+0x60 (schedule+0x60c)
>> :    #func                -207    0.888  __ipipe_unstall_root+0x10 (finish_task_switch+0x8c)
>> :|   #begin   0x80000000  -206    0.666  __ipipe_unstall_root+0x2c (finish_task_switch+0x8c)
>> :|   #func                -205    0.925  ipipe_check_context+0x10 (__ipipe_unstall_root+0x34)
>> :|   +end     0x80000000  -205    0.740  __ipipe_unstall_root+0x68 (finish_task_switch+0x8c)
>> :    +func                -204+   1.629  ipipe_check_context+0x10 (schedule+0x664)
>> :|   +begin   0x80000001  -202    0.814  preempt_schedule_irq+0x7c (__ipipe_preempt_schedule_irq+0x84)
>> :|   #end     0x80000001  -201    0.592  preempt_schedule_irq+0x9c (__ipipe_preempt_schedule_irq+0x84)
>> :    #func                -201+   1.148  ipipe_check_context+0x10 (preempt_schedule_irq+0xa8)
>> :|   #begin   0x80000000  -200+   3.185  __ipipe_preempt_schedule_irq+0x9c (__ipipe_sync_stage+0x188)
>> :|   +end     0x00000144  -196+   1.370  gpio_demux_inner+0x88 (gpio_irq_handler+0x178)
>> :|   +func                -195+   2.962  gpio_demux_inner+0x10 (gpio_irq_handler+0x18c)
>> :|   +(0x02)  0x00000010  -192    0.629  gpio_irq_handler+0x15c (__ipipe_handle_irq+0x150) /* a custom trace point */
>> :|   +func                -191    0.925  gpio_demux_inner+0x10 (gpio_irq_handler+0x178)
>> :|   +begin   0x00000144  -191+   1.111  gpio_demux_inner+0x74 (gpio_irq_handler+0x178)
>> :|   +func                -189+   1.518  __ipipe_handle_irq+0x14 (gpio_demux_inner+0x80)
>> :|   +func                -188+   2.148  __ipipe_set_irq_pending+0x10 (__ipipe_handle_irq+0x120)
>> :|   +func                -186+   1.074  __ipipe_ack_edge_irq+0x10 (__ipipe_handle_irq+0x150)
>> :|   +func                -185+   1.370  gpio_ack_irq+0x10 (__ipipe_ack_edge_irq+0x24)
>> :|   +func                -183+   1.333  __ipipe_walk_pipeline+0x10 (__ipipe_handle_irq+0x1a0)

The problem is here: __ipipe_walk_pipeline should not be called before
gpio_demux_inner or gpio_irq_handler are finished (and have unmasked the
parent irq). This is what the patch is supposed to avoid.


-- 
                                                                Gilles.