Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1755627AbdC2Jaq convert rfc822-to-8bit (ORCPT ); Wed, 29 Mar 2017 05:30:46 -0400 Received: from mx1.redhat.com ([209.132.183.28]:37334 "EHLO mx1.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754816AbdC2Jal (ORCPT ); Wed, 29 Mar 2017 05:30:41 -0400 DMARC-Filter: OpenDMARC Filter v1.3.2 mx1.redhat.com 9495880474 Authentication-Results: ext-mx04.extmail.prod.ext.phx2.redhat.com; dmarc=none (p=none dis=none) header.from=redhat.com Authentication-Results: ext-mx04.extmail.prod.ext.phx2.redhat.com; spf=pass smtp.mailfrom=brouer@redhat.com DKIM-Filter: OpenDKIM Filter v2.11.0 mx1.redhat.com 9495880474 Date: Wed, 29 Mar 2017 11:30:30 +0200 From: Jesper Dangaard Brouer To: Frederic Weisbecker 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 , brouer@redhat.com Subject: Re: Bisected softirq accounting issue in v4.11-rc1~170^2~28 Message-ID: <20170329113030.671ff443@redhat.com> In-Reply-To: <20170328211121.GA8615@lerouge> References: <20170328101403.34a82fbf@redhat.com> <20170328143431.GB4216@lerouge> <20170328172303.78a3c6d4@redhat.com> <20170328211121.GA8615@lerouge> MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8BIT X-Greylist: Sender IP whitelisted, not delayed by milter-greylist-4.5.16 (mx1.redhat.com [10.5.110.28]); Wed, 29 Mar 2017 09:30:40 +0000 (UTC) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 5401 Lines: 121 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) > > > > 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