timers: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected

[Sasha Levin]

Hi all,

While fuzzing with trinity inside a KVM tools guest, running the latest -next
kernel, I've hit the following lockdep warning:

[ 3408.411602] ======================================================

[ 3408.418607] [ INFO: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected ]

[ 3408.419322] 4.4.0-rc8-next-20160111-sasha-00024-g376a9c2-dirty #2782 Not tainted

[ 3408.420171] ------------------------------------------------------

[ 3408.420984] trinity-c65/30907 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire:

[ 3408.421869] (&lock->wait_lock){+.+...}, at: rt_mutex_slowunlock (kernel/locking/rtmutex.c:1266)
[ 3408.423182]

[ 3408.423182] and this task is already holding:

[ 3408.423916] (&(&new_timer->it_lock)->rlock){-.-...}, at: __lock_timer (kernel/time/posix-timers.c:707)
[ 3408.425281] which would create a new lock dependency:

[ 3408.425942]  (&(&new_timer->it_lock)->rlock){-.-...} -> (&lock->wait_lock){+.+...}

[ 3408.427118]

[ 3408.427118] but this new dependency connects a HARDIRQ-irq-safe lock:

[ 3408.428093]  (&(&new_timer->it_lock)->rlock){-.-...}

... which became HARDIRQ-irq-safe at:

[ 3408.429232] __lock_acquire (kernel/locking/lockdep.c:2796 kernel/locking/lockdep.c:3162)
[ 3408.430075] lock_acquire (./arch/x86/include/asm/current.h:14 kernel/locking/lockdep.c:3587)
[ 3408.430814] _raw_spin_lock (include/linux/spinlock_api_smp.h:145 kernel/locking/spinlock.c:151)
[ 3408.431584] run_posix_cpu_timers (include/linux/list.h:156 kernel/time/posix-cpu-timers.c:1231)
[ 3408.437683] update_process_times (kernel/time/timer.c:1427)
[ 3408.438528] tick_sched_handle (kernel/time/tick-sched.c:152)
[ 3408.439305] tick_sched_timer (kernel/time/tick-sched.c:1089)
[ 3408.440086] __hrtimer_run_queues (kernel/time/hrtimer.c:1233 kernel/time/hrtimer.c:1295)
[ 3408.446607] hrtimer_interrupt (kernel/time/hrtimer.c:1332)
[ 3408.447427] smp_trace_apic_timer_interrupt (./arch/x86/include/asm/apic.h:659 arch/x86/kernel/apic/apic.c:953)
[ 3408.448406] smp_apic_timer_interrupt (arch/x86/kernel/apic/apic.c:956)
[ 3408.460706] apic_timer_interrupt (arch/x86/entry/entry_64.S:687)
[ 3408.461517] _raw_spin_lock (include/linux/spinlock_api_smp.h:145 kernel/locking/spinlock.c:151)
[ 3408.462259] sync_inodes_sb (fs/fs-writeback.c:2133 fs/fs-writeback.c:2292)
[ 3408.463042] sync_inodes_one_sb (fs/sync.c:74)
[ 3408.463826] iterate_supers (fs/super.c:535)
[ 3408.464583] sys_sync (fs/sync.c:113)
[ 3408.465239] entry_SYSCALL_64_fastpath (arch/x86/entry/entry_64.S:186)
[ 3408.466074]

[ 3408.466074] to a HARDIRQ-irq-unsafe lock:

[ 3408.466732]  (&lock->wait_lock){+.+...}

... which became HARDIRQ-irq-unsafe at:

