high prioritized threaded interrupt is delayed due to low priority softirq job

high prioritized threaded interrupt is delayed due to low priority softirq job

[yosi yarchi]

  Hi

  my platform is:
    SAM9X35 (8 CAN mailboxes),
    Linux mscb 5.4.41-linux4sam-2020.04-rt24 #1 PREEMPT_RT Wed Nov 9 
06:12:28 UTC 2022 armv5tejl GNU/Linux
    CAN threaded interrupt (irq/30-can0-346) is configured to be highest 
priority on
      system, and it is scheduled very quickly after CAN irq_handler expires
      (irq_handler_entry: irq=30 name=can0), doing its job (at91_irq).

  my problem is that from time to time I get CAN RX overflow. problem 
analysis is as the following (see trace below):
    after CAN threaded interrupt completes its job (at91_irq_r), 
scheduler force it to
      run some other low priority softirq jobs (softirq_entry: vec=1 
[action=TIMER],
      softirq_entry: vec=3 [action=NET_RX]). during the processing of 
those jobs, new HW
      CAN irq_handler expires (irq_handler_entry: irq=30 name=can0), but 
scheduler
      schedule the at91_irq job at the end of job queue, which is too 
late, and I get CAN
      rx overflow.

  I've tried some solutions, no one worked out of the box:
    1. disable all relevant irqs (timer, network) at CAN irq_handler 
(irq_handler_entry:
      irq=30 name=can0), and enable them at the end of CAN threaded 
interrupt job
      processing (at91_irq_r)
    2. configure CAN job (at91_irq) to run inside the CAN irq_handler 
(irq_handler_entry:
      irq=30 name=can0) by adding IRQF_NO_THREAD flag to request_irq.

  is there built-in solution for this problem at linux-rt?
  if not, what could be good 'hacked' solutions for the problem?

  with best regards
  Yosi Yarchi

  kernel trace:
  -------------

         <idle>-0     [000] d..h1..  6020.481859: irq_handler_entry: 
irq=30 name=can0
         <idle>-0     [000] d..h1..  6020.481875: irq_handler_exit: 
irq=30 ret=handled
    irq/30-can0-346   [000] d......  6020.481972: at91_irq: 
(at91_irq+0x0/0xab0)
    irq/30-can0-346   [000] d...1..  6020.482090: at91_irq_r: 
(irq_forced_thread_fn+0x3c/0x8c <- at91_irq)
         <idle>-0     [000] d..h1..  6020.482330: irq_handler_entry: 
irq=30 name=can0
         <idle>-0     [000] d..h1..  6020.482347: irq_handler_exit: 
irq=30 ret=handled
    irq/30-can0-346   [000] d......  6020.482438: at91_irq: 
(at91_irq+0x0/0xab0)
    irq/30-can0-346   [000] d...1..  6020.482553: at91_irq_r: 
(irq_forced_thread_fn+0x3c/0x8c <- at91_irq)
         <idle>-0     [000] d..h1..  6020.482812: irq_handler_entry: 
irq=30 name=can0
         <idle>-0     [000] d..h1..  6020.482829: irq_handler_exit: 
irq=30 ret=handled
    irq/30-can0-346   [000] d......  6020.482923: at91_irq: 
(at91_irq+0x0/0xab0)
    irq/30-can0-346   [000] d...1..  6020.483040: at91_irq_r: 
(irq_forced_thread_fn+0x3c/0x8c <- at91_irq)
         <idle>-0     [000] d..h1..  6020.483290: irq_handler_entry: 
irq=30 name=can0
         <idle>-0     [000] d..h1..  6020.483308: irq_handler_exit: 
irq=30 ret=handled
    irq/30-can0-346   [000] d......  6020.483400: at91_irq: 
(at91_irq+0x0/0xab0)
    irq/30-can0-346   [000] d...1..  6020.483514: at91_irq_r: 
(irq_forced_thread_fn+0x3c/0x8c <- at91_irq)
         <idle>-0     [000] d..h1..  6020.483781: irq_handler_entry: 
irq=30 name=can0
         <idle>-0     [000] d..h1..  6020.483799: irq_handler_exit: 
irq=30 ret=handled
    irq/30-can0-346   [000] d..h...  6020.483891: irq_handler_entry: 
irq=16 name=tc_clkevt
    irq/30-can0-346   [000] d..h...  6020.483956: softirq_raise: vec=1 
[action=TIMER]
    irq/30-can0-346   [000] d..h...  6020.484006: irq_handler_exit: 
irq=16 ret=handled
    irq/30-can0-346   [000] d......  6020.484048: at91_irq: 
(at91_irq+0x0/0xab0)
    irq/30-can0-346   [000] d...1..  6020.484169: at91_irq_r: 
(irq_forced_thread_fn+0x3c/0x8c <- at91_irq)
    irq/30-can0-346   [000] .......  6020.484207: softirq_entry: vec=1 
[action=TIMER]
    irq/30-can0-346   [000] d..h1..  6020.484254: irq_handler_entry: 
