1:56 a.m.
Greetings,
0day kernel testing robot got the below dmesg and the first bad commit is
https://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git master
commit cb42c9a3ebbbb23448c3f9a25417fae6309b1a92
Author: Matt Fleming <matt(a)codeblueprint.co.uk>
AuthorDate: Wed Sep 21 14:38:13 2016 +0100
Commit: Ingo Molnar <mingo(a)kernel.org>
CommitDate: Sat Jan 14 11:29:35 2017 +0100
sched/core: Add debugging code to catch missing update_rq_clock() calls
There's no diagnostic checks for figuring out when we've accidentally
missed update_rq_clock() calls. Let's add some by piggybacking on the
rq_*pin_lock() wrappers.
The idea behind the diagnostic checks is that upon pining rq lock the
rq clock should be updated, via update_rq_clock(), before anybody
reads the clock with rq_clock() or rq_clock_task().
The exception to this rule is when updates have explicitly been
disabled with the rq_clock_skip_update() optimisation.
There are some functions that only unpin the rq lock in order to grab
some other lock and avoid deadlock. In that case we don't need to
update the clock again and the previous diagnostic state can be
carried over in rq_repin_lock() by saving the state in the rq_flags
context.
Since this patch adds a new clock update flag and some already exist
in rq::clock_skip_update, that field has now been renamed. An attempt
has been made to keep the flag manipulation code small and fast since
it's used in the heart of the __schedule() fast path.
For the !CONFIG_SCHED_DEBUG case the only object code change (other
than addresses) is the following change to reset RQCF_ACT_SKIP inside
of __schedule(),
- c7 83 38 09 00 00 00 movl $0x0,0x938(%rbx)
- 00 00 00
+ 83 a3 38 09 00 00 fc andl $0xfffffffc,0x938(%rbx)
Suggested-by: Peter Zijlstra <peterz(a)infradead.org>
Signed-off-by: Matt Fleming <matt(a)codeblueprint.co.uk>
Signed-off-by: Peter Zijlstra (Intel) <peterz(a)infradead.org>
Cc: Byungchul Park <byungchul.park(a)lge.com>
Cc: Frederic Weisbecker <fweisbec(a)gmail.com>
Cc: Jan Kara <jack(a)suse.cz>
Cc: Linus Torvalds <torvalds(a)linux-foundation.org>
Cc: Luca Abeni <luca.abeni(a)unitn.it>
Cc: Mel Gorman <mgorman(a)techsingularity.net>
Cc: Mike Galbraith <efault(a)gmx.de>
Cc: Mike Galbraith <umgwanakikbuti(a)gmail.com>
Cc: Petr Mladek <pmladek(a)suse.com>
Cc: Rik van Riel <riel(a)redhat.com>
Cc: Sergey Senozhatsky <sergey.senozhatsky.work(a)gmail.com>
Cc: Thomas Gleixner <tglx(a)linutronix.de>
Cc: Wanpeng Li <wanpeng.li(a)hotmail.com>
Cc: Yuyang Du <yuyang.du(a)intel.com>
Link: http://lkml.kernel.org/r/20160921133813.31976-8-matt@codeblueprint.co.uk
Signed-off-by: Ingo Molnar <mingo(a)kernel.org>
+--------------------------------------------------------------+------------+------------+
| | 2fb8d36787 | cb42c9a3eb
|
+--------------------------------------------------------------+------------+------------+
| boot_successes | 1219 | 170
|
| boot_failures | 5 | 144
|
| WARNING:at_arch/x86/include/asm/fpu/internal.h:#fpu__restore | 3 |
|
| BUG:workqueue_lockup-pool | 2 |
|
| WARNING:at_kernel/sched/sched.h:#rq_clock_task | 0 | 143
|
| INFO:possible_circular_locking_dependency_detected | 0 | 100
|
| calltrace:disk_events_workfn | 0 | 48
|
| calltrace:torture_shuffle | 0 | 100
|
| calltrace:_do_fork | 0 | 100
|
| calltrace:workqueue_init | 0 | 100
|
| calltrace:ret_from_fork | 0 | 78
|
| EIP:ide_output_data | 0 | 78
|
| calltrace:blk_delay_work | 0 | 30
|
| EIP:native_safe_halt | 0 | 19
|
| EIP:__do_softirq | 0 | 8
|
| calltrace:SyS_fstatat64 | 0 | 3
|
| EIP:_raw_spin_unlock_irq | 0 | 1
|
| EIP:check_poison_obj | 0 | 2
|
| EIP:strcmp | 0 | 1
|
| invoked_oom-killer:gfp_mask=0x | 0 | 2
|
| Mem-Info | 0 | 2
|
+--------------------------------------------------------------+------------+------------+
[ 83.578917] rcu-torture: rtc: c5a6c780 ver: 1 tfle: 0 rta: 1 rtaf: 0 rtf: 0 rtmbe: 0
rtbe: 0 rtbke: 0 rtbre: 0 rtbf: 0 rtb: 0 nt: 1 barrier: 0/0:0 cbflood: 1
[ 83.584146] rcu-torture: Reader Pipe: 2 0 0 0 0 0 0 0 0 0 0
[ 83.586253] rcu-torture: Reader Batch: 1 1 0 0 0 0 0 0 0 0 0
[ 83.587877] rcu-torture: Free-Block Circulation: 0 0 0 0 0 0 0 0 0 0 0
[ 83.791548] ------------[ cut here ]------------
[ 83.793245] WARNING: CPU: 0 PID: 40 at kernel/sched/sched.h:804
rq_clock_task+0x126/0x290
[ 83.796441] rq->clock_update_flags < RQCF_ACT_SKIP
[ 83.796454] CPU: 0 PID: 40 Comm: torture_shuffle Not tainted 4.10.0-rc3-00256-gcb42c9a
#3
[ 83.800931] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.9.3-20161025_171302-gandalf 04/01/2014
[ 83.815146] Call Trace:
[ 83.816232] dump_stack+0x2c6/0x39a
[ 83.817461] __warn+0x23d/0x280
[ 83.818643] ? rq_clock_task+0x126/0x290
[ 83.819947] ? rq_clock_task+0x126/0x290
[ 83.821244] warn_slowpath_fmt+0x57/0x70
[ 83.831558] rq_clock_task+0x126/0x290
[ 83.832837] set_next_entity+0x90/0xc0
[ 83.834107] set_curr_task_fair+0x48/0x60
[ 83.835414] do_set_cpus_allowed+0x26f/0x470
[ 83.836768] __set_cpus_allowed_ptr+0x1e8/0x510
[ 83.838161] set_cpus_allowed_ptr+0x1d/0x30
[ 83.839498] torture_shuffle+0x21b/0x610
[ 83.858854] kthread+0x224/0x240
[ 83.860043] ? torture_shutdown+0x620/0x620
[ 83.861375] ? __kthread_bind_mask+0xf0/0xf0
[ 83.862748] ret_from_fork+0x19/0x30
[ 83.864065] ---[ end trace 6227f0c8323ad65a ]---
[ 86.016087] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11
git bisect start 7ba5052770189d990301ffc7d970616dca3e7ddd
7089db84e356562f8ba737c29e472cc42d530dbc --
git bisect bad 273df238275de49611ba1e8716f31907b87a78f7 # 23:47 2- 6 Merge
'wsa/renesas/topic/sdhi-dma-sync-v2' into devel-spot-201702181304
git bisect good b3ce255771424298b466f7b1a1c5988534205a8b # 00:58 306+ 2 Merge
'linux-review/Lepton-Wu/Make-mtdblock-can-handle-partition-bigger-than-4G/20170218-080401'
into devel-spot-201702181304
git bisect bad 5bfd5a19aad7f0dbe19d7df4faa3c465de5c1322 # 01:27 6- 2 Merge
'linux-review/David-Daney/of_mdio-Add-broadcom-bcm5241-to-the-whitelist/20170218-050724'
into devel-spot-201702181304
git bisect bad c1f80db5c3d68d6740ba755383ea35c5bf460a38 # 01:46 0- 1 Merge
'linux-review/Steven-Rostedt-VMware/sched-rt-Add-comments-describing-the-RT-IPI-pull-method/20170218-072124'
into devel-spot-201702181304
git bisect good fc4e0527223c01107d9eed1e54fb9e79474531b8 # 03:31 307+ 3 Merge
'linux-review/Colin-King/ext4-fix-spelling-mistake-alligned-aligned/20170218-073533'
into devel-spot-201702181304
git bisect good 2d386e93a226eb2e71ca775fefa4cd3a42bc3a08 # 04:37 300+ 1 Merge
'block/for-4.11/block' into devel-spot-201702181304
git bisect good e77acbd376baaeddcaa8bfd4a0acbd01c01eafb0 # 05:25 302+ 2 Merge
'pci/next' into devel-spot-201702181304
git bisect bad 07e5f5e353aaa61696c8353d87050994a0c4648a # 05:41 2- 3 time:
Introduce jiffies64_to_nsecs()
git bisect bad 9881b024b7d7671f6a014091bc96506b89081802 # 06:01 1- 3
sched/clock: Delay switching sched_clock to stable
git bisect good c8d7dabf8f91fadd265e6eb87afb201d14ea299b # 08:36 301+ 3
sched/cputime: Rename vtime_account_user() to vtime_flush()
git bisect good 80f5c1b84baa8180c3c27b7e227429712cd967b6 # 09:52 304+ 3
sched/core: Add missing update_rq_clock() in detach_task_cfs_rq()
git bisect bad cb42c9a3ebbbb23448c3f9a25417fae6309b1a92 # 11:20 1- 2
sched/core: Add debugging code to catch missing update_rq_clock() calls
git bisect good 2fb8d36787affe26f3536c3d8ec094995a48037d # 12:59 302+ 1
sched/core: Add missing update_rq_clock() call in set_user_nice()
# first bad commit: [cb42c9a3ebbbb23448c3f9a25417fae6309b1a92] sched/core: Add debugging
code to catch missing update_rq_clock() calls
git bisect good 2fb8d36787affe26f3536c3d8ec094995a48037d # 16:20 918+ 5
sched/core: Add missing update_rq_clock() call in set_user_nice()
# extra tests with CONFIG_DEBUG_INFO_REDUCED
git bisect bad cb42c9a3ebbbb23448c3f9a25417fae6309b1a92 # 16:41 24- 5
sched/core: Add debugging code to catch missing update_rq_clock() calls
# extra tests on HEAD of linux-devel/devel-spot-201702181304
git bisect bad 7ba5052770189d990301ffc7d970616dca3e7ddd # 16:41 0- 3 0day
head guard for 'devel-spot-201702181304'
# extra tests on tree/branch linux-next/master
git bisect good 4ce4a759a3e221b5265ebd03c2f8888b69a7cf3e # 18:56 910+ 914 Add
linux-next specific files for 20170217
# extra tests on tree/branch linus/master
git bisect good 00ea1ceebe0d9f2dc1cc2b7bd575a00100c27869 # 21:27 903+ 5 ipv6:
release dst on error in ip6_dst_lookup_tail
# extra tests on tree/branch linux-next/master
git bisect good 4ce4a759a3e221b5265ebd03c2f8888b69a7cf3e # 21:57 910+ 1824 Add
linux-next specific files for 20170217
---
0-DAY kernel test infrastructure Open Source Technology Center
https://lists.01.org/pipermail/lkp Intel Corporation
10:21 p.m.
On Mon, 20 Feb, at 09:56:19AM, Fengguang Wu wrote:
[ 83.791548] ------------[ cut here ]------------
[ 83.793245] WARNING: CPU: 0 PID: 40 at kernel/sched/sched.h:804
rq_clock_task+0x126/0x290
[ 83.796441] rq->clock_update_flags < RQCF_ACT_SKIP
[ 83.796454] CPU: 0 PID: 40 Comm: torture_shuffle Not tainted 4.10.0-rc3-00256-gcb42c9a
#3
[ 83.800931] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.9.3-20161025_171302-gandalf 04/01/2014
[ 83.815146] Call Trace:
[ 83.816232] dump_stack+0x2c6/0x39a
[ 83.817461] __warn+0x23d/0x280
[ 83.818643] ? rq_clock_task+0x126/0x290
[ 83.819947] ? rq_clock_task+0x126/0x290
[ 83.821244] warn_slowpath_fmt+0x57/0x70
[ 83.831558] rq_clock_task+0x126/0x290
[ 83.832837] set_next_entity+0x90/0xc0
[ 83.834107] set_curr_task_fair+0x48/0x60
[ 83.835414] do_set_cpus_allowed+0x26f/0x470
[ 83.836768] __set_cpus_allowed_ptr+0x1e8/0x510
[ 83.838161] set_cpus_allowed_ptr+0x1d/0x30
[ 83.839498] torture_shuffle+0x21b/0x610
[ 83.858854] kthread+0x224/0x240
[ 83.860043] ? torture_shutdown+0x620/0x620
[ 83.861375] ? __kthread_bind_mask+0xf0/0xf0
[ 83.862748] ret_from_fork+0x19/0x30
[ 83.864065] ---[ end trace 6227f0c8323ad65a ]---
[ 86.016087] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11
Urgh, yeah. This is similar to the one that Peter fixed in
commit 1b1d62254df0f ("sched/core: Add missing update_rq_clock() call in
sched_move_task()")
I'll take a closer look at submitting a fix in the morning.
2003
days inactive
2003
days old
1 comments
2 participants
participants (2)
-
Fengguang Wu -
Matt Fleming