| Message ID | 20160630074710.GC30114@js1304-P5Q-DELUXE (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
Hi Joonsoo, On Thu, Jun 30, 2016 at 9:47 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote: > On Wed, Jun 29, 2016 at 11:12:08AM -0700, Paul E. McKenney wrote: >> On Wed, Jun 29, 2016 at 07:52:06PM +0200, Geert Uytterhoeven wrote: >> > On Wed, Jun 29, 2016 at 6:44 PM, Paul E. McKenney >> > <paulmck@linux.vnet.ibm.com> wrote: >> > > On Wed, Jun 29, 2016 at 04:54:44PM +0200, Geert Uytterhoeven wrote: >> > >> On Thu, Jun 23, 2016 at 4:53 AM, Paul E. McKenney >> > >> <paulmck@linux.vnet.ibm.com> wrote: >> > >> > On Wed, Jun 22, 2016 at 07:47:42PM -0700, Paul E. McKenney wrote: >> > > >> > > [ . . . ] >> > > >> > >> > @@ -4720,11 +4720,18 @@ static void __init rcu_dump_rcu_node_tree(struct rcu_state *rsp) >> > >> > pr_info(" "); >> > >> > level = rnp->level; >> > >> > } >> > >> > - pr_cont("%d:%d ^%d ", rnp->grplo, rnp->grphi, rnp->grpnum); >> > >> > + pr_cont("%d:%d/%#lx/%#lx ^%d ", rnp->grplo, rnp->grphi, >> > >> > + rnp->qsmask, >> > >> > + rnp->qsmaskinit | rnp->qsmaskinitnext, rnp->grpnum); >> > >> > } >> > >> > pr_cont("\n"); >> > >> > } >> > >> >> > >> For me it always crashes during the 37th call of synchronize_sched() in >> > >> setup_kmem_cache_node(), which is the first call after secondary CPU bring up. >> > >> With your and my debug code, I get: >> > >> >> > >> CPU: Testing write buffer coherency: ok >> > >> CPU0: thread -1, cpu 0, socket 0, mpidr 80000000 >> > >> Setting up static identity map for 0x40100000 - 0x40100058 >> > >> cnt = 36, sync >> > >> CPU1: thread -1, cpu 1, socket 0, mpidr 80000001 >> > >> Brought up 2 CPUs >> > >> SMP: Total of 2 processors activated (2132.00 BogoMIPS). >> > >> CPU: All CPU(s) started in SVC mode. >> > >> rcu_node tree layout dump >> > >> 0:1/0x0/0x3 ^0 >> > > >> > > Thank you for running this! >> > > >> > > OK, so RCU knows about both CPUs (the "0x3"), and the previous >> > > grace period has seen quiescent states from both of them (the "0x0"). >> > > That would indicate that your synchronize_sched() showed up when RCU was >> > > idle, so it had to start a new grace period. It also rules out failure >> > > modes where RCU thinks that there are more CPUs than really exist. >> > > (Don't laugh, such things have really happened.) >> > > >> > >> devtmpfs: initialized >> > >> VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 1 >> > >> clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, >> > >> max_idle_ns: 19112604462750000 ns >> > >> >> > >> I hope it helps. Thanks! >> > > >> > > I am going to guess that this was the first grace period since the second >> > > CPU came online. When there only on CPU online, synchronize_sched() >> > > is a no-op. >> > > >> > > OK, this showed some things that aren't a problem. What might the >> > > problem be? >> > > >> > > o The grace-period kthread has not yet started. It -should- start >> > > at early_initcall() time, but who knows? Adding code to print >> > > out that kthread's task_struct address. >> > > >> > > o The grace-period kthread might not be responding to wakeups. >> > > Checking this requires that a grace period be in progress, >> > > so please put a call_rcu_sched() just before the call to >> > > rcu_dump_rcu_node_tree(). (Sample code below.) Adding code >> > > to my patch to print out more GP-kthread state as well. >> > > >> > > o One of the CPUs might not be responding to RCU. That -should- >> > > result in an RCU CPU stall warning, so I will ignore this >> > > possibility for the moment. >> > > >> > > That said, do you have some way to determine whether scheduling >> > > clock interrupts are really happening? Without these interrupts, >> > > no RCU CPU stall warnings. >> > >> > I believe there are no clocksources yet. The jiffies clocksource is the first >> > clocksource found, and that happens after the first call to >> > synchronize_sched(), cfr. my dmesg snippet above. >> > >> > In a working boot: >> > # cat /sys/bus/clocksource/devices/clocksource0/available_clocksource >> > e0180000.timer jiffies >> > # cat /sys/bus/clocksource/devices/clocksource0/current_clocksource >> > e0180000.timer >> >> Ah! But if there is no jiffies clocksource, then schedule_timeout() >> and friends will never return, correct? If so, I guarantee you that >> synchronize_sched() will unconditionally hang. >> >> So if I understand correctly, the fix is to get the jiffies clocksource >> running before the first call to synchronize_sched(). > > If so, following change would be sufficient. > > Thanks. > > ------>8------- > diff --git a/kernel/time/jiffies.c b/kernel/time/jiffies.c > index 555e21f..4f6471f 100644 > --- a/kernel/time/jiffies.c > +++ b/kernel/time/jiffies.c > @@ -98,7 +98,7 @@ static int __init init_jiffies_clocksource(void) > return __clocksource_register(&clocksource_jiffies); > } > > -core_initcall(init_jiffies_clocksource); > +early_initcall(init_jiffies_clocksource); > > struct clocksource * __init __weak clocksource_default_clock(void) > { Thanks for your patch! While this does move jiffies clocksource initialization before secondary CPU bringup, it still hangs when calling call_rcu() or synchronize_sched(): CPU: Testing write buffer coherency: ok CPU0: thread -1, cpu 0, socket 0, mpidr 80000000 Setting up static identity map for 0x40100000 - 0x40100058 cnt = 36, sync clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns CPU1: thread -1, cpu 1, socket 0, mpidr 80000001 Brought up 2 CPUs SMP: Total of 2 processors activated (2132.00 BogoMIPS). CPU: All CPU(s) started in SVC mode. RCU: rcu_sched GP kthread: c784e1c0 state: 1 flags: 0x0 g:-300 c:-300 jiffies: 0xffff8ad0 GP start: 0x0 Last GP activity: 0x0 rcu_node tree layout dump 0:1/0x0/0x3 ^0 devtmpfs: initialized VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 1 Gr{oetje,eeting}s, Geert -- Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org In personal conversations with technical people, I call myself a hacker. But when I'm talking to journalists I just say "programmer" or something like that. -- Linus Torvalds
On Thu, Jun 30, 2016 at 09:58:51AM +0200, Geert Uytterhoeven wrote: > Hi Joonsoo, > > On Thu, Jun 30, 2016 at 9:47 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote: > > On Wed, Jun 29, 2016 at 11:12:08AM -0700, Paul E. McKenney wrote: > >> On Wed, Jun 29, 2016 at 07:52:06PM +0200, Geert Uytterhoeven wrote: > >> > On Wed, Jun 29, 2016 at 6:44 PM, Paul E. McKenney > >> > <paulmck@linux.vnet.ibm.com> wrote: > >> > > On Wed, Jun 29, 2016 at 04:54:44PM +0200, Geert Uytterhoeven wrote: > >> > >> On Thu, Jun 23, 2016 at 4:53 AM, Paul E. McKenney > >> > >> <paulmck@linux.vnet.ibm.com> wrote: > >> > >> > On Wed, Jun 22, 2016 at 07:47:42PM -0700, Paul E. McKenney wrote: > >> > > > >> > > [ . . . ] > >> > > > >> > >> > @@ -4720,11 +4720,18 @@ static void __init rcu_dump_rcu_node_tree(struct rcu_state *rsp) > >> > >> > pr_info(" "); > >> > >> > level = rnp->level; > >> > >> > } > >> > >> > - pr_cont("%d:%d ^%d ", rnp->grplo, rnp->grphi, rnp->grpnum); > >> > >> > + pr_cont("%d:%d/%#lx/%#lx ^%d ", rnp->grplo, rnp->grphi, > >> > >> > + rnp->qsmask, > >> > >> > + rnp->qsmaskinit | rnp->qsmaskinitnext, rnp->grpnum); > >> > >> > } > >> > >> > pr_cont("\n"); > >> > >> > } > >> > >> > >> > >> For me it always crashes during the 37th call of synchronize_sched() in > >> > >> setup_kmem_cache_node(), which is the first call after secondary CPU bring up. > >> > >> With your and my debug code, I get: > >> > >> > >> > >> CPU: Testing write buffer coherency: ok > >> > >> CPU0: thread -1, cpu 0, socket 0, mpidr 80000000 > >> > >> Setting up static identity map for 0x40100000 - 0x40100058 > >> > >> cnt = 36, sync > >> > >> CPU1: thread -1, cpu 1, socket 0, mpidr 80000001 > >> > >> Brought up 2 CPUs > >> > >> SMP: Total of 2 processors activated (2132.00 BogoMIPS). > >> > >> CPU: All CPU(s) started in SVC mode. > >> > >> rcu_node tree layout dump > >> > >> 0:1/0x0/0x3 ^0 > >> > > > >> > > Thank you for running this! > >> > > > >> > > OK, so RCU knows about both CPUs (the "0x3"), and the previous > >> > > grace period has seen quiescent states from both of them (the "0x0"). > >> > > That would indicate that your synchronize_sched() showed up when RCU was > >> > > idle, so it had to start a new grace period. It also rules out failure > >> > > modes where RCU thinks that there are more CPUs than really exist. > >> > > (Don't laugh, such things have really happened.) > >> > > > >> > >> devtmpfs: initialized > >> > >> VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 1 > >> > >> clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, > >> > >> max_idle_ns: 19112604462750000 ns > >> > >> > >> > >> I hope it helps. Thanks! > >> > > > >> > > I am going to guess that this was the first grace period since the second > >> > > CPU came online. When there only on CPU online, synchronize_sched() > >> > > is a no-op. > >> > > > >> > > OK, this showed some things that aren't a problem. What might the > >> > > problem be? > >> > > > >> > > o The grace-period kthread has not yet started. It -should- start > >> > > at early_initcall() time, but who knows? Adding code to print > >> > > out that kthread's task_struct address. > >> > > > >> > > o The grace-period kthread might not be responding to wakeups. > >> > > Checking this requires that a grace period be in progress, > >> > > so please put a call_rcu_sched() just before the call to > >> > > rcu_dump_rcu_node_tree(). (Sample code below.) Adding code > >> > > to my patch to print out more GP-kthread state as well. > >> > > > >> > > o One of the CPUs might not be responding to RCU. That -should- > >> > > result in an RCU CPU stall warning, so I will ignore this > >> > > possibility for the moment. > >> > > > >> > > That said, do you have some way to determine whether scheduling > >> > > clock interrupts are really happening? Without these interrupts, > >> > > no RCU CPU stall warnings. > >> > > >> > I believe there are no clocksources yet. The jiffies clocksource is the first > >> > clocksource found, and that happens after the first call to > >> > synchronize_sched(), cfr. my dmesg snippet above. > >> > > >> > In a working boot: > >> > # cat /sys/bus/clocksource/devices/clocksource0/available_clocksource > >> > e0180000.timer jiffies > >> > # cat /sys/bus/clocksource/devices/clocksource0/current_clocksource > >> > e0180000.timer > >> > >> Ah! But if there is no jiffies clocksource, then schedule_timeout() > >> and friends will never return, correct? If so, I guarantee you that > >> synchronize_sched() will unconditionally hang. > >> > >> So if I understand correctly, the fix is to get the jiffies clocksource > >> running before the first call to synchronize_sched(). > > > > If so, following change would be sufficient. > > > > Thanks. > > > > ------>8------- > > diff --git a/kernel/time/jiffies.c b/kernel/time/jiffies.c > > index 555e21f..4f6471f 100644 > > --- a/kernel/time/jiffies.c > > +++ b/kernel/time/jiffies.c > > @@ -98,7 +98,7 @@ static int __init init_jiffies_clocksource(void) > > return __clocksource_register(&clocksource_jiffies); > > } > > > > -core_initcall(init_jiffies_clocksource); > > +early_initcall(init_jiffies_clocksource); > > > > struct clocksource * __init __weak clocksource_default_clock(void) > > { > > Thanks for your patch! > > While this does move jiffies clocksource initialization before secondary CPU > bringup, it still hangs when calling call_rcu() or synchronize_sched(): > > CPU: Testing write buffer coherency: ok > CPU0: thread -1, cpu 0, socket 0, mpidr 80000000 > Setting up static identity map for 0x40100000 - 0x40100058 > cnt = 36, sync > clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, > max_idle_ns: 19112604462750000 ns > CPU1: thread -1, cpu 1, socket 0, mpidr 80000001 > Brought up 2 CPUs > SMP: Total of 2 processors activated (2132.00 BogoMIPS). > CPU: All CPU(s) started in SVC mode. > RCU: rcu_sched GP kthread: c784e1c0 state: 1 flags: 0x0 g:-300 c:-300 > jiffies: 0xffff8ad0 GP start: 0x0 Last GP activity: 0x0 > rcu_node tree layout dump > 0:1/0x0/0x3 ^0 This is in fact the initial state for RCU grace periods. In other words, all the earlier calls to synchronize_sched() likely happened while there was only one CPU online. > devtmpfs: initialized > VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 1 Could you please add the call_rcu() and timed delay as described in my earlier email? That would hopefully help me see the state of the stalled grace period. Thanx, Paul > Gr{oetje,eeting}s, > > Geert > > -- > Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org > > In personal conversations with technical people, I call myself a hacker. But > when I'm talking to journalists I just say "programmer" or something like that. > -- Linus Torvalds >
Hi Paul, On Thu, Jun 30, 2016 at 3:24 PM, Paul E. McKenney <paulmck@linux.vnet.ibm.com> wrote: > On Thu, Jun 30, 2016 at 09:58:51AM +0200, Geert Uytterhoeven wrote: >> On Thu, Jun 30, 2016 at 9:47 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote: >> > On Wed, Jun 29, 2016 at 11:12:08AM -0700, Paul E. McKenney wrote: >> >> On Wed, Jun 29, 2016 at 07:52:06PM +0200, Geert Uytterhoeven wrote: >> >> > On Wed, Jun 29, 2016 at 6:44 PM, Paul E. McKenney >> >> > <paulmck@linux.vnet.ibm.com> wrote: >> >> > > On Wed, Jun 29, 2016 at 04:54:44PM +0200, Geert Uytterhoeven wrote: >> >> > >> On Thu, Jun 23, 2016 at 4:53 AM, Paul E. McKenney >> >> > >> <paulmck@linux.vnet.ibm.com> wrote: >> >> > >> > On Wed, Jun 22, 2016 at 07:47:42PM -0700, Paul E. McKenney wrote: >> >> > > >> >> > > [ . . . ] >> >> > > >> >> > >> > @@ -4720,11 +4720,18 @@ static void __init rcu_dump_rcu_node_tree(struct rcu_state *rsp) >> >> > >> > pr_info(" "); >> >> > >> > level = rnp->level; >> >> > >> > } >> >> > >> > - pr_cont("%d:%d ^%d ", rnp->grplo, rnp->grphi, rnp->grpnum); >> >> > >> > + pr_cont("%d:%d/%#lx/%#lx ^%d ", rnp->grplo, rnp->grphi, >> >> > >> > + rnp->qsmask, >> >> > >> > + rnp->qsmaskinit | rnp->qsmaskinitnext, rnp->grpnum); >> >> > >> > } >> >> > >> > pr_cont("\n"); >> >> > >> > } >> >> > >> >> >> > >> For me it always crashes during the 37th call of synchronize_sched() in >> >> > >> setup_kmem_cache_node(), which is the first call after secondary CPU bring up. >> >> > >> With your and my debug code, I get: >> >> > >> >> >> > >> CPU: Testing write buffer coherency: ok >> >> > >> CPU0: thread -1, cpu 0, socket 0, mpidr 80000000 >> >> > >> Setting up static identity map for 0x40100000 - 0x40100058 >> >> > >> cnt = 36, sync >> >> > >> CPU1: thread -1, cpu 1, socket 0, mpidr 80000001 >> >> > >> Brought up 2 CPUs >> >> > >> SMP: Total of 2 processors activated (2132.00 BogoMIPS). >> >> > >> CPU: All CPU(s) started in SVC mode. >> >> > >> rcu_node tree layout dump >> >> > >> 0:1/0x0/0x3 ^0 >> >> > > >> >> > > Thank you for running this! >> >> > > >> >> > > OK, so RCU knows about both CPUs (the "0x3"), and the previous >> >> > > grace period has seen quiescent states from both of them (the "0x0"). >> >> > > That would indicate that your synchronize_sched() showed up when RCU was >> >> > > idle, so it had to start a new grace period. It also rules out failure >> >> > > modes where RCU thinks that there are more CPUs than really exist. >> >> > > (Don't laugh, such things have really happened.) >> >> > > >> >> > >> devtmpfs: initialized >> >> > >> VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 1 >> >> > >> clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, >> >> > >> max_idle_ns: 19112604462750000 ns >> >> > >> >> >> > >> I hope it helps. Thanks! >> >> > > >> >> > > I am going to guess that this was the first grace period since the second >> >> > > CPU came online. When there only on CPU online, synchronize_sched() >> >> > > is a no-op. >> >> > > >> >> > > OK, this showed some things that aren't a problem. What might the >> >> > > problem be? >> >> > > >> >> > > o The grace-period kthread has not yet started. It -should- start >> >> > > at early_initcall() time, but who knows? Adding code to print >> >> > > out that kthread's task_struct address. >> >> > > >> >> > > o The grace-period kthread might not be responding to wakeups. >> >> > > Checking this requires that a grace period be in progress, >> >> > > so please put a call_rcu_sched() just before the call to >> >> > > rcu_dump_rcu_node_tree(). (Sample code below.) Adding code >> >> > > to my patch to print out more GP-kthread state as well. >> >> > > >> >> > > o One of the CPUs might not be responding to RCU. That -should- >> >> > > result in an RCU CPU stall warning, so I will ignore this >> >> > > possibility for the moment. >> >> > > >> >> > > That said, do you have some way to determine whether scheduling >> >> > > clock interrupts are really happening? Without these interrupts, >> >> > > no RCU CPU stall warnings. >> >> > >> >> > I believe there are no clocksources yet. The jiffies clocksource is the first >> >> > clocksource found, and that happens after the first call to >> >> > synchronize_sched(), cfr. my dmesg snippet above. >> >> > >> >> > In a working boot: >> >> > # cat /sys/bus/clocksource/devices/clocksource0/available_clocksource >> >> > e0180000.timer jiffies >> >> > # cat /sys/bus/clocksource/devices/clocksource0/current_clocksource >> >> > e0180000.timer >> >> >> >> Ah! But if there is no jiffies clocksource, then schedule_timeout() >> >> and friends will never return, correct? If so, I guarantee you that >> >> synchronize_sched() will unconditionally hang. >> >> >> >> So if I understand correctly, the fix is to get the jiffies clocksource >> >> running before the first call to synchronize_sched(). >> > >> > If so, following change would be sufficient. >> > >> > Thanks. >> > >> > ------>8------- >> > diff --git a/kernel/time/jiffies.c b/kernel/time/jiffies.c >> > index 555e21f..4f6471f 100644 >> > --- a/kernel/time/jiffies.c >> > +++ b/kernel/time/jiffies.c >> > @@ -98,7 +98,7 @@ static int __init init_jiffies_clocksource(void) >> > return __clocksource_register(&clocksource_jiffies); >> > } >> > >> > -core_initcall(init_jiffies_clocksource); >> > +early_initcall(init_jiffies_clocksource); >> > >> > struct clocksource * __init __weak clocksource_default_clock(void) >> > { >> >> Thanks for your patch! >> >> While this does move jiffies clocksource initialization before secondary CPU >> bringup, it still hangs when calling call_rcu() or synchronize_sched(): >> >> CPU: Testing write buffer coherency: ok >> CPU0: thread -1, cpu 0, socket 0, mpidr 80000000 >> Setting up static identity map for 0x40100000 - 0x40100058 >> cnt = 36, sync >> clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, >> max_idle_ns: 19112604462750000 ns >> CPU1: thread -1, cpu 1, socket 0, mpidr 80000001 >> Brought up 2 CPUs >> SMP: Total of 2 processors activated (2132.00 BogoMIPS). >> CPU: All CPU(s) started in SVC mode. >> RCU: rcu_sched GP kthread: c784e1c0 state: 1 flags: 0x0 g:-300 c:-300 >> jiffies: 0xffff8ad0 GP start: 0x0 Last GP activity: 0x0 >> rcu_node tree layout dump >> 0:1/0x0/0x3 ^0 > > This is in fact the initial state for RCU grace periods. In other words, > all the earlier calls to synchronize_sched() likely happened while there > was only one CPU online. > >> devtmpfs: initialized >> VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 1 > > Could you please add the call_rcu() and timed delay as described in my > earlier email? That would hopefully help me see the state of the stalled > grace period. I already did, cfr. "it still hangs when calling call_rcu() or synchronize_sched()". Gr{oetje,eeting}s, Geert -- Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org In personal conversations with technical people, I call myself a hacker. But when I'm talking to journalists I just say "programmer" or something like that. -- Linus Torvalds
On Thu, Jun 30, 2016 at 03:31:57PM +0200, Geert Uytterhoeven wrote: > Hi Paul, > > On Thu, Jun 30, 2016 at 3:24 PM, Paul E. McKenney > <paulmck@linux.vnet.ibm.com> wrote: > > On Thu, Jun 30, 2016 at 09:58:51AM +0200, Geert Uytterhoeven wrote: > >> On Thu, Jun 30, 2016 at 9:47 AM, Joonsoo Kim <iamjoonsoo.kim@lge.com> wrote: > >> > On Wed, Jun 29, 2016 at 11:12:08AM -0700, Paul E. McKenney wrote: > >> >> On Wed, Jun 29, 2016 at 07:52:06PM +0200, Geert Uytterhoeven wrote: > >> >> > On Wed, Jun 29, 2016 at 6:44 PM, Paul E. McKenney > >> >> > <paulmck@linux.vnet.ibm.com> wrote: > >> >> > > On Wed, Jun 29, 2016 at 04:54:44PM +0200, Geert Uytterhoeven wrote: > >> >> > >> On Thu, Jun 23, 2016 at 4:53 AM, Paul E. McKenney > >> >> > >> <paulmck@linux.vnet.ibm.com> wrote: > >> >> > >> > On Wed, Jun 22, 2016 at 07:47:42PM -0700, Paul E. McKenney wrote: > >> >> > > > >> >> > > [ . . . ] > >> >> > > > >> >> > >> > @@ -4720,11 +4720,18 @@ static void __init rcu_dump_rcu_node_tree(struct rcu_state *rsp) > >> >> > >> > pr_info(" "); > >> >> > >> > level = rnp->level; > >> >> > >> > } > >> >> > >> > - pr_cont("%d:%d ^%d ", rnp->grplo, rnp->grphi, rnp->grpnum); > >> >> > >> > + pr_cont("%d:%d/%#lx/%#lx ^%d ", rnp->grplo, rnp->grphi, > >> >> > >> > + rnp->qsmask, > >> >> > >> > + rnp->qsmaskinit | rnp->qsmaskinitnext, rnp->grpnum); > >> >> > >> > } > >> >> > >> > pr_cont("\n"); > >> >> > >> > } > >> >> > >> > >> >> > >> For me it always crashes during the 37th call of synchronize_sched() in > >> >> > >> setup_kmem_cache_node(), which is the first call after secondary CPU bring up. > >> >> > >> With your and my debug code, I get: > >> >> > >> > >> >> > >> CPU: Testing write buffer coherency: ok > >> >> > >> CPU0: thread -1, cpu 0, socket 0, mpidr 80000000 > >> >> > >> Setting up static identity map for 0x40100000 - 0x40100058 > >> >> > >> cnt = 36, sync > >> >> > >> CPU1: thread -1, cpu 1, socket 0, mpidr 80000001 > >> >> > >> Brought up 2 CPUs > >> >> > >> SMP: Total of 2 processors activated (2132.00 BogoMIPS). > >> >> > >> CPU: All CPU(s) started in SVC mode. > >> >> > >> rcu_node tree layout dump > >> >> > >> 0:1/0x0/0x3 ^0 > >> >> > > > >> >> > > Thank you for running this! > >> >> > > > >> >> > > OK, so RCU knows about both CPUs (the "0x3"), and the previous > >> >> > > grace period has seen quiescent states from both of them (the "0x0"). > >> >> > > That would indicate that your synchronize_sched() showed up when RCU was > >> >> > > idle, so it had to start a new grace period. It also rules out failure > >> >> > > modes where RCU thinks that there are more CPUs than really exist. > >> >> > > (Don't laugh, such things have really happened.) > >> >> > > > >> >> > >> devtmpfs: initialized > >> >> > >> VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 1 > >> >> > >> clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, > >> >> > >> max_idle_ns: 19112604462750000 ns > >> >> > >> > >> >> > >> I hope it helps. Thanks! > >> >> > > > >> >> > > I am going to guess that this was the first grace period since the second > >> >> > > CPU came online. When there only on CPU online, synchronize_sched() > >> >> > > is a no-op. > >> >> > > > >> >> > > OK, this showed some things that aren't a problem. What might the > >> >> > > problem be? > >> >> > > > >> >> > > o The grace-period kthread has not yet started. It -should- start > >> >> > > at early_initcall() time, but who knows? Adding code to print > >> >> > > out that kthread's task_struct address. > >> >> > > > >> >> > > o The grace-period kthread might not be responding to wakeups. > >> >> > > Checking this requires that a grace period be in progress, > >> >> > > so please put a call_rcu_sched() just before the call to > >> >> > > rcu_dump_rcu_node_tree(). (Sample code below.) Adding code > >> >> > > to my patch to print out more GP-kthread state as well. > >> >> > > > >> >> > > o One of the CPUs might not be responding to RCU. That -should- > >> >> > > result in an RCU CPU stall warning, so I will ignore this > >> >> > > possibility for the moment. > >> >> > > > >> >> > > That said, do you have some way to determine whether scheduling > >> >> > > clock interrupts are really happening? Without these interrupts, > >> >> > > no RCU CPU stall warnings. > >> >> > > >> >> > I believe there are no clocksources yet. The jiffies clocksource is the first > >> >> > clocksource found, and that happens after the first call to > >> >> > synchronize_sched(), cfr. my dmesg snippet above. > >> >> > > >> >> > In a working boot: > >> >> > # cat /sys/bus/clocksource/devices/clocksource0/available_clocksource > >> >> > e0180000.timer jiffies > >> >> > # cat /sys/bus/clocksource/devices/clocksource0/current_clocksource > >> >> > e0180000.timer > >> >> > >> >> Ah! But if there is no jiffies clocksource, then schedule_timeout() > >> >> and friends will never return, correct? If so, I guarantee you that > >> >> synchronize_sched() will unconditionally hang. > >> >> > >> >> So if I understand correctly, the fix is to get the jiffies clocksource > >> >> running before the first call to synchronize_sched(). > >> > > >> > If so, following change would be sufficient. > >> > > >> > Thanks. > >> > > >> > ------>8------- > >> > diff --git a/kernel/time/jiffies.c b/kernel/time/jiffies.c > >> > index 555e21f..4f6471f 100644 > >> > --- a/kernel/time/jiffies.c > >> > +++ b/kernel/time/jiffies.c > >> > @@ -98,7 +98,7 @@ static int __init init_jiffies_clocksource(void) > >> > return __clocksource_register(&clocksource_jiffies); > >> > } > >> > > >> > -core_initcall(init_jiffies_clocksource); > >> > +early_initcall(init_jiffies_clocksource); > >> > > >> > struct clocksource * __init __weak clocksource_default_clock(void) > >> > { > >> > >> Thanks for your patch! > >> > >> While this does move jiffies clocksource initialization before secondary CPU > >> bringup, it still hangs when calling call_rcu() or synchronize_sched(): > >> > >> CPU: Testing write buffer coherency: ok > >> CPU0: thread -1, cpu 0, socket 0, mpidr 80000000 > >> Setting up static identity map for 0x40100000 - 0x40100058 > >> cnt = 36, sync > >> clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, > >> max_idle_ns: 19112604462750000 ns > >> CPU1: thread -1, cpu 1, socket 0, mpidr 80000001 > >> Brought up 2 CPUs > >> SMP: Total of 2 processors activated (2132.00 BogoMIPS). > >> CPU: All CPU(s) started in SVC mode. > >> RCU: rcu_sched GP kthread: c784e1c0 state: 1 flags: 0x0 g:-300 c:-300 > >> jiffies: 0xffff8ad0 GP start: 0x0 Last GP activity: 0x0 > >> rcu_node tree layout dump > >> 0:1/0x0/0x3 ^0 > > > > This is in fact the initial state for RCU grace periods. In other words, > > all the earlier calls to synchronize_sched() likely happened while there > > was only one CPU online. > > > >> devtmpfs: initialized > >> VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 1 > > > > Could you please add the call_rcu() and timed delay as described in my > > earlier email? That would hopefully help me see the state of the stalled > > grace period. > > I already did, cfr. "it still hangs when calling call_rcu() or > synchronize_sched()". Ah, sorry for my inattention. I am a bit surprised that it could hang when calling call_rcu(), given that call_rcu() is callable from atomic contexts. Could you please show me the current test code you have? If the hang is in call_rcu(), could you please try disabling irqs across the call to call_rcu()? Thanx, Paul
diff --git a/kernel/time/jiffies.c b/kernel/time/jiffies.c index 555e21f..4f6471f 100644 --- a/kernel/time/jiffies.c +++ b/kernel/time/jiffies.c @@ -98,7 +98,7 @@ static int __init init_jiffies_clocksource(void) return __clocksource_register(&clocksource_jiffies); } -core_initcall(init_jiffies_clocksource); +early_initcall(init_jiffies_clocksource); struct clocksource * __init __weak clocksource_default_clock(void) {