Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753526AbeAJVUm (ORCPT + 1 other); Wed, 10 Jan 2018 16:20:42 -0500 Received: from mail-wr0-f172.google.com ([209.85.128.172]:35415 "EHLO mail-wr0-f172.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753288AbeAJVUe (ORCPT ); Wed, 10 Jan 2018 16:20:34 -0500 X-Google-Smtp-Source: ACJfBosEKKilNWg/VZ1G8cTrn4HtWmrXRFNrhCm7KZHGLJ9Hu0lpvpWX7HBjbdiLAEISGUzeEH7rVg== Message-ID: <1515619231.3350.36.camel@arista.com> Subject: Re: [RFC 1/2] softirq: Defer net rx/tx processing to ksoftirqd context From: Dmitry Safonov To: Frederic Weisbecker Cc: linux-kernel@vger.kernel.org, 0x7f454c46@gmail.com, Andrew Morton , David Miller , Eric Dumazet , Hannes Frederic Sowa , Ingo Molnar , "Levin, Alexander (Sasha Levin)" , Linus Torvalds , Paolo Abeni , "Paul E. McKenney" , Peter Zijlstra , Radu Rendec , Rik van Riel , Stanislaw Gruszka , Thomas Gleixner , Wanpeng Li Date: Wed, 10 Jan 2018 21:20:31 +0000 In-Reply-To: References: <20180109133623.10711-1-dima@arista.com> <20180109133623.10711-2-dima@arista.com> Content-Type: text/plain; charset="UTF-8" X-Mailer: Evolution 3.24.6 (3.24.6-1.fc26) Mime-Version: 1.0 Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Return-Path: On Tue, 2018-01-09 at 17:03 +0100, Frederic Weisbecker wrote: > 2018-01-09 14:36 UTC+01:00, Dmitry Safonov : > > Warning: Not merge-ready > > > > I. Current workflow of ksoftirqd. > > Softirqs are processed in the context of ksoftirqd iff they are > > being raised very frequently. How it works: > > do_softirq() and invoke_softirq() deffer pending softirq iff > > ksoftirqd is in runqueue. Ksoftirqd is scheduled mostly in the > > end of processed softirqs if 2ms were not enough to process all > > pending softirqs. > > > > Here is pseudo-picture of the workflow (for simplicity on UMP): > > ------------- ------------------ ------------------ > > | ksoftirqd | | User's process | | Softirqs | > > ------------- ------------------ ------------------ > > Not scheduled Running > > | > > o------------------------o > > | > > __do_softirq() > > | > > 2ms & softirq > > pending? > > Schedule ksoftirqd > > | > > Scheduled o------------------------o > > | > > o--------------------o > > | > > Running Scheduled > > | > > o--------------------o > > | > > Not scheduled Running > > > > Timegraph for the workflow, > > dash (-) means ksoftirqd not scheduled; > > equal(=) ksoftirqd is scheduled, a softirq may still be > > pending > > > > Pending softirqs > > | | | | | | | | | > > v v v v | | | | v > > Processing o-----o | | | | o--o > > softirqs | | | | | | | | > > | | | | | | | | > > | | | | | | | | > > Userspace o-o o=========o | | | | o----o o---------o > > <-2ms-> | | | | | | > > | v v v v | > > Ksoftirqd o----------o > > > > II. Corner-conditions. > > During testing of commit [1] on some non-mainstream driver, > > I've found that due to platform specifics, the IRQ is being > > raised too late (after softirq has been processed). > > I'm a bit confused about that part. I would expect the softirq to be > raised by the IRQ. The rx-softirq is raised by napi_schedule(), which is called on receiving an interrupt from device, yes. > So I guess in this scenario the softirq is raised by something else > and you expect the upcoming IRQ to handle the softirq, right? (sorry > I'm not used to networking code). So, the softirq is served by after upcomming IRQ. But in the end of the softirq there is no yet-pending softirq. And just after irq_exit(), there emerges another pending softirq. ITOW, here is what I see on the trace: python-8597 [001] d... 16635.495480: __do_softirq <-irq_exit python-8597 [001] d... 16635.495498: rcu_irq_exit <-irq_exit python-8597 [001] d... 16635.495503: __do_softirq <-irq_exit python-8597 [001] d... 16635.495533: rcu_irq_exit <-irq_exit python-8597 [001] d... 16635.495542: __do_softirq <-irq_exit python-8597 [001] d... 16635.495567: rcu_irq_exit <-irq_exit python-8597 [001] d... 16635.495576: __do_softirq <-irq_exit python-8597 [001] d... 16635.495601: rcu_irq_exit <-irq_exit python-8597 [001] d... 16635.495615: __do_softirq <-irq_exit python-8597 [001] d... 16635.495627: rcu_irq_exit <-irq_exit python-8597 [001] d... 16635.495637: __do_softirq <-irq_exit python-8597 [001] d... 16635.495668: rcu_irq_exit <-irq_exit python-8597 [001] d... 16635.495684: __do_softirq <-irq_exit python-8597 [001] d... 16635.495703: rcu_irq_exit <-irq_exit python-8597 [001] d... 16635.495710: __do_softirq <-irq_exit python-8597 [001] d... 16635.495723: rcu_irq_exit <-irq_exit python-8597 [001] d... 16635.495736: __do_softirq <-irq_exit python-8597 [001] d... 16635.495755: rcu_irq_exit <-irq_exit python-8597 [001] d... 16635.495769: __do_softirq <-irq_exit python-8597 [001] d... 16635.495788: rcu_irq_exit <-irq_exit python-8597 [001] d... 16635.495804: __do_softirq <-irq_exit python-8597 [001] d... 16635.495822: rcu_irq_exit <-irq_exit python-8597 [001] d... 16635.495834: __do_softirq <-irq_exit python-8597 [001] d... 16635.495857: rcu_irq_exit <-irq_exit python-8597 [001] d... 16635.495868: __do_softirq <-irq_exit python-8597 [001] d... 16635.495891: rcu_irq_exit <-irq_exit python-8597 [001] d.s1 16635.495907: rcu_irq_exit <-irq_exit python-8597 [001] d..1 16635.495908: __do_softirq <- do_softirq_own_stack python-8597 [001] d... 16635.495939: __do_softirq <-irq_exit python-8597 [001] d... 16635.495959: rcu_irq_exit <-irq_exit python-8597 [001] d... 16635.495973: __do_softirq <-irq_exit python-8597 [001] d... 16635.495988: rcu_irq_exit <-irq_exit python-8597 [001] d... 16635.496002: __do_softirq <-irq_exit python-8597 [001] d... 16635.496014: rcu_irq_exit <-irq_exit python-8597 [001] d... 16635.496027: __do_softirq <-irq_exit python-8597 [001] d... 16635.496044: rcu_irq_exit <-irq_exit python-8597 [001] d... 16635.496059: __do_softirq <-irq_exit python-8597 [001] d... 16635.496088: rcu_irq_exit <-irq_exit python-8597 [001] d... 16635.496102: __do_softirq <-irq_exit python-8597 [001] d.s. 16635.496108: rcu_irq_exit <-irq_exit python-8597 [001] dN.. 16635.496131: rcu_irq_exit <-irq_exit ksoftirqd/1-14 [001] d... 16635.496132: __do_softirq <- run_ksoftirqd ksoftirqd/1-14 [001] d.s1 16635.496145: rcu_irq_exit <-irq_exit python-8597 [001] d... 16635.496171: __do_softirq <-irq_exit python-8597 [001] d... 16635.496191: rcu_irq_exit <-irq_exit python-8597 [001] d... 16635.496204: __do_softirq <-irq_exit python-8597 [001] d... 16635.496218: rcu_irq_exit <-irq_exit python-8597 [001] d... 16635.496231: __do_softirq <-irq_exit python-8597 [001] d... 16635.496250: rcu_irq_exit <-irq_exit python-8597 [001] d... 16635.496263: __do_softirq <-irq_exit python-8597 [001] d... 16635.496283: rcu_irq_exit <-irq_exit Ksoftirqd here is very rarely scheduled, the python process here is receiver, and looks CPU-starving: %Cpu1 : 0.6 us, 9.5 sy, 0.0 ni, 0.0 id, 0.0 wa, 35.3 hi, 54.6 si, 0.0 st [..] PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 8597 root 20 0 7664 5736 3924 R 10 0.0 4:00.69 python That's what I tried to picture there with diagrams. (the source of __do_softirq() also show how ksoftirq got scheduled) -- Thanks, Dmitry