Strange behavior of sigstep-threads.exp?

Strange behavior of sigstep-threads.exp?

[Andreas Arnez]

On x86-64 with upstream GDB, I'm observing what I consider strange
behavior of the sigstep-threads.exp test case.

Here's an excerpt from the log file:

  32        var++;                /* step-1 */
  (gdb) disable $step1
  (gdb) step

  Program received signal SIGUSR1, User defined signal 1.

  Program received signal SIGUSR1, User defined signal 1.

  Program received signal SIGUSR1, User defined signal 1.

  Program received signal SIGUSR1, User defined signal 1.
  33        tgkill (getpid (), gettid (), SIGUSR1);       /* step-2 */

It seems that running from step-1 to step-2 produced four SIGUSR1.  And
in total ca. 3 times as many signals are encountered than we pass
tgkill()'s:

  $ grep tgkill gdb.log | wc
      100    1000    5900
  $ grep 'Program received signal SIGUSR1' gdb.log | wc
      310    2480   17670

From the code I wouldn't expect that.  Is this a known bug or expected
behavior?  Note that the test case doesn't fail, since it doesn't care
about the number of incoming signals.

On s390x the test case actually fails sometimes.  In those cases, when
stepping from step-1 to step-2, a ton of SIGUSR1 are indicated, and then
the inferior seems to stop at the closing brace of the handler()
function instead of the tgkill().

Re: Strange behavior of sigstep-threads.exp?

[Pedro Alves]

On 11/08/2012 03:50 PM, Andreas Arnez wrote:
> On x86-64 with upstream GDB, I'm observing what I consider strange
> behavior of the sigstep-threads.exp test case.
> 
> Here's an excerpt from the log file:
> 
>   32        var++;                /* step-1 */
>   (gdb) disable $step1
>   (gdb) step
> 
>   Program received signal SIGUSR1, User defined signal 1.
> 
>   Program received signal SIGUSR1, User defined signal 1.
> 
>   Program received signal SIGUSR1, User defined signal 1.
> 
>   Program received signal SIGUSR1, User defined signal 1.
>   33        tgkill (getpid (), gettid (), SIGUSR1);       /* step-2 */
> 
> It seems that running from step-1 to step-2 produced four SIGUSR1.  And
> in total ca. 3 times as many signals are encountered than we pass
> tgkill()'s:
> 
>   $ grep tgkill gdb.log | wc
>       100    1000    5900
>   $ grep 'Program received signal SIGUSR1' gdb.log | wc
>       310    2480   17670
> 
> From the code I wouldn't expect that.  Is this a known bug or expected
> behavior?  Note that the test case doesn't fail, since it doesn't care
> about the number of incoming signals.

static void
handler (int signo)	/* step-0 */
{			/* step-0 */
  var++;		/* step-1 */
  tgkill (getpid (), gettid (), SIGUSR1);	/* step-2 */
}

static void *
start (void *arg)
{
  tgkill (getpid (), gettid (), SIGUSR1);
  assert (0);
  return NULL;
}

int
main (void)
{
  pthread_t thread;

  signal (SIGUSR1, handler);

  pthread_create (&thread, NULL, start, NULL);
  start (NULL);	/* main-start */
  return 0;
}

There are two threads in the test.  The main thread, and another
spawned by pthread_create.  They both start at "start", and
send SIGUSR1 to themselves.  The SIGUSR1 handler sends a
SIGUSR1 to the current thread, so each thread is constantly re-entering
"handler" ad infinitum.

The test does "handle SIGUSR1 nostop print pass", which means that
control is never passed to the user whenever the program gets a
SIGUSR1, but GDB still prints the signal (the "Program received ..." lines).

The test then steps _one_ of the threads (the one that happens to reach
the "step-1" line first), let's call it thread #1.  This "step" involves
multiple single-steps behind the scenes.  Whenever each of those single-steps
is done, the other thread (let's call it thread #2) is allowed to run free (the
"set scheduler-locking off" setting).  Occasionally, that other thread
will run enough to send itself another SIGUSR1.  And then, occasionally
GDB will see that SIGUSR1 in thread #2, print "Program received", and
go back to single-stepping thread #1, until it reaches a different line.

So "grep tgkill gdb.log" will only count the "step"s that have passed
through the "tgkill (getpid (), ..." line, while "grep 'Program received
signal SIGUSR1'" counts both threads sending themselves SIGUSR1.

Moreover, since thread #2 is "continued", while thread #1 is
single-stepped, it is expected that thread #2 makes progress faster, hence
the 3 to 1 ratio you see.  I see 4 to 1 on my machine even.

> On s390x the test case actually fails sometimes.  In those cases, when
> stepping from step-1 to step-2, a ton of SIGUSR1 are indicated, and then
> the inferior seems to stop at the closing brace of the handler()
> function instead of the tgkill().

That does sound like something's wrong.  Hacking the the test to force
"set debug infrun 1" and "set debug lin-lwp 1" would be my first move.

