Re: unpinning an unpinned lock

From: Paul E. McKenney
Date: Tue Sep 15 2015 - 17:42:53 EST

Next message: Alexander Duyck: "Re: First kernel patch (optimization)"
Previous message: Paul E. McKenney: "Re: [4.2] commit d59cfc09c32 (sched, cgroup: replace signal_struct->group_rwsem with a global percpu_rwsem) causes regression for libvirt/kvm"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Mon, Sep 14, 2015 at 04:22:53PM -0700, Tim Spriggs wrote:
> Hello!

Adding Sasha and LKML on CC.

> I noticed some traffic at http://www.gossamer-threads.com/lists/linux/kernel/2229593 that you three generated. Iâve run into a similar issue and Iâm wondering if I can contribute anything with the info I have. Initially I was seeing deadlocks (giant load averages and processes stop responding) and I was able to get a stuck-app stack-traces. They (cron/sshd/â) looked like this:
>
> [71458.731530] Call Trace:
> [71458.734130] [<ffffffff815614ce>] schedule+0x3e/0x90
> [71458.739250] [<ffffffff81561578>] schedule_preempt_disabled+0x18/0x30
> [71458.745857] [<ffffffff81562ee5>] __mutex_lock_slowpath+0x95/0x130
> [71458.752193] [<ffffffff81562f9b>] mutex_lock+0x1b/0x30
> [71458.757490] [<ffffffff810f2bc1>] audit_receive+0x21/0xb0
> [71458.763049] [<ffffffff814cbf05>] netlink_unicast+0x185/0x210
> [71458.768954] [<ffffffff814cccca>] netlink_sendmsg+0x32a/0x3b0
> [71458.774861] [<ffffffff8148695d>] sock_sendmsg+0x4d/0x60
> [71458.780336] [<ffffffff8148861f>] SYSC_sendto+0xef/0x130
> [71458.785806] [<ffffffff8117e679>] ? __handle_mm_fault+0xf9/0x190
> [71458.791970] [<ffffffff8101234b>] ? syscall_trace_enter_phase1+0x13b/0x170
> [71458.799006] [<ffffffff8148866e>] SyS_sendto+0xe/0x10
> [71458.804214] [<ffffffff81565517>] system_call_fastpath+0x12/0x6a
>
> I enabled lock debugging in the kernel and ran it across a bunch of nodes and waited for call traces. After the weekend, I found 3 distinct traces on 16 nodes.
>
> All nodes report from: kernel/locking/lockdep.c:3497 lock_unpin_lock+0xed/0xf0()

Dave Jones was seeing lock_unpin_lock(), IIRC. Me, I was seeing
infrequent silent hangs.

Thanx, Paul

