Sporadic failures of selftest tests

Sporadic failures of selftest tests

[Ulrich Weigand]

Hello,

I'm now seeing sporadic failures of some of the self-test test cases
running natively on x64_86.  A failing case looks like:

(gdb) break captured_command_loop
Breakpoint 1 at 0x7117b0: file ../../binutils-gdb/gdb/main.c, line 324.
(gdb) PASS: gdb.gdb/complaints.exp: breakpoint in captured_command_loop
run -nw -nx -data-directory /home/uweigand/fsf/binutils-gdb-build/gdb/testsuite/../data-directory
Starting program: /home/uweigand/fsf/binutils-gdb-build/gdb/testsuite/outputs/gdb.gdb/complaints/xgdb -nw -nx -data-directory /home/uweigand/fsf/binutils-gdb-build/gdb/testsuite/../data-directory
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
GNU gdb (GDB) 8.0.50.20171017-git
Copyright (C) 2017 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-pc-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word".
(gdb) FAIL: gdb.gdb/complaints.exp: run until breakpoint at captured_command_loop
WARNING: Couldn't test self

while the good case looks instead like:

(gdb) break captured_command_loop
Breakpoint 1 at 0x7117b0: file ../../binutils-gdb/gdb/main.c, line 324.
(gdb) PASS: gdb.gdb/complaints.exp: breakpoint in captured_command_loop
run -nw -nx -data-directory /home/uweigand/fsf/binutils-gdb-build/gdb/testsuite/../data-directory
Starting program: /home/uweigand/fsf/binutils-gdb-build/gdb/testsuite/outputs/gdb.gdb/complaints/xgdb -nw -nx -data-directory /home/uweigand/fsf/binutils-gdb-build/gdb/testsuite/../data-directory
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
GNU gdb (GDB) 8.0.50.20171017-git
Copyright (C) 2017 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-pc-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word".
(gdb) 
Breakpoint 1, captured_main (data=0x7fffffffd2e0) at ../../binutils-gdb/gdb/main.c:1147
1147              captured_command_loop ();
(gdb) XFAIL: gdb.gdb/complaints.exp: run until breakpoint at captured_command_loop (line numbers scrambled?)

Just from reading the logs this looks like the gdb_test_multiple in selftest_setup
gets the GDB prompt from the inferior GDB and assumes it comes from the outer GDB.
Depending on the exact timing, it might see this before the breakpoint message,
and fall into the failure case of the gdb_test_multiple ...

Pedro, I'm not sure if this may have anything to do with your recent testsuite
changes, but I didn't see any other obvious candidates in the logs either :-)

Have you see this issue before?  How is this supposed to work in the first place?
Is there anything that would allow the testsuite to distinguish the gdb prompts
emitted by the two GDBs?

Bye,
Ulrich

-- 
  Dr. Ulrich Weigand
  GNU/Linux compilers and toolchain
  Ulrich.Weigand@de.ibm.com

Re: Sporadic failures of selftest tests

[Pedro Alves]

On 10/17/2017 03:00 PM, Ulrich Weigand wrote:
> Hello,
> 
> I'm now seeing sporadic failures of some of the self-test test cases
> running natively on x64_86.  A failing case looks like:
> 
> (gdb) break captured_command_loop
> Breakpoint 1 at 0x7117b0: file ../../binutils-gdb/gdb/main.c, line 324.
> (gdb) PASS: gdb.gdb/complaints.exp: breakpoint in captured_command_loop

[...]

> Type "apropos word" to search for commands related to "word".
> (gdb) 
> Breakpoint 1, captured_main (data=0x7fffffffd2e0) at ../../binutils-gdb/gdb/main.c:1147
> 1147              captured_command_loop ();
> (gdb) XFAIL: gdb.gdb/complaints.exp: run until breakpoint at captured_command_loop (line numbers scrambled?)
> 
> Just from reading the logs this looks like the gdb_test_multiple in selftest_setup
> gets the GDB prompt from the inferior GDB and assumes it comes from the outer GDB.

I don't think so.  "captured_main" is a function in the inferior
GDB, so that's the superior gdb's prompt.  I.e., the test ran
the inferior GDB to main, well before the inferior GDB could print
a prompt.

> Pedro, I'm not sure if this may have anything to do with your recent testsuite
> changes, but I didn't see any other obvious candidates in the logs either :-)

This one kind of looks related:

commit bf4692711232eb96cd840f96d88897a2746d8190
Author:     Pedro Alves <palves@redhat.com>
AuthorDate: Tue Oct 10 16:45:50 2017 +0100

    Eliminate catch_errors

which did:

