Re: [RFC 1/2] softirq: Defer net rx/tx processing to ksoftirqd context

[Dmitry Safonov <dima@arista.com>]

On Tue, 2018-01-09 at 17:03 +0100, Frederic Weisbecker wrote:
> 2018-01-09 14:36 UTC+01:00, Dmitry Safonov <dima@arista.com>:
> > Warning: Not merge-ready
> > 
> > I. Current workflow of ksoftirqd.
> >   Softirqs are processed in the context of ksoftirqd iff they are
> >   being raised very frequently. How it works:
> >   do_softirq() and invoke_softirq() deffer pending softirq iff
> >   ksoftirqd is in runqueue. Ksoftirqd is scheduled mostly in the
> >   end of processed softirqs if 2ms were not enough to process all
> >   pending softirqs.
> > 
> >   Here is pseudo-picture of the workflow (for simplicity on UMP):
> >   -------------      ------------------      ------------------
> >   | ksoftirqd |      | User's process |      |   Softirqs     |
> >   -------------      ------------------      ------------------
> >    Not scheduled          Running
> >                              |
> >                              o------------------------o
> >                                                       |
> >                                                 __do_softirq()
> >                                                       |
> >                                               2ms & softirq
> > pending?
> >                                               Schedule ksoftirqd
> >                                                       |
> >     Scheduled                o------------------------o
> >                              |
> >         o--------------------o
> >         |
> >      Running             Scheduled
> >         |
> >         o--------------------o
> >                              |
> >    Not scheduled          Running
> > 
> >    Timegraph for the workflow,
> >      dash (-) means ksoftirqd not scheduled;
> >      equal(=) ksoftirqd is scheduled, a softirq may still be
> > pending
> > 
> >                            Pending softirqs
> >                 | | | |           | | | |       |
> >                 v v v v           | | | |       v
> >    Processing   o-----o           | | | |       o--o
> >     softirqs    |     |           | | | |       |  |
> >                 |     |           | | | |       |  |
> >                 |     |           | | | |       |  |
> >    Userspace  o-o     o=========o | | | |  o----o  o---------o
> >                 <-2ms->         | | | | |  |
> >                                 | v v v v  |
> >    Ksoftirqd                    o----------o
> > 
> > II. Corner-conditions.
> >   During testing of commit [1] on some non-mainstream driver,
> >   I've found that due to platform specifics, the IRQ is being
> >   raised too late (after softirq has been processed).
> 
> I'm a bit confused about that part. I would expect the softirq to be
> raised by the IRQ.

The rx-softirq is raised by napi_schedule(), which is called on
receiving an interrupt from device, yes.

> So I guess in this scenario the softirq is raised by something else
> and you expect the upcoming IRQ to handle the softirq, right? (sorry
> I'm not used to networking code).

So, the softirq is served by after upcomming IRQ. But in the end of the
softirq there is no yet-pending softirq. And just after irq_exit(),
there emerges another pending softirq.
ITOW, here is what I see on the trace:


          python-8597  [001] d... 16635.495480: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.495498: rcu_irq_exit <-irq_exit
          python-8597  [001] d... 16635.495503: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.495533: rcu_irq_exit <-irq_exit
          python-8597  [001] d... 16635.495542: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.495567: rcu_irq_exit <-irq_exit
          python-8597  [001] d... 16635.495576: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.495601: rcu_irq_exit <-irq_exit
          python-8597  [001] d... 16635.495615: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.495627: rcu_irq_exit <-irq_exit
          python-8597  [001] d... 16635.495637: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.495668: rcu_irq_exit <-irq_exit
          python-8597  [001] d... 16635.495684: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.495703: rcu_irq_exit <-irq_exit
          python-8597  [001] d... 16635.495710: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.495723: rcu_irq_exit <-irq_exit
          python-8597  [001] d... 16635.495736: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.495755: rcu_irq_exit <-irq_exit
          python-8597  [001] d... 16635.495769: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.495788: rcu_irq_exit <-irq_exit
          python-8597  [001] d... 16635.495804: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.495822: rcu_irq_exit <-irq_exit
          python-8597  [001] d... 16635.495834: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.495857: rcu_irq_exit <-irq_exit
          python-8597  [001] d... 16635.495868: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.495891: rcu_irq_exit <-irq_exit
          python-8597  [001] d.s1 16635.495907: rcu_irq_exit <-irq_exit
          python-8597  [001] d..1 16635.495908: __do_softirq <-
do_softirq_own_stack
          python-8597  [001] d... 16635.495939: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.495959: rcu_irq_exit <-irq_exit
          python-8597  [001] d... 16635.495973: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.495988: rcu_irq_exit <-irq_exit
          python-8597  [001] d... 16635.496002: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.496014: rcu_irq_exit <-irq_exit
          python-8597  [001] d... 16635.496027: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.496044: rcu_irq_exit <-irq_exit
          python-8597  [001] d... 16635.496059: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.496088: rcu_irq_exit <-irq_exit
          python-8597  [001] d... 16635.496102: __do_softirq <-irq_exit
          python-8597  [001] d.s. 16635.496108: rcu_irq_exit <-irq_exit
          python-8597  [001] dN.. 16635.496131: rcu_irq_exit <-irq_exit
     ksoftirqd/1-14    [001] d... 16635.496132: __do_softirq <-
run_ksoftirqd
     ksoftirqd/1-14    [001] d.s1 16635.496145: rcu_irq_exit <-irq_exit
          python-8597  [001] d... 16635.496171: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.496191: rcu_irq_exit <-irq_exit
          python-8597  [001] d... 16635.496204: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.496218: rcu_irq_exit <-irq_exit
          python-8597  [001] d... 16635.496231: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.496250: rcu_irq_exit <-irq_exit
          python-8597  [001] d... 16635.496263: __do_softirq <-irq_exit
          python-8597  [001] d... 16635.496283: rcu_irq_exit <-irq_exit

Ksoftirqd here is very rarely scheduled, the python process here is
receiver, and looks CPU-starving:

%Cpu1  :  0.6 us,  9.5 sy,  0.0 ni,  0.0 id,  0.0 wa, 35.3 hi, 54.6
si,  0.0 st
[..]
  PID USER      PR  NI  VIRT  RES  SHR S  %CPU
%MEM    TIME+  COMMAND           
 8597 root      20   0  7664 5736 3924 R    10  0.0   4:00.69 python 

That's what I tried to picture there with diagrams.
(the source of __do_softirq() also show how ksoftirq got scheduled)

-- 
Thanks,
             Dmitry