Groups > linux.kernel > #1345055 > unrolled thread

Softirq priority inversion from "softirq: reduce latencies"

Started by	Peter Hurley <peter@hurleysoftware.com>
First post	2016-02-27 19:20 +0100
Last post	2016-02-29 18:20 +0100
Articles	20 on this page of 29 — 6 participants

Back to article view | Back to linux.kernel

  Softirq priority inversion from "softirq: reduce latencies" Peter Hurley <peter@hurleysoftware.com> - 2016-02-27 19:20 +0100
    Re: Softirq priority inversion from "softirq: reduce latencies" Eric Dumazet <eric.dumazet@gmail.com> - 2016-02-27 21:20 +0100
      Re: Softirq priority inversion from "softirq: reduce latencies" Peter Hurley <peter@hurleysoftware.com> - 2016-02-27 21:40 +0100
        Re: Softirq priority inversion from "softirq: reduce latencies" David Miller <davem@davemloft.net> - 2016-02-28 00:10 +0100
          Re: Softirq priority inversion from "softirq: reduce latencies" Peter Hurley <peter@hurleysoftware.com> - 2016-02-28 00:40 +0100
            Re: Softirq priority inversion from "softirq: reduce latencies" Eric Dumazet <eric.dumazet@gmail.com> - 2016-02-28 03:10 +0100
              Re: Softirq priority inversion from "softirq: reduce latencies" Peter Hurley <peter@hurleysoftware.com> - 2016-02-28 03:20 +0100
                Re: Softirq priority inversion from "softirq: reduce latencies" Eric Dumazet <eric.dumazet@gmail.com> - 2016-02-28 03:20 +0100
                Re: Softirq priority inversion from "softirq: reduce latencies" David Miller <davem@davemloft.net> - 2016-02-28 05:50 +0100
    Re: Softirq priority inversion from "softirq: reduce latencies" Mike Galbraith <umgwanakikbuti@gmail.com> - 2016-02-28 07:00 +0100
      Re: Softirq priority inversion from "softirq: reduce latencies" Francois Romieu <romieu@fr.zoreil.com> - 2016-02-28 18:10 +0100
        Re: Softirq priority inversion from "softirq: reduce latencies" Mike Galbraith <umgwanakikbuti@gmail.com> - 2016-02-29 06:00 +0100
          Re: Softirq priority inversion from "softirq: reduce latencies" Peter Hurley <peter@hurleysoftware.com> - 2016-02-29 16:10 +0100
            Re: Softirq priority inversion from "softirq: reduce latencies" Eric Dumazet <eric.dumazet@gmail.com> - 2016-02-29 16:30 +0100
              Re: Softirq priority inversion from "softirq: reduce latencies" Peter Hurley <peter@hurleysoftware.com> - 2016-02-29 17:00 +0100
                Re: Softirq priority inversion from "softirq: reduce latencies" Eric Dumazet <eric.dumazet@gmail.com> - 2016-02-29 17:30 +0100
                  Re: Softirq priority inversion from "softirq: reduce latencies" Peter Hurley <peter@hurleysoftware.com> - 2016-02-29 19:10 +0100
                    Re: Softirq priority inversion from "softirq: reduce latencies" Eric Dumazet <eric.dumazet@gmail.com> - 2016-02-29 19:30 +0100
                      Re: Softirq priority inversion from "softirq: reduce latencies" Peter Hurley <peter@hurleysoftware.com> - 2016-02-29 20:00 +0100
                        Re: Softirq priority inversion from "softirq: reduce latencies" Thomas Gleixner <tglx@linutronix.de> - 2016-02-29 20:20 +0100
                          Re: Softirq priority inversion from "softirq: reduce latencies" David Miller <davem@davemloft.net> - 2016-02-29 21:30 +0100
                          Re: Softirq priority inversion from "softirq: reduce latencies" Peter Hurley <peter@hurleysoftware.com> - 2016-03-01 00:10 +0100
            Re: Softirq priority inversion from "softirq: reduce latencies" Eric Dumazet <eric.dumazet@gmail.com> - 2016-02-29 16:30 +0100
              Re: Softirq priority inversion from "softirq: reduce latencies" Peter Hurley <peter@hurleysoftware.com> - 2016-02-29 20:20 +0100
                Re: Softirq priority inversion from "softirq: reduce latencies" Eric Dumazet <eric.dumazet@gmail.com> - 2016-02-29 20:50 +0100
            Re: Softirq priority inversion from "softirq: reduce latencies" Mike Galbraith <umgwanakikbuti@gmail.com> - 2016-02-29 16:50 +0100
              Re: Softirq priority inversion from "softirq: reduce latencies" Peter Hurley <peter@hurleysoftware.com> - 2016-02-29 17:00 +0100
                Re: Softirq priority inversion from "softirq: reduce latencies" Eric Dumazet <eric.dumazet@gmail.com> - 2016-02-29 17:30 +0100
            Re: Softirq priority inversion from "softirq: reduce latencies" David Miller <davem@davemloft.net> - 2016-02-29 18:20 +0100

Page 1 of 2 [1] 2 Next page →

#1345055 — Softirq priority inversion from "softirq: reduce latencies"

From	Peter Hurley <peter@hurleysoftware.com>
Date	2016-02-27 19:20 +0100
Subject	Softirq priority inversion from "softirq: reduce latencies"
Message-ID	<r6RDc-70n-9@gated-at.bofh.it>

Hi Eric,

For a while now, we've been struggling to understand why we've been
observing missed uart rx DMA.

Because both the uart driver (omap8250) and the dmaengine driver
(edma) were (relatively) new, we assumed there was some race between
starting a new rx DMA and processing the previous one.

However, after instrumenting both the uart driver and the dmaengine
driver, what we've observed is huge anomalous latencies between receiving
the DMA interrupt and servicing the DMA tasklet.

For example, at 3Mbaud we recorded the following distribution of
softirq[TASKLET] service latency for this specific DMA channel:

root@black:/sys/kernel/debug/edma# cat 35
latency(us):   0+   20+   40+   60+   80+  100+  120+  140+  160+  180+  200+  220+  240+  260+  280+  300+  320+  340+  360+  380+
           195681    33    53    15     7     4     3     1     0     0     0     1     4     6     1     0     0     0     0     0

As you can see, the vast majority of tasklet service happens immediately,
tapering off to 140+us.

However, note the island of distribution at 220~300 [latencies beyond 300+
are not recorded because the uart fifo has filled again by this point and
dma must be aborted].

So I cribbed together a latency tracer to catch what was happening at
the extreme, and what it caught was a priority inversion stemming from
your commit:

   commit c10d73671ad30f54692f7f69f0e09e75d3a8926a
   Author: Eric Dumazet <edumazet@google.com>
   Date:   Thu Jan 10 15:26:34 2013 -0800

       softirq: reduce latencies
    
       In various network workloads, __do_softirq() latencies can be up
       to 20 ms if HZ=1000, and 200 ms if HZ=100.
    
       This is because we iterate 10 times in the softirq dispatcher,
       and some actions can consume a lot of cycles.


In the trace below [1], the trace begins in the edma completion interrupt
handler when the tasklet is scheduled; the edma interrupt has occurred during
NET_RX softirq context.

However, instead of causing a restart of the softirq loop to process the
tasklet _which occurred before sshd was scheduled_, the softirq loop is
aborted and deferred for ksoftirqd. The tasklet is not serviced for 521us,
which is way too long, so DMA was aborted.

Your patch has effectively inverted the priority of tasklets with normal
pri/nice processes that have merely received a network packet.

ISTM, the problem you're trying to solve here was caused by NET_RX softirq
to begin with, and maybe that thing needs a diet.

But rather than outright reverting your patch, what if more selective
conditions are used to abort the softirq restart? What would those conditions
be? In the netperf benchmark you referred to in that commit, is it just
NET_TX/NET_RX softirqs that are causing scheduling latencies?

It just doesn't make sense to special case for a workload that isn't
even running.


Regards,
Peter Hurley


[1] softirq tasklet latency trace  (apologies that it's only events - full
    function trace introduces too much overhead)

