| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <5342BCD1.4050202@intel.com>
Date: Mon, 07 Apr 2014 22:57:21 +0800
From: Jet Chen <jet.chen@...el.com>
To: Viresh Kumar <viresh.kumar@...aro.org>
CC: Jet Chen <jet.chen@...el.com>,
Linux Kernel Mailing List <linux-kernel@...r.kernel.org>,
Fengguang Wu <fengguang.wu@...el.com>
Subject: [clocksource] INFO: possible irq lock inversion dependency detected
Hi Viresh,
Your patch on my testing branch in LKP system:
git://bee.sh.intel.com/git/tchen37/linux.git timer_debug3 got the below
dmesg.
FYI, I applied your patch on the top of commit
6378cb51af5f4743db0dcb3cbcf862eac5908754 - timer: don't migrate pinned
timers.
commit 90585a71ecf3285bc73d54e37080c3bb21583594
Author: Viresh Kumar <viresh.kumar@...aro.org>
AuthorDate: Sat Apr 5 11:43:25 2014 +0530
Commit: Jet Chen <jet.chen@...el.com>
CommitDate: Sat Apr 5 14:32:32 2014 +0800
clocksource: register cpu notifier to remove timer from dying CPU
clocksource core is using add_timer_on() to run
clocksource_watchdog() on all
CPUs one by one. But when a core is brought down, clocksource core
doesn't
remove this timer from the dying CPU. And in this case timer core
gives this
(Gives this only with unmerged code, anyway in the current code as
well timer
core is migrating a pinned timer to other CPUs, which is also wrong:
http://www.gossamer-threads.com/lists/linux/kernel/1898117)
migrate_timer_list: can't migrate pinned timer: ffffffff81f06a60,
timer->function: ffffffff810d7010,deactivating it Modules linked in:
CPU: 0 PID: 1932 Comm: 01-cpu-hotplug Not tainted
3.14.0-rc1-00088-gab3c4fd #4
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
0000000000000009 ffff88001d407c38 ffffffff817237bd ffff88001d407c80
ffff88001d407c70 ffffffff8106a1dd 0000000000000010 ffffffff81f06a60
ffff88001e04d040 ffffffff81e3d4c0 ffff88001e04d030 ffff88001d407cd0
Call Trace:
[<ffffffff817237bd>] dump_stack+0x4d/0x66
[<ffffffff8106a1dd>] warn_slowpath_common+0x7d/0xa0
[<ffffffff8106a24c>] warn_slowpath_fmt+0x4c/0x50
[<ffffffff810761c3>] ? __internal_add_timer+0x113/0x130
[<ffffffff810d7010>] ? clocksource_watchdog_kthread+0x40/0x40
[<ffffffff8107753b>] migrate_timer_list+0xdb/0xf0
[<ffffffff810782dc>] timer_cpu_notify+0xfc/0x1f0
[<ffffffff8173046c>] notifier_call_chain+0x4c/0x70
[<ffffffff8109340e>] __raw_notifier_call_chain+0xe/0x10
[<ffffffff8106a3f3>] cpu_notify+0x23/0x50
[<ffffffff8106a44e>] cpu_notify_nofail+0xe/0x20
[<ffffffff81712a5d>] _cpu_down+0x1ad/0x2e0
[<ffffffff81712bc4>] cpu_down+0x34/0x50
[<ffffffff813fec54>] cpu_subsys_offline+0x14/0x20
[<ffffffff813f9f65>] device_offline+0x95/0xc0
[<ffffffff813fa060>] online_store+0x40/0x90
[<ffffffff813f75d8>] dev_attr_store+0x18/0x30
[<ffffffff8123309d>] sysfs_kf_write+0x3d/0x50
This patch tries to fix this by registering cpu notifiers from
clocksource core,
only when we start clocksource-watchdog. And if on the CPU_DEAD
notification it
is found that dying CPU was the CPU on which this timer is queued
on, then it is
removed from that CPU and queued to next CPU.
Reported-by: Jet Chen <jet.chen@...el.com>
Reported-by: Fengguang Wu <fengguang.wu@...el.com>
Signed-off-by: Viresh Kumar <viresh.kumar@...aro.org>
===================================================
PARENT COMMIT NOT CLEAN. LOOK OUT FOR WRONG BISECT!
===================================================
+------------------------------------------------------------------+------------+------------+------------+
| |
6378cb51af | 90585a71ec | 3db74909a7 |
+------------------------------------------------------------------+------------+------------+------------+
| boot_successes | 24
| 0 | 0 |
| boot_failures | 56
| 20 | 13 |
| BUG:soft_lockup-CPU_stuck_for_s | 50
| | |
| EIP_is_at_insert | 10
| | |
| Kernel_panic-not_syncing:softlockup:hung_tasks | 50
| | |
| backtrace:rbtree_test_init | 41
| | |
| backtrace:kernel_init_freeable | 49
| 20 | 13 |
| backtrace:apic_timer_interrupt | 44
| | |
| EIP_is_at_rbtree_test_init | 17
| | |
| EIP_is_at_rb_erase | 11
| | |
| EIP_is_at_rb_insert_color | 9
| | |
| backtrace:insert | 4
| | |
| Out_of_memory:Kill_process | 6
| 2 | 1 |
| Kernel_panic-not_syncing:Out_of_memory_and_no_killable_processes | 6
| 1 | 1 |
| backtrace:tty_ldisc_setup | 1
| | |
| backtrace:tty_init_dev | 1
| | |
| backtrace:do_sys_open | 1
| | |
| backtrace:SyS_open | 1
| | |
| EIP_is_at__do_softirq | 1
| | |
| EIP_is_at_strcmp | 1
| | |
| backtrace:gcov_enable_events | 1
| | |
| backtrace:gcov_fs_init | 1
| | |
| EIP_is_at__rb_erase_color | 1
| | |
| INFO:possible_irq_lock_inversion_dependency_detected | 0
| 20 | 13 |
| BUG:unable_to_handle_kernel_NULL_pointer_dereference | 0
| 7 | |
| Oops | 0
| 4 | |
| Kernel_panic-not_syncing:Fatal_exception | 0
| 4 | |
| backtrace:register_cpu_notifier | 0
| 20 | 13 |
| backtrace:page_writeback_init | 0
| 20 | 13 |
| backtrace:cpu_up | 0
| 20 | 13 |
| backtrace:smp_init | 0
| 20 | 13 |
| backtrace:kmem_cache_init | 0
| 10 | 5 |
| backtrace:tsc_refine_calibration_work | 0
| 20 | 13 |
| backtrace:vfs_read | 0
| 4 | |
| backtrace:SyS_read | 0
| 4 | |
| backtrace:slab_sysfs_init | 0
| 2 | 4 |
| backtrace:kvm_guest_init | 0
| 10 | 8 |
| backtrace:__clocksource_register_scale | 0
| 10 | 8 |
| backtrace:kvmclock_init | 0
| 10 | 8 |
| backtrace:__mm_populate | 0
| 1 | |
| backtrace:SyS_mlockall | 0
| 1 | |
| backtrace:__raw_spin_lock_init | 0
| 1 | |
+------------------------------------------------------------------+------------+------------+------------+
[ 3.650334] crc32c_combine: 8373 self tests passed
[ 3.651169] rbtree testing
[ 3.787010] =========================================================
[ 3.787976] [ INFO: possible irq lock inversion dependency detected ]
[ 3.788955] 3.14.0-rc1-00088-g90585a7 #2 Not tainted
[ 3.789772] ---------------------------------------------------------
[ 3.789969] swapper/0/1 just changed the state of lock:
[ 3.789969] (watchdog_lock){..-...}, at: [<c1124731>]
clocksource_watchdog+0x21/0x450
[ 3.789969] but this lock took another, SOFTIRQ-unsafe lock in the past:
[ 3.789969] (cpu_add_remove_lock){+.+.+.}
and interrupts could create inverse lock ordering between them.
[ 3.789969] [ 3.789969] other info that might help us debug this:
[ 3.789969] Possible interrupt unsafe locking scenario:
[ 3.789969] [ 3.789969] CPU0 CPU1
[ 3.789969] ---- ----
[ 3.789969] lock(cpu_add_remove_lock);
[ 3.789969] local_irq_disable();
[ 3.789969] lock(watchdog_lock);
[ 3.789969] lock(cpu_add_remove_lock);
[ 3.789969] <Interrupt>
[ 3.789969] lock(watchdog_lock);
[ 3.789969] [ 3.789969] *** DEADLOCK ***
[ 3.789969] [ 3.789969] 1 lock held by swapper/0/1:
[ 3.789969] #0: ((&watchdog_timer)){+.-...}, at: [<c1090560>]
call_timer_fn+0x0/0x170
[ 3.789969] [ 3.789969] the shortest dependencies between 2nd lock
and 1st lock:
[ 3.789969] -> (cpu_add_remove_lock){+.+.+.} ops: 16 {
[ 3.789969] HARDIRQ-ON-W at:
[ 3.789969] [<c10f8345>]
__lock_acquire+0xa05/0x1880
[ 3.789969] [<c10f9292>] lock_acquire+0xd2/0x110
[ 3.789969] [<c2895b78>]
mutex_lock_nested+0x98/0x790
[ 3.789969] [<c28708c0>]
register_cpu_notifier+0x20/0x70
[ 3.789969] [<c33ad060>]
page_writeback_init+0x2e/0x56
[ 3.789969] [<c337c5e8>] start_kernel+0x9f0/0xa51
[ 3.789969] [<c337b3c8>]
i386_start_kernel+0x19e/0x1af
[ 3.789969] SOFTIRQ-ON-W at:
[ 3.789969] [<c10f8393>]
__lock_acquire+0xa53/0x1880
[ 3.789969] [<c10f9292>] lock_acquire+0xd2/0x110
[ 3.789969] [<c2895b78>]
mutex_lock_nested+0x98/0x790
[ 3.789969] [<c28708c0>]
register_cpu_notifier+0x20/0x70
[ 3.789969] [<c33ad060>]
page_writeback_init+0x2e/0x56
[ 3.789969] [<c337c5e8>] start_kernel+0x9f0/0xa51
[ 3.789969] [<c337b3c8>]
i386_start_kernel+0x19e/0x1af
[ 3.789969] RECLAIM_FS-ON-W at:
[ 3.789969] [<c10f35e0>]
mark_held_locks+0xc0/0x1e0
[ 3.789969] [<c10f4966>]
lockdep_trace_alloc+0x126/0x230
[ 3.789969] [<c11c345f>]
kmem_cache_alloc+0x3f/0x260
[ 3.789969] [<c10be745>]
__smpboot_create_thread+0x55/0x190
[ 3.789969] [<c10beb6b>]
smpboot_create_threads+0x7b/0xc0
[ 3.789969] [<c107f1da>] cpu_up+0x12a/0x520
[ 3.789969] [<c33a90dc>] smp_init+0x18b/0x1f2
[ 3.789969] [<c337c957>]
kernel_init_freeable+0xec/0x3f4
[ 3.789969] [<c286fff9>] kernel_init+0x19/0x230
[ 3.789969] [<c289eef7>]
ret_from_kernel_thread+0x1b/0x28
[ 3.789969] INITIAL USE at:
[ 3.789969] [<c10f7dbc>] __lock_acquire+0x47c/0x1880
[ 3.789969] [<c10f9292>] lock_acquire+0xd2/0x110
[ 3.789969] [<c2895b78>]
mutex_lock_nested+0x98/0x790
[ 3.789969] [<c28708c0>]
register_cpu_notifier+0x20/0x70
[ 3.789969] [<c339e846>] kvm_guest_init+0x1bc/0x24d
[ 3.789969] [<c33820b8>] setup_arch+0x1835/0x18e2
[ 3.789969] [<c337bd3d>] start_kernel+0x145/0xa51
[ 3.789969] [<c337b3c8>]
i386_start_kernel+0x19e/0x1af
[ 3.789969] }
[ 3.789969] ... key at: [<c3080a80>] cpu_add_remove_lock+0x40/0xf0
[ 3.789969] ... acquired at:
[ 3.789969] [<c10f7fab>] __lock_acquire+0x66b/0x1880
[ 3.789969] [<c10f9292>] lock_acquire+0xd2/0x110
[ 3.789969] [<c2895b78>] mutex_lock_nested+0x98/0x790
[ 3.789969] [<c28708c0>] register_cpu_notifier+0x20/0x70
[ 3.789969] [<c112389e>] clocksource_enqueue_watchdog+0xde/0x230
[ 3.789969] [<c11250b1>] __clocksource_register_scale+0xf1/0x140
[ 3.789969] [<c100fe9d>] tsc_refine_calibration_work+0x1bd/0x2a0
[ 3.789969] [<c10a5495>] process_one_work+0x265/0x740
[ 3.789969] [<c10a612a>] worker_thread+0x28a/0x6f0
[ 3.789969] [<c10b1b60>] kthread+0x110/0x150
[ 3.789969] [<c289eef7>] ret_from_kernel_thread+0x1b/0x28
[ 3.789969] [ 3.789969] -> (watchdog_lock){..-...} ops: 8 {
[ 3.789969] IN-SOFTIRQ-W at:
[ 3.789969] [<c10f8510>] __lock_acquire+0xbd0/0x1880
[ 3.789969] [<c10f9292>] lock_acquire+0xd2/0x110
[ 3.789969] [<c289c6d7>] _raw_spin_lock+0x67/0x110
[ 3.789969] [<c1124731>]
clocksource_watchdog+0x21/0x450
[ 3.789969] [<c1090607>] call_timer_fn+0xa7/0x170
[ 3.789969] [<c1090b76>]
run_timer_softirq+0x206/0x380
[ 3.789969] [<c108614c>] __do_softirq+0x14c/0x380
[ 3.789969] INITIAL USE at:
[ 3.789969] [<c10f7dbc>] __lock_acquire+0x47c/0x1880
[ 3.789969] [<c10f9292>] lock_acquire+0xd2/0x110
[ 3.789969] [<c289c825>]
_raw_spin_lock_irqsave+0xa5/0x150
[ 3.789969] [<c11237e2>]
clocksource_enqueue_watchdog+0x22/0x230
[ 3.789969] [<c11250b1>]
__clocksource_register_scale+0xf1/0x140
[ 3.789969] [<c339eba6>] kvmclock_init+0x2cf/0x35b
[ 3.789969] [<c3381f80>] setup_arch+0x16fd/0x18e2
[ 3.789969] [<c337bd3d>] start_kernel+0x145/0xa51
[ 3.789969] [<c337b3c8>] i386_start_kernel+0x19e/0x1af
[ 3.789969] }
[ 3.789969] ... key at: [<c30963d0>] watchdog_lock+0x10/0x40
[ 3.789969] ... acquired at:
[ 3.789969] [<c10ef619>] check_usage_forwards+0xb9/0x190
[ 3.789969] [<c10f2fab>] mark_lock+0x69b/0xc10
[ 3.789969] [<c10f8510>] __lock_acquire+0xbd0/0x1880
[ 3.789969] [<c10f9292>] lock_acquire+0xd2/0x110
[ 3.789969] [<c289c6d7>] _raw_spin_lock+0x67/0x110
[ 3.789969] [<c1124731>] clocksource_watchdog+0x21/0x450
[ 3.789969] [<c1090607>] call_timer_fn+0xa7/0x170
[ 3.789969] [<c1090b76>] run_timer_softirq+0x206/0x380
[ 3.789969] [<c108614c>] __do_softirq+0x14c/0x380
[ 3.789969] [ 3.789969] [ 3.789969] stack backtrace:
[ 3.789969] CPU: 0 PID: 1 Comm: swapper/0 Not tainted
3.14.0-rc1-00088-g90585a7 #2
[ 3.789969] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
[ 3.789969] c3adc020 d180dd7c c287f340 d180ddd8 d180ddb8 c10ef2b9
c2e845e0 c2e8492e
[ 3.789969] 00000001 d180ddd8 00000006 c10ef560 d180ddb8 c10ed183
00000000 00000000
[ 3.789969] d186054c d1860000 c10ef560 d180de04 c10ef619 d186054c
00000001 c2e8492e
[ 3.789969] Call Trace:
[ 3.789969] [<c287f340>] dump_stack+0xb8/0x108
[ 3.789969] [<c10ef2b9>] print_irq_inversion_bug+0x389/0x4a0
[ 3.789969] [<c10ef560>] ? check_usage_backwards+0x190/0x190
[ 3.789969] [<c10ed183>] ? find_usage_forwards+0x53/0xd0
[ 3.789969] [<c10ef560>] ? check_usage_backwards+0x190/0x190
[ 3.789969] [<c10ef619>] check_usage_forwards+0xb9/0x190
[ 3.789969] [<c10f2fab>] mark_lock+0x69b/0xc10
[ 3.789969] [<c1008e7d>] ? print_context_stack+0x5d/0x160
[ 3.789969] [<c10f8510>] __lock_acquire+0xbd0/0x1880
[ 3.789969] [<c10f9292>] lock_acquire+0xd2/0x110
[ 3.789969] [<c1124731>] ? clocksource_watchdog+0x21/0x450
[ 3.789969] [<c289c6d7>] _raw_spin_lock+0x67/0x110
[ 3.789969] [<c1124731>] ? clocksource_watchdog+0x21/0x450
[ 3.789969] [<c1124710>] ? clocksource_cpu_notify+0xd0/0xd0
[ 3.789969] [<c1124731>] clocksource_watchdog+0x21/0x450
[ 3.789969] [<c1090560>] ? process_timeout+0x30/0x30
[ 3.789969] [<c1124710>] ? clocksource_cpu_notify+0xd0/0xd0
[ 3.789969] [<c1090607>] call_timer_fn+0xa7/0x170
[ 3.789969] [<c1090560>] ? process_timeout+0x30/0x30
[ 3.789969] [<c1090b76>] run_timer_softirq+0x206/0x380
[ 3.789969] [<c1124710>] ? clocksource_cpu_notify+0xd0/0xd0
[ 3.789969] [<c108614c>] __do_softirq+0x14c/0x380
[ 3.789969] [<c1086000>] ? _local_bh_enable+0xa0/0xa0
[ 3.789969] <IRQ> [<c10868eb>] ? irq_exit+0xcb/0xe0
[ 3.789969] [<c104c74b>] ? smp_apic_timer_interrupt+0x6b/0x90
[ 3.789969] [<c289eb02>] ? apic_timer_interrupt+0x32/0x38
[ 3.789969] [<c28800d8>] ? check+0x7e/0x52d
[ 3.789969] [<c33c846b>] ? rbtree_test_init+0xa3/0x45f
[ 3.789969] [<c33aaad6>] ? audit_register_class+0x29/0x10a
[ 3.789969] [<c33c83c8>] ? test_atomic64+0xdc0/0xdc0
[ 3.789969] [<c337c73f>] ? do_one_initcall+0xf6/0x222
[ 3.789969] [<c10ae871>] ? parameq+0x21/0x100
[ 3.789969] [<c337b749>] ? repair_env_string+0x32/0xd3
[ 3.789969] [<c10aec3b>] ? parse_args+0x2eb/0x5f0
[ 3.789969] [<c337cad7>] ? kernel_init_freeable+0x26c/0x3f4
[ 3.789969] [<c337b717>] ? do_early_param+0x131/0x131
[ 3.789969] [<c286fff9>] ? kernel_init+0x19/0x230
[ 3.789969] [<c289eef7>] ? ret_from_kernel_thread+0x1b/0x28
[ 3.789969] [<c286ffe0>] ? rest_init+0x170/0x170
[ 4.202425] -> 13739 cycles
[ 4.252106] augmented rbtree testing -> 15602 cycles
[ 4.943124] Console: switching consoles 13-16 to MDA-2
git bisect start 3db74909a7c789e467b126d837f7e0cea4a5c165
455c6fdbd219161bd09b1165f11699d6d73de11c --
git bisect bad 1301fa9378b394d49525c4a3df8e61a64b11fd0d # 10:34 0-
1 Merge 'tchen/timer_debug3' into devel-roam-i386-201404051825
git bisect good 9fde1e2345f8ac522a84c77156d7e2b8ec4e8d94 # 10:56 20+
6 0day base guard for 'devel-roam-i386-201404051825'
git bisect good b712c8dae05931a76b6c17a4254f403798e6caef # 11:06 20+
11 x86: hpet: Use proper destructor for delayed work
git bisect good 5b108727a416a790e9ef87eecd370f67773838d3 # 11:14 20+
7 hrtimer: remove 'base' parameter from hrtimer_{enqueue_}reprogram()
git bisect good af57797fadd8c265ce34605153b75c417d3df384 # 11:20 20+
4 hrtimer: remove {} around a single liner 'for' loop in
migrate_hrtimers()
git bisect good 9ffd0897bd721352543c84041daf5dc07e60f559 # 11:27 20+
6 hrtimer: take lock only once for a cpu_base in hrtimer_run_queues()
git bisect good 5a8530b7c3b1889861949d4e52b2da82d0aff242 # 11:38 20+
14 timer: track pinned timers with TIMER_PINNED flag
git bisect bad 90585a71ecf3285bc73d54e37080c3bb21583594 # 11:44 0-
3 clocksource: register cpu notifier to remove timer from dying CPU
git bisect good 6378cb51af5f4743db0dcb3cbcf862eac5908754 # 11:50 20+
9 timer: don't migrate pinned timers
# first bad commit: [90585a71ecf3285bc73d54e37080c3bb21583594]
clocksource: register cpu notifier to remove timer from dying CPU
git bisect good 6378cb51af5f4743db0dcb3cbcf862eac5908754 # 11:54 60+
56 timer: don't migrate pinned timers
git bisect bad 3db74909a7c789e467b126d837f7e0cea4a5c165 # 11:54 0-
13 0day head guard for 'devel-roam-i386-201404051825'
git bisect good 18a1a7a1d862ae0794a0179473d08a414dd49234 # 12:15 60+
15 Merge
git://git.kernel.org/pub/scm/linux/kernel/git/cmetcalf/linux-tile
git bisect good 4b22efdd5595f0acb48f02bf664a451ee98f9a2e # 12:23 60+
29 Add linux-next specific files for 20140403
This script may reproduce the error.
-----------------------------------------------------------------------------
#!/bin/bash
kernel=$1
initrd=quantal-core-i386.cgz
wget --no-clobber
https://github.com/fengguang/reproduce-kernel-bug/blob/master/initrd/$initrd
kvm=(
qemu-system-x86_64 -cpu kvm64 -enable-kvm
-kernel $kernel
-initrd $initrd
-smp 2
-m 256M
-net nic,vlan=0,macaddr=00:00:00:00:00:00,model=virtio
-net user,vlan=0
-net nic,vlan=1,model=e1000
-net user,vlan=1
-boot order=nc
-no-reboot
-watchdog i6300esb
-serial stdio
-display none
-monitor null
)
append=(
debug
sched_debug
apic=debug
ignore_loglevel
sysrq_always_enabled
panic=10
prompt_ramdisk=0
earlyprintk=ttyS0,115200
console=ttyS0,115200
console=tty0
vga=normal
root=/dev/ram0
rw
)
"${kvm[@]}" --append "${append[*]}"
-----------------------------------------------------------------------------
Thanks,
Jet
View attachment "dmesg-quantal-lkp-ib04-21:20140407114350:i386-randconfig-r3-0405:3.14.0-rc1-00088-g90585a7:2" of type "text/plain" (270582 bytes)
Download attachment "i386-randconfig-r3-0405-3db74909a7c789e467b126d837f7e0cea4a5c165-INFO:-possible-irq-lock-inversion-dependency-detected-7860.log" of type "application/octet-stream" (52009 bytes)
View attachment "config-3.14.0-rc1-00088-g90585a7" of type "text/plain" (104401 bytes)
Powered by blists - more mailing lists