Re: Bisected softirq accounting issue in v4.11-rc1~170^2~28

[Frederic Weisbecker]

On Tue, Mar 28, 2017 at 10:14:03AM +0200, Jesper Dangaard Brouer wrote:
> 
> (While evaluating some changes to the page allocator) I ran into an
> issue with ksoftirqd getting too much CPU sched time.
> 
> I bisected the problem to
>  a499a5a14dbd ("sched/cputime: Increment kcpustat directly on irqtime account")
> 
>  a499a5a14dbd1d0315a96fc62a8798059325e9e6 is the first bad commit
>  commit a499a5a14dbd1d0315a96fc62a8798059325e9e6
>  Author: Frederic Weisbecker <fweisbec@xxxxxxxxx>
>  Date:   Tue Jan 31 04:09:32 2017 +0100
> 
>     sched/cputime: Increment kcpustat directly on irqtime account
>     
>     The irqtime is accounted is nsecs and stored in
>     cpu_irq_time.hardirq_time and cpu_irq_time.softirq_time. Once the
>     accumulated amount reaches a new jiffy, this one gets accounted to the
>     kcpustat.
>     
>     This was necessary when kcpustat was stored in cputime_t, which could at
>     worst have jiffies granularity. But now kcpustat is stored in nsecs
>     so this whole discretization game with temporary irqtime storage has
>     become unnecessary.
>     
>     We can now directly account the irqtime to the kcpustat.
>     
>     Signed-off-by: Frederic Weisbecker <fweisbec@xxxxxxxxx>
>     Cc: Benjamin Herrenschmidt <benh@xxxxxxxxxxxxxxxxxxx>
>     Cc: Fenghua Yu <fenghua.yu@xxxxxxxxx>
>     Cc: Heiko Carstens <heiko.carstens@xxxxxxxxxx>
>     Cc: Linus Torvalds <torvalds@xxxxxxxxxxxxxxxxxxxx>
>     Cc: Martin Schwidefsky <schwidefsky@xxxxxxxxxx>
>     Cc: Michael Ellerman <mpe@xxxxxxxxxxxxxx>
>     Cc: Paul Mackerras <paulus@xxxxxxxxx>
>     Cc: Peter Zijlstra <peterz@xxxxxxxxxxxxx>
>     Cc: Rik van Riel <riel@xxxxxxxxxx>
>     Cc: Stanislaw Gruszka <sgruszka@xxxxxxxxxx>
>     Cc: Thomas Gleixner <tglx@xxxxxxxxxxxxx>
>     Cc: Tony Luck <tony.luck@xxxxxxxxx>
>     Cc: Wanpeng Li <wanpeng.li@xxxxxxxxxxx>
>     Link: http://lkml.kernel.org/r/1485832191-26889-17-git-send-email-fweisbec@xxxxxxxxx
>     Signed-off-by: Ingo Molnar <mingo@xxxxxxxxxx>
> 
> The reproducer is running a userspace udp_sink[1] program, and taskset
> pinning the process to the same CPU as softirq RX is running on, and
> starting a UDP flood with pktgen (tool part of kernel tree:
> samples/pktgen/pktgen_sample03_burst_single_flow.sh).

So that means I need to run udp_sink on the same CPU than pktgen?

> 
> [1] udp_sink
>  https://github.com/netoptimizer/network-testing/blob/master/src/udp_sink.c
> 
> The expected results (after commit 4cd13c21b207 ("softirq: Let
> ksoftirqd do its job")) is that the scheduler split the CPU time 50/50
> between udp_sink and ksoftirqd.

I guess you mean that this is what happened before this commit?

> 
> After this commit, the udp_sink program does not get any sched CPU
> time, and no packets are delivered to userspace.  (All packets are
> dropped by softirq due to a full socket queue, nstat UdpRcvbufErrors).
> 
> A related symptom is that ksoftirqd no longer get accounted in top.

That's indeed what I observe. udp_sink has almost no CPU time, neither has
ksoftirqd but kpktgend_0 has everything.

Finally a bug I can reproduce!