Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S932748AbdC2NN2 (ORCPT ); Wed, 29 Mar 2017 09:13:28 -0400 Received: from mail-wr0-f193.google.com ([209.85.128.193]:33337 "EHLO mail-wr0-f193.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1755818AbdC2NN0 (ORCPT ); Wed, 29 Mar 2017 09:13:26 -0400 Date: Wed, 29 Mar 2017 15:13:22 +0200 From: Frederic Weisbecker To: Jesper Dangaard Brouer Cc: linux-kernel@vger.kernel.org, "netdev@vger.kernel.org" , linux-mm , Mel Gorman , Tariq Toukan , Tariq Toukan , Peter Zijlstra , Rik van Riel , Thomas Gleixner , Ingo Molnar Subject: Re: Bisected softirq accounting issue in v4.11-rc1~170^2~28 Message-ID: <20170329131321.GC8306@lerouge> References: <20170328101403.34a82fbf@redhat.com> <20170328143431.GB4216@lerouge> <20170328172303.78a3c6d4@redhat.com> <20170328211121.GA8615@lerouge> <20170329113030.671ff443@redhat.com> MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Disposition: inline Content-Transfer-Encoding: 8bit In-Reply-To: <20170329113030.671ff443@redhat.com> User-Agent: Mutt/1.5.24 (2015-08-30) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 5642 Lines: 117 On Wed, Mar 29, 2017 at 11:30:30AM +0200, Jesper Dangaard Brouer wrote: > On Tue, 28 Mar 2017 23:11:22 +0200 > Frederic Weisbecker 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 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 > > > > > 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 > > > > > Cc: Benjamin Herrenschmidt > > > > > Cc: Fenghua Yu > > > > > Cc: Heiko Carstens > > > > > Cc: Linus Torvalds > > > > > Cc: Martin Schwidefsky > > > > > Cc: Michael Ellerman > > > > > Cc: Paul Mackerras > > > > > Cc: Peter Zijlstra > > > > > Cc: Rik van Riel > > > > > Cc: Stanislaw Gruszka > > > > > Cc: Thomas Gleixner > > > > > Cc: Tony Luck > > > > > Cc: Wanpeng Li > > > > > Link: http://lkml.kernel.org/r/1485832191-26889-17-git-send-email-fweisbec@gmail.com > > > > > Signed-off-by: Ingo Molnar > > > > > > > > > > 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) What? I need to raise from the couch and plug an ethernet cable?? ;-) ;-) More seriously you're right, wifi probably won't be enough to trigger the desired storm on the destination interface. I'm going to try with eth0, that should also fix the clone_skb issues. > > > > > 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. Well, I prefer to reproduce the same thing than you to make sure I'm chasing the right problem. Thanks!