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

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <20170328211121.GA8615@lerouge>
Date:   Tue, 28 Mar 2017 23:11:22 +0200
From:   Frederic Weisbecker <fweisbec@...il.com>
To:     Jesper Dangaard Brouer <brouer@...hat.com>
Cc:     linux-kernel@...r.kernel.org,
        "netdev@...r.kernel.org" <netdev@...r.kernel.org>,
        linux-mm <linux-mm@...ck.org>,
        Mel Gorman <mgorman@...hsingularity.net>,
        Tariq Toukan <tariqt@...lanox.com>,
        Tariq Toukan <ttoukan.linux@...il.com>,
        Peter Zijlstra <peterz@...radead.org>,
        Rik van Riel <riel@...hat.com>,
        Thomas Gleixner <tglx@...utronix.de>,
        Ingo Molnar <mingo@...nel.org>
Subject: Re: Bisected softirq accounting issue in v4.11-rc1~170^2~28

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 <fweisbec@...il.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 <fweisbec@...il.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 <fweisbec@...il.com>
> > >     Cc: Benjamin Herrenschmidt <benh@...nel.crashing.org>
> > >     Cc: Fenghua Yu <fenghua.yu@...el.com>
> > >     Cc: Heiko Carstens <heiko.carstens@...ibm.com>
> > >     Cc: Linus Torvalds <torvalds@...ux-foundation.org>
> > >     Cc: Martin Schwidefsky <schwidefsky@...ibm.com>
> > >     Cc: Michael Ellerman <mpe@...erman.id.au>
> > >     Cc: Paul Mackerras <paulus@...ba.org>
> > >     Cc: Peter Zijlstra <peterz@...radead.org>
> > >     Cc: Rik van Riel <riel@...hat.com>
> > >     Cc: Stanislaw Gruszka <sgruszka@...hat.com>
> > >     Cc: Thomas Gleixner <tglx@...utronix.de>
> > >     Cc: Tony Luck <tony.luck@...el.com>
> > >     Cc: Wanpeng Li <wanpeng.li@...mail.com>
> > >     Link: http://lkml.kernel.org/r/1485832191-26889-17-git-send-email-fweisbec@gmail.com
> > >     Signed-off-by: Ingo Molnar <mingo@...nel.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?

> 
> 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...