> All nodes state: unpinning an unpinned lock
>
> All nodes have these modules linked in: ahci(E) dca(E) dm_log(E) dm_mirror(E) dm_mod(E) dm_region_hash(E) hwmon(E) i2c_algo_bit(E) i2c_core(E) i2c_i801(E) iTCO_vendor_support(E) iTCO_wdt(E) igb(E) ioatdma(E) ipmi_msghandler(E) ipmi_si(E) ipmi_ssif(E) ixgbe(E) libahci(E) lpc_ich(E) mdio(E) mfd_core(E) microcode(E) overlay(E) pps_core(E) ptp(E) sb_edac(E) sd_mod(E) sg(E) vxlan(E) wmi(E) xhci_hcd(E) xhci_pci(E)
>
> There was one variation on Workqueue:
> 15 Workqueue: events key_garbage_collector
> 1 Workqueue: kdmflush dm_wq_work [dm_mod]
>
> Iâm hoping that the extra info will help in your debugging/tracing this error down.
>
> Cheers,
> -Tim
>
> â
>
> [<ffffffff816b2a4e>] dump_stack+0x48/0x5a
> [<ffffffff81053545>] warn_slowpath_common+0x95/0xe0
> [<ffffffff81053646>] warn_slowpath_fmt+0x46/0x50
> [<ffffffff810a49dd>] lock_unpin_lock+0xed/0xf0
> [<ffffffff810962f1>] pick_next_task_fair+0x51/0x220
> [<ffffffff816b2c9c>] __schedule+0x12c/0x990
> [<ffffffff810a9eab>] ? __lock_acquire+0x3ab/0x560
> [<ffffffff816b367e>] schedule+0x3e/0x80
> [<ffffffff816b74d6>] schedule_timeout+0x1c6/0x220
> [<ffffffff816b4711>] ? wait_for_completion+0x91/0x110
> [<ffffffff810a8920>] ? mark_held_locks+0x70/0x90
> [<ffffffff816b8910>] ? _raw_spin_unlock_irq+0x30/0x40
> [<ffffffff810a8bef>] ? trace_hardirqs_on_caller+0xff/0x1c0
> [<ffffffff816b4719>] wait_for_completion+0x99/0x110
> [<ffffffff810875e0>] ? try_to_wake_up+0x2e0/0x2e0
> [<ffffffff810bed00>] ? __call_rcu.clone.0+0x1a0/0x1a0
> [<ffffffff810bb760>] wait_rcu_gp+0x50/0x60
> [<ffffffff810bb770>] ? wait_rcu_gp+0x60/0x60
> [<ffffffff810c02f7>] synchronize_sched+0x47/0xb0
> [<ffffffff813412dd>] key_garbage_collector+0x19d/0x3e0
> [<ffffffff8106f95f>] process_one_work+0x1df/0x570
> [<ffffffff8106f8e0>] ? process_one_work+0x160/0x570
> [<ffffffff8106fe81>] ? worker_thread+0x191/0x420
> [<ffffffff816b8910>] ? _raw_spin_unlock_irq+0x30/0x40
> [<ffffffff8106fe0d>] worker_thread+0x11d/0x420
> [<ffffffff810a8cbd>] ? trace_hardirqs_on+0xd/0x10
> [<ffffffff8106fcf0>] ? process_one_work+0x570/0x570
> [<ffffffff8106fcf0>] ? process_one_work+0x570/0x570
> [<ffffffff81076a5e>] kthread+0xde/0x100
> [<ffffffff81080e6e>] ? schedule_tail+0x1e/0xd0
> [<ffffffff81076980>] ? __init_kthread_worker+0x70/0x70
> [<ffffffff816b914f>] ret_from_fork+0x3f/0x70
> [<ffffffff81076980>] ? __init_kthread_worker+0x70/0x70
>
> (â and a diff -u variation on this)
>
> @@ -5,6 +5,7 @@
> [<ffffffff810a49dd>] lock_unpin_lock+0xed/0xf0
> [<ffffffff810962f1>] pick_next_task_fair+0x51/0x220
> [<ffffffff816b2c9c>] __schedule+0x12c/0x990
> + [<ffffffff810aa247>] ? __lock_release+0xc7/0x390
> [<ffffffff810a9eab>] ? __lock_acquire+0x3ab/0x560
> [<ffffffff816b367e>] schedule+0x3e/0x80
> [<ffffffff816b74d6>] schedule_timeout+0x1c6/0x220
>
> â
>
> [<ffffffff816b2a4e>] dump_stack+0x48/0x5a
> [<ffffffff81053545>] warn_slowpath_common+0x95/0xe0
> [<ffffffff81053646>] warn_slowpath_fmt+0x46/0x50
> [<ffffffff810a49dd>] lock_unpin_lock+0xed/0xf0
> [<ffffffff816b2f21>] __schedule+0x3b1/0x990
> [<ffffffff810a8920>] ? mark_held_locks+0x70/0x90
> [<ffffffff816b8910>] ? _raw_spin_unlock_irq+0x30/0x40
> [<ffffffff816b367e>] schedule+0x3e/0x80
> [<ffffffffa0269a45>] get_active_stripe+0x295/0x430 [raid456]
> [<ffffffff8109d1a0>] ? woken_wake_function+0x20/0x20
> [<ffffffffa0271e5e>] make_request+0x1ee/0x670 [raid456]
> [<ffffffff81547446>] ? md_make_request+0x1d6/0x480
> [<ffffffff8109d1a0>] ? woken_wake_function+0x20/0x20
> [<ffffffff81370aea>] ? generic_make_request_checks+0x15a/0x3e0
> [<ffffffff81547446>] md_make_request+0x1d6/0x480
> [<ffffffff815472c3>] ? md_make_request+0x53/0x480
> [<ffffffff81163345>] ? mempool_alloc_slab+0x15/0x20
> [<ffffffff81163499>] ? mempool_alloc+0x59/0x160
> [<ffffffff81370e21>] generic_make_request+0xb1/0xe0
> [<ffffffffa000301e>] __map_bio+0xbe/0x130 [dm_mod]
> [<ffffffffa0003352>] __clone_and_map_data_bio+0x112/0x130 [dm_mod]
> [<ffffffffa00033dc>] __split_and_process_non_flush+0x6c/0xb0 [dm_mod]
> [<ffffffffa0004c47>] __split_and_process_bio+0x207/0x2c0 [dm_mod]
> [<ffffffffa0004a65>] ? __split_and_process_bio+0x25/0x2c0 [dm_mod]
> [<ffffffff816b8910>] ? _raw_spin_unlock_irq+0x30/0x40
> [<ffffffffa0004e8f>] dm_wq_work+0xbf/0xe0 [dm_mod]
> [<ffffffff8106f95f>] process_one_work+0x1df/0x570
> [<ffffffff8106f8e0>] ? process_one_work+0x160/0x570
> [<ffffffff8106fe81>] ? worker_thread+0x191/0x420
> [<ffffffff816b8910>] ? _raw_spin_unlock_irq+0x30/0x40
> [<ffffffff8106fe0d>] worker_thread+0x11d/0x420
> [<ffffffff810a8cbd>] ? trace_hardirqs_on+0xd/0x10
> [<ffffffff8106fcf0>] ? process_one_work+0x570/0x570
> [<ffffffff8106fcf0>] ? process_one_work+0x570/0x570
> [<ffffffff81076a5e>] kthread+0xde/0x100
> [<ffffffff81080e6e>] ? schedule_tail+0x1e/0xd0
> [<ffffffff81076980>] ? __init_kthread_worker+0x70/0x70
> [<ffffffff816b914f>] ret_from_fork+0x3f/0x70
> [<ffffffff81076980>] ? __init_kthread_worker+0x70/0x70
>
> â
>
> [<ffffffff816b2a4e>] dump_stack+0x48/0x5a
> [<ffffffff81053545>] warn_slowpath_common+0x95/0xe0
> [<ffffffff81053646>] warn_slowpath_fmt+0x46/0x50
> [<ffffffff810a49dd>] lock_unpin_lock+0xed/0xf0
> [<ffffffff810962f1>] pick_next_task_fair+0x51/0x220
> [<ffffffff816b2c9c>] __schedule+0x12c/0x990
> [<ffffffff810aa247>] ? __lock_release+0xc7/0x390
> [<ffffffff810a9eab>] ? __lock_acquire+0x3ab/0x560
> [<ffffffff816b367e>] schedule+0x3e/0x80
> [<ffffffff816b74d6>] schedule_timeout+0x1c6/0x220
> [<ffffffff816b4711>] ? wait_for_completion+0x91/0x110
> [<ffffffff810a8920>] ? mark_held_locks+0x70/0x90
> [<ffffffff816b8910>] ? _raw_spin_unlock_irq+0x30/0x40
> [<ffffffff810a8bef>] ? trace_hardirqs_on_caller+0xff/0x1c0
> [<ffffffff816b4719>] wait_for_completion+0x99/0x110
> [<ffffffff810875e0>] ? try_to_wake_up+0x2e0/0x2e0
> [<ffffffff810bed00>] ? __call_rcu.clone.0+0x1a0/0x1a0
> [<ffffffff810bb760>] wait_rcu_gp+0x50/0x60
> [<ffffffff810bb770>] ? wait_rcu_gp+0x60/0x60
> [<ffffffff810c02f7>] synchronize_sched+0x47/0xb0
> [<ffffffff813412dd>] key_garbage_collector+0x19d/0x3e0
> [<ffffffff8106f95f>] process_one_work+0x1df/0x570
> [<ffffffff8106f8e0>] ? process_one_work+0x160/0x570
> [<ffffffff8106fe81>] ? worker_thread+0x191/0x420
> [<ffffffff816b8910>] ? _raw_spin_unlock_irq+0x30/0x40
> [<ffffffff8106fef8>] worker_thread+0x208/0x420
> [<ffffffff810a8cbd>] ? trace_hardirqs_on+0xd/0x10
> [<ffffffff8106fcf0>] ? process_one_work+0x570/0x570
> [<ffffffff8106fcf0>] ? process_one_work+0x570/0x570
> [<ffffffff81076a5e>] kthread+0xde/0x100
> [<ffffffff81080e6e>] ? schedule_tail+0x1e/0xd0
> [<ffffffff81076980>] ? __init_kthread_worker+0x70/0x70
> [<ffffffff816b914f>] ret_from_fork+0x3f/0x70
> [<ffffffff81076980>] ? __init_kthread_worker+0x70/0x70
>

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Next message: Alexander Duyck: "Re: First kernel patch (optimization)"
Previous message: Paul E. McKenney: "Re: [4.2] commit d59cfc09c32 (sched, cgroup: replace signal_struct->group_rwsem with a global percpu_rwsem) causes regression for libvirt/kvm"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]