* [2.6.35-rc3] NFS: possible irq lock inversion dependency
@ 2010-06-24 11:53 Tetsuo Handa
2010-09-07 12:32 ` [2.6.36-rc3] " Tetsuo Handa
0 siblings, 1 reply; 24+ messages in thread
From: Tetsuo Handa @ 2010-06-24 11:53 UTC (permalink / raw)
To: linux-fsdevel, netdev
Hello.
I sometimes get below warning when the system is about to reboot/halt.
Is this already reported? If not, I'll try to establish steps to reproduce.
----- Dump 1 -----
[ 508.594713] nfsd: last server has exited, flushing export cache
[ 509.100525]
[ 509.100529] =========================================================
[ 509.102129] [ INFO: possible irq lock inversion dependency detected ]
<4>[ 509.102513] [<c103f69f>] sys_exit_group+0xf/0x20
<4>[ 509.102513] [<c13327e1>] syscall_call+0x7/0xb
[ 509.102513] }
[ 509.102513] ... key at: [<c1cbfd90>] af_callback_keys+0x10/0x130
[ 509.102513] ... acquired at:
[ 509.102513] [<c10656c6>] check_usage_backwards+0x76/0xd0
[ 509.102513] [<c10658d9>] mark_lock_irq+0x99/0x240
[ 509.102513] [<c106657c>] mark_lock+0x21c/0x3c0
[ 509.102513] [<c1066242>] mark_irqflags+0xe2/0x180
[ 509.102513] [<c1066fdd>] __lock_acquire+0x38d/0x8e0
[ 509.102513] [<c106857a>] lock_acquire+0x7a/0xa0
[ 509.102513] [<c1331f69>] _raw_read_lock+0x39/0x70
[ 509.102513] [<c130a0ae>] xs_tcp_state_change+0x1e/0x1c0
[ 509.102513] [<c12e2397>] inet_shutdown+0x97/0x110
[ 509.102513] [<c1289649>] kernel_sock_shutdown+0x9/0x10
[ 509.102513] [<c13093a7>] xs_tcp_shutdown+0x17/0x20
[ 509.102513] [<c13096a7>] xs_tcp_close+0x27/0x30
[ 509.102513] [<c130792d>] xprt_autoclose+0x1d/0x50
[ 509.102513] [<c104edc0>] run_workqueue+0xe0/0x1d0
[ 509.102513] [<c104ef4b>] worker_thread+0x9b/0xd0
[ 509.102513] [<c1052a65>] kthread+0x75/0x80
[ 509.102513] [<c100317a>] kernel_thread_helper+0x6/0x1c
[ 509.102513]
[ 509.102513]
[ 509.102513] stack backtrace:
[ 509.102513] Pid: 337, comm: rpciod/1 Not tainted 2.6.35-rc3-ccs #6
[ 509.102513] Call Trace:
[ 509.102513] [<c103cbe8>] ? printk+0x18/0x20
[ 509.102513] [<c1065558>] print_irq_inversion_bug+0x108/0x120
[ 509.102513] [<c10656c6>] check_usage_backwards+0x76/0xd0
[ 509.102513] [<c10658d9>] mark_lock_irq+0x99/0x240
[ 509.102513] [<c1065650>] ? check_usage_backwards+0x0/0xd0
[ 509.102513] [<c106657c>] mark_lock+0x21c/0x3c0
[ 509.102513] [<c1066242>] mark_irqflags+0xe2/0x180
[ 509.102513] [<c1066fdd>] __lock_acquire+0x38d/0x8e0
[ 509.102513] [<c10682da>] ? __lock_is_held+0x3a/0x60
[ 509.102513] [<c106857a>] lock_acquire+0x7a/0xa0
[ 509.102513] [<c130a0ae>] ? xs_tcp_state_change+0x1e/0x1c0
[ 509.102513] [<c1331f69>] _raw_read_lock+0x39/0x70
[ 509.102513] [<c130a0ae>] ? xs_tcp_state_change+0x1e/0x1c0
[ 509.102513] [<c130a0ae>] xs_tcp_state_change+0x1e/0x1c0
[ 509.102513] [<c12cf3bf>] ? tcp_send_fin+0x4f/0xc0
[ 509.102513] [<c12e2397>] inet_shutdown+0x97/0x110
[ 509.102513] [<c104ed5e>] ? run_workqueue+0x7e/0x1d0
[ 509.102513] [<c1289649>] kernel_sock_shutdown+0x9/0x10
[ 509.102513] [<c13093a7>] xs_tcp_shutdown+0x17/0x20
[ 509.102513] [<c13096a7>] xs_tcp_close+0x27/0x30
[ 509.102513] [<c130792d>] xprt_autoclose+0x1d/0x50
[ 509.102513] [<c104edc0>] run_workqueue+0xe0/0x1d0
[ 509.102513] [<c104ed5e>] ? run_workqueue+0x7e/0x1d0
[ 509.102513] [<c1307910>] ? xprt_autoclose+0x0/0x50
[ 509.102513] [<c1052e8a>] ? prepare_to_wait+0x3a/0x60
[ 509.102513] [<c104ef4b>] worker_thread+0x9b/0xd0
[ 509.102513] [<c1053000>] ? autoremove_wake_function+0x0/0x50
[ 509.102513] [<c1053000>] ? autoremove_wake_function+0x0/0x50
[ 509.102513] [<c1035456>] ? complete+0x46/0x60
[ 509.102513] [<c1052a65>] kthread+0x75/0x80
[ 509.102513] [<c104eeb0>] ? worker_thread+0x0/0xd0
[ 509.102513] [<c10529f0>] ? kthread+0x0/0x80
[ 509.102513] [<c10529f0>] ? kthread+0x0/0x80
[ 509.102513] [<c100317a>] kernel_thread_helper+0x6/0x1c
9>] _raw_spin_lock+0x39/0x70
[ 509.102513] [<c128ae51>] sk_clone+0xb1/0x2c0
[ 509.102513] [<c12c0046>] inet_csk_clone+0x16/0x90
[ 509.102513] [<c12d519c>] tcp_create_openreq_child+0x1c/0x460
[ 509.102513] [<c12d2a1f>] tcp_v4_syn_recv_sock+0x3f/0x1e0
[ 509.102513] [<c12d576c>] tcp_check_req+0x18c/0x3b0
[ 509.102513] [<c12d2c0d>] tcp_v4_hnd_req+0x4d/0x160
[ 509.102513] [<c12d2f39>] tcp_v4_do_rcv+0x159/0x280
[ 509.102513] [<c12d35d4>] tcp_v4_rcv+0x574/0xa30
[ 509.102513] [<c12b5c4f>] ip_local_deliver_finish+0xff/0x2c0
[ 509.102513] [<c12b5e40>] ip_local_deliver+0x30/0x40
[ 509.102513] [<c12b5f99>] ip_rcv_finish+0x149/0x440
[ 509.102513] [<c12b63f6>] ip_rcv+0x166/0x240
[ 509.102513] [<c1297b0d>] __netif_receive_skb+0x1cd/0x280
[ 509.102513] [<c12985e8>] process_backlog+0x88/0x160
[ 509.102513] [<c12989b7>] net_rx_action+0x127/0x140
[ 509.102513] [<c1041b30>] __do_softirq+0xd0/0x130
[ 509.102513] INITIAL USE at:
[ 509.102513] [<c1066e16>] __lock_acquire+0x1c6/0x8e0
[ 509.102513] [<c106857a>] lock_acquire+0x7a/0xa0
[ 509.102513] [<c1331dbe>] _raw_spin_lock_bh+0x3e/0x80
[ 509.102513] [<c128c4c9>] lock_sock_fast+0x29/0x90
[ 509.102513] [<c12dae84>] udp_destroy_sock+0x14/0x40
[ 509.102513] [<c128c823>] sk_common_release+0xb3/0xc0
[ 509.102513] [<c12db7f8>] udp_lib_close+0x8/0x10
[ 509.102513] [<c12e18ce>] inet_release+0xbe/0x100
[ 509.102513] [<c1286c36>] sock_release+0x66/0x80
[ 509.102513] [<c1287952>] sock_close+0x12/0x30
[ 509.102513] [<c10b705b>] __fput+0x1cb/0x210
[ 509.102513] [<c10b70b9>] fput+0x19/0x20
[ 509.102513] [<c10b54f3>] filp_close+0x43/0x70
[ 509.102513] [<c103eafb>] close_files+0xab/0x140
[ 509.102513] [<c103ebf9>] put_files_struct+0x29/0xf0
[ 509.102513] [<c103ed50>] exit_files+0x40/0x50
[ 509.102513] [<c103f400>] do_exit+0x100/0x2b0
[ 509.102513] [<c103f614>] do_group_exit+0x34/0xb0
[ 509.102513] [<c103f69f>] sys_exit_group+0xf/0x20
[ 509.102513] [<c13327e1>] syscall_call+0x7/0xb
[ 509.102513] }
[ 509.102513] ... key at: [<c1cbfc50>] af_family_slock_keys+0x10/0x140
[ 509.102513] ... acquired at:
[ 509.102513] [<c1064a8b>] check_prevs_add+0xab/0x100
[ 509.102513] [<c1064e15>] validate_chain+0x305/0x5a0
[ 509.102513] [<c1066f03>] __lock_acquire+0x2b3/0x8e0
[ 509.102513] [<c106857a>] lock_acquire+0x7a/0xa0
[ 509.102513] [<c13323fe>] _raw_write_lock_bh+0x3e/0x80
[ 509.102513] [<c12c0356>] inet_csk_listen_stop+0x86/0x160
[ 509.102513] [<c12c2dc0>] tcp_close+0x350/0x360
[ 509.102513] [<c12e18ce>] inet_release+0xbe/0x100
[ 509.102513] [<c1286c36>] sock_release+0x66/0x80
[ 509.102513] [<c1287952>] sock_close+0x12/0x30
[ 509.102513] [<c10b705b>] __fput+0x1cb/0x210
[ 509.102513] [<c10b70b9>] fput+0x19/0x20
[ 509.102513] [<c10b54f3>] filp_close+0x43/0x70
[ 509.102513] [<c10b558d>] sys_close+0x6d/0x100
[ 509.102513] [<c13327e1>] syscall_call+0x7/0xb
[ 509.102513]
[ 509.102513] -> (clock-AF_INET){++.?..} ops: 877 {
[ 509.102513] HARDIRQ-ON-W at:
[ 509.102513] [<c106625e>] mark_irqflags+0xfe/0x180
[ 509.102513] [<c1066fdd>] __lock_acquire+0x38d/0x8e0
[ 509.102513] [<c106857a>] lock_acquire+0x7a/0xa0
[ 509.102513] [<c13323fe>] _raw_write_lock_bh+0x3e/0x80
[ 509.102513] [<c128c79f>] sk_common_release+0x2f/0xc0
[ 509.102513] [<c12db7f8>] udp_lib_close+0x8/0x10
[ 509.102513] [<c12e18ce>] inet_release+0xbe/0x100
[ 509.102513] [<c1286c36>] sock_release+0x66/0x80
[ 509.102513] [<c1287952>] sock_close+0x12/0x30
[ 509.102513] [<c10b705b>] __fput+0x1cb/0x210
[ 509.102513] [<c10b70b9>] fput+0x19/0x20
[ 509.102513] [<c10b54f3>] filp_close+0x43/0x70
[ 509.102513] [<c103eafb>] close_files+0xab/0x140
[ 509.102513] [<c103ebf9>] put_files_struct+0x29/0xf0
[ 509.102513] [<c103ed50>] exit_files+0x40/0x50
[ 509.102513] [<c103f400>] do_exit+0x100/0x2b0
[ 509.102513] [<c103f614>] do_group_exit+0x34/0xb0
[ 509.102513] [<c103f69f>] sys_exit_group+0xf/0x20
[ 509.102513] [<c13327e1>] syscall_call+0x7/0xb
[ 509.102513] HARDIRQ-ON-R at:
[ 509.102513] [<c10661ce>] mark_irqflags+0x6e/0x180
[ 509.102513] [<c1066fdd>] __lock_acquire+0x38d/0x8e0
[ 509.102513] [<c106857a>] lock_acquire+0x7a/0xa0
[ 509.102513] [<c1331f69>] _raw_read_lock+0x39/0x70
[ 509.102513] [<c130a0ae>] xs_tcp_state_change+0x1e/0x1c0
[ 509.102513] [<c12cbea8>] tcp_rcv_synsent_state_process+0x388/0x580
[ 509.102513] [<c12cc547>] tcp_rcv_state_process+0x4a7/0x560
[ 509.102513] [<c12d2e51>] tcp_v4_do_rcv+0x71/0x280
[ 509.102513] [<c128b786>] __release_sock+0x66/0x150
[ 509.102513] [<c128c497>] release_sock+0x87/0x90
[ 509.102513] [<c12e1cba>] inet_stream_connect+0x5a/0x1b0
[ 509.102513] [<c1289448>] kernel_connect+0x18/0x30
[ 509.102513] [<c130acce>] xs_tcp_finish_connecting+0x4e/0x120
[ 509.102513] [<c130adfb>] xs_tcp_setup_socket+0x5b/0x180
[ 509.102513] [<c130b034>] xs_tcp_connect_worker4+0x14/0x20
[ 509.102513] [<c104edc0>] run_workqueue+0xe0/0x1d0
[ 509.102513] [<c104ef4b>] worker_thread+0x9b/0xd0
[ 509.102513] [<c1052a65>] kthread+0x75/0x80
[ 509.102513] [<c100317a>] kernel_thread_helper+0x6/0x1c
[ 509.102513] IN-SOFTIRQ-R at:
[ 509.102513] [<c106627e>] mark_irqflags+0x11e/0x180
[ 509.102513] [<c1066fdd>] __lock_acquire+0x38d/0x8e0
[ 509.102513] [<c106857a>] lock_acquire+0x7a/0xa0
[ 509.102513] [<c1331f69>] _raw_read_lock+0x39/0x70
[ 509.102513] [<c1309f81>] xs_tcp_data_ready+0x21/0x90
[ 509.102513] [<c12ca378>] tcp_data_queue+0x248/0x820
[ 509.102513] [<c12cb6ee>] tcp_rcv_established+0xae/0x4e0
[ 509.102513] [<c12d2fb1>] tcp_v4_do_rcv+0x1d1/0x280
[ 509.102513] [<c12d35d4>] tcp_v4_rcv+0x574/0xa30
[ 509.102513] [<c12b5c4f>] ip_local_deliver_finish+0xff/0x2c0
[ 509.102513] [<c12b5e40>] ip_local_deliver+0x30/0x40
[ 509.102513] [<c12b5f99>] ip_rcv_finish+0x149/0x440
[ 509.102513] [<c12b63f6>] ip_rcv+0x166/0x240
[ 509.102513] [<c1297b0d>] __netif_receive_skb+0x1cd/0x280
[ 509.102513] [<c12985e8>] process_backlog+0x88/0x160
[ 509.102513] [<c12989b7>] net_rx_action+0x127/0x140
[ 509.102513] [<c1041b30>] __do_softirq+0xd0/0x130
[ 509.102513] SOFTIRQ-ON-R at:
[ 509.102513] [<c1066242>] mark_irqflags+0xe2/0x180
[ 509.102513] [<c1066fdd>] __lock_acquire+0x38d/0x8e0
[ 509.102513] [<c106857a>] lock_acquire+0x7a/0xa0
[ 509.102513] [<c1331f69>] _raw_read_lock+0x39/0x70
[ 509.102513] [<c130a0ae>] xs_tcp_state_change+0x1e/0x1c0
[ 509.102513] [<c12e2397>] inet_shutdown+0x97/0x110
[ 509.102513] [<c1289649>] kernel_sock_shutdown+0x9/0x10
[ 509.102513] [<c13093a7>] xs_tcp_shutdown+0x17/0x20
[ 509.102513] [<c13096a7>] xs_tcp_close+0x27/0x30
[ 509.102513] [<c130792d>] xprt_autoclose+0x1d/0x50
[ 509.102513] [<c104edc0>] run_workqueue+0xe0/0x1d0
[ 509.102513] [<c104ef4b>] worker_thread+0x9b/0xd0
[ 509.102513] [<c1052a65>] kthread+0x75/0x80
[ 509.102513] [<c100317a>] kernel_thread_helper+0x6/0x1c
[ 509.102513] INITIAL USE at:
[ 509.102513] [<c1066e16>] __lock_acquire+0x1c6/0x8e0
[ 509.102513] [<c106857a>] lock_acquire+0x7a/0xa0
[ 509.102513] [<c13323fe>] _raw_write_lock_bh+0x3e/0x80
[ 509.102513] [<c128c79f>] sk_common_release+0x2f/0xc0
[ 509.102513] [<c12db7f8>] udp_lib_close+0x8/0x10
[ 509.102513] [<c12e18ce>] inet_release+0xbe/0x100
[ 509.102513] [<c1286c36>] sock_release+0x66/0x80
[ 509.102513] [<c1287952>] sock_close+0x12/0x30
[ 509.102513] [<c10b705b>] __fput+0x1cb/0x210
[ 509.102513] [<c10b70b9>] fput+0x19/0x20
[ 509.102513] [<c10b54f3>] filp_close+0x43/0x70
[ 509.102513] [<c103eafb>] close_files+0xab/0x140
[ 509.102513] [<c103ebf9>] put_files_struct+0x29/0xf0
[ 509.102513] [<c103ed50>] exit_files+0x40/0x50
[ 509.102513] [<c103f400>] do_exit+0x100/0x2b0
[ 509.102513] [<c103f614>] do_group_exit+0x34/0xb0
[ 509.102513] [<c103f69f>] sys_exit_group+0xf/0x20
[ 509.102513] [<c13327e1>] syscall_call+0x7/0xb
[ 509.102513] }
[ 509.102513] ... key at: [<c1cbfd90>] af_callback_keys+0x10/0x130
[ 509.102513] ... acquired at:
[ 509.102513] [<c10656c6>] check_usage_backwards+0x76/0xd0
[ 509.102513] [<c10658d9>] mark_lock_irq+0x99/0x240
[ 509.102513] [<c106657c>] mark_lock+0x21c/0x3c0
[ 509.102513] [<c1066242>] mark_irqflags+0xe2/0x180
[ 509.102513] [<c1066fdd>] __lock_acquire+0x38d/0x8e0
[ 509.102513] [<c106857a>] lock_acquire+0x7a/0xa0
[ 509.102513] [<c1331f69>] _raw_read_lock+0x39/0x70
[ 509.102513] [<c130a0ae>] xs_tcp_state_change+0x1e/0x1c0
[ 509.102513] [<c12e2397>] inet_shutdown+0x97/0x110
[ 509.102513] [<c1289649>] kernel_sock_shutdown+0x9/0x10
[ 509.102513] [<c13093a7>] xs_tcp_shutdown+0x17/0x20
[ 509.102513] [<c13096a7>] xs_tcp_close+0x27/0x30
[ 509.102513] [<c130792d>] xprt_autoclose+0x1d/0x50
[ 509.102513] [<c104edc0>] run_workqueue+0xe0/0x1d0
[ 509.102513] [<c104ef4b>] worker_thread+0x9b/0xd0
[ 509.102513] [<c1052a65>] kthread+0x75/0x80
[ 509.102513] [<c100317a>] kernel_thread_helper+0x6/0x1c
[ 509.102513]
[ 509.102513]
[ 509.102513] stack backtrace:
[ 509.102513] Pid: 337, comm: rpciod/1 Not tainted 2.6.35-rc3-ccs #6
[ 509.102513] Call Trace:
[ 509.102513] [<c103cbe8>] ? printk+0x18/0x20
[ 509.102513] [<c1065558>] print_irq_inversion_bug+0x108/0x120
[ 509.102513] [<c10656c6>] check_usage_backwards+0x76/0xd0
[ 509.102513] [<c10658d9>] mark_lock_irq+0x99/0x240
[ 509.102513] [<c1065650>] ? check_usage_backwards+0x0/0xd0
[ 509.102513] [<c106657c>] mark_lock+0x21c/0x3c0
[ 509.102513] [<c1066242>] mark_irqflags+0xe2/0x180
[ 509.102513] [<c1066fdd>] __lock_acquire+0x38d/0x8e0
[ 509.102513] [<c10682da>] ? __lock_is_held+0x3a/0x60
[ 509.102513] [<c106857a>] lock_acquire+0x7a/0xa0
[ 509.102513] [<c130a0ae>] ? xs_tcp_state_change+0x1e/0x1c0
[ 509.102513] [<c1331f69>] _raw_read_lock+0x39/0x70
[ 509.102513] [<c130a0ae>] ? xs_tcp_state_change+0x1e/0x1c0
[ 509.102513] [<c130a0ae>] xs_tcp_state_change+0x1e/0x1c0
[ 509.102513] [<c12cf3bf>] ? tcp_send_fin+0x4f/0xc0
[ 509.102513] [<c12e2397>] inet_shutdown+0x97/0x110
[ 509.102513] [<c104ed5e>] ? run_workqueue+0x7e/0x1d0
[ 509.102513] [<c1289649>] kernel_sock_shutdown+0x9/0x10
[ 509.102513] [<c13093a7>] xs_tcp_shutdown+0x17/0x20
[ 509.102513] [<c13096a7>] xs_tcp_close+0x27/0x30
[ 509.102513] [<c130792d>] xprt_autoclose+0x1d/0x50
[ 509.102513] [<c104edc0>] run_workqueue+0xe0/0x1d0
[ 509.102513] [<c104ed5e>] ? run_workqueue+0x7e/0x1d0
[ 509.102513] [<c1307910>] ? xprt_autoclose+0x0/0x50
[ 509.102513] [<c1052e8a>] ? prepare_to_wait+0x3a/0x60
[ 509.102513] [<c104ef4b>] worker_thread+0x9b/0xd0
[ 509.102513] [<c1053000>] ? autoremove_wake_function+0x0/0x50
[ 509.102513] [<c1053000>] ? autoremove_wake_function+0x0/0x50
[ 509.102513] [<c1035456>] ? complete+0x46/0x60
[ 509.102513] [<c1052a65>] kthread+0x75/0x80
[ 509.102513] [<c104eeb0>] ? worker_thread+0x0/0xd0
[ 509.102513] [<c10529f0>] ? kthread+0x0/0x80
[ 509.102513] [<c10529f0>] ? kthread+0x0/0x80
[ 509.102513] [<c100317a>] kernel_thread_helper+0x6/0x1c
[ 518.099361] ACPI: Preparing to enter system sleep state S5
[ 518.101223] Disabling non-boot CPUs ...
[ 518.607480] lockdep: fixing up alternatives.
[ 518.608334] SMP alternatives: switching to UP code
[ 518.908243] Power down.
[ 518.909864] acpi_power_off called
----- Dump 2 -----
[ 974.096047] nfsd: last server has exited, flushing export cache
[ 975.514620]
[ 975.514622] =========================================================
[ 975.516172] [ INFO: possible irq lock inversion dependency detected ]
x34/0xb0
<4>[ 975.517504] [<c103f69f>] sys_exit_group+0xf/0x20
[ 975.517507] [<c13327e1>] syscall_call+0x7/0xb
[ 975.517510] }
[ 975.517511] ... key at: [<c1cbfd90>] af_callback_keys+0x10/0x130
[ 975.517513] ... acquired at:
[ 975.517515] [<c10656c6>] check_usage_backwards+0x76/0xd0
[ 975.517517] [<c10658d9>] mark_lock_irq+0x99/0x240
[ 975.517519] [<c106657c>] mark_lock+0x21c/0x3c0
[ 975.517522] [<c1066242>] mark_irqflags+0xe2/0x180
[ 975.517524] [<c1066fdd>] __lock_acquire+0x38d/0x8e0
[ 975.517526] [<c106857a>] lock_acquire+0x7a/0xa0
[ 975.517529] [<c1331f69>] _raw_read_lock+0x39/0x70
[ 975.517531] [<c130a0ae>] xs_tcp_state_change+0x1e/0x1c0
[ 975.517534] [<c12e2397>] inet_shutdown+0x97/0x110
[ 975.517536] [<c1289649>] kernel_sock_shutdown+0x9/0x10
[ 975.517539] [<c13093a7>] xs_tcp_shutdown+0x17/0x20
[ 975.517541] [<c13096a7>] xs_tcp_close+0x27/0x30
[ 975.517544] [<c130792d>] xprt_autoclose+0x1d/0x50
[ 975.517546] [<c104edc0>] run_workqueue+0xe0/0x1d0
[ 975.517549] [<c104ef4b>] worker_thread+0x9b/0xd0
[ 975.517551] [<c1052a65>] kthread+0x75/0x80
[ 975.517553] [<c100317a>] kernel_thread_helper+0x6/0x1c
[ 975.517556]
[ 975.517570]
[ 975.517571] stack backtrace:
[ 975.517628] Pid: 337, comm: rpciod/1 Not tainted 2.6.35-rc3-ccs #6
[ 975.517648] Call Trace:
[ 975.517692] [<c103cbe8>] ? printk+0x18/0x20
[ 975.517704] [<c1065558>] print_irq_inversion_bug+0x108/0x120
[ 975.517708] [<c10656c6>] check_usage_backwards+0x76/0xd0
[ 975.517711] [<c10658d9>] mark_lock_irq+0x99/0x240
[ 975.517713] [<c1065650>] ? check_usage_backwards+0x0/0xd0
[ 975.517716] [<c106657c>] mark_lock+0x21c/0x3c0
[ 975.517718] [<c1066242>] mark_irqflags+0xe2/0x180
[ 975.517721] [<c1066fdd>] __lock_acquire+0x38d/0x8e0
[ 975.517723] [<c10682da>] ? __lock_is_held+0x3a/0x60
[ 975.517726] [<c106857a>] lock_acquire+0x7a/0xa0
[ 975.517729] [<c130a0ae>] ? xs_tcp_state_change+0x1e/0x1c0
[ 975.517732] [<c1331f69>] _raw_read_lock+0x39/0x70
[ 975.517735] [<c130a0ae>] ? xs_tcp_state_change+0x1e/0x1c0
[ 975.517737] [<c130a0ae>] xs_tcp_state_change+0x1e/0x1c0
[ 975.517740] [<c12cf3bf>] ? tcp_send_fin+0x4f/0xc0
[ 975.517743] [<c12e2397>] inet_shutdown+0x97/0x110
[ 975.517745] [<c104ed5e>] ? run_workqueue+0x7e/0x1d0
[ 975.517748] [<c1289649>] kernel_sock_shutdown+0x9/0x10
[ 975.517751] [<c13093a7>] xs_tcp_shutdown+0x17/0x20
[ 975.517753] [<c13096a7>] xs_tcp_close+0x27/0x30
[ 975.517756] [<c130792d>] xprt_autoclose+0x1d/0x50
[ 975.517758] [<c104edc0>] run_workqueue+0xe0/0x1d0
[ 975.517761] [<c104ed5e>] ? run_workqueue+0x7e/0x1d0
[ 975.517763] [<c1307910>] ? xprt_autoclose+0x0/0x50
[ 975.517766] [<c1052e8a>] ? prepare_to_wait+0x3a/0x60
[ 975.517769] [<c104ef4b>] worker_thread+0x9b/0xd0
[ 975.517771] [<c1053000>] ? autoremove_wake_function+0x0/0x50
[ 975.517774] [<c1053000>] ? autoremove_wake_function+0x0/0x50
[ 975.517779] [<c1035456>] ? complete+0x46/0x60
[ 975.517782] [<c1052a65>] kthread+0x75/0x80
[ 975.517784] [<c104eeb0>] ? worker_thread+0x0/0xd0
[ 975.517786] [<c10529f0>] ? kthread+0x0/0x80
[ 975.517789] [<c10529f0>] ? kthread+0x0/0x80
[ 975.517791] [<c100317a>] kernel_thread_helper+0x6/0x1c
9>] _raw_spin_lock+0x39/0x70
[ 975.517015] [<c128ae51>] sk_clone+0xb1/0x2c0
[ 975.517018] [<c12c0046>] inet_csk_clone+0x16/0x90
[ 975.517022] [<c12d519c>] tcp_create_openreq_child+0x1c/0x460
[ 975.517025] [<c12d2a1f>] tcp_v4_syn_recv_sock+0x3f/0x1e0
[ 975.517028] [<c12d576c>] tcp_check_req+0x18c/0x3b0
[ 975.517031] [<c12d2c0d>] tcp_v4_hnd_req+0x4d/0x160
[ 975.517033] [<c12d2f39>] tcp_v4_do_rcv+0x159/0x280
[ 975.517036] [<c12d35d4>] tcp_v4_rcv+0x574/0xa30
[ 975.517038] [<c12b5c4f>] ip_local_deliver_finish+0xff/0x2c0
[ 975.517042] [<c12b5e40>] ip_local_deliver+0x30/0x40
[ 975.517045] [<c12b5f99>] ip_rcv_finish+0x149/0x440
[ 975.517048] [<c12b63f6>] ip_rcv+0x166/0x240
[ 975.517050] [<c1297b0d>] __netif_receive_skb+0x1cd/0x280
[ 975.517054] [<c12985e8>] process_backlog+0x88/0x160
[ 975.517057] [<c12989b7>] net_rx_action+0x127/0x140
[ 975.517060] [<c1041b30>] __do_softirq+0xd0/0x130
[ 975.517063] INITIAL USE at:
[ 975.517065] [<c1066e16>] __lock_acquire+0x1c6/0x8e0
[ 975.517067] [<c106857a>] lock_acquire+0x7a/0xa0
[ 975.517070] [<c1331dbe>] _raw_spin_lock_bh+0x3e/0x80
[ 975.517073] [<c128c4c9>] lock_sock_fast+0x29/0x90
[ 975.517076] [<c12dae84>] udp_destroy_sock+0x14/0x40
[ 975.517079] [<c128c823>] sk_common_release+0xb3/0xc0
[ 975.517083] [<c12db7f8>] udp_lib_close+0x8/0x10
[ 975.517085] [<c12e18ce>] inet_release+0xbe/0x100
[ 975.517088] [<c1286c36>] sock_release+0x66/0x80
[ 975.517091] [<c1287952>] sock_close+0x12/0x30
[ 975.517094] [<c10b705b>] __fput+0x1cb/0x210
[ 975.517097] [<c10b70b9>] fput+0x19/0x20
[ 975.517099] [<c10b54f3>] filp_close+0x43/0x70
[ 975.517102] [<c103eafb>] close_files+0xab/0x140
[ 975.517105] [<c103ebf9>] put_files_struct+0x29/0xf0
[ 975.517108] [<c103ed50>] exit_files+0x40/0x50
[ 975.517111] [<c103f400>] do_exit+0x100/0x2b0
[ 975.517114] [<c103f614>] do_group_exit+0x34/0xb0
[ 975.517117] [<c103f69f>] sys_exit_group+0xf/0x20
[ 975.517120] [<c13327e1>] syscall_call+0x7/0xb
[ 975.517130] }
[ 975.517139] ... key at: [<c1cbfc50>] af_family_slock_keys+0x10/0x140
[ 975.517180] ... acquired at:
[ 975.517187] [<c1064a8b>] check_prevs_add+0xab/0x100
[ 975.517190] [<c1064e15>] validate_chain+0x305/0x5a0
[ 975.517193] [<c1066f03>] __lock_acquire+0x2b3/0x8e0
[ 975.517195] [<c106857a>] lock_acquire+0x7a/0xa0
[ 975.517198] [<c13323fe>] _raw_write_lock_bh+0x3e/0x80
[ 975.517200] [<c12c0356>] inet_csk_listen_stop+0x86/0x160
[ 975.517203] [<c12c2dc0>] tcp_close+0x350/0x360
[ 975.517205] [<c12e18ce>] inet_release+0xbe/0x100
[ 975.517208] [<c1286c36>] sock_release+0x66/0x80
[ 975.517210] [<c1287952>] sock_close+0x12/0x30
[ 975.517212] [<c10b705b>] __fput+0x1cb/0x210
[ 975.517215] [<c10b70b9>] fput+0x19/0x20
[ 975.517217] [<c10b54f3>] filp_close+0x43/0x70
[ 975.517220] [<c10b558d>] sys_close+0x6d/0x100
[ 975.517222] [<c13327e1>] syscall_call+0x7/0xb
[ 975.517230]
[ 975.517240] -> (clock-AF_INET){++.?..} ops: 879 {
[ 975.517244] HARDIRQ-ON-W at:
[ 975.517246] [<c106625e>] mark_irqflags+0xfe/0x180
[ 975.517249] [<c1066fdd>] __lock_acquire+0x38d/0x8e0
[ 975.517252] [<c106857a>] lock_acquire+0x7a/0xa0
[ 975.517254] [<c13323fe>] _raw_write_lock_bh+0x3e/0x80
[ 975.517257] [<c128c79f>] sk_common_release+0x2f/0xc0
[ 975.517260] [<c12db7f8>] udp_lib_close+0x8/0x10
[ 975.517263] [<c12e18ce>] inet_release+0xbe/0x100
[ 975.517266] [<c1286c36>] sock_release+0x66/0x80
[ 975.517269] [<c1287952>] sock_close+0x12/0x30
[ 975.517271] [<c10b705b>] __fput+0x1cb/0x210
[ 975.517274] [<c10b70b9>] fput+0x19/0x20
[ 975.517277] [<c10b54f3>] filp_close+0x43/0x70
[ 975.517280] [<c103eafb>] close_files+0xab/0x140
[ 975.517283] [<c103ebf9>] put_files_struct+0x29/0xf0
[ 975.517286] [<c103ed50>] exit_files+0x40/0x50
[ 975.517289] [<c103f400>] do_exit+0x100/0x2b0
[ 975.517291] [<c103f614>] do_group_exit+0x34/0xb0
[ 975.517294] [<c103f69f>] sys_exit_group+0xf/0x20
[ 975.517297] [<c13327e1>] syscall_call+0x7/0xb
[ 975.517300] HARDIRQ-ON-R at:
[ 975.517302] [<c10661ce>] mark_irqflags+0x6e/0x180
[ 975.517304] [<c1066fdd>] __lock_acquire+0x38d/0x8e0
[ 975.517307] [<c106857a>] lock_acquire+0x7a/0xa0
[ 975.517310] [<c1331f69>] _raw_read_lock+0x39/0x70
[ 975.517312] [<c130a0ae>] xs_tcp_state_change+0x1e/0x1c0
[ 975.517316] [<c12cbea8>] tcp_rcv_synsent_state_process+0x388/0x580
[ 975.517319] [<c12cc547>] tcp_rcv_state_process+0x4a7/0x560
[ 975.517322] [<c12d2e51>] tcp_v4_do_rcv+0x71/0x280
[ 975.517325] [<c128b786>] __release_sock+0x66/0x150
[ 975.517327] [<c128c497>] release_sock+0x87/0x90
[ 975.517330] [<c12e1cba>] inet_stream_connect+0x5a/0x1b0
[ 975.517333] [<c1289448>] kernel_connect+0x18/0x30
[ 975.517336] [<c130acce>] xs_tcp_finish_connecting+0x4e/0x120
[ 975.517339] [<c130adfb>] xs_tcp_setup_socket+0x5b/0x180
[ 975.517342] [<c130b034>] xs_tcp_connect_worker4+0x14/0x20
[ 975.517344] [<c104edc0>] run_workqueue+0xe0/0x1d0
[ 975.517347] [<c104ef4b>] worker_thread+0x9b/0xd0
[ 975.517350] [<c1052a65>] kthread+0x75/0x80
[ 975.517353] [<c100317a>] kernel_thread_helper+0x6/0x1c
[ 975.517358] IN-SOFTIRQ-R at:
[ 975.517359] [<c106627e>] mark_irqflags+0x11e/0x180
[ 975.517364] [<c1066fdd>] __lock_acquire+0x38d/0x8e0
[ 975.517367] [<c106857a>] lock_acquire+0x7a/0xa0
[ 975.517369] [<c1331f69>] _raw_read_lock+0x39/0x70
[ 975.517372] [<c1309f81>] xs_tcp_data_ready+0x21/0x90
[ 975.517375] [<c12ca378>] tcp_data_queue+0x248/0x820
[ 975.517378] [<c12cb6ee>] tcp_rcv_established+0xae/0x4e0
[ 975.517381] [<c12d2fb1>] tcp_v4_do_rcv+0x1d1/0x280
[ 975.517384] [<c12d35d4>] tcp_v4_rcv+0x574/0xa30
[ 975.517386] [<c12b5c4f>] ip_local_deliver_finish+0xff/0x2c0
[ 975.517389] [<c12b5e40>] ip_local_deliver+0x30/0x40
[ 975.517392] [<c12b5f99>] ip_rcv_finish+0x149/0x440
[ 975.517395] [<c12b63f6>] ip_rcv+0x166/0x240
[ 975.517398] [<c1297b0d>] __netif_receive_skb+0x1cd/0x280
[ 975.517401] [<c12985e8>] process_backlog+0x88/0x160
[ 975.517404] [<c12989b7>] net_rx_action+0x127/0x140
[ 975.517407] [<c1041b30>] __do_softirq+0xd0/0x130
[ 975.517411] SOFTIRQ-ON-R at:
[ 975.517412] [<c1066242>] mark_irqflags+0xe2/0x180
[ 975.517415] [<c1066fdd>] __lock_acquire+0x38d/0x8e0
[ 975.517418] [<c106857a>] lock_acquire+0x7a/0xa0
[ 975.517421] [<c1331f69>] _raw_read_lock+0x39/0x70
[ 975.517423] [<c130a0ae>] xs_tcp_state_change+0x1e/0x1c0
[ 975.517427] [<c12e2397>] inet_shutdown+0x97/0x110
[ 975.517429] [<c1289649>] kernel_sock_shutdown+0x9/0x10
[ 975.517432] [<c13093a7>] xs_tcp_shutdown+0x17/0x20
[ 975.517435] [<c13096a7>] xs_tcp_close+0x27/0x30
[ 975.517438] [<c130792d>] xprt_autoclose+0x1d/0x50
[ 975.517442] [<c104edc0>] run_workqueue+0xe0/0x1d0
[ 975.517445] [<c104ef4b>] worker_thread+0x9b/0xd0
[ 975.517448] [<c1052a65>] kthread+0x75/0x80
[ 975.517450] [<c100317a>] kernel_thread_helper+0x6/0x1c
[ 975.517453] INITIAL USE at:
[ 975.517455] [<c1066e16>] __lock_acquire+0x1c6/0x8e0
[ 975.517457] [<c106857a>] lock_acquire+0x7a/0xa0
[ 975.517460] [<c13323fe>] _raw_write_lock_bh+0x3e/0x80
[ 975.517463] [<c128c79f>] sk_common_release+0x2f/0xc0
[ 975.517466] [<c12db7f8>] udp_lib_close+0x8/0x10
[ 975.517469] [<c12e18ce>] inet_release+0xbe/0x100
[ 975.517471] [<c1286c36>] sock_release+0x66/0x80
[ 975.517474] [<c1287952>] sock_close+0x12/0x30
[ 975.517477] [<c10b705b>] __fput+0x1cb/0x210
[ 975.517480] [<c10b70b9>] fput+0x19/0x20
[ 975.517483] [<c10b54f3>] filp_close+0x43/0x70
[ 975.517485] [<c103eafb>] close_files+0xab/0x140
[ 975.517488] [<c103ebf9>] put_files_struct+0x29/0xf0
[ 975.517495] [<c103ed50>] exit_files+0x40/0x50
[ 975.517498] [<c103f400>] do_exit+0x100/0x2b0
[ 975.517501] [<c103f614>] do_group_exit+0x34/0xb0
[ 975.517504] [<c103f69f>] sys_exit_group+0xf/0x20
[ 975.517507] [<c13327e1>] syscall_call+0x7/0xb
[ 975.517510] }
[ 975.517511] ... key at: [<c1cbfd90>] af_callback_keys+0x10/0x130
[ 975.517513] ... acquired at:
[ 975.517515] [<c10656c6>] check_usage_backwards+0x76/0xd0
[ 975.517517] [<c10658d9>] mark_lock_irq+0x99/0x240
[ 975.517519] [<c106657c>] mark_lock+0x21c/0x3c0
[ 975.517522] [<c1066242>] mark_irqflags+0xe2/0x180
[ 975.517524] [<c1066fdd>] __lock_acquire+0x38d/0x8e0
[ 975.517526] [<c106857a>] lock_acquire+0x7a/0xa0
[ 975.517529] [<c1331f69>] _raw_read_lock+0x39/0x70
[ 975.517531] [<c130a0ae>] xs_tcp_state_change+0x1e/0x1c0
[ 975.517534] [<c12e2397>] inet_shutdown+0x97/0x110
[ 975.517536] [<c1289649>] kernel_sock_shutdown+0x9/0x10
[ 975.517539] [<c13093a7>] xs_tcp_shutdown+0x17/0x20
[ 975.517541] [<c13096a7>] xs_tcp_close+0x27/0x30
[ 975.517544] [<c130792d>] xprt_autoclose+0x1d/0x50
[ 975.517546] [<c104edc0>] run_workqueue+0xe0/0x1d0
[ 975.517549] [<c104ef4b>] worker_thread+0x9b/0xd0
[ 975.517551] [<c1052a65>] kthread+0x75/0x80
[ 975.517553] [<c100317a>] kernel_thread_helper+0x6/0x1c
[ 975.517556]
[ 975.517570]
[ 975.517571] stack backtrace:
[ 975.517628] Pid: 337, comm: rpciod/1 Not tainted 2.6.35-rc3-ccs #6
[ 975.517648] Call Trace:
[ 975.517692] [<c103cbe8>] ? printk+0x18/0x20
[ 975.517704] [<c1065558>] print_irq_inversion_bug+0x108/0x120
[ 975.517708] [<c10656c6>] check_usage_backwards+0x76/0xd0
[ 975.517711] [<c10658d9>] mark_lock_irq+0x99/0x240
[ 975.517713] [<c1065650>] ? check_usage_backwards+0x0/0xd0
[ 975.517716] [<c106657c>] mark_lock+0x21c/0x3c0
[ 975.517718] [<c1066242>] mark_irqflags+0xe2/0x180
[ 975.517721] [<c1066fdd>] __lock_acquire+0x38d/0x8e0
[ 975.517723] [<c10682da>] ? __lock_is_held+0x3a/0x60
[ 975.517726] [<c106857a>] lock_acquire+0x7a/0xa0
[ 975.517729] [<c130a0ae>] ? xs_tcp_state_change+0x1e/0x1c0
[ 975.517732] [<c1331f69>] _raw_read_lock+0x39/0x70
[ 975.517735] [<c130a0ae>] ? xs_tcp_state_change+0x1e/0x1c0
[ 975.517737] [<c130a0ae>] xs_tcp_state_change+0x1e/0x1c0
[ 975.517740] [<c12cf3bf>] ? tcp_send_fin+0x4f/0xc0
[ 975.517743] [<c12e2397>] inet_shutdown+0x97/0x110
[ 975.517745] [<c104ed5e>] ? run_workqueue+0x7e/0x1d0
[ 975.517748] [<c1289649>] kernel_sock_shutdown+0x9/0x10
[ 975.517751] [<c13093a7>] xs_tcp_shutdown+0x17/0x20
[ 975.517753] [<c13096a7>] xs_tcp_close+0x27/0x30
[ 975.517756] [<c130792d>] xprt_autoclose+0x1d/0x50
[ 975.517758] [<c104edc0>] run_workqueue+0xe0/0x1d0
[ 975.517761] [<c104ed5e>] ? run_workqueue+0x7e/0x1d0
[ 975.517763] [<c1307910>] ? xprt_autoclose+0x0/0x50
[ 975.517766] [<c1052e8a>] ? prepare_to_wait+0x3a/0x60
[ 975.517769] [<c104ef4b>] worker_thread+0x9b/0xd0
[ 975.517771] [<c1053000>] ? autoremove_wake_function+0x0/0x50
[ 975.517774] [<c1053000>] ? autoremove_wake_function+0x0/0x50
[ 975.517779] [<c1035456>] ? complete+0x46/0x60
[ 975.517782] [<c1052a65>] kthread+0x75/0x80
[ 975.517784] [<c104eeb0>] ? worker_thread+0x0/0xd0
[ 975.517786] [<c10529f0>] ? kthread+0x0/0x80
[ 975.517789] [<c10529f0>] ? kthread+0x0/0x80
[ 975.517791] [<c100317a>] kernel_thread_helper+0x6/0x1c
[ 984.626828] Restarting system.
[ 984.627458] machine restart
^ permalink raw reply [flat|nested] 24+ messages in thread* [2.6.36-rc3] NFS: possible irq lock inversion dependency 2010-06-24 11:53 [2.6.35-rc3] NFS: possible irq lock inversion dependency Tetsuo Handa @ 2010-09-07 12:32 ` Tetsuo Handa 2010-09-21 6:51 ` [2.6.35-rc5] INET?: " Tetsuo Handa 0 siblings, 1 reply; 24+ messages in thread From: Tetsuo Handa @ 2010-09-07 12:32 UTC (permalink / raw) To: linux-fsdevel, netdev, linux-security-module Tetsuo Handa wrote: > Hello. > > I sometimes get below warning when the system is about to reboot/halt. > Is this already reported? If not, I'll try to establish steps to reproduce. Although none of my patch's function is printed in the trace, this warning may be my fault because I haven't succeeded to reproduce using vanilla kernels. Does somebody know what's happening here? Regards. [ 149.577099] nfsd: last server has exited, flushing export cache [ 151.108010] [ 151.108015] ========================================================= [ 151.109597] [ INFO: possible irq lock inversion dependency detected ] [ 151.110778] 2.6.36-rc3-ccs #2 [ 151.110778] ------------------------ [<c104093f>] sys_exit_group+0xf/0x20 [ 151.110778] 78] [<c106cd3a>] lock_acquire+0x7a/0xa0 [ 151.110778] [<c138f239>] _raw_spin_lock+0x39/0x70 [ 151.110778] [<c12dd021>] sk_clone+0xb1/0x2c0 [ 151.110778] [<c13134da>] inet_csk_clone+0x1a/0xb0 [ 151.110778] [<c1328a9c>] tcp_create_openreq_child+0x1c/0x460 [ 151.110778] [<c132616f>] tcp_v4_syn_recv_sock+0x3f/0x1e0 [ 151.110778] [<c132906c>] tcp_check_req+0x18c/0x3b0 [ 151.110778] [<c132635d>] tcp_v4_hnd_req+0x4d/0x160 [ 151.110778] [<c1326689>] tcp_v4_do_rcv+0x159/0x280 [ 151.110778] [<c1326d24>] tcp_v4_rcv+0x574/0xa30 [ 151.110778] [<c1308b63>] ip_local_deliver_finish+0x103/0x320 [ 151.110778] [<c1308db0>] ip_local_deliver+0x30/0x40 [ 151.110778] [<c1308f29>] ip_rcv_finish+0x169/0x480 [ 151.110778] [<c13093da>] ip_rcv+0x19a/0x2b0 [ 151.110778] [<c12ea04d>] __netif_receive_skb+0x21d/0x310 [ 151.110778] [<c12eab58>] process_backlog+0x88/0x160 [ 151.110778] [<c12eaf27>] net_rx_action+0x127/0x140 [ 151.110778] [<c1042e00>] __do_softirq+0xd0/0x130 [ 151.110778] INITIAL USE at: [ 151.110778] [<c106b5d0>] __lock_acquire+0x1c0/0x8e0 [ 151.110778] [<c106cd3a>] lock_acquire+0x7a/0xa0 [ 151.110778] [<c138f3ae>] _raw_spin_lock_bh+0x3e/0x80 [ 151.110778] [<c12de689>] lock_sock_fast+0x29/0x90 [ 151.110778] [<c132e834>] udp_destroy_sock+0x14/0x40 [ 151.110778] [<c12de9e3>] sk_common_release+0xb3/0xc0 [ 151.110778] [<c132f1a8>] udp_lib_close+0x8/0x10 [ 151.110778] [<c133510e>] inet_release+0xbe/0x100 [ 151.110778] [<c12d8b96>] sock_release+0x66/0x80 [ 151.110778] [<c12d9912>] sock_close+0x12/0x30 [ 151.110778] [<c10c600b>] __fput+0x1cb/0x240 [ 151.110778] [<c10c6099>] fput+0x19/0x20 [ 151.110778] [<c10c3ed3>] filp_close+0x43/0x70 [ 151.110778] [<c103fd5d>] close_files+0xad/0x150 [ 151.110778] [<c103fe69>] put_files_struct+0x29/0xf0 [ 151.110778] [<c103ffc0>] exit_files+0x40/0x50 [ 151.110778] [<c1040686>] do_exit+0x116/0x2e0 [ 151.110778] [<c10408b4>] do_group_exit+0x34/0xb0 [ 151.110778] [<c104093f>] sys_exit_group+0xf/0x20 [ 151.110778] [<c138fe51>] syscall_call+0x7/0xb [ 151.110778] } [ 151.110778] ... key at: [<c1d63a70>] af_family_slock_keys+0x10/0x140 [ 151.110778] ... acquired at: [ 151.110778] [<c106924b>] check_prevs_add+0xab/0x100 [ 151.110778] [<c10695d5>] validate_chain+0x305/0x5a0 [ 151.110778] [<c106b6bd>] __lock_acquire+0x2ad/0x8e0 [ 151.110778] [<c106cd3a>] lock_acquire+0x7a/0xa0 [ 151.110778] [<c138f9ee>] _raw_write_lock_bh+0x3e/0x80 [ 151.110778] [<c1313806>] inet_csk_listen_stop+0x86/0x160 [ 151.110778] [<c1316348>] tcp_close+0x378/0x380 [ 151.110778] [<c133510e>] inet_release+0xbe/0x100 [ 151.110778] [<c12d8b96>] sock_release+0x66/0x80 [ 151.110778] [<c12d9912>] sock_close+0x12/0x30 [ 151.110778] [<c10c600b>] __fput+0x1cb/0x240 [ 151.110778] [<c10c6099>] fput+0x19/0x20 [ 151.110778] [<c10c3ed3>] filp_close+0x43/0x70 [ 151.110778] [<c10c3f6d>] sys_close+0x6d/0x110 [ 151.110778] [<c138fe51>] syscall_call+0x7/0xb [ 151.110778] [ 151.110778] -> (clock-AF_INET){++.?..} ops: 1650 { [ 151.110778] HARDIRQ-ON-W at: [ 151.110778] [<c106aa1e>] mark_irqflags+0xfe/0x180 [ 151.110778] [<c106b79d>] __lock_acquire+0x38d/0x8e0 [ 151.110778] [<c106cd3a>] lock_acquire+0x7a/0xa0 [ 151.110778] [<c138f9ee>] _raw_write_lock_bh+0x3e/0x80 [ 151.110778] [<c12de95f>] sk_common_release+0x2f/0xc0 [ 151.110778] [<c132f1a8>] udp_lib_close+0x8/0x10 [ 151.110778] [<c133510e>] inet_release+0xbe/0x100 [ 151.110778] [<c12d8b96>] sock_release+0x66/0x80 [ 151.110778] [<c12d9912>] sock_close+0x12/0x30 [ 151.110778] [<c10c600b>] __fput+0x1cb/0x240 [ 151.110778] [<c10c6099>] fput+0x19/0x20 [ 151.110778] [<c10c3ed3>] filp_close+0x43/0x70 [ 151.110778] [<c103fd5d>] close_files+0xad/0x150 [ 151.110778] [<c103fe69>] put_files_struct+0x29/0xf0 [ 151.110778] [<c103ffc0>] exit_files+0x40/0x50 [ 151.110778] [<c1040686>] do_exit+0x116/0x2e0 [ 151.110778] [<c10408b4>] do_group_exit+0x34/0xb0 [ 151.110778] [<c104093f>] sys_exit_group+0xf/0x20 [ 151.110778] [<c138fe51>] syscall_call+0x7/0xb [ 151.110778] HARDIRQ-ON-R at: [ 151.110778] [<c106a98e>] mark_irqflags+0x6e/0x180 [ 151.110778] [<c106b79d>] __lock_acquire+0x38d/0x8e0 [ 151.110778] [<c106cd3a>] lock_acquire+0x7a/0xa0 [ 151.110778] [<c138f559>] _raw_read_lock+0x39/0x70 [ 151.110778] [<c13613ee>] xs_tcp_state_change+0x1e/0x1d0 [ 151.110778] [<c131f478>] tcp_rcv_synsent_state_process+0x398/0x590 [ 151.110778] [<c131fb17>] tcp_rcv_state_process+0x4a7/0x560 [ 151.110778] [<c13265a1>] tcp_v4_do_rcv+0x71/0x280 [ 151.110778] [<c12dd956>] __release_sock+0x66/0x150 [ 151.110778] [<c12de657>] release_sock+0x87/0x90 [ 151.110778] [<c13354fa>] inet_stream_connect+0x5a/0x1b0 [ 151.110778] [<c12db4b8>] kernel_connect+0x18/0x30 [ 151.110778] [<c136209e>] xs_tcp_finish_connecting+0x4e/0x120 [ 151.110778] [<c13621cb>] xs_tcp_setup_socket+0x5b/0x180 [ 151.110778] [<c1362404>] xs_tcp_connect_worker4+0x14/0x20 [ 151.110778] [<c1051617>] process_one_work+0x147/0x3a0 [ 151.110778] [<c1051956>] worker_thread+0xa6/0x200 [ 151.110778] [<c1056825>] kthread+0x75/0x80 [ 151.110778] [<c10031fa>] kernel_thread_helper+0x6/0x1c [ 151.110778] IN-SOFTIRQ-R at: [ 151.110778] [<c106aa3e>] mark_irqflags+0x11e/0x180 [ 151.110778] [<c106b79d>] __lock_acquire+0x38d/0x8e0 [ 151.110778] [<c106cd3a>] lock_acquire+0x7a/0xa0 [ 151.110778] [<c138f559>] _raw_read_lock+0x39/0x70 [ 151.110778] [<c13612c1>] xs_tcp_data_ready+0x21/0x90 [ 151.110778] [<c131d938>] tcp_data_queue+0x248/0x820 [ 151.110778] [<c131ecae>] tcp_rcv_established+0xae/0x4e0 [ 151.110778] [<c1326701>] tcp_v4_do_rcv+0x1d1/0x280 [ 151.110778] [<c1326d24>] tcp_v4_rcv+0x574/0xa30 [ 151.110778] [<c1308b63>] ip_local_deliver_finish+0x103/0x320 [ 151.110778] [<c1308db0>] ip_local_deliver+0x30/0x40 [ 151.110778] [<c1308f29>] ip_rcv_finish+0x169/0x480 [ 151.110778] [<c13093da>] ip_rcv+0x19a/0x2b0 [ 151.110778] [<c12ea04d>] __netif_receive_skb+0x21d/0x310 [ 151.110778] [<c12eab58>] process_backlog+0x88/0x160 [ 151.110778] [<c12eaf27>] net_rx_action+0x127/0x140 [ 151.110778] [<c1042e00>] __do_softirq+0xd0/0x130 [ 151.110778] SOFTIRQ-ON-R at: [ 151.110778] [<c106aa02>] mark_irqflags+0xe2/0x180 [ 151.110778] [<c106b79d>] __lock_acquire+0x38d/0x8e0 [ 151.110778] [<c106cd3a>] lock_acquire+0x7a/0xa0 [ 151.110778] [<c138f559>] _raw_read_lock+0x39/0x70 [ 151.110778] [<c13613ee>] xs_tcp_state_change+0x1e/0x1d0 [ 151.110778] [<c1335be7>] inet_shutdown+0x97/0x110 [ 151.110778] [<c12db6b9>] kernel_sock_shutdown+0x9/0x10 [ 151.110778] [<c13606e7>] xs_tcp_shutdown+0x17/0x20 [ 151.110778] [<c13609e7>] xs_tcp_close+0x27/0x30 [ 151.110778] [<c135ec3d>] xprt_autoclose+0x1d/0x50 [ 151.110778] [<c1051617>] process_one_work+0x147/0x3a0 [ 151.110778] [<c1051956>] worker_thread+0xa6/0x200 [ 151.110778] [<c1056825>] kthread+0x75/0x80 [ 151.110778] [<c10031fa>] kernel_thread_helper+0x6/0x1c [ 151.110778] INITIAL USE at: [ 151.110778] [<c106b5d0>] __lock_acquire+0x1c0/0x8e0 [ 151.110778] [<c106cd3a>] lock_acquire+0x7a/0xa0 [ 151.110778] [<c138f9ee>] _raw_write_lock_bh+0x3e/0x80 [ 151.110778] [<c12de95f>] sk_common_release+0x2f/0xc0 [ 151.110778] [<c132f1a8>] udp_lib_close+0x8/0x10 [ 151.110778] [<c133510e>] inet_release+0xbe/0x100 [ 151.110778] [<c12d8b96>] sock_release+0x66/0x80 [ 151.110778] [<c12d9912>] sock_close+0x12/0x30 [ 151.110778] [<c10c600b>] __fput+0x1cb/0x240 [ 151.110778] [<c10c6099>] fput+0x19/0x20 [ 151.110778] [<c10c3ed3>] filp_close+0x43/0x70 [ 151.110778] [<c103fd5d>] close_files+0xad/0x150 [ 151.110778] [<c103fe69>] put_files_struct+0x29/0xf0 [ 151.110778] [<c103ffc0>] exit_files+0x40/0x50 [ 151.110778] [<c1040686>] do_exit+0x116/0x2e0 [ 151.110778] [<c10408b4>] do_group_exit+0x34/0xb0 [ 151.110778] [<c104093f>] sys_exit_group+0xf/0x20 [ 151.110778] [<c138fe51>] syscall_call+0x7/0xb [ 151.110778] } [ 151.110778] ... key at: [<c1d63bb0>] af_callback_keys+0x10/0x130 [ 151.110778] ... acquired at: [ 151.110778] [<c1069e86>] check_usage_backwards+0x76/0xd0 [ 151.110778] [<c106a099>] mark_lock_irq+0x99/0x240 [ 151.110778] [<c106ad3c>] mark_lock+0x21c/0x3c0 [ 151.110778] [<c106aa02>] mark_irqflags+0xe2/0x180 [ 151.110778] [<c106b79d>] __lock_acquire+0x38d/0x8e0 [ 151.110778] [<c106cd3a>] lock_acquire+0x7a/0xa0 [ 151.110778] [<c138f559>] _raw_read_lock+0x39/0x70 [ 151.110778] [<c13613ee>] xs_tcp_state_change+0x1e/0x1d0 [ 151.110778] [<c1335be7>] inet_shutdown+0x97/0x110 [ 151.110778] [<c12db6b9>] kernel_sock_shutdown+0x9/0x10 [ 151.110778] [<c13606e7>] xs_tcp_shutdown+0x17/0x20 [ 151.110778] [<c13609e7>] xs_tcp_close+0x27/0x30 [ 151.110778] [<c135ec3d>] xprt_autoclose+0x1d/0x50 [ 151.110778] [<c1051617>] process_one_work+0x147/0x3a0 [ 151.110778] [<c1051956>] worker_thread+0xa6/0x200 [ 151.110778] [<c1056825>] kthread+0x75/0x80 [ 151.110778] [<c10031fa>] kernel_thread_helper+0x6/0x1c [ 151.110778] [ 151.110778] [ 151.110778] stack backtrace: [ 151.110778] Pid: 418, comm: kworker/1:1 Not tainted 2.6.36-rc3-ccs #2 [ 151.110778] Call Trace: [ 151.110778] [<c103de48>] ? printk+0x18/0x20 [ 151.110778] [<c1069d18>] print_irq_inversion_bug+0x108/0x120 [ 151.110778] [<c1069e86>] check_usage_backwards+0x76/0xd0 [ 151.110778] [<c106a099>] mark_lock_irq+0x99/0x240 [ 151.110778] [<c1069e10>] ? check_usage_backwards+0x0/0xd0 [ 151.110778] [<c106ad3c>] mark_lock+0x21c/0x3c0 [ 151.110778] [<c106aa02>] mark_irqflags+0xe2/0x180 [ 151.110778] [<c106b79d>] __lock_acquire+0x38d/0x8e0 [ 151.110778] [<c106ca9a>] ? __lock_is_held+0x3a/0x60 [ 151.110778] [<c106cd3a>] lock_acquire+0x7a/0xa0 [ 151.110778] [<c13613ee>] ? xs_tcp_state_change+0x1e/0x1d0 [ 151.110778] [<c138f559>] _raw_read_lock+0x39/0x70 [ 151.110778] [<c13613ee>] ? xs_tcp_state_change+0x1e/0x1d0 [ 151.110778] [<c13613ee>] xs_tcp_state_change+0x1e/0x1d0 [ 151.110778] [<c13229af>] ? tcp_send_fin+0x4f/0xc0 [ 151.110778] [<c1335be7>] inet_shutdown+0x97/0x110 [ 151.110778] [<c12db6b9>] kernel_sock_shutdown+0x9/0x10 [ 151.110778] [<c13606e7>] xs_tcp_shutdown+0x17/0x20 [ 151.110778] [<c13609e7>] xs_tcp_close+0x27/0x30 [ 151.110778] [<c135ec3d>] xprt_autoclose+0x1d/0x50 [ 151.110778] [<c1051617>] process_one_work+0x147/0x3a0 [ 151.110778] [<c10515a6>] ? process_one_work+0xd6/0x3a0 [ 151.110778] [<c106d2b9>] ? __lock_acquired+0x119/0x1c0 [ 151.110778] [<c135ec20>] ? xprt_autoclose+0x0/0x50 [ 151.110778] [<c10518cc>] ? worker_thread+0x1c/0x200 [ 151.110778] [<c1050457>] ? __need_more_worker+0x17/0x40 [ 151.110778] [<c1051956>] worker_thread+0xa6/0x200 [ 151.110778] [<c1056825>] kthread+0x75/0x80 [ 151.110778] [<c10518b0>] ? worker_thread+0x0/0x200 [ 151.110778] [<c10567b0>] ? kthread+0x0/0x80 [ 151.110778] [<c10031fa>] kernel_thread_helper+0x6/0x1c [ 159.600716] Restarting system. [ 159.601345] machine restart ^ permalink raw reply [flat|nested] 24+ messages in thread
* [2.6.35-rc5] INET?: possible irq lock inversion dependency 2010-09-07 12:32 ` [2.6.36-rc3] " Tetsuo Handa @ 2010-09-21 6:51 ` Tetsuo Handa 2010-09-21 7:56 ` Eric Dumazet 0 siblings, 1 reply; 24+ messages in thread From: Tetsuo Handa @ 2010-09-21 6:51 UTC (permalink / raw) To: eric.dumazet; +Cc: linux-fsdevel, netdev I succeeded to save undamaged messages by doing echo 1 > /proc/sys/kernel/printk_delay . (Well, it would be nice to do above before printing lockdep warning because it prints a lot of lines enough to drop some lines.) Although my patch is still applied, I believe my patch is not the culprit. This warning might be related to lock_sock_fast() which was introduced in 2.6.35 because I'm seeing this warning since 2.6.35-rcX . What can I do next? Regards. [ 199.267633] nfsd: last server has exited, flushing export cache [ 200.784089] [ 200.784094] ========================================================= [ 200.786186] [ INFO: possible irq lock inversion dependency detected ] [ 200.786186] 2.6.36-rc5-old #2 [ 200.786186] --------------------------------------------------------- [ 200.786186] kworker/0:1/10 just changed the state of lock: [ 200.786186] (clock-AF_INET){++.?..}, at: [<c135e9be>] xs_tcp_state_change+0x1e/0x1d0 [ 200.786186] but this lock was taken by another, SOFTIRQ-safe lock in the past: [ 200.786186] (slock-AF_INET){+.-...} [ 200.786186] [ 200.786186] and interrupts could create inverse lock ordering between them. [ 200.786186] [ 200.786186] [ 200.786186] other info that might help us debug this: [ 200.786186] 3 locks held by kworker/0:1/10: [ 200.786186] #0: (rpciod){+.+.+.}, at: [<c10516f6>] process_one_work+0xd6/0x3a0 [ 200.786186] #1: ((&xprt->task_cleanup)){+.+...}, at: [<c10516f6>] process_one_work+0xd6/0x3a0 [ 200.786186] #2: (sk_lock-AF_INET-RPC){+.+...}, at: [<c1333119>] inet_shutdown+0x49/0x110 [ 200.786186] [ 200.786186] the shortest dependencies between 2nd lock and 1st lock: [ 200.786186] -> (slock-AF_INET){+.-...} ops: 11832 { [ 200.786186] HARDIRQ-ON-W at: [ 200.786186] [<c106ab8e>] mark_irqflags+0xfe/0x180 [ 200.786186] [<c106b90d>] __lock_acquire+0x38d/0x8e0 [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 200.786186] [<c138ca3e>] _raw_spin_lock_bh+0x3e/0x80 [ 200.786186] [<c12dba59>] lock_sock_fast+0x29/0x90 [ 200.786186] [<c132bdb4>] udp_destroy_sock+0x14/0x40 [ 200.786186] [<c12dbdb3>] sk_common_release+0xb3/0xc0 [ 200.786186] [<c132c728>] udp_lib_close+0x8/0x10 [ 200.786186] [<c133268e>] inet_release+0xbe/0x100 [ 200.786186] [<c12d5f66>] sock_release+0x66/0x80 [ 200.786186] [<c12d6ce2>] sock_close+0x12/0x30 [ 200.786186] [<c10c66fb>] __fput+0x1cb/0x240 [ 200.786186] [<c10c6789>] fput+0x19/0x20 [ 200.786186] [<c10c45c3>] filp_close+0x43/0x70 [ 200.786186] [<c103fded>] close_files+0xad/0x150 [ 200.786186] [<c103fef9>] put_files_struct+0x29/0xf0 [ 200.786186] [<c1040050>] exit_files+0x40/0x50 [ 200.786186] [<c1040716>] do_exit+0x116/0x2e0 [ 200.786186] [<c1040944>] do_group_exit+0x34/0xb0 [ 200.786186] [<c10409cf>] sys_exit_group+0xf/0x20 [ 200.786186] [<c138d4e1>] syscall_call+0x7/0xb [ 200.786186] IN-SOFTIRQ-W at: [ 200.786186] [<c106abae>] mark_irqflags+0x11e/0x180 [ 200.786186] [<c106b90d>] __lock_acquire+0x38d/0x8e0 [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 200.786186] [<c138c8c9>] _raw_spin_lock+0x39/0x70 [ 200.786186] [<c12da3f1>] sk_clone+0xb1/0x2c0 [ 200.786186] [<c13108ea>] inet_csk_clone+0x1a/0xb0 [ 200.786186] [<c1325ecc>] tcp_create_openreq_child+0x1c/0x460 [ 200.786186] [<c132359f>] tcp_v4_syn_recv_sock+0x3f/0x1e0 [ 200.786186] [<c132649c>] tcp_check_req+0x18c/0x3b0 [ 200.786186] [<c132378d>] tcp_v4_hnd_req+0x4d/0x160 [ 200.786186] [<c1323ab9>] tcp_v4_do_rcv+0x159/0x280 [ 200.786186] [<c1324154>] tcp_v4_rcv+0x574/0xa30 [ 200.786186] [<c1305f63>] ip_local_deliver_finish+0x103/0x320 [ 200.786186] [<c13061b0>] ip_local_deliver+0x30/0x40 [ 200.786186] [<c1306329>] ip_rcv_finish+0x169/0x480 [ 200.786186] [<c13067da>] ip_rcv+0x19a/0x2b0 [ 200.786186] [<c12e743d>] __netif_receive_skb+0x21d/0x310 [ 200.786186] [<c12e7f48>] process_backlog+0x88/0x160 [ 200.786186] [<c12e8317>] net_rx_action+0x127/0x140 [ 200.786186] [<c1042e90>] __do_softirq+0xd0/0x130 [ 200.786186] INITIAL USE at: [ 200.786186] [<c106b740>] __lock_acquire+0x1c0/0x8e0 [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 200.786186] [<c138ca3e>] _raw_spin_lock_bh+0x3e/0x80 [ 200.786186] [<c12dba59>] lock_sock_fast+0x29/0x90 [ 200.786186] [<c132bdb4>] udp_destroy_sock+0x14/0x40 [ 200.786186] [<c12dbdb3>] sk_common_release+0xb3/0xc0 [ 200.786186] [<c132c728>] udp_lib_close+0x8/0x10 [ 200.786186] [<c133268e>] inet_release+0xbe/0x100 [ 200.786186] [<c12d5f66>] sock_release+0x66/0x80 [ 200.786186] [<c12d6ce2>] sock_close+0x12/0x30 [ 200.786186] [<c10c66fb>] __fput+0x1cb/0x240 [ 200.786186] [<c10c6789>] fput+0x19/0x20 [ 200.786186] [<c10c45c3>] filp_close+0x43/0x70 [ 200.786186] [<c103fded>] close_files+0xad/0x150 [ 200.786186] [<c103fef9>] put_files_struct+0x29/0xf0 [ 200.786186] [<c1040050>] exit_files+0x40/0x50 [ 200.786186] [<c1040716>] do_exit+0x116/0x2e0 [ 200.786186] [<c1040944>] do_group_exit+0x34/0xb0 [ 200.786186] [<c10409cf>] sys_exit_group+0xf/0x20 [ 200.786186] [<c138d4e1>] syscall_call+0x7/0xb [ 200.786186] } [ 200.786186] ... key at: [<c1d4d9f0>] af_family_slock_keys+0x10/0x140 [ 200.786186] ... acquired at: [ 200.786186] [<c10693bb>] check_prevs_add+0xab/0x100 [ 200.786186] [<c1069745>] validate_chain+0x305/0x5a0 [ 200.786186] [<c106b82d>] __lock_acquire+0x2ad/0x8e0 [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 200.786186] [<c138d07e>] _raw_write_lock_bh+0x3e/0x80 [ 200.786186] [<c1310c16>] inet_csk_listen_stop+0x86/0x160 [ 200.786186] [<c1313772>] tcp_close+0x382/0x390 [ 200.786186] [<c133268e>] inet_release+0xbe/0x100 [ 200.786186] [<c12d5f66>] sock_release+0x66/0x80 [ 200.786186] [<c12d6ce2>] sock_close+0x12/0x30 [ 200.786186] [<c10c66fb>] __fput+0x1cb/0x240 [ 200.786186] [<c10c6789>] fput+0x19/0x20 [ 200.786186] [<c10c45c3>] filp_close+0x43/0x70 [ 200.786186] [<c10c465d>] sys_close+0x6d/0x110 [ 200.786186] [<c138d4e1>] syscall_call+0x7/0xb [ 200.786186] [ 200.786186] -> (clock-AF_INET){++.?..} ops: 2429 { [ 200.786186] HARDIRQ-ON-W at: [ 200.786186] [<c106ab8e>] mark_irqflags+0xfe/0x180 [ 200.786186] [<c106b90d>] __lock_acquire+0x38d/0x8e0 [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 200.786186] [<c138d07e>] _raw_write_lock_bh+0x3e/0x80 [ 200.786186] [<c12dbd2f>] sk_common_release+0x2f/0xc0 [ 200.786186] [<c132c728>] udp_lib_close+0x8/0x10 [ 200.786186] [<c133268e>] inet_release+0xbe/0x100 [ 200.786186] [<c12d5f66>] sock_release+0x66/0x80 [ 200.786186] [<c12d6ce2>] sock_close+0x12/0x30 [ 200.786186] [<c10c66fb>] __fput+0x1cb/0x240 [ 200.786186] [<c10c6789>] fput+0x19/0x20 [ 200.786186] [<c10c45c3>] filp_close+0x43/0x70 [ 200.786186] [<c103fded>] close_files+0xad/0x150 [ 200.786186] [<c103fef9>] put_files_struct+0x29/0xf0 [ 200.786186] [<c1040050>] exit_files+0x40/0x50 [ 200.786186] [<c1040716>] do_exit+0x116/0x2e0 [ 200.786186] [<c1040944>] do_group_exit+0x34/0xb0 [ 200.786186] [<c10409cf>] sys_exit_group+0xf/0x20 [ 200.786186] [<c138d4e1>] syscall_call+0x7/0xb [ 200.786186] HARDIRQ-ON-R at: [ 200.786186] [<c106aafe>] mark_irqflags+0x6e/0x180 [ 200.786186] [<c106b90d>] __lock_acquire+0x38d/0x8e0 [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 200.786186] [<c138cbe9>] _raw_read_lock+0x39/0x70 [ 200.786186] [<c135e9be>] xs_tcp_state_change+0x1e/0x1d0 [ 200.786186] [<c131c8a8>] tcp_rcv_synsent_state_process+0x398/0x590 [ 200.786186] [<c131cf47>] tcp_rcv_state_process+0x4a7/0x560 [ 200.786186] [<c13239d1>] tcp_v4_do_rcv+0x71/0x280 [ 200.786186] [<c12dad26>] __release_sock+0x66/0x150 [ 200.786186] [<c12dba27>] release_sock+0x87/0x90 [ 200.786186] [<c1332a7a>] inet_stream_connect+0x5a/0x1b0 [ 200.786186] [<c12d8888>] kernel_connect+0x18/0x30 [ 200.786186] [<c135f66e>] xs_tcp_finish_connecting+0x4e/0x120 [ 200.786186] [<c135f79b>] xs_tcp_setup_socket+0x5b/0x180 [ 200.786186] [<c135f9d4>] xs_tcp_connect_worker4+0x14/0x20 [ 200.786186] [<c1051767>] process_one_work+0x147/0x3a0 [ 200.786186] [<c1051aa6>] worker_thread+0xa6/0x200 [ 200.786186] [<c1056985>] kthread+0x75/0x80 [ 200.786186] [<c10031fa>] kernel_thread_helper+0x6/0x1c [ 200.786186] IN-SOFTIRQ-R at: [ 200.786186] [<c106abae>] mark_irqflags+0x11e/0x180 [ 200.786186] [<c106b90d>] __lock_acquire+0x38d/0x8e0 [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 200.786186] [<c138cbe9>] _raw_read_lock+0x39/0x70 [ 200.786186] [<c135e891>] xs_tcp_data_ready+0x21/0x90 [ 200.786186] [<c131ad68>] tcp_data_queue+0x248/0x820 [ 200.786186] [<c131c0de>] tcp_rcv_established+0xae/0x4e0 [ 200.786186] [<c1323b31>] tcp_v4_do_rcv+0x1d1/0x280 [ 200.786186] [<c1324154>] tcp_v4_rcv+0x574/0xa30 [ 200.786186] [<c1305f63>] ip_local_deliver_finish+0x103/0x320 [ 200.786186] [<c13061b0>] ip_local_deliver+0x30/0x40 [ 200.786186] [<c1306329>] ip_rcv_finish+0x169/0x480 [ 200.786186] [<c13067da>] ip_rcv+0x19a/0x2b0 [ 200.786186] [<c12e743d>] __netif_receive_skb+0x21d/0x310 [ 200.786186] [<c12e7f48>] process_backlog+0x88/0x160 [ 200.786186] [<c12e8317>] net_rx_action+0x127/0x140 [ 200.786186] [<c1042e90>] __do_softirq+0xd0/0x130 [ 200.786186] SOFTIRQ-ON-R at: [ 200.786186] [<c106ab72>] mark_irqflags+0xe2/0x180 [ 200.786186] [<c106b90d>] __lock_acquire+0x38d/0x8e0 [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 200.786186] [<c138cbe9>] _raw_read_lock+0x39/0x70 [ 200.786186] [<c135e9be>] xs_tcp_state_change+0x1e/0x1d0 [ 200.786186] [<c1333167>] inet_shutdown+0x97/0x110 [ 200.786186] [<c12d8a89>] kernel_sock_shutdown+0x9/0x10 [ 200.786186] [<c135dcb7>] xs_tcp_shutdown+0x17/0x20 [ 200.786186] [<c135dfb7>] xs_tcp_close+0x27/0x30 [ 200.786186] [<c135c20d>] xprt_autoclose+0x1d/0x50 [ 200.786186] [<c1051767>] process_one_work+0x147/0x3a0 [ 200.786186] [<c1051aa6>] worker_thread+0xa6/0x200 [ 200.786186] [<c1056985>] kthread+0x75/0x80 [ 200.786186] [<c10031fa>] kernel_thread_helper+0x6/0x1c [ 200.786186] INITIAL USE at: [ 200.786186] [<c106b740>] __lock_acquire+0x1c0/0x8e0 [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 200.786186] [<c138d07e>] _raw_write_lock_bh+0x3e/0x80 [ 200.786186] [<c12dbd2f>] sk_common_release+0x2f/0xc0 [ 200.786186] [<c132c728>] udp_lib_close+0x8/0x10 [ 200.786186] [<c133268e>] inet_release+0xbe/0x100 [ 200.786186] [<c12d5f66>] sock_release+0x66/0x80 [ 200.786186] [<c12d6ce2>] sock_close+0x12/0x30 [ 200.786186] [<c10c66fb>] __fput+0x1cb/0x240 [ 200.786186] [<c10c6789>] fput+0x19/0x20 [ 200.786186] [<c10c45c3>] filp_close+0x43/0x70 [ 200.786186] [<c103fded>] close_files+0xad/0x150 [ 200.786186] [<c103fef9>] put_files_struct+0x29/0xf0 [ 200.786186] [<c1040050>] exit_files+0x40/0x50 [ 200.786186] [<c1040716>] do_exit+0x116/0x2e0 [ 200.786186] [<c1040944>] do_group_exit+0x34/0xb0 [ 200.786186] [<c10409cf>] sys_exit_group+0xf/0x20 [ 200.786186] [<c138d4e1>] syscall_call+0x7/0xb [ 200.786186] } [ 200.786186] ... key at: [<c1d4db30>] af_callback_keys+0x10/0x130 [ 200.786186] ... acquired at: [ 200.786186] [<c1069ff6>] check_usage_backwards+0x76/0xd0 [ 200.786186] [<c106a209>] mark_lock_irq+0x99/0x240 [ 200.786186] [<c106aeac>] mark_lock+0x21c/0x3c0 [ 200.786186] [<c106ab72>] mark_irqflags+0xe2/0x180 [ 200.786186] [<c106b90d>] __lock_acquire+0x38d/0x8e0 [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 200.786186] [<c138cbe9>] _raw_read_lock+0x39/0x70 [ 200.786186] [<c135e9be>] xs_tcp_state_change+0x1e/0x1d0 [ 200.786186] [<c1333167>] inet_shutdown+0x97/0x110 [ 200.786186] [<c12d8a89>] kernel_sock_shutdown+0x9/0x10 [ 200.786186] [<c135dcb7>] xs_tcp_shutdown+0x17/0x20 [ 200.786186] [<c135dfb7>] xs_tcp_close+0x27/0x30 [ 200.786186] [<c135c20d>] xprt_autoclose+0x1d/0x50 [ 200.786186] [<c1051767>] process_one_work+0x147/0x3a0 [ 200.786186] [<c1051aa6>] worker_thread+0xa6/0x200 [ 200.786186] [<c1056985>] kthread+0x75/0x80 [ 200.786186] [<c10031fa>] kernel_thread_helper+0x6/0x1c [ 200.786186] [ 200.786186] [ 200.786186] stack backtrace: [ 200.786186] Pid: 10, comm: kworker/0:1 Not tainted 2.6.36-rc5-old #2 [ 200.786186] Call Trace: [ 200.786186] [<c103ded8>] ? printk+0x18/0x20 [ 200.786186] [<c1069e88>] print_irq_inversion_bug+0x108/0x120 [ 200.786186] [<c1069ff6>] check_usage_backwards+0x76/0xd0 [ 200.786186] [<c106a209>] mark_lock_irq+0x99/0x240 [ 200.786186] [<c1069f80>] ? check_usage_backwards+0x0/0xd0 [ 200.786186] [<c106aeac>] mark_lock+0x21c/0x3c0 [ 200.786186] [<c106ab72>] mark_irqflags+0xe2/0x180 [ 200.786186] [<c106b90d>] __lock_acquire+0x38d/0x8e0 [ 200.786186] [<c106cc0a>] ? __lock_is_held+0x3a/0x60 [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 200.786186] [<c135e9be>] ? xs_tcp_state_change+0x1e/0x1d0 [ 200.786186] [<c138cbe9>] _raw_read_lock+0x39/0x70 [ 200.786186] [<c135e9be>] ? xs_tcp_state_change+0x1e/0x1d0 [ 200.786186] [<c135e9be>] xs_tcp_state_change+0x1e/0x1d0 [ 200.786186] [<c131fddf>] ? tcp_send_fin+0x4f/0xc0 [ 200.786186] [<c1333167>] inet_shutdown+0x97/0x110 [ 200.786186] [<c12d8a89>] kernel_sock_shutdown+0x9/0x10 [ 200.786186] [<c135dcb7>] xs_tcp_shutdown+0x17/0x20 [ 200.786186] [<c135dfb7>] xs_tcp_close+0x27/0x30 [ 200.786186] [<c135c20d>] xprt_autoclose+0x1d/0x50 [ 200.786186] [<c1051767>] process_one_work+0x147/0x3a0 [ 200.786186] [<c10516f6>] ? process_one_work+0xd6/0x3a0 [ 200.786186] [<c106d429>] ? __lock_acquired+0x119/0x1c0 [ 200.786186] [<c135c1f0>] ? xprt_autoclose+0x0/0x50 [ 200.786186] [<c1051a1c>] ? worker_thread+0x1c/0x200 [ 200.786186] [<c1050537>] ? __need_more_worker+0x17/0x40 [ 200.786186] [<c1051aa6>] worker_thread+0xa6/0x200 [ 200.786186] [<c1056985>] kthread+0x75/0x80 [ 200.786186] [<c1051a00>] ? worker_thread+0x0/0x200 [ 200.786186] [<c1056910>] ? kthread+0x0/0x80 [ 200.786186] [<c10031fa>] kernel_thread_helper+0x6/0x1c [ 208.718821] Restarting system. [ 208.720581] machine restart ^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [2.6.35-rc5] INET?: possible irq lock inversion dependency 2010-09-21 6:51 ` [2.6.35-rc5] INET?: " Tetsuo Handa @ 2010-09-21 7:56 ` Eric Dumazet 2010-09-21 9:10 ` [2.6.36-rc5] " Tetsuo Handa 0 siblings, 1 reply; 24+ messages in thread From: Eric Dumazet @ 2010-09-21 7:56 UTC (permalink / raw) To: Tetsuo Handa; +Cc: linux-fsdevel, netdev Le mardi 21 septembre 2010 à 15:51 +0900, Tetsuo Handa a écrit : > I succeeded to save undamaged messages by doing > > echo 1 > /proc/sys/kernel/printk_delay > > . (Well, it would be nice to do above before printing lockdep warning because > it prints a lot of lines enough to drop some lines.) > > Although my patch is still applied, I believe my patch is not the culprit. > This warning might be related to lock_sock_fast() which was introduced in > 2.6.35 because I'm seeing this warning since 2.6.35-rcX . What can I do next? > > Regards. > > [ 199.267633] nfsd: last server has exited, flushing export cache > [ 200.784089] > [ 200.784094] ========================================================= > [ 200.786186] [ INFO: possible irq lock inversion dependency detected ] > [ 200.786186] 2.6.36-rc5-old #2 > [ 200.786186] --------------------------------------------------------- > [ 200.786186] kworker/0:1/10 just changed the state of lock: > [ 200.786186] (clock-AF_INET){++.?..}, at: [<c135e9be>] xs_tcp_state_change+0x1e/0x1d0 > [ 200.786186] but this lock was taken by another, SOFTIRQ-safe lock in the past: > [ 200.786186] (slock-AF_INET){+.-...} > [ 200.786186] > [ 200.786186] and interrupts could create inverse lock ordering between them. > [ 200.786186] > [ 200.786186] > [ 200.786186] other info that might help us debug this: > [ 200.786186] 3 locks held by kworker/0:1/10: > [ 200.786186] #0: (rpciod){+.+.+.}, at: [<c10516f6>] process_one_work+0xd6/0x3a0 > [ 200.786186] #1: ((&xprt->task_cleanup)){+.+...}, at: [<c10516f6>] process_one_work+0xd6/0x3a0 > [ 200.786186] #2: (sk_lock-AF_INET-RPC){+.+...}, at: [<c1333119>] inet_shutdown+0x49/0x110 > [ 200.786186] > [ 200.786186] the shortest dependencies between 2nd lock and 1st lock: > [ 200.786186] -> (slock-AF_INET){+.-...} ops: 11832 { > [ 200.786186] HARDIRQ-ON-W at: > [ 200.786186] [<c106ab8e>] mark_irqflags+0xfe/0x180 > [ 200.786186] [<c106b90d>] __lock_acquire+0x38d/0x8e0 > [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 > [ 200.786186] [<c138ca3e>] _raw_spin_lock_bh+0x3e/0x80 > [ 200.786186] [<c12dba59>] lock_sock_fast+0x29/0x90 > [ 200.786186] [<c132bdb4>] udp_destroy_sock+0x14/0x40 > [ 200.786186] [<c12dbdb3>] sk_common_release+0xb3/0xc0 > [ 200.786186] [<c132c728>] udp_lib_close+0x8/0x10 > [ 200.786186] [<c133268e>] inet_release+0xbe/0x100 > [ 200.786186] [<c12d5f66>] sock_release+0x66/0x80 > [ 200.786186] [<c12d6ce2>] sock_close+0x12/0x30 > [ 200.786186] [<c10c66fb>] __fput+0x1cb/0x240 > [ 200.786186] [<c10c6789>] fput+0x19/0x20 > [ 200.786186] [<c10c45c3>] filp_close+0x43/0x70 > [ 200.786186] [<c103fded>] close_files+0xad/0x150 > [ 200.786186] [<c103fef9>] put_files_struct+0x29/0xf0 > [ 200.786186] [<c1040050>] exit_files+0x40/0x50 > [ 200.786186] [<c1040716>] do_exit+0x116/0x2e0 > [ 200.786186] [<c1040944>] do_group_exit+0x34/0xb0 > [ 200.786186] [<c10409cf>] sys_exit_group+0xf/0x20 > [ 200.786186] [<c138d4e1>] syscall_call+0x7/0xb > [ 200.786186] IN-SOFTIRQ-W at: > [ 200.786186] [<c106abae>] mark_irqflags+0x11e/0x180 > [ 200.786186] [<c106b90d>] __lock_acquire+0x38d/0x8e0 > [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 > [ 200.786186] [<c138c8c9>] _raw_spin_lock+0x39/0x70 > [ 200.786186] [<c12da3f1>] sk_clone+0xb1/0x2c0 > [ 200.786186] [<c13108ea>] inet_csk_clone+0x1a/0xb0 > [ 200.786186] [<c1325ecc>] tcp_create_openreq_child+0x1c/0x460 > [ 200.786186] [<c132359f>] tcp_v4_syn_recv_sock+0x3f/0x1e0 > [ 200.786186] [<c132649c>] tcp_check_req+0x18c/0x3b0 > [ 200.786186] [<c132378d>] tcp_v4_hnd_req+0x4d/0x160 > [ 200.786186] [<c1323ab9>] tcp_v4_do_rcv+0x159/0x280 > [ 200.786186] [<c1324154>] tcp_v4_rcv+0x574/0xa30 > [ 200.786186] [<c1305f63>] ip_local_deliver_finish+0x103/0x320 > [ 200.786186] [<c13061b0>] ip_local_deliver+0x30/0x40 > [ 200.786186] [<c1306329>] ip_rcv_finish+0x169/0x480 > [ 200.786186] [<c13067da>] ip_rcv+0x19a/0x2b0 > [ 200.786186] [<c12e743d>] __netif_receive_skb+0x21d/0x310 > [ 200.786186] [<c12e7f48>] process_backlog+0x88/0x160 > [ 200.786186] [<c12e8317>] net_rx_action+0x127/0x140 > [ 200.786186] [<c1042e90>] __do_softirq+0xd0/0x130 > [ 200.786186] INITIAL USE at: > [ 200.786186] [<c106b740>] __lock_acquire+0x1c0/0x8e0 > [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 > [ 200.786186] [<c138ca3e>] _raw_spin_lock_bh+0x3e/0x80 > [ 200.786186] [<c12dba59>] lock_sock_fast+0x29/0x90 > [ 200.786186] [<c132bdb4>] udp_destroy_sock+0x14/0x40 > [ 200.786186] [<c12dbdb3>] sk_common_release+0xb3/0xc0 > [ 200.786186] [<c132c728>] udp_lib_close+0x8/0x10 > [ 200.786186] [<c133268e>] inet_release+0xbe/0x100 > [ 200.786186] [<c12d5f66>] sock_release+0x66/0x80 > [ 200.786186] [<c12d6ce2>] sock_close+0x12/0x30 > [ 200.786186] [<c10c66fb>] __fput+0x1cb/0x240 > [ 200.786186] [<c10c6789>] fput+0x19/0x20 > [ 200.786186] [<c10c45c3>] filp_close+0x43/0x70 > [ 200.786186] [<c103fded>] close_files+0xad/0x150 > [ 200.786186] [<c103fef9>] put_files_struct+0x29/0xf0 > [ 200.786186] [<c1040050>] exit_files+0x40/0x50 > [ 200.786186] [<c1040716>] do_exit+0x116/0x2e0 > [ 200.786186] [<c1040944>] do_group_exit+0x34/0xb0 > [ 200.786186] [<c10409cf>] sys_exit_group+0xf/0x20 > [ 200.786186] [<c138d4e1>] syscall_call+0x7/0xb > [ 200.786186] } > [ 200.786186] ... key at: [<c1d4d9f0>] af_family_slock_keys+0x10/0x140 > [ 200.786186] ... acquired at: > [ 200.786186] [<c10693bb>] check_prevs_add+0xab/0x100 > [ 200.786186] [<c1069745>] validate_chain+0x305/0x5a0 > [ 200.786186] [<c106b82d>] __lock_acquire+0x2ad/0x8e0 > [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 > [ 200.786186] [<c138d07e>] _raw_write_lock_bh+0x3e/0x80 > [ 200.786186] [<c1310c16>] inet_csk_listen_stop+0x86/0x160 > [ 200.786186] [<c1313772>] tcp_close+0x382/0x390 > [ 200.786186] [<c133268e>] inet_release+0xbe/0x100 > [ 200.786186] [<c12d5f66>] sock_release+0x66/0x80 > [ 200.786186] [<c12d6ce2>] sock_close+0x12/0x30 > [ 200.786186] [<c10c66fb>] __fput+0x1cb/0x240 > [ 200.786186] [<c10c6789>] fput+0x19/0x20 > [ 200.786186] [<c10c45c3>] filp_close+0x43/0x70 > [ 200.786186] [<c10c465d>] sys_close+0x6d/0x110 > [ 200.786186] [<c138d4e1>] syscall_call+0x7/0xb > [ 200.786186] > [ 200.786186] -> (clock-AF_INET){++.?..} ops: 2429 { > [ 200.786186] HARDIRQ-ON-W at: > [ 200.786186] [<c106ab8e>] mark_irqflags+0xfe/0x180 > [ 200.786186] [<c106b90d>] __lock_acquire+0x38d/0x8e0 > [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 > [ 200.786186] [<c138d07e>] _raw_write_lock_bh+0x3e/0x80 > [ 200.786186] [<c12dbd2f>] sk_common_release+0x2f/0xc0 > [ 200.786186] [<c132c728>] udp_lib_close+0x8/0x10 > [ 200.786186] [<c133268e>] inet_release+0xbe/0x100 > [ 200.786186] [<c12d5f66>] sock_release+0x66/0x80 > [ 200.786186] [<c12d6ce2>] sock_close+0x12/0x30 > [ 200.786186] [<c10c66fb>] __fput+0x1cb/0x240 > [ 200.786186] [<c10c6789>] fput+0x19/0x20 > [ 200.786186] [<c10c45c3>] filp_close+0x43/0x70 > [ 200.786186] [<c103fded>] close_files+0xad/0x150 > [ 200.786186] [<c103fef9>] put_files_struct+0x29/0xf0 > [ 200.786186] [<c1040050>] exit_files+0x40/0x50 > [ 200.786186] [<c1040716>] do_exit+0x116/0x2e0 > [ 200.786186] [<c1040944>] do_group_exit+0x34/0xb0 > [ 200.786186] [<c10409cf>] sys_exit_group+0xf/0x20 > [ 200.786186] [<c138d4e1>] syscall_call+0x7/0xb > [ 200.786186] HARDIRQ-ON-R at: > [ 200.786186] [<c106aafe>] mark_irqflags+0x6e/0x180 > [ 200.786186] [<c106b90d>] __lock_acquire+0x38d/0x8e0 > [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 > [ 200.786186] [<c138cbe9>] _raw_read_lock+0x39/0x70 > [ 200.786186] [<c135e9be>] xs_tcp_state_change+0x1e/0x1d0 > [ 200.786186] [<c131c8a8>] tcp_rcv_synsent_state_process+0x398/0x590 > [ 200.786186] [<c131cf47>] tcp_rcv_state_process+0x4a7/0x560 > [ 200.786186] [<c13239d1>] tcp_v4_do_rcv+0x71/0x280 > [ 200.786186] [<c12dad26>] __release_sock+0x66/0x150 > [ 200.786186] [<c12dba27>] release_sock+0x87/0x90 > [ 200.786186] [<c1332a7a>] inet_stream_connect+0x5a/0x1b0 > [ 200.786186] [<c12d8888>] kernel_connect+0x18/0x30 > [ 200.786186] [<c135f66e>] xs_tcp_finish_connecting+0x4e/0x120 > [ 200.786186] [<c135f79b>] xs_tcp_setup_socket+0x5b/0x180 > [ 200.786186] [<c135f9d4>] xs_tcp_connect_worker4+0x14/0x20 > [ 200.786186] [<c1051767>] process_one_work+0x147/0x3a0 > [ 200.786186] [<c1051aa6>] worker_thread+0xa6/0x200 > [ 200.786186] [<c1056985>] kthread+0x75/0x80 > [ 200.786186] [<c10031fa>] kernel_thread_helper+0x6/0x1c > [ 200.786186] IN-SOFTIRQ-R at: > [ 200.786186] [<c106abae>] mark_irqflags+0x11e/0x180 > [ 200.786186] [<c106b90d>] __lock_acquire+0x38d/0x8e0 > [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 > [ 200.786186] [<c138cbe9>] _raw_read_lock+0x39/0x70 > [ 200.786186] [<c135e891>] xs_tcp_data_ready+0x21/0x90 > [ 200.786186] [<c131ad68>] tcp_data_queue+0x248/0x820 > [ 200.786186] [<c131c0de>] tcp_rcv_established+0xae/0x4e0 > [ 200.786186] [<c1323b31>] tcp_v4_do_rcv+0x1d1/0x280 > [ 200.786186] [<c1324154>] tcp_v4_rcv+0x574/0xa30 > [ 200.786186] [<c1305f63>] ip_local_deliver_finish+0x103/0x320 > [ 200.786186] [<c13061b0>] ip_local_deliver+0x30/0x40 > [ 200.786186] [<c1306329>] ip_rcv_finish+0x169/0x480 > [ 200.786186] [<c13067da>] ip_rcv+0x19a/0x2b0 > [ 200.786186] [<c12e743d>] __netif_receive_skb+0x21d/0x310 > [ 200.786186] [<c12e7f48>] process_backlog+0x88/0x160 > [ 200.786186] [<c12e8317>] net_rx_action+0x127/0x140 > [ 200.786186] [<c1042e90>] __do_softirq+0xd0/0x130 > [ 200.786186] SOFTIRQ-ON-R at: > [ 200.786186] [<c106ab72>] mark_irqflags+0xe2/0x180 > [ 200.786186] [<c106b90d>] __lock_acquire+0x38d/0x8e0 > [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 > [ 200.786186] [<c138cbe9>] _raw_read_lock+0x39/0x70 > [ 200.786186] [<c135e9be>] xs_tcp_state_change+0x1e/0x1d0 > [ 200.786186] [<c1333167>] inet_shutdown+0x97/0x110 > [ 200.786186] [<c12d8a89>] kernel_sock_shutdown+0x9/0x10 > [ 200.786186] [<c135dcb7>] xs_tcp_shutdown+0x17/0x20 > [ 200.786186] [<c135dfb7>] xs_tcp_close+0x27/0x30 > [ 200.786186] [<c135c20d>] xprt_autoclose+0x1d/0x50 > [ 200.786186] [<c1051767>] process_one_work+0x147/0x3a0 > [ 200.786186] [<c1051aa6>] worker_thread+0xa6/0x200 > [ 200.786186] [<c1056985>] kthread+0x75/0x80 > [ 200.786186] [<c10031fa>] kernel_thread_helper+0x6/0x1c > [ 200.786186] INITIAL USE at: > [ 200.786186] [<c106b740>] __lock_acquire+0x1c0/0x8e0 > [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 > [ 200.786186] [<c138d07e>] _raw_write_lock_bh+0x3e/0x80 > [ 200.786186] [<c12dbd2f>] sk_common_release+0x2f/0xc0 > [ 200.786186] [<c132c728>] udp_lib_close+0x8/0x10 > [ 200.786186] [<c133268e>] inet_release+0xbe/0x100 > [ 200.786186] [<c12d5f66>] sock_release+0x66/0x80 > [ 200.786186] [<c12d6ce2>] sock_close+0x12/0x30 > [ 200.786186] [<c10c66fb>] __fput+0x1cb/0x240 > [ 200.786186] [<c10c6789>] fput+0x19/0x20 > [ 200.786186] [<c10c45c3>] filp_close+0x43/0x70 > [ 200.786186] [<c103fded>] close_files+0xad/0x150 > [ 200.786186] [<c103fef9>] put_files_struct+0x29/0xf0 > [ 200.786186] [<c1040050>] exit_files+0x40/0x50 > [ 200.786186] [<c1040716>] do_exit+0x116/0x2e0 > [ 200.786186] [<c1040944>] do_group_exit+0x34/0xb0 > [ 200.786186] [<c10409cf>] sys_exit_group+0xf/0x20 > [ 200.786186] [<c138d4e1>] syscall_call+0x7/0xb > [ 200.786186] } > [ 200.786186] ... key at: [<c1d4db30>] af_callback_keys+0x10/0x130 > [ 200.786186] ... acquired at: > [ 200.786186] [<c1069ff6>] check_usage_backwards+0x76/0xd0 > [ 200.786186] [<c106a209>] mark_lock_irq+0x99/0x240 > [ 200.786186] [<c106aeac>] mark_lock+0x21c/0x3c0 > [ 200.786186] [<c106ab72>] mark_irqflags+0xe2/0x180 > [ 200.786186] [<c106b90d>] __lock_acquire+0x38d/0x8e0 > [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 > [ 200.786186] [<c138cbe9>] _raw_read_lock+0x39/0x70 > [ 200.786186] [<c135e9be>] xs_tcp_state_change+0x1e/0x1d0 > [ 200.786186] [<c1333167>] inet_shutdown+0x97/0x110 > [ 200.786186] [<c12d8a89>] kernel_sock_shutdown+0x9/0x10 > [ 200.786186] [<c135dcb7>] xs_tcp_shutdown+0x17/0x20 > [ 200.786186] [<c135dfb7>] xs_tcp_close+0x27/0x30 > [ 200.786186] [<c135c20d>] xprt_autoclose+0x1d/0x50 > [ 200.786186] [<c1051767>] process_one_work+0x147/0x3a0 > [ 200.786186] [<c1051aa6>] worker_thread+0xa6/0x200 > [ 200.786186] [<c1056985>] kthread+0x75/0x80 > [ 200.786186] [<c10031fa>] kernel_thread_helper+0x6/0x1c > [ 200.786186] > [ 200.786186] > [ 200.786186] stack backtrace: > [ 200.786186] Pid: 10, comm: kworker/0:1 Not tainted 2.6.36-rc5-old #2 > [ 200.786186] Call Trace: > [ 200.786186] [<c103ded8>] ? printk+0x18/0x20 > [ 200.786186] [<c1069e88>] print_irq_inversion_bug+0x108/0x120 > [ 200.786186] [<c1069ff6>] check_usage_backwards+0x76/0xd0 > [ 200.786186] [<c106a209>] mark_lock_irq+0x99/0x240 > [ 200.786186] [<c1069f80>] ? check_usage_backwards+0x0/0xd0 > [ 200.786186] [<c106aeac>] mark_lock+0x21c/0x3c0 > [ 200.786186] [<c106ab72>] mark_irqflags+0xe2/0x180 > [ 200.786186] [<c106b90d>] __lock_acquire+0x38d/0x8e0 > [ 200.786186] [<c106cc0a>] ? __lock_is_held+0x3a/0x60 > [ 200.786186] [<c106ceaa>] lock_acquire+0x7a/0xa0 > [ 200.786186] [<c135e9be>] ? xs_tcp_state_change+0x1e/0x1d0 > [ 200.786186] [<c138cbe9>] _raw_read_lock+0x39/0x70 > [ 200.786186] [<c135e9be>] ? xs_tcp_state_change+0x1e/0x1d0 > [ 200.786186] [<c135e9be>] xs_tcp_state_change+0x1e/0x1d0 > [ 200.786186] [<c131fddf>] ? tcp_send_fin+0x4f/0xc0 > [ 200.786186] [<c1333167>] inet_shutdown+0x97/0x110 > [ 200.786186] [<c12d8a89>] kernel_sock_shutdown+0x9/0x10 > [ 200.786186] [<c135dcb7>] xs_tcp_shutdown+0x17/0x20 > [ 200.786186] [<c135dfb7>] xs_tcp_close+0x27/0x30 > [ 200.786186] [<c135c20d>] xprt_autoclose+0x1d/0x50 > [ 200.786186] [<c1051767>] process_one_work+0x147/0x3a0 > [ 200.786186] [<c10516f6>] ? process_one_work+0xd6/0x3a0 > [ 200.786186] [<c106d429>] ? __lock_acquired+0x119/0x1c0 > [ 200.786186] [<c135c1f0>] ? xprt_autoclose+0x0/0x50 > [ 200.786186] [<c1051a1c>] ? worker_thread+0x1c/0x200 > [ 200.786186] [<c1050537>] ? __need_more_worker+0x17/0x40 > [ 200.786186] [<c1051aa6>] worker_thread+0xa6/0x200 > [ 200.786186] [<c1056985>] kthread+0x75/0x80 > [ 200.786186] [<c1051a00>] ? worker_thread+0x0/0x200 > [ 200.786186] [<c1056910>] ? kthread+0x0/0x80 > [ 200.786186] [<c10031fa>] kernel_thread_helper+0x6/0x1c > [ 208.718821] Restarting system. > [ 208.720581] machine restart I would say someone calls xs_tcp_state_change() while softirqs are not masked. If its expected, then following patch is needed ? diff --git a/net/sunrpc/xprtsock.c b/net/sunrpc/xprtsock.c index b6309db..fc94e5e 100644 --- a/net/sunrpc/xprtsock.c +++ b/net/sunrpc/xprtsock.c @@ -1301,7 +1301,7 @@ static void xs_tcp_state_change(struct sock *sk) { struct rpc_xprt *xprt; - read_lock(&sk->sk_callback_lock); + read_lock_bh(&sk->sk_callback_lock); if (!(xprt = xprt_from_sock(sk))) goto out; dprintk("RPC: xs_tcp_state_change client %p...\n", xprt); @@ -1313,7 +1313,7 @@ static void xs_tcp_state_change(struct sock *sk) switch (sk->sk_state) { case TCP_ESTABLISHED: - spin_lock_bh(&xprt->transport_lock); + spin_lock(&xprt->transport_lock); if (!xprt_test_and_set_connected(xprt)) { struct sock_xprt *transport = container_of(xprt, struct sock_xprt, xprt); @@ -1327,7 +1327,7 @@ static void xs_tcp_state_change(struct sock *sk) xprt_wake_pending_tasks(xprt, -EAGAIN); } - spin_unlock_bh(&xprt->transport_lock); + spin_unlock(&xprt->transport_lock); break; case TCP_FIN_WAIT1: /* The client initiated a shutdown of the socket */ @@ -1365,7 +1365,7 @@ static void xs_tcp_state_change(struct sock *sk) xs_sock_mark_closed(xprt); } out: - read_unlock(&sk->sk_callback_lock); + read_unlock_bh(&sk->sk_callback_lock); } /** -- To unsubscribe from this list: send the line "unsubscribe linux-fsdevel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html ^ permalink raw reply related [flat|nested] 24+ messages in thread
* Re: [2.6.36-rc5] INET?: possible irq lock inversion dependency 2010-09-21 7:56 ` Eric Dumazet @ 2010-09-21 9:10 ` Tetsuo Handa 2010-09-21 9:35 ` Eric Dumazet 0 siblings, 1 reply; 24+ messages in thread From: Tetsuo Handa @ 2010-09-21 9:10 UTC (permalink / raw) To: eric.dumazet; +Cc: linux-fsdevel, netdev Eric Dumazet wrote: > I would say someone calls xs_tcp_state_change() while softirqs are not > masked. > > If its expected, then following patch is needed ? After applying your patch, I got the same warning on different place. I got this when doing "mount 127.0.0.1:/usr/src/ /mnt/". Regards. [ 320.747630] [ 320.747633] ========================================================= [ 320.749957] [ INFO: possible irq lock inversion dependency detected ] [ 320.749957] 2.6.36-rc5-old #3 [ 320.749957] --------------------------------------------------------- [ 320.749957] mount/3799 just changed the state of lock: [ 320.749957] (clock-AF_INET){++.?..}, at: [<c135ec4c>] xs_udp_write_space+0x1c/0x50 [ 320.749957] but this lock was taken by another, SOFTIRQ-safe lock in the past: [ 320.749957] (slock-AF_INET){+.-...} [ 320.749957] [ 320.749957] and interrupts could create inverse lock ordering between them. [ 320.749957] [ 320.749957] [ 320.749957] other info that might help us debug this: [ 320.749957] no locks held by mount/3799. [ 320.749957] [ 320.749957] the shortest dependencies between 2nd lock and 1st lock: [ 320.749957] -> (slock-AF_INET){+.-...} ops: 4340 { [ 320.749957] HARDIRQ-ON-W at: [ 320.749957] [<c106ab8e>] mark_irqflags+0xfe/0x180 [ 320.749957] [<c106b90d>] __lock_acquire+0x38d/0x8e0 [ 320.749957] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 320.749957] [<c138ca3e>] _raw_spin_lock_bh+0x3e/0x80 [ 320.749957] [<c12dba59>] lock_sock_fast+0x29/0x90 [ 320.749957] [<c132bdb4>] udp_destroy_sock+0x14/0x40 [ 320.749957] [<c12dbdb3>] sk_common_release+0xb3/0xc0 [ 320.749957] [<c132c728>] udp_lib_close+0x8/0x10 [ 320.749957] [<c133268e>] inet_release+0xbe/0x100 [ 320.749957] [<c12d5f66>] sock_release+0x66/0x80 [ 320.749957] [<c12d6ce2>] sock_close+0x12/0x30 [ 320.749957] [<c10c66fb>] __fput+0x1cb/0x240 [ 320.749957] [<c10c6789>] fput+0x19/0x20 [ 320.749957] [<c10c45c3>] filp_close+0x43/0x70 [ 320.749957] [<c103fded>] close_files+0xad/0x150 [ 320.749957] [<c103fef9>] put_files_struct+0x29/0xf0 [ 320.749957] [<c1040050>] exit_files+0x40/0x50 [ 320.749957] [<c1040716>] do_exit+0x116/0x2e0 [ 320.749957] [<c1040944>] do_group_exit+0x34/0xb0 [ 320.749957] [<c10409cf>] sys_exit_group+0xf/0x20 [ 320.749957] [<c138d4e1>] syscall_call+0x7/0xb [ 320.749957] IN-SOFTIRQ-W at: [ 320.749957] [<c106abae>] mark_irqflags+0x11e/0x180 [ 320.749957] [<c106b90d>] __lock_acquire+0x38d/0x8e0 [ 320.749957] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 320.749957] [<c138c8c9>] _raw_spin_lock+0x39/0x70 [ 320.749957] [<c12da3f1>] sk_clone+0xb1/0x2c0 [ 320.749957] [<c13108ea>] inet_csk_clone+0x1a/0xb0 [ 320.749957] [<c1325ecc>] tcp_create_openreq_child+0x1c/0x460 [ 320.749957] [<c132359f>] tcp_v4_syn_recv_sock+0x3f/0x1e0 [ 320.749957] [<c132649c>] tcp_check_req+0x18c/0x3b0 [ 320.749957] [<c132378d>] tcp_v4_hnd_req+0x4d/0x160 [ 320.749957] [<c1323ab9>] tcp_v4_do_rcv+0x159/0x280 [ 320.749957] [<c1324154>] tcp_v4_rcv+0x574/0xa30 [ 320.749957] [<c1305f63>] ip_local_deliver_finish+0x103/0x320 [ 320.749957] [<c13061b0>] ip_local_deliver+0x30/0x40 [ 320.749957] [<c1306329>] ip_rcv_finish+0x169/0x480 [ 320.749957] [<c13067da>] ip_rcv+0x19a/0x2b0 [ 320.749957] [<c12e743d>] __netif_receive_skb+0x21d/0x310 [ 320.749957] [<c12e7f48>] process_backlog+0x88/0x160 [ 320.749957] [<c12e8317>] net_rx_action+0x127/0x140 [ 320.749957] [<c1042e90>] __do_softirq+0xd0/0x130 [ 320.749957] INITIAL USE at: [ 320.749957] [<c106b740>] __lock_acquire+0x1c0/0x8e0 [ 320.749957] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 320.749957] [<c138ca3e>] _raw_spin_lock_bh+0x3e/0x80 [ 320.749957] [<c12dba59>] lock_sock_fast+0x29/0x90 [ 320.749957] [<c132bdb4>] udp_destroy_sock+0x14/0x40 [ 320.749957] [<c12dbdb3>] sk_common_release+0xb3/0xc0 [ 320.749957] [<c132c728>] udp_lib_close+0x8/0x10 [ 320.749957] [<c133268e>] inet_release+0xbe/0x100 [ 320.749957] [<c12d5f66>] sock_release+0x66/0x80 [ 320.749957] [<c12d6ce2>] sock_close+0x12/0x30 [ 320.749957] [<c10c66fb>] __fput+0x1cb/0x240 [ 320.749957] [<c10c6789>] fput+0x19/0x20 [ 320.749957] [<c10c45c3>] filp_close+0x43/0x70 [ 320.749957] [<c103fded>] close_files+0xad/0x150 [ 320.749957] [<c103fef9>] put_files_struct+0x29/0xf0 [ 320.749957] [<c1040050>] exit_files+0x40/0x50 [ 320.749957] [<c1040716>] do_exit+0x116/0x2e0 [ 320.749957] [<c1040944>] do_group_exit+0x34/0xb0 [ 320.749957] [<c10409cf>] sys_exit_group+0xf/0x20 [ 320.749957] [<c138d4e1>] syscall_call+0x7/0xb [ 320.749957] } [ 320.749957] ... key at: [<c1d4d9f0>] af_family_slock_keys+0x10/0x140 [ 320.749957] ... acquired at: [ 320.749957] [<c10693bb>] check_prevs_add+0xab/0x100 [ 320.749957] [<c1069745>] validate_chain+0x305/0x5a0 [ 320.749957] [<c106b82d>] __lock_acquire+0x2ad/0x8e0 [ 320.749957] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 320.749957] [<c138d07e>] _raw_write_lock_bh+0x3e/0x80 [ 320.749957] [<c1310c16>] inet_csk_listen_stop+0x86/0x160 [ 320.749957] [<c1313772>] tcp_close+0x382/0x390 [ 320.749957] [<c133268e>] inet_release+0xbe/0x100 [ 320.749957] [<c12d5f66>] sock_release+0x66/0x80 [ 320.749957] [<c12d6ce2>] sock_close+0x12/0x30 [ 320.749957] [<c10c66fb>] __fput+0x1cb/0x240 [ 320.749957] [<c10c6789>] fput+0x19/0x20 [ 320.749957] [<c10c45c3>] filp_close+0x43/0x70 [ 320.749957] [<c10c465d>] sys_close+0x6d/0x110 [ 320.749957] [<c138d4e1>] syscall_call+0x7/0xb [ 320.749957] [ 320.749957] -> (clock-AF_INET){++.?..} ops: 850 { [ 320.749957] HARDIRQ-ON-W at: [ 320.749957] [<c106ab8e>] mark_irqflags+0xfe/0x180 [ 320.749957] [<c106b90d>] __lock_acquire+0x38d/0x8e0 [ 320.749957] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 320.749957] [<c138d07e>] _raw_write_lock_bh+0x3e/0x80 [ 320.749957] [<c12dbd2f>] sk_common_release+0x2f/0xc0 [ 320.749957] [<c132c728>] udp_lib_close+0x8/0x10 [ 320.749957] [<c133268e>] inet_release+0xbe/0x100 [ 320.749957] [<c12d5f66>] sock_release+0x66/0x80 [ 320.749957] [<c12d6ce2>] sock_close+0x12/0x30 [ 320.749957] [<c10c66fb>] __fput+0x1cb/0x240 [ 320.749957] [<c10c6789>] fput+0x19/0x20 [ 320.749957] [<c10c45c3>] filp_close+0x43/0x70 [ 320.749957] [<c103fded>] close_files+0xad/0x150 [ 320.749957] [<c103fef9>] put_files_struct+0x29/0xf0 [ 320.749957] [<c1040050>] exit_files+0x40/0x50 [ 320.749957] [<c1040716>] do_exit+0x116/0x2e0 [ 320.749957] [<c1040944>] do_group_exit+0x34/0xb0 [ 320.749957] [<c10409cf>] sys_exit_group+0xf/0x20 [ 320.749957] [<c138d4e1>] syscall_call+0x7/0xb [ 320.749957] HARDIRQ-ON-R at: [ 320.749957] [<c106aafe>] mark_irqflags+0x6e/0x180 [ 320.749957] [<c106b90d>] __lock_acquire+0x38d/0x8e0 [ 320.749957] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 320.749957] [<c138cd5e>] _raw_read_lock_bh+0x3e/0x80 [ 320.749957] [<c135e9be>] xs_tcp_state_change+0x1e/0x1d0 [ 320.749957] [<c131c8a8>] tcp_rcv_synsent_state_process+0x398/0x590 [ 320.749957] [<c131cf47>] tcp_rcv_state_process+0x4a7/0x560 [ 320.749957] [<c13239d1>] tcp_v4_do_rcv+0x71/0x280 [ 320.749957] [<c12dad26>] __release_sock+0x66/0x150 [ 320.749957] [<c12dba27>] release_sock+0x87/0x90 [ 320.749957] [<c1332a7a>] inet_stream_connect+0x5a/0x1b0 [ 320.749957] [<c12d8888>] kernel_connect+0x18/0x30 [ 320.749957] [<c135f66e>] xs_tcp_finish_connecting+0x4e/0x120 [ 320.749957] [<c135f79b>] xs_tcp_setup_socket+0x5b/0x180 [ 320.749957] [<c135f9d4>] xs_tcp_connect_worker4+0x14/0x20 [ 320.749957] [<c1051767>] process_one_work+0x147/0x3a0 [ 320.749957] [<c1051aa6>] worker_thread+0xa6/0x200 [ 320.749957] [<c1056985>] kthread+0x75/0x80 [ 320.749957] [<c10031fa>] kernel_thread_helper+0x6/0x1c [ 320.749957] IN-SOFTIRQ-R at: [ 320.749957] [<c106abae>] mark_irqflags+0x11e/0x180 [ 320.749957] [<c106b90d>] __lock_acquire+0x38d/0x8e0 [ 320.749957] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 320.749957] [<c138cbe9>] _raw_read_lock+0x39/0x70 [ 320.749957] [<c135e891>] xs_tcp_data_ready+0x21/0x90 [ 320.749957] [<c131ad68>] tcp_data_queue+0x248/0x820 [ 320.749957] [<c131c0de>] tcp_rcv_established+0xae/0x4e0 [ 320.749957] [<c1323b31>] tcp_v4_do_rcv+0x1d1/0x280 [ 320.749957] [<c1324154>] tcp_v4_rcv+0x574/0xa30 [ 320.749957] [<c1305f63>] ip_local_deliver_finish+0x103/0x320 [ 320.749957] [<c13061b0>] ip_local_deliver+0x30/0x40 [ 320.749957] [<c1306329>] ip_rcv_finish+0x169/0x480 [ 320.749957] [<c13067da>] ip_rcv+0x19a/0x2b0 [ 320.749957] [<c12e743d>] __netif_receive_skb+0x21d/0x310 [ 320.749957] [<c12e7f48>] process_backlog+0x88/0x160 [ 320.749957] [<c12e8317>] net_rx_action+0x127/0x140 [ 320.749957] [<c1042e90>] __do_softirq+0xd0/0x130 [ 320.749957] SOFTIRQ-ON-R at: [ 320.749957] [<c106ab72>] mark_irqflags+0xe2/0x180 [ 320.749957] [<c106b90d>] __lock_acquire+0x38d/0x8e0 [ 320.749957] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 320.749957] [<c138cbe9>] _raw_read_lock+0x39/0x70 [ 320.749957] [<c135ec4c>] xs_udp_write_space+0x1c/0x50 [ 320.749957] [<c135ed5a>] xs_udp_do_set_buffer_size+0x8a/0x90 [ 320.749957] [<c135ed9d>] xs_udp_set_buffer_size+0x3d/0x40 [ 320.749957] [<c135a0e8>] rpc_setbufsize+0x28/0x30 [ 320.749957] [<e09c4314>] nfs_server_set_fsinfo+0x364/0x400 [nfs] [ 320.749957] [<e09c4415>] nfs_probe_fsinfo+0x65/0x100 [nfs] [ 320.749957] [<e09c4717>] nfs_create_server+0x87/0x240 [nfs] [ 320.749957] [<e09ceaeb>] nfs_get_sb+0x8b/0x240 [nfs] [ 320.749957] [<c10c82c1>] vfs_kern_mount+0x71/0x190 [ 320.749957] [<c10c8607>] do_kern_mount+0x37/0x90 [ 320.749957] [<c10deae7>] do_new_mount+0x57/0xa0 [ 320.749957] [<c10df111>] do_mount+0x171/0x1b0 [ 320.749957] [<c10df40c>] sys_mount+0x6c/0xa0 [ 320.749957] [<c138d4e1>] syscall_call+0x7/0xb [ 320.749957] INITIAL USE at: [ 320.749957] [<c106b740>] __lock_acquire+0x1c0/0x8e0 [ 320.749957] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 320.749957] [<c138d07e>] _raw_write_lock_bh+0x3e/0x80 [ 320.749957] [<c12dbd2f>] sk_common_release+0x2f/0xc0 [ 320.749957] [<c132c728>] udp_lib_close+0x8/0x10 [ 320.749957] [<c133268e>] inet_release+0xbe/0x100 [ 320.749957] [<c12d5f66>] sock_release+0x66/0x80 [ 320.749957] [<c12d6ce2>] sock_close+0x12/0x30 [ 320.749957] [<c10c66fb>] __fput+0x1cb/0x240 [ 320.749957] [<c10c6789>] fput+0x19/0x20 [ 320.749957] [<c10c45c3>] filp_close+0x43/0x70 [ 320.749957] [<c103fded>] close_files+0xad/0x150 [ 320.749957] [<c103fef9>] put_files_struct+0x29/0xf0 [ 320.749957] [<c1040050>] exit_files+0x40/0x50 [ 320.749957] [<c1040716>] do_exit+0x116/0x2e0 [ 320.749957] [<c1040944>] do_group_exit+0x34/0xb0 [ 320.749957] [<c10409cf>] sys_exit_group+0xf/0x20 [ 320.749957] [<c138d4e1>] syscall_call+0x7/0xb [ 320.749957] } [ 320.749957] ... key at: [<c1d4db30>] af_callback_keys+0x10/0x130 [ 320.749957] ... acquired at: [ 320.749957] [<c1069ff6>] check_usage_backwards+0x76/0xd0 [ 320.749957] [<c106a209>] mark_lock_irq+0x99/0x240 [ 320.749957] [<c106aeac>] mark_lock+0x21c/0x3c0 [ 320.749957] [<c106ab72>] mark_irqflags+0xe2/0x180 [ 320.749957] [<c106b90d>] __lock_acquire+0x38d/0x8e0 [ 320.749957] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 320.749957] [<c138cbe9>] _raw_read_lock+0x39/0x70 [ 320.749957] [<c135ec4c>] xs_udp_write_space+0x1c/0x50 [ 320.749957] [<c135ed5a>] xs_udp_do_set_buffer_size+0x8a/0x90 [ 320.749957] [<c135ed9d>] xs_udp_set_buffer_size+0x3d/0x40 [ 320.749957] [<c135a0e8>] rpc_setbufsize+0x28/0x30 [ 320.749957] [<e09c4314>] nfs_server_set_fsinfo+0x364/0x400 [nfs] [ 320.749957] [<e09c4415>] nfs_probe_fsinfo+0x65/0x100 [nfs] [ 320.749957] [<e09c4717>] nfs_create_server+0x87/0x240 [nfs] [ 320.749957] [<e09ceaeb>] nfs_get_sb+0x8b/0x240 [nfs] [ 320.749957] [<c10c82c1>] vfs_kern_mount+0x71/0x190 [ 320.749957] [<c10c8607>] do_kern_mount+0x37/0x90 [ 320.749957] [<c10deae7>] do_new_mount+0x57/0xa0 [ 320.749957] [<c10df111>] do_mount+0x171/0x1b0 [ 320.749957] [<c10df40c>] sys_mount+0x6c/0xa0 [ 320.749957] [<c138d4e1>] syscall_call+0x7/0xb [ 320.749957] [ 320.749957] [ 320.749957] stack backtrace: [ 320.749957] Pid: 3799, comm: mount Not tainted 2.6.36-rc5-old #3 [ 320.749957] Call Trace: [ 320.749957] [<c103ded8>] ? printk+0x18/0x20 [ 320.749957] [<c1069e88>] print_irq_inversion_bug+0x108/0x120 [ 320.749957] [<c1069ff6>] check_usage_backwards+0x76/0xd0 [ 320.749957] [<c106a209>] mark_lock_irq+0x99/0x240 [ 320.749957] [<c1069f80>] ? check_usage_backwards+0x0/0xd0 [ 320.749957] [<c106aeac>] mark_lock+0x21c/0x3c0 [ 320.749957] [<c106ab72>] mark_irqflags+0xe2/0x180 [ 320.749957] [<c106b90d>] __lock_acquire+0x38d/0x8e0 [ 320.749957] [<c109a95e>] ? mempool_free_slab+0xe/0x10 [ 320.749957] [<c109a938>] ? mempool_free+0x98/0xa0 [ 320.749957] [<c106ceaa>] lock_acquire+0x7a/0xa0 [ 320.749957] [<c135ec4c>] ? xs_udp_write_space+0x1c/0x50 [ 320.749957] [<c138cbe9>] _raw_read_lock+0x39/0x70 [ 320.749957] [<c135ec4c>] ? xs_udp_write_space+0x1c/0x50 [ 320.749957] [<c135ec4c>] xs_udp_write_space+0x1c/0x50 [ 320.749957] [<c135ed5a>] xs_udp_do_set_buffer_size+0x8a/0x90 [ 320.749957] [<c135ed9d>] xs_udp_set_buffer_size+0x3d/0x40 [ 320.749957] [<c135ed60>] ? xs_udp_set_buffer_size+0x0/0x40 [ 320.749957] [<c135a0e8>] rpc_setbufsize+0x28/0x30 [ 320.749957] [<e09c4314>] nfs_server_set_fsinfo+0x364/0x400 [nfs] [ 320.749957] [<e09c4415>] nfs_probe_fsinfo+0x65/0x100 [nfs] [ 320.749957] [<c10bf8b8>] ? cache_alloc_debugcheck_after+0x98/0x1d0 [ 320.749957] [<e09cb1d3>] ? nfs_alloc_fattr+0x23/0x30 [nfs] [ 320.749957] [<e09c4717>] nfs_create_server+0x87/0x240 [nfs] [ 320.749957] [<e09cb1f5>] ? nfs_alloc_fhandle+0x15/0x30 [nfs] [ 320.749957] [<e09ceaeb>] nfs_get_sb+0x8b/0x240 [nfs] [ 320.749957] [<e09ce9b0>] ? nfs_compare_super+0x0/0x90 [nfs] [ 320.749957] [<c10c82c1>] vfs_kern_mount+0x71/0x190 [ 320.749957] [<c10dc4fc>] ? get_fs_type+0x8c/0xa0 [ 320.749957] [<c10c8607>] do_kern_mount+0x37/0x90 [ 320.749957] [<c10deae7>] do_new_mount+0x57/0xa0 [ 320.749957] [<c10df111>] do_mount+0x171/0x1b0 [ 320.749957] [<c10df40c>] sys_mount+0x6c/0xa0 [ 320.749957] [<c138d4e1>] syscall_call+0x7/0xb ^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [2.6.36-rc5] INET?: possible irq lock inversion dependency 2010-09-21 9:10 ` [2.6.36-rc5] " Tetsuo Handa @ 2010-09-21 9:35 ` Eric Dumazet 2010-09-21 10:13 ` Eric Dumazet 0 siblings, 1 reply; 24+ messages in thread From: Eric Dumazet @ 2010-09-21 9:35 UTC (permalink / raw) To: Tetsuo Handa; +Cc: linux-fsdevel, netdev Le mardi 21 septembre 2010 à 18:10 +0900, Tetsuo Handa a écrit : > Eric Dumazet wrote: > > I would say someone calls xs_tcp_state_change() while softirqs are not > > masked. > > > > If its expected, then following patch is needed ? > > After applying your patch, I got the same warning on different place. > I got this when doing "mount 127.0.0.1:/usr/src/ /mnt/". Hmm, but what are the changes in your tree ? -- To unsubscribe from this list: send the line "unsubscribe linux-fsdevel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html ^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [2.6.36-rc5] INET?: possible irq lock inversion dependency 2010-09-21 9:35 ` Eric Dumazet @ 2010-09-21 10:13 ` Eric Dumazet 2010-09-22 7:14 ` Tetsuo Handa 0 siblings, 1 reply; 24+ messages in thread From: Eric Dumazet @ 2010-09-21 10:13 UTC (permalink / raw) To: Tetsuo Handa; +Cc: linux-fsdevel, netdev Le mardi 21 septembre 2010 à 11:36 +0200, Eric Dumazet a écrit : > Le mardi 21 septembre 2010 à 18:10 +0900, Tetsuo Handa a écrit : > > Eric Dumazet wrote: > > > I would say someone calls xs_tcp_state_change() while softirqs are not > > > masked. > > > > > > If its expected, then following patch is needed ? > > > > After applying your patch, I got the same warning on different place. > > I got this when doing "mount 127.0.0.1:/usr/src/ /mnt/". > > Hmm, but what are the changes in your tree ? > (Because I dont have these lockdep splats here with 2.6.36-rc5) ^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [2.6.36-rc5] INET?: possible irq lock inversion dependency 2010-09-21 10:13 ` Eric Dumazet @ 2010-09-22 7:14 ` Tetsuo Handa 2010-09-22 8:31 ` Eric Dumazet 0 siblings, 1 reply; 24+ messages in thread From: Tetsuo Handa @ 2010-09-22 7:14 UTC (permalink / raw) To: eric.dumazet; +Cc: linux-fsdevel, netdev I established steps to reproduce this warning using clean 2.6.36-rc5 . [ 37.539697] ========================================================= [ 37.541991] [ INFO: possible irq lock inversion dependency detected ] [ 37.541991] 2.6.36-rc5 #1 [ 37.541991] --------------------------------------------------------- [ 37.541991] mount/2681 just changed the state of lock: [ 37.541991] (clock-AF_INET){++.?..}, at: [<c135e03c>] xs_udp_write_space+0x1c/0x50 [ 37.541991] but this lock was taken by another, SOFTIRQ-safe lock in the past: [ 37.541991] (slock-AF_INET){+.-...} [ 37.541991] [ 37.541991] and interrupts could create inverse lock ordering between them. [ 37.541991] [ 37.541991] [ 37.541991] other info that might help us debug this: [ 37.541991] no locks held by mount/2681. [ 37.541991] [ 37.541991] the shortest dependencies between 2nd lock and 1st lock: [ 37.541991] -> (slock-AF_INET){+.-...} ops: 562 { [ 37.541991] HARDIRQ-ON-W at: [ 37.541991] [<c106a8de>] mark_irqflags+0xfe/0x180 [ 37.541991] [<c106b65d>] __lock_acquire+0x38d/0x8e0 [ 37.541991] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 37.541991] [<c138be2e>] _raw_spin_lock_bh+0x3e/0x80 [ 37.541991] [<c12daf39>] lock_sock_fast+0x29/0x90 [ 37.541991] [<c132b1a4>] udp_destroy_sock+0x14/0x40 [ 37.541991] [<c12db293>] sk_common_release+0xb3/0xc0 [ 37.541991] [<c132bb18>] udp_lib_close+0x8/0x10 [ 37.541991] [<c1331a7e>] inet_release+0xbe/0x100 [ 37.541991] [<c12d5476>] sock_release+0x66/0x80 [ 37.541991] [<c12d61f2>] sock_close+0x12/0x30 [ 37.541991] [<c10c637b>] __fput+0x1cb/0x240 [ 37.541991] [<c10c6409>] fput+0x19/0x20 [ 37.541991] [<c10c4263>] filp_close+0x43/0x70 [ 37.541991] [<c103fdcd>] close_files+0xad/0x150 [ 37.541991] [<c103fed9>] put_files_struct+0x29/0xf0 [ 37.541991] [<c1040030>] exit_files+0x40/0x50 [ 37.541991] [<c10406f6>] do_exit+0x116/0x2e0 [ 37.541991] [<c1040924>] do_group_exit+0x34/0xb0 [ 37.541991] [<c10409af>] sys_exit_group+0xf/0x20 [ 37.541991] [<c138c8d1>] syscall_call+0x7/0xb [ 37.541991] IN-SOFTIRQ-W at: [ 37.541991] [<c106a8fe>] mark_irqflags+0x11e/0x180 [ 37.541991] [<c106b65d>] __lock_acquire+0x38d/0x8e0 [ 37.541991] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 37.541991] [<c138bcb9>] _raw_spin_lock+0x39/0x70 [ 37.541991] [<c12d98d1>] sk_clone+0xb1/0x2c0 [ 37.541991] [<c130fd7a>] inet_csk_clone+0x1a/0xb0 [ 37.541991] [<c132535c>] tcp_create_openreq_child+0x1c/0x460 [ 37.541991] [<c1322a2f>] tcp_v4_syn_recv_sock+0x3f/0x1e0 [ 37.940862] [<c132592c>] tcp_check_req+0x18c/0x3b0 [ 37.940862] [<c1322c1d>] tcp_v4_hnd_req+0x4d/0x160 [ 37.940862] [<c1322f49>] tcp_v4_do_rcv+0x159/0x280 [ 37.940862] [<c13235e4>] tcp_v4_rcv+0x574/0xa30 [ 37.940862] [<c1305443>] ip_local_deliver_finish+0x103/0x320 [ 37.940862] [<c1305690>] ip_local_deliver+0x30/0x40 [ 37.940862] [<c1305809>] ip_rcv_finish+0x169/0x480 [ 37.940862] [<c1305cba>] ip_rcv+0x19a/0x2b0 [ 37.940862] [<c12e691d>] __netif_receive_skb+0x21d/0x310 [ 37.940862] [<c12e7428>] process_backlog+0x88/0x160 [ 37.940862] [<c12e77f7>] net_rx_action+0x127/0x140 [ 37.940862] [<c1042e70>] __do_softirq+0xd0/0x130 [ 37.940862] INITIAL USE at: [ 37.940862] [<c106b490>] __lock_acquire+0x1c0/0x8e0 [ 37.940862] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 37.940862] [<c138be2e>] _raw_spin_lock_bh+0x3e/0x80 [ 37.940862] [<c12daf39>] lock_sock_fast+0x29/0x90 [ 37.940862] [<c132b1a4>] udp_destroy_sock+0x14/0x40 [ 37.940862] [<c12db293>] sk_common_release+0xb3/0xc0 [ 37.940862] [<c132bb18>] udp_lib_close+0x8/0x10 [ 37.940862] [<c1331a7e>] inet_release+0xbe/0x100 [ 37.940862] [<c12d5476>] sock_release+0x66/0x80 [ 37.940862] [<c12d61f2>] sock_close+0x12/0x30 [ 37.940862] [<c10c637b>] __fput+0x1cb/0x240 [ 37.940862] [<c10c6409>] fput+0x19/0x20 [ 37.940862] [<c10c4263>] filp_close+0x43/0x70 [ 37.940862] [<c103fdcd>] close_files+0xad/0x150 [ 37.940862] [<c103fed9>] put_files_struct+0x29/0xf0 [ 37.940862] [<c1040030>] exit_files+0x40/0x50 [ 37.940862] [<c10406f6>] do_exit+0x116/0x2e0 [ 37.940862] [<c1040924>] do_group_exit+0x34/0xb0 [ 37.940862] [<c10409af>] sys_exit_group+0xf/0x20 [ 37.940862] [<c138c8d1>] syscall_call+0x7/0xb [ 37.940862] } [ 37.940862] ... key at: [<c1d4c9d0>] af_family_slock_keys+0x10/0x140 [ 37.940862] ... acquired at: [ 37.940862] [<c106910b>] check_prevs_add+0xab/0x100 [ 37.940862] [<c1069495>] validate_chain+0x305/0x5a0 [ 37.940862] [<c106b57d>] __lock_acquire+0x2ad/0x8e0 [ 37.940862] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 37.940862] [<c138c46e>] _raw_write_lock_bh+0x3e/0x80 [ 37.940862] [<c13100a6>] inet_csk_listen_stop+0x86/0x160 [ 37.940862] [<c1312c02>] tcp_close+0x382/0x390 [ 37.940862] [<c1331a7e>] inet_release+0xbe/0x100 [ 37.940862] [<c12d5476>] sock_release+0x66/0x80 [ 37.940862] [<c12d61f2>] sock_close+0x12/0x30 [ 37.940862] [<c10c637b>] __fput+0x1cb/0x240 [ 37.940862] [<c10c6409>] fput+0x19/0x20 [ 37.940862] [<c10c4263>] filp_close+0x43/0x70 [ 37.940862] [<c10c42fd>] sys_close+0x6d/0x110 [ 37.940862] [<c138c8d1>] syscall_call+0x7/0xb [ 37.940862] [ 37.940862] -> (clock-AF_INET){++.?..} ops: 72 { [ 37.940862] HARDIRQ-ON-W at: [ 37.940862] [<c106a8de>] mark_irqflags+0xfe/0x180 [ 37.940862] [<c106b65d>] __lock_acquire+0x38d/0x8e0 [ 37.940862] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 37.940862] [<c138c46e>] _raw_write_lock_bh+0x3e/0x80 [ 37.940862] [<c12db20f>] sk_common_release+0x2f/0xc0 [ 37.940862] [<c132bb18>] udp_lib_close+0x8/0x10 [ 37.940862] [<c1331a7e>] inet_release+0xbe/0x100 [ 37.940862] [<c12d5476>] sock_release+0x66/0x80 [ 37.940862] [<c12d61f2>] sock_close+0x12/0x30 [ 37.940862] [<c10c637b>] __fput+0x1cb/0x240 [ 37.940862] [<c10c6409>] fput+0x19/0x20 [ 37.940862] [<c10c4263>] filp_close+0x43/0x70 [ 37.940862] [<c103fdcd>] close_files+0xad/0x150 [ 37.940862] [<c103fed9>] put_files_struct+0x29/0xf0 [ 37.940862] [<c1040030>] exit_files+0x40/0x50 [ 37.940862] [<c10406f6>] do_exit+0x116/0x2e0 [ 37.940862] [<c1040924>] do_group_exit+0x34/0xb0 [ 37.940862] [<c10409af>] sys_exit_group+0xf/0x20 [ 37.940862] [<c138c8d1>] syscall_call+0x7/0xb [ 37.940862] HARDIRQ-ON-R at: [ 37.940862] [<c106a84e>] mark_irqflags+0x6e/0x180 [ 37.940862] [<c106b65d>] __lock_acquire+0x38d/0x8e0 [ 37.940862] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 37.940862] [<c138bfd9>] _raw_read_lock+0x39/0x70 [ 37.940862] [<c135ddae>] xs_tcp_state_change+0x1e/0x1d0 [ 37.940862] [<c131bd38>] tcp_rcv_synsent_state_process+0x398/0x590 [ 37.940862] [<c131c3d7>] tcp_rcv_state_process+0x4a7/0x560 [ 37.940862] [<c1322e61>] tcp_v4_do_rcv+0x71/0x280 [ 37.940862] [<c12da206>] __release_sock+0x66/0x150 [ 37.940862] [<c12daf07>] release_sock+0x87/0x90 [ 37.940862] [<c1331e6a>] inet_stream_connect+0x5a/0x1b0 [ 37.940862] [<c12d7d68>] kernel_connect+0x18/0x30 [ 37.940862] [<c135ea5e>] xs_tcp_finish_connecting+0x4e/0x120 [ 37.940862] [<c135eb8b>] xs_tcp_setup_socket+0x5b/0x180 [ 37.940862] [<c135edc4>] xs_tcp_connect_worker4+0x14/0x20 [ 37.940862] [<c1051547>] process_one_work+0x147/0x3a0 [ 37.940862] [<c1051886>] worker_thread+0xa6/0x200 [ 37.940862] [<c1056765>] kthread+0x75/0x80 [ 37.940862] [<c10031fa>] kernel_thread_helper+0x6/0x1c [ 37.940862] IN-SOFTIRQ-R at: [ 37.940862] [<c106a8fe>] mark_irqflags+0x11e/0x180 [ 37.940862] [<c106b65d>] __lock_acquire+0x38d/0x8e0 [ 37.940862] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 37.940862] [<c138bfd9>] _raw_read_lock+0x39/0x70 [ 37.940862] [<c135dc81>] xs_tcp_data_ready+0x21/0x90 [ 37.940862] [<c131a1f8>] tcp_data_queue+0x248/0x820 [ 37.940862] [<c131b56e>] tcp_rcv_established+0xae/0x4e0 [ 37.940862] [<c1322fc1>] tcp_v4_do_rcv+0x1d1/0x280 [ 37.940862] [<c13235e4>] tcp_v4_rcv+0x574/0xa30 [ 37.940862] [<c1305443>] ip_local_deliver_finish+0x103/0x320 [ 37.940862] [<c1305690>] ip_local_deliver+0x30/0x40 [ 37.940862] [<c1305809>] ip_rcv_finish+0x169/0x480 [ 37.940862] [<c1305cba>] ip_rcv+0x19a/0x2b0 [ 37.940862] [<c12e691d>] __netif_receive_skb+0x21d/0x310 [ 37.940862] [<c12e7428>] process_backlog+0x88/0x160 [ 37.940862] [<c12e77f7>] net_rx_action+0x127/0x140 [ 37.940862] [<c1042e70>] __do_softirq+0xd0/0x130 [ 37.940862] SOFTIRQ-ON-R at: [ 37.940862] [<c106a8c2>] mark_irqflags+0xe2/0x180 [ 37.940862] [<c106b65d>] __lock_acquire+0x38d/0x8e0 [ 37.940862] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 37.940862] [<c138bfd9>] _raw_read_lock+0x39/0x70 [ 37.940862] [<c135e03c>] xs_udp_write_space+0x1c/0x50 [ 37.940862] [<c135e14a>] xs_udp_do_set_buffer_size+0x8a/0x90 [ 37.940862] [<c135e18d>] xs_udp_set_buffer_size+0x3d/0x40 [ 37.940862] [<c13594d8>] rpc_setbufsize+0x28/0x30 [ 37.940862] [<e0967314>] nfs_server_set_fsinfo+0x364/0x400 [nfs] [ 37.940862] [<e0967415>] nfs_probe_fsinfo+0x65/0x100 [nfs] [ 37.940862] [<e0967717>] nfs_create_server+0x87/0x240 [nfs] [ 37.940862] [<e0971aeb>] nfs_get_sb+0x8b/0x240 [nfs] [ 37.940862] [<c10c7f41>] vfs_kern_mount+0x71/0x190 [ 37.940862] [<c10c8287>] do_kern_mount+0x37/0x90 [ 37.940862] [<c10de6c7>] do_new_mount+0x57/0xa0 [ 37.940862] [<c10decc1>] do_mount+0x171/0x1b0 [ 37.940862] [<c10defbc>] sys_mount+0x6c/0xa0 [ 37.940862] [<c138c8d1>] syscall_call+0x7/0xb [ 37.940862] INITIAL USE at: [ 37.940862] [<c106b490>] __lock_acquire+0x1c0/0x8e0 [ 37.940862] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 37.940862] [<c138c46e>] _raw_write_lock_bh+0x3e/0x80 [ 37.940862] [<c12db20f>] sk_common_release+0x2f/0xc0 [ 37.940862] [<c132bb18>] udp_lib_close+0x8/0x10 [ 37.940862] [<c1331a7e>] inet_release+0xbe/0x100 [ 37.940862] [<c12d5476>] sock_release+0x66/0x80 [ 37.940862] [<c12d61f2>] sock_close+0x12/0x30 [ 37.940862] [<c10c637b>] __fput+0x1cb/0x240 [ 37.940862] [<c10c6409>] fput+0x19/0x20 [ 37.940862] [<c10c4263>] filp_close+0x43/0x70 [ 37.940862] [<c103fdcd>] close_files+0xad/0x150 [ 37.940862] [<c103fed9>] put_files_struct+0x29/0xf0 [ 37.940862] [<c1040030>] exit_files+0x40/0x50 [ 37.940862] [<c10406f6>] do_exit+0x116/0x2e0 [ 37.940862] [<c1040924>] do_group_exit+0x34/0xb0 [ 37.940862] [<c10409af>] sys_exit_group+0xf/0x20 [ 37.940862] [<c138c8d1>] syscall_call+0x7/0xb [ 37.940862] } [ 37.940862] ... key at: [<c1d4cb10>] af_callback_keys+0x10/0x130 [ 37.940862] ... acquired at: [ 37.940862] [<c1069d46>] check_usage_backwards+0x76/0xd0 [ 37.940862] [<c1069f59>] mark_lock_irq+0x99/0x240 [ 37.940862] [<c106abfc>] mark_lock+0x21c/0x3c0 [ 37.940862] [<c106a8c2>] mark_irqflags+0xe2/0x180 [ 37.940862] [<c106b65d>] __lock_acquire+0x38d/0x8e0 [ 37.940862] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 37.940862] [<c138bfd9>] _raw_read_lock+0x39/0x70 [ 37.940862] [<c135e03c>] xs_udp_write_space+0x1c/0x50 [ 37.940862] [<c135e14a>] xs_udp_do_set_buffer_size+0x8a/0x90 [ 37.940862] [<c135e18d>] xs_udp_set_buffer_size+0x3d/0x40 [ 37.940862] [<c13594d8>] rpc_setbufsize+0x28/0x30 [ 37.940862] [<e0967314>] nfs_server_set_fsinfo+0x364/0x400 [nfs] [ 37.940862] [<e0967415>] nfs_probe_fsinfo+0x65/0x100 [nfs] [ 37.940862] [<e0967717>] nfs_create_server+0x87/0x240 [nfs] [ 37.940862] [<e0971aeb>] nfs_get_sb+0x8b/0x240 [nfs] [ 37.940862] [<c10c7f41>] vfs_kern_mount+0x71/0x190 [ 37.940862] [<c10c8287>] do_kern_mount+0x37/0x90 [ 37.940862] [<c10de6c7>] do_new_mount+0x57/0xa0 [ 37.940862] [<c10decc1>] do_mount+0x171/0x1b0 [ 37.940862] [<c10defbc>] sys_mount+0x6c/0xa0 [ 37.940862] [<c138c8d1>] syscall_call+0x7/0xb [ 37.940862] [ 37.940862] [ 37.940862] stack backtrace: [ 37.940862] Pid: 2681, comm: mount Not tainted 2.6.36-rc5 #1 [ 37.940862] Call Trace: [ 37.940862] [<c103deb8>] ? printk+0x18/0x20 [ 37.940862] [<c1069bd8>] print_irq_inversion_bug+0x108/0x120 [ 37.940862] [<c1069d46>] check_usage_backwards+0x76/0xd0 [ 37.940862] [<c1069f59>] mark_lock_irq+0x99/0x240 [ 37.940862] [<c1069cd0>] ? check_usage_backwards+0x0/0xd0 [ 37.940862] [<c106abfc>] mark_lock+0x21c/0x3c0 [ 37.940862] [<c106a8c2>] mark_irqflags+0xe2/0x180 [ 37.940862] [<c106b65d>] __lock_acquire+0x38d/0x8e0 [ 37.940862] [<c109a5fe>] ? mempool_free_slab+0xe/0x10 [ 37.940862] [<c109a5d8>] ? mempool_free+0x98/0xa0 [ 37.940862] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 37.940862] [<c135e03c>] ? xs_udp_write_space+0x1c/0x50 [ 37.940862] [<c138bfd9>] _raw_read_lock+0x39/0x70 [ 37.940862] [<c135e03c>] ? xs_udp_write_space+0x1c/0x50 [ 37.940862] [<c135e03c>] xs_udp_write_space+0x1c/0x50 [ 37.940862] [<c135e14a>] xs_udp_do_set_buffer_size+0x8a/0x90 [ 37.940862] [<c135e18d>] xs_udp_set_buffer_size+0x3d/0x40 [ 37.940862] [<c135e150>] ? xs_udp_set_buffer_size+0x0/0x40 [ 37.940862] [<c13594d8>] rpc_setbufsize+0x28/0x30 [ 37.940862] [<e0967314>] nfs_server_set_fsinfo+0x364/0x400 [nfs] [ 37.940862] [<e0967415>] nfs_probe_fsinfo+0x65/0x100 [nfs] [ 37.940862] [<c10bf558>] ? cache_alloc_debugcheck_after+0x98/0x1d0 [ 37.940862] [<e096e1d3>] ? nfs_alloc_fattr+0x23/0x30 [nfs] [ 37.940862] [<e0967717>] nfs_create_server+0x87/0x240 [nfs] [ 37.940862] [<e096e1f5>] ? nfs_alloc_fhandle+0x15/0x30 [nfs] [ 37.940862] [<e0971aeb>] nfs_get_sb+0x8b/0x240 [nfs] [ 37.940862] [<e09719b0>] ? nfs_compare_super+0x0/0x90 [nfs] [ 37.940862] [<c10c7f41>] vfs_kern_mount+0x71/0x190 [ 37.940862] [<c10dc11c>] ? get_fs_type+0x8c/0xa0 [ 37.940862] [<c10c8287>] do_kern_mount+0x37/0x90 [ 37.940862] [<c10de6c7>] do_new_mount+0x57/0xa0 [ 37.940862] [<c10decc1>] do_mount+0x171/0x1b0 [ 37.940862] [<c10defbc>] sys_mount+0x6c/0xa0 [ 37.940862] [<c138c8d1>] syscall_call+0x7/0xb Boot and login and run test.sh below --- test.sh start --- #! /bin/sh ./a.out echo 1 > /proc/sys/kernel/printk_delay mount 127.0.0.1:/usr/src/ /mnt/ umount /mnt/ --- test.sh end --- where a.out is made by "gcc -Wall -O3 test.c" --- test.c start --- #include <stdlib.h> #include <unistd.h> #include <sys/types.h> #include <sys/socket.h> #include <arpa/inet.h> int main(int argc, char *argv[]) { int fd1 = socket(AF_INET, SOCK_STREAM, 0); int fd2 = socket(AF_INET, SOCK_STREAM, 0); struct sockaddr_in addr = { }; socklen_t size = sizeof(addr); addr.sin_family = AF_INET; addr.sin_addr.s_addr = htonl(INADDR_LOOPBACK); addr.sin_port = htons(0); bind(fd1, (struct sockaddr *) &addr, sizeof(addr)); listen(fd1, 5); getsockname(fd1, (struct sockaddr *) &addr, &size); connect(fd2, (struct sockaddr *) &addr, sizeof(addr)); close(fd1); close(fd2); return 0; } --- test.c end --- Config is at http://I-love.SAKURA.ne.jp/tmp/config-2.6.36-rc5 Full log is at http://I-love.SAKURA.ne.jp/tmp/dmesg-2.6.36-rc5.txt I'm using Debian Sarge on i686. Regards. ^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [2.6.36-rc5] INET?: possible irq lock inversion dependency 2010-09-22 7:14 ` Tetsuo Handa @ 2010-09-22 8:31 ` Eric Dumazet 2010-09-22 8:34 ` Eric Dumazet 0 siblings, 1 reply; 24+ messages in thread From: Eric Dumazet @ 2010-09-22 8:31 UTC (permalink / raw) To: Tetsuo Handa; +Cc: linux-fsdevel, netdev Le mercredi 22 septembre 2010 à 16:14 +0900, Tetsuo Handa a écrit : > I established steps to reproduce this warning using clean 2.6.36-rc5 . > > [ 37.539697] ========================================================= > [ 37.541991] [ INFO: possible irq lock inversion dependency detected ] > [ 37.541991] 2.6.36-rc5 #1 > [ 37.541991] --------------------------------------------------------- > [ 37.541991] mount/2681 just changed the state of lock: > [ 37.541991] (clock-AF_INET){++.?..}, at: [<c135e03c>] xs_udp_write_space+0x1c/0x50 > [ 37.541991] but this lock was taken by another, SOFTIRQ-safe lock in the past: > [ 37.541991] (slock-AF_INET){+.-...} > [ 37.541991] > [ 37.541991] and interrupts could create inverse lock ordering between them. > [ 37.541991] > [ 37.541991] > [ 37.541991] other info that might help us debug this: > [ 37.541991] no locks held by mount/2681. > [ 37.541991] > [ 37.541991] the shortest dependencies between 2nd lock and 1st lock: > [ 37.541991] -> (slock-AF_INET){+.-...} ops: 562 { > [ 37.541991] HARDIRQ-ON-W at: > [ 37.541991] [<c106a8de>] mark_irqflags+0xfe/0x180 > [ 37.541991] [<c106b65d>] __lock_acquire+0x38d/0x8e0 > [ 37.541991] [<c106cbfa>] lock_acquire+0x7a/0xa0 > [ 37.541991] [<c138be2e>] _raw_spin_lock_bh+0x3e/0x80 > [ 37.541991] [<c12daf39>] lock_sock_fast+0x29/0x90 > [ 37.541991] [<c132b1a4>] udp_destroy_sock+0x14/0x40 > [ 37.541991] [<c12db293>] sk_common_release+0xb3/0xc0 > [ 37.541991] [<c132bb18>] udp_lib_close+0x8/0x10 > [ 37.541991] [<c1331a7e>] inet_release+0xbe/0x100 > [ 37.541991] [<c12d5476>] sock_release+0x66/0x80 > [ 37.541991] [<c12d61f2>] sock_close+0x12/0x30 > [ 37.541991] [<c10c637b>] __fput+0x1cb/0x240 > [ 37.541991] [<c10c6409>] fput+0x19/0x20 > [ 37.541991] [<c10c4263>] filp_close+0x43/0x70 > [ 37.541991] [<c103fdcd>] close_files+0xad/0x150 > [ 37.541991] [<c103fed9>] put_files_struct+0x29/0xf0 > [ 37.541991] [<c1040030>] exit_files+0x40/0x50 > [ 37.541991] [<c10406f6>] do_exit+0x116/0x2e0 > [ 37.541991] [<c1040924>] do_group_exit+0x34/0xb0 > [ 37.541991] [<c10409af>] sys_exit_group+0xf/0x20 > [ 37.541991] [<c138c8d1>] syscall_call+0x7/0xb > [ 37.541991] IN-SOFTIRQ-W at: > [ 37.541991] [<c106a8fe>] mark_irqflags+0x11e/0x180 > [ 37.541991] [<c106b65d>] __lock_acquire+0x38d/0x8e0 > [ 37.541991] [<c106cbfa>] lock_acquire+0x7a/0xa0 > [ 37.541991] [<c138bcb9>] _raw_spin_lock+0x39/0x70 > [ 37.541991] [<c12d98d1>] sk_clone+0xb1/0x2c0 > [ 37.541991] [<c130fd7a>] inet_csk_clone+0x1a/0xb0 > [ 37.541991] [<c132535c>] tcp_create_openreq_child+0x1c/0x460 > [ 37.541991] [<c1322a2f>] tcp_v4_syn_recv_sock+0x3f/0x1e0 > [ 37.940862] [<c132592c>] tcp_check_req+0x18c/0x3b0 > [ 37.940862] [<c1322c1d>] tcp_v4_hnd_req+0x4d/0x160 > [ 37.940862] [<c1322f49>] tcp_v4_do_rcv+0x159/0x280 > [ 37.940862] [<c13235e4>] tcp_v4_rcv+0x574/0xa30 > [ 37.940862] [<c1305443>] ip_local_deliver_finish+0x103/0x320 > [ 37.940862] [<c1305690>] ip_local_deliver+0x30/0x40 > [ 37.940862] [<c1305809>] ip_rcv_finish+0x169/0x480 > [ 37.940862] [<c1305cba>] ip_rcv+0x19a/0x2b0 > [ 37.940862] [<c12e691d>] __netif_receive_skb+0x21d/0x310 > [ 37.940862] [<c12e7428>] process_backlog+0x88/0x160 > [ 37.940862] [<c12e77f7>] net_rx_action+0x127/0x140 > [ 37.940862] [<c1042e70>] __do_softirq+0xd0/0x130 > [ 37.940862] INITIAL USE at: > [ 37.940862] [<c106b490>] __lock_acquire+0x1c0/0x8e0 > [ 37.940862] [<c106cbfa>] lock_acquire+0x7a/0xa0 > [ 37.940862] [<c138be2e>] _raw_spin_lock_bh+0x3e/0x80 > [ 37.940862] [<c12daf39>] lock_sock_fast+0x29/0x90 > [ 37.940862] [<c132b1a4>] udp_destroy_sock+0x14/0x40 > [ 37.940862] [<c12db293>] sk_common_release+0xb3/0xc0 > [ 37.940862] [<c132bb18>] udp_lib_close+0x8/0x10 > [ 37.940862] [<c1331a7e>] inet_release+0xbe/0x100 > [ 37.940862] [<c12d5476>] sock_release+0x66/0x80 > [ 37.940862] [<c12d61f2>] sock_close+0x12/0x30 > [ 37.940862] [<c10c637b>] __fput+0x1cb/0x240 > [ 37.940862] [<c10c6409>] fput+0x19/0x20 > [ 37.940862] [<c10c4263>] filp_close+0x43/0x70 > [ 37.940862] [<c103fdcd>] close_files+0xad/0x150 > [ 37.940862] [<c103fed9>] put_files_struct+0x29/0xf0 > [ 37.940862] [<c1040030>] exit_files+0x40/0x50 > [ 37.940862] [<c10406f6>] do_exit+0x116/0x2e0 > [ 37.940862] [<c1040924>] do_group_exit+0x34/0xb0 > [ 37.940862] [<c10409af>] sys_exit_group+0xf/0x20 > [ 37.940862] [<c138c8d1>] syscall_call+0x7/0xb > [ 37.940862] } > [ 37.940862] ... key at: [<c1d4c9d0>] af_family_slock_keys+0x10/0x140 > [ 37.940862] ... acquired at: > [ 37.940862] [<c106910b>] check_prevs_add+0xab/0x100 > [ 37.940862] [<c1069495>] validate_chain+0x305/0x5a0 > [ 37.940862] [<c106b57d>] __lock_acquire+0x2ad/0x8e0 > [ 37.940862] [<c106cbfa>] lock_acquire+0x7a/0xa0 > [ 37.940862] [<c138c46e>] _raw_write_lock_bh+0x3e/0x80 > [ 37.940862] [<c13100a6>] inet_csk_listen_stop+0x86/0x160 > [ 37.940862] [<c1312c02>] tcp_close+0x382/0x390 > [ 37.940862] [<c1331a7e>] inet_release+0xbe/0x100 > [ 37.940862] [<c12d5476>] sock_release+0x66/0x80 > [ 37.940862] [<c12d61f2>] sock_close+0x12/0x30 > [ 37.940862] [<c10c637b>] __fput+0x1cb/0x240 > [ 37.940862] [<c10c6409>] fput+0x19/0x20 > [ 37.940862] [<c10c4263>] filp_close+0x43/0x70 > [ 37.940862] [<c10c42fd>] sys_close+0x6d/0x110 > [ 37.940862] [<c138c8d1>] syscall_call+0x7/0xb > [ 37.940862] > [ 37.940862] -> (clock-AF_INET){++.?..} ops: 72 { > [ 37.940862] HARDIRQ-ON-W at: > [ 37.940862] [<c106a8de>] mark_irqflags+0xfe/0x180 > [ 37.940862] [<c106b65d>] __lock_acquire+0x38d/0x8e0 > [ 37.940862] [<c106cbfa>] lock_acquire+0x7a/0xa0 > [ 37.940862] [<c138c46e>] _raw_write_lock_bh+0x3e/0x80 > [ 37.940862] [<c12db20f>] sk_common_release+0x2f/0xc0 > [ 37.940862] [<c132bb18>] udp_lib_close+0x8/0x10 > [ 37.940862] [<c1331a7e>] inet_release+0xbe/0x100 > [ 37.940862] [<c12d5476>] sock_release+0x66/0x80 > [ 37.940862] [<c12d61f2>] sock_close+0x12/0x30 > [ 37.940862] [<c10c637b>] __fput+0x1cb/0x240 > [ 37.940862] [<c10c6409>] fput+0x19/0x20 > [ 37.940862] [<c10c4263>] filp_close+0x43/0x70 > [ 37.940862] [<c103fdcd>] close_files+0xad/0x150 > [ 37.940862] [<c103fed9>] put_files_struct+0x29/0xf0 > [ 37.940862] [<c1040030>] exit_files+0x40/0x50 > [ 37.940862] [<c10406f6>] do_exit+0x116/0x2e0 > [ 37.940862] [<c1040924>] do_group_exit+0x34/0xb0 > [ 37.940862] [<c10409af>] sys_exit_group+0xf/0x20 > [ 37.940862] [<c138c8d1>] syscall_call+0x7/0xb > [ 37.940862] HARDIRQ-ON-R at: > [ 37.940862] [<c106a84e>] mark_irqflags+0x6e/0x180 > [ 37.940862] [<c106b65d>] __lock_acquire+0x38d/0x8e0 > [ 37.940862] [<c106cbfa>] lock_acquire+0x7a/0xa0 > [ 37.940862] [<c138bfd9>] _raw_read_lock+0x39/0x70 > [ 37.940862] [<c135ddae>] xs_tcp_state_change+0x1e/0x1d0 > [ 37.940862] [<c131bd38>] tcp_rcv_synsent_state_process+0x398/0x590 > [ 37.940862] [<c131c3d7>] tcp_rcv_state_process+0x4a7/0x560 > [ 37.940862] [<c1322e61>] tcp_v4_do_rcv+0x71/0x280 > [ 37.940862] [<c12da206>] __release_sock+0x66/0x150 > [ 37.940862] [<c12daf07>] release_sock+0x87/0x90 > [ 37.940862] [<c1331e6a>] inet_stream_connect+0x5a/0x1b0 > [ 37.940862] [<c12d7d68>] kernel_connect+0x18/0x30 > [ 37.940862] [<c135ea5e>] xs_tcp_finish_connecting+0x4e/0x120 > [ 37.940862] [<c135eb8b>] xs_tcp_setup_socket+0x5b/0x180 > [ 37.940862] [<c135edc4>] xs_tcp_connect_worker4+0x14/0x20 > [ 37.940862] [<c1051547>] process_one_work+0x147/0x3a0 > [ 37.940862] [<c1051886>] worker_thread+0xa6/0x200 > [ 37.940862] [<c1056765>] kthread+0x75/0x80 > [ 37.940862] [<c10031fa>] kernel_thread_helper+0x6/0x1c > [ 37.940862] IN-SOFTIRQ-R at: > [ 37.940862] [<c106a8fe>] mark_irqflags+0x11e/0x180 > [ 37.940862] [<c106b65d>] __lock_acquire+0x38d/0x8e0 > [ 37.940862] [<c106cbfa>] lock_acquire+0x7a/0xa0 > [ 37.940862] [<c138bfd9>] _raw_read_lock+0x39/0x70 > [ 37.940862] [<c135dc81>] xs_tcp_data_ready+0x21/0x90 > [ 37.940862] [<c131a1f8>] tcp_data_queue+0x248/0x820 > [ 37.940862] [<c131b56e>] tcp_rcv_established+0xae/0x4e0 > [ 37.940862] [<c1322fc1>] tcp_v4_do_rcv+0x1d1/0x280 > [ 37.940862] [<c13235e4>] tcp_v4_rcv+0x574/0xa30 > [ 37.940862] [<c1305443>] ip_local_deliver_finish+0x103/0x320 > [ 37.940862] [<c1305690>] ip_local_deliver+0x30/0x40 > [ 37.940862] [<c1305809>] ip_rcv_finish+0x169/0x480 > [ 37.940862] [<c1305cba>] ip_rcv+0x19a/0x2b0 > [ 37.940862] [<c12e691d>] __netif_receive_skb+0x21d/0x310 > [ 37.940862] [<c12e7428>] process_backlog+0x88/0x160 > [ 37.940862] [<c12e77f7>] net_rx_action+0x127/0x140 > [ 37.940862] [<c1042e70>] __do_softirq+0xd0/0x130 > [ 37.940862] SOFTIRQ-ON-R at: > [ 37.940862] [<c106a8c2>] mark_irqflags+0xe2/0x180 > [ 37.940862] [<c106b65d>] __lock_acquire+0x38d/0x8e0 > [ 37.940862] [<c106cbfa>] lock_acquire+0x7a/0xa0 > [ 37.940862] [<c138bfd9>] _raw_read_lock+0x39/0x70 > [ 37.940862] [<c135e03c>] xs_udp_write_space+0x1c/0x50 > [ 37.940862] [<c135e14a>] xs_udp_do_set_buffer_size+0x8a/0x90 > [ 37.940862] [<c135e18d>] xs_udp_set_buffer_size+0x3d/0x40 > [ 37.940862] [<c13594d8>] rpc_setbufsize+0x28/0x30 > [ 37.940862] [<e0967314>] nfs_server_set_fsinfo+0x364/0x400 [nfs] > [ 37.940862] [<e0967415>] nfs_probe_fsinfo+0x65/0x100 [nfs] > [ 37.940862] [<e0967717>] nfs_create_server+0x87/0x240 [nfs] > [ 37.940862] [<e0971aeb>] nfs_get_sb+0x8b/0x240 [nfs] > [ 37.940862] [<c10c7f41>] vfs_kern_mount+0x71/0x190 > [ 37.940862] [<c10c8287>] do_kern_mount+0x37/0x90 > [ 37.940862] [<c10de6c7>] do_new_mount+0x57/0xa0 > [ 37.940862] [<c10decc1>] do_mount+0x171/0x1b0 > [ 37.940862] [<c10defbc>] sys_mount+0x6c/0xa0 > [ 37.940862] [<c138c8d1>] syscall_call+0x7/0xb > [ 37.940862] INITIAL USE at: > [ 37.940862] [<c106b490>] __lock_acquire+0x1c0/0x8e0 > [ 37.940862] [<c106cbfa>] lock_acquire+0x7a/0xa0 > [ 37.940862] [<c138c46e>] _raw_write_lock_bh+0x3e/0x80 > [ 37.940862] [<c12db20f>] sk_common_release+0x2f/0xc0 > [ 37.940862] [<c132bb18>] udp_lib_close+0x8/0x10 > [ 37.940862] [<c1331a7e>] inet_release+0xbe/0x100 > [ 37.940862] [<c12d5476>] sock_release+0x66/0x80 > [ 37.940862] [<c12d61f2>] sock_close+0x12/0x30 > [ 37.940862] [<c10c637b>] __fput+0x1cb/0x240 > [ 37.940862] [<c10c6409>] fput+0x19/0x20 > [ 37.940862] [<c10c4263>] filp_close+0x43/0x70 > [ 37.940862] [<c103fdcd>] close_files+0xad/0x150 > [ 37.940862] [<c103fed9>] put_files_struct+0x29/0xf0 > [ 37.940862] [<c1040030>] exit_files+0x40/0x50 > [ 37.940862] [<c10406f6>] do_exit+0x116/0x2e0 > [ 37.940862] [<c1040924>] do_group_exit+0x34/0xb0 > [ 37.940862] [<c10409af>] sys_exit_group+0xf/0x20 > [ 37.940862] [<c138c8d1>] syscall_call+0x7/0xb > [ 37.940862] } > [ 37.940862] ... key at: [<c1d4cb10>] af_callback_keys+0x10/0x130 > [ 37.940862] ... acquired at: > [ 37.940862] [<c1069d46>] check_usage_backwards+0x76/0xd0 > [ 37.940862] [<c1069f59>] mark_lock_irq+0x99/0x240 > [ 37.940862] [<c106abfc>] mark_lock+0x21c/0x3c0 > [ 37.940862] [<c106a8c2>] mark_irqflags+0xe2/0x180 > [ 37.940862] [<c106b65d>] __lock_acquire+0x38d/0x8e0 > [ 37.940862] [<c106cbfa>] lock_acquire+0x7a/0xa0 > [ 37.940862] [<c138bfd9>] _raw_read_lock+0x39/0x70 > [ 37.940862] [<c135e03c>] xs_udp_write_space+0x1c/0x50 > [ 37.940862] [<c135e14a>] xs_udp_do_set_buffer_size+0x8a/0x90 > [ 37.940862] [<c135e18d>] xs_udp_set_buffer_size+0x3d/0x40 > [ 37.940862] [<c13594d8>] rpc_setbufsize+0x28/0x30 > [ 37.940862] [<e0967314>] nfs_server_set_fsinfo+0x364/0x400 [nfs] > [ 37.940862] [<e0967415>] nfs_probe_fsinfo+0x65/0x100 [nfs] > [ 37.940862] [<e0967717>] nfs_create_server+0x87/0x240 [nfs] > [ 37.940862] [<e0971aeb>] nfs_get_sb+0x8b/0x240 [nfs] > [ 37.940862] [<c10c7f41>] vfs_kern_mount+0x71/0x190 > [ 37.940862] [<c10c8287>] do_kern_mount+0x37/0x90 > [ 37.940862] [<c10de6c7>] do_new_mount+0x57/0xa0 > [ 37.940862] [<c10decc1>] do_mount+0x171/0x1b0 > [ 37.940862] [<c10defbc>] sys_mount+0x6c/0xa0 > [ 37.940862] [<c138c8d1>] syscall_call+0x7/0xb > [ 37.940862] > [ 37.940862] > [ 37.940862] stack backtrace: > [ 37.940862] Pid: 2681, comm: mount Not tainted 2.6.36-rc5 #1 > [ 37.940862] Call Trace: > [ 37.940862] [<c103deb8>] ? printk+0x18/0x20 > [ 37.940862] [<c1069bd8>] print_irq_inversion_bug+0x108/0x120 > [ 37.940862] [<c1069d46>] check_usage_backwards+0x76/0xd0 > [ 37.940862] [<c1069f59>] mark_lock_irq+0x99/0x240 > [ 37.940862] [<c1069cd0>] ? check_usage_backwards+0x0/0xd0 > [ 37.940862] [<c106abfc>] mark_lock+0x21c/0x3c0 > [ 37.940862] [<c106a8c2>] mark_irqflags+0xe2/0x180 > [ 37.940862] [<c106b65d>] __lock_acquire+0x38d/0x8e0 > [ 37.940862] [<c109a5fe>] ? mempool_free_slab+0xe/0x10 > [ 37.940862] [<c109a5d8>] ? mempool_free+0x98/0xa0 > [ 37.940862] [<c106cbfa>] lock_acquire+0x7a/0xa0 > [ 37.940862] [<c135e03c>] ? xs_udp_write_space+0x1c/0x50 > [ 37.940862] [<c138bfd9>] _raw_read_lock+0x39/0x70 > [ 37.940862] [<c135e03c>] ? xs_udp_write_space+0x1c/0x50 > [ 37.940862] [<c135e03c>] xs_udp_write_space+0x1c/0x50 > [ 37.940862] [<c135e14a>] xs_udp_do_set_buffer_size+0x8a/0x90 > [ 37.940862] [<c135e18d>] xs_udp_set_buffer_size+0x3d/0x40 > [ 37.940862] [<c135e150>] ? xs_udp_set_buffer_size+0x0/0x40 > [ 37.940862] [<c13594d8>] rpc_setbufsize+0x28/0x30 > [ 37.940862] [<e0967314>] nfs_server_set_fsinfo+0x364/0x400 [nfs] > [ 37.940862] [<e0967415>] nfs_probe_fsinfo+0x65/0x100 [nfs] > [ 37.940862] [<c10bf558>] ? cache_alloc_debugcheck_after+0x98/0x1d0 > [ 37.940862] [<e096e1d3>] ? nfs_alloc_fattr+0x23/0x30 [nfs] > [ 37.940862] [<e0967717>] nfs_create_server+0x87/0x240 [nfs] > [ 37.940862] [<e096e1f5>] ? nfs_alloc_fhandle+0x15/0x30 [nfs] > [ 37.940862] [<e0971aeb>] nfs_get_sb+0x8b/0x240 [nfs] > [ 37.940862] [<e09719b0>] ? nfs_compare_super+0x0/0x90 [nfs] > [ 37.940862] [<c10c7f41>] vfs_kern_mount+0x71/0x190 > [ 37.940862] [<c10dc11c>] ? get_fs_type+0x8c/0xa0 > [ 37.940862] [<c10c8287>] do_kern_mount+0x37/0x90 > [ 37.940862] [<c10de6c7>] do_new_mount+0x57/0xa0 > [ 37.940862] [<c10decc1>] do_mount+0x171/0x1b0 > [ 37.940862] [<c10defbc>] sys_mount+0x6c/0xa0 > [ 37.940862] [<c138c8d1>] syscall_call+0x7/0xb > > Boot and login and run test.sh below > > --- test.sh start --- > #! /bin/sh > ./a.out > echo 1 > /proc/sys/kernel/printk_delay > mount 127.0.0.1:/usr/src/ /mnt/ > umount /mnt/ > --- test.sh end --- > > where a.out is made by "gcc -Wall -O3 test.c" > > --- test.c start --- > #include <stdlib.h> > #include <unistd.h> > #include <sys/types.h> > #include <sys/socket.h> > #include <arpa/inet.h> > > int main(int argc, char *argv[]) > { > int fd1 = socket(AF_INET, SOCK_STREAM, 0); > int fd2 = socket(AF_INET, SOCK_STREAM, 0); > struct sockaddr_in addr = { }; > socklen_t size = sizeof(addr); > addr.sin_family = AF_INET; > addr.sin_addr.s_addr = htonl(INADDR_LOOPBACK); > addr.sin_port = htons(0); > bind(fd1, (struct sockaddr *) &addr, sizeof(addr)); > listen(fd1, 5); > getsockname(fd1, (struct sockaddr *) &addr, &size); > connect(fd2, (struct sockaddr *) &addr, sizeof(addr)); > close(fd1); > close(fd2); > return 0; > } > --- test.c end --- > > Config is at http://I-love.SAKURA.ne.jp/tmp/config-2.6.36-rc5 > Full log is at http://I-love.SAKURA.ne.jp/tmp/dmesg-2.6.36-rc5.txt > > I'm using Debian Sarge on i686. > > Regards. Thanks no splat here using your script/program And I dont really understand why a mixed udp & tcp workload could trigger a lockdep splat. Ah, all sockets of a same family (AF_INET in your case) share a single af_callback_keys : commit da21f24dd7395 said so. Problem is about sk_callback_lock, not the lock_sock_fast() I wonder if we dont need to use a separate "struct lock_class_key" per protocol (stored in struct proto) ... Could you try following interim patch ? Thanks diff --git a/include/net/sock.h b/include/net/sock.h index adab9dc..c5104bc 100644 --- a/include/net/sock.h +++ b/include/net/sock.h @@ -800,6 +800,7 @@ struct proto { #ifdef SOCK_REFCNT_DEBUG atomic_t socks; #endif + struct lock_class_key *callback_key; }; extern int proto_register(struct proto *prot, int alloc_slab); diff --git a/net/core/sock.c b/net/core/sock.c index b05b9b6..afd0f69 100644 --- a/net/core/sock.c +++ b/net/core/sock.c @@ -1210,7 +1210,9 @@ struct sock *sk_clone(const struct sock *sk, const gfp_t priority) spin_lock_init(&newsk->sk_dst_lock); rwlock_init(&newsk->sk_callback_lock); lockdep_set_class_and_name(&newsk->sk_callback_lock, - af_callback_keys + newsk->sk_family, + sk->sk_prot->callback_key ? + sk->sk_prot->callback_key : + af_callback_keys + newsk->sk_family, af_family_clock_key_strings[newsk->sk_family]); newsk->sk_dst_cache = NULL; @@ -1965,6 +1967,9 @@ void sock_init_data(struct socket *sock, struct sock *sk) spin_lock_init(&sk->sk_dst_lock); rwlock_init(&sk->sk_callback_lock); lockdep_set_class_and_name(&sk->sk_callback_lock, + sk->sk_prot->callback_key ? + sk->sk_prot->callback_key : + af_callback_keys + newsk->sk_family, af_callback_keys + sk->sk_family, af_family_clock_key_strings[sk->sk_family]); diff --git a/net/ipv4/udp.c b/net/ipv4/udp.c index fb23c2e..c0877b6 100644 --- a/net/ipv4/udp.c +++ b/net/ipv4/udp.c @@ -1870,6 +1870,8 @@ unsigned int udp_poll(struct file *file, struct socket *sock, poll_table *wait) } EXPORT_SYMBOL(udp_poll); +static struct lock_class_key udp_callback_key; + struct proto udp_prot = { .name = "UDP", .owner = THIS_MODULE, @@ -1899,6 +1901,7 @@ struct proto udp_prot = { .compat_setsockopt = compat_udp_setsockopt, .compat_getsockopt = compat_udp_getsockopt, #endif + .callback_key = &udp_callback_key, }; EXPORT_SYMBOL(udp_prot); diff --git a/net/ipv4/udplite.c b/net/ipv4/udplite.c index ab76aa9..51b159d 100644 --- a/net/ipv4/udplite.c +++ b/net/ipv4/udplite.c @@ -32,6 +32,8 @@ static const struct net_protocol udplite_protocol = { .netns_ok = 1, }; +static struct lock_class_key udplite_callback_key; + struct proto udplite_prot = { .name = "UDP-Lite", .owner = THIS_MODULE, @@ -57,6 +59,7 @@ struct proto udplite_prot = { .compat_setsockopt = compat_udp_setsockopt, .compat_getsockopt = compat_udp_getsockopt, #endif + .callback_key = &udplite_callback_key, }; EXPORT_SYMBOL(udplite_prot); diff --git a/net/ipv6/udp.c b/net/ipv6/udp.c index 5acb356..0777934 100644 --- a/net/ipv6/udp.c +++ b/net/ipv6/udp.c @@ -1441,6 +1441,8 @@ void udp6_proc_exit(struct net *net) { /* ------------------------------------------------------------------------ */ +static struct lock_class_key udp6_callback_key; + struct proto udpv6_prot = { .name = "UDPv6", .owner = THIS_MODULE, @@ -1469,6 +1471,7 @@ struct proto udpv6_prot = { .compat_setsockopt = compat_udpv6_setsockopt, .compat_getsockopt = compat_udpv6_getsockopt, #endif + .callback_key = &udp6_callback_key, }; static struct inet_protosw udpv6_protosw = { diff --git a/net/ipv6/udplite.c b/net/ipv6/udplite.c index 5f48fad..7bbb627 100644 --- a/net/ipv6/udplite.c +++ b/net/ipv6/udplite.c @@ -31,6 +31,8 @@ static const struct inet6_protocol udplitev6_protocol = { .flags = INET6_PROTO_NOPOLICY|INET6_PROTO_FINAL, }; +static struct lock_class_key udp6lite_callback_key; + struct proto udplitev6_prot = { .name = "UDPLITEv6", .owner = THIS_MODULE, @@ -55,6 +57,7 @@ struct proto udplitev6_prot = { .compat_setsockopt = compat_udpv6_setsockopt, .compat_getsockopt = compat_udpv6_getsockopt, #endif + .callback_key = &udp6lite_callback_key, }; static struct inet_protosw udplite6_protosw = { -- To unsubscribe from this list: send the line "unsubscribe linux-fsdevel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html ^ permalink raw reply related [flat|nested] 24+ messages in thread
* Re: [2.6.36-rc5] INET?: possible irq lock inversion dependency 2010-09-22 8:31 ` Eric Dumazet @ 2010-09-22 8:34 ` Eric Dumazet 2010-09-22 8:38 ` Eric Dumazet 0 siblings, 1 reply; 24+ messages in thread From: Eric Dumazet @ 2010-09-22 8:34 UTC (permalink / raw) To: Tetsuo Handa; +Cc: linux-fsdevel, netdev Le mercredi 22 septembre 2010 à 10:31 +0200, Eric Dumazet a écrit : > diff --git a/net/core/sock.c b/net/core/sock.c > index b05b9b6..afd0f69 100644 > --- a/net/core/sock.c > +++ b/net/core/sock.c > @@ -1210,7 +1210,9 @@ struct sock *sk_clone(const struct sock *sk, const gfp_t priority) > spin_lock_init(&newsk->sk_dst_lock); > rwlock_init(&newsk->sk_callback_lock); > lockdep_set_class_and_name(&newsk->sk_callback_lock, > - af_callback_keys + newsk->sk_family, > + sk->sk_prot->callback_key ? > + sk->sk_prot->callback_key : > + af_callback_keys + newsk->sk_family, > af_family_clock_key_strings[newsk->sk_family]); > > newsk->sk_dst_cache = NULL; > @@ -1965,6 +1967,9 @@ void sock_init_data(struct socket *sock, struct sock *sk) > spin_lock_init(&sk->sk_dst_lock); > rwlock_init(&sk->sk_callback_lock); > lockdep_set_class_and_name(&sk->sk_callback_lock, > + sk->sk_prot->callback_key ? > + sk->sk_prot->callback_key : > + af_callback_keys + newsk->sk_family, small bug in my patch , please delete the orphan line : > af_callback_keys + sk->sk_family, > af_family_clock_key_strings[sk->sk_family]); > -- To unsubscribe from this list: send the line "unsubscribe linux-fsdevel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html ^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [2.6.36-rc5] INET?: possible irq lock inversion dependency 2010-09-22 8:34 ` Eric Dumazet @ 2010-09-22 8:38 ` Eric Dumazet 2010-09-22 8:58 ` Tetsuo Handa 0 siblings, 1 reply; 24+ messages in thread From: Eric Dumazet @ 2010-09-22 8:38 UTC (permalink / raw) To: Tetsuo Handa; +Cc: linux-fsdevel, netdev Le mercredi 22 septembre 2010 à 10:34 +0200, Eric Dumazet a écrit : > small bug in my patch , please delete the orphan line : > > > af_callback_keys + sk->sk_family, > > > > af_family_clock_key_strings[sk->sk_family]); > > > Updated and booted/tested patch : include/net/sock.h | 1 + net/core/sock.c | 8 ++++++-- net/ipv4/udp.c | 3 +++ net/ipv4/udplite.c | 3 +++ net/ipv6/udp.c | 3 +++ net/ipv6/udplite.c | 3 +++ 6 files changed, 19 insertions(+), 2 deletions(-) diff --git a/include/net/sock.h b/include/net/sock.h index adab9dc..c5104bc 100644 --- a/include/net/sock.h +++ b/include/net/sock.h @@ -800,6 +800,7 @@ struct proto { #ifdef SOCK_REFCNT_DEBUG atomic_t socks; #endif + struct lock_class_key *callback_key; }; extern int proto_register(struct proto *prot, int alloc_slab); diff --git a/net/core/sock.c b/net/core/sock.c index b05b9b6..79ef50a 100644 --- a/net/core/sock.c +++ b/net/core/sock.c @@ -1210,7 +1210,9 @@ struct sock *sk_clone(const struct sock *sk, const gfp_t priority) spin_lock_init(&newsk->sk_dst_lock); rwlock_init(&newsk->sk_callback_lock); lockdep_set_class_and_name(&newsk->sk_callback_lock, - af_callback_keys + newsk->sk_family, + sk->sk_prot->callback_key ? + sk->sk_prot->callback_key : + af_callback_keys + newsk->sk_family, af_family_clock_key_strings[newsk->sk_family]); newsk->sk_dst_cache = NULL; @@ -1965,7 +1967,9 @@ void sock_init_data(struct socket *sock, struct sock *sk) spin_lock_init(&sk->sk_dst_lock); rwlock_init(&sk->sk_callback_lock); lockdep_set_class_and_name(&sk->sk_callback_lock, - af_callback_keys + sk->sk_family, + sk->sk_prot->callback_key ? + sk->sk_prot->callback_key : + af_callback_keys + sk->sk_family, af_family_clock_key_strings[sk->sk_family]); sk->sk_state_change = sock_def_wakeup; diff --git a/net/ipv4/udp.c b/net/ipv4/udp.c index fb23c2e..c0877b6 100644 --- a/net/ipv4/udp.c +++ b/net/ipv4/udp.c @@ -1870,6 +1870,8 @@ unsigned int udp_poll(struct file *file, struct socket *sock, poll_table *wait) } EXPORT_SYMBOL(udp_poll); +static struct lock_class_key udp_callback_key; + struct proto udp_prot = { .name = "UDP", .owner = THIS_MODULE, @@ -1899,6 +1901,7 @@ struct proto udp_prot = { .compat_setsockopt = compat_udp_setsockopt, .compat_getsockopt = compat_udp_getsockopt, #endif + .callback_key = &udp_callback_key, }; EXPORT_SYMBOL(udp_prot); diff --git a/net/ipv4/udplite.c b/net/ipv4/udplite.c index ab76aa9..51b159d 100644 --- a/net/ipv4/udplite.c +++ b/net/ipv4/udplite.c @@ -32,6 +32,8 @@ static const struct net_protocol udplite_protocol = { .netns_ok = 1, }; +static struct lock_class_key udplite_callback_key; + struct proto udplite_prot = { .name = "UDP-Lite", .owner = THIS_MODULE, @@ -57,6 +59,7 @@ struct proto udplite_prot = { .compat_setsockopt = compat_udp_setsockopt, .compat_getsockopt = compat_udp_getsockopt, #endif + .callback_key = &udplite_callback_key, }; EXPORT_SYMBOL(udplite_prot); diff --git a/net/ipv6/udp.c b/net/ipv6/udp.c index 5acb356..0777934 100644 --- a/net/ipv6/udp.c +++ b/net/ipv6/udp.c @@ -1441,6 +1441,8 @@ void udp6_proc_exit(struct net *net) { /* ------------------------------------------------------------------------ */ +static struct lock_class_key udp6_callback_key; + struct proto udpv6_prot = { .name = "UDPv6", .owner = THIS_MODULE, @@ -1469,6 +1471,7 @@ struct proto udpv6_prot = { .compat_setsockopt = compat_udpv6_setsockopt, .compat_getsockopt = compat_udpv6_getsockopt, #endif + .callback_key = &udp6_callback_key, }; static struct inet_protosw udpv6_protosw = { diff --git a/net/ipv6/udplite.c b/net/ipv6/udplite.c index 5f48fad..7bbb627 100644 --- a/net/ipv6/udplite.c +++ b/net/ipv6/udplite.c @@ -31,6 +31,8 @@ static const struct inet6_protocol udplitev6_protocol = { .flags = INET6_PROTO_NOPOLICY|INET6_PROTO_FINAL, }; +static struct lock_class_key udp6lite_callback_key; + struct proto udplitev6_prot = { .name = "UDPLITEv6", .owner = THIS_MODULE, @@ -55,6 +57,7 @@ struct proto udplitev6_prot = { .compat_setsockopt = compat_udpv6_setsockopt, .compat_getsockopt = compat_udpv6_getsockopt, #endif + .callback_key = &udp6lite_callback_key, }; static struct inet_protosw udplite6_protosw = { -- To unsubscribe from this list: send the line "unsubscribe linux-fsdevel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html ^ permalink raw reply related [flat|nested] 24+ messages in thread
* Re: [2.6.36-rc5] INET?: possible irq lock inversion dependency 2010-09-22 8:38 ` Eric Dumazet @ 2010-09-22 8:58 ` Tetsuo Handa 2010-09-22 17:35 ` Eric Dumazet 0 siblings, 1 reply; 24+ messages in thread From: Tetsuo Handa @ 2010-09-22 8:58 UTC (permalink / raw) To: eric.dumazet; +Cc: linux-fsdevel, netdev > Updated and booted/tested patch : The warning by test.sh disappeared by your patch. But the warning which I encounter upon reboot still appears. [ 74.289683] nfsd: last server has exited, flushing export cache [ 75.935807] [ 75.935811] ========================================================= [ 75.937431] [ INFO: possible irq lock inversion dependency detected ] [ 75.937431] 2.6.36-rc5 #2 [ 75.937431] --------------------------------------------------------- [ 75.937431] kworker/1:1/418 just changed the state of lock: [ 75.937431] (clock-AF_INET#2){++.?..}, at: [<c135ddee>] xs_tcp_state_change+0x1e/0x1d0 [ 75.937431] but this lock was taken by another, SOFTIRQ-safe lock in the past: [ 75.937431] (slock-AF_INET){+.-...} [ 75.937431] [ 75.937431] and interrupts could create inverse lock ordering between them. [ 75.937431] [ 75.937431] [ 75.937431] other info that might help us debug this: [ 75.937431] 3 locks held by kworker/1:1/418: [ 75.937431] #0: (rpciod){+.+.+.}, at: [<c10514d6>] process_one_work+0xd6/0x3a0 [ 75.937431] #1: ((&xprt->task_cleanup)){+.+...}, at: [<c10514d6>] process_one_work+0xd6/0x3a0 [ 75.937431] #2: (sk_lock-AF_INET-RPC){+.+...}, at: [<c1332549>] inet_shutdown+0x49/0x110 [ 75.937431] [ 75.937431] the shortest dependencies between 2nd lock and 1st lock: [ 75.937431] -> (slock-AF_INET){+.-...} ops: 1648 { [ 75.937431] HARDIRQ-ON-W at: [ 75.937431] [<c106a8de>] mark_irqflags+0xfe/0x180 [ 75.937431] [<c106b65d>] __lock_acquire+0x38d/0x8e0 [ 75.937431] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 75.937431] [<c138be6e>] _raw_spin_lock_bh+0x3e/0x80 [ 75.937431] [<c12daf79>] lock_sock_fast+0x29/0x90 [ 75.937431] [<c132b1e4>] udp_destroy_sock+0x14/0x40 [ 75.937431] [<c12db2d3>] sk_common_release+0xb3/0xc0 [ 75.937431] [<c132bb58>] udp_lib_close+0x8/0x10 [ 75.937431] [<c1331abe>] inet_release+0xbe/0x100 [ 75.937431] [<c12d5476>] sock_release+0x66/0x80 [ 75.937431] [<c12d61f2>] sock_close+0x12/0x30 [ 75.937431] [<c10c637b>] __fput+0x1cb/0x240 [ 75.937431] [<c10c6409>] fput+0x19/0x20 [ 75.937431] [<c10c4263>] filp_close+0x43/0x70 [ 75.937431] [<c103fdcd>] close_files+0xad/0x150 [ 75.937431] [<c103fed9>] put_files_struct+0x29/0xf0 [ 75.937431] [<c1040030>] exit_files+0x40/0x50 [ 75.937431] [<c10406f6>] do_exit+0x116/0x2e0 [ 75.937431] [<c1040924>] do_group_exit+0x34/0xb0 [ 75.937431] [<c10409af>] sys_exit_group+0xf/0x20 [ 75.937431] [<c138c911>] syscall_call+0x7/0xb [ 75.937431] IN-SOFTIRQ-W at: [ 75.937431] [<c106a8fe>] mark_irqflags+0x11e/0x180 [ 75.937431] [<c106b65d>] __lock_acquire+0x38d/0x8e0 [ 75.937431] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 75.937431] [<c138bcf9>] _raw_spin_lock+0x39/0x70 [ 75.937431] [<c12d98d1>] sk_clone+0xb1/0x2e0 [ 75.937431] [<c130fdba>] inet_csk_clone+0x1a/0xb0 [ 75.937431] [<c132539c>] tcp_create_openreq_child+0x1c/0x460 [ 75.937431] [<c1322a6f>] tcp_v4_syn_recv_sock+0x3f/0x1e0 [ 75.937431] [<c132596c>] tcp_check_req+0x18c/0x3b0 [ 75.937431] [<c1322c5d>] tcp_v4_hnd_req+0x4d/0x160 [ 75.937431] [<c1322f89>] tcp_v4_do_rcv+0x159/0x280 [ 75.937431] [<c1323624>] tcp_v4_rcv+0x574/0xa30 [ 75.937431] [<c1305483>] ip_local_deliver_finish+0x103/0x320 [ 75.937431] [<c13056d0>] ip_local_deliver+0x30/0x40 [ 75.937431] [<c1305849>] ip_rcv_finish+0x169/0x480 [ 75.937431] [<c1305cfa>] ip_rcv+0x19a/0x2b0 [ 75.937431] [<c12e695d>] __netif_receive_skb+0x21d/0x310 [ 75.937431] [<c12e7468>] process_backlog+0x88/0x160 [ 75.937431] [<c12e7837>] net_rx_action+0x127/0x140 [ 75.937431] [<c1042e70>] __do_softirq+0xd0/0x130 [ 75.937431] INITIAL USE at: [ 75.937431] [<c106b490>] __lock_acquire+0x1c0/0x8e0 [ 75.937431] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 75.937431] [<c138be6e>] _raw_spin_lock_bh+0x3e/0x80 [ 75.937431] [<c12daf79>] lock_sock_fast+0x29/0x90 [ 75.937431] [<c132b1e4>] udp_destroy_sock+0x14/0x40 [ 75.937431] [<c12db2d3>] sk_common_release+0xb3/0xc0 [ 75.937431] [<c132bb58>] udp_lib_close+0x8/0x10 [ 75.937431] [<c1331abe>] inet_release+0xbe/0x100 [ 75.937431] [<c12d5476>] sock_release+0x66/0x80 [ 75.937431] [<c12d61f2>] sock_close+0x12/0x30 [ 75.937431] [<c10c637b>] __fput+0x1cb/0x240 [ 75.937431] [<c10c6409>] fput+0x19/0x20 [ 75.937431] [<c10c4263>] filp_close+0x43/0x70 [ 75.937431] [<c103fdcd>] close_files+0xad/0x150 [ 75.937431] [<c103fed9>] put_files_struct+0x29/0xf0 [ 75.937431] [<c1040030>] exit_files+0x40/0x50 [ 75.937431] [<c10406f6>] do_exit+0x116/0x2e0 [ 75.937431] [<c1040924>] do_group_exit+0x34/0xb0 [ 75.937431] [<c10409af>] sys_exit_group+0xf/0x20 [ 75.937431] [<c138c911>] syscall_call+0x7/0xb [ 75.937431] } [ 75.937431] ... key at: [<c1d4c9d0>] af_family_slock_keys+0x10/0x140 [ 75.937431] ... acquired at: [ 75.937431] [<c106910b>] check_prevs_add+0xab/0x100 [ 75.937431] [<c1069495>] validate_chain+0x305/0x5a0 [ 75.937431] [<c106b57d>] __lock_acquire+0x2ad/0x8e0 [ 75.937431] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 75.937431] [<c138c4ae>] _raw_write_lock_bh+0x3e/0x80 [ 75.937431] [<c13100e6>] inet_csk_listen_stop+0x86/0x160 [ 75.937431] [<c1312c42>] tcp_close+0x382/0x390 [ 75.937431] [<c1331abe>] inet_release+0xbe/0x100 [ 75.937431] [<c12d5476>] sock_release+0x66/0x80 [ 75.937431] [<c12d61f2>] sock_close+0x12/0x30 [ 75.937431] [<c10c637b>] __fput+0x1cb/0x240 [ 75.937431] [<c10c6409>] fput+0x19/0x20 [ 75.937431] [<c10c4263>] filp_close+0x43/0x70 [ 75.937431] [<c10c42fd>] sys_close+0x6d/0x110 [ 75.937431] [<c138c911>] syscall_call+0x7/0xb [ 75.937431] [ 75.937431] -> (clock-AF_INET#2){++.?..} ops: 96 { [ 75.937431] HARDIRQ-ON-W at: [ 75.937431] [<c106a8de>] mark_irqflags+0xfe/0x180 [ 75.937431] [<c106b65d>] __lock_acquire+0x38d/0x8e0 [ 75.937431] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 75.937431] [<c138c4ae>] _raw_write_lock_bh+0x3e/0x80 [ 75.937431] [<c135eac3>] xs_tcp_finish_connecting+0x73/0x120 [ 75.937431] [<c135ebcb>] xs_tcp_setup_socket+0x5b/0x180 [ 75.937431] [<c135ee04>] xs_tcp_connect_worker4+0x14/0x20 [ 75.937431] [<c1051547>] process_one_work+0x147/0x3a0 [ 75.937431] [<c1051886>] worker_thread+0xa6/0x200 [ 75.937431] [<c1056765>] kthread+0x75/0x80 [ 75.937431] [<c10031fa>] kernel_thread_helper+0x6/0x1c [ 75.937431] HARDIRQ-ON-R at: [ 75.937431] [<c106a84e>] mark_irqflags+0x6e/0x180 [ 75.937431] [<c106b65d>] __lock_acquire+0x38d/0x8e0 [ 75.937431] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 75.937431] [<c138c019>] _raw_read_lock+0x39/0x70 [ 75.937431] [<c135ddee>] xs_tcp_state_change+0x1e/0x1d0 [ 75.937431] [<c131bd78>] tcp_rcv_synsent_state_process+0x398/0x590 [ 75.937431] [<c131c417>] tcp_rcv_state_process+0x4a7/0x560 [ 75.937431] [<c1322ea1>] tcp_v4_do_rcv+0x71/0x280 [ 75.937431] [<c12da226>] __release_sock+0x66/0x150 [ 75.937431] [<c12daf47>] release_sock+0x87/0x90 [ 75.937431] [<c1331eaa>] inet_stream_connect+0x5a/0x1b0 [ 75.937431] [<c12d7d68>] kernel_connect+0x18/0x30 [ 75.937431] [<c135ea9e>] xs_tcp_finish_connecting+0x4e/0x120 [ 75.937431] [<c135ebcb>] xs_tcp_setup_socket+0x5b/0x180 [ 75.937431] [<c135ee04>] xs_tcp_connect_worker4+0x14/0x20 [ 75.937431] [<c1051547>] process_one_work+0x147/0x3a0 [ 75.937431] [<c1051886>] worker_thread+0xa6/0x200 [ 75.937431] [<c1056765>] kthread+0x75/0x80 [ 75.937431] [<c10031fa>] kernel_thread_helper+0x6/0x1c [ 75.937431] IN-SOFTIRQ-R at: [ 75.937431] [<c106a8fe>] mark_irqflags+0x11e/0x180 [ 75.937431] [<c106b65d>] __lock_acquire+0x38d/0x8e0 [ 75.937431] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 75.937431] [<c138c019>] _raw_read_lock+0x39/0x70 [ 75.937431] [<c135dcc1>] xs_tcp_data_ready+0x21/0x90 [ 75.937431] [<c131a238>] tcp_data_queue+0x248/0x820 [ 75.937431] [<c131b5ae>] tcp_rcv_established+0xae/0x4e0 [ 75.937431] [<c1323001>] tcp_v4_do_rcv+0x1d1/0x280 [ 75.937431] [<c1323624>] tcp_v4_rcv+0x574/0xa30 [ 75.937431] [<c1305483>] ip_local_deliver_finish+0x103/0x320 [ 75.937431] [<c13056d0>] ip_local_deliver+0x30/0x40 [ 75.937431] [<c1305849>] ip_rcv_finish+0x169/0x480 [ 75.937431] [<c1305cfa>] ip_rcv+0x19a/0x2b0 [ 75.937431] [<c12e695d>] __netif_receive_skb+0x21d/0x310 [ 75.937431] [<c12e7468>] process_backlog+0x88/0x160 [ 75.937431] [<c12e7837>] net_rx_action+0x127/0x140 [ 75.937431] [<c1042e70>] __do_softirq+0xd0/0x130 [ 75.937431] SOFTIRQ-ON-R at: [ 75.937431] [<c106a8c2>] mark_irqflags+0xe2/0x180 [ 75.937431] [<c106b65d>] __lock_acquire+0x38d/0x8e0 [ 75.937431] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 75.937431] [<c138c019>] _raw_read_lock+0x39/0x70 [ 75.937431] [<c135ddee>] xs_tcp_state_change+0x1e/0x1d0 [ 75.937431] [<c1332597>] inet_shutdown+0x97/0x110 [ 75.937431] [<c12d7f69>] kernel_sock_shutdown+0x9/0x10 [ 75.937431] [<c135d0e7>] xs_tcp_shutdown+0x17/0x20 [ 75.937431] [<c135d3e7>] xs_tcp_close+0x27/0x30 [ 75.937431] [<c135b63d>] xprt_autoclose+0x1d/0x50 [ 75.937431] [<c1051547>] process_one_work+0x147/0x3a0 [ 75.937431] [<c1051886>] worker_thread+0xa6/0x200 [ 75.937431] [<c1056765>] kthread+0x75/0x80 [ 75.937431] [<c10031fa>] kernel_thread_helper+0x6/0x1c [ 75.937431] INITIAL USE at: [ 75.937431] [<c106b490>] __lock_acquire+0x1c0/0x8e0 [ 75.937431] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 75.937431] [<c138c4ae>] _raw_write_lock_bh+0x3e/0x80 [ 75.937431] [<c135eac3>] xs_tcp_finish_connecting+0x73/0x120 [ 75.937431] [<c135ebcb>] xs_tcp_setup_socket+0x5b/0x180 [ 75.937431] [<c135ee04>] xs_tcp_connect_worker4+0x14/0x20 [ 75.937431] [<c1051547>] process_one_work+0x147/0x3a0 [ 75.937431] [<c1051886>] worker_thread+0xa6/0x200 [ 75.937431] [<c1056765>] kthread+0x75/0x80 [ 75.937431] [<c10031fa>] kernel_thread_helper+0x6/0x1c [ 75.937431] } [ 75.937431] ... key at: [<c1d4cb10>] af_callback_keys+0x10/0x130 [ 75.937431] ... acquired at: [ 75.937431] [<c1069d46>] check_usage_backwards+0x76/0xd0 [ 75.937431] [<c1069f59>] mark_lock_irq+0x99/0x240 [ 75.937431] [<c106abfc>] mark_lock+0x21c/0x3c0 [ 75.937431] [<c106a8c2>] mark_irqflags+0xe2/0x180 [ 75.937431] [<c106b65d>] __lock_acquire+0x38d/0x8e0 [ 75.937431] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 75.937431] [<c138c019>] _raw_read_lock+0x39/0x70 [ 75.937431] [<c135ddee>] xs_tcp_state_change+0x1e/0x1d0 [ 75.937431] [<c1332597>] inet_shutdown+0x97/0x110 [ 75.937431] [<c12d7f69>] kernel_sock_shutdown+0x9/0x10 [ 75.937431] [<c135d0e7>] xs_tcp_shutdown+0x17/0x20 [ 75.937431] [<c135d3e7>] xs_tcp_close+0x27/0x30 [ 75.937431] [<c135b63d>] xprt_autoclose+0x1d/0x50 [ 75.937431] [<c1051547>] process_one_work+0x147/0x3a0 [ 75.937431] [<c1051886>] worker_thread+0xa6/0x200 [ 75.937431] [<c1056765>] kthread+0x75/0x80 [ 75.937431] [<c10031fa>] kernel_thread_helper+0x6/0x1c [ 75.937431] [ 75.937431] [ 75.937431] stack backtrace: [ 75.937431] Pid: 418, comm: kworker/1:1 Not tainted 2.6.36-rc5 #2 [ 75.937431] Call Trace: [ 75.937431] [<c103deb8>] ? printk+0x18/0x20 [ 75.937431] [<c1069bd8>] print_irq_inversion_bug+0x108/0x120 [ 75.937431] [<c1069d46>] check_usage_backwards+0x76/0xd0 [ 75.937431] [<c1069f59>] mark_lock_irq+0x99/0x240 [ 75.937431] [<c1069cd0>] ? check_usage_backwards+0x0/0xd0 [ 75.937431] [<c106abfc>] mark_lock+0x21c/0x3c0 [ 75.937431] [<c106a8c2>] mark_irqflags+0xe2/0x180 [ 75.937431] [<c106b65d>] __lock_acquire+0x38d/0x8e0 [ 75.937431] [<c106c95a>] ? __lock_is_held+0x3a/0x60 [ 75.937431] [<c106cbfa>] lock_acquire+0x7a/0xa0 [ 75.937431] [<c135ddee>] ? xs_tcp_state_change+0x1e/0x1d0 [ 75.937431] [<c138c019>] _raw_read_lock+0x39/0x70 [ 75.937431] [<c135ddee>] ? xs_tcp_state_change+0x1e/0x1d0 [ 75.937431] [<c135ddee>] xs_tcp_state_change+0x1e/0x1d0 [ 75.937431] [<c131f2af>] ? tcp_send_fin+0x4f/0xc0 [ 75.937431] [<c1332597>] inet_shutdown+0x97/0x110 [ 75.937431] [<c12d7f69>] kernel_sock_shutdown+0x9/0x10 [ 75.937431] [<c135d0e7>] xs_tcp_shutdown+0x17/0x20 [ 75.937431] [<c135d3e7>] xs_tcp_close+0x27/0x30 [ 75.937431] [<c135b63d>] xprt_autoclose+0x1d/0x50 [ 75.937431] [<c1051547>] process_one_work+0x147/0x3a0 [ 75.937431] [<c10514d6>] ? process_one_work+0xd6/0x3a0 [ 75.937431] [<c106d179>] ? __lock_acquired+0x119/0x1c0 [ 75.937431] [<c135b620>] ? xprt_autoclose+0x0/0x50 [ 75.937431] [<c10517fc>] ? worker_thread+0x1c/0x200 [ 75.937431] [<c1050317>] ? __need_more_worker+0x17/0x40 [ 75.937431] [<c1051886>] worker_thread+0xa6/0x200 [ 75.937431] [<c1056765>] kthread+0x75/0x80 [ 75.937431] [<c10517e0>] ? worker_thread+0x0/0x200 [ 75.937431] [<c10566f0>] ? kthread+0x0/0x80 [ 75.937431] [<c10031fa>] kernel_thread_helper+0x6/0x1c [ 83.749463] Restarting system. [ 83.751581] machine restart FYI, # cat /etc/exports /usr/src/ *(rw,no_root_squash,async) # grep nfs /proc/mounts 127.0.0.1:/usr/src/ /mnt nfs rw,relatime,vers=3,rsize=32768,wsize=32768,namlen=255,hard,proto=udp,port=65535,timeo=7,retrans=3,sec=sys,addr=127.0.0.1 0 0 test.sh does not trigger this warning on 2.6.34.7 and triggers this warning on 2.6.35.5 . Regards. ^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [2.6.36-rc5] INET?: possible irq lock inversion dependency 2010-09-22 8:58 ` Tetsuo Handa @ 2010-09-22 17:35 ` Eric Dumazet 2010-09-22 19:34 ` [PATCH] net: fix a lockdep splat Eric Dumazet 0 siblings, 1 reply; 24+ messages in thread From: Eric Dumazet @ 2010-09-22 17:35 UTC (permalink / raw) To: Tetsuo Handa; +Cc: linux-fsdevel, netdev Le mercredi 22 septembre 2010 à 17:58 +0900, Tetsuo Handa a écrit : > > Updated and booted/tested patch : > > The warning by test.sh disappeared by your patch. > But the warning which I encounter upon reboot still appears. > FYI, > > # cat /etc/exports > /usr/src/ *(rw,no_root_squash,async) > > # grep nfs /proc/mounts > 127.0.0.1:/usr/src/ /mnt nfs rw,relatime,vers=3,rsize=32768,wsize=32768,namlen=255,hard,proto=udp,port=65535,timeo=7,retrans=3,sec=sys,addr=127.0.0.1 0 0 > > test.sh does not trigger this warning on 2.6.34.7 and > triggers this warning on 2.6.35.5 . > Thanks ! We have for each socket : One spinlock (sk_slock.slock) One rwlock (sk_callback_lock) It is legal to use : A) (this is used in net/sunrpc/xprtsock.c) read_lock(&sk->sk_callback_lock) (without blocking BH) <BH> spin_lock(&sk->sk_slock.slock); ... read_lock(&sk->sk_callback_lock); ... Its also legal to do B) write_lock_bh(&sk->sk_callback_lock) stuff write_unlock_bh(&sk->sk_callback_lock) But if we have a path that : C) spin_lock_bh(&sk->sk_slock) ... write_lock_bh(&sk->sk_callback_lock) stuff write_unlock_bh(&sk->sk_callback_lock) Then we can have a deadlock with A) CPU1 [A] CPU2 [C] read_lock(&sk->sk_callback_lock) <BH> spin_lock_bh(&sk->sk_slock) <wait to spin_lock(slock)> <wait to write_lock_bh(callback_lock)> We have one such path C) in inet_csk_listen_stop() : local_bh_disable(); bh_lock_sock(child); // spin_lock_bh(&sk->sk_slock) WARN_ON(sock_owned_by_user(child)); ... sock_orphan(child); // write_lock_bh(&sk->sk_callback_lock) This is a false positive because its not possible that this particular deadlock can occur, since inet_csk_listen_stop() manipulates half sockets (not yet given to a listener) Give me a moment to think about it and write a fix. ^ permalink raw reply [flat|nested] 24+ messages in thread
* [PATCH] net: fix a lockdep splat 2010-09-22 17:35 ` Eric Dumazet @ 2010-09-22 19:34 ` Eric Dumazet 2010-09-22 20:33 ` David Miller 2010-09-22 22:13 ` Jarek Poplawski 0 siblings, 2 replies; 24+ messages in thread From: Eric Dumazet @ 2010-09-22 19:34 UTC (permalink / raw) To: Tetsuo Handa, David Miller; +Cc: linux-fsdevel, netdev Le mercredi 22 septembre 2010 à 19:35 +0200, Eric Dumazet a écrit : > Thanks ! > > We have for each socket : > > One spinlock (sk_slock.slock) > One rwlock (sk_callback_lock) > > It is legal to use : > > A) (this is used in net/sunrpc/xprtsock.c) > read_lock(&sk->sk_callback_lock) (without blocking BH) > <BH> > spin_lock(&sk->sk_slock.slock); > ... > read_lock(&sk->sk_callback_lock); > ... > > Its also legal to do > > B) > write_lock_bh(&sk->sk_callback_lock) > stuff > write_unlock_bh(&sk->sk_callback_lock) > > > But if we have a path that : > > C) > spin_lock_bh(&sk->sk_slock) > ... > write_lock_bh(&sk->sk_callback_lock) > stuff > write_unlock_bh(&sk->sk_callback_lock) > > Then we can have a deadlock with A) > > CPU1 [A] CPU2 [C] > read_lock(&sk->sk_callback_lock) > <BH> spin_lock_bh(&sk->sk_slock) > <wait to spin_lock(slock)> > <wait to write_lock_bh(callback_lock)> > > We have one such path C) in inet_csk_listen_stop() : > > local_bh_disable(); > bh_lock_sock(child); // spin_lock_bh(&sk->sk_slock) > WARN_ON(sock_owned_by_user(child)); > ... > sock_orphan(child); // write_lock_bh(&sk->sk_callback_lock) > > This is a false positive because its not possible that this particular > deadlock can occur, since inet_csk_listen_stop() manipulates half > sockets (not yet given to a listener) > > Give me a moment to think about it and write a fix. > > Could you try following patch ? Thanks ! [PATCH] net: fix a lockdep splat We have for each socket : One spinlock (sk_slock.slock) One rwlock (sk_callback_lock) Possible scenarios are : (A) (this is used in net/sunrpc/xprtsock.c) read_lock(&sk->sk_callback_lock) (without blocking BH) <BH> spin_lock(&sk->sk_slock.slock); ... read_lock(&sk->sk_callback_lock); ... (B) write_lock_bh(&sk->sk_callback_lock) stuff write_unlock_bh(&sk->sk_callback_lock) (C) spin_lock_bh(&sk->sk_slock) ... write_lock_bh(&sk->sk_callback_lock) stuff write_unlock_bh(&sk->sk_callback_lock) spin_unlock_bh(&sk->sk_slock) This (C) case conflicts with (A) : CPU1 [A] CPU2 [C] read_lock(callback_lock) <BH> spin_lock_bh(slock) <wait to spin_lock(slock)> <wait to write_lock_bh(callback_lock)> We have one problematic (C) use case in inet_csk_listen_stop() : local_bh_disable(); bh_lock_sock(child); // spin_lock_bh(&sk->sk_slock) WARN_ON(sock_owned_by_user(child)); ... sock_orphan(child); // write_lock_bh(&sk->sk_callback_lock) lockdep is not happy with this, as reported by Tetsuo Handa This patch makes sure inet_csk_listen_stop() uses following lock order : write_lock_bh(&sk->sk_callback_lock) spin_lock(&sk->sk_slock) ... spin_unlock(&sk->sk_slock) write_unlock_bh(&sk->sk_callback_lock) Reported-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> Signed-off-by: Eric Dumazet <eric.dumazet@gmail.com> --- include/net/sock.h | 18 +++++++++++++++--- net/ipv4/inet_connection_sock.c | 7 ++++--- 2 files changed, 19 insertions(+), 6 deletions(-) diff --git a/include/net/sock.h b/include/net/sock.h index adab9dc..b6c60d5 100644 --- a/include/net/sock.h +++ b/include/net/sock.h @@ -1242,6 +1242,14 @@ static inline wait_queue_head_t *sk_sleep(struct sock *sk) { return &sk->sk_wq->wait; } + +static inline void __sock_orphan(struct sock *sk) +{ + sock_set_flag(sk, SOCK_DEAD); + sk_set_socket(sk, NULL); + sk->sk_wq = NULL; +} + /* Detach socket from process context. * Announce socket dead, detach it from wait queue and inode. * Note that parent inode held reference count on this struct sock, @@ -1251,15 +1259,19 @@ static inline wait_queue_head_t *sk_sleep(struct sock *sk) */ static inline void sock_orphan(struct sock *sk) { +#ifdef CONFIG_PROVE_LOCKING + WARN_ON(lockdep_is_held(&sk->sk_lock.slock)); +#endif write_lock_bh(&sk->sk_callback_lock); - sock_set_flag(sk, SOCK_DEAD); - sk_set_socket(sk, NULL); - sk->sk_wq = NULL; + __sock_orphan(sk); write_unlock_bh(&sk->sk_callback_lock); } static inline void sock_graft(struct sock *sk, struct socket *parent) { +#ifdef CONFIG_PROVE_LOCKING + WARN_ON(lockdep_is_held(&sk->sk_lock.slock)); +#endif write_lock_bh(&sk->sk_callback_lock); rcu_assign_pointer(sk->sk_wq, parent->wq); parent->sk = sk; diff --git a/net/ipv4/inet_connection_sock.c b/net/ipv4/inet_connection_sock.c index 7174370..c65df13 100644 --- a/net/ipv4/inet_connection_sock.c +++ b/net/ipv4/inet_connection_sock.c @@ -685,21 +685,22 @@ void inet_csk_listen_stop(struct sock *sk) acc_req = req->dl_next; - local_bh_disable(); + write_lock_bh(&child->sk_callback_lock); + bh_lock_sock(child); WARN_ON(sock_owned_by_user(child)); sock_hold(child); sk->sk_prot->disconnect(child, O_NONBLOCK); - sock_orphan(child); + __sock_orphan(child); percpu_counter_inc(sk->sk_prot->orphan_count); inet_csk_destroy_sock(child); bh_unlock_sock(child); - local_bh_enable(); + write_unlock_bh(&child->sk_callback_lock); sock_put(child); sk_acceptq_removed(sk); ^ permalink raw reply related [flat|nested] 24+ messages in thread
* Re: [PATCH] net: fix a lockdep splat 2010-09-22 19:34 ` [PATCH] net: fix a lockdep splat Eric Dumazet @ 2010-09-22 20:33 ` David Miller 2010-09-22 22:13 ` Jarek Poplawski 1 sibling, 0 replies; 24+ messages in thread From: David Miller @ 2010-09-22 20:33 UTC (permalink / raw) To: eric.dumazet; +Cc: penguin-kernel, linux-fsdevel, netdev From: Eric Dumazet <eric.dumazet@gmail.com> Date: Wed, 22 Sep 2010 21:34:48 +0200 > [PATCH] net: fix a lockdep splat > > We have for each socket : ... > This patch makes sure inet_csk_listen_stop() uses following lock order : > > write_lock_bh(&sk->sk_callback_lock) > spin_lock(&sk->sk_slock) > ... > spin_unlock(&sk->sk_slock) > write_unlock_bh(&sk->sk_callback_lock) > > Reported-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> > Signed-off-by: Eric Dumazet <eric.dumazet@gmail.com> FWIW, this looks fine to me. I'll apply it when we have positive testing feedback from Tetsuo. Thanks. ^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [PATCH] net: fix a lockdep splat 2010-09-22 19:34 ` [PATCH] net: fix a lockdep splat Eric Dumazet 2010-09-22 20:33 ` David Miller @ 2010-09-22 22:13 ` Jarek Poplawski 2010-09-22 22:43 ` Eric Dumazet 1 sibling, 1 reply; 24+ messages in thread From: Jarek Poplawski @ 2010-09-22 22:13 UTC (permalink / raw) To: Eric Dumazet; +Cc: Tetsuo Handa, David Miller, linux-fsdevel, netdev Eric Dumazet wrote: > [PATCH] net: fix a lockdep splat > > We have for each socket : > > One spinlock (sk_slock.slock) > One rwlock (sk_callback_lock) > > Possible scenarios are : > > (A) (this is used in net/sunrpc/xprtsock.c) > read_lock(&sk->sk_callback_lock) (without blocking BH) > <BH> > spin_lock(&sk->sk_slock.slock); > ... > read_lock(&sk->sk_callback_lock); > ... > > > (B) > write_lock_bh(&sk->sk_callback_lock) > stuff > write_unlock_bh(&sk->sk_callback_lock) > > > (C) > spin_lock_bh(&sk->sk_slock) > ... > write_lock_bh(&sk->sk_callback_lock) > stuff > write_unlock_bh(&sk->sk_callback_lock) > spin_unlock_bh(&sk->sk_slock) > > This (C) case conflicts with (A) : > > CPU1 [A] CPU2 [C] > read_lock(callback_lock) > <BH> spin_lock_bh(slock) > <wait to spin_lock(slock)> > <wait to write_lock_bh(callback_lock)> > > We have one problematic (C) use case in inet_csk_listen_stop() : > > local_bh_disable(); > bh_lock_sock(child); // spin_lock_bh(&sk->sk_slock) > WARN_ON(sock_owned_by_user(child)); > ... > sock_orphan(child); // write_lock_bh(&sk->sk_callback_lock) > > lockdep is not happy with this, as reported by Tetsuo Handa > > This patch makes sure inet_csk_listen_stop() uses following lock order : > > write_lock_bh(&sk->sk_callback_lock) > spin_lock(&sk->sk_slock) > ... > spin_unlock(&sk->sk_slock) > write_unlock_bh(&sk->sk_callback_lock) IMHO this order conflicts with (A) too (but I'm not sure lockdep tracks that): CPU1 [A] CPU2 [C-reversed] ... write_lock_bh(callback_lock) <BH> spin_lock(slock) <wait to spin_lock(slock)> <wait to read_lock(callback_lock)> My proposal is to BH protect read_lock(sk_callback_lock) everywhere (it's done by netfilter in a few places already). Jarek P. ^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [PATCH] net: fix a lockdep splat 2010-09-22 22:13 ` Jarek Poplawski @ 2010-09-22 22:43 ` Eric Dumazet 2010-09-23 3:53 ` David Miller ` (2 more replies) 0 siblings, 3 replies; 24+ messages in thread From: Eric Dumazet @ 2010-09-22 22:43 UTC (permalink / raw) To: Jarek Poplawski; +Cc: Tetsuo Handa, David Miller, linux-fsdevel, netdev Le jeudi 23 septembre 2010 à 00:13 +0200, Jarek Poplawski a écrit : > Eric Dumazet wrote: > > [PATCH] net: fix a lockdep splat > > > > We have for each socket : > > > > One spinlock (sk_slock.slock) > > One rwlock (sk_callback_lock) > > > > Possible scenarios are : > > > > (A) (this is used in net/sunrpc/xprtsock.c) > > read_lock(&sk->sk_callback_lock) (without blocking BH) > > <BH> > > spin_lock(&sk->sk_slock.slock); > > ... > > read_lock(&sk->sk_callback_lock); > > ... > > > > > > (B) > > write_lock_bh(&sk->sk_callback_lock) > > stuff > > write_unlock_bh(&sk->sk_callback_lock) > > > > > > (C) > > spin_lock_bh(&sk->sk_slock) > > ... > > write_lock_bh(&sk->sk_callback_lock) > > stuff > > write_unlock_bh(&sk->sk_callback_lock) > > spin_unlock_bh(&sk->sk_slock) > > > > This (C) case conflicts with (A) : > > > > CPU1 [A] CPU2 [C] > > read_lock(callback_lock) > > <BH> spin_lock_bh(slock) > > <wait to spin_lock(slock)> > > <wait to write_lock_bh(callback_lock)> > > > > We have one problematic (C) use case in inet_csk_listen_stop() : > > > > local_bh_disable(); > > bh_lock_sock(child); // spin_lock_bh(&sk->sk_slock) > > WARN_ON(sock_owned_by_user(child)); > > ... > > sock_orphan(child); // write_lock_bh(&sk->sk_callback_lock) > > > > lockdep is not happy with this, as reported by Tetsuo Handa > > > > This patch makes sure inet_csk_listen_stop() uses following lock order : > > > > write_lock_bh(&sk->sk_callback_lock) > > spin_lock(&sk->sk_slock) > > ... > > spin_unlock(&sk->sk_slock) > > write_unlock_bh(&sk->sk_callback_lock) > > IMHO this order conflicts with (A) too (but I'm not sure lockdep > tracks that): > It should... thats strange I did not hit it in my tests > CPU1 [A] CPU2 [C-reversed] > ... write_lock_bh(callback_lock) > <BH> > spin_lock(slock) > <wait to spin_lock(slock)> > <wait to read_lock(callback_lock)> > Oh well, you're right. I tried to avoid the _bh everywhere but it seems buggy too. > My proposal is to BH protect read_lock(sk_callback_lock) everywhere (it's > done by netfilter in a few places already). > Yes... its a bit strange we never hit this lockdep splat before... I tried to track recent changes but really I am mystified ??? Thanks ! [PATCH v2] net: fix a lockdep splat We have for each socket : One spinlock (sk_slock.slock) One rwlock (sk_callback_lock) Possible scenarios are : (A) (this is used in net/sunrpc/xprtsock.c) read_lock(&sk->sk_callback_lock) (without blocking BH) <BH> spin_lock(&sk->sk_slock.slock); ... read_lock(&sk->sk_callback_lock); ... (B) write_lock_bh(&sk->sk_callback_lock) stuff write_unlock_bh(&sk->sk_callback_lock) (C) spin_lock_bh(&sk->sk_slock) ... write_lock_bh(&sk->sk_callback_lock) stuff write_unlock_bh(&sk->sk_callback_lock) spin_unlock_bh(&sk->sk_slock) This (C) case conflicts with (A) : CPU1 [A] CPU2 [C] read_lock(callback_lock) <BH> spin_lock_bh(slock) <wait to spin_lock(slock)> <wait to write_lock_bh(callback_lock)> We have one problematic (C) use case in inet_csk_listen_stop() : local_bh_disable(); bh_lock_sock(child); // spin_lock_bh(&sk->sk_slock) WARN_ON(sock_owned_by_user(child)); ... sock_orphan(child); // write_lock_bh(&sk->sk_callback_lock) lockdep is not happy with this, as reported by Tetsuo Handa It seems only way to deal with this is to use read_lock_bh(callbacklock) everywhere. Thanks to Jarek for pointing a bug in my first attempt and suggesting this solution. Reported-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> Signed-off-by: Eric Dumazet <eric.dumazet@gmail.com> CC: Jarek Poplawski <jarkao2@gmail.com> --- net/core/sock.c | 8 ++++---- net/rds/tcp_connect.c | 4 ++-- net/rds/tcp_listen.c | 4 ++-- net/rds/tcp_recv.c | 4 ++-- net/rds/tcp_send.c | 4 ++-- net/sunrpc/xprtsock.c | 28 ++++++++++++++-------------- 6 files changed, 26 insertions(+), 26 deletions(-) diff --git a/net/core/sock.c b/net/core/sock.c index b05b9b6..ef30e9d 100644 --- a/net/core/sock.c +++ b/net/core/sock.c @@ -1351,9 +1351,9 @@ int sock_i_uid(struct sock *sk) { int uid; - read_lock(&sk->sk_callback_lock); + read_lock_bh(&sk->sk_callback_lock); uid = sk->sk_socket ? SOCK_INODE(sk->sk_socket)->i_uid : 0; - read_unlock(&sk->sk_callback_lock); + read_unlock_bh(&sk->sk_callback_lock); return uid; } EXPORT_SYMBOL(sock_i_uid); @@ -1362,9 +1362,9 @@ unsigned long sock_i_ino(struct sock *sk) { unsigned long ino; - read_lock(&sk->sk_callback_lock); + read_lock_bh(&sk->sk_callback_lock); ino = sk->sk_socket ? SOCK_INODE(sk->sk_socket)->i_ino : 0; - read_unlock(&sk->sk_callback_lock); + read_unlock_bh(&sk->sk_callback_lock); return ino; } EXPORT_SYMBOL(sock_i_ino); diff --git a/net/rds/tcp_connect.c b/net/rds/tcp_connect.c index c397524..c519939 100644 --- a/net/rds/tcp_connect.c +++ b/net/rds/tcp_connect.c @@ -43,7 +43,7 @@ void rds_tcp_state_change(struct sock *sk) struct rds_connection *conn; struct rds_tcp_connection *tc; - read_lock(&sk->sk_callback_lock); + read_lock_bh(&sk->sk_callback_lock); conn = sk->sk_user_data; if (conn == NULL) { state_change = sk->sk_state_change; @@ -68,7 +68,7 @@ void rds_tcp_state_change(struct sock *sk) break; } out: - read_unlock(&sk->sk_callback_lock); + read_unlock_bh(&sk->sk_callback_lock); state_change(sk); } diff --git a/net/rds/tcp_listen.c b/net/rds/tcp_listen.c index 975183f..27844f2 100644 --- a/net/rds/tcp_listen.c +++ b/net/rds/tcp_listen.c @@ -114,7 +114,7 @@ void rds_tcp_listen_data_ready(struct sock *sk, int bytes) rdsdebug("listen data ready sk %p\n", sk); - read_lock(&sk->sk_callback_lock); + read_lock_bh(&sk->sk_callback_lock); ready = sk->sk_user_data; if (ready == NULL) { /* check for teardown race */ ready = sk->sk_data_ready; @@ -131,7 +131,7 @@ void rds_tcp_listen_data_ready(struct sock *sk, int bytes) queue_work(rds_wq, &rds_tcp_listen_work); out: - read_unlock(&sk->sk_callback_lock); + read_unlock_bh(&sk->sk_callback_lock); ready(sk, bytes); } diff --git a/net/rds/tcp_recv.c b/net/rds/tcp_recv.c index 1aba687..e437974 100644 --- a/net/rds/tcp_recv.c +++ b/net/rds/tcp_recv.c @@ -324,7 +324,7 @@ void rds_tcp_data_ready(struct sock *sk, int bytes) rdsdebug("data ready sk %p bytes %d\n", sk, bytes); - read_lock(&sk->sk_callback_lock); + read_lock_bh(&sk->sk_callback_lock); conn = sk->sk_user_data; if (conn == NULL) { /* check for teardown race */ ready = sk->sk_data_ready; @@ -338,7 +338,7 @@ void rds_tcp_data_ready(struct sock *sk, int bytes) if (rds_tcp_read_sock(conn, GFP_ATOMIC, KM_SOFTIRQ0) == -ENOMEM) queue_delayed_work(rds_wq, &conn->c_recv_w, 0); out: - read_unlock(&sk->sk_callback_lock); + read_unlock_bh(&sk->sk_callback_lock); ready(sk, bytes); } diff --git a/net/rds/tcp_send.c b/net/rds/tcp_send.c index a28b895..2f012a0 100644 --- a/net/rds/tcp_send.c +++ b/net/rds/tcp_send.c @@ -224,7 +224,7 @@ void rds_tcp_write_space(struct sock *sk) struct rds_connection *conn; struct rds_tcp_connection *tc; - read_lock(&sk->sk_callback_lock); + read_lock_bh(&sk->sk_callback_lock); conn = sk->sk_user_data; if (conn == NULL) { write_space = sk->sk_write_space; @@ -244,7 +244,7 @@ void rds_tcp_write_space(struct sock *sk) queue_delayed_work(rds_wq, &conn->c_send_w, 0); out: - read_unlock(&sk->sk_callback_lock); + read_unlock_bh(&sk->sk_callback_lock); /* * write_space is only called when data leaves tcp's send queue if diff --git a/net/sunrpc/xprtsock.c b/net/sunrpc/xprtsock.c index b6309db..fe9306b 100644 --- a/net/sunrpc/xprtsock.c +++ b/net/sunrpc/xprtsock.c @@ -800,7 +800,7 @@ static void xs_udp_data_ready(struct sock *sk, int len) u32 _xid; __be32 *xp; - read_lock(&sk->sk_callback_lock); + read_lock_bh(&sk->sk_callback_lock); dprintk("RPC: xs_udp_data_ready...\n"); if (!(xprt = xprt_from_sock(sk))) goto out; @@ -852,7 +852,7 @@ static void xs_udp_data_ready(struct sock *sk, int len) dropit: skb_free_datagram(sk, skb); out: - read_unlock(&sk->sk_callback_lock); + read_unlock_bh(&sk->sk_callback_lock); } static inline void xs_tcp_read_fraghdr(struct rpc_xprt *xprt, struct xdr_skb_reader *desc) @@ -1229,7 +1229,7 @@ static void xs_tcp_data_ready(struct sock *sk, int bytes) dprintk("RPC: xs_tcp_data_ready...\n"); - read_lock(&sk->sk_callback_lock); + read_lock_bh(&sk->sk_callback_lock); if (!(xprt = xprt_from_sock(sk))) goto out; if (xprt->shutdown) @@ -1248,7 +1248,7 @@ static void xs_tcp_data_ready(struct sock *sk, int bytes) read = tcp_read_sock(sk, &rd_desc, xs_tcp_data_recv); } while (read > 0); out: - read_unlock(&sk->sk_callback_lock); + read_unlock_bh(&sk->sk_callback_lock); } /* @@ -1301,7 +1301,7 @@ static void xs_tcp_state_change(struct sock *sk) { struct rpc_xprt *xprt; - read_lock(&sk->sk_callback_lock); + read_lock_bh(&sk->sk_callback_lock); if (!(xprt = xprt_from_sock(sk))) goto out; dprintk("RPC: xs_tcp_state_change client %p...\n", xprt); @@ -1313,7 +1313,7 @@ static void xs_tcp_state_change(struct sock *sk) switch (sk->sk_state) { case TCP_ESTABLISHED: - spin_lock_bh(&xprt->transport_lock); + spin_lock(&xprt->transport_lock); if (!xprt_test_and_set_connected(xprt)) { struct sock_xprt *transport = container_of(xprt, struct sock_xprt, xprt); @@ -1327,7 +1327,7 @@ static void xs_tcp_state_change(struct sock *sk) xprt_wake_pending_tasks(xprt, -EAGAIN); } - spin_unlock_bh(&xprt->transport_lock); + spin_unlock(&xprt->transport_lock); break; case TCP_FIN_WAIT1: /* The client initiated a shutdown of the socket */ @@ -1365,7 +1365,7 @@ static void xs_tcp_state_change(struct sock *sk) xs_sock_mark_closed(xprt); } out: - read_unlock(&sk->sk_callback_lock); + read_unlock_bh(&sk->sk_callback_lock); } /** @@ -1376,7 +1376,7 @@ static void xs_error_report(struct sock *sk) { struct rpc_xprt *xprt; - read_lock(&sk->sk_callback_lock); + read_lock_bh(&sk->sk_callback_lock); if (!(xprt = xprt_from_sock(sk))) goto out; dprintk("RPC: %s client %p...\n" @@ -1384,7 +1384,7 @@ static void xs_error_report(struct sock *sk) __func__, xprt, sk->sk_err); xprt_wake_pending_tasks(xprt, -EAGAIN); out: - read_unlock(&sk->sk_callback_lock); + read_unlock_bh(&sk->sk_callback_lock); } static void xs_write_space(struct sock *sk) @@ -1416,13 +1416,13 @@ static void xs_write_space(struct sock *sk) */ static void xs_udp_write_space(struct sock *sk) { - read_lock(&sk->sk_callback_lock); + read_lock_bh(&sk->sk_callback_lock); /* from net/core/sock.c:sock_def_write_space */ if (sock_writeable(sk)) xs_write_space(sk); - read_unlock(&sk->sk_callback_lock); + read_unlock_bh(&sk->sk_callback_lock); } /** @@ -1437,13 +1437,13 @@ static void xs_udp_write_space(struct sock *sk) */ static void xs_tcp_write_space(struct sock *sk) { - read_lock(&sk->sk_callback_lock); + read_lock_bh(&sk->sk_callback_lock); /* from net/core/stream.c:sk_stream_write_space */ if (sk_stream_wspace(sk) >= sk_stream_min_wspace(sk)) xs_write_space(sk); - read_unlock(&sk->sk_callback_lock); + read_unlock_bh(&sk->sk_callback_lock); } static void xs_udp_do_set_buffer_size(struct rpc_xprt *xprt) ^ permalink raw reply related [flat|nested] 24+ messages in thread
* Re: [PATCH] net: fix a lockdep splat 2010-09-22 22:43 ` Eric Dumazet @ 2010-09-23 3:53 ` David Miller 2010-09-23 4:23 ` David Miller 2010-09-23 5:42 ` Eric Dumazet 2010-09-23 6:32 ` Tetsuo Handa 2 siblings, 1 reply; 24+ messages in thread From: David Miller @ 2010-09-23 3:53 UTC (permalink / raw) To: eric.dumazet; +Cc: jarkao2, penguin-kernel, linux-fsdevel, netdev From: Eric Dumazet <eric.dumazet@gmail.com> Date: Thu, 23 Sep 2010 00:43:39 +0200 > (A) (this is used in net/sunrpc/xprtsock.c) > read_lock(&sk->sk_callback_lock) (without blocking BH) > <BH> > spin_lock(&sk->sk_slock.slock); > ... > read_lock(&sk->sk_callback_lock); > ... What's the exact path that leads to this? I looked quickly and couldn't find which sunrpc callback override does it. Thanks. ^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [PATCH] net: fix a lockdep splat 2010-09-23 3:53 ` David Miller @ 2010-09-23 4:23 ` David Miller 2010-09-23 5:05 ` Eric Dumazet 0 siblings, 1 reply; 24+ messages in thread From: David Miller @ 2010-09-23 4:23 UTC (permalink / raw) To: eric.dumazet; +Cc: jarkao2, penguin-kernel, linux-fsdevel, netdev From: David Miller <davem@davemloft.net> Date: Wed, 22 Sep 2010 20:53:24 -0700 (PDT) > From: Eric Dumazet <eric.dumazet@gmail.com> > Date: Thu, 23 Sep 2010 00:43:39 +0200 > >> (A) (this is used in net/sunrpc/xprtsock.c) >> read_lock(&sk->sk_callback_lock) (without blocking BH) >> <BH> >> spin_lock(&sk->sk_slock.slock); >> ... >> read_lock(&sk->sk_callback_lock); >> ... > > What's the exact path that leads to this? I looked quickly and couldn't > find which sunrpc callback override does it. Sorry, I'm being unusually dense at the moment, ignore this question :-) ^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [PATCH] net: fix a lockdep splat 2010-09-23 4:23 ` David Miller @ 2010-09-23 5:05 ` Eric Dumazet 0 siblings, 0 replies; 24+ messages in thread From: Eric Dumazet @ 2010-09-23 5:05 UTC (permalink / raw) To: David Miller; +Cc: jarkao2, penguin-kernel, linux-fsdevel, netdev Le mercredi 22 septembre 2010 à 21:23 -0700, David Miller a écrit : > From: David Miller <davem@davemloft.net> > Date: Wed, 22 Sep 2010 20:53:24 -0700 (PDT) > > > From: Eric Dumazet <eric.dumazet@gmail.com> > > Date: Thu, 23 Sep 2010 00:43:39 +0200 > > > >> (A) (this is used in net/sunrpc/xprtsock.c) > >> read_lock(&sk->sk_callback_lock) (without blocking BH) > >> <BH> > >> spin_lock(&sk->sk_slock.slock); > >> ... > >> read_lock(&sk->sk_callback_lock); > >> ... > > > > What's the exact path that leads to this? I looked quickly and couldn't > > find which sunrpc callback override does it. > > Sorry, I'm being unusually dense at the moment, ignore this question :-) No problem ;) But we might answer it anyway for other readers : vi +1417 net/sunrpc/xprtsock.c static void xs_udp_write_space(struct sock *sk) { read_lock(&sk->sk_callback_lock); // We can be interrupted here and call INPUT_PATH() /* from net/core/sock.c:sock_def_write_space */ if (sock_writeable(sk)) xs_write_space(sk); read_unlock(&sk->sk_callback_lock); } INPUT_PATH() { spin_lock(&sk->slock); queue skb to receive queue or backlog spin_unlock(&sk->slock); } If another cpu does (C), we can deadlock. C) spin_lock_bh(&sk->sk_slock) ... write_lock_bh(&sk->sk_callback_lock) ... Then we can have a deadlock with (A) CPU1 [A] CPU2 [C] read_lock(&sk->sk_callback_lock) <BH> spin_lock_bh(&sk->sk_slock) <wait to spin_lock(slock)> <wait to write_lock_bh(callback_lock)> It seems only TCP stack contains [C] cases, in very unlikely paths, but still... Since all AF_INET sockets share the same af_callback_key *and* the same af_family_slock_keys, lockdep warned Tetsuo because it detects an UDP [A] case and a TCP [C] case. ^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [PATCH] net: fix a lockdep splat 2010-09-22 22:43 ` Eric Dumazet 2010-09-23 3:53 ` David Miller @ 2010-09-23 5:42 ` Eric Dumazet 2010-09-23 6:32 ` Tetsuo Handa 2 siblings, 0 replies; 24+ messages in thread From: Eric Dumazet @ 2010-09-23 5:42 UTC (permalink / raw) To: Jarek Poplawski; +Cc: Tetsuo Handa, David Miller, linux-fsdevel, netdev Le jeudi 23 septembre 2010 à 00:43 +0200, Eric Dumazet a écrit : > > [PATCH v2] net: fix a lockdep splat > ... > lockdep is not happy with this, as reported by Tetsuo Handa > > It seems only way to deal with this is to use read_lock_bh(callbacklock) > everywhere. > > Thanks to Jarek for pointing a bug in my first attempt and suggesting > this solution. > > Reported-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> > Signed-off-by: Eric Dumazet <eric.dumazet@gmail.com> > CC: Jarek Poplawski <jarkao2@gmail.com> Tested-by: Eric Dumazet <eric.dumazet@gmail.com> I tested it on my machine and could not reproduce the lockdep splat. -- To unsubscribe from this list: send the line "unsubscribe linux-fsdevel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html ^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [PATCH] net: fix a lockdep splat 2010-09-22 22:43 ` Eric Dumazet 2010-09-23 3:53 ` David Miller 2010-09-23 5:42 ` Eric Dumazet @ 2010-09-23 6:32 ` Tetsuo Handa 2010-09-23 6:44 ` Eric Dumazet 2010-09-25 5:26 ` David Miller 2 siblings, 2 replies; 24+ messages in thread From: Tetsuo Handa @ 2010-09-23 6:32 UTC (permalink / raw) To: eric.dumazet, jarkao2; +Cc: davem, linux-fsdevel, netdev Eric Dumazet wrote: > [PATCH v2] net: fix a lockdep splat The lockdep warning disappeared for both linux-2.6.35.5.tar.bz2 and linux-2.6.36-rc5.tar.bz2 . Thank you. ^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [PATCH] net: fix a lockdep splat 2010-09-23 6:32 ` Tetsuo Handa @ 2010-09-23 6:44 ` Eric Dumazet 2010-09-25 5:26 ` David Miller 1 sibling, 0 replies; 24+ messages in thread From: Eric Dumazet @ 2010-09-23 6:44 UTC (permalink / raw) To: Tetsuo Handa; +Cc: jarkao2, davem, linux-fsdevel, netdev Le jeudi 23 septembre 2010 à 15:32 +0900, Tetsuo Handa a écrit : > Eric Dumazet wrote: > > [PATCH v2] net: fix a lockdep splat > > The lockdep warning disappeared for both > linux-2.6.35.5.tar.bz2 and linux-2.6.36-rc5.tar.bz2 . > Thanks Tetsuo ! -- To unsubscribe from this list: send the line "unsubscribe linux-fsdevel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html ^ permalink raw reply [flat|nested] 24+ messages in thread
* Re: [PATCH] net: fix a lockdep splat 2010-09-23 6:32 ` Tetsuo Handa 2010-09-23 6:44 ` Eric Dumazet @ 2010-09-25 5:26 ` David Miller 1 sibling, 0 replies; 24+ messages in thread From: David Miller @ 2010-09-25 5:26 UTC (permalink / raw) To: penguin-kernel; +Cc: eric.dumazet, jarkao2, linux-fsdevel, netdev From: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> Date: Thu, 23 Sep 2010 15:32:23 +0900 > Eric Dumazet wrote: >> [PATCH v2] net: fix a lockdep splat > > The lockdep warning disappeared for both > linux-2.6.35.5.tar.bz2 and linux-2.6.36-rc5.tar.bz2 . Thanks everyone, I've applied Eric's patch to net-2.6 ^ permalink raw reply [flat|nested] 24+ messages in thread
end of thread, other threads:[~2010-09-25 5:26 UTC | newest] Thread overview: 24+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2010-06-24 11:53 [2.6.35-rc3] NFS: possible irq lock inversion dependency Tetsuo Handa 2010-09-07 12:32 ` [2.6.36-rc3] " Tetsuo Handa 2010-09-21 6:51 ` [2.6.35-rc5] INET?: " Tetsuo Handa 2010-09-21 7:56 ` Eric Dumazet 2010-09-21 9:10 ` [2.6.36-rc5] " Tetsuo Handa 2010-09-21 9:35 ` Eric Dumazet 2010-09-21 10:13 ` Eric Dumazet 2010-09-22 7:14 ` Tetsuo Handa 2010-09-22 8:31 ` Eric Dumazet 2010-09-22 8:34 ` Eric Dumazet 2010-09-22 8:38 ` Eric Dumazet 2010-09-22 8:58 ` Tetsuo Handa 2010-09-22 17:35 ` Eric Dumazet 2010-09-22 19:34 ` [PATCH] net: fix a lockdep splat Eric Dumazet 2010-09-22 20:33 ` David Miller 2010-09-22 22:13 ` Jarek Poplawski 2010-09-22 22:43 ` Eric Dumazet 2010-09-23 3:53 ` David Miller 2010-09-23 4:23 ` David Miller 2010-09-23 5:05 ` Eric Dumazet 2010-09-23 5:42 ` Eric Dumazet 2010-09-23 6:32 ` Tetsuo Handa 2010-09-23 6:44 ` Eric Dumazet 2010-09-25 5:26 ` David Miller
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).