# tracer: latency
#
# latency latency trace v1.1.5 on 4.5.0-rc2+
# --------------------------------------------------------------------
# latency: 476 us, #59/59, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0)
#    -----------------
#    | task: sshd-750 (uid:1000 nice:0 policy:0 rt_prio:0)
#    -----------------
#  => started at: __tasklet_schedule  
#  => ended at:   tasklet_action
#
#
#                  _------=> CPU#
#                 / _-----=> irqs-off 
#                | / _----=> need-resched
#                || / _---=> hardirq/softirq
#                ||| / _--=> preempt-depth
#                |||| /     delay
#  cmd     pid   ||||| time  |   caller
#     \   /      |||||  \    |   /
  <idle>-0       0d.H3    1us : __tasklet_schedule
  <idle>-0       0d.H4    3us : softirq_raise: vec=6 [action=TASKLET]
  <idle>-0       0d.H3    6us : irq_handler_exit: irq=20 ret=handled
  <idle>-0       0..s2   15us : kmem_cache_alloc: call_site=c08378e4 ptr=de55d7c0 bytes_req=192 bytes_alloc=192 gfp_flags=GFP_ATOMIC
  <idle>-0       0..s2   23us : netif_receive_skb_entry: dev=eth0 napi_id=0x0 queue_mapping=0 skbaddr=dca04400 vlan_tagged=0 vlan_proto=0x0000 vlan_tci=0x000
0 protocol=0x0800 ip_summed=0 hash=0x00000000 l4_hash=0 len=88 data_len=0 truesize=1984 mac_header_valid=1 mac_header=-14 nr_frags=0 gso_size=0 gso_type=0x0
  <idle>-0       0..s2   30us+: netif_receive_skb: dev=eth0 skbaddr=dca04400 len=88
  <idle>-0       0d.s5   98us : sched_waking: comm=sshd pid=750 prio=120 target_cpu=000
  <idle>-0       0d.s6  105us : sched_stat_sleep: comm=sshd pid=750 delay=3125230447 [ns]
  <idle>-0       0dns6  110us+: sched_wakeup: comm=sshd pid=750 prio=120 target_cpu=000
  <idle>-0       0dns4  123us+: timer_start: timer=dc940e9c function=tcp_delack_timer expires=9746 [timeout=10] flags=0x00000000
  <idle>-0       0dnH3  150us : irq_handler_entry: irq=176 name=4a100000.ethernet
  <idle>-0       0dnH3  153us : softirq_raise: vec=3 [action=NET_RX]
  <idle>-0       0dnH3  155us : irq_handler_exit: irq=176 ret=handled
  <idle>-0       0dnH3  160us : irq_handler_entry: irq=20 name=49000000.edma_ccint
  <idle>-0       0dnH3  163us : irq_handler_exit: irq=20 ret=handled
  <idle>-0       0.ns2  169us : napi_poll: napi poll on napi struct de465c30 for device eth0
  <idle>-0       0.ns2  171us : softirq_exit: vec=3 [action=NET_RX]
  <idle>-0       0dns3  175us : sched_waking: comm=ksoftirqd/0 pid=3 prio=120 target_cpu=000
  <idle>-0       0dns4  178us : sched_stat_sleep: comm=ksoftirqd/0 pid=3 delay=19371625 [ns]
  <idle>-0       0dns4  180us : sched_wakeup: comm=ksoftirqd/0 pid=3 prio=120 target_cpu=000
  <idle>-0       0.n.3  186us : gpio_value: 55 set 1
  <idle>-0       0dn.3  191us : hrtimer_cancel: hrtimer=c0e2af80
  <idle>-0       0dn.3  196us : hrtimer_start: hrtimer=c0e2af80 function=tick_sched_timer expires=338948000000 softexpires=338948000000
  <idle>-0       0dn.2  199us : rcu_utilization: Start context switch
  <idle>-0       0dn.2  202us : rcu_utilization: End context switch
  <idle>-0       0dn.3  206us : sched_stat_wait: comm=sshd pid=750 delay=74042 [ns]
  <idle>-0       0d..3  209us+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=sshd next_pid=750 next_prio=120
    sshd-750     0...1  252us : sys_exit: NR 142 = 1
    sshd-750     0...1  257us+: sys_select -> 0x1
    sshd-750     0...1  273us : sys_enter: NR 175 (0, be9cc238, be9cc1b8, 8, be9cc1b8, 0)
    sshd-750     0...1  276us : sys_rt_sigprocmask(how: 0, nset: be9cc238, oset: be9cc1b8, sigsetsize: 8)
    sshd-750     0...1  285us : sys_exit: NR 175 = 0
    sshd-750     0...1  287us : sys_rt_sigprocmask -> 0x0
    sshd-750     0...1  289us : sys_enter: NR 175 (2, be9cc1b8, 0, 8, 0, 2)
    sshd-750     0...1  290us : sys_rt_sigprocmask(how: 2, nset: be9cc1b8, oset: 0, sigsetsize: 8)
    sshd-750     0...1  292us : sys_exit: NR 175 = 0
    sshd-750     0...1  293us : sys_rt_sigprocmask -> 0x0
    sshd-750     0...1  299us : sys_enter: NR 263 (1, be9cc270, 801b25e8, 0, 7f60e3b0, 7f60ee7c)
    sshd-750     0...1  301us : sys_clock_gettime(which_clock: 1, tp: be9cc270)
    sshd-750     0...1  307us : sys_exit: NR 263 = 0
    sshd-750     0d.h2  313us+: irq_handler_entry: irq=160 name=481aa000.serial
    sshd-750     0d.h3  327us : omap_8250_rx_dma_flush: 481aa000.serial: ret:22 iir:0xc4 seq:19389 last:19388 elapsed:446292
    sshd-750     0d.h3  335us : __dma_rx_do_complete: 481aa000.serial: cmplt: iir=c4 count=48
    sshd-750     0d.h4  341us : workqueue_queue_work: work struct=de41239c function=flush_to_ldisc workqueue=de1bef00 req_cpu=1 cpu=4294967295
    sshd-750     0d.h4  343us : workqueue_activate_work: work struct de41239c
    sshd-750     0d.h5  346us : sched_waking: comm=kworker/u2:2 pid=763 prio=120 target_cpu=000
    sshd-750     0d.h6  350us : sched_stat_sleep: comm=kworker/u2:2 pid=763 delay=442250 [ns]
    sshd-750     0d.h6  359us : sched_wakeup: comm=kworker/u2:2 pid=763 prio=120 target_cpu=000
    sshd-750     0d.h3  366us : kfree: call_site=c05a88f0 ptr=de6ba940
    sshd-750     0d.h3  367us+: kfree: call_site=c05a88f0 ptr=de6f5640
    sshd-750     0d.h4  445us : kmalloc: call_site=c05aa6d0 ptr=de6f5640 bytes_req=132 bytes_alloc=192 gfp_flags=GFP_ATOMIC|GFP_ZERO
    sshd-750     0d.h2  455us : irq_handler_exit: irq=160 ret=handled
    sshd-750     0..s2  460us : softirq_entry: vec=3 [action=NET_RX]
    sshd-750     0..s2  469us : napi_poll: napi poll on napi struct de465c30 for device eth0
    sshd-750     0..s2  470us : softirq_exit: vec=3 [action=NET_RX]
    sshd-750     0..s2  472us : softirq_entry: vec=6 [action=TASKLET]
    sshd-750     0..s1  475us : tasklet_action
    sshd-750     0d.s1  478us+: tasklet_action <-tasklet_action
    sshd-750     0d.s1  521us : <stack trace>
 => irq_exit
 => __handle_domain_irq
 => omap_intc_handle_irq
 => __irq_svc
 => ftrace_syscall_exit
 => ftrace_syscall_exit
 => syscall_trace_exit
 => __sys_trace_return

[toc] | [next] | [standalone]

#1345085

From	Eric Dumazet <eric.dumazet@gmail.com>
Date	2016-02-27 21:20 +0100
Message-ID	<r6Tvl-8g6-23@gated-at.bofh.it>
In reply to	#1345055

