Re: [PATCH v3] sched/deadline: fix earliest_dl.next logic

Wanpeng Li
2015-11-30T02:20:56Z

2015-11-27 20:14 GMT+08:00 Luca Abeni <luca.abeni@unitn.it>:
> Hi all,
>
> I ran some quick tests on this patch (because I was working on something
> related), and it seems to me that it triggers a bug. Here are some
> information:
> - I applied the patch to git master (to be sure that I did not corrupt the
> patch,
> I extracted it again with git format-patch, and posted it here:
>
> http://disi.unitn.it/~abeni/H-Test/0001-sched-deadline-fix-earliest_dl.next-logic.patch
> )
> - I tried a simple test program creating 4 periodic threads and scheduling
> them with
> SCHED_DEADLINE. And I got something like:
> [ 29.055688] ------------[ cut here ]------------
> [ 29.056563] kernel BUG at
> /home/luca/Src/Kernel/linux/kernel/sched/deadline.c:1443!
> [ 29.056563] invalid opcode: 0000 [#1] SMP
> [ 29.056563] Modules linked in:
> [ 29.056563] CPU: 0 PID: 1136 Comm: periodic_thread Not tainted 4.4.0-rc2+
> #3
> [ 29.056563] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS
> Bochs 01/01/2011
> [ 29.056563] task: ffff880006603d80 ti: ffff8800067f4000 task.ti:
> ffff8800067f4000
> [ 29.056563] RIP: 0010:[<ffffffff8109704a>] [<ffffffff8109704a>]
> pick_next_pushable_dl_task+0x5a/0x60
> [ 29.056563] RSP: 0000:ffff8800067f7e38 EFLAGS: 00010046
> [ 29.056563] RAX: ffff880006603d80 RBX: ffff880006a7ac50 RCX:
> ffff8800067f4000
> [ 29.056563] RDX: ffff8800066040d0 RSI: 0000000000000000 RDI:
> ffff880007a15ac0
> [ 29.056563] RBP: ffff8800067f7e38 R08: 0000000000000000 R09:
> 0000000000000000
> [ 29.056563] R10: ffff880006603d80 R11: ffff880006604548 R12:
> ffff880007a15ac0
> [ 29.056563] R13: ffff880006a7a900 R14: ffff8800066042e0 R15:
> ffffffff81a09cc0
> [ 29.056563] FS: 00007f667e179700(0000) GS:ffff880007a00000(0000)
> knlGS:0000000000000000
> [ 29.056563] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
> [ 29.056563] CR2: 00007f71f3c221b8 CR3: 00000000067ae000 CR4:
> 00000000000006f0
> [ 29.056563] Stack:
> [ 29.056563] ffff8800067f7e60 ffffffff81097137 ffff880007a15ac0
> ffff880006a7ab20
> [ 29.056563] ffff880006a7a900 ffff8800067f7e90 ffffffff81098ef1
> ffff880006603d80
> [ 29.056563] ffff880007a15ac0 ffff880007a15ad8 0000000000000000
> ffff8800067f7ee8
> [ 29.056563] Call Trace:
> [ 29.056563] [<ffffffff81097137>] dequeue_pushable_dl_task+0x47/0x90
> [ 29.056563] [<ffffffff81098ef1>] pick_next_task_dl+0x81/0x200
> [ 29.056563] [<ffffffff819521ad>] __schedule+0xb3d/0xd00
> [ 29.056563] [<ffffffff819523a7>] schedule+0x37/0x80
> [ 29.056563] [<ffffffff81050d46>] exit_to_usermode_loop+0x39/0x7f
> [ 29.056563] [<ffffffff81001a76>] prepare_exit_to_usermode+0x46/0x50
> [ 29.056563] [<ffffffff819586a5>] retint_user+0x8/0x20
> [ 29.056563] Code: 3b 87 18 09 00 00 74 23 83 7a 98 01 7e 1b 83 ba f4 fc
> ff ff 01 75 10 8b 92 f8 fc ff ff 85 d2 78 04 0f 0b 31 c0 5d c3 0f 0b 0f 0b
> <0f> 0b 0f 0b 66 90 55 48 89 e5 41 54 49 89 f4 53 48 8b b7 18 09
> [ 29.056563] RIP [<ffffffff8109704a>]
> pick_next_pushable_dl_task+0x5a/0x60
> [ 29.056563] RSP <ffff8800067f7e38>
> [ 29.056563] ---[ end trace 9f49218ec54a0b55 ]---
> - How to reproduce:
> + Download http://disi.unitn.it/~abeni/H-Test/newcore-3.gz
> + Start KVM with:
> qemu-system-x86_64 -initrd newcore-3.gz -machine
> pc-q35-2.0,accel=kvm -smp cpus=2 -kernel bzImage -serial file:qlog.txt
> -append "console=ttyS0"
> + Inside the VM, do
> cd /
> sudo ./periodic_thread
> + You should see a crash in few seconds
> The "periodic_thread" program just creates 4 periodic threads (with
> execution time about
> 10ms and period about 100ms) scheduled with SCHED_DEADLINE (with runtime
> 15ms and period
> 100ms). I can provide the source code if needed.
> - The full kernel log is available here:
> http://disi.unitn.it/~abeni/H-Test/qlog.txt
>
>
> Here is my understanding of the crash:
> - schedule() invokes pick_next_task_dl() which wants to do a context switch
> (by selecting
> for execution a new task "p" which is different from "prev")
> - pick_next_task_dl() invokes put_prev, which puts the "prev" task in the
> pushable tasks
> queue (WARNING! "prev" is still the "current" task in this rq, because the
> scheduler is
> still running... I think this is the source of the issue)
> - then, pick_next_task_dl() invokes dequeue_pushable_dl_task() on p, to
> remove the selected
> task from the pushable tasks queue...
> - ...But after your patch dequeue_pushable_dl_task() invokes
> pick_next_pushable_dl_task().
> Which sees that the next pushable task is the "current" task (see above).
> This happens
> becuase "prev" has already been inserted in the pushable tasks queue, and
> can be the
> next pushable task... But "current" has not been updated yet.
> - The BUG_ON() at line 1443 of deadline.c is just "BUG_ON(task_current(rq,
> p))"

Thanks for your report and great analyse, Luca, you are right.

>
> Summing up, I think pick_next_pushable_dl_task() cannot be called from
> dequeue_pushable_dl_task() (at least, not without removing or modifying that
> BUG_ON()).

Juri, how about remove this BUG_ON() just like rt class?

Regards,
Wanpeng Li