Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1595543 > unrolled thread
| Started by | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| First post | 2017-03-08 23:00 +0100 |
| Last post | 2017-03-13 17:00 +0100 |
| Articles | 7 — 2 participants |
Back to article view | Back to linux.kernel
[PATCH] clock: Fix smp_processor_id() in preemptible bug "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-03-08 23:00 +0100
Re: [PATCH] clock: Fix smp_processor_id() in preemptible bug Peter Zijlstra <peterz@infradead.org> - 2017-03-09 16:30 +0100
Re: [PATCH] clock: Fix smp_processor_id() in preemptible bug "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-03-09 16:40 +0100
Re: [PATCH] clock: Fix smp_processor_id() in preemptible bug "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-03-09 19:40 +0100
Re: [PATCH] clock: Fix smp_processor_id() in preemptible bug "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-03-10 18:30 +0100
Re: [PATCH] clock: Fix smp_processor_id() in preemptible bug Peter Zijlstra <peterz@infradead.org> - 2017-03-13 13:50 +0100
Re: [PATCH] clock: Fix smp_processor_id() in preemptible bug "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-03-13 17:00 +0100
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2017-03-08 23:00 +0100 |
| Subject | [PATCH] clock: Fix smp_processor_id() in preemptible bug |
| Message-ID | <tiRMJ-3Y7-11@gated-at.bofh.it> |
The v4.11-rc1 kernel emits the following splat in some configurations:
[ 43.681891] BUG: using smp_processor_id() in preemptible [00000000] code: kworker/3:1/49
[ 43.682511] caller is debug_smp_processor_id+0x17/0x20
[ 43.682893] CPU: 0 PID: 49 Comm: kworker/3:1 Not tainted 4.11.0-rc1+ #1
[ 43.683382] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
[ 43.683497] Workqueue: events __clear_sched_clock_stable
[ 43.683497] Call Trace:
[ 43.683497] dump_stack+0x4f/0x69
[ 43.683497] check_preemption_disabled+0xd9/0xf0
[ 43.683497] debug_smp_processor_id+0x17/0x20
[ 43.683497] __clear_sched_clock_stable+0x11/0x60
[ 43.683497] process_one_work+0x146/0x430
[ 43.683497] worker_thread+0x126/0x490
[ 43.683497] kthread+0xfc/0x130
[ 43.683497] ? process_one_work+0x430/0x430
[ 43.683497] ? kthread_create_on_node+0x40/0x40
[ 43.683497] ? umh_complete+0x30/0x30
[ 43.683497] ? call_usermodehelper_exec_async+0x12a/0x130
[ 43.683497] ret_from_fork+0x29/0x40
[ 43.689244] sched_clock: Marking unstable (43688244724, 179505618)<-(43867750342, 0)
This happens because workqueue handlers run with preemption enabled
by default and the new this_scd() function accesses per-CPU variables.
This commit therefore disables preemption across this call to this_scd()
and to the uses of the pointer that it returns. Lightly tested
successfully on x86.
Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
diff --git a/kernel/sched/clock.c b/kernel/sched/clock.c
index a08795e21628..aa184bea1344 100644
--- a/kernel/sched/clock.c
+++ b/kernel/sched/clock.c
@@ -143,7 +143,7 @@ static void __set_sched_clock_stable(void)
static void __clear_sched_clock_stable(struct work_struct *work)
{
- struct sched_clock_data *scd = this_scd();
+ struct sched_clock_data *scd;
/*
* Attempt to make the stable->unstable transition continuous.
@@ -154,7 +154,10 @@ static void __clear_sched_clock_stable(struct work_struct *work)
*
* Still do what we can.
*/
+ preempt_disable();
+ scd = this_scd();
gtod_offset = (scd->tick_raw + raw_offset) - (scd->tick_gtod);
+ preempt_enable();
printk(KERN_INFO "sched_clock: Marking unstable (%lld, %lld)<-(%lld, %lld)\n",
scd->tick_gtod, gtod_offset,
[toc] | [next] | [standalone]
| From | Peter Zijlstra <peterz@infradead.org> |
|---|---|
| Date | 2017-03-09 16:30 +0100 |
| Message-ID | <tj8aR-71c-9@gated-at.bofh.it> |
| In reply to | #1595543 |
On Wed, Mar 08, 2017 at 01:53:06PM -0800, Paul E. McKenney wrote: > The v4.11-rc1 kernel emits the following splat in some configurations: > > [ 43.681891] BUG: using smp_processor_id() in preemptible [00000000] code: kworker/3:1/49 > [ 43.682511] caller is debug_smp_processor_id+0x17/0x20 > [ 43.682893] CPU: 0 PID: 49 Comm: kworker/3:1 Not tainted 4.11.0-rc1+ #1 > [ 43.683382] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011 > [ 43.683497] Workqueue: events __clear_sched_clock_stable > [ 43.683497] Call Trace: > [ 43.683497] dump_stack+0x4f/0x69 > [ 43.683497] check_preemption_disabled+0xd9/0xf0 > [ 43.683497] debug_smp_processor_id+0x17/0x20 > [ 43.683497] __clear_sched_clock_stable+0x11/0x60 > [ 43.683497] process_one_work+0x146/0x430 > [ 43.683497] worker_thread+0x126/0x490 > [ 43.683497] kthread+0xfc/0x130 > [ 43.683497] ? process_one_work+0x430/0x430 > [ 43.683497] ? kthread_create_on_node+0x40/0x40 > [ 43.683497] ? umh_complete+0x30/0x30 > [ 43.683497] ? call_usermodehelper_exec_async+0x12a/0x130 > [ 43.683497] ret_from_fork+0x29/0x40 > [ 43.689244] sched_clock: Marking unstable (43688244724, 179505618)<-(43867750342, 0) > > This happens because workqueue handlers run with preemption enabled > by default and the new this_scd() function accesses per-CPU variables. > This commit therefore disables preemption across this call to this_scd() > and to the uses of the pointer that it returns. Lightly tested > successfully on x86. Does this also work? --- kernel/sched/clock.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/kernel/sched/clock.c b/kernel/sched/clock.c index a08795e21628..c63042253b65 100644 --- a/kernel/sched/clock.c +++ b/kernel/sched/clock.c @@ -173,7 +173,7 @@ void clear_sched_clock_stable(void) smp_mb(); /* matches sched_clock_init_late() */ if (sched_clock_running == 2) - schedule_work(&sched_clock_work); + schedule_work_on(smp_processor_id(), &sched_clock_work); } void sched_clock_init_late(void)
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2017-03-09 16:40 +0100 |
| Message-ID | <tj8kx-76H-1@gated-at.bofh.it> |
| In reply to | #1596153 |
On Thu, Mar 09, 2017 at 04:24:20PM +0100, Peter Zijlstra wrote: > On Wed, Mar 08, 2017 at 01:53:06PM -0800, Paul E. McKenney wrote: > > The v4.11-rc1 kernel emits the following splat in some configurations: > > > > [ 43.681891] BUG: using smp_processor_id() in preemptible [00000000] code: kworker/3:1/49 > > [ 43.682511] caller is debug_smp_processor_id+0x17/0x20 > > [ 43.682893] CPU: 0 PID: 49 Comm: kworker/3:1 Not tainted 4.11.0-rc1+ #1 > > [ 43.683382] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011 > > [ 43.683497] Workqueue: events __clear_sched_clock_stable > > [ 43.683497] Call Trace: > > [ 43.683497] dump_stack+0x4f/0x69 > > [ 43.683497] check_preemption_disabled+0xd9/0xf0 > > [ 43.683497] debug_smp_processor_id+0x17/0x20 > > [ 43.683497] __clear_sched_clock_stable+0x11/0x60 > > [ 43.683497] process_one_work+0x146/0x430 > > [ 43.683497] worker_thread+0x126/0x490 > > [ 43.683497] kthread+0xfc/0x130 > > [ 43.683497] ? process_one_work+0x430/0x430 > > [ 43.683497] ? kthread_create_on_node+0x40/0x40 > > [ 43.683497] ? umh_complete+0x30/0x30 > > [ 43.683497] ? call_usermodehelper_exec_async+0x12a/0x130 > > [ 43.683497] ret_from_fork+0x29/0x40 > > [ 43.689244] sched_clock: Marking unstable (43688244724, 179505618)<-(43867750342, 0) > > > > This happens because workqueue handlers run with preemption enabled > > by default and the new this_scd() function accesses per-CPU variables. > > This commit therefore disables preemption across this call to this_scd() > > and to the uses of the pointer that it returns. Lightly tested > > successfully on x86. > > Does this also work? Thank you! I will give it a shot after the other tests complete. > --- > kernel/sched/clock.c | 2 +- > 1 file changed, 1 insertion(+), 1 deletion(-) > > diff --git a/kernel/sched/clock.c b/kernel/sched/clock.c > index a08795e21628..c63042253b65 100644 > --- a/kernel/sched/clock.c > +++ b/kernel/sched/clock.c > @@ -173,7 +173,7 @@ void clear_sched_clock_stable(void) > smp_mb(); /* matches sched_clock_init_late() */ > > if (sched_clock_running == 2) > - schedule_work(&sched_clock_work); > + schedule_work_on(smp_processor_id(), &sched_clock_work); > } > > void sched_clock_init_late(void) >
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2017-03-09 19:40 +0100 |
| Message-ID | <tjb8J-yF-5@gated-at.bofh.it> |
| In reply to | #1596155 |
On Thu, Mar 09, 2017 at 07:31:14AM -0800, Paul E. McKenney wrote: > On Thu, Mar 09, 2017 at 04:24:20PM +0100, Peter Zijlstra wrote: > > On Wed, Mar 08, 2017 at 01:53:06PM -0800, Paul E. McKenney wrote: > > > The v4.11-rc1 kernel emits the following splat in some configurations: > > > > > > [ 43.681891] BUG: using smp_processor_id() in preemptible [00000000] code: kworker/3:1/49 > > > [ 43.682511] caller is debug_smp_processor_id+0x17/0x20 > > > [ 43.682893] CPU: 0 PID: 49 Comm: kworker/3:1 Not tainted 4.11.0-rc1+ #1 > > > [ 43.683382] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011 > > > [ 43.683497] Workqueue: events __clear_sched_clock_stable > > > [ 43.683497] Call Trace: > > > [ 43.683497] dump_stack+0x4f/0x69 > > > [ 43.683497] check_preemption_disabled+0xd9/0xf0 > > > [ 43.683497] debug_smp_processor_id+0x17/0x20 > > > [ 43.683497] __clear_sched_clock_stable+0x11/0x60 > > > [ 43.683497] process_one_work+0x146/0x430 > > > [ 43.683497] worker_thread+0x126/0x490 > > > [ 43.683497] kthread+0xfc/0x130 > > > [ 43.683497] ? process_one_work+0x430/0x430 > > > [ 43.683497] ? kthread_create_on_node+0x40/0x40 > > > [ 43.683497] ? umh_complete+0x30/0x30 > > > [ 43.683497] ? call_usermodehelper_exec_async+0x12a/0x130 > > > [ 43.683497] ret_from_fork+0x29/0x40 > > > [ 43.689244] sched_clock: Marking unstable (43688244724, 179505618)<-(43867750342, 0) > > > > > > This happens because workqueue handlers run with preemption enabled > > > by default and the new this_scd() function accesses per-CPU variables. > > > This commit therefore disables preemption across this call to this_scd() > > > and to the uses of the pointer that it returns. Lightly tested > > > successfully on x86. > > > > Does this also work? > > Thank you! I will give it a shot after the other tests complete. And it does pass light testing. I will hammer it harder this evening. So please send a formal patch! Thanx, Paul > > --- > > kernel/sched/clock.c | 2 +- > > 1 file changed, 1 insertion(+), 1 deletion(-) > > > > diff --git a/kernel/sched/clock.c b/kernel/sched/clock.c > > index a08795e21628..c63042253b65 100644 > > --- a/kernel/sched/clock.c > > +++ b/kernel/sched/clock.c > > @@ -173,7 +173,7 @@ void clear_sched_clock_stable(void) > > smp_mb(); /* matches sched_clock_init_late() */ > > > > if (sched_clock_running == 2) > > - schedule_work(&sched_clock_work); > > + schedule_work_on(smp_processor_id(), &sched_clock_work); > > } > > > > void sched_clock_init_late(void) > >
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2017-03-10 18:30 +0100 |
| Message-ID | <tjwwy-79v-9@gated-at.bofh.it> |
| In reply to | #1596303 |
On Thu, Mar 09, 2017 at 10:37:32AM -0800, Paul E. McKenney wrote:
> On Thu, Mar 09, 2017 at 07:31:14AM -0800, Paul E. McKenney wrote:
> > On Thu, Mar 09, 2017 at 04:24:20PM +0100, Peter Zijlstra wrote:
> > > On Wed, Mar 08, 2017 at 01:53:06PM -0800, Paul E. McKenney wrote:
> > > > The v4.11-rc1 kernel emits the following splat in some configurations:
> > > >
> > > > [ 43.681891] BUG: using smp_processor_id() in preemptible [00000000] code: kworker/3:1/49
> > > > [ 43.682511] caller is debug_smp_processor_id+0x17/0x20
> > > > [ 43.682893] CPU: 0 PID: 49 Comm: kworker/3:1 Not tainted 4.11.0-rc1+ #1
> > > > [ 43.683382] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
> > > > [ 43.683497] Workqueue: events __clear_sched_clock_stable
> > > > [ 43.683497] Call Trace:
> > > > [ 43.683497] dump_stack+0x4f/0x69
> > > > [ 43.683497] check_preemption_disabled+0xd9/0xf0
> > > > [ 43.683497] debug_smp_processor_id+0x17/0x20
> > > > [ 43.683497] __clear_sched_clock_stable+0x11/0x60
> > > > [ 43.683497] process_one_work+0x146/0x430
> > > > [ 43.683497] worker_thread+0x126/0x490
> > > > [ 43.683497] kthread+0xfc/0x130
> > > > [ 43.683497] ? process_one_work+0x430/0x430
> > > > [ 43.683497] ? kthread_create_on_node+0x40/0x40
> > > > [ 43.683497] ? umh_complete+0x30/0x30
> > > > [ 43.683497] ? call_usermodehelper_exec_async+0x12a/0x130
> > > > [ 43.683497] ret_from_fork+0x29/0x40
> > > > [ 43.689244] sched_clock: Marking unstable (43688244724, 179505618)<-(43867750342, 0)
> > > >
> > > > This happens because workqueue handlers run with preemption enabled
> > > > by default and the new this_scd() function accesses per-CPU variables.
> > > > This commit therefore disables preemption across this call to this_scd()
> > > > and to the uses of the pointer that it returns. Lightly tested
> > > > successfully on x86.
> > >
> > > Does this also work?
> >
> > Thank you! I will give it a shot after the other tests complete.
>
> And it does pass light testing. I will hammer it harder this evening.
>
> So please send a formal patch!
And the diffs below passed overnight testing, so:
Tested-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
------------------------------------------------------------------------
commit e87df240b9e6a24635a1c8674f715554f27df6cc
Author: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
Date: Thu Mar 9 07:51:25 2017 -0800
EXPERIMENTAL: Peter Zijlstra hotplug fix
Not-signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
diff --git a/kernel/sched/clock.c b/kernel/sched/clock.c
index a08795e21628..1560d5f961ef 100644
--- a/kernel/sched/clock.c
+++ b/kernel/sched/clock.c
@@ -172,8 +172,8 @@ void clear_sched_clock_stable(void)
smp_mb(); /* matches sched_clock_init_late() */
- if (sched_clock_running == 2)
- schedule_work(&sched_clock_work);
+ if (sched_clock_running == 2 && sched_clock_stable())
+ schedule_work_on(smp_processor_id(), &sched_clock_work);
}
void sched_clock_init_late(void)
[toc] | [prev] | [next] | [standalone]
| From | Peter Zijlstra <peterz@infradead.org> |
|---|---|
| Date | 2017-03-13 13:50 +0100 |
| Message-ID | <tkxAe-ys-27@gated-at.bofh.it> |
| In reply to | #1596303 |
On Thu, Mar 09, 2017 at 10:37:32AM -0800, Paul E. McKenney wrote:
> And it does pass light testing. I will hammer it harder this evening.
>
> So please send a formal patch!
Changed it a bit...
---
Subject: sched/clock: Some clear_sched_clock_stable() vs hotplug wobbles
Paul reported two independent problems with clear_sched_clock_stable().
- if we tickle it during hotplug (even though the sched_clock was
already marked unstable) we'll attempt to schedule_work() and
this explodes because RCU isn't watching the new CPU quite yet.
- since we run all of __clear_sched_clock_stable() from workqueue
context, there's a preempt problem.
Cure both by only doing the static_branch_disable() from a workqueue,
and only when it's still stable.
This leaves the problem what to do about hotplug actually wrecking TSC
though, because if it was stable and now isn't, then we will want to run
that work, which then will prod RCU the wrong way. Bloody hotplug.
Reported-by: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
---
kernel/sched/clock.c | 17 ++++++++++++-----
1 file changed, 12 insertions(+), 5 deletions(-)
diff --git a/kernel/sched/clock.c b/kernel/sched/clock.c
index a08795e21628..fec0f58c8dee 100644
--- a/kernel/sched/clock.c
+++ b/kernel/sched/clock.c
@@ -141,7 +141,14 @@ static void __set_sched_clock_stable(void)
tick_dep_clear(TICK_DEP_BIT_CLOCK_UNSTABLE);
}
-static void __clear_sched_clock_stable(struct work_struct *work)
+static void __sched_clock_work(struct work_struct *work)
+{
+ static_branch_disable(&__sched_clock_stable);
+}
+
+static DECLARE_WORK(sched_clock_work, __sched_clock_work);
+
+static void __clear_sched_clock_stable(void)
{
struct sched_clock_data *scd = this_scd();
@@ -160,11 +167,11 @@ static void __clear_sched_clock_stable(struct work_struct *work)
scd->tick_gtod, gtod_offset,
scd->tick_raw, raw_offset);
- static_branch_disable(&__sched_clock_stable);
tick_dep_set(TICK_DEP_BIT_CLOCK_UNSTABLE);
-}
-static DECLARE_WORK(sched_clock_work, __clear_sched_clock_stable);
+ if (sched_clock_stable())
+ schedule_work(&sched_clock_work);
+}
void clear_sched_clock_stable(void)
{
@@ -173,7 +180,7 @@ void clear_sched_clock_stable(void)
smp_mb(); /* matches sched_clock_init_late() */
if (sched_clock_running == 2)
- schedule_work(&sched_clock_work);
+ __clear_sched_clock_stable();
}
void sched_clock_init_late(void)
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2017-03-13 17:00 +0100 |
| Message-ID | <tkAy5-2Gl-7@gated-at.bofh.it> |
| In reply to | #1599301 |
On Mon, Mar 13, 2017 at 01:46:21PM +0100, Peter Zijlstra wrote:
> On Thu, Mar 09, 2017 at 10:37:32AM -0800, Paul E. McKenney wrote:
> > And it does pass light testing. I will hammer it harder this evening.
> >
> > So please send a formal patch!
>
> Changed it a bit...
>
> ---
> Subject: sched/clock: Some clear_sched_clock_stable() vs hotplug wobbles
>
> Paul reported two independent problems with clear_sched_clock_stable().
>
> - if we tickle it during hotplug (even though the sched_clock was
> already marked unstable) we'll attempt to schedule_work() and
> this explodes because RCU isn't watching the new CPU quite yet.
>
> - since we run all of __clear_sched_clock_stable() from workqueue
> context, there's a preempt problem.
>
> Cure both by only doing the static_branch_disable() from a workqueue,
> and only when it's still stable.
>
> This leaves the problem what to do about hotplug actually wrecking TSC
> though, because if it was stable and now isn't, then we will want to run
> that work, which then will prod RCU the wrong way. Bloody hotplug.
>
> Reported-by: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
> Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
This passes initial testing. I will hammer it harder overnight, but
in the meantime:
Tested-by: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
> ---
> kernel/sched/clock.c | 17 ++++++++++++-----
> 1 file changed, 12 insertions(+), 5 deletions(-)
>
> diff --git a/kernel/sched/clock.c b/kernel/sched/clock.c
> index a08795e21628..fec0f58c8dee 100644
> --- a/kernel/sched/clock.c
> +++ b/kernel/sched/clock.c
> @@ -141,7 +141,14 @@ static void __set_sched_clock_stable(void)
> tick_dep_clear(TICK_DEP_BIT_CLOCK_UNSTABLE);
> }
>
> -static void __clear_sched_clock_stable(struct work_struct *work)
> +static void __sched_clock_work(struct work_struct *work)
> +{
> + static_branch_disable(&__sched_clock_stable);
> +}
> +
> +static DECLARE_WORK(sched_clock_work, __sched_clock_work);
> +
> +static void __clear_sched_clock_stable(void)
> {
> struct sched_clock_data *scd = this_scd();
>
> @@ -160,11 +167,11 @@ static void __clear_sched_clock_stable(struct work_struct *work)
> scd->tick_gtod, gtod_offset,
> scd->tick_raw, raw_offset);
>
> - static_branch_disable(&__sched_clock_stable);
> tick_dep_set(TICK_DEP_BIT_CLOCK_UNSTABLE);
> -}
>
> -static DECLARE_WORK(sched_clock_work, __clear_sched_clock_stable);
> + if (sched_clock_stable())
> + schedule_work(&sched_clock_work);
> +}
>
> void clear_sched_clock_stable(void)
> {
> @@ -173,7 +180,7 @@ void clear_sched_clock_stable(void)
> smp_mb(); /* matches sched_clock_init_late() */
>
> if (sched_clock_running == 2)
> - schedule_work(&sched_clock_work);
> + __clear_sched_clock_stable();
> }
>
> void sched_clock_init_late(void)
>
[toc] | [prev] | [standalone]
Back to top | Article view | linux.kernel
csiph-web