[Xenomai] Gpio: IRQ handler is called ~4ms after state change

[Xenomai] Gpio: IRQ handler is called ~4ms after state change

[Giulio Moro]

Hi,
I ported this GPIO driver from Xenomai 2.6 to Xenomai 3 and I run it on the Beaglebone Black: https://github.com/giuliomoro/gpio-irq-rtdm/

TheRTDM  irq_handler (in gpio_irq_rtdm.c) toggles a pin "kernel timingpin" as soon as the IRQ is received.
The test program registers a pin to monitor and sleeps in a ioctl() waiting for the pin to go low. When the kernel unblocks it from the ioctl(), the task toggles another pin "user timingpin".

The original authors claims that, on the BeagleBone Black, with Xenomai 2.6:
* the kernel timingpin will change roughly 5us after the test pin is toggled by an external clock
*  the user timingpin will change roughly 5-10us after the kernel timingpin

The above values make sense to me.

My observations, on the BeagleBone Black, Linux 4.4.65 with Xenomai 3.0.5:
* the kernel timingpin will change roughly 4ms (milliseconds) after the test pin is toggled by an external clock
* the user timingpin will change 40 to 60us (microseconds) after the kernel timingpin

So it seems that in my case it takes a long time for the irq_handler() to be called after the test pin is toggled.
Am I doing something wrong in the kernel module ?

See in particular irq_handler() and gpio_irq_ioctl_rt() in gpio_irq_rtdm.c
and demo() in gpio-irq-test.c

$  cat /proc/xenomai/sched/stat
CPU  PID    MSW        CSW        XSC        PF    STAT       %CPU  NAME
  0  0      0          166718     0          0     00018000   99.1  [ROOT]
  0  691    1          1          5          0     000600c0    0.0  gpio-irq-test
  0  698    1          112758     338273     0     00040042    0.6  trivial
  0  0      0          978799     0          0     00000000    0.1  [IRQ16: [timer]]
  0  0      0          112756     0          0     00000000    0.2  [IRQ98: gpio69]

$ cat /proc/xenomai/sched/threads

CPU  PID    CLASS  TYPE      PRI   TIMEOUT       STAT       NAME
  0  0      idle   core       -1   -             R          [ROOT]
  0  691    rt     cobalt      0   -             X          gpio-irq-test
  0  698    rt     cobalt     99   -             W          trivial

Thanks,
Giulio

Re: [Xenomai] Gpio: IRQ handler is called ~4ms after state change

[Giulio Moro]

> So it seems that in my case it takes a long time for the irq_handler() to be called after the test pin is toggled.
> Am I doing something wrong in the kernel module ?

by the way, I get this in dmesg:

[   76.152289] irq 98, desc: dc18df00, depth: 1, count: 0, unhandled: 0
[   76.152314] ->handle_irq():  c008e008, handle_edge_irq+0x0/0x150
[   76.152351] ->irq_data.chip(): dc18d9d0, 0xdc18d9d0
[   76.152364] ->action():   (null)
[   76.152371]    IRQ_NOPROBE set
[   76.152378] unexpected IRQ trap at vector 62
[   76.156676] ------------[ cut here ]------------
[   76.156692] WARNING: CPU: 0 PID: 0 at kernel/irq/chip.c:843 __ipipe_ack_bad_irq+0x3c/0x48()
[   76.156699] Modules linked in: gpio_irq_rtdm(O) c_can_platform c_can can_dev tieqep pwm_tiehrpwm pwm_tiecap spidev usb_f_midi snd_rawmidi snd_seq_device usb_f_acm u_serial usb_f_mass_storage usb_f_rndis u_ether arc4 omap_aes_driver omap_sham uio_pruss rt2800usb rt2800lib rt2x00usb rt2x00lib mac80211 omap_rng rng_core snd_soc_davinci_mcasp cfg80211 snd_soc_edma snd_soc_omap crc_ccitt rfkill snd_soc_core snd_pcm_dmaengine snd_pcm snd_timer snd spi_omap2_mcspi soundcore evdev uio_pdrv_genirq uio libcomposite ip_tables x_tables
[   76.156852] CPU: 0 PID: 0 Comm: swapper Tainted: G        W  O    4.4.68-ti-xenomai-r106 #1
[   76.156860] Hardware name: Generic AM33XX (Flattened Device Tree)
[   76.156866] I-pipe domain: Linux
[   76.156901] [<c0018d30>] (unwind_backtrace) from [<c0015bfc>] (show_stack+0x20/0x24)
[   76.156922] [<c0015bfc>] (show_stack) from [<c058dc94>] (dump_stack+0x24/0x28)
[   76.156950] [<c058dc94>] (dump_stack) from [<c0040294>] (warn_slowpath_common+0x94/0xc0)
[   76.156967] [<c0040294>] (warn_slowpath_common) from [<c00403c4>] (warn_slowpath_null+0x2c/0x34)
[   76.156985] [<c00403c4>] (warn_slowpath_null) from [<c008d7bc>] (__ipipe_ack_bad_irq+0x3c/0x48)
[   76.157004] [<c008d7bc>] (__ipipe_ack_bad_irq) from [<c00e6e8c>] (__ipipe_dispatch_irq+0x8c/0x1a8)
[   76.157024] [<c00e6e8c>] (__ipipe_dispatch_irq) from [<c05d7ad4>] (omap_gpio_irq_handler+0x170/0x1d8)
[   76.157041] [<c05d7ad4>] (omap_gpio_irq_handler) from [<c008a294>] (handle_irq_event_percpu+0xa4/0x254)
[   76.157057] [<c008a294>] (handle_irq_event_percpu) from [<c008a47c>] (handle_irq_event+0x38/0x4c)
[   76.157072] [<c008a47c>] (handle_irq_event) from [<c008dfc8>] (handle_level_irq+0x78/0xb8)
[   76.157088] [<c008dfc8>] (handle_level_irq) from [<c00898f0>] (generic_handle_irq+0x34/0x44)
[   76.157102] [<c00898f0>] (generic_handle_irq) from [<c0089b9c>] (__handle_domain_irq+0x64/0xb8)
[   76.157125] [<c0089b9c>] (__handle_domain_irq) from [<c00118f4>] (handle_IRQ+0x28/0x2c)
[   76.157145] [<c00118f4>] (handle_IRQ) from [<c001c990>] (__ipipe_do_IRQ+0x1c/0x24)
[   76.157161] [<c001c990>] (__ipipe_do_IRQ) from [<c00e6810>] (__ipipe_do_sync_stage+0x24c/0x270)
[   76.157175] [<c00e6810>] (__ipipe_do_sync_stage) from [<c00e68c8>] (__ipipe_do_sync_pipeline+0x94/0x98)
[   76.157189] [<c00e68c8>] (__ipipe_do_sync_pipeline) from [<c00e6f3c>] (__ipipe_dispatch_irq+0x13c/0x1a8)
[   76.157203] [<c00e6f3c>] (__ipipe_dispatch_irq) from [<c00092a4>] (__ipipe_grab_irq+0x58/0x70)
[   76.157217] [<c00092a4>] (__ipipe_grab_irq) from [<c000961c>] (omap_intc_handle_irq+0x48/0xa8)
[   76.157226] Exception stack(0xc0f0dee8 to 0xc0f0df30)
[   76.157240] dee0:                   c00e6908 600c0013 c0f0df5c c0f0df00 c0a17494 c00095e0
[   76.157254] df00: 00000000 00000000 00000000 c0f399dc c0ffd040 c0f0c000 c0f0f134 c0fe570c
[   76.157264] df20: c0f399dc c0fe4e52 c0c9de24 c0f0df5c
[   76.157284] [<c000961c>] (omap_intc_handle_irq) from [<c0a17494>] (__irq_svc+0x54/0x60)
[   76.157292] Exception stack(0xc0f0df00 to 0xc0f0df48)
[   76.157305] df00: 00000000 00000000 00000000 c0f399dc c0ffd040 c0f0c000 c0f0f134 c0fe570c
[   76.157319] df20: c0f399dc c0fe4e52 c0c9de24 c0f0df5c c00e68e0 c0f0df50 c0011a08 c00e6908
[   76.157327] df40: 600c0013 ffffffff
[   76.157343] [<c0a17494>] (__irq_svc) from [<c00e6908>] (ipipe_unstall_root+0x3c/0x4c)
[   76.157357] [<c00e6908>] (ipipe_unstall_root) from [<c0011a08>] (arch_cpu_idle+0x84/0x90)
[   76.157374] [<c0011a08>] (arch_cpu_idle) from [<c0072760>] (default_idle_call+0x30/0x3c)
[   76.157389] [<c0072760>] (default_idle_call) from [<c00728dc>] (cpu_startup_entry+0x170/0x1b0)
[   76.157403] [<c00728dc>] (cpu_startup_entry) from [<c0a12adc>] (rest_init+0x80/0x84)
[   76.157430] [<c0a12adc>] (rest_init) from [<c0e91e08>] (start_kernel+0x44c/0x46c)
[   76.157440] ---[ end trace 706c0a6fb4268ac1 ]---

Re: [Xenomai] Gpio: IRQ handler is called ~4ms after state change

[Philippe Gerum]

On 06/17/2017 06:52 PM, Giulio Moro wrote:
> Hi,
> I ported this GPIO driver from Xenomai 2.6 to Xenomai 3 and I run it on the Beaglebone Black: https://github.com/giuliomoro/gpio-irq-rtdm/
> 
> TheRTDM  irq_handler (in gpio_irq_rtdm.c) toggles a pin "kernel timingpin" as soon as the IRQ is received.
> The test program registers a pin to monitor and sleeps in a ioctl() waiting for the pin to go low. When the kernel unblocks it from the ioctl(), the task toggles another pin "user timingpin".
> 
> The original authors claims that, on the BeagleBone Black, with Xenomai 2.6:
> * the kernel timingpin will change roughly 5us after the test pin is toggled by an external clock
> *  the user timingpin will change roughly 5-10us after the kernel timingpin

If by "user timing", the author claims 10 us worst-case latency for
waking up a user task on this class of hardware, then the machine must
have been fairly idle under test. 50 us would make more sense under
heavy load conditions.

> 
> The above values make sense to me.
> 
> My observations, on the BeagleBone Black, Linux 4.4.65 with Xenomai 3.0.5:
> * the kernel timingpin will change roughly 4ms (milliseconds) after the test pin is toggled by an external clock
> * the user timingpin will change 40 to 60us (microseconds) after the kernel timingpin

4ms do not make sense obviously. You may be measuring the time it takes
to catch and emit this WARN_ON() message over the IRQ handler.

>    76.152289] irq 98, desc: dc18df00, depth: 1, count: 0, unhandled: 0
> [   76.152314] ->handle_irq():  c008e008, handle_edge_irq+0x0/0x150
> [   76.152351] ->irq_data.chip(): dc18d9d0, 0xdc18d9d0
> [   76.152364] ->action():   (null)
> [   76.152371]    IRQ_NOPROBE set
> [   76.152378] unexpected IRQ trap at vector 62
> [   76.156676] ------------[ cut here ]------------
> [   76.156692] WARNING: CPU: 0 PID: 0 at kernel/irq/chip.c:843 __ipipe_ack_bad_irq+0x3c/0x48()
> [   76.156699] Modules linked in: gpio_irq_rtdm(O) c_can_platform c_can can_dev tieqep pwm_tiehrpwm pwm_tiecap spidev usb_f_midi snd_rawmidi snd_seq_device usb_f_acm u_serial usb_f_mass_storage usb_f_rndis u_ether arc4 omap_aes_driver omap_sham uio_pruss rt2800usb rt2800lib rt2x00usb rt2x00lib mac80211 omap_rng rng_core snd_soc_davinci_mcasp cfg80211 snd_soc_edma snd_soc_omap crc_ccitt rfkill snd_soc_core snd_pcm_dmaengine snd_pcm snd_timer snd spi_omap2_mcspi soundcore evdev uio_pdrv_genirq uio libcomposite ip_tables x_tables
> [   76.156852] CPU: 0 PID: 0 Comm: swapper Tainted: G        W  O    4.4.68-ti-xenomai-r106 #1
> [   76.156860] Hardware name: Generic AM33XX (Flattened Device Tree)
> [   76.156866] I-pipe domain: Linux
> [   76.156901] [<c0018d30>] (unwind_backtrace) from [<c0015bfc>] (show_stack+0x20/0x24)
> [   76.156922] [<c0015bfc>] (show_stack) from [<c058dc94>] (dump_stack+0x24/0x28)
> [   76.156950] [<c058dc94>] (dump_stack) from [<c0040294>] (warn_slowpath_common+0x94/0xc0)
> [   76.156967] [<c0040294>] (warn_slowpath_common) from [<c00403c4>] (warn_slowpath_null+0x2c/0x34)
> [   76.156985] [<c00403c4>] (warn_slowpath_null) from [<c008d7bc>] (__ipipe_ack_bad_irq+0x3c/0x48)
> [   76.157004] [<c008d7bc>] (__ipipe_ack_bad_irq) from [<c00e6e8c>] (__ipipe_dispatch_irq+0x8c/0x1a8)
> [   76.157024] [<c00e6e8c>] (__ipipe_dispatch_irq) from [<c05d7ad4>] (omap_gpio_irq_handler+0x170/0x1d8)
> [   76.157041] [<c05d7ad4>] (omap_gpio_irq_handler) from [<c008a294>] (handle_irq_event_percpu+0xa4/0x254)