irq=30 name=can0
    irq/30-can0-346   [000] d..h1..  6020.484267: irq_handler_exit: 
irq=30 ret=handled
    irq/30-can0-346   [000] d......  6020.484493: softirq_raise: vec=3 
[action=NET_RX]
    irq/30-can0-346   [000] .......  6020.485282: softirq_exit: vec=1 
[action=TIMER]
    irq/30-can0-346   [000] .......  6020.485306: softirq_entry: vec=3 
[action=NET_RX]
    irq/30-can0-346   [000] d..h...  6020.485607: irq_handler_entry: 
irq=16 name=tc_clkevt
    irq/30-can0-346   [000] d..h...  6020.485673: irq_handler_entry: 
irq=17 name=at91_rtc
    irq/30-can0-346   [000] d..h...  6020.485685: irq_handler_exit: 
irq=17 ret=handled
    irq/30-can0-346   [000] d..h...  6020.485706: irq_handler_entry: 
irq=17 name=atmel_usart_serial.0.auto
    irq/30-can0-346   [000] d..h...  6020.485713: irq_handler_exit: 
irq=17 ret=handled
    irq/30-can0-346   [000] d..h...  6020.485754: irq_handler_exit: 
irq=16 ret=handled
    irq/30-can0-346   [000] d..h...  6020.486008: irq_handler_entry: 
irq=29 name=eth0
    irq/30-can0-346   [000] d..h...  6020.486027: irq_handler_exit: 
irq=29 ret=handled
    irq/30-can0-346   [000] .......  6020.486571: softirq_exit: vec=3 
[action=NET_RX]
    irq/30-can0-346   [000] d......  6020.486626: at91_irq: 
(at91_irq+0x0/0xab0)
    irq/30-can0-346   [000] d......  6020.486788: at91_rx_overflow_err: 
(at91_irq+0x200/0xab0)

Re: high prioritized threaded interrupt is delayed due to low priority softirq job

[yosi yarchi]

Hi


I hope this mail will be more readable (prev mail lines had been cut):



my platform is:

1. SAM9X35 (8 CAN mailboxes),

2. Linux mscb 5.4.41-linux4sam-2020.04-rt24 #1 PREEMPT_RT Wed Nov 9 
06:12:28 UTC 2022 armv5tejl GNU/Linux

3. CAN threaded interrupt (irq/30-can0-346) is configured to be highest 
priority on system, and it is scheduled very quickly after CAN 
irq_handler expires (irq_handler_entry: irq=30 name=can0), doing its job 
(at91_irq).


my problem is that from time to time I get CAN RX overflow. problem 
analysis is as the following (see trace below): after CAN threaded 
interrupt completes its job (at91_irq_r), scheduler force it to run some 
other low priority softirq jobs (softirq_entry: vec=1 [action=TIMER], 
softirq_entry: vec=3 [action=NET_RX]). during the processing of those 
jobs, new HW CAN irq_handler expires (irq_handler_entry: irq=30 
name=can0), but scheduler schedule the at91_irq job at the end of job 
queue, which is too late, and I get CAN rx overflow.


I've tried some solutions, no one worked out of the box:

1. disable all relevant irqs (timer, network) at CAN irq_handler 
(irq_handler_entry: irq=30 name=can0), and enable them at the end of CAN 
threaded interrupt job processing (at91_irq_r)

2. configure CAN job (at91_irq) to run inside the CAN irq_handler 
(irq_handler_entry: irq=30 name=can0) by adding IRQF_NO_THREAD flag to 
request_irq.


is there built-in solution for this problem at linux-rt?
if not, what could be good 'hacked' solutions for the problem?

with best regards
Yosi Yarchi


kernel trace:
-------------

      <idle>-0   d..h1 1859: irq_handler_entry: irq=30 name=can0
      <idle>-0   d..h1 1875: irq_handler_exit: irq=30 ret=handled