On sam., 2016-02-27 at 10:19 -0800, Peter Hurley wrote:
> Hi Eric,
> 
> For a while now, we've been struggling to understand why we've been
> observing missed uart rx DMA.
> 
> Because both the uart driver (omap8250) and the dmaengine driver
> (edma) were (relatively) new, we assumed there was some race between
> starting a new rx DMA and processing the previous one.
> 
> However, after instrumenting both the uart driver and the dmaengine
> driver, what we've observed is huge anomalous latencies between receiving
> the DMA interrupt and servicing the DMA tasklet.
> 
> For example, at 3Mbaud we recorded the following distribution of
> softirq[TASKLET] service latency for this specific DMA channel:
> 
> root@black:/sys/kernel/debug/edma# cat 35
> latency(us):   0+   20+   40+   60+   80+  100+  120+  140+  160+  180+  200+  220+  240+  260+  280+  300+  320+  340+  360+  380+
>            195681    33    53    15     7     4     3     1     0     0     0     1     4     6     1     0     0     0     0     0
> 
> As you can see, the vast majority of tasklet service happens immediately,
> tapering off to 140+us.
> 
> However, note the island of distribution at 220~300 [latencies beyond 300+
> are not recorded because the uart fifo has filled again by this point and
> dma must be aborted].
> 
> So I cribbed together a latency tracer to catch what was happening at
> the extreme, and what it caught was a priority inversion stemming from
> your commit:
> 
>    commit c10d73671ad30f54692f7f69f0e09e75d3a8926a
>    Author: Eric Dumazet <edumazet@google.com>
>    Date:   Thu Jan 10 15:26:34 2013 -0800
> 
>        softirq: reduce latencies
>     
>        In various network workloads, __do_softirq() latencies can be up
>        to 20 ms if HZ=1000, and 200 ms if HZ=100.
>     
>        This is because we iterate 10 times in the softirq dispatcher,
>        and some actions can consume a lot of cycles.
> 
> 
> In the trace below [1], the trace begins in the edma completion interrupt
> handler when the tasklet is scheduled; the edma interrupt has occurred during
> NET_RX softirq context.
> 
> However, instead of causing a restart of the softirq loop to process the
> tasklet _which occurred before sshd was scheduled_, the softirq loop is
> aborted and deferred for ksoftirqd. The tasklet is not serviced for 521us,
> which is way too long, so DMA was aborted.
> 
> Your patch has effectively inverted the priority of tasklets with normal
> pri/nice processes that have merely received a network packet.
> 
> ISTM, the problem you're trying to solve here was caused by NET_RX softirq
> to begin with, and maybe that thing needs a diet.
> 
> But rather than outright reverting your patch, what if more selective
> conditions are used to abort the softirq restart? What would those conditions
> be? In the netperf benchmark you referred to in that commit, is it just
> NET_TX/NET_RX softirqs that are causing scheduling latencies?
> 
> It just doesn't make sense to special case for a workload that isn't
> even running.
> 
> 
> Regards,
> Peter Hurley
> 
> 
> [1] softirq tasklet latency trace  (apologies that it's only events - full
>     function trace introduces too much overhead)
> 
> # tracer: latency
> #
> # latency latency trace v1.1.5 on 4.5.0-rc2+
> # --------------------------------------------------------------------
> # latency: 476 us, #59/59, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0)
> #    -----------------
> #    | task: sshd-750 (uid:1000 nice:0 policy:0 rt_prio:0)
> #    -----------------
> #  => started at: __tasklet_schedule  
> #  => ended at:   tasklet_action
> #
> #
> #                  _------=> CPU#
> #                 / _-----=> irqs-off 
> #                | / _----=> need-resched
> #                || / _---=> hardirq/softirq
> #                ||| / _--=> preempt-depth
> #                |||| /     delay
> #  cmd     pid   ||||| time  |   caller
> #     \   /      |||||  \    |   /
>   <idle>-0       0d.H3    1us : __tasklet_schedule
>   <idle>-0       0d.H4    3us : softirq_raise: vec=6 [action=TASKLET]
>   <idle>-0       0d.H3    6us : irq_handler_exit: irq=20 ret=handled
>   <idle>-0       0..s2   15us : kmem_cache_alloc: call_site=c08378e4 ptr=de55d7c0 bytes_req=192 bytes_alloc=192 gfp_flags=GFP_ATOMIC
>   <idle>-0       0..s2   23us : netif_receive_skb_entry: dev=eth0 napi_id=0x0 queue_mapping=0 skbaddr=dca04400 vlan_tagged=0 vlan_proto=0x0000 vlan_tci=0x000
> 0 protocol=0x0800 ip_summed=0 hash=0x00000000 l4_hash=0 len=88 data_len=0 truesize=1984 mac_header_valid=1 mac_header=-14 nr_frags=0 gso_size=0 gso_type=0x0
>   <idle>-0       0..s2   30us+: netif_receive_skb: dev=eth0 skbaddr=dca04400 len=88
>   <idle>-0       0d.s5   98us : sched_waking: comm=sshd pid=750 prio=120 target_cpu=000
>   <idle>-0       0d.s6  105us : sched_stat_sleep: comm=sshd pid=750 delay=3125230447 [ns]
>   <idle>-0       0dns6  110us+: sched_wakeup: comm=sshd pid=750 prio=120 target_cpu=000
>   <idle>-0       0dns4  123us+: timer_start: timer=dc940e9c function=tcp_delack_timer expires=9746 [timeout=10] flags=0x00000000
>   <idle>-0       0dnH3  150us : irq_handler_entry: irq=176 name=4a100000.ethernet
>   <idle>-0       0dnH3  153us : softirq_raise: vec=3 [action=NET_RX]
>   <idle>-0       0dnH3  155us : irq_handler_exit: irq=176 ret=handled
>   <idle>-0       0dnH3  160us : irq_handler_entry: irq=20 name=49000000.edma_ccint
>   <idle>-0       0dnH3  163us : irq_handler_exit: irq=20 ret=handled
>   <idle>-0       0.ns2  169us : napi_poll: napi poll on napi struct de465c30 for device eth0
>   <idle>-0       0.ns2  171us : softirq_exit: vec=3 [action=NET_RX]
>   <idle>-0       0dns3  175us : sched_waking: comm=ksoftirqd/0 pid=3 prio=120 target_cpu=000
>   <idle>-0       0dns4  178us : sched_stat_sleep: comm=ksoftirqd/0 pid=3 delay=19371625 [ns]
>   <idle>-0       0dns4  180us : sched_wakeup: comm=ksoftirqd/0 pid=3 prio=120 target_cpu=000
>   <idle>-0       0.n.3  186us : gpio_value: 55 set 1
>   <idle>-0       0dn.3  191us : hrtimer_cancel: hrtimer=c0e2af80
>   <idle>-0       0dn.3  196us : hrtimer_start: hrtimer=c0e2af80 function=tick_sched_timer expires=338948000000 softexpires=338948000000
>   <idle>-0       0dn.2  199us : rcu_utilization: Start context switch
>   <idle>-0       0dn.2  202us : rcu_utilization: End context switch
>   <idle>-0       0dn.3  206us : sched_stat_wait: comm=sshd pid=750 delay=74042 [ns]
>   <idle>-0       0d..3  209us+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=sshd next_pid=750 next_prio=120
>     sshd-750     0...1  252us : sys_exit: NR 142 = 1
>     sshd-750     0...1  257us+: sys_select -> 0x1
>     sshd-750     0...1  273us : sys_enter: NR 175 (0, be9cc238, be9cc1b8, 8, be9cc1b8, 0)
>     sshd-750     0...1  276us : sys_rt_sigprocmask(how: 0, nset: be9cc238, oset: be9cc1b8, sigsetsize: 8)
>     sshd-750     0...1  285us : sys_exit: NR 175 = 0
>     sshd-750     0...1  287us : sys_rt_sigprocmask -> 0x0
>     sshd-750     0...1  289us : sys_enter: NR 175 (2, be9cc1b8, 0, 8, 0, 2)
>     sshd-750     0...1  290us : sys_rt_sigprocmask(how: 2, nset: be9cc1b8, oset: 0, sigsetsize: 8)
>     sshd-750     0...1  292us : sys_exit: NR 175 = 0
>     sshd-750     0...1  293us : sys_rt_sigprocmask -> 0x0
>     sshd-750     0...1  299us : sys_enter: NR 263 (1, be9cc270, 801b25e8, 0, 7f60e3b0, 7f60ee7c)
>     sshd-750     0...1  301us : sys_clock_gettime(which_clock: 1, tp: be9cc270)
>     sshd-750     0...1  307us : sys_exit: NR 263 = 0
>     sshd-750     0d.h2  313us+: irq_handler_entry: irq=160 name=481aa000.serial
>     sshd-750     0d.h3  327us : omap_8250_rx_dma_flush: 481aa000.serial: ret:22 iir:0xc4 seq:19389 last:19388 elapsed:446292
>     sshd-750     0d.h3  335us : __dma_rx_do_complete: 481aa000.serial: cmplt: iir=c4 count=48
>     sshd-750     0d.h4  341us : workqueue_queue_work: work struct=de41239c function=flush_to_ldisc workqueue=de1bef00 req_cpu=1 cpu=4294967295
>     sshd-750     0d.h4  343us : workqueue_activate_work: work struct de41239c
>     sshd-750     0d.h5  346us : sched_waking: comm=kworker/u2:2 pid=763 prio=120 target_cpu=000
>     sshd-750     0d.h6  350us : sched_stat_sleep: comm=kworker/u2:2 pid=763 delay=442250 [ns]
>     sshd-750     0d.h6  359us : sched_wakeup: comm=kworker/u2:2 pid=763 prio=120 target_cpu=000
>     sshd-750     0d.h3  366us : kfree: call_site=c05a88f0 ptr=de6ba940
>     sshd-750     0d.h3  367us+: kfree: call_site=c05a88f0 ptr=de6f5640
>     sshd-750     0d.h4  445us : kmalloc: call_site=c05aa6d0 ptr=de6f5640 bytes_req=132 bytes_alloc=192 gfp_flags=GFP_ATOMIC|GFP_ZERO
>     sshd-750     0d.h2  455us : irq_handler_exit: irq=160 ret=handled
>     sshd-750     0..s2  460us : softirq_entry: vec=3 [action=NET_RX]
>     sshd-750     0..s2  469us : napi_poll: napi poll on napi struct de465c30 for device eth0
>     sshd-750     0..s2  470us : softirq_exit: vec=3 [action=NET_RX]
>     sshd-750     0..s2  472us : softirq_entry: vec=6 [action=TASKLET]
>     sshd-750     0..s1  475us : tasklet_action
>     sshd-750     0d.s1  478us+: tasklet_action <-tasklet_action
>     sshd-750     0d.s1  521us : <stack trace>
>  => irq_exit
>  => __handle_domain_irq
>  => omap_intc_handle_irq
>  => __irq_svc
>  => ftrace_syscall_exit
>  => ftrace_syscall_exit
>  => syscall_trace_exit
>  => __sys_trace_return