I wonder if this makes a difference?

 gdb/infrun.c |    6 ++++--
 1 file changed, 4 insertions(+), 2 deletions(-)

diff --git a/gdb/infrun.c b/gdb/infrun.c
index de2cf19..9621b84 100644
--- a/gdb/infrun.c
+++ b/gdb/infrun.c
@@ -4698,8 +4698,10 @@ process_event_stop_test:
 	  ecs->event_thread = tp;
 	  ecs->ptid = tp->ptid;
 	  context_switch (ecs->ptid);
-	  keep_going (ecs);
-	  return;
+
+	  /* Keep checking.  The stepped thread might have already
+	     reached its destination, but not have reported it yet.
+	     If we just kept going, we could end up overstepping.  */
 	}
     }

Re: Strange behavior of sigstep-threads.exp?

[Andreas Arnez]

Pedro Alves <palves@redhat.com> writes:

> Whenever each of those single-steps is done, the other thread (let's
> call it thread #2) is allowed to run free (the "set scheduler-locking
> off" setting).

Got it.  Seems I misunderstood the "step" behavior in this case.  Thanks
for the explanation.

>> On s390x the test case actually fails sometimes.  In those cases,
>> when stepping from step-1 to step-2, a ton of SIGUSR1 are indicated,
>> and then the inferior seems to stop at the closing brace of the
>> handler() function instead of the tgkill().
>
> That does sound like something's wrong.  Hacking the the test to force
> "set debug infrun 1" and "set debug lin-lwp 1" would be my first move.

As soon as "lin-lwp" debugging is turned on the test always seems to
succeed.  But with "debug infrun" alone the failure still occurs, and I
observe the following:

1. The stepped thread reaches the last instruction inside the stepping
range.

2. After resuming the stepped thread again, it traps at getpid@plt.
Which is curious, because getpid() shouldn't be called until the
instruction _after_ the stepping range.  It seems like the trap for that
instruction was missed somehow.  (In the good case the thread always
traps at the subroutine call, before having carried out the call.)

3. The thread is single-stepped until the jump to getpid().  The
getpid() invocation itself is skipped with a step-resume breakpoint on
the instruction after the original subroutine call.

4. The step-resume breakpoint is reached.  Despite now being well
outside the original stepping range, the thread is resumed.  Upon the
next trap, an updated stepping range is shown, adjusted to fit the line
of the tgkill().  Then stepping continues until the next line, which is
the closing brace.

> I wonder if this makes a difference?
>
>  gdb/infrun.c |    6 ++++--
>  1 file changed, 4 insertions(+), 2 deletions(-)
>
> diff --git a/gdb/infrun.c b/gdb/infrun.c
> index de2cf19..9621b84 100644
> --- a/gdb/infrun.c
> +++ b/gdb/infrun.c
> @@ -4698,8 +4698,10 @@ process_event_stop_test:
>  	  ecs->event_thread = tp;
>  	  ecs->ptid = tp->ptid;
>  	  context_switch (ecs->ptid);
> -	  keep_going (ecs);
> -	  return;
> +
> +	  /* Keep checking.  The stepped thread might have already
> +	     reached its destination, but not have reported it yet.
> +	     If we just kept going, we could end up overstepping.  */
>  	}
>      }

Yes, it does make a difference.  The test case still fails at a similar
rate as before, but this time after "continue", because the inferior
reaches "assert (0)".  Again, I can not reproduce this failure with "set
debug infrun 1" and "set debug lin-lwp 1".

Re: Strange behavior of sigstep-threads.exp?

[Pedro Alves]