[ 3408.467701] ... __lock_acquire (kernel/locking/lockdep.c:2813 kernel/locking/lockdep.c:3162)
[ 3408.468551] lock_acquire (./arch/x86/include/asm/current.h:14 kernel/locking/lockdep.c:3587)
[ 3408.469240] _raw_spin_lock (include/linux/spinlock_api_smp.h:145 kernel/locking/spinlock.c:151)
[ 3408.469987] rt_mutex_slowlock (kernel/locking/rtmutex.c:1184)
[ 3408.470722] rt_mutex_lock (kernel/locking/rtmutex.c:1402)
[ 3408.471416] rcu_boost_kthread (kernel/rcu/tree_plugin.h:1033 kernel/rcu/tree_plugin.h:1055)
[ 3408.472253] kthread (kernel/kthread.c:209)
[ 3408.472937] ret_from_fork (arch/x86/entry/entry_64.S:469)
[ 3408.473642]

[ 3408.473642] other info that might help us debug this:

[ 3408.473642]

[ 3408.474461]  Possible interrupt unsafe locking scenario:

[ 3408.474461]

[ 3408.475239]        CPU0                    CPU1

[ 3408.475809]        ----                    ----

[ 3408.476380]   lock(&lock->wait_lock);

[ 3408.476925]                                local_irq_disable();

[ 3408.477640]                                lock(&(&new_timer->it_lock)->rlock);

[ 3408.478607]                                lock(&lock->wait_lock);

[ 3408.479445]   <Interrupt>

[ 3408.479796]     lock(&(&new_timer->it_lock)->rlock);

[ 3408.480504]

[ 3408.480504]  *** DEADLOCK ***

[ 3408.480504]

[ 3408.481270] 2 locks held by trinity-c65/30907:

[ 3408.481826] #0: (rcu_read_lock){......}, at: __lock_timer (include/linux/rcupdate.h:872 kernel/time/posix-timers.c:704)
[ 3408.483007] #1: (&(&new_timer->it_lock)->rlock){-.-...}, at: __lock_timer (kernel/time/posix-timers.c:707)
[ 3408.484369]

the dependencies between HARDIRQ-irq-safe lock and the holding lock:

[ 3408.485317] -> (&(&new_timer->it_lock)->rlock){-.-...} ops: 3448 {

[ 3408.486264]    IN-HARDIRQ-W at:

[ 3408.486707] __lock_acquire (kernel/locking/lockdep.c:2796 kernel/locking/lockdep.c:3162)
[ 3408.487670] lock_acquire (./arch/x86/include/asm/current.h:14 kernel/locking/lockdep.c:3587)
[ 3408.504632] _raw_spin_lock (include/linux/spinlock_api_smp.h:145 kernel/locking/spinlock.c:151)
[ 3408.505511] run_posix_cpu_timers (include/linux/list.h:156 kernel/time/posix-cpu-timers.c:1231)
[ 3408.506496] update_process_times (kernel/time/timer.c:1427)
[ 3408.507473] tick_sched_handle (kernel/time/tick-sched.c:152)
[ 3408.508447] tick_sched_timer (kernel/time/tick-sched.c:1089)
[ 3408.509366] __hrtimer_run_queues (kernel/time/hrtimer.c:1233 kernel/time/hrtimer.c:1295)
[ 3408.510356] hrtimer_interrupt (kernel/time/hrtimer.c:1332)
[ 3408.511308] smp_trace_apic_timer_interrupt (./arch/x86/include/asm/apic.h:659 arch/x86/kernel/apic/apic.c:953)
[ 3408.512386] smp_apic_timer_interrupt (arch/x86/kernel/apic/apic.c:956)
[ 3408.513380] apic_timer_interrupt (arch/x86/entry/entry_64.S:687)
[ 3408.514351] _raw_spin_lock (include/linux/spinlock_api_smp.h:145 kernel/locking/spinlock.c:151)
[ 3408.515112] sync_inodes_sb (fs/fs-writeback.c:2133 fs/fs-writeback.c:2292)
[ 3408.528093] sync_inodes_one_sb (fs/sync.c:74)
[ 3408.529101] iterate_supers (fs/super.c:535)
[ 3408.530052] sys_sync (fs/sync.c:113)
[ 3408.530926] entry_SYSCALL_64_fastpath (arch/x86/entry/entry_64.S:186)
[ 3408.531988]    IN-SOFTIRQ-W at:

[ 3408.532442] __lock_acquire (kernel/locking/lockdep.c:2799 kernel/locking/lockdep.c:3162)
[ 3408.533415] lock_acquire (./arch/x86/include/asm/current.h:14 kernel/locking/lockdep.c:3587)
[ 3408.534345] _raw_spin_lock (include/linux/spinlock_api_smp.h:145 kernel/locking/spinlock.c:151)
[ 3408.535239] run_posix_cpu_timers (include/linux/list.h:156 kernel/time/posix-cpu-timers.c:1231)
[ 3408.552300] update_process_times (kernel/time/timer.c:1427)
[ 3408.553305] tick_sched_handle (kernel/time/tick-sched.c:152)
[ 3408.554283] tick_sched_timer (kernel/time/tick-sched.c:1089)
[ 3408.555241] __hrtimer_run_queues (kernel/time/hrtimer.c:1233 kernel/time/hrtimer.c:1295)
[ 3408.556226] hrtimer_interrupt (kernel/time/hrtimer.c:1332)
[ 3408.557101] smp_trace_apic_timer_interrupt (./arch/x86/include/asm/apic.h:659 arch/x86/kernel/apic/apic.c:953)
[ 3408.558131] smp_apic_timer_interrupt (arch/x86/kernel/apic/apic.c:956)
[ 3408.559122] apic_timer_interrupt (arch/x86/entry/entry_64.S:687)
[ 3408.560128] irq_exit (kernel/softirq.c:350 kernel/softirq.c:391)
[ 3408.561008] smp_trace_apic_timer_interrupt (./arch/x86/include/asm/irq_regs.h:26 arch/x86/kernel/apic/apic.c:955)
[ 3408.562123] smp_apic_timer_interrupt (arch/x86/kernel/apic/apic.c:956)
[ 3408.563153] apic_timer_interrupt (arch/x86/entry/entry_64.S:687)
[ 3408.566483]    INITIAL USE at:

[ 3408.566917] __lock_acquire (kernel/locking/lockdep.c:3166)
[ 3408.567903] lock_acquire (./arch/x86/include/asm/current.h:14 kernel/locking/lockdep.c:3587)
[ 3408.568826] _raw_spin_lock_irqsave (include/linux/spinlock_api_smp.h:119 kernel/locking/spinlock.c:159)
[ 3408.569824] exit_itimers (kernel/time/posix-timers.c:936 kernel/time/posix-timers.c:983 kernel/time/posix-timers.c:1008)
[ 3408.570725] do_exit (kernel/exit.c:724)
[ 3408.571606] do_group_exit (kernel/exit.c:862)
[ 3408.572539] get_signal (kernel/signal.c:2327)
[ 3408.573458] do_signal (arch/x86/kernel/signal.c:781)
[ 3408.574357] exit_to_usermode_loop (arch/x86/entry/common.c:249)
[ 3408.575335] syscall_return_slowpath (./arch/x86/include/asm/jump_label.h:35 include/linux/context_tracking_state.h:30 include/linux/context_tracking.h:24 arch/x86/entry/common.c:284 arch/x86/entry/common.c:344)
[ 3408.576356] int_ret_from_sys_call (arch/x86/entry/entry_64.S:282)
[ 3408.577326]  }

[ 3408.577574] ... key at: __key.35766 (??:?)
[ 3408.578477]  ... acquired at:

[ 3408.578863] check_irq_usage (kernel/locking/lockdep.c:1649)
[ 3408.579640] __lock_acquire (kernel/locking/lockdep_states.h:7 kernel/locking/lockdep.c:1857 kernel/locking/lockdep.c:1958 kernel/locking/lockdep.c:2144 kernel/locking/lockdep.c:3206)
[ 3408.596505] lock_acquire (./arch/x86/include/asm/current.h:14 kernel/locking/lockdep.c:3587)
[ 3408.597191] _raw_spin_lock (include/linux/spinlock_api_smp.h:145 kernel/locking/spinlock.c:151)
[ 3408.597965] rt_mutex_slowunlock (kernel/locking/rtmutex.c:1266)
[ 3408.598720] rt_mutex_unlock (kernel/locking/rtmutex.c:1384 kernel/locking/rtmutex.c:1486)
[ 3408.599499] rcu_read_unlock_special (kernel/rcu/tree_plugin.h:503)
[ 3408.603731] __rcu_read_unlock (kernel/rcu/update.c:223)
[ 3408.604452] __lock_timer (include/linux/rcupdate.h:495 include/linux/rcupdate.h:930 kernel/time/posix-timers.c:709)
[ 3408.605221] SyS_timer_settime (kernel/time/posix-timers.c:903 kernel/time/posix-timers.c:881)
[ 3408.605982] entry_SYSCALL_64_fastpath (arch/x86/entry/entry_64.S:186)
[ 3408.606791]

[ 3408.607008]

the dependencies between the lock to be acquired and HARDIRQ-irq-unsafe lock:

[ 3408.608038] -> (&lock->wait_lock){+.+...} ops: 134 {

[ 3408.608843]    HARDIRQ-ON-W at:

[ 3408.609209] __lock_acquire (kernel/locking/lockdep.c:2813 kernel/locking/lockdep.c:3162)
[ 3408.610199] lock_acquire (./arch/x86/include/asm/current.h:14 kernel/locking/lockdep.c:3587)
[ 3408.611069] _raw_spin_lock (include/linux/spinlock_api_smp.h:145 kernel/locking/spinlock.c:151)
[ 3408.611996] rt_mutex_slowlock (kernel/locking/rtmutex.c:1184)
[ 3408.612972] rt_mutex_lock (kernel/locking/rtmutex.c:1402)
[ 3408.613856] rcu_boost_kthread (kernel/rcu/tree_plugin.h:1033 kernel/rcu/tree_plugin.h:1055)
[ 3408.614733] kthread (kernel/kthread.c:209)
[ 3408.615599] ret_from_fork (arch/x86/entry/entry_64.S:469)
[ 3408.628604]    SOFTIRQ-ON-W at:

[ 3408.629055] __lock_acquire (kernel/locking/lockdep.c:2817 kernel/locking/lockdep.c:3162)
[ 3408.630046] lock_acquire (./arch/x86/include/asm/current.h:14 kernel/locking/lockdep.c:3587)
[ 3408.630992] _raw_spin_lock (include/linux/spinlock_api_smp.h:145 kernel/locking/spinlock.c:151)
[ 3408.638480] rt_mutex_slowlock (kernel/locking/rtmutex.c:1184)
[ 3408.640811] rt_mutex_lock (kernel/locking/rtmutex.c:1402)
[ 3408.644207] rcu_boost_kthread (kernel/rcu/tree_plugin.h:1033 kernel/rcu/tree_plugin.h:1055)
[ 3408.647236] kthread (kernel/kthread.c:209)
[ 3408.650140] ret_from_fork (arch/x86/entry/entry_64.S:469)
[ 3408.653122]    INITIAL USE at:

[ 3408.654723] __lock_acquire (kernel/locking/lockdep.c:3166)
[ 3408.656792] lock_acquire (./arch/x86/include/asm/current.h:14 kernel/locking/lockdep.c:3587)
[ 3408.658136] _raw_spin_lock (include/linux/spinlock_api_smp.h:145 kernel/locking/spinlock.c:151)
[ 3408.659612] rt_mutex_slowlock (kernel/locking/rtmutex.c:1184)
[ 3408.660998] rt_mutex_lock (kernel/locking/rtmutex.c:1402)
[ 3408.663768] rcu_boost_kthread (kernel/rcu/tree_plugin.h:1033 kernel/rcu/tree_plugin.h:1055)
[ 3408.672030] kthread (kernel/kthread.c:209)
[ 3408.675053] ret_from_fork (arch/x86/entry/entry_64.S:469)
[ 3408.678075]  }

