Opened 15 years ago
Closed 15 years ago
#4343 closed bug (fixed)
Debugger's console output frequently deadlocks Terminal
| Reported by: | anevilyak | Owned by: | jackburton |
|---|---|---|---|
| Priority: | normal | Milestone: | R1 |
| Component: | Applications/Terminal | Version: | R1/pre-alpha1 |
| Keywords: | Cc: | ||
| Blocked By: | Blocking: | ||
| Platform: | All |
Description
During startup, the graphical debugger spits out a ton of output when parsing the DWARF data in binaries. This frequently manages to completely deadlock Terminal (and consequently also the debugger, since it's stuck writing to stdout which the terminal isn't emptying buffers for), especially when run with a larger lib such as libtracker or libbe that's built with debugging information included.
Change History (10)
follow-up: 2 comment:1 by , 15 years ago
comment:2 by , 15 years ago
Replying to bonefish:
Haven't seen that yet. Could you be bribed into have a look how the Terminal deadlocks when you next encounter it? :-) There are three threads involved in the Terminal:
No bribe needed, just needed some pointers as to what to investigate :). It's pretty easily reproducible here with a debug build libtracker and/or libbe at least, though it doesn't happen 100% of the time. Will let you know the results along with the other 2-3 bugs I need to report further details on tonight hopefully.
comment:3 by , 15 years ago
As requested:
PANIC: Keyboard Requested Halt.
Welcome to Kernel Debugging Land...
Thread 2 "idle thread 2" running on CPU 0
kdebug> teams
team id parent name
0x811b0990 62 0x811b0198 app_server
0x811b0198 1 0x00000000 kernel_team
0x8146e4c8 250 0x8146e330 sh
0x81272330 95 0x811b0198 Deskbar
0x81272660 97 0x811b0198 media_server
0x812727f8 98 0x811b0198 midi_server
0x81272b28 100 0x811b0198 print_server
0x81272cc0 132 0x81272660 media_addon_server
0x81272e58 102 0x811b0198 cddb_daemon
0x81272000 543 0x8146e4c8 Debugger
0x8146e000 546 0x81272000 Tracker
0x811b0b28 81 0x811b0198 syslog_daemon
0x811b04c8 53 0x811b0198 registrar
0x812724c8 209 0x811b0198 Vision
0x81272198 85 0x811b0990 input_server
0x8146e660 461 0x8146e4c8 infopopper_server
0x8146e330 246 0x812724c8 Terminal
0x811b0660 60 0x811b0198 debug_server
0x811b07f8 61 0x811b0198 net_server
kdebug> threads 246
thread id state wait for object cpu pri stack team name
0x90117000 251 waiting sem 4068 - 10 0x913b2000 246 PtyReader
0x900ab800 252 waiting sem 4067 - 15 0x913b6000 246 EscParse
0x9012f000 253 waiting cvar 0x913bdbe0 - 15 0x913ba000 246 w>Terminal 1
0x90116800 246 waiting sem 3971 - 10 0x913a2000 246 Terminal
kdebug> sem 4068
SEM: 0x8f995ba0
id: 4068 (0xfe4)
name: 'pty_locker_sem'
owner: 246
count: -1
queue: 251
last acquired by: 251
kdebug> sem 4067
SEM: 0x8f995b78
id: 4067 (0xfe3)
name: 'pty_reader_sem'
owner: 246
count: -1
queue: 252
last acquired by: 252
kdebug> cvar 0x913bdbe0
condition variable 0x913bdbe0
object: 0x913bddbc (tty request)
threads: 253
kdebug> bt 251
stack trace for thread 251 "PtyReader"
kernel stack: 0x913b2000 to 0x913b6000
user stack: 0x70000000 to 0x70040000
frame caller <image>:function + offset
0 913b5e84 (+ 64) 8005ff17 <kernel_x86> affine_reschedule() + 0x039c
1 913b5ec4 (+ 80) 8004ef43 <kernel_x86>:switch_sem_etc + 0x054a
2 913b5f14 (+ 48) 8004f0a4 <kernel_x86>:_user_acquire_sem + 0x0019
3 913b5f44 (+ 100) 800cbaf1 <kernel_x86>:handle_syscall + 0x00be
user iframe at 0x913b5fa8 (end = 0x913b6000)
eax 0xb ebx 0x7f2808 ecx 0x7003f740 edx 0xffff0114
esi 0x18056e50 edi 0x800 ebp 0x7003f75c esp 0x913b5fdc
eip 0xffff0114 eflags 0x212 user esp 0x7003f740
vector: 0x63, error code: 0x0
4 913b5fa8 (+ 0) ffff0114 <commpage>:commpage_syscall + 0x0004
5 7003f75c (+2112) 00221132 <_APP_> TermParse<0x18056e50>::PtyReader() + 0x005c
6 7003ff9c (+ 32) 002212b3 <_APP_> TermParse<0x18056e50>::_ptyreader_thread(void*: NULL) + 0x001b
7 7003ffbc (+ 32) 0075808d <libroot.so>:_thread_do_exit_notification (nearest) + 0x007a
8 7003ffdc (+ 0) 7003ffec 3632:PtyReader_251_stack@0x70000000 + 0x3ffec
kdebug> bt 252
stack trace for thread 252 "EscParse"
kernel stack: 0x913b6000 to 0x913ba000
user stack: 0x70041000 to 0x70081000
frame caller <image>:function + offset
0 913b9e84 (+ 64) 8005ff17 <kernel_x86> affine_reschedule() + 0x039c
1 913b9ec4 (+ 80) 8004ef43 <kernel_x86>:switch_sem_etc + 0x054a
2 913b9f14 (+ 48) 8004f0a4 <kernel_x86>:_user_acquire_sem + 0x0019
3 913b9f44 (+ 100) 800cbaf1 <kernel_x86>:handle_syscall + 0x00be
user iframe at 0x913b9fa8 (end = 0x913ba000)
eax 0xb ebx 0x7f2808 ecx 0x70080c90 edx 0xffff0114
esi 0x18056e50 edi 0x0 ebp 0x70080cac esp 0x913b9fdc
eip 0xffff0114 eflags 0x212 user esp 0x70080c90
vector: 0x63, error code: 0x0
4 913b9fa8 (+ 0) ffff0114 <commpage>:commpage_syscall + 0x0004
5 70080cac (+ 48) 00220ecd <_APP_> TermParse<0x18056e50>::_ReadParserBuffer() + 0x004d
6 70080cdc (+ 704) 0022183c <_APP_> TermParse<0x18056e50>::EscParse() + 0x00a2
7 70080f9c (+ 32) 00222859 <_APP_> TermParse<0x18056e50>::_escparse_thread(void*: NULL) + 0x001b
8 70080fbc (+ 32) 0075808d <libroot.so>:_thread_do_exit_notification (nearest) + 0x007a
9 70080fdc (+ 0) 70080fec 3634:EscParse_252_stack@0x70041000 + 0x3ffec
kdebug> bt 253
stack trace for thread 253 "w>Terminal 1"
kernel stack: 0x913ba000 to 0x913be000
user stack: 0x70082000 to 0x700c2000
frame caller <image>:function + offset
0 913bdaf4 (+ 64) 8005ff17 <kernel_x86> affine_reschedule() + 0x039c
1 913bdb34 (+ 32) 80059693 <kernel_x86>:thread_block_with_timeout_locked + 0x011f
2 913bdb54 (+ 64) 8003cb44 <kernel_x86> ConditionVariableEntry<0x913bdbcc>::Wait(uint32: 0x9 (9), int64: 9223372036854775807) + 0x00d2
3 913bdb94 (+ 112) 8079c61b </boot/system/add-ons/kernel/drivers/dev/tty> RequestOwner<0x913bddbc>::Wait(true, int64: 9223372036854775807) + 0x00d5
4 913bdc04 (+ 64) 8079da70 </boot/system/add-ons/kernel/drivers/dev/tty> WriterLocker<0x913bddac>::AcquireWriter(false, uint32: 0x0 (0)) + 0x012e
5 913bdc44 (+ 480) 8079e02e </boot/system/add-ons/kernel/drivers/dev/tty> tty_write_to_tty_master(tty_cookie*: 0x81469e20, void const*: 0x18155892, unsigned long*: 0x913bdf30) + 0x0189
6 913bde24 (+ 32) 8079f31a </boot/system/add-ons/kernel/drivers/dev/tty> master_write(void*: 0x81469e20, int64: 40347773, void const*: 0x18155892, unsigned long*: 0x913bdf30) + 0x0021
7 913bde44 (+ 80) 80079585 <kernel_x86> devfs_write(fs_volume*: 0x811b59b0, fs_vnode*: 0x8146b6e8, void*: 0x811feaa0, int64: 40347773, void const*: 0x18155892, unsigned long*: 0x913bdf30) + 0x00af
8 913bde94 (+ 64) 8009903b <kernel_x86> file_write(file_descriptor*: 0x81454e10, int64: 40347773, void const*: 0x18155892, unsigned long*: 0x913bdf30) + 0x0053
9 913bded4 (+ 80) 80091767 <kernel_x86> common_user_io(int32: 404052114, int64: 4294967296, void*: 0x9012f000, uint32: 0x913bdfa8, true) + 0x0109
10 913bdf24 (+ 32) 80091803 <kernel_x86>:_user_write + 0x001c
11 913bdf44 (+ 100) 800cbaf1 <kernel_x86>:handle_syscall + 0x00be
user iframe at 0x913bdfa8 (end = 0x913be000)
eax 0x85 ebx 0x7f2808 ecx 0x700c1b90 edx 0xffff0114
esi 0x18155892 edi 0x18155892 ebp 0x700c1bbc esp 0x913bdfdc
eip 0xffff0114 eflags 0x212 user esp 0x700c1b90
vector: 0x63, error code: 0x0
12 913bdfa8 (+ 0) ffff0114 <commpage>:commpage_syscall + 0x0004
13 700c1bbc (+ 32) 0021de89 <_APP_> Shell<0x18021820>::Write(void const*: 0x18155892, uint32: 0x1 (1)) + 0x0031
14 700c1bdc (+ 144) 00225a84 <_APP_> TermView<0x18029de8>::KeyDown(char const*: 0x18155892 "a", int32: 1) + 0x046c
15 700c1c6c (+ 720) 0039b745 <libbe.so> BWindow<0x1802a040>::DispatchMessage(BMessage*: 0x1800fd70, BHandler*: 0x18029de8) + 0x0d39
16 700c1f3c (+ 96) 00397f3f <libbe.so> BWindow<0x1802a040>::task_looper() + 0x0277
17 700c1f9c (+ 32) 002e80b4 <libbe.so> BLooper<0x1802a040>::_task0_(void*: NULL) + 0x0030
18 700c1fbc (+ 32) 0075808d <libroot.so>:_thread_do_exit_notification (nearest) + 0x007a
19 700c1fdc (+ 0) 700c1fec 3649:w>Terminal 1_253_stack@0x70082000 + 0x3ffec
kdebug>
Let me know what else you need please.
comment:4 by , 15 years ago
My recollection was not quite correct. The buffer shared by PtyReader and EscParse thread is not protected by a lock; both use atomic operations instead. There are two semaphores though: One the PtyReader waits on when the buffer is full and one the EscParse thread waits on when the buffer is empty. Interestingly both threads wait on their respective semaphore, which means the buffer is in a superposed quantum state: both empty and full at the same time. Well, or there's a logical bug in the code. ;-)
Apparently some key has been pressed which caused the window thread to write something to the TTY. Since it is in echo mode by default and the TTY master buffer is full, this thread also blocks. I guess writing to the TTY in the window thread is something one shouldn't do anyway, since even under normal circumstances the thread will block when the TTY client buffer is full (e.g. when the client doesn't read its stdin).
follow-up: 6 comment:5 by , 15 years ago
So, need any further information to analyze the problem, or is that enough to work with for now? For me at least, building with the following rules:
SetConfigVar DEBUG : HAIKU_TOP src kits : 1 : global ; SetConfigVar DEBUG : HAIKU_TOP src apps tracker : 1 : global ;
And then installing the resulting libbe, libtracker and Tracker, followed by /boot/system/apps/Debugger /system/Tracker (after quitting the running instance of Tracker) reproduces this bug with about an 80% success rate. One step I forgot though: after the debugger's output spontaneously stops (it's obvious it's not actually done since the Debugger doesn't jump into the state where it shows source and is ready to hit the Run button on the initial thread), the cursor still blinks, ergo the window thread isn't yet deadlocked. Typing a letter in the Terminal however does not echo back and results in the deadlock situation seen above. Sorry I'd forgotten to mention that earlier, though I doubt it makes much difference. Let me know if you need any further data to analyze this one.
comment:6 by , 15 years ago
Replying to anevilyak:
So, need any further information to analyze the problem, or is that enough to work with for now?
The basic problem is understood -- both PtyReader and EscParse wait because they think the same buffer is full respectively empty -- I just fail to see the bug in the code. For anyone interested, the two methods in question are TermParse::PtyReader() and _ReadParserBuffer() in src/apps/terminal/TermParse.cpp.
One step I forgot though: after the debugger's output spontaneously stops (it's obvious it's not actually done since the Debugger doesn't jump into the state where it shows source and is ready to hit the Run button on the initial thread), the cursor still blinks, ergo the window thread isn't yet deadlocked. Typing a letter in the Terminal however does not echo back and results in the deadlock situation seen above. Sorry I'd forgotten to mention that earlier, though I doubt it makes much difference.
That's exactly what I guessed anyway. The main problem is PtyReader and EscParse both blocking. The blocking of the window thread is just collateral damage.
comment:7 by , 15 years ago
Tried to reproduce with the described method, but couldn't even a single time of more than a dozen attempts. I'm still on hrev32367, so maybe something has changed in the meantime (scheduling) that makes the bug better reproducible. Since you seem to be able to easily reproduce it, if you could build a debug version of Terminal, attach gdb when the bug occurs the next time, and print *this for the TermParse object in question as well as a few interesting locals for PtyReader and EscParse that would help.
comment:9 by , 15 years ago
Seem to be having some issues replicating the situation when using a debug build of Terminal...will keep trying, but maybe a hint nonetheless.
Haven't seen that yet. Could you be bribed into have a look how the Terminal deadlocks when you next encounter it? :-) There are three threads involved in the Terminal:
Having a look in the kernel debugger, what the threads are doing, should hopefully result in a good hint.