[haiku-bugs] Re: [Haiku] #6300: LegacyDevice-related lock order reversal deadlock
- From: "anevilyak" <trac@xxxxxxxxxxxx>
- Date: Mon, 12 Jul 2010 02:01:11 -0000
#6300: LegacyDevice-related lock order reversal deadlock
----------------------------+-----------------------------------------------
Reporter: anevilyak | Owner: axeld
Type: bug | Status: new
Priority: normal | Milestone: R1
Component: System/Kernel | Version: R1/Development
Resolution: | Keywords:
Blocked By: | Has a Patch: 0
Platform: All | Blocking:
----------------------------+-----------------------------------------------
Description changed by anevilyak:
Old description:
> I was compiling something and simultaneously unplugged/replugged my USB
> keyboard. The shell handling the compile deadlocked, and the keyboard
> never came up. Looking further, I found that the shell thread was
> deadlocked waiting on a mutex, which another thread held but was waiting
> to acquire a different mutex. KDL session info below.
>
> {{{
>
> teams
> team id parent name
> 0x90848e00 62 0x82027e00 net_server
> 0x82027540 63 0x82027e00 app_server
> 0x82027e00 1 0x00000000 kernel_team
> 0x9ac5a000 1707 0x82027e00 sh
> 0x820278c0 95 0x82027e00 mount_server
> 0x90af6540 443 0x82027e00 Terminal
> 0x82027a80 539 0x91142c40 Tracker
> 0x91142c40 447 0x90af6540 bash
> 0x90848a80 106 0x82027e00 Deskbar
> 0x82027380 75 0x82027e00 syslog_daemon
> 0x90848700 107 0x82027e00 media_server
> 0x908481c0 139 0x90848700 media_addon_server
> 0x90848540 108 0x82027e00 midi_server
> 0x90848380 109 0x82027e00 print_server
> 0x90af6c40 111 0x82027e00 cddb_daemon
> 0x820271c0 54 0x82027e00 registrar
> 0x908488c0 86 0x82027540 input_server
> 0x90af6000 464 0x82027e00 Vision
> 0x82027000 61 0x82027e00 debug_server
> kdebug> bt 1707
> stack trace for thread 1707 "sh"
> kernel stack: 0x80713000 to 0x80717000
> user stack: 0x7efee000 to 0x7ffee000
> frame caller <image>:function + offset
> 0 80716cb4 (+ 64) 80072dc2 <kernel_x86> reschedule() + 0x036d
> 1 80716cf4 (+ 64) 8006feb8 <kernel_x86>:_mutex_lock + 0x01a9
> 2 80716d34 (+ 32) 8006ff04 <kernel_x86>:recursive_lock_lock + 0x004a
> 3 80716d54 (+ 64) 800919d5 <kernel_x86> devfs_lookup(fs_volume*:
> 0x82207b40d
> 4 80716d94 (+ 64) 800b960d <kernel_x86> lookup_dir_entry(vnode*:
> 0x1716ee8,2
> 5 80716dd4 (+ 64) 800bbde7 <kernel_x86> vnode_path_to_vnode(vnode*:
> NULL, ca
> 6 80716e14 (+ 48) 800bc83a <kernel_x86> vnode_path_to_vnode(vnode*:
> NULL, cc
> 7 80716e44 (+ 64) 800bc933 <kernel_x86> path_to_vnode(char*:
> 0x80716edc, fa1
> 8 80716e84 (+ 64) 800bdeed <kernel_x86> fd_and_path_to_vnode(int32:
> -2140045
> 9 80716ec4 (+ 64) 800c0427 <kernel_x86> file_open(int32: 0, char*:
> 0x2938230
> 10 80716f04 (+ 64) 800c0fc4 <kernel_x86>:_user_open + 0x0091
> 11 80716f44 (+ 100) 800f8e71 <kernel_x86>:handle_syscall + 0x00be
> user iframe at 0x80716fa8 (end = 0x80717000)
> eax 0x64 ebx 0x372de8 ecx 0x7ffedecc edx 0xffff0114
> esi 0x7ffee538 edi 0x7ffee548 ebp 0x7ffedee8 esp 0x80716fdc
> eip 0xffff0114 eflags 0x246 user esp 0x7ffedecc
> vector: 0x63, error code: 0x0
> 12 80716fa8 (+ 0) ffff0114 <commpage>:commpage_syscall + 0x0004
> 13 7ffedee8 (+ 32) 002271ac <_APP_>:check_dev_tty + 0x0024
> 14 7ffedf08 (+ 96) 00224a1b <_APP_>:main + 0x0054
> 15 7ffedf68 (+ 52) 0021a0dd <_APP_>:_start + 0x0051
> 16 7ffedf9c (+ 64) 001052ab
> </boot/system/runtime_loader@0x00100000>:unknownb
> 17 7ffedfdc (+ 0) 7ffedfec 44887:sh_main_stack@0x7efee000 + 0xffffec
> kdebug> thread 1707
> THREAD: 0x90e55400
> id: 1707 (0x6ab)
> name: "sh"
> all_next: 0x82354800
> team_next: 0x00000000
> q_next: 0x80160a00
> priority: 1 (next 10, I/O: -1)
> state: waiting
> next_state: waiting
> cpu: 0x00000000
> sig_pending: 0x2 (blocked: 0x0, temp enabled: 0x0)
> in_kernel: 1
> waiting for: mutex 0x82207b18
> fault_handler: 0x00000000
> args: 0x821cca80 0x00000000
> entry: 0x80065751
> team: 0x9ac5a000, "sh"
> exit.sem: 32369
> exit.status: 0x0 (No error)
> exit.reason: 0x0
> exit.signal: 0x0
> exit.waiters:
> kernel_stack_area: 44885
> kernel_stack_base: 0x80713000
> user_stack_area: 44887
> user_stack_base: 0x7efee000
> user_local_storage: 0x7ffee000
> user_thread: 0x6fff0000
> kernel_errno: 0x0 (No error)
> kernel_time: 10712
> user_time: 534
> flags: 0x1
> architecture dependant section:
> esp: 0x80716c58
> ss: 0x00000010
> fpu_state at 0x90e557e0
> kdebug> mutex 0x82207b18
> mutex 0x82207b18:
> name: devfs lock
> flags: 0x0
> holder: 153
> waiting threads: 29 1707
> kdebug> bt 153
> stack trace for thread 153 "user thread"
> kernel stack: 0x80717000 to 0x8071b000
> user stack: 0x70041000 to 0x70081000
> frame caller <image>:function + offset
> 0 8071ad34 (+ 64) 80072dc2 <kernel_x86> reschedule() + 0x036d
> 1 8071ad74 (+ 64) 8006feb8 <kernel_x86>:_mutex_lock + 0x01a9
> 2 8071adb4 (+ 32) 8006ff04 <kernel_x86>:recursive_lock_lock + 0x004a
> 3 8071add4 (+ 48) 80094442 <kernel_x86>
> LegacyDevice<0x917ff548>::Removed()6
> 4 8071ae04 (+ 32) 800900bd <kernel_x86> devfs_delete_vnode(devfs*:
> 0x8200301
> 5 8071ae24 (+ 48) 80091592 <kernel_x86>
> devfs_remove_vnode(fs_volume*: 0x828
> 6 8071ae54 (+ 32) 800b6b06 <kernel_x86> free_vnode(vnode*:
> 0x917dff20, truea
> 7 8071ae74 (+ 48) 800ba93a <kernel_x86> dec_vnode_ref_count(vnode*:
> NULL, t6
> 8 8071aea4 (+ 16) 800bad5b <kernel_x86>
> file_free_fd(file_descriptor*: 0x910
> 9 8071aeb4 (+ 32) 800ab40b <kernel_x86>:put_fd + 0x002d
> 10 8071aed4 (+ 64) 800ab55a <kernel_x86>:close_fd_index + 0x00a6
> 11 8071af14 (+ 32) 800ab5b6 <kernel_x86> common_close(int32:
> -2140033112, tr3
> 12 8071af34 (+ 16) 800ab5e3 <kernel_x86>:_user_close + 0x0013
> 13 8071af44 (+ 100) 800f8e71 <kernel_x86>:handle_syscall + 0x00be
> user iframe at 0x8071afa8 (end = 0x8071b000)
> eax 0x90 ebx 0x2e4de8 ecx 0x70080d40 edx 0xffff0114
> esi 0x18049020 edi 0x18049020 ebp 0x70080d5c esp 0x8071afdc
> eip 0xffff0114 eflags 0x216 user esp 0x70080d40
> vector: 0x63, error code: 0x0
> 14 8071afa8 (+ 0) ffff0114 <commpage>:commpage_syscall + 0x0004
> 15 70080d5c (+ 64) 017386d2
> </boot/system/lib/libdevice.so@0x01730000>:unkno2
> 16 70080d9c (+ 32) 017387f2
> </boot/system/lib/libdevice.so@0x01730000>:unkno2
> 17 70080dbc (+ 80) 017398cd
> </boot/system/lib/libdevice.so@0x01730000>:unknod
> 18 70080e0c (+ 64) 01739a75
> </boot/system/lib/libdevice.so@0x01730000>:unkno5
> 19 70080e4c (+ 64) 01739a95
> </boot/system/lib/libdevice.so@0x01730000>:unkno5
> 20 70080e8c (+ 64) 01739a95
> </boot/system/lib/libdevice.so@0x01730000>:unkno5
> 21 70080ecc (+ 96) 0173a4b2
> </boot/system/lib/libdevice.so@0x01730000>:unkno2
> 22 70080f2c (+ 32) 003c72f8 <libbe.so>
> BLooper<0x18035050>::DispatchMessage(0
> 23 70080f4c (+ 80) 003c8e34 <libbe.so>
> BLooper<0x18035050>::task_looper() + 6
> 24 70080f9c (+ 32) 003c8b5a <libbe.so>
> BLooper<0x18035050>::_task0_(void*: N0
> 25 70080fbc (+ 32) 0024b4ec <libroot.so>:exit_thread (nearest) +
> 0x0058
> 26 70080fdc (+ 0) 70080fec 3301:user thread_153_stack@0x70041000 +
> 0x3ffec
> kdebug> bt 29
> stack trace for thread 29 "usb explore"
> kernel stack: 0x817f3000 to 0x817f7000
> frame caller <image>:function + offset
> 0 817f6de8 (+ 64) 80072dc2 <kernel_x86> reschedule() + 0x036d
> 1 817f6e28 (+ 64) 8006feb8 <kernel_x86>:_mutex_lock + 0x01a9
> 2 817f6e68 (+ 32) 8006ff04 <kernel_x86>:recursive_lock_lock + 0x004a
> 3 817f6e88 (+ 64) 8009085f <kernel_x86> unpublish_node(devfs*:
> 0x90d28f60, d
> 4 817f6ec8 (+ 48) 800908e7 <kernel_x86>
> devfs_unpublish_device(BaseDevice*:2
> 5 817f6ef8 (+ 64) 80093c35 <kernel_x86>
> republish_driver(legacy_driver*: 0x1
> 6 817f6f38 (+ 16) 80094583 <kernel_x86>:legacy_driver_rescan + 0x0036
> 7 817f6f48 (+ 32) 8009073f <kernel_x86>:devfs_rescan_driver + 0x000e
> 8 817f6f68 (+ 32) 817a054a <usb>
> Stack<0x822f0730>::RescanDrivers(rescan_it6
> 9 817f6f88 (+ 80) 817a094c <usb>
> Stack<0x822f0730>::ExploreThread(void*: NUc
> 10 817f6fd8 (+ 32) 80069337 <kernel_x86>
> _create_kernel_thread_kentry() + 0x5
> 11 817f6ff8 (+2122354696) 8006d518 <kernel_x86> thread_kthread_exit() +
> 0x0000
> kdebug> thread 153
> THREAD: 0x90e37800
> id: 153 (0x99)
> name: "user thread"
> all_next: 0x82350600
> team_next: 0x90e3a800
> q_next: 0x80160420
> priority: 10 (next 10, I/O: -1)
> state: waiting
> next_state: waiting
> cpu: 0x00000000
> sig_pending: 0x0 (blocked: 0x0, temp enabled: 0x0)
> in_kernel: 1
> waiting for: mutex 0x80168de4
> fault_handler: 0x00000000
> args: 0x003c8b2a 0x18045620
> entry: 0x0024b4bf
> team: 0x90848380, "print_server"
> exit.sem: 1124
> exit.status: 0x0 (No error)
> exit.reason: 0x0
> exit.signal: 0x0
> exit.waiters:
> kernel_stack_area: 3300
> kernel_stack_base: 0x80717000
> user_stack_area: 3301
> user_stack_base: 0x70041000
> user_local_storage: 0x70081000
> user_thread: 0x6fff0018
> kernel_errno: 0x0 (No error)
> kernel_time: 437
> user_time: 403
> flags: 0x0
> architecture dependant section:
> esp: 0x8071acd8
> ss: 0x00000010
> fpu_state at 0x90e37be0
> kdebug> mutex 0x80168de4
> mutex 0x80168de4:
> name: legacy driver
> flags: 0x0
> holder: 29
> waiting threads: 153
>
> }}}
New description:
I was compiling something and simultaneously unplugged/replugged my USB
keyboard. The shell handling the compile deadlocked, and the keyboard
never came up. Looking further, I found that the shell thread was
deadlocked waiting on the devfs mutex, which another thread held but was
waiting to acquire the legacy device mutex, so it seems we have a lock
order reversal problem here. KDL session info below.
{{{
teams
team id parent name
0x90848e00 62 0x82027e00 net_server
0x82027540 63 0x82027e00 app_server
0x82027e00 1 0x00000000 kernel_team
0x9ac5a000 1707 0x82027e00 sh
0x820278c0 95 0x82027e00 mount_server
0x90af6540 443 0x82027e00 Terminal
0x82027a80 539 0x91142c40 Tracker
0x91142c40 447 0x90af6540 bash
0x90848a80 106 0x82027e00 Deskbar
0x82027380 75 0x82027e00 syslog_daemon
0x90848700 107 0x82027e00 media_server
0x908481c0 139 0x90848700 media_addon_server
0x90848540 108 0x82027e00 midi_server
0x90848380 109 0x82027e00 print_server
0x90af6c40 111 0x82027e00 cddb_daemon
0x820271c0 54 0x82027e00 registrar
0x908488c0 86 0x82027540 input_server
0x90af6000 464 0x82027e00 Vision
0x82027000 61 0x82027e00 debug_server
kdebug> bt 1707
stack trace for thread 1707 "sh"
kernel stack: 0x80713000 to 0x80717000
user stack: 0x7efee000 to 0x7ffee000
frame caller <image>:function + offset
0 80716cb4 (+ 64) 80072dc2 <kernel_x86> reschedule() + 0x036d
1 80716cf4 (+ 64) 8006feb8 <kernel_x86>:_mutex_lock + 0x01a9
2 80716d34 (+ 32) 8006ff04 <kernel_x86>:recursive_lock_lock + 0x004a
3 80716d54 (+ 64) 800919d5 <kernel_x86> devfs_lookup(fs_volume*:
0x82207b40d
4 80716d94 (+ 64) 800b960d <kernel_x86> lookup_dir_entry(vnode*:
0x1716ee8,2
5 80716dd4 (+ 64) 800bbde7 <kernel_x86> vnode_path_to_vnode(vnode*:
NULL, ca
6 80716e14 (+ 48) 800bc83a <kernel_x86> vnode_path_to_vnode(vnode*:
NULL, cc
7 80716e44 (+ 64) 800bc933 <kernel_x86> path_to_vnode(char*:
0x80716edc, fa1
8 80716e84 (+ 64) 800bdeed <kernel_x86> fd_and_path_to_vnode(int32:
-2140045
9 80716ec4 (+ 64) 800c0427 <kernel_x86> file_open(int32: 0, char*:
0x2938230
10 80716f04 (+ 64) 800c0fc4 <kernel_x86>:_user_open + 0x0091
11 80716f44 (+ 100) 800f8e71 <kernel_x86>:handle_syscall + 0x00be
user iframe at 0x80716fa8 (end = 0x80717000)
eax 0x64 ebx 0x372de8 ecx 0x7ffedecc edx 0xffff0114
esi 0x7ffee538 edi 0x7ffee548 ebp 0x7ffedee8 esp 0x80716fdc
eip 0xffff0114 eflags 0x246 user esp 0x7ffedecc
vector: 0x63, error code: 0x0
12 80716fa8 (+ 0) ffff0114 <commpage>:commpage_syscall + 0x0004
13 7ffedee8 (+ 32) 002271ac <_APP_>:check_dev_tty + 0x0024
14 7ffedf08 (+ 96) 00224a1b <_APP_>:main + 0x0054
15 7ffedf68 (+ 52) 0021a0dd <_APP_>:_start + 0x0051
16 7ffedf9c (+ 64) 001052ab
</boot/system/runtime_loader@0x00100000>:unknownb
17 7ffedfdc (+ 0) 7ffedfec 44887:sh_main_stack@0x7efee000 + 0xffffec
kdebug> thread 1707
THREAD: 0x90e55400
id: 1707 (0x6ab)
name: "sh"
all_next: 0x82354800
team_next: 0x00000000
q_next: 0x80160a00
priority: 1 (next 10, I/O: -1)
state: waiting
next_state: waiting
cpu: 0x00000000
sig_pending: 0x2 (blocked: 0x0, temp enabled: 0x0)
in_kernel: 1
waiting for: mutex 0x82207b18
fault_handler: 0x00000000
args: 0x821cca80 0x00000000
entry: 0x80065751
team: 0x9ac5a000, "sh"
exit.sem: 32369
exit.status: 0x0 (No error)
exit.reason: 0x0
exit.signal: 0x0
exit.waiters:
kernel_stack_area: 44885
kernel_stack_base: 0x80713000
user_stack_area: 44887
user_stack_base: 0x7efee000
user_local_storage: 0x7ffee000
user_thread: 0x6fff0000
kernel_errno: 0x0 (No error)
kernel_time: 10712
user_time: 534
flags: 0x1
architecture dependant section:
esp: 0x80716c58
ss: 0x00000010
fpu_state at 0x90e557e0
kdebug> mutex 0x82207b18
mutex 0x82207b18:
name: devfs lock
flags: 0x0
holder: 153
waiting threads: 29 1707
kdebug> bt 153
stack trace for thread 153 "user thread"
kernel stack: 0x80717000 to 0x8071b000
user stack: 0x70041000 to 0x70081000
frame caller <image>:function + offset
0 8071ad34 (+ 64) 80072dc2 <kernel_x86> reschedule() + 0x036d
1 8071ad74 (+ 64) 8006feb8 <kernel_x86>:_mutex_lock + 0x01a9
2 8071adb4 (+ 32) 8006ff04 <kernel_x86>:recursive_lock_lock + 0x004a
3 8071add4 (+ 48) 80094442 <kernel_x86>
LegacyDevice<0x917ff548>::Removed()6
4 8071ae04 (+ 32) 800900bd <kernel_x86> devfs_delete_vnode(devfs*:
0x8200301
5 8071ae24 (+ 48) 80091592 <kernel_x86> devfs_remove_vnode(fs_volume*:
0x828
6 8071ae54 (+ 32) 800b6b06 <kernel_x86> free_vnode(vnode*: 0x917dff20,
truea
7 8071ae74 (+ 48) 800ba93a <kernel_x86> dec_vnode_ref_count(vnode*:
NULL, t6
8 8071aea4 (+ 16) 800bad5b <kernel_x86> file_free_fd(file_descriptor*:
0x910
9 8071aeb4 (+ 32) 800ab40b <kernel_x86>:put_fd + 0x002d
10 8071aed4 (+ 64) 800ab55a <kernel_x86>:close_fd_index + 0x00a6
11 8071af14 (+ 32) 800ab5b6 <kernel_x86> common_close(int32:
-2140033112, tr3
12 8071af34 (+ 16) 800ab5e3 <kernel_x86>:_user_close + 0x0013
13 8071af44 (+ 100) 800f8e71 <kernel_x86>:handle_syscall + 0x00be
user iframe at 0x8071afa8 (end = 0x8071b000)
eax 0x90 ebx 0x2e4de8 ecx 0x70080d40 edx 0xffff0114
esi 0x18049020 edi 0x18049020 ebp 0x70080d5c esp 0x8071afdc
eip 0xffff0114 eflags 0x216 user esp 0x70080d40
vector: 0x63, error code: 0x0
14 8071afa8 (+ 0) ffff0114 <commpage>:commpage_syscall + 0x0004
15 70080d5c (+ 64) 017386d2
</boot/system/lib/libdevice.so@0x01730000>:unkno2
16 70080d9c (+ 32) 017387f2
</boot/system/lib/libdevice.so@0x01730000>:unkno2
17 70080dbc (+ 80) 017398cd
</boot/system/lib/libdevice.so@0x01730000>:unknod
18 70080e0c (+ 64) 01739a75
</boot/system/lib/libdevice.so@0x01730000>:unkno5
19 70080e4c (+ 64) 01739a95
</boot/system/lib/libdevice.so@0x01730000>:unkno5
20 70080e8c (+ 64) 01739a95
</boot/system/lib/libdevice.so@0x01730000>:unkno5
21 70080ecc (+ 96) 0173a4b2
</boot/system/lib/libdevice.so@0x01730000>:unkno2
22 70080f2c (+ 32) 003c72f8 <libbe.so>
BLooper<0x18035050>::DispatchMessage(0
23 70080f4c (+ 80) 003c8e34 <libbe.so>
BLooper<0x18035050>::task_looper() + 6
24 70080f9c (+ 32) 003c8b5a <libbe.so>
BLooper<0x18035050>::_task0_(void*: N0
25 70080fbc (+ 32) 0024b4ec <libroot.so>:exit_thread (nearest) + 0x0058
26 70080fdc (+ 0) 70080fec 3301:user thread_153_stack@0x70041000 +
0x3ffec
kdebug> bt 29
stack trace for thread 29 "usb explore"
kernel stack: 0x817f3000 to 0x817f7000
frame caller <image>:function + offset
0 817f6de8 (+ 64) 80072dc2 <kernel_x86> reschedule() + 0x036d
1 817f6e28 (+ 64) 8006feb8 <kernel_x86>:_mutex_lock + 0x01a9
2 817f6e68 (+ 32) 8006ff04 <kernel_x86>:recursive_lock_lock + 0x004a
3 817f6e88 (+ 64) 8009085f <kernel_x86> unpublish_node(devfs*:
0x90d28f60, d
4 817f6ec8 (+ 48) 800908e7 <kernel_x86>
devfs_unpublish_device(BaseDevice*:2
5 817f6ef8 (+ 64) 80093c35 <kernel_x86>
republish_driver(legacy_driver*: 0x1
6 817f6f38 (+ 16) 80094583 <kernel_x86>:legacy_driver_rescan + 0x0036
7 817f6f48 (+ 32) 8009073f <kernel_x86>:devfs_rescan_driver + 0x000e
8 817f6f68 (+ 32) 817a054a <usb>
Stack<0x822f0730>::RescanDrivers(rescan_it6
9 817f6f88 (+ 80) 817a094c <usb>
Stack<0x822f0730>::ExploreThread(void*: NUc
10 817f6fd8 (+ 32) 80069337 <kernel_x86> _create_kernel_thread_kentry()
+ 0x5
11 817f6ff8 (+2122354696) 8006d518 <kernel_x86> thread_kthread_exit() +
0x0000
kdebug> thread 153
THREAD: 0x90e37800
id: 153 (0x99)
name: "user thread"
all_next: 0x82350600
team_next: 0x90e3a800
q_next: 0x80160420
priority: 10 (next 10, I/O: -1)
state: waiting
next_state: waiting
cpu: 0x00000000
sig_pending: 0x0 (blocked: 0x0, temp enabled: 0x0)
in_kernel: 1
waiting for: mutex 0x80168de4
fault_handler: 0x00000000
args: 0x003c8b2a 0x18045620
entry: 0x0024b4bf
team: 0x90848380, "print_server"
exit.sem: 1124
exit.status: 0x0 (No error)
exit.reason: 0x0
exit.signal: 0x0
exit.waiters:
kernel_stack_area: 3300
kernel_stack_base: 0x80717000
user_stack_area: 3301
user_stack_base: 0x70041000
user_local_storage: 0x70081000
user_thread: 0x6fff0018
kernel_errno: 0x0 (No error)
kernel_time: 437
user_time: 403
flags: 0x0
architecture dependant section:
esp: 0x8071acd8
ss: 0x00000010
fpu_state at 0x90e37be0
kdebug> mutex 0x80168de4
mutex 0x80168de4:
name: legacy driver
flags: 0x0
holder: 29
waiting threads: 153
}}}
--
--
Ticket URL: <http://dev.haiku-os.org/ticket/6300#comment:1>
Haiku <http://dev.haiku-os.org>
Haiku - the operating system.
Other related posts:
