WARN ON at kernel/sched/deadline.c task_non_contending

From: chengjian (D)
Date: Mon Mar 11 2019 - 22:03:34 EST

Next message: Arnaldo Carvalho de Melo: "[PATCH 20/30] tools headers uapi: Sync copy of asm-generic/unistd.h with the kernel sources"
Previous message: Arnaldo Carvalho de Melo: "[PATCH 18/30] perf script python: Add printdate function to SQL exporters"
Next in thread: luca abeni: "Re: WARN ON at kernel/sched/deadline.c task_non_contending"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Hi.

When looking to test SCHED_DEADLINE syzkaller report an warn in
task_non_contending(). I tested the mainline kernel with the C program
and captured the same call trace.

[The previous message contains some strings in other formats,

making the mail less readable. So I resend it. SORRY.]

[Â 948.126369] WARNING: CPU: 4 PID: 17089 at kernel/sched/deadline.c:255 task_non_contending+0xae0/0x1950
[Â 948.130198] Kernel panic - not syncing: panic_on_warn set ...
[Â 948.130198]
[Â 948.134221] CPU: 4 PID: 17089 Comm: syz-executor.1 Not tainted 4.19.27 #2
[Â 948.139072] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1ubuntu1 04/01/2014
[Â 948.141603] Call Trace:
[Â 948.142277]Â dump_stack+0xca/0x13e
[Â 948.164636]Â panic+0x1f7/0x543
[Â 948.168704]Â ? refcount_error_report+0x29d/0x29d
[Â 948.172438]Â ? __warn+0x1d1/0x210
[Â 948.183359]Â ? task_non_contending+0xae0/0x1950
[Â 948.191747]Â __warn+0x1ec/0x210
[Â 948.196276]Â ? task_non_contending+0xae0/0x1950
[Â 948.202476]Â report_bug+0x1ee/0x2b0
[Â 948.204622]Â fixup_bug.part.7+0x37/0x80
[Â 948.206879]Â do_error_trap+0x22c/0x290
[Â 948.211340]Â ? math_error+0x2f0/0x2f0
[Â 948.217033]Â ? trace_hardirqs_off_caller+0x40/0x190
[Â 948.222477]Â ? trace_hardirqs_off_thunk+0x1a/0x1c
[Â 948.229877]Â invalid_op+0x14/0x20
[Â 948.238317] RIP: 0010:task_non_contending+0xae0/0x1950
[Â 948.253825] Code: 6d 29 83 48 89 4c 24 20 48 89 54 24 10 c6 05 d0 89 5a 03 01 e8 11 ea ee ff 0f 0b 48 8b 4c 24 20 48 8b 54 24 10 e9 bb f7 ff ff <0f> 0b e9 1d f6 ff ff e8 d4 a7 09 00 85 c0 0f 85 74 f8 ff ff 48 c7
[Â 948.272329] RSP: 0018:ffff8883d443f8c0 EFLAGS: 00010002
[Â 948.293045] RAX: 0000000000000001 RBX: ffff8883d3572468 RCX: ffffffff813a6571
[Â 948.300323] RDX: 00000000000008ab RSI: ffffc900030e4000 RDI: ffff8883e2fe6278
[Â 948.305278] RBP: ffff8883e2f00000 R08: ffffed1078ea3ab2 R09: ffffed1078ea3ab2
[Â 948.316441] R10: 0000000000000001 R11: ffffed1078ea3ab1 R12: 000000000002c680
[Â 948.320257] R13: ffff8883d357217c R14: 0000000000000001 R15: ffff8883d3572140
[Â 948.324500]Â ? hrtimer_active+0x171/0x1f0
[Â 948.327421]Â ? dequeue_task_dl+0x38/0x970
[Â 948.330572]Â __schedule+0x94b/0x1a80
[Â 948.333578]Â ? __sched_text_start+0x8/0x8
[Â 948.336141]Â ? lock_downgrade+0x5e0/0x5e0
[Â 948.338111]Â ? plist_add+0x23e/0x480
[Â 948.339706]Â schedule+0x7c/0x1a0
[Â 948.341395]Â futex_wait_queue_me+0x319/0x600
[Â 948.343329]Â ? get_futex_key_refs+0xd0/0xd0
[Â 948.345037]Â ? lock_downgrade+0x5e0/0x5e0
[Â 948.347206]Â ? get_futex_key_refs+0xa4/0xd0
[Â 948.353007]Â futex_wait+0x1e7/0x590
[Â 948.355328]Â ? futex_wait_setup+0x2b0/0x2b0
[Â 948.360578]Â ? __lock_acquire+0x60c/0x3b70
[Â 948.369186]Â ? __save_stack_trace+0x92/0x100
[Â 948.374344]Â ? hash_futex+0x15/0x210
[Â 948.376832]Â ? drop_futex_key_refs+0x3c/0xd0
[Â 948.378591]Â ? futex_wake+0x14e/0x450
[Â 948.381609]Â do_futex+0x5c9/0x15e0
[Â 948.384567]Â ? perf_syscall_enter+0xb1/0xc80
[Â 948.390307]Â ? exit_robust_list+0x240/0x240
[Â 948.393566]Â ? ftrace_syscall_exit+0x5c0/0x5c0
[Â 948.396369]Â ? lock_downgrade+0x5e0/0x5e0
[Â 948.401748]Â ? __might_fault+0x17c/0x1c0
[Â 948.404171]Â __x64_sys_futex+0x296/0x380
[Â 948.406472]Â ? __ia32_sys_futex+0x370/0x370
[Â 948.440630]Â ? trace_hardirqs_on_thunk+0x1a/0x1c
[Â 948.441774]Â ? trace_hardirqs_off_caller+0x40/0x190
[Â 948.442770]Â ? do_syscall_64+0x3b/0x580
[Â 948.486728]Â do_syscall_64+0xc8/0x580
[Â 948.489138]Â entry_SYSCALL_64_after_hwframe+0x49/0xbe
[Â 948.492072] RIP: 0033:0x462eb9
[Â 948.492788] Code: f7 d8 64 89 02 b8 ff ff ff ff c3 66 0f 1f 44 00 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 c7 c1 bc ff ff ff f7 d8 64 89 01 48
[Â 948.532016] RSP: 002b:00007f7ac8a67cd8 EFLAGS: 00000246 ORIG_RAX: 00000000000000ca
[Â 948.536811] RAX: ffffffffffffffda RBX: 000000000073bf08 RCX: 0000000000462eb9
[Â 948.542138] RDX: 0000000000000000 RSI: 0000000000000080 RDI: 000000000073bf08
[Â 948.548077] RBP: 000000000073bf00 R08: 0000000000000000 R09: 0000000000000000
[Â 948.562535] R10: 0000000000000000 R11: 0000000000000246 R12: 000000000073bf0c
[Â 948.569184] R13: 0000000000000000 R14: 000000000073bf00 R15: 00007fff106d8c10

WARNING at :

```cpp
static void task_non_contending(struct task_struct *p){
ÂÂÂ // ......
ÂÂÂ WARN_ON(hrtimer_active(&dl_se->inactive_timer));
ÂÂÂ WARN_ON(dl_se->dl_non_contending);
}
```

I have debug for it and found that hrtimer_try_to_cancel FAILED(return -1) in
migrate_task_rq_dl() because the timer handler `inactive_task_timer()` is running
at that time. so when the taskÂ blocks later, theinactive_timer is still active
indequeue_task_dl().

```cpp
static void migrate_task_rq_dl(struct task_struct *p, int new_cpu __maybe_unused){
ÂÂÂ /*
ÂÂÂÂ * If the timer handler is currently running and the
ÂÂÂ Â* timer cannot be cancelled, inactive_task_timer()
ÂÂÂÂ * will see that dl_not_contending is not set, and
ÂÂÂÂ * will not touch the rq's active utilization,
ÂÂÂÂ * so we are still safe.
ÂÂÂ */
ÂÂÂ if (hrtimer_try_to_cancel(&p->dl.inactive_timer) == 1)
ÂÂÂÂÂÂÂ put_task_struct(p);
}
```

I also read the comment and i think this is a Non-issue phenomenon.
If you delete WARN_ON, the kernel can still work very well.
correct?

However the task_struct's refcount is still held, so the code looks like this :

diff --git a/kernel/sched/deadline.c b/kernel/sched/deadline.c
index 31c050a0d0ce..d73cb033a06d 100644
--- a/kernel/sched/deadline.c
+++ b/kernel/sched/deadline.c
@@ -252,7 +252,6 @@ static void task_non_contending(struct task_struct *p)
ÂÂÂÂÂÂÂ if (dl_entity_is_special(dl_se))
ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂ return;

-ÂÂÂÂÂÂ WARN_ON(hrtimer_active(&dl_se->inactive_timer));
ÂÂÂÂÂÂÂ WARN_ON(dl_se->dl_non_contending);

ÂÂÂÂÂÂÂ zerolag_time = dl_se->deadline -
@@ -287,7 +286,9 @@ static void task_non_contending(struct task_struct *p)
ÂÂÂÂÂÂÂ }

ÂÂÂÂÂÂÂ dl_se->dl_non_contending = 1;
-ÂÂÂÂÂÂ get_task_struct(p);
+
+ÂÂÂÂÂÂ if (!hrtimer_active(&dl_se->inactive_timer));
+ÂÂÂÂÂÂÂÂÂÂÂÂÂÂ get_task_struct(p);
ÂÂÂÂÂÂÂ hrtimer_start(timer, ns_to_ktime(zerolag_time), HRTIMER_MODE_REL);
Â}

Did I miss something ?

I saw it directly remove the hrtimer in hrtime_start() if hrtime is queued,
it may be unsafe here when the timer handler is running.

Help ?

I put the syzkaller log and C demo in attachments.

Thanks.

Next message: Arnaldo Carvalho de Melo: "[PATCH 20/30] tools headers uapi: Sync copy of asm-generic/unistd.h with the kernel sources"
Previous message: Arnaldo Carvalho de Melo: "[PATCH 18/30] perf script python: Add printdate function to SQL exporters"
Next in thread: luca abeni: "Re: WARN ON at kernel/sched/deadline.c task_non_contending"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]