Nothing in the linux kernel will make sure softirq are always processed
under the higher prio.

You are pointing out my patch but the real problem for you is having
ksoftirqd in the first place.

You need RT variant I guess, or a better hardware.

[toc] | [prev] | [next] | [standalone]

#1345090

From	Peter Hurley <peter@hurleysoftware.com>
Date	2016-02-27 21:40 +0100
Message-ID	<r6TOG-8mL-7@gated-at.bofh.it>
In reply to	#1345085

On 02/27/2016 12:13 PM, Eric Dumazet wrote:
> On sam., 2016-02-27 at 10:19 -0800, Peter Hurley wrote:
>> Hi Eric,
>>
>> For a while now, we've been struggling to understand why we've been
>> observing missed uart rx DMA.
>>
>> Because both the uart driver (omap8250) and the dmaengine driver
>> (edma) were (relatively) new, we assumed there was some race between
>> starting a new rx DMA and processing the previous one.
>>
>> However, after instrumenting both the uart driver and the dmaengine
>> driver, what we've observed is huge anomalous latencies between receiving
>> the DMA interrupt and servicing the DMA tasklet.
>>
>> For example, at 3Mbaud we recorded the following distribution of
>> softirq[TASKLET] service latency for this specific DMA channel:
>>
>> root@black:/sys/kernel/debug/edma# cat 35
>> latency(us):   0+   20+   40+   60+   80+  100+  120+  140+  160+  180+  200+  220+  240+  260+  280+  300+  320+  340+  360+  380+
>>            195681    33    53    15     7     4     3     1     0     0     0     1     4     6     1     0     0     0     0     0
>>
>> As you can see, the vast majority of tasklet service happens immediately,
>> tapering off to 140+us.
>>
>> However, note the island of distribution at 220~300 [latencies beyond 300+
>> are not recorded because the uart fifo has filled again by this point and
>> dma must be aborted].
>>
>> So I cribbed together a latency tracer to catch what was happening at
>> the extreme, and what it caught was a priority inversion stemming from
>> your commit:
>>
>>    commit c10d73671ad30f54692f7f69f0e09e75d3a8926a
>>    Author: Eric Dumazet <edumazet@google.com>
>>    Date:   Thu Jan 10 15:26:34 2013 -0800
>>
>>        softirq: reduce latencies
>>     
>>        In various network workloads, __do_softirq() latencies can be up
>>        to 20 ms if HZ=1000, and 200 ms if HZ=100.
>>     
>>        This is because we iterate 10 times in the softirq dispatcher,
>>        and some actions can consume a lot of cycles.
>>
>>
>> In the trace below [1], the trace begins in the edma completion interrupt
>> handler when the tasklet is scheduled; the edma interrupt has occurred during
>> NET_RX softirq context.
>>
>> However, instead of causing a restart of the softirq loop to process the
>> tasklet _which occurred before sshd was scheduled_, the softirq loop is
>> aborted and deferred for ksoftirqd. The tasklet is not serviced for 521us,
>> which is way too long, so DMA was aborted.
>>
>> Your patch has effectively inverted the priority of tasklets with normal
>> pri/nice processes that have merely received a network packet.
>>
>> ISTM, the problem you're trying to solve here was caused by NET_RX softirq
>> to begin with, and maybe that thing needs a diet.
>>
>> But rather than outright reverting your patch, what if more selective
>> conditions are used to abort the softirq restart? What would those conditions
>> be? In the netperf benchmark you referred to in that commit, is it just
>> NET_TX/NET_RX softirqs that are causing scheduling latencies?
>>
>> It just doesn't make sense to special case for a workload that isn't
>> even running.
>>
>>
>> Regards,
>> Peter Hurley
>>
>>
>> [1] softirq tasklet latency trace  (apologies that it's only events - full
>>     function trace introduces too much overhead)
>>
>> # tracer: latency
>> #
>> # latency latency trace v1.1.5 on 4.5.0-rc2+
>> # --------------------------------------------------------------------
>> # latency: 476 us, #59/59, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0)
>> #    -----------------
>> #    | task: sshd-750 (uid:1000 nice:0 policy:0 rt_prio:0)
>> #    -----------------
>> #  => started at: __tasklet_schedule  
>> #  => ended at:   tasklet_action
>> #
>> #
>> #                  _------=> CPU#
>> #                 / _-----=> irqs-off 
>> #                | / _----=> need-resched
>> #                || / _---=> hardirq/softirq
>> #                ||| / _--=> preempt-depth
>> #                |||| /     delay
>> #  cmd     pid   ||||| time  |   caller
>> #     \   /      |||||  \    |   /
>>   <idle>-0       0d.H3    1us : __tasklet_schedule
>>   <idle>-0       0d.H4    3us : softirq_raise: vec=6 [action=TASKLET]
>>   <idle>-0       0d.H3    6us : irq_handler_exit: irq=20 ret=handled
>>   <idle>-0       0..s2   15us : kmem_cache_alloc: call_site=c08378e4 ptr=de55d7c0 bytes_req=192 bytes_alloc=192 gfp_flags=GFP_ATOMIC
>>   <idle>-0       0..s2   23us : netif_receive_skb_entry: dev=eth0 napi_id=0x0 queue_mapping=0 skbaddr=dca04400 vlan_tagged=0 vlan_proto=0x0000 vlan_tci=0x000
>> 0 protocol=0x0800 ip_summed=0 hash=0x00000000 l4_hash=0 len=88 data_len=0 truesize=1984 mac_header_valid=1 mac_header=-14 nr_frags=0 gso_size=0 gso_type=0x0
>>   <idle>-0       0..s2   30us+: netif_receive_skb: dev=eth0 skbaddr=dca04400 len=88
>>   <idle>-0       0d.s5   98us : sched_waking: comm=sshd pid=750 prio=120 target_cpu=000
>>   <idle>-0       0d.s6  105us : sched_stat_sleep: comm=sshd pid=750 delay=3125230447 [ns]
>>   <idle>-0       0dns6  110us+: sched_wakeup: comm=sshd pid=750 prio=120 target_cpu=000
>>   <idle>-0       0dns4  123us+: timer_start: timer=dc940e9c function=tcp_delack_timer expires=9746 [timeout=10] flags=0x00000000
>>   <idle>-0       0dnH3  150us : irq_handler_entry: irq=176 name=4a100000.ethernet
>>   <idle>-0       0dnH3  153us : softirq_raise: vec=3 [action=NET_RX]
>>   <idle>-0       0dnH3  155us : irq_handler_exit: irq=176 ret=handled
>>   <idle>-0       0dnH3  160us : irq_handler_entry: irq=20 name=49000000.edma_ccint
>>   <idle>-0       0dnH3  163us : irq_handler_exit: irq=20 ret=handled
>>   <idle>-0       0.ns2  169us : napi_poll: napi poll on napi struct de465c30 for device eth0
>>   <idle>-0       0.ns2  171us : softirq_exit: vec=3 [action=NET_RX]
>>   <idle>-0       0dns3  175us : sched_waking: comm=ksoftirqd/0 pid=3 prio=120 target_cpu=000
>>   <idle>-0       0dns4  178us : sched_stat_sleep: comm=ksoftirqd/0 pid=3 delay=19371625 [ns]
>>   <idle>-0       0dns4  180us : sched_wakeup: comm=ksoftirqd/0 pid=3 prio=120 target_cpu=000
>>   <idle>-0       0.n.3  186us : gpio_value: 55 set 1
>>   <idle>-0       0dn.3  191us : hrtimer_cancel: hrtimer=c0e2af80
>>   <idle>-0       0dn.3  196us : hrtimer_start: hrtimer=c0e2af80 function=tick_sched_timer expires=338948000000 softexpires=338948000000
>>   <idle>-0       0dn.2  199us : rcu_utilization: Start context switch
>>   <idle>-0       0dn.2  202us : rcu_utilization: End context switch
>>   <idle>-0       0dn.3  206us : sched_stat_wait: comm=sshd pid=750 delay=74042 [ns]
>>   <idle>-0       0d..3  209us+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=sshd next_pid=750 next_prio=120
>>     sshd-750     0...1  252us : sys_exit: NR 142 = 1
>>     sshd-750     0...1  257us+: sys_select -> 0x1
>>     sshd-750     0...1  273us : sys_enter: NR 175 (0, be9cc238, be9cc1b8, 8, be9cc1b8, 0)
>>     sshd-750     0...1  276us : sys_rt_sigprocmask(how: 0, nset: be9cc238, oset: be9cc1b8, sigsetsize: 8)
>>     sshd-750     0...1  285us : sys_exit: NR 175 = 0
>>     sshd-750     0...1  287us : sys_rt_sigprocmask -> 0x0
>>     sshd-750     0...1  289us : sys_enter: NR 175 (2, be9cc1b8, 0, 8, 0, 2)
>>     sshd-750     0...1  290us : sys_rt_sigprocmask(how: 2, nset: be9cc1b8, oset: 0, sigsetsize: 8)
>>     sshd-750     0...1  292us : sys_exit: NR 175 = 0
>>     sshd-750     0...1  293us : sys_rt_sigprocmask -> 0x0
>>     sshd-750     0...1  299us : sys_enter: NR 263 (1, be9cc270, 801b25e8, 0, 7f60e3b0, 7f60ee7c)
>>     sshd-750     0...1  301us : sys_clock_gettime(which_clock: 1, tp: be9cc270)
>>     sshd-750     0...1  307us : sys_exit: NR 263 = 0
>>     sshd-750     0d.h2  313us+: irq_handler_entry: irq=160 name=481aa000.serial
>>     sshd-750     0d.h3  327us : omap_8250_rx_dma_flush: 481aa000.serial: ret:22 iir:0xc4 seq:19389 last:19388 elapsed:446292
>>     sshd-750     0d.h3  335us : __dma_rx_do_complete: 481aa000.serial: cmplt: iir=c4 count=48
>>     sshd-750     0d.h4  341us : workqueue_queue_work: work struct=de41239c function=flush_to_ldisc workqueue=de1bef00 req_cpu=1 cpu=4294967295
>>     sshd-750     0d.h4  343us : workqueue_activate_work: work struct de41239c
>>     sshd-750     0d.h5  346us : sched_waking: comm=kworker/u2:2 pid=763 prio=120 target_cpu=000
>>     sshd-750     0d.h6  350us : sched_stat_sleep: comm=kworker/u2:2 pid=763 delay=442250 [ns]
>>     sshd-750     0d.h6  359us : sched_wakeup: comm=kworker/u2:2 pid=763 prio=120 target_cpu=000
>>     sshd-750     0d.h3  366us : kfree: call_site=c05a88f0 ptr=de6ba940
>>     sshd-750     0d.h3  367us+: kfree: call_site=c05a88f0 ptr=de6f5640
>>     sshd-750     0d.h4  445us : kmalloc: call_site=c05aa6d0 ptr=de6f5640 bytes_req=132 bytes_alloc=192 gfp_flags=GFP_ATOMIC|GFP_ZERO
>>     sshd-750     0d.h2  455us : irq_handler_exit: irq=160 ret=handled
>>     sshd-750     0..s2  460us : softirq_entry: vec=3 [action=NET_RX]
>>     sshd-750     0..s2  469us : napi_poll: napi poll on napi struct de465c30 for device eth0
>>     sshd-750     0..s2  470us : softirq_exit: vec=3 [action=NET_RX]
>>     sshd-750     0..s2  472us : softirq_entry: vec=6 [action=TASKLET]
>>     sshd-750     0..s1  475us : tasklet_action
>>     sshd-750     0d.s1  478us+: tasklet_action <-tasklet_action
>>     sshd-750     0d.s1  521us : <stack trace>
>>  => irq_exit
>>  => __handle_domain_irq
>>  => omap_intc_handle_irq
>>  => __irq_svc
>>  => ftrace_syscall_exit
>>  => ftrace_syscall_exit
>>  => syscall_trace_exit
>>  => __sys_trace_return
> 
> 
> Nothing in the linux kernel will make sure softirq are always processed
> under the higher prio.

