Bisected softirq accounting issue in v4.11-rc1~170^2~28
Subsystems (4)
(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 <[email protected]>
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.
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
Signature · 10 lines
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 [email protected]. For more info on Linux MM, see: http://www.linux-mm.org/ . Don't email: <a href=mailto:"[email protected]"> [email protected] </a>
2017-03-28 16:14 GMT+08:00 Jesper Dangaard Brouer <[email protected]>:
Quoted 59 lines
(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")
a499a5a14dbd1d0315a96fc62a8798059325e9e6is the first bad commit commita499a5a14dbd1d0315a96fc62a8798059325e9e6
Author: Frederic Weisbecker <[email protected]>
Date: Tue Jan 31 04:09:32 2017 +0100sched/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 <[email protected]>Cc Benjamin Herrenschmidt <[email protected]>Cc Fenghua Yu <[email protected]>Cc Heiko Carstens <[email protected]>Cc Linus Torvalds <[email protected]>Cc Martin Schwidefsky <[email protected]>Cc Michael Ellerman <[email protected]>Cc Paul Mackerras <[email protected]>Cc Peter Zijlstra <[email protected]>Cc Rik van Riel <[email protected]>Cc Stanislaw Gruszka <[email protected]>Cc Thomas Gleixner <[email protected]>Cc Tony Luck <[email protected]>Cc Wanpeng Li <[email protected]>Signed-off-by Ingo Molnar <[email protected]>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.cThe expected results (after commit
4cd13c21b207("softirq: Let ksoftirqd do its job")) is that the scheduler split the CPU time 50/50 betweenudp_sinkand ksoftirqd.After this commit, the
udp_sinkprogram 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).
Quoted 7 lines
A related symptom is that ksoftirqd no longer get accounted in top.
$ grep CONFIG_IRQ_TIME_ACCOUNTING .config CONFIG_IRQ_TIME_ACCOUNTING=yFull .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?
include/linux/sched/cputime.h +3 -3
@@ -7,14 +7,14 @@* cputime accounting APIs: */ -#ifdef CONFIG_VIRT_CPU_ACCOUNTING_NATIVE -#include <asm/cputime.h> +#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,
kernel/sched/cputime.c +1 -1
@@ -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);
Regards,
Wanpeng Li
--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>
Quoted 81 lines · On Tue, 28 Mar 2017 18:34:52 +0800 Wanpeng Li <[email protected]> wrote:
2017-03-28 16:14 GMT+08:00 Jesper Dangaard Brouer <[email protected]>:
Quoted 59 lines
(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")
a499a5a14dbd1d0315a96fc62a8798059325e9e6is the first bad commit commita499a5a14dbd1d0315a96fc62a8798059325e9e6
Author: Frederic Weisbecker <[email protected]>
Date: Tue Jan 31 04:09:32 2017 +0100sched/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 <[email protected]>Cc Benjamin Herrenschmidt <[email protected]>Cc Fenghua Yu <[email protected]>Cc Heiko Carstens <[email protected]>Cc Linus Torvalds <[email protected]>Cc Martin Schwidefsky <[email protected]>Cc Michael Ellerman <[email protected]>Cc Paul Mackerras <[email protected]>Cc Peter Zijlstra <[email protected]>Cc Rik van Riel <[email protected]>Cc Stanislaw Gruszka <[email protected]>Cc Thomas Gleixner <[email protected]>Cc Tony Luck <[email protected]>Cc Wanpeng Li <[email protected]>Signed-off-by Ingo Molnar <[email protected]>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.cThe expected results (after commit
4cd13c21b207("softirq: Let ksoftirqd do its job")) is that the scheduler split the CPU time 50/50 betweenudp_sinkand ksoftirqd.After this commit, the
udp_sinkprogram 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).Quoted 7 lines
A related symptom is that ksoftirqd no longer get accounted in top.
$ grep CONFIG_IRQ_TIME_ACCOUNTING .config CONFIG_IRQ_TIME_ACCOUNTING=yFull .config uploaded here[2]:
[2] http://people.netfilter.org/hawk/kconfig/config02-bisect-softirq-a499a5a14dbdvoid
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;
Quoted 4 lines
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 :-(
Quoted 35 lines
include/linux/sched/cputime.h +3
-3@@ -7,14 +7,14 @@* cputime accounting APIs: */ -#ifdef CONFIG_VIRT_CPU_ACCOUNTING_NATIVE -#include <asm/cputime.h> +#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,kernel/sched/cputime.c +1
-1@@ -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);
Signature · 10 lines
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 [email protected]. For more info on Linux MM, see: http://www.linux-mm.org/ . Don't email: <a href=mailto:"[email protected]"> [email protected] </a>
Peter Zijlstra
maintainerQuoted 2 lines · Wanpeng Li
sched_clock_cpu(cpu)should be converted from cputime to ns.
Uhm, no. sched_clock_cpu() returns u64 in ns.
--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>
Quoted 5 lines · Peter Zijlstra
Quoted 2 lines · Wanpeng Li
sched_clock_cpu(cpu)should be converted from cputime to ns.Uhm, no.
sched_clock_cpu()returns u64 in ns.
Yes, and most of the cputime_t have been converted to u64 so there should be no such conversion issue between u64 and cputime_t anymore.
Perhaps my commit has another side effect on softirq time accounting, I'll see if I can reproduce.
--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>
Quoted 5 lines · On Tue, 28 Mar 2017 15:06:04 +0200 Frederic Weisbecker <[email protected]>…
Quoted 4 lines · Peter Zijlstra
Quoted 2 lines · Wanpeng Li
sched_clock_cpu(cpu)should be converted from cputime to ns.
Quoted 7 lines
Quoted 1 line
Uhm, no.
sched_clock_cpu()returns u64 in ns.Yes, and most of the
cputime_thave been converted to u64 so there should be no such conversion issue between u64 andcputime_tanymore.Perhaps my commit has another side effect on softirq time accounting, I'll see if I can reproduce.
(Disclaimer without knowing anything about the scheduler code) my theory is that irqtime_account_irq() does not get invoked often enough, as in my pktgen "overload" use-case keeps softirq always running. And your change moved updating cpustat[CPUTIME_SOFTIRQ] here. Before it got updated by account_other_time() which gets invoked from irqtime_account_process_tick().
Signature · 10 lines
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 [email protected]. For more info on Linux MM, see: http://www.linux-mm.org/ . Don't email: <a href=mailto:"[email protected]"> [email protected] </a>
Quoted 43 lines · 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")
a499a5a14dbd1d0315a96fc62a8798059325e9e6is the first bad commit commita499a5a14dbd1d0315a96fc62a8798059325e9e6
Author: Frederic Weisbecker <[email protected]>
Date: Tue Jan 31 04:09:32 2017 +0100sched/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 <[email protected]>Cc Benjamin Herrenschmidt <[email protected]>Cc Fenghua Yu <[email protected]>Cc Heiko Carstens <[email protected]>Cc Linus Torvalds <[email protected]>Cc Martin Schwidefsky <[email protected]>Cc Michael Ellerman <[email protected]>Cc Paul Mackerras <[email protected]>Cc Peter Zijlstra <[email protected]>Cc Rik van Riel <[email protected]>Cc Stanislaw Gruszka <[email protected]>Cc Thomas Gleixner <[email protected]>Cc Tony Luck <[email protected]>Cc Wanpeng Li <[email protected]>Signed-off-by Ingo Molnar <[email protected]>
Quoted 4 lines
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?
Quoted 7 lines
[1]
udp_sink
https://github.com/netoptimizer/network-testing/blob/master/src/udp_sink.cThe expected results (after commit
4cd13c21b207("softirq: Let ksoftirqd do its job")) is that the scheduler split the CPU time 50/50 betweenudp_sinkand ksoftirqd.
I guess you mean that this is what happened before this commit?
Quoted 6 lines
After this commit, the
udp_sinkprogram 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!
--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>
Quoted 44 lines · On Tue, 28 Mar 2017 16:34:36 +0200 Frederic Weisbecker <[email protected]>…
Quoted 43 lines · 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")
a499a5a14dbd1d0315a96fc62a8798059325e9e6is the first bad commit commita499a5a14dbd1d0315a96fc62a8798059325e9e6
Author: Frederic Weisbecker <[email protected]>
Date: Tue Jan 31 04:09:32 2017 +0100sched/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 <[email protected]>Cc Benjamin Herrenschmidt <[email protected]>Cc Fenghua Yu <[email protected]>Cc Heiko Carstens <[email protected]>Cc Linus Torvalds <[email protected]>Cc Martin Schwidefsky <[email protected]>Cc Michael Ellerman <[email protected]>Cc Paul Mackerras <[email protected]>Cc Peter Zijlstra <[email protected]>Cc Rik van Riel <[email protected]>Cc Stanislaw Gruszka <[email protected]>Cc Thomas Gleixner <[email protected]>Cc Tony Luck <[email protected]>Cc Wanpeng Li <[email protected]>Signed-off-by Ingo Molnar <[email protected]>
Quoted 6 lines
Quoted 4 lines
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_sinkon 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.
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
Quoted 8 lines
Quoted 6 lines
[1]
udp_sink
https://github.com/netoptimizer/network-testing/blob/master/src/udp_sink.cThe expected results (after commit
4cd13c21b207("softirq: Let ksoftirqd do its job")) is that the scheduler split the CPU time 50/50 betweenudp_sinkand ksoftirqd.I guess you mean that this is what happened before this commit?
Yes. (I just pointed out the kernel had another softirq bug, that I was involved in fixing)
Quoted 6 lines
Quoted 6 lines
After this commit, the
udp_sinkprogram 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).
Quoted 7 lines
Quoted 2 lines
A related symptom is that ksoftirqd no longer get accounted in top.
That's indeed what I observe.
udp_sinkhas almost no CPU time, neither has ksoftirqd butkpktgend_0has everything.Finally a bug I can reproduce!
Good to hear you can reproduce it! :-)
Signature · 10 lines
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 [email protected]. For more info on Linux MM, see: http://www.linux-mm.org/ . Don't email: <a href=mailto:"[email protected]"> [email protected] </a>
Quoted 52 lines · Jesper Dangaard Brouer
Quoted 49 lines · On Tue, 28 Mar 2017 16:34:36 +0200 Frederic Weisbecker <[email protected]>…
Quoted 47 lines · 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")
a499a5a14dbd1d0315a96fc62a8798059325e9e6is the first bad commit commita499a5a14dbd1d0315a96fc62a8798059325e9e6
Author: Frederic Weisbecker <[email protected]>
Date: Tue Jan 31 04:09:32 2017 +0100sched/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 <[email protected]>Cc Benjamin Herrenschmidt <[email protected]>Cc Fenghua Yu <[email protected]>Cc Heiko Carstens <[email protected]>Cc Linus Torvalds <[email protected]>Cc Martin Schwidefsky <[email protected]>Cc Michael Ellerman <[email protected]>Cc Paul Mackerras <[email protected]>Cc Peter Zijlstra <[email protected]>Cc Rik van Riel <[email protected]>Cc Stanislaw Gruszka <[email protected]>Cc Thomas Gleixner <[email protected]>Cc Tony Luck <[email protected]>Cc Wanpeng Li <[email protected]>Signed-off-by Ingo Molnar <[email protected]>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).
Quoted 6 lines
Quoted 1 line
So that means I need to run
udp_sinkon 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?
Quoted 6 lines
E.g determine RX-CPU via mpstat command:
mpstat -P ALL -u -I SCPU -I SUM 2I 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!
Quoted 8 lines
Quoted 8 lines
Quoted 7 lines
After this commit, the
udp_sinkprogram 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.
Quoted 6 lines
Quoted 4 lines
That's indeed what I observe.
udp_sinkhas almost no CPU time, neither has ksoftirqd butkpktgend_0has 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...
--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>
Quoted 60 lines · On Tue, 28 Mar 2017 23:11:22 +0200 Frederic Weisbecker <[email protected]>…
Quoted 52 lines · Jesper Dangaard Brouer
Quoted 49 lines · On Tue, 28 Mar 2017 16:34:36 +0200 Frederic Weisbecker <[email protected]>…
Quoted 47 lines · 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")
a499a5a14dbd1d0315a96fc62a8798059325e9e6is the first bad commit commita499a5a14dbd1d0315a96fc62a8798059325e9e6
Author: Frederic Weisbecker <[email protected]>
Date: Tue Jan 31 04:09:32 2017 +0100sched/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 <[email protected]>Cc Benjamin Herrenschmidt <[email protected]>Cc Fenghua Yu <[email protected]>Cc Heiko Carstens <[email protected]>Cc Linus Torvalds <[email protected]>Cc Martin Schwidefsky <[email protected]>Cc Michael Ellerman <[email protected]>Cc Paul Mackerras <[email protected]>Cc Peter Zijlstra <[email protected]>Cc Rik van Riel <[email protected]>Cc Stanislaw Gruszka <[email protected]>Cc Thomas Gleixner <[email protected]>Cc Tony Luck <[email protected]>Cc Wanpeng Li <[email protected]>Signed-off-by Ingo Molnar <[email protected]>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).Quoted 6 lines
Quoted 1 line
So that means I need to run
udp_sinkon 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.
Quoted 7 lines
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)
Quoted 20 lines
Quoted 6 lines
E.g determine RX-CPU via mpstat command:
mpstat -P ALL -u -I SCPU -I SUM 2I then start
udp_sink, pinned to the RX-CPU, like:
sudo taskset -c 2 ./udp_sink --port 9 --count $((10**6)) --recvmsg --repeat 1000Ah thanks for these hints!
Quoted 11 lines
Quoted 11 lines
Quoted 7 lines
After this commit, the
udp_sinkprogram 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_sinkhas almost no CPU time, neither has ksoftirqd butkpktgend_0has everything.
Quoted 6 lines
Quoted 3 lines
Quoted 1 line
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.
Signature · 10 lines
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 [email protected]. For more info on Linux MM, see: http://www.linux-mm.org/ . Don't email: <a href=mailto:"[email protected]"> [email protected] </a>
Quoted 75 lines · Jesper Dangaard Brouer
Quoted 60 lines · On Tue, 28 Mar 2017 23:11:22 +0200 Frederic Weisbecker <[email protected]>…
Quoted 52 lines · Jesper Dangaard Brouer
Quoted 49 lines · On Tue, 28 Mar 2017 16:34:36 +0200 Frederic Weisbecker <[email protected]>…
Quoted 47 lines · 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")
a499a5a14dbd1d0315a96fc62a8798059325e9e6is the first bad commit commita499a5a14dbd1d0315a96fc62a8798059325e9e6
Author: Frederic Weisbecker <[email protected]>
Date: Tue Jan 31 04:09:32 2017 +0100sched/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 <[email protected]>Cc Benjamin Herrenschmidt <[email protected]>Cc Fenghua Yu <[email protected]>Cc Heiko Carstens <[email protected]>Cc Linus Torvalds <[email protected]>Cc Martin Schwidefsky <[email protected]>Cc Michael Ellerman <[email protected]>Cc Paul Mackerras <[email protected]>Cc Peter Zijlstra <[email protected]>Cc Rik van Riel <[email protected]>Cc Stanislaw Gruszka <[email protected]>Cc Thomas Gleixner <[email protected]>Cc Tony Luck <[email protected]>Cc Wanpeng Li <[email protected]>Signed-off-by Ingo Molnar <[email protected]>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).Quoted 6 lines
Quoted 1 line
So that means I need to run
udp_sinkon 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.
Quoted 7 lines
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".
Quoted 6 lines
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.
Quoted 15 lines
Quoted 15 lines
Quoted 14 lines
Quoted 5 lines
Quoted 5 lines
After this commit, the
udp_sinkprogram 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).Quoted 7 lines
Quoted 2 lines
A related symptom is that ksoftirqd no longer get accounted in top.
That's indeed what I observe.
udp_sinkhas almost no CPU time, neither has ksoftirqd butkpktgend_0has everything.Finally a bug I can reproduce!
Good to hear you can reproduce it! :-)
Quoted 8 lines
Quoted 2 lines
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!
--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>