Created attachment 7630 [details] source file. Since target-async was turned on by default, debugging on x86-windows using GDB+GDBserver sometimes hangs while waiting for a command that resumed the program's execution to report that the inferior stopped. The problem seems to be very racy in nature and does not allways appear, or not always at the same point in the debugging scenario (probability is about 70-80% of the time when debug traces are not enabled, it becomes much lower when GDBserver's --debug option is used, and nearly zero when GDBserver's --remote-debug option is used; enabling debug traces on the GDB side seem to have little effect on the probability). I could reprorduce the problem using the attached file (simple.c), compiled with GCC on x86-windows: % gcc -o simple -g simple.c In one shell, I started GDBserver: % /tardes.a/tmp/brobecke/bld/gdb-public/gdb/gdbserver/gdbserver.exe :4444 simple In another, I started GDB, set a breakpoint on the first call to "increment", connected to the target, ran to that breakpoint, and then I do as many "next" as possible until the debugger hangs. For instance: (gdb) b simple.c:12 Breakpoint 1 at 0x401610: file simple.c, line 12. (gdb) tar rem :4444 Remote debugging using :4444 0x77d7103c in ntdll!RtlUpcaseUnicodeToOemN () from C:\Windows\SysWOW64\ntdll.dll (gdb) c Continuing. Breakpoint 1, main () at simple.c:12 12 increment (&i); (gdb) n 13 increment (&i); (gdb) n 14 increment (&i); (gdb) n [hangs] After having added ad hoc traces in GDBserver, and turning infrun+remote traces on the GDB side, it looks like GDB is not receiving a T05 packet that GDBserver is sending to signal that the step is done. This is what we see for a faulty next on the GDB side: (gdb) n infrun: clear_proceed_status_thread (Thread 4424) infrun: proceed (addr=0xffffffff, signal=GDB_SIGNAL_DEFAULT, step=1) Sending packet: $m401610,1#f6...Packet received: 8d Sending packet: $X401610,1:�#e7...Packet received: OK Sending packet: $m763c4b72,1#cc...Packet received: 55 Sending packet: $X763c4b72,1:�#bd...Packet received: OK infrun: resume (step=1, signal=GDB_SIGNAL_0), trap_expected=0, current thread [Thread 4424] at 0x401634 Sending packet: $vCont;s:1148;c#5e... On the GDBserver side, this is what we see: DEBUG: write_prim ($OK#9a) -> 6 handling possible serial event DEBUG: write_prim ($8d#9c) -> 6 handling possible serial event DEBUG: write_prim ($OK#9a) -> 6 handling possible serial event DEBUG: write_prim ($55#6a) -> 6 handling possible serial event DEBUG: write_prim ($OK#9a) -> 6 handling possible serial event gdbserver: kernel event EXCEPTION_DEBUG_EVENT for pid=4968 tid=1148 EXCEPTION_SINGLE_STEP Child Stopped with signal = 5 Writing resume reply for LWP 4968.4424:1 DEBUG: write_prim ($T0505:c8fe2800;04:a0fe2800;08:38164000;thread:1148;#f0) -> 55 The "DEBUG: write_prim" traces show that write_prim was called and what value it returned. In particular for our last vCont, it eventually sent a T05 packet, which GDB is waiting for. At this point, attaching a debugger to the hanging GDB confirms that it is blocked, waiting for a socket event: #6 0x757841d8 in WaitForMultipleObjects () from C:\Windows\syswow64\kernel32.dll #7 0x004708e7 in gdb_select (n=469, readfds=0x88ca50 <gdb_notifier+784>, writefds=0x88cb54 <gdb_notifier+1044>, exceptfds=0x88cc58 <gdb_notifier+1304>, timeout=0x0) at /[...]/gdb/mingw-hdep.c:172 #8 0x00527926 in gdb_wait_for_event (block=1) at /[...]/gdb/event-loop.c:831 #9 0x00526ff1 in gdb_do_one_event () at /[...]/gdb/event-loop.c:403 Not sure why the event does not show up on the GDB side, though, and why target-async makes any difference.
> Not sure why the event does not show up on the GDB side. > though, and why target-async makes any difference. I haven't tried debugging this myself, but I'm clueless atm too. I'd suspect some gdb_select issue, but seems we block in gdb_select too on !target-async, within do_ser_base_readchar. I'd add some debug output to mingw-hdep.c:gdb_select, right after the WaitForMultipleObjects, to check whether something odd is doing on, like actually waking up from WaitForMultipleObjects once, but then not doing anything with the result, and then blocking again (forever). I was also wondering whether it'd be easy to make gdb_select call the real select, to try to isolate/identify the problem. Note: I think ctrl-c would stop working properly.
I have to say I'm quite surprised by this, given remote non-stop (+async) has been known to work on Windows hosts for a long while.
> I have to say I'm quite surprised by this, given remote non-stop (+async) has > been known to work on Windows hosts for a long while. I don't know, never tried it before. One of the differences that "set debug serial 1" seems to highlight is the fact that, in target-async mode, GDB seems to be making adjustments to the serial descriptor. I see things like this in the output (the "[fd468->...]" notifications). | Sending packet: $vCont;s:2930#c0...[ | w $][v][C][o][n][t][;][s][:][2][9][3][0][#][c][0][fd468->asynchronous] | [fd468->fd-scheduled] | [fd468->timer-scheduled] | [ | r $][T][0][5][0][5][:][c][8][f][e][2][8][0][0][;][0][4][:][a][0][f][e][2][8][0][0][;][0][8][:][1][4][1][6][4][0][0][0][;][t][h][r][e][a][d][:][2][9][3][0][;][#][e][fd468->fd-scheduled] | [a]Packet received (fd-468): T0505:c8fe2800;04:a0fe2800;08:14164000;thread:2930; On a vCont that does not work, I see: | Sending packet: $vCont;s:114c;c#89...[ | w $][v][C][o][n][t][;][s][:][1][1][4][c][;][c][#][8][9][fd468->asynchronous] | [fd468->fd-scheduled] Note the absence of changing the state to timer-scheduled. I don't know this code much. You? I am not sure whether this code is in fact relevant to this issue or not; I just started looking at it because I wanted to find a way to get to the file descriptor number for the remote connection.
I'm familiar with it, but a lot of the details have flushed out of cache. :-) I'll try setting up an environment to debug this.
I am discovering quite a bit with this PR, and one of the things I discovered is that we use a thread to perform select calls. That might explains the racy nature of this bug, and why adding traces ahead of the call to WaitForMultipleObjects seems to hide the issue. Putting some small traces in net_windows_wait_handle seems to indicate that sometimes the answer comes back fast enough that we don't need to start the select thread, while other times we do, and it's completely random - we must be right around the edge. It doesn't explain yet why turning target-async mode on would make any difference.
I changed the test to loop forever, like: void increment (int *i) { *i++; } int main (void) { int i = 0; again: increment (&i); increment (&i); increment (&i); increment (&i); increment (&i); increment (&i); increment (&i); increment (&i); increment (&i); increment (&i); increment (&i); increment (&i); increment (&i); increment (&i); increment (&i); increment (&i); increment (&i); increment (&i); increment (&i); increment (&i); increment (&i); goto again; } And I managed to reproduce it too: Sending packet: $vCont;s:9c0;c#5c... *hang* This is on Windows 7, 64-bit, in case we're hitting a Windows bug.
> I am discovering quite a bit with this PR, and one of the things > I discovered is that we use a thread to perform select calls. Yeah, that's actually why I was thinking of trying to make gdb_select call select directly, since we're using sockets here (gdb_select is needed for things _other_ than sockets). Not as a fix, but as a way to check that that's where the bug lies.
I tried now reading commands from a script, to check whether stdin getting signalled as ready for gdb_select too early might have something to do with it. But I can still trigger the issue that way: $ cat test.cmd tar rem :9999 tb increment c set debug remote 1 while 1 next end $ gdb ... -x test.cmd ... 19 increment (&i); Sending packet: $vCont;s:610;c#27...Packet received: T0505:c8fe2800;04:a0fe2800;08:d0154000;thread:610; Sending packet: $vCont;s:610;c#27...Packet received: T0505:c8fe2800;04:a0fe2800;08:d3154000;thread:610; Sending packet: $vCont;s:610;c#27... *hang* Well, at least it's a little easier to reproduce that way. :-)
I confirm that I can't reproduce this with "maint set target-async off".
> This is on Windows 7, 64-bit, in case we're hitting a Windows bug. Actually, I was using 64-bit Windows, but my GDB and test program were both compiled as 32-bit. Tried now real 64-bit, and I can still reproduce it, so WoW64 it not the culprit.
Oh, I think I found something. I noticed that the N argument to gdb_select was quite high. So I added an assertion to check that we're not doing undefined things with select and the FD_SET, etc. macros. See "man 3 select": "The behavior of these macros is undefined if the fd argument is less than 0 or greater than or equal to FD_SETSIZE, or if fd is not a valid file descriptor, or if any of the arguments are expressions with side effects." diff --git c/gdb/event-loop.c w/gdb/event-loop.c index 5999c97..662deb2 100644 --- c/gdb/event-loop.c +++ w/gdb/event-loop.c @@ -566,6 +566,8 @@ create_file_handler (int fd, int mask, handler_func * proc, } else { + gdb_assert (fd >= 0 && fd < FD_SETSIZE); + if (mask & GDB_READABLE) FD_SET (fd, &gdb_notifier.check_masks[0]); else diff --git c/gdb/gdbserver/event-loop.c w/gdb/gdbserver/event-loop.c index dc1eb41..1512e32 100644 --- c/gdb/gdbserver/event-loop.c +++ w/gdb/gdbserver/event-loop.c @@ -300,6 +300,10 @@ create_file_handler (gdb_fildes_t fd, int mask, handler_func *proc, file_ptr->next_file = gdb_notifier.first_file_handler; gdb_notifier.first_file_handler = file_ptr; + fprintf (stderr, "fd=%d, FD_SETSIZE=%d\n", fd, FD_SETSIZE); + + gdb_assert (fd >= 0 && fd < FD_SETSIZE); + if (mask & GDB_READABLE) FD_SET (fd, &gdb_notifier.check_masks[0]); else And lo: E:\gdb\mygit\build-win32\gdb\gdbserver>gdbserver :9999 ../simple32.exe Process ../simple32.exe created; pid = 1244 Listening on port 9999 fd=116, FD_SETSIZE=64 ../../../src/gdb/gdbserver/event-loop.c:305: A problem internal to GDBserver has been detected. create_file_handler: Assertion `fd >= 0 && fd < FD_SETSIZE' failed. E:\gdb\mygit\build-win32\gdb\gdbserver>
Nope, red herring. That assertion isn't valid for Windows. Socket descriptors are naturally high, and the FD_XXX macros handle it. Please the first argument to 'select' is actually ignored...
I think I found the race. I'd added some debug logs to ser-mingw.c, and this is what I see: w $][v][C][o][n][t][;][s][:][1][0][5][c][;][c][#][8][9][fd364->asynchronous] [fd364->fd-scheduled] net_windows_select_thread: WaitForMultipleObjects blocking net_windows_select_thread: WaitForMultipleObjects returned 1 (***) gdb_select: WaitForMultipleObjects blocking (t=0) gdb_select: WaitForMultipleObjects returned 102 gdb_select: WAIT_TIMEOUT net_windows_select_thread: WaitForMultipleObjects blocking gdb_select: WaitForMultipleObjects blocking (INFINITE) Notice the line at (***), just above. That indicates that the select thread noticed data was available. But, gdb_select was called with timeout == 0, IOW, it was just a non-blocking poll ("is there data ready now?"). Recall that is running on a separate thread. That WaitForMultipleObjects manages to run before net_windows_select_thread sets state->base.read_event, and returns WAIT_TIMEOUT. GDB then goes back to the event loop, and calls a blocking/infinite gdb_select. This loops through all fds, and calls net_windows_wait_handle. Recall that state->base.read_event is set, with data waiting to be consumed. But look, net_windows_wait_handle clears state->base.read_event! This #if 0 seems to fix it for me: static void net_windows_wait_handle (struct serial *scb, HANDLE *read, HANDLE *except) { struct net_windows_state *state = scb->state; /* Start from a clean slate. */ #if 0 ResetEvent (state->base.read_event); ResetEvent (state->base.except_event); #endif ResetEvent (state->base.stop_select); I haven't thought through consequences, but seems quite promising.
> I think I found the race. [...] > This #if 0 seems to fix it for me: > > static void > net_windows_wait_handle (struct serial *scb, HANDLE *read, HANDLE *except) > { > struct net_windows_state *state = scb->state; > /* Start from a clean slate. */ > #if 0 > ResetEvent (state->base.read_event); > ResetEvent (state->base.except_event); > #endif > ResetEvent (state->base.stop_select); > > I haven't thought through consequences, but seems quite promising. Indeed! I had seen that piece of code and questionned it, but somehow convinced myself that the reset was a necessary initialization and that it was always run before the select...
Patch posted: https://sourceware.org/ml/gdb-patches/2014-06/msg00424.html
This is an automated email from the git hooks/post-receive script. It was generated because a ref change was pushed to the repository containing the project "gdb and binutils". The branch, master has been updated via 364fe1f72265eb54bce08511233d06ed48e9c41a (commit) from 7ed689ad61de0cbfe4e5a6f18f097776128202e4 (commit) Those revisions listed above that are new to this repository have not appeared on any other notification email; so we list those revisions in full, below. - Log ----------------------------------------------------------------- https://sourceware.org/git/gitweb.cgi?p=binutils-gdb.git;h=364fe1f72265eb54bce08511233d06ed48e9c41a commit 364fe1f72265eb54bce08511233d06ed48e9c41a Author: Pedro Alves <palves@redhat.com> Date: Wed Jun 11 11:04:31 2014 +0100 PR remote/17028: GDB+GDBserver hangs on Windows Since target-async was turned on by default, debugging on Windows using GDB+GDBserver sometimes hangs while waiting for a RSP reply. The problem is a race in the gdb_select machinery. This is what we see for a faulty next on the GDB side: (gdb) n infrun: clear_proceed_status_thread (Thread 4424) infrun: proceed (addr=0xffffffff, signal=GDB_SIGNAL_DEFAULT, step=1) (...) infrun: resume (step=1, signal=GDB_SIGNAL_0), ... Sending packet: $vCont;s:1148;c#5e... *hang* At this point, attaching a debugger to the hanging GDB confirms that it is blocked, waiting for a socket event: #6 0x757841d8 in WaitForMultipleObjects () from C:\Windows\syswow64\kernel32.dll #7 0x004708e7 in gdb_select (n=469, readfds=0x88ca50 <gdb_notifier+784>, writefds=0x88cb54 <gdb_notifier+1044>, exceptfds=0x88cc58 <gdb_notifier+1304>, timeout=0x0) at /[...]/gdb/mingw-hdep.c:172 #8 0x00527926 in gdb_wait_for_event (block=1) at /[...]/gdb/event-loop.c:831 #9 0x00526ff1 in gdb_do_one_event () at /[...]/gdb/event-loop.c:403 However, on the GDBserver side, we see that GDBserver already sent a T05 packet reply: gdbserver: kernel event EXCEPTION_DEBUG_EVENT for pid=4968 tid=1148 EXCEPTION_SINGLE_STEP Child Stopped with signal = 5 Writing resume reply for LWP 4968.4424:1 DEBUG: write_prim ($T0505:c8fe2800;04:a0fe2800;08:38164000;thread:1148;#f0) -> 55 To recap, on Windows, 'select' only works with sockets, so we have a wrapper, gdb_select, that uses the GDB serial abstraction to handle sockets, consoles, pipes, and serial ports. Each serial descriptor has a thread associated (we call those the select threads), and those threads communicate with the main thread by means of standard Windows events. It basically goes like this: gdb_select first loops through all fds of interest, calling their wait_handle hooks, which returns an event that WaitForMultipleObjects can wait on. gdb_select then blocks in WaitForMultipleObjects with all those event handles. The wait_handle hook is responsible for arranging for the returned event to become set once data is available. This is done by setting the descriptor's helper thread running, which itself knows how to wait for data from the type of handle it manages (sockets, pipes, consoles, files, etc.). Once data arrives, the select thread sets the corresponding event which unblocks WaitForMultipleObjects within gdb_select. However, the wait_handle hook can also apply an optimization: if data is already pending, then there's no need to set the thread running, and the descriptors event can be set immediately. It's around this latter aspect that lies the bug/race. Adding some ad hoc debug logs to ser-mingw.c and mingw-hdep.c, we see the following sequence of events, right after sending "$vCont;s:1148;c#5e". Thread 1 is the main thread, and thread 2 is the socket's helper/select thread. gdb_select was only passed one descriptor to wait on, the remote target's socket. net_windows_select_thread is the entry point of the select threads for sockets. #1 - thread 1: gdb_select: enter #2 - thread 2: net_windows_select_thread: WaitForMultipleObjects blocking gdb_select walked over the wait_handle hooks, and woke up the socket's helper thread. The helper thread is now blocked waiting for socket events. #3 - thread 1: gdb_select: WaitForMultipleObjects polling (timeout=0ms) #4 - thread 1: gdb_select: WaitForMultipleObjects returned 102 (WAIT_TIMEOUT) There was no pending data available yet, and gdb_select was passed timeout==0ms, and so WaitForMultipleObjects times out immediately. #5 - thread 2: net_windows_select_thread: WaitForMultipleObjects returned 1 Just afterwards, socket data arrives, and thread 2 wakes up. Thread 2 calls WSAEnumNetworkEvents, which clears state->sock_event, and marks the serial's read_event event, telling the main thread that data is available. #6 - thread 1: gdb_select: call serial_done_wait_handle on each serial gdb_select stops all the helper/select threads. #7 - thread 1: gdb_select: return 0 (WAIT_TIMEOUT) gdb_select in the main thread returns to the caller. Note that at this point, data is pending on the socket, the serial's read_event is set, but the socket's sock_event event is not set, until _further_ data arrives. Now GDB does its thing and goes back to the event loop. That calls gdb_select, but with timeout==INFINITE. Again, gdb_select calls the socket serial's wait_handle hook. It first clears its events, starting from a clean slate: ResetEvent (state->base.read_event); ResetEvent (state->base.except_event); ResetEvent (state->base.stop_select); That cleared read_event, which was previously set in #5 above. And then it checks for pending events, in the sock_event event: /* Check any pending events. This both avoids starting the thread unnecessarily, and handles stray FD_READ events (see below). */ if (WaitForSingleObject (state->sock_event, 0) == WAIT_OBJECT_0) { That also fails because state->sock_event was cleared in #5 too... So the wait_handle hook erroneously decides that it needs to start the helper thread to wait for input: #8 - thread 2: net_windows_select_thread: WaitForMultipleObjects blocking #9 - thread 1: gdb_select: WaitForMultipleObjects blocking (INFINITE) But, GDBserver already sent all it had to send, so both threads waits forever... At first I thought that net_windows_wait_handle shouldn't be resetting state->base.read_event or state->base.except_event, but looking deeper, the pipe and console wait_handle hooks reset all events too. It actually makes sense that way -- consuming an event from different threads is bad practice, and, we should always be able to query pending state without looking at the state->sock_event from within net_windows_wait_handle. The end result is much simpler, and makes net_windows_select_thread look a lot like console_select_thread, actually. gdb/ 2014-06-11 Pedro Alves <palves@redhat.com> PR remote/17028 * ser-mingw.c (net_windows_socket_check_pending): New function. (net_windows_select_thread): Ignore spurious wakeups. Use net_windows_socket_check_pending. (net_windows_wait_handle): Check for pending events with ioctlsocket, through net_windows_socket_check_pending, instead of checking the socket's event. ----------------------------------------------------------------------- Summary of changes: gdb/ChangeLog | 10 ++++ gdb/ser-mingw.c | 141 +++++++++++++++++++++++++++---------------------------- 2 files changed, 79 insertions(+), 72 deletions(-)
Fixed.