[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

[Xen-devel] xenstored unsafe lock order detected, xlate_proc_name, evtchn_ioctl, port_user_lock



Hello,

I just tried the latest xen/stable-2.6.32.x kernel, ie. 2.6.32.15, with Xen 
4.0.0,
and I got this:

http://pasik.reaktio.net/xen/pv_ops-dom0-debug/log-2.6.32.15-pvops-dom0-xen-stable-x86_64.txt


Jun  5 20:28:46 f13 kernel: device vif1.0 entered promiscuous mode
Jun  5 20:28:46 f13 kernel: virbr0: topology change detected, propagating
Jun  5 20:28:46 f13 kernel: virbr0: port 1(vif1.0) entering forwarding state
Jun  5 20:28:47 f13 avahi-daemon[1384]: Registering new address record for 
fe80::fcff:ffff:feff:ffff on vif1.0.*.
Jun  5 20:29:28 f13 kernel:
Jun  5 20:29:28 f13 kernel: 
======================================================
Jun  5 20:29:28 f13 kernel: [ INFO: HARDIRQ-safe -> HARDIRQ-unsafe lock order 
detected ]
Jun  5 20:29:28 f13 kernel: 2.6.32.15 #2
Jun  5 20:29:28 f13 kernel: 
------------------------------------------------------
Jun  5 20:29:28 f13 kernel: xenstored/1508 [HC0[0]:SC0[0]:HE0:SE1] is trying to 
acquire:
Jun  5 20:29:28 f13 kernel: (proc_subdir_lock){+.+...}, at: 
[<ffffffff8117bd76>] xlate_proc_name+0x3d/0xbb
Jun  5 20:29:28 f13 kernel:
Jun  5 20:29:28 f13 kernel: and this task is already holding:
Jun  5 20:29:28 f13 kernel: (&port_user_lock){-.-...}, at: [<ffffffffa015a390>] 
evtchn_ioctl+0x1ae/0x2c7 [xen_evtchn]
Jun  5 20:29:28 f13 kernel: which would create a new lock dependency:
Jun  5 20:29:28 f13 kernel: (&port_user_lock){-.-...} -> 
(proc_subdir_lock){+.+...}
Jun  5 20:29:28 f13 kernel:
Jun  5 20:29:28 f13 kernel: but this new dependency connects a HARDIRQ-irq-safe 
lock:
Jun  5 20:29:28 f13 kernel: (&port_user_lock){-.-...}
Jun  5 20:29:28 f13 kernel: ... which became HARDIRQ-irq-safe at:
Jun  5 20:29:28 f13 kernel:  [<ffffffff8108c2e8>] __lock_acquire+0x2d6/0xd3a
Jun  5 20:29:28 f13 kernel:  [<ffffffff8108ce28>] lock_acquire+0xdc/0x102
Jun  5 20:29:28 f13 kernel:  [<ffffffff81478cf1>] _spin_lock+0x36/0x69
Jun  5 20:29:28 f13 kernel:  [<ffffffffa015a815>] evtchn_interrupt+0x2b/0x119 
[xen_evtchn]
Jun  5 20:29:28 f13 kernel:  [<ffffffff810b80f4>] handle_IRQ_event+0x53/0x119
Jun  5 20:29:28 f13 kernel:  [<ffffffff810ba096>] handle_level_irq+0x7d/0xdf
Jun  5 20:29:28 f13 kernel:  [<ffffffff812b72bd>] 
__xen_evtchn_do_upcall+0xe7/0x168
Jun  5 20:29:28 f13 kernel:  [<ffffffff812b7820>] xen_evtchn_do_upcall+0x37/0x4c
Jun  5 20:29:28 f13 kernel:  [<ffffffff81013f3e>] 
xen_do_hypervisor_callback+0x1e/0x30
Jun  5 20:29:28 f13 kernel:
Jun  5 20:29:28 f13 kernel: to a HARDIRQ-irq-unsafe lock:
Jun  5 20:29:28 f13 kernel: (proc_subdir_lock){+.+...}
Jun  5 20:29:28 f13 kernel: ... which became HARDIRQ-irq-unsafe at:
Jun  5 20:29:28 f13 kernel: ...  [<ffffffff8108c35c>] __lock_acquire+0x34a/0xd3a
Jun  5 20:29:28 f13 kernel:  [<ffffffff8108ce28>] lock_acquire+0xdc/0x102
Jun  5 20:29:28 f13 kernel:  [<ffffffff81478cf1>] _spin_lock+0x36/0x69
Jun  5 20:29:28 f13 kernel:  [<ffffffff8117bd76>] xlate_proc_name+0x3d/0xbb
Jun  5 20:29:28 f13 kernel:  [<ffffffff8117c8ef>] __proc_create+0x44/0x125
Jun  5 20:29:28 f13 kernel:  [<ffffffff8117cc05>] proc_symlink+0x30/0xa3
Jun  5 20:29:28 f13 kernel:  [<ffffffff819b8fde>] proc_root_init+0x62/0xb9
Jun  5 20:29:28 f13 kernel:  [<ffffffff81995d49>] start_kernel+0x400/0x433
Jun  5 20:29:28 f13 kernel:  [<ffffffff819952c1>] 
x86_64_start_reservations+0xac/0xb0
Jun  5 20:29:28 f13 kernel:  [<ffffffff819990f3>] xen_start_kernel+0x659/0x660
Jun  5 20:29:28 f13 kernel:
Jun  5 20:29:28 f13 kernel: other info that might help us debug this:
Jun  5 20:29:28 f13 kernel:
Jun  5 20:29:28 f13 kernel: 2 locks held by xenstored/1508:
Jun  5 20:29:28 f13 kernel: #0:  (&u->bind_mutex){+.+.+.}, at: 
[<ffffffffa015a20b>] evtchn_ioctl+0x29/0x2c7 [xen_evtchn]
Jun  5 20:29:28 f13 kernel: #1:  (&port_user_lock){-.-...}, at: 
[<ffffffffa015a390>] evtchn_ioctl+0x1ae/0x2c7 [xen_evtchn]
Jun  5 20:29:28 f13 kernel:
Jun  5 20:29:28 f13 kernel: the dependencies between HARDIRQ-irq-safe lock and 
the holding lock:
Jun  5 20:29:28 f13 kernel: -> (&port_user_lock){-.-...} ops: 0 {
Jun  5 20:29:28 f13 kernel:   IN-HARDIRQ-W at:
Jun  5 20:29:28 f13 kernel:                        [<ffffffff8108c2e8>] 
__lock_acquire+0x2d6/0xd3a
Jun  5 20:29:28 f13 kernel:                        [<ffffffff8108ce28>] 
lock_acquire+0xdc/0x102
Jun  5 20:29:28 f13 kernel:                        [<ffffffff81478cf1>] 
_spin_lock+0x36/0x69
Jun  5 20:29:28 f13 kernel:                        [<ffffffffa015a815>] 
evtchn_interrupt+0x2b/0x119 [xen_evtchn]
Jun  5 20:29:28 f13 kernel:                        [<ffffffff810b80f4>] 
handle_IRQ_event+0x53/0x119
Jun  5 20:29:28 f13 kernel:                        [<ffffffff810ba096>] 
handle_level_irq+0x7d/0xdf
Jun  5 20:29:28 f13 kernel:                        [<ffffffff812b72bd>] 
__xen_evtchn_do_upcall+0xe7/0x168
Jun  5 20:29:28 f13 kernel:                        [<ffffffff812b7820>] 
xen_evtchn_do_upcall+0x37/0x4c
Jun  5 20:29:28 f13 kernel:                        [<ffffffff81013f3e>] 
xen_do_hypervisor_callback+0x1e/0x30
Jun  5 20:29:28 f13 kernel:   IN-SOFTIRQ-W at:
Jun  5 20:29:28 f13 kernel:                        [<ffffffff8108c309>] 
__lock_acquire+0x2f7/0xd3a
Jun  5 20:29:28 f13 kernel:                        [<ffffffff8108ce28>] 
lock_acquire+0xdc/0x102
Jun  5 20:29:28 f13 kernel:                        [<ffffffff81478cf1>] 
_spin_lock+0x36/0x69
Jun  5 20:29:28 f13 kernel:                        [<ffffffffa015a815>] 
evtchn_interrupt+0x2b/0x119 [xen_evtchn]
Jun  5 20:29:28 f13 kernel:                        [<ffffffff810b80f4>] 
handle_IRQ_event+0x53/0x119
Jun  5 20:29:28 f13 kernel:                        [<ffffffff810ba096>] 
handle_level_irq+0x7d/0xdf
Jun  5 20:29:28 f13 kernel:                        [<ffffffff812b72bd>] 
__xen_evtchn_do_upcall+0xe7/0x168
Jun  5 20:29:28 f13 kernel:                        [<ffffffff812b7820>] 
xen_evtchn_do_upcall+0x37/0x4c
Jun  5 20:29:28 f13 kernel:                        [<ffffffff81013f3e>] 
xen_do_hypervisor_callback+0x1e/0x30
Jun  5 20:29:28 f13 kernel:   INITIAL USE at:
Jun  5 20:29:28 f13 kernel:                       [<ffffffff8108c3d3>] 
__lock_acquire+0x3c1/0xd3a
Jun  5 20:29:28 f13 kernel:                       [<ffffffff8108ce28>] 
lock_acquire+0xdc/0x102
Jun  5 20:29:28 f13 kernel:                       [<ffffffff81478cf1>] 
_spin_lock+0x36/0x69
Jun  5 20:29:28 f13 kernel:                       [<ffffffffa015a815>] 
evtchn_interrupt+0x2b/0x119 [xen_evtchn]
Jun  5 20:29:28 f13 kernel:                       [<ffffffff810b80f4>] 
handle_IRQ_event+0x53/0x119
Jun  5 20:29:28 f13 kernel:                       [<ffffffff810ba096>] 
handle_level_irq+0x7d/0xdf
Jun  5 20:29:28 f13 kernel:                       [<ffffffff812b72bd>] 
__xen_evtchn_do_upcall+0xe7/0x168
Jun  5 20:29:28 f13 kernel:                       [<ffffffff812b7820>] 
xen_evtchn_do_upcall+0x37/0x4c
Jun  5 20:29:28 f13 kernel:                       [<ffffffff81013f3e>] 
xen_do_hypervisor_callback+0x1e/0x30
Jun  5 20:29:28 f13 kernel: }
Jun  5 20:29:28 f13 kernel: ... key      at: [<ffffffffa015afb8>] 
__key.27039+0x0/0xfffffffffffffaaa [xen_evtchn]
Jun  5 20:29:28 f13 kernel: ... acquired at:
Jun  5 20:29:28 f13 kernel:   [<ffffffff8108bfb1>] check_irq_usage+0x5d/0xbe
Jun  5 20:29:28 f13 kernel:   [<ffffffff8108ca6a>] __lock_acquire+0xa58/0xd3a
Jun  5 20:29:28 f13 kernel:   [<ffffffff8108ce28>] lock_acquire+0xdc/0x102
Jun  5 20:29:28 f13 kernel:   [<ffffffff81478cf1>] _spin_lock+0x36/0x69
Jun  5 20:29:28 f13 kernel:   [<ffffffff8117bd76>] xlate_proc_name+0x3d/0xbb
Jun  5 20:29:28 f13 kernel:   [<ffffffff8117be94>] remove_proc_entry+0x34/0x221
Jun  5 20:29:28 f13 kernel:   [<ffffffff810bab5b>] 
unregister_handler_proc+0x31/0x35
Jun  5 20:29:28 f13 kernel:   [<ffffffff810b925a>] __free_irq+0x104/0x193
Jun  5 20:29:28 f13 kernel:   [<ffffffff810b9321>] free_irq+0x38/0x53
Jun  5 20:29:28 f13 kernel:   [<ffffffff812b7c03>] 
unbind_from_irqhandler+0x15/0x20
Jun  5 20:29:28 f13 kernel:   [<ffffffffa015a09a>] 
evtchn_unbind_from_user+0x23/0x36 [xen_evtchn]
Jun  5 20:29:28 f13 kernel:   [<ffffffffa015a3c7>] evtchn_ioctl+0x1e5/0x2c7 
[xen_evtchn]
Jun  5 20:29:28 f13 kernel:   [<ffffffff81135e95>] vfs_ioctl+0x22/0x87
Jun  5 20:29:28 f13 kernel:   [<ffffffff811363fe>] do_vfs_ioctl+0x488/0x4ce
Jun  5 20:29:28 f13 kernel:   [<ffffffff8113649a>] sys_ioctl+0x56/0x79
Jun  5 20:29:28 f13 kernel:   [<ffffffff81012cb2>] 
system_call_fastpath+0x16/0x1b
Jun  5 20:29:28 f13 kernel:
Jun  5 20:29:28 f13 kernel:
Jun  5 20:29:28 f13 kernel: the dependencies between the lock to be acquired 
and HARDIRQ-irq-unsafe lock:
Jun  5 20:29:28 f13 kernel: -> (proc_subdir_lock){+.+...} ops: 0 {
Jun  5 20:29:28 f13 kernel:   HARDIRQ-ON-W at:
Jun  5 20:29:28 f13 kernel:                        [<ffffffff8108c35c>] 
__lock_acquire+0x34a/0xd3a
Jun  5 20:29:28 f13 kernel:                        [<ffffffff8108ce28>] 
lock_acquire+0xdc/0x102
Jun  5 20:29:28 f13 kernel:                        [<ffffffff81478cf1>] 
_spin_lock+0x36/0x69
Jun  5 20:29:28 f13 kernel:                        [<ffffffff8117bd76>] 
xlate_proc_name+0x3d/0xbb
Jun  5 20:29:28 f13 kernel:                        [<ffffffff8117c8ef>] 
__proc_create+0x44/0x125
Jun  5 20:29:28 f13 kernel:                        [<ffffffff8117cc05>] 
proc_symlink+0x30/0xa3
Jun  5 20:29:28 f13 kernel:                        [<ffffffff819b8fde>] 
proc_root_init+0x62/0xb9
Jun  5 20:29:28 f13 kernel:                        [<ffffffff81995d49>] 
start_kernel+0x400/0x433
Jun  5 20:29:28 f13 kernel:                        [<ffffffff819952c1>] 
x86_64_start_reservations+0xac/0xb0
Jun  5 20:29:28 f13 kernel:                        [<ffffffff819990f3>] 
xen_start_kernel+0x659/0x660
Jun  5 20:29:28 f13 kernel:   SOFTIRQ-ON-W at:
Jun  5 20:29:28 f13 kernel:                        [<ffffffff8108c37d>] 
__lock_acquire+0x36b/0xd3a
Jun  5 20:29:28 f13 kernel:                        [<ffffffff8108ce28>] 
lock_acquire+0xdc/0x102
Jun  5 20:29:28 f13 kernel:                        [<ffffffff81478cf1>] 
_spin_lock+0x36/0x69
Jun  5 20:29:28 f13 kernel:                        [<ffffffff8117bd76>] 
xlate_proc_name+0x3d/0xbb
Jun  5 20:29:28 f13 kernel:                        [<ffffffff8117c8ef>] 
__proc_create+0x44/0x125
Jun  5 20:29:28 f13 kernel:                        [<ffffffff8117cc05>] 
proc_symlink+0x30/0xa3
Jun  5 20:29:28 f13 kernel:                        [<ffffffff819b8fde>] 
proc_root_init+0x62/0xb9
Jun  5 20:29:28 f13 kernel:                        [<ffffffff81995d49>] 
start_kernel+0x400/0x433
Jun  5 20:29:28 f13 kernel:                        [<ffffffff819952c1>] 
x86_64_start_reservations+0xac/0xb0
Jun  5 20:29:28 f13 kernel:                        [<ffffffff819990f3>] 
xen_start_kernel+0x659/0x660
Jun  5 20:29:28 f13 kernel:   INITIAL USE at:
Jun  5 20:29:28 f13 kernel:                       [<ffffffff8108c3d3>] 
__lock_acquire+0x3c1/0xd3a
Jun  5 20:29:28 f13 kernel:                       [<ffffffff8108ce28>] 
lock_acquire+0xdc/0x102
Jun  5 20:29:28 f13 kernel:                       [<ffffffff81478cf1>] 
_spin_lock+0x36/0x69
Jun  5 20:29:28 f13 kernel:                       [<ffffffff8117bd76>] 
xlate_proc_name+0x3d/0xbb
Jun  5 20:29:28 f13 kernel:                       [<ffffffff8117c8ef>] 
__proc_create+0x44/0x125
Jun  5 20:29:28 f13 kernel:                       [<ffffffff8117cc05>] 
proc_symlink+0x30/0xa3
Jun  5 20:29:28 f13 kernel:                       [<ffffffff819b8fde>] 
proc_root_init+0x62/0xb9
Jun  5 20:29:28 f13 kernel:                       [<ffffffff81995d49>] 
start_kernel+0x400/0x433
Jun  5 20:29:28 f13 kernel:                       [<ffffffff819952c1>] 
x86_64_start_reservations+0xac/0xb0
Jun  5 20:29:28 f13 kernel:                       [<ffffffff819990f3>] 
xen_start_kernel+0x659/0x660
Jun  5 20:29:28 f13 kernel: }
Jun  5 20:29:28 f13 kernel: ... key      at: [<ffffffff8172b238>] 
proc_subdir_lock+0x18/0x40
Jun  5 20:29:28 f13 kernel: ... acquired at:
Jun  5 20:29:28 f13 kernel:   [<ffffffff8108bfb1>] check_irq_usage+0x5d/0xbe
Jun  5 20:29:28 f13 kernel:   [<ffffffff8108ca6a>] __lock_acquire+0xa58/0xd3a
Jun  5 20:29:28 f13 kernel:   [<ffffffff8108ce28>] lock_acquire+0xdc/0x102
Jun  5 20:29:28 f13 kernel:   [<ffffffff81478cf1>] _spin_lock+0x36/0x69
Jun  5 20:29:28 f13 kernel:   [<ffffffff8117bd76>] xlate_proc_name+0x3d/0xbb
Jun  5 20:29:28 f13 kernel:   [<ffffffff8117be94>] remove_proc_entry+0x34/0x221
Jun  5 20:29:28 f13 kernel:   [<ffffffff810bab5b>] 
unregister_handler_proc+0x31/0x35
Jun  5 20:29:28 f13 kernel:   [<ffffffff810b925a>] __free_irq+0x104/0x193
Jun  5 20:29:28 f13 kernel:   [<ffffffff810b9321>] free_irq+0x38/0x53
Jun  5 20:29:28 f13 kernel:   [<ffffffff812b7c03>] 
unbind_from_irqhandler+0x15/0x20
Jun  5 20:29:28 f13 kernel:   [<ffffffffa015a09a>] 
evtchn_unbind_from_user+0x23/0x36 [xen_evtchn]
Jun  5 20:29:28 f13 kernel:   [<ffffffffa015a3c7>] evtchn_ioctl+0x1e5/0x2c7 
[xen_evtchn]
Jun  5 20:29:28 f13 kernel:   [<ffffffff81135e95>] vfs_ioctl+0x22/0x87
Jun  5 20:29:28 f13 kernel:   [<ffffffff811363fe>] do_vfs_ioctl+0x488/0x4ce
Jun  5 20:29:28 f13 kernel:   [<ffffffff8113649a>] sys_ioctl+0x56/0x79
Jun  5 20:29:28 f13 kernel:   [<ffffffff81012cb2>] 
system_call_fastpath+0x16/0x1b
Jun  5 20:29:28 f13 kernel:
Jun  5 20:29:28 f13 kernel:
Jun  5 20:29:28 f13 kernel: stack backtrace:
Jun  5 20:29:28 f13 kernel: Pid: 1508, comm: xenstored Not tainted 2.6.32.15 #2
Jun  5 20:29:28 f13 kernel: Call Trace:
Jun  5 20:29:28 f13 kernel: [<ffffffff8108bf40>] check_usage+0x349/0x35d
Jun  5 20:29:28 f13 kernel: [<ffffffff8100f465>] ? xen_sched_clock+0x14/0x8c
Jun  5 20:29:28 f13 kernel: [<ffffffff8100f572>] ? check_events+0x12/0x20
Jun  5 20:29:28 f13 kernel: [<ffffffff8108bfb1>] check_irq_usage+0x5d/0xbe
Jun  5 20:29:28 f13 kernel: [<ffffffff8108ca6a>] __lock_acquire+0xa58/0xd3a
Jun  5 20:29:28 f13 kernel: [<ffffffff8100f465>] ? xen_sched_clock+0x14/0x8c
Jun  5 20:29:28 f13 kernel: [<ffffffff8108ce28>] lock_acquire+0xdc/0x102
Jun  5 20:29:28 f13 kernel: [<ffffffff8117bd76>] ? xlate_proc_name+0x3d/0xbb
Jun  5 20:29:28 f13 kernel: [<ffffffff8100f572>] ? check_events+0x12/0x20
Jun  5 20:29:28 f13 kernel: [<ffffffff81170076>] ? posix_acl_clone+0x10/0x31
Jun  5 20:29:28 f13 kernel: [<ffffffff81478cf1>] _spin_lock+0x36/0x69
Jun  5 20:29:28 f13 kernel: [<ffffffff8117bd76>] ? xlate_proc_name+0x3d/0xbb
Jun  5 20:29:28 f13 kernel: [<ffffffff8117bd76>] xlate_proc_name+0x3d/0xbb
Jun  5 20:29:28 f13 kernel: [<ffffffff8117be94>] remove_proc_entry+0x34/0x221
Jun  5 20:29:28 f13 kernel: [<ffffffff8100ede1>] ? 
xen_force_evtchn_callback+0xd/0xf
Jun  5 20:29:28 f13 kernel: [<ffffffff8100f572>] ? check_events+0x12/0x20
Jun  5 20:29:28 f13 kernel: [<ffffffff8100ede1>] ? 
xen_force_evtchn_callback+0xd/0xf
Jun  5 20:29:28 f13 kernel: [<ffffffff8100f572>] ? check_events+0x12/0x20
Jun  5 20:29:28 f13 kernel: [<ffffffff8100ede1>] ? 
xen_force_evtchn_callback+0xd/0xf
Jun  5 20:29:28 f13 kernel: [<ffffffff8100f572>] ? check_events+0x12/0x20
Jun  5 20:29:28 f13 kernel: [<ffffffff810bab5b>] 
unregister_handler_proc+0x31/0x35
Jun  5 20:29:28 f13 kernel: [<ffffffff810b925a>] __free_irq+0x104/0x193
Jun  5 20:29:28 f13 kernel: [<ffffffff810b9321>] free_irq+0x38/0x53
Jun  5 20:29:28 f13 kernel: [<ffffffff812b7c03>] 
unbind_from_irqhandler+0x15/0x20
Jun  5 20:29:28 f13 kernel: [<ffffffffa015a09a>] 
evtchn_unbind_from_user+0x23/0x36 [xen_evtchn]
Jun  5 20:29:28 f13 kernel: [<ffffffffa015a3c7>] evtchn_ioctl+0x1e5/0x2c7 
[xen_evtchn]
Jun  5 20:29:28 f13 kernel: [<ffffffffa015643e>] ? privcmd_ioctl+0x75/0x87 
[xenfs]
Jun  5 20:29:28 f13 kernel: [<ffffffff81135e95>] vfs_ioctl+0x22/0x87
Jun  5 20:29:28 f13 kernel: [<ffffffff8100ede1>] ? 
xen_force_evtchn_callback+0xd/0xf
Jun  5 20:29:28 f13 kernel: [<ffffffff811363fe>] do_vfs_ioctl+0x488/0x4ce
Jun  5 20:29:28 f13 kernel: [<ffffffff81012cea>] ? sysret_check+0x2e/0x69
Jun  5 20:29:28 f13 kernel: [<ffffffff8113649a>] sys_ioctl+0x56/0x79
Jun  5 20:29:28 f13 kernel: [<ffffffff81012cb2>] system_call_fastpath+0x16/0x1b
Jun  5 20:29:29 f13 avahi-daemon[1384]: Withdrawing address record for 
fe80::fcff:ffff:feff:ffff on vif1.0.
Jun  5 20:29:29 f13 kernel: virbr0: port 1(vif1.0) entering disabled state
Jun  5 20:29:29 f13 kernel: virbr0: port 1(vif1.0) entering disabled state


Kernel .config here: 
http://pasik.reaktio.net/xen/pv_ops-dom0-debug/config-2.6.32.15-pvops-dom0-xen-stable-x86_64

Any ideas? 


-- Pasi



_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxxxxxxxx
http://lists.xensource.com/xen-devel


 


Rackspace

Lists.xenproject.org is hosted with RackSpace, monitoring our
servers 24x7x365 and backed by RackSpace's Fanatical Support®.