From mboxrd@z Thu Jan 1 00:00:00 1970 From: Dave Jones Subject: lockdep trace from sockstat_seq_show Date: Fri, 22 Feb 2013 12:13:43 -0500 Message-ID: <20130222171343.GB27619@redhat.com> Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii Cc: netdev@vger.kernel.org To: Linux Kernel Return-path: Content-Disposition: inline Sender: linux-kernel-owner@vger.kernel.org List-Id: netdev.vger.kernel.org Just hit this on Linus' current tree. [ 1789.629729] ========================================================= [ 1789.629731] [ INFO: possible irq lock inversion dependency detected ] [ 1789.629736] 3.8.0+ #76 Not tainted [ 1789.629738] --------------------------------------------------------- [ 1789.629742] swapper/0/0 just changed the state of lock: [ 1789.629744] blocked: (&(&q->lock)->rlock){+.-...}, instance: ffff88006c24da58, at: [] ip_expire+0x28/0x220 [ 1789.629762] but this lock took another, SOFTIRQ-unsafe lock in the past: [ 1789.629765] (key#15){+.+...} and interrupts could create inverse lock ordering between them. [ 1789.629772] other info that might help us debug this: [ 1789.629775] Possible interrupt unsafe locking scenario: [ 1789.629778] CPU0 CPU1 [ 1789.629780] ---- ---- [ 1789.629782] lock(key#15); [ 1789.629788] local_irq_disable(); [ 1789.629790] lock(&(&q->lock)->rlock); [ 1789.629794] lock(key#15); [ 1789.629799] [ 1789.629801] lock(&(&q->lock)->rlock); [ 1789.629805] *** DEADLOCK *** [ 1789.629809] 1 lock on stack by swapper/0/0: [ 1789.629812] #0: blocked: (((&q->timer))){+.-...}, instance: ffff880119803dd0, at: [] call_timer_fn+0x5/0x1f0 [ 1789.629826] the shortest dependencies between 2nd lock and 1st lock: [ 1789.629844] -> (key#15){+.+...} ops: 132 { [ 1789.629854] HARDIRQ-ON-W at: [ 1789.629857] [] __lock_acquire+0x64a/0x1cb0 [ 1789.629865] [] lock_acquire+0x96/0x150 [ 1789.629871] [] _raw_spin_lock+0x40/0x80 [ 1789.629878] [] __percpu_counter_sum+0x19/0xc0 [ 1789.629885] [] ip_frag_mem+0x15/0x30 [ 1789.629891] [] sockstat_seq_show+0x128/0x170 [ 1789.629898] [] seq_read+0xcc/0x460 [ 1789.629904] [] proc_reg_read+0x80/0xc0 [ 1789.629910] [] vfs_read+0xac/0x180 [ 1789.629916] [] sys_read+0x55/0xa0 [ 1789.629920] [] system_call_fastpath+0x16/0x1b [ 1789.629926] SOFTIRQ-ON-W at: [ 1789.629929] [] __lock_acquire+0x686/0x1cb0 [ 1789.629935] [] lock_acquire+0x96/0x150 [ 1789.629941] [] _raw_spin_lock+0x40/0x80 [ 1789.629946] [] __percpu_counter_sum+0x19/0xc0 [ 1789.629951] [] ip_frag_mem+0x15/0x30 [ 1789.629957] [] sockstat_seq_show+0x128/0x170 [ 1789.629963] [] seq_read+0xcc/0x460 [ 1789.629968] [] proc_reg_read+0x80/0xc0 [ 1789.629973] [] vfs_read+0xac/0x180 [ 1789.629977] [] sys_read+0x55/0xa0 [ 1789.629981] [] system_call_fastpath+0x16/0x1b [ 1789.629986] INITIAL USE at: [ 1789.629989] [] __lock_acquire+0x30d/0x1cb0 [ 1789.629995] [] lock_acquire+0x96/0x150 [ 1789.630001] [] _raw_spin_lock+0x40/0x80 [ 1789.630006] [] __percpu_counter_sum+0x19/0xc0 [ 1789.630012] [] ip_frag_mem+0x15/0x30 [ 1789.630017] [] sockstat_seq_show+0x128/0x170 [ 1789.630023] [] seq_read+0xcc/0x460 [ 1789.630028] [] proc_reg_read+0x80/0xc0 [ 1789.630033] [] vfs_read+0xac/0x180 [ 1789.630038] [] sys_read+0x55/0xa0 [ 1789.630042] [] system_call_fastpath+0x16/0x1b [ 1789.630047] } [ 1789.630049] ... key at: [] __key.23045+0x0/0x8 [ 1789.630055] ... acquired at: [ 1789.630057] [] lock_acquire+0x96/0x150 [ 1789.630063] [] _raw_spin_lock+0x40/0x80 [ 1789.630068] [] __percpu_counter_add+0x54/0xc0 [ 1789.630073] [] ip_defrag+0x6e4/0xd40 [ 1789.630079] [] ip_local_deliver+0x34/0x2e0 [ 1789.630084] [] ip_rcv+0x36d/0x5c0 [ 1789.630090] [] __netif_receive_skb_core+0x3da/0x6d0 [ 1789.630095] [] __netif_receive_skb+0x21/0x70 [ 1789.630099] [] netif_receive_skb+0x23/0x100 [ 1789.630103] [] ieee80211_deliver_skb.isra.30+0xa3/0x200 [mac80211] [ 1789.630132] [] ieee80211_rx_handlers+0xcae/0x23b0 [mac80211] [ 1789.630152] [] ieee80211_prepare_and_rx_handle+0x1a0/0xb00 [mac80211] [ 1789.630170] [] ieee80211_rx+0x32d/0x910 [mac80211] [ 1789.630188] [] iwlagn_rx_reply_rx+0x3f0/0x760 [iwldvm] [ 1789.630201] [] iwl_rx_dispatch+0xa3/0x110 [iwldvm] [ 1789.630212] [] iwl_pcie_irq_handler+0x93f/0xe00 [iwlwifi] [ 1789.630225] [] irq_thread_fn+0x29/0x50 [ 1789.630232] [] irq_thread+0x12f/0x160 [ 1789.630237] [] kthread+0xed/0x100 [ 1789.630243] [] ret_from_fork+0x7c/0xb0 [ 1789.630251] -> (&(&q->lock)->rlock){+.-...} ops: 18 { [ 1789.630260] HARDIRQ-ON-W at: [ 1789.630264] [] __lock_acquire+0x64a/0x1cb0 [ 1789.630270] [] lock_acquire+0x96/0x150 [ 1789.630276] [] _raw_spin_lock+0x40/0x80 [ 1789.630281] [] ip_defrag+0x11f/0xd40 [ 1789.630287] [] ip_local_deliver+0x34/0x2e0 [ 1789.630292] [] ip_rcv+0x36d/0x5c0 [ 1789.630297] [] __netif_receive_skb_core+0x3da/0x6d0 [ 1789.630301] [] __netif_receive_skb+0x21/0x70 [ 1789.630305] [] netif_receive_skb+0x23/0x100 [ 1789.630310] [] ieee80211_deliver_skb.isra.30+0xa3/0x200 [mac80211] [ 1789.630330] [] ieee80211_rx_handlers+0xcae/0x23b0 [mac80211] [ 1789.630348] [] ieee80211_prepare_and_rx_handle+0x1a0/0xb00 [mac80211] [ 1789.630365] [] ieee80211_rx+0x32d/0x910 [mac80211] [ 1789.630382] [] iwlagn_rx_reply_rx+0x3f0/0x760 [iwldvm] [ 1789.630392] [] iwl_rx_dispatch+0xa3/0x110 [iwldvm] [ 1789.630402] [] iwl_pcie_irq_handler+0x93f/0xe00 [iwlwifi] [ 1789.630412] [] irq_thread_fn+0x29/0x50 [ 1789.630418] [] irq_thread+0x12f/0x160 [ 1789.630423] [] kthread+0xed/0x100 [ 1789.630429] [] ret_from_fork+0x7c/0xb0 [ 1789.630434] IN-SOFTIRQ-W at: [ 1789.630437] [] __lock_acquire+0x603/0x1cb0 [ 1789.630444] [] lock_acquire+0x96/0x150 [ 1789.630449] [] _raw_spin_lock+0x40/0x80 [ 1789.630454] [] ip_expire+0x28/0x220 [ 1789.630460] [] call_timer_fn+0x8a/0x1f0 [ 1789.630466] [] run_timer_softirq+0x234/0x2e0 [ 1789.630471] [] __do_softirq+0xf8/0x2b0 [ 1789.630478] [] call_softirq+0x1c/0x26 [ 1789.630483] [] do_softirq+0xa5/0xe0 [ 1789.630488] [] irq_exit+0xd5/0xe0 [ 1789.630494] [] smp_apic_timer_interrupt+0x6b/0x98 [ 1789.630499] [] apic_timer_interrupt+0x72/0x80 [ 1789.630504] [] cpuidle_enter_tk+0x10/0x20 [ 1789.630510] [] cpuidle_idle_call+0xa5/0x250 [ 1789.630516] [] cpu_idle+0xd5/0x170 [ 1789.630521] [] rest_init+0xc1/0xd0 [ 1789.630528] [] start_kernel+0x403/0x410 [ 1789.630536] [] x86_64_start_reservations+0x2a/0x2c [ 1789.630541] [] x86_64_start_kernel+0xec/0xfb [ 1789.630547] INITIAL USE at: [ 1789.630550] [] __lock_acquire+0x30d/0x1cb0 [ 1789.630556] [] lock_acquire+0x96/0x150 [ 1789.630562] [] _raw_spin_lock+0x40/0x80 [ 1789.630566] [] ip_defrag+0x11f/0xd40 [ 1789.630572] [] ip_local_deliver+0x34/0x2e0 [ 1789.630577] [] ip_rcv+0x36d/0x5c0 [ 1789.630583] [] __netif_receive_skb_core+0x3da/0x6d0 [ 1789.630587] [] __netif_receive_skb+0x21/0x70 [ 1789.630591] [] netif_receive_skb+0x23/0x100 [ 1789.630595] [] ieee80211_deliver_skb.isra.30+0xa3/0x200 [mac80211] [ 1789.630615] [] ieee80211_rx_handlers+0xcae/0x23b0 [mac80211] [ 1789.630631] [] ieee80211_prepare_and_rx_handle+0x1a0/0xb00 [mac80211] [ 1789.630647] [] ieee80211_rx+0x32d/0x910 [mac80211] [ 1789.630664] [] iwlagn_rx_reply_rx+0x3f0/0x760 [iwldvm] [ 1789.630674] [] iwl_rx_dispatch+0xa3/0x110 [iwldvm] [ 1789.630684] [] iwl_pcie_irq_handler+0x93f/0xe00 [iwlwifi] [ 1789.630694] [] irq_thread_fn+0x29/0x50 [ 1789.630700] [] irq_thread+0x12f/0x160 [ 1789.630705] [] kthread+0xed/0x100 [ 1789.630711] [] ret_from_fork+0x7c/0xb0 [ 1789.630716] } [ 1789.630718] ... key at: [] __key.32665+0x0/0x8 [ 1789.630723] ... acquired at: [ 1789.630726] [] check_usage_forwards+0x136/0x140 [ 1789.630732] [] mark_lock+0x176/0x2b0 [ 1789.630737] [] __lock_acquire+0x603/0x1cb0 [ 1789.630743] [] lock_acquire+0x96/0x150 [ 1789.630748] [] _raw_spin_lock+0x40/0x80 [ 1789.630753] [] ip_expire+0x28/0x220 [ 1789.630759] [] call_timer_fn+0x8a/0x1f0 [ 1789.630765] [] run_timer_softirq+0x234/0x2e0 [ 1789.630770] [] __do_softirq+0xf8/0x2b0 [ 1789.630776] [] call_softirq+0x1c/0x26 [ 1789.630781] [] do_softirq+0xa5/0xe0 [ 1789.630785] [] irq_exit+0xd5/0xe0 [ 1789.630791] [] smp_apic_timer_interrupt+0x6b/0x98 [ 1789.630796] [] apic_timer_interrupt+0x72/0x80 [ 1789.630800] [] cpuidle_enter_tk+0x10/0x20 [ 1789.630806] [] cpuidle_idle_call+0xa5/0x250 [ 1789.630811] [] cpu_idle+0xd5/0x170 [ 1789.630816] [] rest_init+0xc1/0xd0 [ 1789.630822] [] start_kernel+0x403/0x410 [ 1789.630828] [] x86_64_start_reservations+0x2a/0x2c [ 1789.630833] [] x86_64_start_kernel+0xec/0xfb [ 1789.630841] stack backtrace: [ 1789.630846] Pid: 0, comm: swapper/0 Not tainted 3.8.0+ #76 [ 1789.630849] Call Trace: [ 1789.630851] [] print_irq_inversion_bug.part.39+0x1b0/0x1bf [ 1789.630865] [] check_usage_forwards+0x136/0x140 [ 1789.630873] [] ? check_usage_backwards+0x140/0x140 [ 1789.630880] [] mark_lock+0x176/0x2b0 [ 1789.630886] [] __lock_acquire+0x603/0x1cb0 [ 1789.630893] [] ? mark_lock+0x213/0x2b0 [ 1789.630900] [] ? __lock_acquire+0xb80/0x1cb0 [ 1789.630907] [] lock_acquire+0x96/0x150 [ 1789.630913] [] ? ip_expire+0x28/0x220 [ 1789.630919] [] ? sched_clock+0x9/0x10 [ 1789.630925] [] ? ip_check_defrag+0x1b0/0x1b0 [ 1789.630931] [] _raw_spin_lock+0x40/0x80 [ 1789.630938] [] ? ip_expire+0x28/0x220 [ 1789.630943] [] ? sched_clock+0x9/0x10 [ 1789.630949] [] ip_expire+0x28/0x220 [ 1789.630956] [] call_timer_fn+0x8a/0x1f0 [ 1789.630961] [] ? call_timer_fn+0x5/0x1f0 [ 1789.630968] [] ? ip_check_defrag+0x1b0/0x1b0 [ 1789.630974] [] run_timer_softirq+0x234/0x2e0 [ 1789.630981] [] ? read_measured_perf_ctrs+0x90/0x90 [ 1789.630987] [] __do_softirq+0xf8/0x2b0 [ 1789.630994] [] ? read_measured_perf_ctrs+0x90/0x90 [ 1789.630999] [] call_softirq+0x1c/0x26 [ 1789.631004] [] do_softirq+0xa5/0xe0 [ 1789.631010] [] irq_exit+0xd5/0xe0 [ 1789.631016] [] smp_apic_timer_interrupt+0x6b/0x98 [ 1789.631022] [] apic_timer_interrupt+0x72/0x80 [ 1789.631024] [] ? leave_mm+0x6f/0xa0 [ 1789.631036] [] ? cpuidle_wrap_enter+0x58/0xa0 [ 1789.631042] [] ? cpuidle_wrap_enter+0x51/0xa0 [ 1789.631049] [] cpuidle_enter_tk+0x10/0x20 [ 1789.631055] [] cpuidle_idle_call+0xa5/0x250 [ 1789.631061] [] cpu_idle+0xd5/0x170 [ 1789.631067] [] rest_init+0xc1/0xd0 [ 1789.631074] [] ? rest_init+0x5/0xd0 [ 1789.631080] [] start_kernel+0x403/0x410 [ 1789.631086] [] ? repair_env_string+0x5e/0x5e [ 1789.631093] [] x86_64_start_reservations+0x2a/0x2c [ 1789.631098] [] x86_64_start_kernel+0xec/0xfb