[ 3408.678996] ... key at: __key.19737 (??:?)
[ 3408.681194]  ... acquired at:

[ 3408.682967] check_irq_usage (kernel/locking/lockdep.c:1649)
[ 3408.684098] __lock_acquire (kernel/locking/lockdep_states.h:7 kernel/locking/lockdep.c:1857 kernel/locking/lockdep.c:1958 kernel/locking/lockdep.c:2144 kernel/locking/lockdep.c:3206)
[ 3408.685496] lock_acquire (./arch/x86/include/asm/current.h:14 kernel/locking/lockdep.c:3587)
[ 3408.686597] _raw_spin_lock (include/linux/spinlock_api_smp.h:145 kernel/locking/spinlock.c:151)
[ 3408.687693] rt_mutex_slowunlock (kernel/locking/rtmutex.c:1266)
[ 3408.688916] rt_mutex_unlock (kernel/locking/rtmutex.c:1384 kernel/locking/rtmutex.c:1486)
[ 3408.690042] rcu_read_unlock_special (kernel/rcu/tree_plugin.h:503)
[ 3408.691451] __rcu_read_unlock (kernel/rcu/update.c:223)
[ 3408.692629] __lock_timer (include/linux/rcupdate.h:495 include/linux/rcupdate.h:930 kernel/time/posix-timers.c:709)
[ 3408.693743] SyS_timer_settime (kernel/time/posix-timers.c:903 kernel/time/posix-timers.c:881)
[ 3408.694978] entry_SYSCALL_64_fastpath (arch/x86/entry/entry_64.S:186)
[ 3408.696162]

[ 3408.696629]

[ 3408.696629] stack backtrace:

[ 3408.697558] CPU: 0 PID: 30907 Comm: trinity-c65 Not tainted 4.4.0-rc8-next-20160111-sasha-00024-g376a9c2-dirty #2782

[ 3408.699544]  1ffff100188b2ecd 000000003efba18a ffff8800c45976e8 ffffffffa401ab02

[ 3408.701068]  0000000041b58ab3 ffffffffaf1b73b8 ffffffffa401aa37 ffff8800c45976e8

[ 3408.702589]  ffffffffa245a127 000000003efba18a 000000005046ad48 0000000000000001

[ 3408.703754] Call Trace:

[ 3408.704185] dump_stack (lib/dump_stack.c:52)
[ 3408.707084] check_usage (kernel/locking/lockdep.c:1561)
[ 3408.714764] check_irq_usage (kernel/locking/lockdep.c:1649)
[ 3408.715747] __lock_acquire (kernel/locking/lockdep_states.h:7 kernel/locking/lockdep.c:1857 kernel/locking/lockdep.c:1958 kernel/locking/lockdep.c:2144 kernel/locking/lockdep.c:3206)
[ 3408.722807] lock_acquire (./arch/x86/include/asm/current.h:14 kernel/locking/lockdep.c:3587)
[ 3408.726723] _raw_spin_lock (include/linux/spinlock_api_smp.h:145 kernel/locking/spinlock.c:151)
[ 3408.728982] rt_mutex_slowunlock (kernel/locking/rtmutex.c:1266)
[ 3408.730066] rt_mutex_unlock (kernel/locking/rtmutex.c:1384 kernel/locking/rtmutex.c:1486)
[ 3408.733192] rcu_read_unlock_special (kernel/rcu/tree_plugin.h:503)
[ 3408.735155] __rcu_read_unlock (kernel/rcu/update.c:223)
[ 3408.736090] __lock_timer (include/linux/rcupdate.h:495 include/linux/rcupdate.h:930 kernel/time/posix-timers.c:709)
[ 3408.737947] SyS_timer_settime (kernel/time/posix-timers.c:903 kernel/time/posix-timers.c:881)
[ 3408.744580] entry_SYSCALL_64_fastpath (arch/x86/entry/entry_64.S:186)