It's still a priority inversion, and an unnecessary one at that.


> You are pointing out my patch but the real problem for you is having
> ksoftirqd in the first place.

Not really. softirq raised from interrupt context will always execute
on this cpu and not in ksoftirqd, unless load forces softirq loop abort.

In this case, there is no load.


> You need RT variant I guess, or a better hardware.

500us for softirq while at idle is hardly the litmus the RT.

So then no suggestions for reducing the scope of your patch?

Regards,
Peter Hurley

[toc] | [prev] | [next] | [standalone]

#1345101

From	David Miller <davem@davemloft.net>
Date	2016-02-28 00:10 +0100
Message-ID	<r6W9Q-1Gk-3@gated-at.bofh.it>
In reply to	#1345090

From: Peter Hurley <peter@hurleysoftware.com>
Date: Sat, 27 Feb 2016 12:29:39 -0800

> Not really. softirq raised from interrupt context will always execute
> on this cpu and not in ksoftirqd, unless load forces softirq loop abort.

That guarantee never was specified.

Or are you saying that by design, on a system under load, your UART
will not function properly?

Surely you don't mean that.

[toc] | [prev] | [next] | [standalone]

#1345111

From	Peter Hurley <peter@hurleysoftware.com>
Date	2016-02-28 00:40 +0100
Message-ID	<r6WCR-1Vu-1@gated-at.bofh.it>
In reply to	#1345101

On 02/27/2016 03:04 PM, David Miller wrote:
> From: Peter Hurley <peter@hurleysoftware.com>
> Date: Sat, 27 Feb 2016 12:29:39 -0800
> 
>> Not really. softirq raised from interrupt context will always execute
>> on this cpu and not in ksoftirqd, unless load forces softirq loop abort.
> 
> That guarantee never was specified.

??

Neither is running network socket servers at normal priority as if they're
higher priority than softirq.

> Or are you saying that by design, on a system under load, your UART
> will not function properly?
> 
> Surely you don't mean that.

No, that's not what I mean.

What I mean is that bypassing the entire SOFTIRQ priority so that
sshd can process one network packet makes a mockery of the point of softirq.

This hack to workaround NET_RX looping over-and-over-and-over affects every
subsystem, not just one uart.

HI, TIMER, BLOCK; all of these are skipped: that's straight-up, a bug.

Regards,
Peter Hurley

[toc] | [prev] | [next] | [standalone]

#1345134

From	Eric Dumazet <eric.dumazet@gmail.com>
Date	2016-02-28 03:10 +0100
Message-ID	<r6YY2-3PY-5@gated-at.bofh.it>
In reply to	#1345111