On 11/13/2012 03:21 PM, Andreas Arnez wrote:
> Pedro Alves <palves@redhat.com> writes:
> 
>> > Whenever each of those single-steps is done, the other thread (let's
>> > call it thread #2) is allowed to run free (the "set scheduler-locking
>> > off" setting).
> Got it.  Seems I misunderstood the "step" behavior in this case.  Thanks
> for the explanation.
> 
>>> >> On s390x the test case actually fails sometimes.  In those cases,
>>> >> when stepping from step-1 to step-2, a ton of SIGUSR1 are indicated,
>>> >> and then the inferior seems to stop at the closing brace of the
>>> >> handler() function instead of the tgkill().
>> >
>> > That does sound like something's wrong.  Hacking the the test to force
>> > "set debug infrun 1" and "set debug lin-lwp 1" would be my first move.
> As soon as "lin-lwp" debugging is turned on the test always seems to
> succeed.  But with "debug infrun" alone the failure still occurs, and I
> observe the following:
> 
> 1. The stepped thread reaches the last instruction inside the stepping
> range.
> 
> 2. After resuming the stepped thread again, it traps at getpid@plt.
> Which is curious, because getpid() shouldn't be called until the
> instruction _after_ the stepping range.  It seems like the trap for that
> instruction was missed somehow.  (In the good case the thread always
> traps at the subroutine call, before having carried out the call.)

Indeed that's odd.  Is the event that is reported to GDB _before_ this
trap at getpid@plt a SIGUSR1 for the other thread?
linux-nat.c always gives preference to a SIGTRAP over other
signals, so it's unexpected that a trap could be lost.  Maybe while GDB goes
about stopping all threads with SIGSTOP (in effect, only the single-stepped
thread), the single step has actually completed, but the kernel manages
to report the SIGSTOP first, for some bizarre reason?  IOW, the kernel loses
the trap.  You could try to add some prints of the current PC of all lwps
at each event, so see if the stepped lwp makes the expected progress, but
we miss the trap, or even perhaps see if the lwp jumps between the last instruction
in the step range and getpid@plt, without the kernel ever reporting any
kind of stop at the branch.  Just adding a few prints instead of full
lin-lwp debug might be non disturbing enough.

> 
> 3. The thread is single-stepped until the jump to getpid().  The
> getpid() invocation itself is skipped with a step-resume breakpoint on
> the instruction after the original subroutine call.
> 
> 4. The step-resume breakpoint is reached.  Despite now being well
> outside the original stepping range, the thread is resumed.  Upon the
> next trap, an updated stepping range is shown, adjusted to fit the line
> of the tgkill().  Then stepping continues until the next line, which is
> the closing brace.
> 
>> > I wonder if this makes a difference?
>> >
>> >  gdb/infrun.c |    6 ++++--
>> >  1 file changed, 4 insertions(+), 2 deletions(-)
>> >
>> > diff --git a/gdb/infrun.c b/gdb/infrun.c
>> > index de2cf19..9621b84 100644
>> > --- a/gdb/infrun.c
>> > +++ b/gdb/infrun.c
>> > @@ -4698,8 +4698,10 @@ process_event_stop_test:
>> >  	  ecs->event_thread = tp;
>> >  	  ecs->ptid = tp->ptid;
>> >  	  context_switch (ecs->ptid);
>> > -	  keep_going (ecs);
>> > -	  return;
>> > +
>> > +	  /* Keep checking.  The stepped thread might have already
>> > +	     reached its destination, but not have reported it yet.
>> > +	     If we just kept going, we could end up overstepping.  */
>> >  	}
>> >      }
> Yes, it does make a difference.  The test case still fails at a similar
> rate as before, but this time after "continue", because the inferior
> reaches "assert (0)".  Again, I can not reproduce this failure with "set
> debug infrun 1" and "set debug lin-lwp 1".

Hmm.  This confirms there's something not expected with single-step traps, like
we discuss above.  I shouldn't really make a difference for hardware step
Linux targets, as the backend always gives preference to single-step traps.  The
patch was originally for fixing something for software single-step targets, only.
If the assert is reached, a SIGUSR1 is mistakenly swallowed, which was the
whole point of the test.

-- 
Pedro Alves

Re: Strange behavior of sigstep-threads.exp?

[Andreas Arnez]

Pedro Alves <palves@redhat.com> writes:

> linux-nat.c always gives preference to a SIGTRAP over other signals,
> so it's unexpected that a trap could be lost.  Maybe while GDB goes
> about stopping all threads with SIGSTOP (in effect, only the
> single-stepped thread), the single step has actually completed, but
> the kernel manages to report the SIGSTOP first, for some bizarre
> reason?  IOW, the kernel loses the trap.

Right, the kernel loses the trap.

While processing the SIGUSR1 from thread #2, GDB stops all other threads
with SIGSTOP -- in this case the single-stepped thread #1.  Now if the
SIGSTOP is sent after thread #1 has received the single-step exception,
but before the kernel has decided what signals to present, the kernel
suppresses the SIGTRAP and just delivers the SIGSTOP instead.

Discussed this with the s390 kernel maintainer.  A kernel patch is on
the way.

Re: Strange behavior of sigstep-threads.exp?

[Pedro Alves]

On 11/21/2012 06:46 PM, Andreas Arnez wrote:
> Pedro Alves <palves@redhat.com> writes:
> 
>> linux-nat.c always gives preference to a SIGTRAP over other signals,
>> so it's unexpected that a trap could be lost.  Maybe while GDB goes
>> about stopping all threads with SIGSTOP (in effect, only the
>> single-stepped thread), the single step has actually completed, but
>> the kernel manages to report the SIGSTOP first, for some bizarre
>> reason?  IOW, the kernel loses the trap.
> 
> Right, the kernel loses the trap.

Great (that GDB isn't at fault).  :-)

> While processing the SIGUSR1 from thread #2, GDB stops all other threads
> with SIGSTOP -- in this case the single-stepped thread #1.  Now if the
> SIGSTOP is sent after thread #1 has received the single-step exception,
> but before the kernel has decided what signals to present, the kernel
> suppresses the SIGTRAP and just delivers the SIGSTOP instead.
> 
> Discussed this with the s390 kernel maintainer.  A kernel patch is on
> the way.

Thanks.

-- 
Pedro Alves