--- a/gdb/testsuite/lib/selftest-support.exp
+++ b/gdb/testsuite/lib/selftest-support.exp
@@ -88,10 +88,10 @@ proc selftest_setup { executable function } {
 
     set description "run until breakpoint at $function"
     gdb_test_multiple "run $INTERNAL_GDBFLAGS" "$description" {
-        -re "Starting program.*Breakpoint \[0-9\]+,.*$function .data.* at .*main.c:.*$gdb_prompt $" {
+        -re "Starting program.*Breakpoint \[0-9\]+,.*$function \\(\\).* at .*main.c:.*$gdb_prompt $" {
             pass "$description"
         }
-        -re "Starting program.*Breakpoint \[0-9\]+,.*$function .data.*$gdb_prompt $" {
+        -re "Starting program.*Breakpoint \[0-9\]+,.*$function \\(\\).*$gdb_prompt $" {
             xfail "$description (line numbers scrambled?)"
         }
        -re "Starting program.*Breakpoint \[0-9\]+,.* at .*main.c:.*$function.*$gdb_prompt $" {


while above in your log, we still see that the test stopped
in the captured_main function, which has a data parameter:

> Breakpoint 1, captured_main (data=0x7fffffffd2e0) at ../../binutils-gdb/gdb/main.c:1147

However, that means GDB stopped in the totally wrong function, so likely
it'd have failed before too.  

Now the question should be why did GDB stop there, when breakpoint 1
was supposedly set on captured_command_loop ?

 > (gdb) break captured_command_loop
 > Breakpoint 1 at 0x7117b0: file ../../binutils-gdb/gdb/main.c, line 324.
 > (gdb) PASS: gdb.gdb/complaints.exp: breakpoint in captured_command_loop
...
 > (gdb) 
 > Breakpoint 1, captured_main (data=0x7fffffffd2e0) at ../../binutils-gdb/gdb/main.c:1147
 > 1147              captured_command_loop ();

That seems to be the root of the problem.

I wonder whether that's somehow related to the other Power regression
Simon reported:
  https://sourceware.org/ml/gdb-patches/2017-10/msg00444.html

I haven't managed to investigate that one.

Does it reproduce easily for you?  If so, I'd suggest a git bisect to
find the culprit.

> Have you see this issue before?  How is this supposed to work in the first place?
> Is there anything that would allow the testsuite to distinguish the gdb prompts
> emitted by the two GDBs?

The selftests that need to distinguish the prompts do "set prompt (xgdb)" to
change one the prompt of one of the gdb's.  But that's a red herring in this case.

Thanks,
Pedro Alves

Re: Sporadic failures of selftest tests

[Pedro Alves]

On 10/17/2017 03:24 PM, Pedro Alves wrote:

> Now the question should be why did GDB stop there, when breakpoint 1
> was supposedly set on captured_command_loop ?
> 
>  > (gdb) break captured_command_loop
>  > Breakpoint 1 at 0x7117b0: file ../../binutils-gdb/gdb/main.c, line 324.
>  > (gdb) PASS: gdb.gdb/complaints.exp: breakpoint in captured_command_loop
> ...
>  > (gdb) 
>  > Breakpoint 1, captured_main (data=0x7fffffffd2e0) at ../../binutils-gdb/gdb/main.c:1147
>  > 1147              captured_command_loop ();
> 
> That seems to be the root of the problem.
> 
> I wonder whether that's somehow related to the other Power regression
> Simon reported:
>   https://sourceware.org/ml/gdb-patches/2017-10/msg00444.html
> 
> I haven't managed to investigate that one.
> 
> Does it reproduce easily for you?  If so, I'd suggest a git bisect to
> find the culprit.

Wait, is your build of GDB an optimized build?  Maybe the compiler
managed to inline captured_command_loop for you?  Currnetly, when
GDB stops for an inline breakpoint, it stops at the stack caller,
which would explain this.

Thanks,
Pedro Alves

Re: Sporadic failures of selftest tests

[Pedro Alves]

On 10/17/2017 03:34 PM, Pedro Alves wrote:

> Wait, is your build of GDB an optimized build?  Maybe the compiler
> managed to inline captured_command_loop for you?  Currnetly, when
> GDB stops for an inline breakpoint, it stops at the stack caller,
> which would explain this.

Yup, I can reproduce this with:

$ rm -f main.o && make CXXFLAGS="-g3 -O2"
$ make check TESTS="*/complaints.exp"
[...]
Running src/gdb/testsuite/gdb.gdb/complaints.exp ...
FAIL: gdb.gdb/complaints.exp: run until breakpoint at captured_command_loop
WARNING: Couldn't test self

Thanks,
Pedro Alves

Re: Sporadic failures of selftest tests

[Pedro Alves]

On 10/17/2017 03:40 PM, Pedro Alves wrote:
> On 10/17/2017 03:34 PM, Pedro Alves wrote:
> 
>> Wait, is your build of GDB an optimized build?  Maybe the compiler
>> managed to inline captured_command_loop for you?  Currnetly, when
>> GDB stops for an inline breakpoint, it stops at the stack caller,
>> which would explain this.
> 
> Yup, I can reproduce this with:
> 
> $ rm -f main.o && make CXXFLAGS="-g3 -O2"
> $ make check TESTS="*/complaints.exp"
> [...]
> Running src/gdb/testsuite/gdb.gdb/complaints.exp ...
> FAIL: gdb.gdb/complaints.exp: run until breakpoint at captured_command_loop
> WARNING: Couldn't test self

Ah, and in addition to the wrong function hit, I do also see
the prompt issue then.  Here's what I just saw in a manual run:

(top-gdb) b captured_command_loop
Breakpoint 3 at 0x71ee60: file src/gdb/main.c, line 324.
(top-gdb) r
Starting program: build/gdb/gdb -data-directory=data-directory
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
[New Thread 0x7fffed131700 (LWP 4358)]
[New Thread 0x7fffec930700 (LWP 4359)]
[New Thread 0x7fffec12f700 (LWP 4360)]
[New Thread 0x7fffeb92e700 (LWP 4361)]
[New Thread 0x7fffeb12d700 (LWP 4362)]
[New Thread 0x7fffea92c700 (LWP 4363)]
[New Thread 0x7fffea12b700 (LWP 4364)]
GNU gdb (GDB) 8.0.50.20171017-git
Copyright (C) 2017 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-pc-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word".
(gdb)                  <<<<<< PROMPT HERE
Thread 1 "gdb" hit Breakpoint 3, captured_main (data=<optimized out>) at src/gdb/main.c:1147
1147              captured_command_loop ();
(top-gdb) 

Note the "PROMPT HERE" line.

So indeed, that inferior gdb prompt can confuse gdb_test_multiple.
That prompt is only output in optimized builds, because in that
case, due to inlining, the breakpoint happens to trigger _after_
captured_command_loop prints the prompt...  In non-optimized builds,
the prompt is _not_ output.

Thanks,
Pedro Alves

Re: Sporadic failures of selftest tests

[Ulrich Weigand]

Pedro Alves wrote:
> On 10/17/2017 03:40 PM, Pedro Alves wrote:
> > On 10/17/2017 03:34 PM, Pedro Alves wrote:
> > 
> >> Wait, is your build of GDB an optimized build?  Maybe the compiler
> >> managed to inline captured_command_loop for you?  Currnetly, when
> >> GDB stops for an inline breakpoint, it stops at the stack caller,
> >> which would explain this.
> > 
> > Yup, I can reproduce this with:
> > 
> > $ rm -f main.o && make CXXFLAGS="-g3 -O2"
> > $ make check TESTS="*/complaints.exp"
> > [...]
> > Running src/gdb/testsuite/gdb.gdb/complaints.exp ...
> > FAIL: gdb.gdb/complaints.exp: run until breakpoint at captured_command_loop
> > WARNING: Couldn't test self
> 
> Ah, and in addition to the wrong function hit, I do also see
> the prompt issue then.

Yes, this looks like what I'm seeing.  Note that the wrong function hit
is just an XFAIL, so I didn't notice it (but this is actually what I
get in the "good" case too).

> So indeed, that inferior gdb prompt can confuse gdb_test_multiple.
> That prompt is only output in optimized builds, because in that
> case, due to inlining, the breakpoint happens to trigger _after_
> captured_command_loop prints the prompt...  In non-optimized builds,
> the prompt is _not_ output.

But what confuses me is that in a normal build, GDB by default gets
built with -O2 for me, so I'm wondering why you had to use special
CXXFLAGS above.  Also, I'm wondering why I'm only seeing this now,
when this has apparently been broken all the time.  Just some random
timing issues that are now different for some reason?

Bye,
Ulrich

-- 
  Dr. Ulrich Weigand
  GNU/Linux compilers and toolchain
  Ulrich.Weigand@de.ibm.com

Re: Sporadic failures of selftest tests

[Pedro Alves]

On 10/17/2017 04:47 PM, Ulrich Weigand wrote:

> But what confuses me is that in a normal build, GDB by default gets
> built with -O2 for me, so I'm wondering why you had to use special
> CXXFLAGS above.  

Ah, sorry for not being clearer.  The build tree that I'm using is
configure with explicit CXXFLAGS="-g3 -O0", and so I had to use CXXFLAGS
to override what I had configured with.

> Also, I'm wondering why I'm only seeing this now,
> when this has apparently been broken all the time.  Just some random
> timing issues that are now different for some reason?

Commit bf4692711232 ("Eliminate catch_errors") also did this:

 @@ -1145,7 +1142,15 @@ captured_main (void *data)
       change - SET_TOP_LEVEL() - has been eliminated.  */
    while (1)
      {
 -      catch_errors (captured_command_loop, 0, "", RETURN_MASK_ALL);
 +      TRY
 +       {
 +         captured_command_loop ();
 +       }
 +      CATCH (ex, RETURN_MASK_ALL)
 +       {
 +         exception_print (gdb_stderr, ex);
 +       }
 +      END_CATCH
      }
 
So most probably before that commit captured_command_loop
wasn't inlined in captured main (unless LTO, maybe).

Thanks,
Pedro Alves

Re: Sporadic failures of selftest tests

[Pedro Alves]

On 10/17/2017 04:54 PM, Pedro Alves wrote:

> Commit bf4692711232 ("Eliminate catch_errors") also did this:
> 
>  @@ -1145,7 +1142,15 @@ captured_main (void *data)
>        change - SET_TOP_LEVEL() - has been eliminated.  */
>     while (1)
>       {
>  -      catch_errors (captured_command_loop, 0, "", RETURN_MASK_ALL);
>  +      TRY
>  +       {
>  +         captured_command_loop ();
>  +       }
>  +      CATCH (ex, RETURN_MASK_ALL)
>  +       {
>  +         exception_print (gdb_stderr, ex);
>  +       }
>  +      END_CATCH
>       }
>  
> So most probably before that commit captured_command_loop
> wasn't inlined in captured main (unless LTO, maybe).

Probably the best fix would be to move away from selftest
entirely and convert them to unit tests instead.

Meanwhile, how about this as an easy fix?  We could try
playing games with making functions extern, but maybe
that'd break again with LTO.

Seems to work for gdb.gdb/selftest.exp and gdb.gdb/complaints.exp
at least.

(I think we can use __attribute__ directly because
include/ansidecl.h defines it to empty on non-gcc or
older gccs.)

From: Pedro Alves <palves@redhat.com>
Date: 2017-10-17 15:04:11 +0100

prevent inlining captured_command_loop
---

 gdb/main.c |    5 +++++
 1 file changed, 5 insertions(+)

diff --git a/gdb/main.c b/gdb/main.c
index beb8203..a60cd50 100644
--- a/gdb/main.c
+++ b/gdb/main.c
@@ -307,6 +307,11 @@ setup_alternate_signal_stack (void)
 
 /* Call command_loop.  */
 
+/* Prevent inlining this function for the benefit of gdb's selftests
+   in the testsuite.  Those tests want to run GDB under GDB and stop
+   here.  */
+static void captured_command_loop () __attribute__((noinline));
+
 static void
 captured_command_loop ()
 {

Re: Sporadic failures of selftest tests

[Ulrich Weigand]

Pedro Alves wrote:

> Probably the best fix would be to move away from selftest
> entirely and convert them to unit tests instead.
> 
> Meanwhile, how about this as an easy fix?  We could try
> playing games with making functions extern, but maybe
> that'd break again with LTO.
> 
> Seems to work for gdb.gdb/selftest.exp and gdb.gdb/complaints.exp
> at least.
> 
> (I think we can use __attribute__ directly because
> include/ansidecl.h defines it to empty on non-gcc or
> older gccs.)
> 
> From: Pedro Alves <palves@redhat.com>
> Date: 2017-10-17 15:04:11 +0100
> 
> prevent inlining captured_command_loop

Makes sense to me ...

Thanks,
Ulrich

-- 
  Dr. Ulrich Weigand
  GNU/Linux compilers and toolchain
  Ulrich.Weigand@de.ibm.com

Re: Sporadic failures of selftest tests

[Pedro Alves]

On 10/20/2017 01:51 PM, Ulrich Weigand wrote:
> Pedro Alves wrote:
> 
>> Probably the best fix would be to move away from selftest
>> entirely and convert them to unit tests instead.
>>
>> Meanwhile, how about this as an easy fix?  We could try
>> playing games with making functions extern, but maybe
>> that'd break again with LTO.
>>
>> Seems to work for gdb.gdb/selftest.exp and gdb.gdb/complaints.exp
>> at least.
>>
>> (I think we can use __attribute__ directly because
>> include/ansidecl.h defines it to empty on non-gcc or
>> older gccs.)
>>
>> From: Pedro Alves <palves@redhat.com>
>> Date: 2017-10-17 15:04:11 +0100
>>
>> prevent inlining captured_command_loop
> 
> Makes sense to me ...

Alright, now pushed:
  https://sourceware.org/ml/gdb-patches/2017-10/msg00664.html

Thanks,
Pedro Alves