On sam., 2016-02-27 at 15:33 -0800, Peter Hurley wrote:
> On 02/27/2016 03:04 PM, David Miller wrote:
> > From: Peter Hurley <peter@hurleysoftware.com>
> > Date: Sat, 27 Feb 2016 12:29:39 -0800
> > 
> >> Not really. softirq raised from interrupt context will always execute
> >> on this cpu and not in ksoftirqd, unless load forces softirq loop abort.
> > 
> > That guarantee never was specified.
> 
> ??
> 
> Neither is running network socket servers at normal priority as if they're
> higher priority than softirq.
> 
> 
> > Or are you saying that by design, on a system under load, your UART
> > will not function properly?
> > 
> > Surely you don't mean that.
> 
> No, that's not what I mean.
> 
> What I mean is that bypassing the entire SOFTIRQ priority so that
> sshd can process one network packet makes a mockery of the point of softirq.
> 
> This hack to workaround NET_RX looping over-and-over-and-over affects every
> subsystem, not just one uart.
> 
> HI, TIMER, BLOCK; all of these are skipped: that's straight-up, a bug.

No idea what you talk about.

All pending softirq interrupts are processed. _Nothing_ is skipped.

Really, your system stability seems to depend on a completely
undocumented behavior of linux kernels before linux-3.8

If I understood, you expect that a tasklet activated from a softirq
handler is run from the same  __do_softirq() loop. This never has been
the case.

My change simply triggers the bug in your driver earlier. As David
pointed out, your bug should trigger the same on a loaded machine, even
if you revert my patch.

I honestly do not know why you arm a tasklet from NET_RX, why don't you
simply process this directly, so that you do not rely on some scheduler
decision ?

[toc] | [prev] | [next] | [standalone]

#1345135

From	Peter Hurley <peter@hurleysoftware.com>
Date	2016-02-28 03:20 +0100
Message-ID	<r6Z7I-3Tt-1@gated-at.bofh.it>
In reply to	#1345134

On 02/27/2016 05:59 PM, Eric Dumazet wrote:
> On sam., 2016-02-27 at 15:33 -0800, Peter Hurley wrote:
>> On 02/27/2016 03:04 PM, David Miller wrote:
>>> From: Peter Hurley <peter@hurleysoftware.com>
>>> Date: Sat, 27 Feb 2016 12:29:39 -0800
>>>
>>>> Not really. softirq raised from interrupt context will always execute
>>>> on this cpu and not in ksoftirqd, unless load forces softirq loop abort.
>>>
>>> That guarantee never was specified.
>>
>> ??
>>
>> Neither is running network socket servers at normal priority as if they're
>> higher priority than softirq.
>>
>>
>>> Or are you saying that by design, on a system under load, your UART
>>> will not function properly?
>>>
>>> Surely you don't mean that.
>>
>> No, that's not what I mean.
>>
>> What I mean is that bypassing the entire SOFTIRQ priority so that
>> sshd can process one network packet makes a mockery of the point of softirq.
>>
>> This hack to workaround NET_RX looping over-and-over-and-over affects every
>> subsystem, not just one uart.
>>
>> HI, TIMER, BLOCK; all of these are skipped: that's straight-up, a bug.
> 
> No idea what you talk about.
> 
> All pending softirq interrupts are processed. _Nothing_ is skipped.

An interrupt that schedules HI softirq while in NET_RX softirq should
still run the HI softirq. But with your patch that won't happen.


> Really, your system stability seems to depend on a completely
> undocumented behavior of linux kernels before linux-3.8
> 
> If I understood, you expect that a tasklet activated from a softirq
> handler is run from the same  __do_softirq() loop. This never has been
> the case.

No.

The *interrupt handler* for DMA goes off while NET_RX softirq is running.
That's what schedules the *DMA tasklet*.

That tasklet should run before any process.

But it doesn't because your patch bails out early from softirq.


> My change simply triggers the bug in your driver earlier. As David
> pointed out, your bug should trigger the same on a loaded machine, even
> if you revert my patch.
> 
> I honestly do not know why you arm a tasklet from NET_RX, why don't you
> simply process this directly, so that you do not rely on some scheduler
> decision ?

[toc] | [prev] | [next] | [standalone]

#1345137

From	Eric Dumazet <eric.dumazet@gmail.com>
Date	2016-02-28 03:20 +0100
Message-ID	<r6Z7I-3Tt-7@gated-at.bofh.it>
In reply to	#1345135

On sam., 2016-02-27 at 18:10 -0800, Peter Hurley wrote:
> On 02/27/2016 05:59 PM, Eric Dumazet wrote:
> > On sam., 2016-02-27 at 15:33 -0800, Peter Hurley wrote:
> >> On 02/27/2016 03:04 PM, David Miller wrote:
> >>> From: Peter Hurley <peter@hurleysoftware.com>
> >>> Date: Sat, 27 Feb 2016 12:29:39 -0800
> >>>
> >>>> Not really. softirq raised from interrupt context will always execute
> >>>> on this cpu and not in ksoftirqd, unless load forces softirq loop abort.
> >>>
> >>> That guarantee never was specified.
> >>
> >> ??
> >>
> >> Neither is running network socket servers at normal priority as if they're
> >> higher priority than softirq.
> >>
> >>
> >>> Or are you saying that by design, on a system under load, your UART
> >>> will not function properly?
> >>>
> >>> Surely you don't mean that.
> >>
> >> No, that's not what I mean.
> >>
> >> What I mean is that bypassing the entire SOFTIRQ priority so that
> >> sshd can process one network packet makes a mockery of the point of softirq.
> >>
> >> This hack to workaround NET_RX looping over-and-over-and-over affects every
> >> subsystem, not just one uart.
> >>
> >> HI, TIMER, BLOCK; all of these are skipped: that's straight-up, a bug.
> > 
> > No idea what you talk about.
> > 
> > All pending softirq interrupts are processed. _Nothing_ is skipped.
> 
> An interrupt that schedules HI softirq while in NET_RX softirq should
> still run the HI softirq. But with your patch that won't happen.

Stop saying this. This never had been the case. I am glad my patch
finally show you are wrong.

> 
> 
> > Really, your system stability seems to depend on a completely
> > undocumented behavior of linux kernels before linux-3.8
> > 
> > If I understood, you expect that a tasklet activated from a softirq
> > handler is run from the same  __do_softirq() loop. This never has been
> > the case.
> 
> No.
> 
> The *interrupt handler* for DMA goes off while NET_RX softirq is running.
> That's what schedules the *DMA tasklet*.
> 
> That tasklet should run before any process.
> 
> But it doesn't because your patch bails out early from softirq.

Fine. Fix your driver.

[toc] | [prev] | [next] | [standalone]

#1345161

From	David Miller <davem@davemloft.net>
Date	2016-02-28 05:50 +0100
Message-ID	<r71sS-5x9-3@gated-at.bofh.it>
In reply to	#1345135

From: Peter Hurley <peter@hurleysoftware.com>
Date: Sat, 27 Feb 2016 18:10:27 -0800

> That tasklet should run before any process.

You never have this guarantee, even before Eric's patch.
Under load tasklets run from ksoftirqd just like any other
softirq.

Please fix your driver and stop blaming Eric's change.

Thank you.

[toc] | [prev] | [next] | [standalone]

#1345169

From	Mike Galbraith <umgwanakikbuti@gmail.com>
Date	2016-02-28 07:00 +0100
Message-ID	<r72yB-6lb-1@gated-at.bofh.it>
In reply to	#1345055

On Sat, 2016-02-27 at 10:19 -0800, Peter Hurley wrote:
> Hi Eric,
> 
> For a while now, we've been struggling to understand why we've been
> observing missed uart rx DMA.
> 
> Because both the uart driver (omap8250) and the dmaengine driver
> (edma) were (relatively) new, we assumed there was some race between
> starting a new rx DMA and processing the previous one.

Hrm, relatively new + tasklet woes rings a bell.  Ah, that..

<quote>
What's worse is that at the point where this code was written it was
already well known that tasklets are a steaming pile of crap and
should die.
</quote>

Source thereof https://lwn.net/Articles/588457/

	-Mike

[toc] | [prev] | [next] | [standalone]

#1345358

From	Francois Romieu <romieu@fr.zoreil.com>
Date	2016-02-28 18:10 +0100
Message-ID	<r7d0Z-5MI-7@gated-at.bofh.it>
In reply to	#1345169

Mike Galbraith <umgwanakikbuti@gmail.com> :
[...]
> Hrm, relatively new + tasklet woes rings a bell.  Ah, that..
> 
> <quote>
> What's worse is that at the point where this code was written it was
> already well known that tasklets are a steaming pile of crap and
> should die.
> </quote>
> 
> Source thereof https://lwn.net/Articles/588457/

tasklets are ingrained in the dmaengine API (see Documentation/dmaengine/client.txt
and drivers/dma/virt-dma.h::vchan_cookie_complete).

