[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
|
![]() |
Lists.xenproject.org is hosted with RackSpace, monitoring our |