Opened 10 years ago

Closed 10 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:
Has a Patch: no 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)

comment:1 by bonefish, 10 years ago

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:

  • PtyReader -- reads from the TTY device into a buffer. Can only block reading from the TTY (while there are no new data) or on the lock protecting the buffer. The latter is unlikely, since the critical sections are very short and shouldn't do anything that can block.
  • EscParse -- reads the characters from the internal buffer, parsing escape/control sequences and adjusting the [Basic]TerminalBuffer accordingly. Can only block reading the buffer (when empty) or only the lock protecting the TerminalBuffer.
  • The window thread -- synchronizes a local copy of the TerminalBuffer with the one EscParse works on, draws the local buffer, processes user (keyboard) input and writes to the TTY, and does the usual window work. Can block on the lock protecting the TerminalBuffer (never for long, though), on the looper port, when writing to the TTY, on the app server port,...

Having a look in the kernel debugger, what the threads are doing, should hopefully result in a good hint.

in reply to:  1 comment:2 by anevilyak, 10 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 anevilyak, 10 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 bonefish, 10 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).

comment:5 by anevilyak, 10 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.

in reply to:  5 comment:6 by bonefish, 10 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 bonefish, 10 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:8 by anevilyak, 10 years ago

Will see what I can do after work in a few hours.

comment:9 by anevilyak, 10 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.

comment:10 by mmlr, 10 years ago

Resolution: fixed
Status: newclosed

Fixed in hrev32733.

Note: See TracTickets for help on using tickets.