Moving everything to irq context or handling his own sub-{jiffy/ms} timer
while losing async dma doesn't exactly smell like roses either. :o(

-- 
Ueimor

[toc] | [prev] | [next] | [standalone]

#1345483

From	Mike Galbraith <umgwanakikbuti@gmail.com>
Date	2016-02-29 06:00 +0100
Message-ID	<r7o66-5A0-5@gated-at.bofh.it>
In reply to	#1345358

On Sun, 2016-02-28 at 18:01 +0100, Francois Romieu wrote:
> Mike Galbraith <umgwanakikbuti@gmail.com> :
> [...]
> > Hrm, relatively new + tasklet woes rings a bell.  Ah, that..
> > 
> > 
> > What's worse is that at the point where this code was written it was
> > already well known that tasklets are a steaming pile of crap and
> > should die.
> > 
> > 
> > Source thereof https://lwn.net/Articles/588457/
> 
> tasklets are ingrained in the dmaengine API (see Documentation/dmaengine/client.txt
> and drivers/dma/virt-dma.h::vchan_cookie_complete).
> 
> Moving everything to irq context or handling his own sub-{jiffy/ms} timer
> while losing async dma doesn't exactly smell like roses either. :o(

https://lwn.net/Articles/239633/

If I'm listening properly, the root cause is that there is a timing
constraint involved, which is being exposed because one softirq raises
another (ew).  Processing timeout happens, freshly raised tasklet
wanders off to SCHED_NORMAL kthread context where its constraint dies.

Given the dma stuff apparently works fine in -rt (or did, see below),
timing constraints can't be super tight, so perhaps we could grow
realtime workqueue support for the truly deserving.  The tricky bit
would be being keeping everybody and his brother from abusing it.

WRT -rt: if dma tasklets really do have hard (ish) constraints, -rt
recently "broke" in the same way.. of all softirqs which are deferred
to kthread context, due to a recent change, only timer/hrtimer are
executed at realtime priority by default.

	-Mike

[toc] | [prev] | [next] | [standalone]

#1345895

From	Peter Hurley <peter@hurleysoftware.com>
Date	2016-02-29 16:10 +0100
Message-ID	<r7xCs-4FN-45@gated-at.bofh.it>
In reply to	#1345483

On 02/28/2016 08:58 PM, Mike Galbraith wrote:
> On Sun, 2016-02-28 at 18:01 +0100, Francois Romieu wrote:
>> Mike Galbraith <umgwanakikbuti@gmail.com> :
>> [...]
>>> Hrm, relatively new + tasklet woes rings a bell.  Ah, that..
>>>
>>>
>>> What's worse is that at the point where this code was written it was
>>> already well known that tasklets are a steaming pile of crap and
>>> should die.
>>>
>>>
>>> Source thereof https://lwn.net/Articles/588457/

Thanks but not applicable. tglx's POV has everything to do with the
tasklet interface and not the general concept of bottom-half interrupt
processing in a timely manner. In any event, the problem created by
Eric's change is not restricted to tasklets, but rather applies to
all softirq.

>> tasklets are ingrained in the dmaengine API (see Documentation/dmaengine/client.txt
>> and drivers/dma/virt-dma.h::vchan_cookie_complete).
>>
>> Moving everything to irq context or handling his own sub-{jiffy/ms} timer
>> while losing async dma doesn't exactly smell like roses either. :o(
> 
> https://lwn.net/Articles/239633/
> 
> If I'm listening properly, the root cause is that there is a timing
> constraint involved, which is being exposed because one softirq raises
> another (ew).

Not the case. The softirq is raised from interrupt.

Before Eric's change, when an interrupt raises a new softirq
while processing another softirq, the new softirq is immediately
processed *after the existing softirq completes*.

After Eric's change, when an interrupt raises a new softirq
while processing another softirq and _that softirq wakes a process_,
the new softirq is *deferred to normal process priority*.
This happens even if the new softirq is higher priority than the
one currently running, which is flat-out wrong.

The reason this happens repeatedly and regularly is because
1. The time window while NET_RX softirq is running is big.
2. NET_RX softirq will almost always wake a process for a received packet.

The reason why Eric's change is so effective for Eric's workload is
that it fixes the problem where NET_RX keeps getting new network packets
so it keeps looping, servicing more NET_RX softirq.

However, I'm pointing out that Eric's sledgehammer approach to fixing
the NET_RX softirq bug is having significant side-effects in other
subsystems.

> Processing timeout happens, freshly raised tasklet
> wanders off to SCHED_NORMAL kthread context where its constraint dies.
> 
> Given the dma stuff apparently works fine in -rt (or did, see below),
> timing constraints can't be super tight, so perhaps we could grow
> realtime workqueue support for the truly deserving.  The tricky bit
> would be being keeping everybody and his brother from abusing it.
> 
> WRT -rt: if dma tasklets really do have hard (ish) constraints, -rt
> recently "broke" in the same way.. of all softirqs which are deferred
> to kthread context, due to a recent change, only timer/hrtimer are
> executed at realtime priority by default.
> 
> 	-Mike
>

[toc] | [prev] | [next] | [standalone]

#1345905

From	Eric Dumazet <eric.dumazet@gmail.com>
Date	2016-02-29 16:30 +0100
Message-ID	<r7xVM-4Nd-15@gated-at.bofh.it>
In reply to	#1345895

On lun., 2016-02-29 at 07:03 -0800, Peter Hurley wrote:

> Not the case. The softirq is raised from interrupt.
> 
> Before Eric's change, when an interrupt raises a new softirq
> while processing another softirq, the new softirq is immediately
> processed *after the existing softirq completes*.
> 
> After Eric's change, when an interrupt raises a new softirq
> while processing another softirq and _that softirq wakes a process_,
> the new softirq is *deferred to normal process priority*.

For the last time, this is not true.

My patch changed the probability for this to happen.

It will happen even if you revert it.

linux never claimed that softirq could steal all cpu time.

Are by any chance still running a HZ=100 kernel ?

[toc] | [prev] | [next] | [standalone]

#1345936

From	Peter Hurley <peter@hurleysoftware.com>
Date	2016-02-29 17:00 +0100
Message-ID	<r7yoP-4YQ-35@gated-at.bofh.it>
In reply to	#1345905

On 02/29/2016 07:19 AM, Eric Dumazet wrote:
> On lun., 2016-02-29 at 07:03 -0800, Peter Hurley wrote:
> 
>> Not the case. The softirq is raised from interrupt.
>>
>> Before Eric's change, when an interrupt raises a new softirq
>> while processing another softirq, the new softirq is immediately
>> processed *after the existing softirq completes*.
>>
>> After Eric's change, when an interrupt raises a new softirq
>> while processing another softirq and _that softirq wakes a process_,
>> the new softirq is *deferred to normal process priority*.
> 
> For the last time, this is not true.
> 
> My patch changed the probability for this to happen.

There is a huge difference between
1. heavy i/o load forcing ksoftirqd to battle out i/o with regular
   sched processes *as a fallback to avoid 100% softirq* and
2. always deferring new softirq just because a process was woken

> It will happen even if you revert it.

I think there is a happy medium where finer constraints on
softirq looping will get us both what we want.

For example, an accumulating mask of softirq already run would
keep one softirq level from looping over-and-over. Or a per-softirq
limiting counter. Or relying on the hard limit that was added later
of a fixed number of softirq loops. Or a combination of those.

> linux never claimed that softirq could steal all cpu time.

That's not the problem observed here.

In fact, what your patch triggers is exactly the opposite:
although cpu load is initially very light because DMA is used to perform
device i/o, once DMA is not being serviced in a timely manner, the
driver fallbacks to purely interrupt-driven i/o which dramatically
increases the real cpu load at those line rates.

> Are by any chance still running a HZ=100 kernel ?

The current kernel is HZ=250 but this would occur on HZ=1000 as well.

Regards,
Peter Hurley

[toc] | [prev] | [next] | [standalone]

#1345960

From	Eric Dumazet <eric.dumazet@gmail.com>
Date	2016-02-29 17:30 +0100
Message-ID	<r7yRQ-5oO-5@gated-at.bofh.it>
In reply to	#1345936

On lun., 2016-02-29 at 07:54 -0800, Peter Hurley wrote:

>  The current kernel is HZ=250 but this would occur on HZ=1000 as well.

Right. But the problem with HZ=100 and HZ=250 is that the detection can
happens because jiffy granularity is too coarse, since 