This is unlikely a Xenomai issue strictly speaking. You may want to
check the I-pipe code instead, there is certainly a problem with the
interrupt delivery code in the low level handler.

-- 
Philippe.

Re: [Xenomai] Gpio: IRQ handler is called ~4ms after state change

[Giulio Moro]

> This is unlikely a Xenomai issue strictly speaking. You may want to
> check the I-pipe code instead, there is certainly a problem with the
> interrupt delivery code in the low level handler.

I have no idea where to start from in checking the i-pipe code.

What I can say is that I went back to 4.4.43, which is the version originally targeted by the i-pipe patch which is released on the xenomai website, and the issue is still there.

Any pointers appreciated.

Thanks,
Giulio

Re: [Xenomai] Gpio: IRQ handler is called ~4ms after state change

[Lennart Sorensen]

On Sat, Jun 17, 2017 at 04:52:18PM +0000, Giulio Moro wrote:
> Hi,
> I ported this GPIO driver from Xenomai 2.6 to Xenomai 3 and I run it on the Beaglebone Black: https://github.com/giuliomoro/gpio-irq-rtdm/
> 
> TheRTDM  irq_handler (in gpio_irq_rtdm.c) toggles a pin "kernel timingpin" as soon as the IRQ is received.
> The test program registers a pin to monitor and sleeps in a ioctl() waiting for the pin to go low. When the kernel unblocks it from the ioctl(), the task toggles another pin "user timingpin".
> 
> The original authors claims that, on the BeagleBone Black, with Xenomai 2.6:
> * the kernel timingpin will change roughly 5us after the test pin is toggled by an external clock
> *  the user timingpin will change roughly 5-10us after the kernel timingpin
> 
> The above values make sense to me.
> 
> My observations, on the BeagleBone Black, Linux 4.4.65 with Xenomai 3.0.5:
> * the kernel timingpin will change roughly 4ms (milliseconds) after the test pin is toggled by an external clock
> * the user timingpin will change 40 to 60us (microseconds) after the kernel timingpin
> 
> So it seems that in my case it takes a long time for the irq_handler() to be called after the test pin is toggled.
> Am I doing something wrong in the kernel module ?
> 
> See in particular irq_handler() and gpio_irq_ioctl_rt() in gpio_irq_rtdm.c
> and demo() in gpio-irq-test.c

The 4ms delay reminds me of a problem I had on the am57xx with a gpio irq.
Turns out that in that case smartidle was enabled and the gpio bank
would go into sleep mode and it took 4ms to wake up before the irq would
show up.  Turning off the smartidle on the gpio bank so that it never
could go to sleep solved the problem.  Maybe this TI chip has a similar
feature.

-- 
Len Sorensen

Re: [Xenomai] Gpio: IRQ handler is called ~4ms after state change

[Giulio Moro]

Thanks Len,

> Turns out that in that case smartidle was enabled and the gpio bank
>  would go into sleep mode and it took 4ms to wake up before the irq would
> show up.  Turning off the smartidle on the gpio bank so that it never
> could go to sleep solved the problem.  Maybe this TI chip has a similar
> feature.

I do not think it is the case in my test: the GPIO banks are on (the pins get exported before the module is loaded), and I would not expect it to go to sleep in the few ms between interrupts in my test.

Giulio

Re: [Xenomai] Gpio: IRQ handler is called ~4ms after state change

[Lennart Sorensen]

On Tue, Jun 20, 2017 at 03:03:33PM +0000, Giulio Moro wrote:
> Thanks Len,
> 
> > Turns out that in that case smartidle was enabled and the gpio bank
> >  would go into sleep mode and it took 4ms to wake up before the irq would
> > show up.  Turning off the smartidle on the gpio bank so that it never
> > could go to sleep solved the problem.  Maybe this TI chip has a similar
> > feature.
> 
> I do not think it is the case in my test: the GPIO banks are on (the pins get exported before the module is loaded), and I would not expect it to go to sleep in the few ms between interrupts in my test.

Based on my experience with the newer TI, it will.  For the auto power
saving bit, miliseconds is a long time.

I fixed it by setting the gpio-bank to ti,no-idle in the dtb.

-- 
Len Sorensen