irq/30-can0-346 d.... 1972: at91_irq: (at91_irq+0x0/0xab0)
irq/30-can0-346 d...1 2090: at91_irq_r: (irq_forced_thread_fn+0x3c/0
      <idle>-0   d..h1 2330: irq_handler_entry: irq=30 name=can0
      <idle>-0   d..h1 2347: irq_handler_exit: irq=30 ret=handled
irq/30-can0-346 d.... 2438: at91_irq: (at91_irq+0x0/0xab0)
irq/30-can0-346 d...1 2553: at91_irq_r: (irq_forced_thread_fn+0x3c/0
      <idle>-0   d..h1 2812: irq_handler_entry: irq=30 name=can0
      <idle>-0   d..h1 2829: irq_handler_exit: irq=30 ret=handled
irq/30-can0-346 d.... 2923: at91_irq: (at91_irq+0x0/0xab0)
irq/30-can0-346 d...1 3040: at91_irq_r: (irq_forced_thread_fn+0x3c/0
      <idle>-0   d..h1 3290: irq_handler_entry: irq=30 name=can0
      <idle>-0   d..h1 3308: irq_handler_exit: irq=30 ret=handled
irq/30-can0-346 d.... 3400: at91_irq: (at91_irq+0x0/0xab0)
irq/30-can0-346 d...1 3514: at91_irq_r: (irq_forced_thread_fn+0x3c/0
      <idle>-0   d..h1 3781: irq_handler_entry: irq=30 name=can0
      <idle>-0   d..h1 3799: irq_handler_exit: irq=30 ret=handled
irq/30-can0-346 d..h. 3891: irq_handler_entry: irq=16 name=tc_clkevt
irq/30-can0-346 d..h. 3956: softirq_raise: vec=1 [action=TIMER]
irq/30-can0-346 d..h. 4006: irq_handler_exit: irq=16 ret=handled
irq/30-can0-346 d.... 4048: at91_irq: (at91_irq+0x0/0xab0)
irq/30-can0-346 d...1 4169: at91_irq_r: (irq_forced_thread_fn+0x3c/0
irq/30-can0-346 ..... 4207: softirq_entry: vec=1 [action=TIMER]
irq/30-can0-346 d..h1 4254: irq_handler_entry: irq=30 name=can0
irq/30-can0-346 d..h1 4267: irq_handler_exit: irq=30 ret=handled
irq/30-can0-346 d.... 4493: softirq_raise: vec=3 [action=NET_RX]
irq/30-can0-346 ..... 5282: softirq_exit: vec=1 [action=TIMER]
irq/30-can0-346 ..... 5306: softirq_entry: vec=3 [action=NET_RX]
irq/30-can0-346 d..h. 5607: irq_handler_entry: irq=16 name=tc_clkevt
irq/30-can0-346 d..h. 5673: irq_handler_entry: irq=17 name=at91_rtc
irq/30-can0-346 d..h. 5685: irq_handler_exit: irq=17 ret=handled
irq/30-can0-346 d..h. 5706: irq_handler_entry: irq=17 name=atmel_usa
irq/30-can0-346 d..h. 5713: irq_handler_exit: irq=17 ret=handled
irq/30-can0-346 d..h. 5754: irq_handler_exit: irq=16 ret=handled
irq/30-can0-346 d..h. 6008: irq_handler_entry: irq=29 name=eth0
irq/30-can0-346 d..h. 6027: irq_handler_exit: irq=29 ret=handled
irq/30-can0-346 ..... 6571: softirq_exit: vec=3 [action=NET_RX]
irq/30-can0-346 d.... 6626: at91_irq: (at91_irq+0x0/0xab0)
irq/30-can0-346 d.... 6788: at91_rx_overflow_err: (at91_irq+0x200/0x

Re: high prioritized threaded interrupt is delayed due to low priority softirq job

[Ahmed S. Darwish]

On Thu, Nov 17, 2022, yosi yarchi wrote:
>
> 1. SAM9X35 (8 CAN mailboxes),
>

This is a *very* very low-end core (ARM926), so be careful that some
latency issues would be expected.

If you don't have a specific Linux use-case, maybe you can try something
like ZephyrOS instead?

Given that low-end core, and if you're stuck with Linux, a mainline
kernel with preemption disabled (CONFIG_PREEMPT_NONE) might actually be
more beneficial latency-wise than PREEMPT_RT...

> 2. Linux mscb 5.4.41-linux4sam-2020.04-rt24 #1 PREEMPT_RT Wed Nov 9
> 06:12:28 UTC 2022 armv5tejl GNU/Linux

"5.4.41-linux4sam-2020.04-rt24". This is a vendored RT kernel, and
vendored RT kernels are known to have latency issues.

Can you please try official RT kernels instead? More info is here:

  https://wiki.linuxfoundation.org/realtime/preempt_rt_versions

Make sure that debugging options are disabled, e.g.
CONFIG_PROVE_LOCKING, and so on. Afterwards, you'd like to measure the
latencies of your (single-core) system with something like:

  cyclictest                    \
        --default-system        \
        --secaligned            \
        --mlockall              \
        --interval=500          \
        --priority=98           \
        --histogram=2000

And then check the reported worst-case latencies.

> 3. CAN threaded interrupt (irq/30-can0-346) is configured to be
> highest priority on system.

Please not that in RT, many system-critical kernel threads run at rtprio
99. The hight (sane) priority to be assigned should thus be 98.

>
> my problem is that from time to time I get CAN RX overflow.
>

That would be kinda expected with such a low-end core, even when
everything else is "perfect".

>
> I've tried some solutions, no one worked out of the box:
>
> 1. disable all relevant irqs (timer, network) at CAN irq_handler
> (irq_handler_entry: irq=30 name=can0), and enable them at the end of CAN
> threaded interrupt job processing (at91_irq_r)
>

That's wrong in so many ways, please don't do that.

> 2. configure CAN job (at91_irq) to run inside the CAN irq_handler
> (irq_handler_entry: irq=30 name=can0) by adding IRQF_NO_THREAD flag to
> request_irq.

ditto.

Good luck,

--
Ahmed S. Darwish
Linutronix GmbH