From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751661AbdC1LuU (ORCPT ); Tue, 28 Mar 2017 07:50:20 -0400 Received: from mx1.redhat.com ([209.132.183.28]:61494 "EHLO mx1.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751430AbdC1LuT (ORCPT ); Tue, 28 Mar 2017 07:50:19 -0400 DMARC-Filter: OpenDMARC Filter v1.3.2 mx1.redhat.com C9C267F40B Authentication-Results: ext-mx01.extmail.prod.ext.phx2.redhat.com; dmarc=none (p=none dis=none) header.from=redhat.com Authentication-Results: ext-mx01.extmail.prod.ext.phx2.redhat.com; spf=pass smtp.mailfrom=brouer@redhat.com DKIM-Filter: OpenDKIM Filter v2.11.0 mx1.redhat.com C9C267F40B Date: Tue, 28 Mar 2017 13:49:49 +0200 From: Jesper Dangaard Brouer To: Wanpeng Li Cc: Frederic Weisbecker , "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: <20170328134949.540e385f@redhat.com> In-Reply-To: References: <20170328101403.34a82fbf@redhat.com> MIME-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit X-Greylist: Sender IP whitelisted, not delayed by milter-greylist-4.5.16 (mx1.redhat.com [10.5.110.25]); Tue, 28 Mar 2017 11:49:59 +0000 (UTC) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Tue, 28 Mar 2017 18:34:52 +0800 Wanpeng Li wrote: > 2017-03-28 16:14 GMT+08:00 Jesper Dangaard Brouer : > > > > (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). > > > > [1] udp_sink > > https://github.com/netoptimizer/network-testing/blob/master/src/udp_sink.c > > > > The expected results (after commit 4cd13c21b207 ("softirq: Let > > ksoftirqd do its job")) is that the scheduler split the CPU time 50/50 > > between udp_sink and ksoftirqd. > > > > 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. > > > > $ grep CONFIG_IRQ_TIME_ACCOUNTING .config > > CONFIG_IRQ_TIME_ACCOUNTING=y > > > > Full .config uploaded here[2]: > > [2] http://people.netfilter.org/hawk/kconfig/config02-bisect-softirq-a499a5a14dbd > > void irqtime_account_irq(struct task_struct *curr) > { > struct irqtime *irqtime = this_cpu_ptr(&cpu_irqtime); > u64 *cpustat = kcpustat_this_cpu->cpustat; > s64 delta; > int cpu; > > if (!sched_clock_irqtime) > return; > > cpu = smp_processor_id(); > delta = sched_clock_cpu(cpu) - irqtime->irq_start_time; > > sched_clock_cpu(cpu) should be converted from cputime to ns. However, > cputime_to_nsecs() API is removed by > https://lkml.org/lkml/2017/1/22/230 for generic usage, so could you > try the below patch just for testing? Sure... it didn't solve the problem :-( > diff --git a/include/linux/sched/cputime.h b/include/linux/sched/cputime.h > index 4c5b973..166efba 100644 > --- a/include/linux/sched/cputime.h > +++ b/include/linux/sched/cputime.h > @@ -7,14 +7,14 @@ > * cputime accounting APIs: > */ > > -#ifdef CONFIG_VIRT_CPU_ACCOUNTING_NATIVE > -#include > +#define cputime_div(__ct, divisor) div_u64((__force u64)__ct, divisor) > +#define cputime_to_usecs(__ct) \ > + cputime_div(__ct, NSEC_PER_USEC) > > #ifndef cputime_to_nsecs > # define cputime_to_nsecs(__ct) \ > (cputime_to_usecs(__ct) * NSEC_PER_USEC) > #endif > -#endif /* CONFIG_VIRT_CPU_ACCOUNTING_NATIVE */ > > #ifdef CONFIG_VIRT_CPU_ACCOUNTING_GEN > extern void task_cputime(struct task_struct *t, > diff --git a/kernel/sched/cputime.c b/kernel/sched/cputime.c > index f3778e2b..68064d1 100644 > --- a/kernel/sched/cputime.c > +++ b/kernel/sched/cputime.c > @@ -49,7 +49,7 @@ void irqtime_account_irq(struct task_struct *curr) > return; > > cpu = smp_processor_id(); > - delta = sched_clock_cpu(cpu) - irqtime->irq_start_time; > + delta = cputime_to_nsecs(sched_clock_cpu(cpu)) - irqtime->irq_start_time; > irqtime->irq_start_time += delta; > > u64_stats_update_begin(&irqtime->sync); -- Best regards, Jesper Dangaard Brouer MSc.CS, Principal Kernel Engineer at Red Hat LinkedIn: http://www.linkedin.com/in/brouer From mboxrd@z Thu Jan 1 00:00:00 1970 From: Jesper Dangaard Brouer Subject: Re: Bisected softirq accounting issue in v4.11-rc1~170^2~28 Date: Tue, 28 Mar 2017 13:49:49 +0200 Message-ID: <20170328134949.540e385f@redhat.com> References: <20170328101403.34a82fbf@redhat.com> Mime-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit Cc: Frederic Weisbecker , "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 To: Wanpeng Li Return-path: In-Reply-To: Sender: owner-linux-mm@kvack.org List-Id: netdev.vger.kernel.org On Tue, 28 Mar 2017 18:34:52 +0800 Wanpeng Li wrote: > 2017-03-28 16:14 GMT+08:00 Jesper Dangaard Brouer : > > > > (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). > > > > [1] udp_sink > > https://github.com/netoptimizer/network-testing/blob/master/src/udp_sink.c > > > > The expected results (after commit 4cd13c21b207 ("softirq: Let > > ksoftirqd do its job")) is that the scheduler split the CPU time 50/50 > > between udp_sink and ksoftirqd. > > > > 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. > > > > $ grep CONFIG_IRQ_TIME_ACCOUNTING .config > > CONFIG_IRQ_TIME_ACCOUNTING=y > > > > Full .config uploaded here[2]: > > [2] http://people.netfilter.org/hawk/kconfig/config02-bisect-softirq-a499a5a14dbd > > void irqtime_account_irq(struct task_struct *curr) > { > struct irqtime *irqtime = this_cpu_ptr(&cpu_irqtime); > u64 *cpustat = kcpustat_this_cpu->cpustat; > s64 delta; > int cpu; > > if (!sched_clock_irqtime) > return; > > cpu = smp_processor_id(); > delta = sched_clock_cpu(cpu) - irqtime->irq_start_time; > > sched_clock_cpu(cpu) should be converted from cputime to ns. However, > cputime_to_nsecs() API is removed by > https://lkml.org/lkml/2017/1/22/230 for generic usage, so could you > try the below patch just for testing? Sure... it didn't solve the problem :-( > diff --git a/include/linux/sched/cputime.h b/include/linux/sched/cputime.h > index 4c5b973..166efba 100644 > --- a/include/linux/sched/cputime.h > +++ b/include/linux/sched/cputime.h > @@ -7,14 +7,14 @@ > * cputime accounting APIs: > */ > > -#ifdef CONFIG_VIRT_CPU_ACCOUNTING_NATIVE > -#include > +#define cputime_div(__ct, divisor) div_u64((__force u64)__ct, divisor) > +#define cputime_to_usecs(__ct) \ > + cputime_div(__ct, NSEC_PER_USEC) > > #ifndef cputime_to_nsecs > # define cputime_to_nsecs(__ct) \ > (cputime_to_usecs(__ct) * NSEC_PER_USEC) > #endif > -#endif /* CONFIG_VIRT_CPU_ACCOUNTING_NATIVE */ > > #ifdef CONFIG_VIRT_CPU_ACCOUNTING_GEN > extern void task_cputime(struct task_struct *t, > diff --git a/kernel/sched/cputime.c b/kernel/sched/cputime.c > index f3778e2b..68064d1 100644 > --- a/kernel/sched/cputime.c > +++ b/kernel/sched/cputime.c > @@ -49,7 +49,7 @@ void irqtime_account_irq(struct task_struct *curr) > return; > > cpu = smp_processor_id(); > - delta = sched_clock_cpu(cpu) - irqtime->irq_start_time; > + delta = cputime_to_nsecs(sched_clock_cpu(cpu)) - irqtime->irq_start_time; > irqtime->irq_start_time += delta; > > u64_stats_update_begin(&irqtime->sync); -- Best regards, Jesper Dangaard Brouer MSc.CS, Principal Kernel Engineer at Red Hat LinkedIn: http://www.linkedin.com/in/brouer -- To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to majordomo@kvack.org. For more info on Linux MM, see: http://www.linux-mm.org/ . Don't email: email@kvack.org