On Tue, 28 Mar 2017 23:11:22 +0200
Frederic Weisbecker <fweis...@gmail.com> wrote:
> On Tue, Mar 28, 2017 at 05:23:03PM +0200, Jesper Dangaard Brouer wrote:
> > On Tue, 28 Mar 2017 16:34:36 +0200
> > Frederic Weisbecker <fweis...@gmail.com> wrote:
> >
> > > 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 <fweis...@gmail.com>
> > > > 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 <fweis...@gmail.com>
> > > > Cc: Benjamin Herrenschmidt <b...@kernel.crashing.org>
> > > > Cc: Fenghua Yu <fenghua...@intel.com>
> > > > Cc: Heiko Carstens <heiko.carst...@de.ibm.com>
> > > > Cc: Linus Torvalds <torva...@linux-foundation.org>
> > > > Cc: Martin Schwidefsky <schwidef...@de.ibm.com>
> > > > Cc: Michael Ellerman <m...@ellerman.id.au>
> > > > Cc: Paul Mackerras <pau...@samba.org>
> > > > Cc: Peter Zijlstra <pet...@infradead.org>
> > > > Cc: Rik van Riel <r...@redhat.com>
> > > > Cc: Stanislaw Gruszka <sgrus...@redhat.com>
> > > > Cc: Thomas Gleixner <t...@linutronix.de>
> > > > Cc: Tony Luck <tony.l...@intel.com>
> > > > Cc: Wanpeng Li <wanpeng...@hotmail.com>
> > > > Link:
> > > > http://lkml.kernel.org/r/1485832191-26889-17-git-send-email-fweis...@gmail.com
> > > > Signed-off-by: Ingo Molnar <mi...@kernel.org>
> > > >
> > > > 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?
> >
> > No, you misunderstood. I run pktgen on another physical machine, which
> > is sending UDP packets towards my Device-Under-Test (DUT) target. The
> > DUT-target is receiving packets and I observe which CPU the NIC is
> > delivering these packets to.
>
> Ah ok, so I tried to run pktgen on another machine and I get that strange
> write error:
>
> # ./pktgen_sample03_burst_single_flow.sh -d 192.168.1.3 -i wlan0
> ./functions.sh: ligne 76 : echo: erreur d'�criture : Erreur inconnue 524
> ERROR: Write error(1) occurred cmd: "clone_skb 100000 >
> /proc/net/pktgen/wlan0@0"
>
> Any idea?
Yes, this interface does not support pktgen "clone_skb". You can
supply cmdline argument "-c 0" to fix this. But I suspect that this
interface also does not support "burst", thus you also need "-b 0".
See all cmdline args via: ./pktgen_sample03_burst_single_flow.sh -h
Why are you using a wifi interface for this kind of overload testing?
(the basic test here is making sure softirq is busy 100%, and at slow
wifi speeds this might not be possible to force ksoftirqd into this
scheduler state)
> >
> > E.g determine RX-CPU via mpstat command:
> > mpstat -P ALL -u -I SCPU -I SUM 2
> >
> > I then start udp_sink, pinned to the RX-CPU, like:
> > sudo taskset -c 2 ./udp_sink --port 9 --count $((10**6)) --recvmsg
> > --repeat 1000
>
> Ah thanks for these hints!
>
> > > > 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!
> >
> > Good to hear you can reproduce it! :-)
>
> Well, since I was generating the packets locally, maybe it didn't trigger
> the expected interrupts...
Well, you definitely didn't create the test case I was using. I cannot
remember if the pktgen kthreads runs in softirq context, but I suspect
it does. If so, you can recreate the main problem, which is a softirq
thread using 100% CPU time, which cause no other processes getting
sched time on that CPU.
--
Best regards,
Jesper Dangaard Brouer
MSc.CS, Principal Kernel Engineer at Red Hat
LinkedIn: http://www.linkedin.com/in/brouer
