sched/isolation: Make NO_HZ_FULL select CPU_ISOLATION
PATCH 1/1 sched/isolation: Make NO_HZ_FULL select CPU_ISOLATION
Commit 5c4991e24c69 ("sched/isolation: Split out new CONFIG_CPU_ISOLATION=y config from CONFIG_NO_HZ_FULL") can result in RCU CPU stall warnings when running rcutorture with CONFIG_NO_HZ_FULL_ALL=y and CONFIG_CPU_ISOLATION=n. These warnings are caused by RCU's grace-period kthreads sleeping for a few jiffies, but never being awakened:
[ 116.353432] rcu_preempt kthread starved for 9974 jiffies! g4294967208 +c4294967207 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x402 ->cpu=0 [ 116.355517] rcu_preempt I 7464 8 2 0x80000000 [ 116.356543] Call Trace: [ 116.357008] __schedule+0x493/0x620 [ 116.357682] schedule+0x24/0x40 [ 116.358291] schedule_timeout+0x330/0x3b0 [ 116.359024] ? preempt_count_sub+0xea/0x140 [ 116.359806] ? collect_expired_timers+0xb0/0xb0 [ 116.360660] rcu_gp_kthread+0x6bf/0xef0
This commit therefore makes NO_HZ_FULL select CPU_ISOLATION, which prevents this behavior and seems like it was the original intention in any case.
kernel/time/Kconfig +1 -0
@@ -95,6 +95,7 @@ config NO_HZ_FULL select RCU_NOCB_CPU select VIRT_CPU_ACCOUNTING_GEN select IRQ_WORK + select CPU_ISOLATION help Adaptively try to shutdown the tick whenever possible, even when the CPU is running tasks. Typically this requires running a single
Frederic Weisbecker
maintainer2017-11-30 21:20 UTC+01:00, Paul E. McKenney <[email protected]>:
Quoted 18 lines
Commit
5c4991e24c69("sched/isolation: Split out newCONFIG_CPU_ISOLATION=yconfig fromCONFIG_NO_HZ_FULL") can result in RCU CPU stall warnings when running rcutorture withCONFIG_NO_HZ_FULL_ALL=yandCONFIG_CPU_ISOLATION=n. These warnings are caused by RCU's grace-period kthreads sleeping for a few jiffies, but never being awakened:[ 116.353432] rcu_preempt kthread starved for 9974 jiffies! g4294967208 +c4294967207 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x402 ->cpu=0 [ 116.355517] rcu_preempt I 7464 8 2 0x80000000 [ 116.356543] Call Trace: [ 116.357008] __schedule+0x493/0x620 [ 116.357682] schedule+0x24/0x40 [ 116.358291] schedule_timeout+0x330/0x3b0 [ 116.359024] ? preempt_count_sub+0xea/0x140 [ 116.359806] ? collect_expired_timers+0xb0/0xb0 [ 116.360660] rcu_gp_kthread+0x6bf/0xef0
Quoted 3 lines
This commit therefore makes
NO_HZ_FULLselectCPU_ISOLATION, which prevents this behavior and seems like it was the original intention in any case.
Although CONFIG_NO_HZ should indeed select CONFIG_CPU_ISOLATION, I'm surprised about this stall. I'm even more surprised that setting CONFIG_CPU_ISOLATION=y is enough to fix the issue because CONFIG_NO_HZ_FULL_ALL shortcuts CONFIG_CPU_ISOLATION entirely (which is not good, but work in progress...).
Did you have any nohz_full= or isolcpus= boot options?
Thanks.
Quoted 23 lines · Frederic Weisbecker
2017-11-30 21:20 UTC+01:00, Paul E. McKenney <[email protected]>:
Quoted 18 lines
Commit
5c4991e24c69("sched/isolation: Split out newCONFIG_CPU_ISOLATION=yconfig fromCONFIG_NO_HZ_FULL") can result in RCU CPU stall warnings when running rcutorture withCONFIG_NO_HZ_FULL_ALL=yandCONFIG_CPU_ISOLATION=n. These warnings are caused by RCU's grace-period kthreads sleeping for a few jiffies, but never being awakened:[ 116.353432] rcu_preempt kthread starved for 9974 jiffies! g4294967208 +c4294967207 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x402 ->cpu=0 [ 116.355517] rcu_preempt I 7464 8 2 0x80000000 [ 116.356543] Call Trace: [ 116.357008] __schedule+0x493/0x620 [ 116.357682] schedule+0x24/0x40 [ 116.358291] schedule_timeout+0x330/0x3b0 [ 116.359024] ? preempt_count_sub+0xea/0x140 [ 116.359806] ? collect_expired_timers+0xb0/0xb0 [ 116.360660] rcu_gp_kthread+0x6bf/0xef0Quoted 3 lines
This commit therefore makes
NO_HZ_FULLselectCPU_ISOLATION, which prevents this behavior and seems like it was the original intention in any case.
Quoted 5 lines
Although
CONFIG_NO_HZshould indeed selectCONFIG_CPU_ISOLATION, I'm surprised about this stall. I'm even more surprised that settingCONFIG_CPU_ISOLATION=yis enough to fix the issue becauseCONFIG_NO_HZ_FULL_ALLshortcutsCONFIG_CPU_ISOLATIONentirely (which is not good, but work in progress...).
Yes, and after applying this patch, I get failures a few commits later, which appears to be due to other changes that break CONFIG_NO_HZ_FULL_ALL=y. So I have another patch staged that removes CONFIG_NO_HZ_FULL_ALL, on the grounds that no one else has complained, so rcutorture is likely to be the only user, and I don't see the point of having a Kconfig option for only one user.
Quoted 1 line
Did you have any nohz_full= or isolcpus= boot options?
Replacing CONFIG_NO_HZ_FULL_ALL=y with nohz_full=1-7 works, that is CONFIG_NO_HZ_FULL=y, CONFIG_NO_HZ_FULL_ALL=n, and nohz_full=1-7 on an eight-CPU test.
But it is relatively easy to test. Running the rcutorture TREE04 scenario on a four-socket x86 gets me RCU CPU stall warnings within a few minutes more than half the time. ;-)
Thanx, Paul
Frederic Weisbecker
maintainer2017-12-02 20:24 UTC+01:00, Paul E. McKenney <[email protected]>:
Quoted 33 lines · Frederic Weisbecker
Quoted 26 lines
2017-11-30 21:20 UTC+01:00, Paul E. McKenney
<[email protected]>:Quoted 20 lines
Commit
5c4991e24c69("sched/isolation: Split out newCONFIG_CPU_ISOLATION=yconfig fromCONFIG_NO_HZ_FULL") can result in RCU
CPU stall warnings when running rcutorture withCONFIG_NO_HZ_FULL_ALL=yandCONFIG_CPU_ISOLATION=n. These warnings are caused by RCU's grace-period kthreads sleeping for a few jiffies, but never being awakened:[ 116.353432] rcu_preempt kthread starved for 9974 jiffies! g4294967208 +c4294967207 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x402 ->cpu=0 [ 116.355517] rcu_preempt I 7464 8 2 0x80000000 [ 116.356543] Call Trace: [ 116.357008] __schedule+0x493/0x620 [ 116.357682] schedule+0x24/0x40 [ 116.358291] schedule_timeout+0x330/0x3b0 [ 116.359024] ? preempt_count_sub+0xea/0x140 [ 116.359806] ? collect_expired_timers+0xb0/0xb0 [ 116.360660] rcu_gp_kthread+0x6bf/0xef0Quoted 3 lines
This commit therefore makes
NO_HZ_FULLselectCPU_ISOLATION, which prevents this behavior and seems like it was the original intention in any case.Quoted 5 lines
Although
CONFIG_NO_HZshould indeed selectCONFIG_CPU_ISOLATION, I'm surprised about this stall. I'm even more surprised that settingCONFIG_CPU_ISOLATION=yis enough to fix the issue becauseCONFIG_NO_HZ_FULL_ALLshortcutsCONFIG_CPU_ISOLATIONentirely (which is not good, but work in progress...).
Quoted 6 lines
Yes, and after applying this patch, I get failures a few commits later, which appears to be due to other changes that break
CONFIG_NO_HZ_FULL_ALL=y. So I have another patch staged that removesCONFIG_NO_HZ_FULL_ALL, on the grounds that no one else has complained, so rcutorture is likely to be the only user, and I don't see the point of having aKconfigoption for only one user.
I would prefer to keep it. It's useful for automated boot testing based on configs such as 0-day or -tip test machines. But I'm likely to migrate it to isolcpus implementation. Maybe something along the lines of CONFIG_CPU_ISOLATION_ALL.
Quoted 10 lines
Quoted 2 lines
Did you have any nohz_full= or isolcpus= boot options?
Replacing
CONFIG_NO_HZ_FULL_ALL=ywith nohz_full=1-7 works, that isCONFIG_NO_HZ_FULL=y,CONFIG_NO_HZ_FULL_ALL=n, and nohz_full=1-7 on an eight-CPU test.But it is relatively easy to test. Running the rcutorture TREE04 scenario on a four-socket x86 gets me RCU CPU stall warnings within a few minutes more than half the time. ;-)
Indeed I managed to trigger something. If it's the same thing I should be able to track down the root cause.
[ 123.907557] ??? Writer stall state RTWS_STUTTER(8) g160 c160 f0x0 ->state 0x1 cpu 2 [ 123.915184] rcu_torture_wri S 0 111 2 0x80080000 [ 123.920673] Call Trace: [ 123.923096] ? __schedule+0x2bf/0xbb0 [ 123.926715] ? _raw_spin_unlock_irqrestore+0x59/0x70 [ 123.931657] schedule+0x3c/0x90 [ 123.934777] schedule_timeout+0x1e1/0x560 [ 123.938785] ? __next_timer_interrupt+0xd0/0xd0 [ 123.943276] stutter_wait+0xc5/0xe0 [ 123.946738] rcu_torture_writer+0x1ae/0x730 [ 123.950912] ? rcu_torture_pipe_update+0xf0/0xf0 [ 123.955491] kthread+0x15f/0x1a0 [ 123.958702] ? kthread_unpark+0x60/0x60 [ 123.962523] ret_from_fork+0x24/0x30 [ 123.966091] rcu_preempt: wait state: 1 ->state: 0x402 [ 123.971112] rcu_sched: wait state: 1 ->state: 0x402 [ 123.975953] rcu_bh: wait state: 1 ->state: 0x402
Thanks!
Quoted 41 lines · Frederic Weisbecker
2017-12-02 20:24 UTC+01:00, Paul E. McKenney <[email protected]>:
Quoted 33 lines · Frederic Weisbecker
Quoted 26 lines
2017-11-30 21:20 UTC+01:00, Paul E. McKenney
<[email protected]>:Quoted 20 lines
Commit
5c4991e24c69("sched/isolation: Split out newCONFIG_CPU_ISOLATION=yconfig fromCONFIG_NO_HZ_FULL") can result in RCU
CPU stall warnings when running rcutorture withCONFIG_NO_HZ_FULL_ALL=yandCONFIG_CPU_ISOLATION=n. These warnings are caused by RCU's grace-period kthreads sleeping for a few jiffies, but never being awakened:[ 116.353432] rcu_preempt kthread starved for 9974 jiffies! g4294967208 +c4294967207 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x402 ->cpu=0 [ 116.355517] rcu_preempt I 7464 8 2 0x80000000 [ 116.356543] Call Trace: [ 116.357008] __schedule+0x493/0x620 [ 116.357682] schedule+0x24/0x40 [ 116.358291] schedule_timeout+0x330/0x3b0 [ 116.359024] ? preempt_count_sub+0xea/0x140 [ 116.359806] ? collect_expired_timers+0xb0/0xb0 [ 116.360660] rcu_gp_kthread+0x6bf/0xef0Quoted 3 lines
This commit therefore makes
NO_HZ_FULLselectCPU_ISOLATION, which prevents this behavior and seems like it was the original intention in any case.Quoted 5 lines
Although
CONFIG_NO_HZshould indeed selectCONFIG_CPU_ISOLATION, I'm surprised about this stall. I'm even more surprised that settingCONFIG_CPU_ISOLATION=yis enough to fix the issue becauseCONFIG_NO_HZ_FULL_ALLshortcutsCONFIG_CPU_ISOLATIONentirely (which is not good, but work in progress...).Quoted 6 lines
Yes, and after applying this patch, I get failures a few commits later, which appears to be due to other changes that break
CONFIG_NO_HZ_FULL_ALL=y. So I have another patch staged that removesCONFIG_NO_HZ_FULL_ALL, on the grounds that no one else has complained, so rcutorture is likely to be the only user, and I don't see the point of having aKconfigoption for only one user.
Quoted 4 lines
I would prefer to keep it. It's useful for automated boot testing based on configs such as 0-day or -tip test machines. But I'm likely to migrate it to isolcpus implementation. Maybe something along the lines of
CONFIG_CPU_ISOLATION_ALL.
How about instead allowing something like "nohz_full=1-" specify that all CPUs other than CPU 0 should be nohz_full CPUs? That would shrink the code by eliminating CONFIG_NO_HZ_FULL_ALL while still allowing easy automation of that particular scenario.
(Right now, the boot code complains about "nohz_full=1-", which means that whatever is generating the boot parameters needs to know how many CPUs there really are, which as you say can be a pain.)
Quoted 13 lines
Quoted 9 lines
Quoted 1 line
Did you have any nohz_full= or isolcpus= boot options?
Replacing
CONFIG_NO_HZ_FULL_ALL=ywith nohz_full=1-7 works, that isCONFIG_NO_HZ_FULL=y,CONFIG_NO_HZ_FULL_ALL=n, and nohz_full=1-7 on an eight-CPU test.But it is relatively easy to test. Running the rcutorture TREE04 scenario on a four-socket x86 gets me RCU CPU stall warnings within a few minutes more than half the time. ;-)
Indeed I managed to trigger something. If it's the same thing I should be able to track down the root cause.
Quoted 8 lines
[ 123.907557] ??? Writer stall state RTWS_STUTTER(8) g160 c160 f0x0 ->state 0x1 cpu 2 [ 123.915184] rcu_torture_wri S 0 111 2 0x80080000 [ 123.920673] Call Trace: [ 123.923096] ? __schedule+0x2bf/0xbb0 [ 123.926715] ? _raw_spin_unlock_irqrestore+0x59/0x70 [ 123.931657] schedule+0x3c/0x90 [ 123.934777] schedule_timeout+0x1e1/0x560
It might well be the same thing, as this schedule_timeout() does look familiar. I have some diagnostic patches in -rcu, please see below for the overall effect.
Thanx, Paul
Quoted 10 lines
[ 123.938785] ? __next_timer_interrupt+0xd0/0xd0 [ 123.943276] stutter_wait+0xc5/0xe0 [ 123.946738] rcu_torture_writer+0x1ae/0x730 [ 123.950912] ? rcu_torture_pipe_update+0xf0/0xf0 [ 123.955491] kthread+0x15f/0x1a0 [ 123.958702] ? kthread_unpark+0x60/0x60 [ 123.962523] ret_from_fork+0x24/0x30 [ 123.966091] rcu_preempt: wait state: 1 ->state: 0x402 [ 123.971112] rcu_sched: wait state: 1 ->state: 0x402 [ 123.975953] rcu_bh: wait state: 1 ->state: 0x402
------------------------------------------------------------------------
kernel/time/timer.c +16 -0
@@ -1755,8 +1755,13 @@ static void process_timeout(struct timer_list *t)*/ signed long __sched schedule_timeout (signed long timeout) { +struct timer_base *base;struct process_timer timer;unsigned long expire; +unsigned long flags; +unsigned long i; +unsigned int idx, idx_now; +unsigned long j;switch (timeout) {
@@ -1793,6 +1798,17 @@ signed long __sched schedule_timeout(signed long timeout)timer_setup_on_stack (&timer.timer, process_timeout,0 );__mod_timer (&timer.timer, expire,0 );schedule (); + j = jiffies; +if (timeout <5 &&time_after (j, expire +8 *HZ ) &&timer_pending (&timer.timer)) { + base =lock_timer_base (&timer.timer, &flags); + idx =timer_get_idx (&timer.timer); + idx_now =calc_wheel_index (j, base->clk); +raw_spin_unlock_irqrestore (&base->lock, flags); +pr_info ("%s: Waylayed timer base->clk: %#lx jiffies: %#lx base->next_expiry: %#lx timer->flags: %#x timer->expires %#lx idx: %x idx_now: %x base->pending_map " , __func__, base->clk, j, base->next_expiry, timer.timer.flags, timer.timer.expires, idx, idx_now); +for (i =0 ; i <WHEEL_SIZE /sizeof (base->pending_map[0 ]) /8 ; i++) +pr_cont ("%016lx" , base->pending_map[i]); +pr_cont ("\n" ); + }del_singleshot_timer_sync (&timer.timer);/* Remove the timer from the object tracker */
Frederic Weisbecker
maintainer2017-12-04 18:16 UTC+01:00, Paul E. McKenney <[email protected]>:
Quoted 7 lines · Frederic Weisbecker
Quoted 5 lines
2017-12-02 20:24 UTC+01:00, Paul E. McKenney
I would prefer to keep it. It's useful for automated boot testing based on configs such as 0-day or -tip test machines. But I'm likely to migrate it to isolcpus implementation. Maybe something along the lines ofCONFIG_CPU_ISOLATION_ALL.
Quoted 8 lines
How about instead allowing something like "nohz_full=1-" specify that all CPUs other than CPU 0 should be
nohz_fullCPUs? That would shrink the code by eliminatingCONFIG_NO_HZ_FULL_ALLwhile still allowing easy automation of that particular scenario.(Right now, the boot code complains about "nohz_full=1-", which means that whatever is generating the boot parameters needs to know how many CPUs there really are, which as you say can be a pain.)
Yes but automated boot testing is rather based on configs than boot options. It's much easier. I think that's how Wu Fengguang lab works, and -tip automated tests as well.
Quoted 23 lines
Quoted 14 lines
Quoted 10 lines
Quoted 2 lines
Did you have any nohz_full= or isolcpus= boot options?
Replacing
CONFIG_NO_HZ_FULL_ALL=ywith nohz_full=1-7 works, that isCONFIG_NO_HZ_FULL=y,CONFIG_NO_HZ_FULL_ALL=n, and nohz_full=1-7 on an eight-CPU test.But it is relatively easy to test. Running the rcutorture TREE04 scenario on a four-socket x86 gets me RCU CPU stall warnings within a few minutes more than half the time. ;-)
Indeed I managed to trigger something. If it's the same thing I should be able to track down the root cause.
Quoted 8 lines
[ 123.907557] ??? Writer stall state RTWS_STUTTER(8) g160 c160 f0x0 ->state 0x1 cpu 2 [ 123.915184] rcu_torture_wri S 0 111 2 0x80080000 [ 123.920673] Call Trace: [ 123.923096] ? __schedule+0x2bf/0xbb0 [ 123.926715] ? _raw_spin_unlock_irqrestore+0x59/0x70 [ 123.931657] schedule+0x3c/0x90 [ 123.934777] schedule_timeout+0x1e1/0x560
Quoted 3 lines
It might well be the same thing, as this
schedule_timeout()does look familiar. I have some diagnostic patches in -rcu, please see below for the overall effect.
I fear I can hit that even without any nohz_full CPU as well.
Quoted 52 lines
Thanx, Paul
Quoted 10 lines
[ 123.938785] ? __next_timer_interrupt+0xd0/0xd0 [ 123.943276] stutter_wait+0xc5/0xe0 [ 123.946738] rcu_torture_writer+0x1ae/0x730 [ 123.950912] ? rcu_torture_pipe_update+0xf0/0xf0 [ 123.955491] kthread+0x15f/0x1a0 [ 123.958702] ? kthread_unpark+0x60/0x60 [ 123.962523] ret_from_fork+0x24/0x30 [ 123.966091] rcu_preempt: wait state: 1 ->state: 0x402 [ 123.971112] rcu_sched: wait state: 1 ->state: 0x402 [ 123.975953] rcu_bh: wait state: 1 ->state: 0x402------------------------------------------------------------------------
kernel/time/timer.c +12
-0@@ -1755,8 +1755,13 @@ static void process_timeout(struct timer_list *t)*/ signed long __sched schedule_timeout (signed long timeout) { +struct timer_base *base;struct process_timer timer;unsigned long expire; +unsigned long flags; +unsigned long i; +unsigned int idx, idx_now; +unsigned long j;switch (timeout) {@@ -1793,6 +1798,17 @@ signed long __sched schedule_timeout(signed long timeout) timer_setup_on_stack(&timer.timer, process_timeout, 0);__mod_timer (&timer.timer, expire,0 );schedule (); + j = jiffies; +if (timeout <5 &&time_after (j, expire +8 *HZ ) &&timer_pending (&timer.timer)) { + base =lock_timer_base (&timer.timer, &flags); + idx =timer_get_idx (&timer.timer); + idx_now =calc_wheel_index (j, base->clk); +raw_spin_unlock_irqrestore (&base->lock, flags); + pr_info("%s: Waylayed timer base->clk: %#lx jiffies: %#lx
base->next_expiry: %#lxtimer->flags: %#xtimer->expires%#lx idx: %xidx_now: %xbase->pending_map",__func__,base->clk, j,base->next_expiry, timer.timer.flags, timer.timer.expires, idx,idx_now);
kernel/time/timer.c signed long __sched schedule_timeout(signed long timeout) · line 1814
Quoted 7 lines
kernel/time/timer.c +4
-0+for (i =0 ; i <WHEEL_SIZE /sizeof (base->pending_map[0 ]) /8 ; i++) +pr_cont ("%016lx" , base->pending_map[i]); +pr_cont ("\n" ); + }del_singleshot_timer_sync (&timer.timer);/* Remove the timer from the object tracker */
Hmm, that message doesn't seem to trigger :-s
Thanks.
Quoted 13 lines · Frederic Weisbecker
2017-12-04 18:16 UTC+01:00, Paul E. McKenney <[email protected]>:
Quoted 12 lines · Frederic Weisbecker
Quoted 5 lines
2017-12-02 20:24 UTC+01:00, Paul E. McKenney
I would prefer to keep it. It's useful for automated boot testing based on configs such as 0-day or -tip test machines. But I'm likely to migrate it to isolcpus implementation. Maybe something along the lines ofCONFIG_CPU_ISOLATION_ALL.How about instead allowing something like "nohz_full=1-" specify that all CPUs other than CPU 0 should be
nohz_fullCPUs? That would shrink the code by eliminatingCONFIG_NO_HZ_FULL_ALLwhile still allowing easy automation of that particular scenario.
Quoted 7 lines
Quoted 3 lines
(Right now, the boot code complains about "nohz_full=1-", which means that whatever is generating the boot parameters needs to know how many CPUs there really are, which as you say can be a pain.)
Yes but automated boot testing is rather based on configs than boot options. It's much easier. I think that's how Wu Fengguang lab works, and -tip automated tests as well.
So you have gotten bug reports from them? Because I see splats from rcutorture testing rather frequently. This thing is in no way a subtle low-probability bug. ;-)
Quoted 22 lines
Quoted 22 lines
Quoted 21 lines
Quoted 9 lines
Quoted 1 line
Did you have any nohz_full= or isolcpus= boot options?
Replacing
CONFIG_NO_HZ_FULL_ALL=ywith nohz_full=1-7 works, that isCONFIG_NO_HZ_FULL=y,CONFIG_NO_HZ_FULL_ALL=n, and nohz_full=1-7 on an eight-CPU test.But it is relatively easy to test. Running the rcutorture TREE04 scenario on a four-socket x86 gets me RCU CPU stall warnings within a few minutes more than half the time. ;-)
Indeed I managed to trigger something. If it's the same thing I should be able to track down the root cause.
[ 123.907557] ??? Writer stall state RTWS_STUTTER(8) g160 c160 f0x0 ->state 0x1 cpu 2 [ 123.915184] rcu_torture_wri S 0 111 2 0x80080000 [ 123.920673] Call Trace: [ 123.923096] ? __schedule+0x2bf/0xbb0 [ 123.926715] ? _raw_spin_unlock_irqrestore+0x59/0x70 [ 123.931657] schedule+0x3c/0x90 [ 123.934777] schedule_timeout+0x1e1/0x560
Quoted 5 lines
Quoted 3 lines
It might well be the same thing, as this
schedule_timeout()does look familiar. I have some diagnostic patches in -rcu, please see below for the overall effect.I fear I can hit that even without any
nohz_fullCPU as well.
Indeed, I do hit that with my TREE01 scenario, which does not set CONFIG_NO_HZ_FULL. But it is much less frequent. The good news is that I have finally figured out a way to extract information from this thing without suppressing it. At the moment it appears to be a rather strange deadlock involving CPU hotplug, timers, and RCU.
But that is a completely different bug from the ones for which I have the two patches in my tree.
Anyway, I will keep those two patches because I cannot have the corresponding bugs possibly hiding RCU bugs in my testing. If you put some other fix in place, I will drop those two patches in favor of your fix.
Thanx, Paul
Quoted 61 lines
Quoted 49 lines
Quoted 10 lines
[ 123.938785] ? __next_timer_interrupt+0xd0/0xd0 [ 123.943276] stutter_wait+0xc5/0xe0 [ 123.946738] rcu_torture_writer+0x1ae/0x730 [ 123.950912] ? rcu_torture_pipe_update+0xf0/0xf0 [ 123.955491] kthread+0x15f/0x1a0 [ 123.958702] ? kthread_unpark+0x60/0x60 [ 123.962523] ret_from_fork+0x24/0x30 [ 123.966091] rcu_preempt: wait state: 1 ->state: 0x402 [ 123.971112] rcu_sched: wait state: 1 ->state: 0x402 [ 123.975953] rcu_bh: wait state: 1 ->state: 0x402------------------------------------------------------------------------
kernel/time/timer.c +12
-0@@ -1755,8 +1755,13 @@ static void process_timeout(struct timer_list *t)*/ signed long __sched schedule_timeout (signed long timeout) { +struct timer_base *base;struct process_timer timer;unsigned long expire; +unsigned long flags; +unsigned long i; +unsigned int idx, idx_now; +unsigned long j;switch (timeout) {@@ -1793,6 +1798,17 @@ signed long __sched schedule_timeout(signed long timeout) timer_setup_on_stack(&timer.timer, process_timeout, 0);__mod_timer (&timer.timer, expire,0 );schedule (); + j = jiffies; +if (timeout <5 &&time_after (j, expire +8 *HZ ) &&timer_pending (&timer.timer)) { + base =lock_timer_base (&timer.timer, &flags); + idx =timer_get_idx (&timer.timer); + idx_now =calc_wheel_index (j, base->clk); +raw_spin_unlock_irqrestore (&base->lock, flags); + pr_info("%s: Waylayed timer base->clk: %#lx jiffies: %#lx
base->next_expiry: %#lxtimer->flags: %#xtimer->expires%#lx idx: %xidx_now: %xbase->pending_map",__func__,base->clk, j,base->next_expiry, timer.timer.flags, timer.timer.expires, idx,idx_now);kernel/time/timer.c signed long __sched schedule_timeout(signed long timeout) · line 1814
Quoted 7 lines
kernel/time/timer.c +4
-0+for (i =0 ; i <WHEEL_SIZE /sizeof (base->pending_map[0 ]) /8 ; i++) +pr_cont ("%016lx" , base->pending_map[i]); +pr_cont ("\n" ); + }del_singleshot_timer_sync (&timer.timer);/* Remove the timer from the object tracker */ Hmm, that message doesn't seem to trigger :-s
Thanks.
Frederic Weisbecker
maintainer2017-12-07 18:29 UTC+01:00, Paul E. McKenney <[email protected]>:
Quoted 19 lines · Frederic Weisbecker
Quoted 18 lines
2017-12-04 18:16 UTC+01:00, Paul E. McKenney
<[email protected]>:Quoted 15 lines · Frederic Weisbecker
Quoted 5 lines
2017-12-02 20:24 UTC+01:00, Paul E. McKenney
I would prefer to keep it. It's useful for automated boot testing based on configs such as 0-day or -tip test machines. But I'm likely to migrate it to isolcpus implementation. Maybe something along the lines ofCONFIG_CPU_ISOLATION_ALL.How about instead allowing something like "nohz_full=1-" specify that all CPUs other than CPU 0 should be
nohz_fullCPUs? That would shrink the code by eliminatingCONFIG_NO_HZ_FULL_ALLwhile still allowing easy automation of that particular scenario.(Right now, the boot code complains about "nohz_full=1-", which means that whatever is generating the boot parameters needs to know how many CPUs there really are, which as you say can be a pain.)
Quoted 7 lines
Quoted 3 lines
Yes but automated boot testing is rather based on configs than boot options. It's much easier. I think that's how Wu Fengguang lab works, and -tip automated tests as well.
So you have gotten bug reports from them? Because I see splats from rcutorture testing rather frequently. This thing is in no way a subtle low-probability bug. ;-)
Nope I haven't got anything from them. So far you're the only reproducer I know :)
Quoted 34 lines
Quoted 22 lines
Quoted 22 lines
Quoted 21 lines
Quoted 9 lines
Quoted 1 line
Did you have any nohz_full= or isolcpus= boot options?
Replacing
CONFIG_NO_HZ_FULL_ALL=ywith nohz_full=1-7 works, that isCONFIG_NO_HZ_FULL=y,CONFIG_NO_HZ_FULL_ALL=n, and nohz_full=1-7 on an eight-CPU test.But it is relatively easy to test. Running the rcutorture TREE04 scenario on a four-socket x86 gets me RCU CPU stall warnings within a few minutes more than half the time. ;-)
Indeed I managed to trigger something. If it's the same thing I should be able to track down the root cause.
[ 123.907557] ??? Writer stall state RTWS_STUTTER(8) g160 c160 f0x0 ->state 0x1 cpu 2 [ 123.915184] rcu_torture_wri S 0 111 2 0x80080000 [ 123.920673] Call Trace: [ 123.923096] ? __schedule+0x2bf/0xbb0 [ 123.926715] ? _raw_spin_unlock_irqrestore+0x59/0x70 [ 123.931657] schedule+0x3c/0x90 [ 123.934777] schedule_timeout+0x1e1/0x560Quoted 5 lines
Quoted 3 lines
It might well be the same thing, as this
schedule_timeout()does look familiar. I have some diagnostic patches in -rcu, please see below for the overall effect.I fear I can hit that even without any
nohz_fullCPU as well.Indeed, I do hit that with my TREE01 scenario, which does not set
CONFIG_NO_HZ_FULL. But it is much less frequent. The good news is that I have finally figured out a way to extract information from this thing without suppressing it. At the moment it appears to be a rather strange deadlock involving CPU hotplug, timers, and RCU.
Quoted 7 lines
But that is a completely different bug from the ones for which I have the two patches in my tree.
Anyway, I will keep those two patches because I cannot have the corresponding bugs possibly hiding RCU bugs in my testing. If you put some other fix in place, I will drop those two patches in favor of your fix.
Ok. I'm a bit troubled by this bug, I hate to push a fix for a bug I don't understand nor can reproduce. But having CONFIG_NO_HZ_FULL select CONFIG_CPU_ISOLATION is already a fix for sanity that I need to push. So I think I'm going to take your patch anyway and rewrite the changelog to take all that into account.
Thanks Paul!
Quoted 68 lines · Frederic Weisbecker
2017-12-07 18:29 UTC+01:00, Paul E. McKenney <[email protected]>:
Quoted 19 lines · Frederic Weisbecker
Quoted 18 lines
2017-12-04 18:16 UTC+01:00, Paul E. McKenney
<[email protected]>:Quoted 15 lines · Frederic Weisbecker
Quoted 5 lines
2017-12-02 20:24 UTC+01:00, Paul E. McKenney
I would prefer to keep it. It's useful for automated boot testing based on configs such as 0-day or -tip test machines. But I'm likely to migrate it to isolcpus implementation. Maybe something along the lines ofCONFIG_CPU_ISOLATION_ALL.How about instead allowing something like "nohz_full=1-" specify that all CPUs other than CPU 0 should be
nohz_fullCPUs? That would shrink the code by eliminatingCONFIG_NO_HZ_FULL_ALLwhile still allowing easy automation of that particular scenario.(Right now, the boot code complains about "nohz_full=1-", which means that whatever is generating the boot parameters needs to know how many CPUs there really are, which as you say can be a pain.)
Quoted 7 lines
Quoted 3 lines
Yes but automated boot testing is rather based on configs than boot options. It's much easier. I think that's how Wu Fengguang lab works, and -tip automated tests as well.
So you have gotten bug reports from them? Because I see splats from rcutorture testing rather frequently. This thing is in no way a subtle low-probability bug. ;-)
Nope I haven't got anything from them. So far you're the only reproducer I know :)
Quoted 37 lines
Quoted 22 lines
Quoted 22 lines
Quoted 21 lines
Quoted 9 lines
Quoted 1 line
Did you have any nohz_full= or isolcpus= boot options?
Replacing
CONFIG_NO_HZ_FULL_ALL=ywith nohz_full=1-7 works, that isCONFIG_NO_HZ_FULL=y,CONFIG_NO_HZ_FULL_ALL=n, and nohz_full=1-7 on an eight-CPU test.But it is relatively easy to test. Running the rcutorture TREE04 scenario on a four-socket x86 gets me RCU CPU stall warnings within a few minutes more than half the time. ;-)
Indeed I managed to trigger something. If it's the same thing I should be able to track down the root cause.
[ 123.907557] ??? Writer stall state RTWS_STUTTER(8) g160 c160 f0x0 ->state 0x1 cpu 2 [ 123.915184] rcu_torture_wri S 0 111 2 0x80080000 [ 123.920673] Call Trace: [ 123.923096] ? __schedule+0x2bf/0xbb0 [ 123.926715] ? _raw_spin_unlock_irqrestore+0x59/0x70 [ 123.931657] schedule+0x3c/0x90 [ 123.934777] schedule_timeout+0x1e1/0x560Quoted 5 lines
Quoted 3 lines
It might well be the same thing, as this
schedule_timeout()does look familiar. I have some diagnostic patches in -rcu, please see below for the overall effect.I fear I can hit that even without any
nohz_fullCPU as well.Indeed, I do hit that with my TREE01 scenario, which does not set
CONFIG_NO_HZ_FULL. But it is much less frequent. The good news is that I have finally figured out a way to extract information from this thing without suppressing it. At the moment it appears to be a rather strange deadlock involving CPU hotplug, timers, and RCU.But that is a completely different bug from the ones for which I have the two patches in my tree.
Quoted 7 lines
Quoted 4 lines
Anyway, I will keep those two patches because I cannot have the corresponding bugs possibly hiding RCU bugs in my testing. If you put some other fix in place, I will drop those two patches in favor of your fix.
Ok. I'm a bit troubled by this bug, I hate to push a fix for a bug I don't understand nor can reproduce.
I would be happy to talk you through running the TREE04 rcutorture scenario, if you would like. I just verified that I can reproduce this on a single-socket four-core (8 hardware threads) x86 system running v4.15-rc1, so I would guess that you have access to hardware that can reproduce it.
In the meantime, please feel free to take a look at the file tools/testing/selftests/rcutorture/doc/initrd.txt in the kernel source. This file tells how to create the initrd that rcutorture uses to avoid the need to maintain root partitions. Once you have that in place in tools/testing/selftests/rcutorture/initrd (as a expanded file tree, not any sort of archive) the reproducer is as follows, run from the top level of the kernel source tree:
bash tools/testing/selftests/rcutorture/bin/kvm.sh --duration 5 --configs TREE04
This will output a bunch of rcutorture status/progress text, ending in something like the following:
--- Sat Dec 9 09:49:26 PST 2017 Test summary:
Results directory: /home/git/linux-2.6/tools/testing/selftests/rcutorture/res/2017.12.09-09:49:26 tools/testing/selftests/rcutorture/bin/kvm.sh --cpus 7 --duration 5 --configs TREE04
TREE04 ------- 350 grace periods (1.16667 per second)
WARNING: Assertion failure in /home/git/linux-2.6/tools/testing/selftests/rcutorture/res/2017.12.09-09:49:26/TREE04/console.log
WARNING: Summary: Call Traces: 7 Stalls: 1 Starves: 1
The big long pathname ending in "console.log" contains the console output.
A successful run would end without the WARNING lines.
Quoted 6 lines
But having
CONFIG_NO_HZ_FULL
selectCONFIG_CPU_ISOLATIONis already a fix for sanity that I need to push. So I think I'm going to take your patch anyway and rewrite the changelog to take all that into account.Thanks Paul!
Works for me! I don't know of anyone else encountering this, so I don't see it as an emergency. Left to myself, I would therefore push the fixes into the v4.17 merge window (that is, the one after the next one). But please let me know when you have pushed fixes, and I will adjust my tree accordingly.
I am of course happy to test your fixes.
Thanx, Paul