msecs_to_jiffies(2) -> 1

Following patch might reduce the probability, but wont really fix your
problem.

Fact that ksoftirqd prio is not what you want is completely orthogonal.

diff --git a/kernel/softirq.c b/kernel/softirq.c
index 479e443..f7cc594 100644
--- a/kernel/softirq.c
+++ b/kernel/softirq.c
@@ -180,7 +180,7 @@ EXPORT_SYMBOL(__local_bh_enable_ip);
 
 /*
  * We restart softirq processing for at most MAX_SOFTIRQ_RESTART times,
- * but break the loop if need_resched() is set or after 2 ms.
+ * but break the loop if need_resched() is set or after 2 ms/ticks.
  * The MAX_SOFTIRQ_TIME provides a nice upper bound in most cases, but in
  * certain cases, such as stop_machine(), jiffies may cease to
  * increment and so we need the MAX_SOFTIRQ_RESTART limit as
@@ -191,7 +191,7 @@ EXPORT_SYMBOL(__local_bh_enable_ip);
  * we want to handle softirqs as soon as possible, but they
  * should not be able to lock up the box.
  */
-#define MAX_SOFTIRQ_TIME  msecs_to_jiffies(2)
+#define MAX_SOFTIRQ_TIME  (1 + msecs_to_jiffies(2))
 #define MAX_SOFTIRQ_RESTART 10
 
 #ifdef CONFIG_TRACE_IRQFLAGS

[toc] | [prev] | [next] | [standalone]

#1346052

From	Peter Hurley <peter@hurleysoftware.com>
Date	2016-02-29 19:10 +0100
Message-ID	<r7AqB-6t8-1@gated-at.bofh.it>
In reply to	#1345960

On 02/29/2016 08:21 AM, Eric Dumazet wrote:
> On lun., 2016-02-29 at 07:54 -0800, Peter Hurley wrote:
> 
>>  The current kernel is HZ=250 but this would occur on HZ=1000 as well.
> 
> Right. But the problem with HZ=100 and HZ=250 is that the detection can
> happens because jiffy granularity is too coarse, since 
> 
> msecs_to_jiffies(2) -> 1
> 
> Following patch might reduce the probability, but wont really fix your
> problem.
> 
> Fact that ksoftirqd prio is not what you want is completely orthogonal.
> 
> diff --git a/kernel/softirq.c b/kernel/softirq.c
> index 479e443..f7cc594 100644
> --- a/kernel/softirq.c
> +++ b/kernel/softirq.c
> @@ -180,7 +180,7 @@ EXPORT_SYMBOL(__local_bh_enable_ip);
>  
>  /*
>   * We restart softirq processing for at most MAX_SOFTIRQ_RESTART times,
> - * but break the loop if need_resched() is set or after 2 ms.
> + * but break the loop if need_resched() is set or after 2 ms/ticks.
>   * The MAX_SOFTIRQ_TIME provides a nice upper bound in most cases, but in
>   * certain cases, such as stop_machine(), jiffies may cease to
>   * increment and so we need the MAX_SOFTIRQ_RESTART limit as
> @@ -191,7 +191,7 @@ EXPORT_SYMBOL(__local_bh_enable_ip);
>   * we want to handle softirqs as soon as possible, but they
>   * should not be able to lock up the box.
>   */
> -#define MAX_SOFTIRQ_TIME  msecs_to_jiffies(2)
> +#define MAX_SOFTIRQ_TIME  (1 + msecs_to_jiffies(2))
>  #define MAX_SOFTIRQ_RESTART 10
>  
>  #ifdef CONFIG_TRACE_IRQFLAGS

While I appreciate the attempt, that's not the problem.

Just to be clear

		if (time_before(jiffies, end) && !need_resched() &&
		    --max_restart)
			goto restart;

aborts softirq *even if 0ns have elapsed*, if NET_RX has woken a process.

[toc] | [prev] | [next] | [standalone]

#1346069

From	Eric Dumazet <eric.dumazet@gmail.com>
Date	2016-02-29 19:30 +0100
Message-ID	<r7AJY-6Ab-9@gated-at.bofh.it>
In reply to	#1346052

On lun., 2016-02-29 at 10:05 -0800, Peter Hurley wrote:

> While I appreciate the attempt, that's not the problem.
> 
> Just to be clear
> 
> 		if (time_before(jiffies, end) && !need_resched() &&
> 		    --max_restart)
> 			goto restart;
> 
> aborts softirq *even if 0ns have elapsed*, if NET_RX has woken a process.

Sure, now remove the 1st and 2nd condition.

You would still 'abort' (ie wakeup ksoftirqd really) when --max_restart
becomes 0

So, instead of some subtle load dependent bug, you know have a reliable
trigger.

The fact it took 3 years for someone to complain about this change
should tell us something really.

The only way for your bug to hide would be to remove all the 'break
infinite loop' logic.

And this is not going to happen.

[toc] | [prev] | [next] | [standalone]

#1346096

From	Peter Hurley <peter@hurleysoftware.com>
Date	2016-02-29 20:00 +0100
Message-ID	<r7Bd1-6NF-41@gated-at.bofh.it>
In reply to	#1346069

On 02/29/2016 10:24 AM, Eric Dumazet wrote:
> On lun., 2016-02-29 at 10:05 -0800, Peter Hurley wrote:
> 
>> While I appreciate the attempt, that's not the problem.
>>
>> Just to be clear
>>
>> 		if (time_before(jiffies, end) && !need_resched() &&
>> 		    --max_restart)
>> 			goto restart;
>>
>> aborts softirq *even if 0ns have elapsed*, if NET_RX has woken a process.
> 
> 
> Sure, now remove the 1st and 2nd condition.

Well just removing the 2nd condition has everything working fine,
because that fixes the priority inversion.

> You would still 'abort' (ie wakeup ksoftirqd really) when --max_restart
> becomes 0

Sure. Which would mean there's contended heavy i/o load so the driver
has to fallback to non-DMA. That's an acceptable outcome.

> So, instead of some subtle load dependent bug, you know have a reliable
> trigger.

There's no "subtle load dependent bug" here.

The driver has a fallback mode of operation that it relies on without
DMA. Of course, as I already wrote, this has consequences.

If system resources are _actually contended_, then naturally, fighting
for cpu and i/o time is fine, and I'm happy to do that in ksoftirqd.

However, when system resources are _not_ contended, it makes no
sense to be forced to revert to ksoftirqd resolution, which is strictly
intended as fallback.

Or flipping your argument on its head, why not just _always_ execute
softirq in ksoftirqd?

[toc] | [prev] | [next] | [standalone]

#1346105

From	Thomas Gleixner <tglx@linutronix.de>
Date	2016-02-29 20:20 +0100
Message-ID	<r7Bwm-79s-13@gated-at.bofh.it>
In reply to	#1346096

On Mon, 29 Feb 2016, Peter Hurley wrote:
> On 02/29/2016 10:24 AM, Eric Dumazet wrote:
> >> Just to be clear
> >>
> >> 		if (time_before(jiffies, end) && !need_resched() &&
> >> 		    --max_restart)
> >> 			goto restart;
> >>
> >> aborts softirq *even if 0ns have elapsed*, if NET_RX has woken a process.
> > 
> > Sure, now remove the 1st and 2nd condition.
> 
> Well just removing the 2nd condition has everything working fine,
> because that fixes the priority inversion.

No. It does not fix anything. It hides the shortcomings of the driver.

> However, when system resources are _not_ contended, it makes no
> sense to be forced to revert to ksoftirqd resolution, which is strictly
> intended as fallback.

No. You claim it is simply because your driver does not handle that situation
properly.

> Or flipping your argument on its head, why not just _always_ execute
> softirq in ksoftirqd?

Which is what that change effectivley does. And that makes a lot of sense,
because you get the softirq load under scheduler control and do not let the
softirq run as a context stealing entity which is completely uncontrollable by
the scheduler.

Running the softirq on return from interrupt can cause real priority
inversions.

Thanks,

	tglx

[toc] | [prev] | [next] | [standalone]

Page 1 of 2 [1] 2 Next page →

csiph-web

Softirq priority inversion from "softirq: reduce latencies"

Contents

#1345055 — Softirq priority inversion from "softirq: reduce latencies"

#1345085

#1345090

#1345101

#1345111

#1345134

#1345135

#1345137

#1345161

#1345169

#1345358

#1345483

#1345895

#1345905

#1345936

#1345960

#1346052

#1346069

#1346096

#1346105