Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1418182 > unrolled thread
| Started by | Chris Wilson <chris@chris-wilson.co.uk> |
|---|---|
| First post | 2016-06-09 11:10 +0200 |
| Last post | 2016-06-09 12:40 +0200 |
| Articles | 4 — 3 participants |
Back to article view | Back to linux.kernel
Divide-by-zero in post_init_entity_util_avg Chris Wilson <chris@chris-wilson.co.uk> - 2016-06-09 11:10 +0200
Re: Divide-by-zero in post_init_entity_util_avg Yuyang Du <yuyang.du@intel.com> - 2016-06-09 11:40 +0200
Re: Divide-by-zero in post_init_entity_util_avg Peter Zijlstra <peterz@infradead.org> - 2016-06-09 15:10 +0200
Re: Divide-by-zero in post_init_entity_util_avg Peter Zijlstra <peterz@infradead.org> - 2016-06-09 12:40 +0200
| From | Chris Wilson <chris@chris-wilson.co.uk> |
|---|---|
| Date | 2016-06-09 11:10 +0200 |
| Subject | Divide-by-zero in post_init_entity_util_avg |
| Message-ID | <rI48p-4md-3@gated-at.bofh.it> |
[15774.966082] divide error: 0000 [#1] SMP
[15774.966137] Modules linked in: i915 intel_gtt
[15774.966208] CPU: 1 PID: 15319 Comm: gemscript Not tainted 4.7.0-rc1+ #330
[15774.966252] Hardware name: /NUC5CPYB, BIOS PYBSWCEL.86A.0027.2015.0507.1758 05/07/2015
[15774.966317] task: ffff880276a55e80 ti: ffff880272c10000 task.ti: ffff880272c10000
[15774.966377] RIP: 0010:[<ffffffff810b12e3>] [<ffffffff810b12e3>] post_init_entity_util_avg+0x43/0x80
[15774.966463] RSP: 0018:ffff880272c13e30 EFLAGS: 00010057
[15774.966504] RAX: 0000000022f00000 RBX: ffff880276a51f80 RCX: 00000000000000e8
[15774.966550] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff880276a52000
[15774.966593] RBP: ffff880272c13e30 R08: 0000000000000000 R09: 0000000000000008
[15774.966635] R10: 0000000000000000 R11: 0000000000000000 R12: ffff880276a52544
[15774.966678] R13: ffff880276a52000 R14: ffff880276a521d8 R15: 0000000000003bda
[15774.966721] FS: 00007fe4df95a740(0000) GS:ffff88027fd00000(0000) knlGS:0000000000000000
[15774.966781] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[15774.966822] CR2: 00007fe4de7f0378 CR3: 0000000275e15000 CR4: 00000000001006e0
[15774.966860] Stack:
[15774.966894] ffff880272c13e68 ffffffff810a69c5 0000000000000206 0000000000003bd7
[15774.966987] 0000000000000000 0000000000000000 ffff880276a51f80 ffff880272c13ee8
[15774.967073] ffffffff8107a364 0000000000003bd7 ffffffffffffffff 0000000000000000
[15774.967162] Call Trace:
[15774.967208] [<ffffffff810a69c5>] wake_up_new_task+0x95/0x130
[15774.967256] [<ffffffff8107a364>] _do_fork+0x184/0x400
[15774.967302] [<ffffffff8107a6b7>] SyS_clone+0x37/0x50
[15774.967353] [<ffffffff8100197d>] do_syscall_64+0x5d/0xe0
[15774.967402] [<ffffffff815719bc>] entry_SYSCALL64_slow_path+0x25/0x25
[15774.967444] Code: 89 d1 48 c1 e9 3f 48 01 d1 48 d1 f9 48 85 c9 7e 38 48 85 c0 74 35 48 0f af 07 31 d2 48 89 87 e0 00 00 00 48 8b 76 70 48 83 c6 01 <48> f7 f6 48 39 c8 77 18 48 89 c1 48 89 87 e0 00 00 00 69 c9 7e
[15774.968086] RIP [<ffffffff810b12e3>] post_init_entity_util_avg+0x43/0x80
[15774.968142] RSP <ffff880272c13e30>
I've presumed commit 2b8c41daba327 ("sched/fair: Initiate a new task's
util avg to a bounded value") to be at fault, hence the CCs. Though it
may just be a victim.
gdb says 0x43/0x80 is
725 if (cfs_rq->avg.util_avg != 0) {
726 sa->util_avg = cfs_rq->avg.util_avg * se->load.weight;
-> 727 sa->util_avg /= (cfs_rq->avg.load_avg + 1);
728
729 if (sa->util_avg > cap)
730 sa->util_avg = cap;
731 } else {
I've run the same fork-heavy workload that seemed to hit the initial
fault under kasan. kasan has not reported any errors, nor has the bug
reoccurred after a day (earlier I had a couple of panics within a few
hours).
Is it possible for a race window where cfg_rq->avg.load_avg is indeed
-1? Any evidence of other memcorruption in the above?
-Chris
--
Chris Wilson, Intel Open Source Technology Centre
[toc] | [next] | [standalone]
| From | Yuyang Du <yuyang.du@intel.com> |
|---|---|
| Date | 2016-06-09 11:40 +0200 |
| Message-ID | <rI4Br-4w8-7@gated-at.bofh.it> |
| In reply to | #1418182 |
On Thu, Jun 09, 2016 at 10:01:42AM +0100, Chris Wilson wrote:
> I've presumed commit 2b8c41daba327 ("sched/fair: Initiate a new task's
> util avg to a bounded value") to be at fault, hence the CCs. Though it
> may just be a victim.
>
> gdb says 0x43/0x80 is
>
> 725 if (cfs_rq->avg.util_avg != 0) {
> 726 sa->util_avg = cfs_rq->avg.util_avg * se->load.weight;
> -> 727 sa->util_avg /= (cfs_rq->avg.load_avg + 1);
> 728
> 729 if (sa->util_avg > cap)
> 730 sa->util_avg = cap;
> 731 } else {
>
> I've run the same fork-heavy workload that seemed to hit the initial
> fault under kasan. kasan has not reported any errors, nor has the bug
> reoccurred after a day (earlier I had a couple of panics within a few
> hours).
>
> Is it possible for a race window where cfg_rq->avg.load_avg is indeed
> -1? Any evidence of other memcorruption in the above?
-1 should not be possible, sounds like a soft error.
But, a race is anyway hazardous. Thanks a lot, Chris.
--
Subject: [PATCH] sched/fair: Avoid hazardous reading cfs_rq->avg.load_avg
without rq lock
The commit 2b8c41daba327 ("sched/fair: Initiate a new task's util avg
to a bounded value") references cfs_rq->avg.load_avg and then the value
is used as a divisor (actually cfs_rq->avg.load_avg + 1).
This race condition may cause a divide-by-zero exception. Fix it by
moving it into rq locked section.
Reported-by: Chris Wilson <chris@chris-wilson.co.uk>
Signed-off-by: Yuyang Du <yuyang.du@intel.com>
---
kernel/sched/core.c | 3 +--
1 file changed, 1 insertion(+), 2 deletions(-)
diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 385c947..b9f44df 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -2535,10 +2535,9 @@ void wake_up_new_task(struct task_struct *p)
*/
set_task_cpu(p, select_task_rq(p, task_cpu(p), SD_BALANCE_FORK, 0));
#endif
+ rq = __task_rq_lock(p, &rf);
/* Post initialize new task's util average when its cfs_rq is set */
post_init_entity_util_avg(&p->se);
-
- rq = __task_rq_lock(p, &rf);
activate_task(rq, p, 0);
p->on_rq = TASK_ON_RQ_QUEUED;
trace_sched_wakeup_new(p);
--
[toc] | [prev] | [next] | [standalone]
| From | Peter Zijlstra <peterz@infradead.org> |
|---|---|
| Date | 2016-06-09 15:10 +0200 |
| Message-ID | <rI7SG-6NK-23@gated-at.bofh.it> |
| In reply to | #1418192 |
Chris Wilson reported a divide by 0 at:
post_init_entity_util_avg():
> 725 if (cfs_rq->avg.util_avg != 0) {
> 726 sa->util_avg = cfs_rq->avg.util_avg * se->load.weight;
> -> 727 sa->util_avg /= (cfs_rq->avg.load_avg + 1);
> 728
> 729 if (sa->util_avg > cap)
> 730 sa->util_avg = cap;
> 731 } else {
Which given the lack of serialization, and the code generated from
update_cfs_rq_load_avg() is entirely possible.
if (atomic_long_read(&cfs_rq->removed_load_avg)) {
s64 r = atomic_long_xchg(&cfs_rq->removed_load_avg, 0);
sa->load_avg = max_t(long, sa->load_avg - r, 0);
sa->load_sum = max_t(s64, sa->load_sum - r * LOAD_AVG_MAX, 0);
removed_load = 1;
}
turns into:
ffffffff81087064: 49 8b 85 98 00 00 00 mov 0x98(%r13),%rax
ffffffff8108706b: 48 85 c0 test %rax,%rax
ffffffff8108706e: 74 40 je ffffffff810870b0 <update_blocked_averages+0xc0>
ffffffff81087070: 4c 89 f8 mov %r15,%rax
ffffffff81087073: 49 87 85 98 00 00 00 xchg %rax,0x98(%r13)
ffffffff8108707a: 49 29 45 70 sub %rax,0x70(%r13)
ffffffff8108707e: 4c 89 f9 mov %r15,%rcx
ffffffff81087081: bb 01 00 00 00 mov $0x1,%ebx
ffffffff81087086: 49 83 7d 70 00 cmpq $0x0,0x70(%r13)
ffffffff8108708b: 49 0f 49 4d 70 cmovns 0x70(%r13),%rcx
Which you'll note ends up with sa->load_avg -= r in memory at
ffffffff8108707a.
Ludicrous code generation if you ask me; I'd have expected something
like (note, r15 holds 0):
mov %r15, %rax
xchg %rax, cfs_rq->removed_load_avg
mov sa->load_avg, %rcx
sub %rax, %rcx
cmovs %r15, %rcx
mov %rcx, sa->load_avg
Adding the serialization (to _both_ call sites) should fix this.
Fixes: 2b8c41daba32 ("sched/fair: Initiate a new task's util avg to a bounded value")
Reported-by: Chris Wilson <chris@chris-wilson.co.uk>
Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
---
kernel/sched/core.c | 3 +--
kernel/sched/fair.c | 8 +++++++-
2 files changed, 8 insertions(+), 3 deletions(-)
diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 385c947482e1..4aff10e3bd14 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -2535,10 +2535,9 @@ void wake_up_new_task(struct task_struct *p)
*/
set_task_cpu(p, select_task_rq(p, task_cpu(p), SD_BALANCE_FORK, 0));
#endif
- /* Post initialize new task's util average when its cfs_rq is set */
+ rq = __task_rq_lock(p, &rf);
post_init_entity_util_avg(&p->se);
- rq = __task_rq_lock(p, &rf);
activate_task(rq, p, 0);
p->on_rq = TASK_ON_RQ_QUEUED;
trace_sched_wakeup_new(p);
diff --git a/kernel/sched/fair.c b/kernel/sched/fair.c
index c6dd8bab010c..f379da14c7dd 100644
--- a/kernel/sched/fair.c
+++ b/kernel/sched/fair.c
@@ -8468,8 +8468,9 @@ void free_fair_sched_group(struct task_group *tg)
int alloc_fair_sched_group(struct task_group *tg, struct task_group *parent)
{
- struct cfs_rq *cfs_rq;
struct sched_entity *se;
+ struct cfs_rq *cfs_rq;
+ struct rq *rq;
int i;
tg->cfs_rq = kzalloc(sizeof(cfs_rq) * nr_cpu_ids, GFP_KERNEL);
@@ -8484,6 +8485,8 @@ int alloc_fair_sched_group(struct task_group *tg, struct task_group *parent)
init_cfs_bandwidth(tg_cfs_bandwidth(tg));
for_each_possible_cpu(i) {
+ rq = cpu_rq(i);
+
cfs_rq = kzalloc_node(sizeof(struct cfs_rq),
GFP_KERNEL, cpu_to_node(i));
if (!cfs_rq)
@@ -8497,7 +8500,10 @@ int alloc_fair_sched_group(struct task_group *tg, struct task_group *parent)
init_cfs_rq(cfs_rq);
init_tg_cfs_entry(tg, cfs_rq, se, i, parent->se[i]);
init_entity_runnable_average(se);
+
+ raw_spin_lock_irq(&rq->lock);
post_init_entity_util_avg(se);
+ raw_spin_unlock_irq(&rq->lock);
}
return 1;
[toc] | [prev] | [next] | [standalone]
| From | Peter Zijlstra <peterz@infradead.org> |
|---|---|
| Date | 2016-06-09 12:40 +0200 |
| Message-ID | <rI5xw-579-13@gated-at.bofh.it> |
| In reply to | #1418182 |
On Thu, Jun 09, 2016 at 10:01:42AM +0100, Chris Wilson wrote:
>
> [15774.966082] divide error: 0000 [#1] SMP
> [15774.966137] Modules linked in: i915 intel_gtt
> [15774.966208] CPU: 1 PID: 15319 Comm: gemscript Not tainted 4.7.0-rc1+ #330
> [15774.966252] Hardware name: /NUC5CPYB, BIOS PYBSWCEL.86A.0027.2015.0507.1758 05/07/2015
> [15774.966317] task: ffff880276a55e80 ti: ffff880272c10000 task.ti: ffff880272c10000
> [15774.966377] RIP: 0010:[<ffffffff810b12e3>] [<ffffffff810b12e3>] post_init_entity_util_avg+0x43/0x80
> [15774.966463] RSP: 0018:ffff880272c13e30 EFLAGS: 00010057
> [15774.966504] RAX: 0000000022f00000 RBX: ffff880276a51f80 RCX: 00000000000000e8
> [15774.966550] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff880276a52000
> [15774.966593] RBP: ffff880272c13e30 R08: 0000000000000000 R09: 0000000000000008
> [15774.966635] R10: 0000000000000000 R11: 0000000000000000 R12: ffff880276a52544
> [15774.966678] R13: ffff880276a52000 R14: ffff880276a521d8 R15: 0000000000003bda
> [15774.966721] FS: 00007fe4df95a740(0000) GS:ffff88027fd00000(0000) knlGS:0000000000000000
> [15774.966781] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [15774.966822] CR2: 00007fe4de7f0378 CR3: 0000000275e15000 CR4: 00000000001006e0
> [15774.966860] Stack:
> [15774.966894] ffff880272c13e68 ffffffff810a69c5 0000000000000206 0000000000003bd7
> [15774.966987] 0000000000000000 0000000000000000 ffff880276a51f80 ffff880272c13ee8
> [15774.967073] ffffffff8107a364 0000000000003bd7 ffffffffffffffff 0000000000000000
> [15774.967162] Call Trace:
> [15774.967208] [<ffffffff810a69c5>] wake_up_new_task+0x95/0x130
> [15774.967256] [<ffffffff8107a364>] _do_fork+0x184/0x400
> [15774.967302] [<ffffffff8107a6b7>] SyS_clone+0x37/0x50
> [15774.967353] [<ffffffff8100197d>] do_syscall_64+0x5d/0xe0
> [15774.967402] [<ffffffff815719bc>] entry_SYSCALL64_slow_path+0x25/0x25
> [15774.967444] Code: 89 d1 48 c1 e9 3f 48 01 d1 48 d1 f9 48 85 c9 7e 38 48 85 c0 74 35 48 0f af 07 31 d2 48 89 87 e0 00 00 00 48 8b 76 70 48 83 c6 01 <48> f7 f6 48 39 c8 77 18 48 89 c1 48 89 87 e0 00 00 00 69 c9 7e
> [15774.968086] RIP [<ffffffff810b12e3>] post_init_entity_util_avg+0x43/0x80
> [15774.968142] RSP <ffff880272c13e30>
>
> I've presumed commit 2b8c41daba327 ("sched/fair: Initiate a new task's
> util avg to a bounded value") to be at fault, hence the CCs. Though it
> may just be a victim.
>
> gdb says 0x43/0x80 is
>
> 725 if (cfs_rq->avg.util_avg != 0) {
> 726 sa->util_avg = cfs_rq->avg.util_avg * se->load.weight;
> -> 727 sa->util_avg /= (cfs_rq->avg.load_avg + 1);
> 728
> 729 if (sa->util_avg > cap)
> 730 sa->util_avg = cap;
> 731 } else {
>
> I've run the same fork-heavy workload that seemed to hit the initial
> fault under kasan. kasan has not reported any errors, nor has the bug
> reoccurred after a day (earlier I had a couple of panics within a few
> hours).
>
> Is it possible for a race window where cfg_rq->avg.load_avg is indeed
> -1? Any evidence of other memcorruption in the above?
> -Chris
Maybe; I need to look harder and at the generated code; but at the very
least serialization isn't right.
We compute/update averages under rq->lock, but post_init_entity_avg()
looks at these values without holding it.
Something like the below should cure that, something similar should
probably be done for the other callsite as well, I'll look harder after
lunch.
diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 385c947482e1..289d99d91883 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -2536,9 +2536,9 @@ void wake_up_new_task(struct task_struct *p)
set_task_cpu(p, select_task_rq(p, task_cpu(p), SD_BALANCE_FORK, 0));
#endif
/* Post initialize new task's util average when its cfs_rq is set */
- post_init_entity_util_avg(&p->se);
rq = __task_rq_lock(p, &rf);
+ post_init_entity_util_avg(&p->se);
activate_task(rq, p, 0);
p->on_rq = TASK_ON_RQ_QUEUED;
trace_sched_wakeup_new(p);
[toc] | [prev] | [standalone]
Back to top | Article view | linux.kernel
csiph-web