Need some Unix and /bin/sh expertise for GCC testsuite

Need some Unix and /bin/sh expertise for GCC testsuite

[Laurent GUERBY]

Hi,

Even after the last patch I can still see random ACATS failures on a
stock debian etch x86_64 machine (gcc13). I've added many traces to the
ACATS script and I can see now a common pattern and it's not related
to Ada multi threading or wrong code generation.

First the ACATS script itself is relatively straightforward: loop
over the test, copy some files, call gnatmake and then run the
compiled test and check the output.

The issue comes for a surprising - to me - /bin/sh behaviour,
if an /bin/sh expert could help me figure out the following:

=> gcc/testsuite/ada/acats/run_all.sh
<<
#!/bin/sh
# Run ACATS with the GNU Ada compiler
...
target_gnatmake () {
  echo gnatmake --GCC=\"$GCC\" $gnatflags $gccflags $* -largs $EXTERNAL_OBJECTS --GCC=\"$GCC\"
  gnatmake --GCC="$GCC" $gnatflags $gccflags $* -largs $EXTERNAL_OBJECTS --GCC="$GCC"
}
...
while ...
      ...
      target_gnatmake $extraflags -I$dir/support $main >> $dir/acats.log 2>&1
      if [ $? -ne 0 ]; then
         display "FAIL:	$i"
         failed="${failed}${i} "
         clean_dir
         continue
      fi

      echo "RUN $binmain" >> $dir/acats.log
      cd $dir/run

      ZSTAMP=none
      if [ ! -x $dir/tests/$chapter/$i/$binmain ]; then
         sync
         ZSTAMP=$(date '+%Y%m%dT%H%M%S')
         ls -l $dir/tests/$chapter/$i/ > /home/guerby/tmp/acats/postsync-${i}-${ZSTAMP} 2>&1
         ps fauxwwwww > /home/guerby/tmp/acats/psfauxw1-${i}-${ZSTAMP} 2>&1
      fi

      target_run $dir/tests/$chapter/$i/$binmain > $dir/tests/$chapter/$i/${i}.log 2>&1
      ...
>>

Now the common fail pattern is as follows:

1/ target_gnatmake succeeds, that is we don't pass in the first "if".

2/ However even is gnatmake has succeeded we enter the second "if"
because there's no executable in the dir as shown by "ls -l" output:

=> postsync-c48005b-20090813T202815
<<
total 44
-rw-r--r-- 1 guerby guerby 10345 2009-08-13 20:28 b~c48005b.adb
-rw-r--r-- 1 guerby guerby 12375 2009-08-13 20:28 b~c48005b.ads
-rw-r--r-- 1 guerby guerby  2786 2009-08-13 20:28 c48005b.adb
-rw-r--r-- 1 guerby guerby   784 2009-08-13 20:28 c48005b.ali
-rw-r--r-- 1 guerby guerby    12 2009-08-13 20:28 c48005b.lst
-rw-r--r-- 1 guerby guerby  3208 2009-08-13 20:28 c48005b.o
>>

3/ Here is the point I find surprising: the "ps fauxww" run in the
second "if" show that even if the script is fully sequential
at least one gnatmake subprocess (collect-ld) is still marked as running 
*in parallel* with the ps command in the subsequent "if" of the script!

=> psfauxw1-c48005b-20090813T202815
<<
...
guerby    7715  1.3  0.0  12176  1936 ?        SN   20:20   0:06   \_ /bin/sh /home/guerby/trunk/gcc/testsuite/ada/acats/run_all.sh
guerby    7794  0.0  0.0  10796  2476 ?        SN   20:28   0:00       \_ gnatmake --GCC=/home/guerby/build/gcc/xgcc -B/home/guerby/build/gcc/ -gnatws -O2 -I/home/guerby/build/gcc/testsuite/ada/acats/support c48005b.adb -largs --GCC=/home/guerby/build/gcc/xgcc -B/home/guerby/build/gcc/
guerby    7803  0.0  0.0   4048  1228 ?        SN   20:28   0:00       |   \_ /home/guerby/build/gcc/gnatlink c48005b.ali --GCC=/home/guerby/build/gcc/xgcc -B/home/guerby/build/gcc/
guerby    7809  0.0  0.0   2880   584 ?        SN   20:28   0:00       |       \_ /home/guerby/build/gcc/xgcc b~c48005b.o ... -o c48005b ...
guerby    7810  0.0  0.0   2756   444 ?        SN   20:28   0:00       |           \_ /home/guerby/build/gcc/collect2 --eh-frame-hdr -m elf_x86_64 -dynamic-linker /lib64/ld-linux-x86-64.so.2 -o c48005b ...
guerby    7811  0.0  0.0  11548  1500 ?        RN   20:28   0:00       |               \_ /bin/sh /home/guerby/build/gcc/collect-ld --eh-frame-hdr -m elf_x86_64 -dynamic-linker /lib64/ld-linux-x86-64.so.2 -o c48005b ....
guerby    7808  0.0  0.0  14328  1156 ?        RN   20:28   0:00       \_ ps fauxwwwww
...
>>

4/ we run the executable but since it's not there we get:

=> c48005b.log
<<
/home/guerby/trunk/gcc/testsuite/ada/acats/run_all.sh: line 16: /home/guerby/build/gcc/testsuite/ada/acats/tests/c4/c48005b/c48005b: Permission denied
>>

5/ After the run an empty file appears in another "ls -l" 
(not shown in the script above):

-rw-r--r-- 1 guerby guerby     0 2009-08-13 20:28 c48005b

6/ Waiting for one more second ("sleep 1" not shown above) the 
full file appears at last in "ls -l":

-rwxr-xr-x 1 guerby guerby 1164960 2009-08-13 20:28 c48005b

Any idea of why /bin/sh is running stuff in parallel instead
of sequential? 

Could some code in 
gnatmake/gnatlink/xgcc/collect2/collect-ld cause it?

guerby@gcc13:~$ /bin/sh --version
GNU bash, version 3.1.17(1)-release (x86_64-pc-linux-gnu)

Thanks in advance,

Laurent

Re: Need some Unix and /bin/sh expertise for GCC testsuite

[Dave Korn]

Laurent GUERBY wrote:

> 3/ Here is the point I find surprising: the "ps fauxww" run in the
> second "if" show that even if the script is fully sequential
> at least one gnatmake subprocess (collect-ld) is still marked as running 
> *in parallel* with the ps command in the subsequent "if" of the script!

> Any idea of why /bin/sh is running stuff in parallel instead
> of sequential? 
> 
> Could some code in 
> gnatmake/gnatlink/xgcc/collect2/collect-ld cause it?

  I notice gnatmake.adb has a reference to GNAT.OS_Lib.Non_Blocking_Spawn in
it.... coincidence?

    cheers,
      DaveK

Re: Need some Unix and /bin/sh expertise for GCC testsuite

[Laurent GUERBY]

On Fri, 2009-08-14 at 22:19 +0100, Dave Korn wrote:
> Laurent GUERBY wrote:
> 
> > 3/ Here is the point I find surprising: the "ps fauxww" run in the
> > second "if" show that even if the script is fully sequential
> > at least one gnatmake subprocess (collect-ld) is still marked as running 
> > *in parallel* with the ps command in the subsequent "if" of the script!
> 
> > Any idea of why /bin/sh is running stuff in parallel instead
> > of sequential? 
> > 
> > Could some code in 
> > gnatmake/gnatlink/xgcc/collect2/collect-ld cause it?
> 
>   I notice gnatmake.adb has a reference to GNAT.OS_Lib.Non_Blocking_Spawn in
> it.... coincidence?

gnatmake uses Non_Blocking_Spawn to call the compiler (gnatmake supports
"-j N" like make), but for the gnatlink call (we see in the "ps fauxww")
it uses in gcc/ada/make.adb:

   procedure Link
...
      GNAT.OS_Lib.Spawn (Gnatlink_Path.all, Link_Args, Success);
   end Link;

which ends up calling gcc/ada/s-os_lib.adb

      Spawn_Internal (Program_Name, Args, Result, Junk, Blocking =>
True);
...
         function Portable_Spawn (Args : Address) return Integer;
         pragma Import (C, Portable_Spawn, "__gnat_portable_spawn");

which ends up calling in gcc/ada/adaint.c:

int
__gnat_portable_spawn (char *args[])
...
  pid = fork ();
  if (pid < 0)
    return -1;

  if (pid == 0)
    {
      /* The child. */
      if (execv (args[0], MAYBE_TO_PTR32 (args)) != 0)
	_exit (1);
    }

  /* The parent.  */
  finished = waitpid (pid, &status, 0);

  if (finished != pid || WIFEXITED (status) == 0)
    return -1;

  return WEXITSTATUS (status);
}

Thanks for your help :).

Laurent

Re: Need some Unix and /bin/sh expertise for GCC testsuite

[Dave Korn]

Laurent GUERBY wrote:

> gnatmake uses Non_Blocking_Spawn to call the compiler (gnatmake supports
> "-j N" like make), but for the gnatlink call (we see in the "ps fauxww")
> it uses in gcc/ada/make.adb:
> 
>    procedure Link
> ...
>       GNAT.OS_Lib.Spawn (Gnatlink_Path.all, Link_Args, Success);
>    end Link;
> 
> which ends up calling gcc/ada/s-os_lib.adb
> 
>       Spawn_Internal (Program_Name, Args, Result, Junk, Blocking =>
> True);
> ...
>          function Portable_Spawn (Args : Address) return Integer;
>          pragma Import (C, Portable_Spawn, "__gnat_portable_spawn");
> 
> which ends up calling in gcc/ada/adaint.c:
> 
> int
> __gnat_portable_spawn (char *args[])
> ...
>   pid = fork ();
>   if (pid < 0)
>     return -1;
> 
>   if (pid == 0)
>     {
>       /* The child. */
>       if (execv (args[0], MAYBE_TO_PTR32 (args)) != 0)
> 	_exit (1);
>     }
> 
>   /* The parent.  */
>   finished = waitpid (pid, &status, 0);
> 
>   if (finished != pid || WIFEXITED (status) == 0)
>     return -1;
> 
>   return WEXITSTATUS (status);
> }

  Hmpf.  That seems to rule out that theory.  Gnatlink is still spawning the
gcc driver to link, rather than the linker itself; maybe the driver's doing
something wrong?  Is collect-ld a shell script or an executable on your host?

    cheers,
      DaveK

Re: Need some Unix and /bin/sh expertise for GCC testsuite

[Laurent GUERBY]

On Sat, 2009-08-15 at 01:37 +0100, Dave Korn wrote:
>   Hmpf.  That seems to rule out that theory.  Gnatlink is still spawning the
> gcc driver to link, rather than the linker itself; maybe the driver's doing
> something wrong?  Is collect-ld a shell script or an executable on your host?

It's a script that appears in the build/gcc directory:

$ file /home/guerby/build/gcc/collect-ld 
/home/guerby/build/gcc/collect-ld: Bourne shell script text executable

Thanks for your help,

Laurent

Re: Need some Unix and /bin/sh expertise for GCC testsuite

[Ralf Wildenhues]

Hello,

* Laurent GUERBY wrote on Fri, Aug 14, 2009 at 10:52:35PM CEST:
> => gcc/testsuite/ada/acats/run_all.sh

> 3/ Here is the point I find surprising: the "ps fauxww" run in the
> second "if" show that even if the script is fully sequential
> at least one gnatmake subprocess (collect-ld) is still marked as running 
> *in parallel* with the ps command in the subsequent "if" of the script!

One thing I see in that script is there is a line
  rm -rf $dir/tests.$$ &

that will be run "in parallel" due to the stray "&".  However, I also
don't see at least parts of the rest of the script that you quote, so
maybe I'm looking at the wrong version (looking at trunk) or you have
added debug statements, so maybe yours has more such stray asynchronous
lists.

Hope that helps.

Cheers,
Ralf

Re: Need some Unix and /bin/sh expertise for GCC testsuite

[Laurent GUERBY]

On Fri, 2009-08-14 at 23:25 +0200, Ralf Wildenhues wrote:
> Hello,
> 
> * Laurent GUERBY wrote on Fri, Aug 14, 2009 at 10:52:35PM CEST:
> > => gcc/testsuite/ada/acats/run_all.sh
> 
> > 3/ Here is the point I find surprising: the "ps fauxww" run in the
> > second "if" show that even if the script is fully sequential
> > at least one gnatmake subprocess (collect-ld) is still marked as running 
> > *in parallel* with the ps command in the subsequent "if" of the script!
> 
> One thing I see in that script is there is a line
>   rm -rf $dir/tests.$$ &
> 
> that will be run "in parallel" due to the stray "&".  

This one is part of initialization done once well before the loop over
the tests, so I don't think it can interfere in any way (and my
"ps fauxww" log doesn't show it around).

> However, I also
> don't see at least parts of the rest of the script that you quote, so
> maybe I'm looking at the wrong version (looking at trunk) or you have
> added debug statements, so maybe yours has more such stray asynchronous
> lists.

Yes my quote is from my heavily instrumented run_all.sh. 

The svn clean run_all.sh will exhibit the random fail with the very same
error message in gcc/testsuite/ada/acats/acats.log so the
instrumentation doesn't change the failure mode.

Thanks for your help,

Laurent

Re: Need some Unix and /bin/sh expertise for GCC testsuite

[Ralf Wildenhues]

> > * Laurent GUERBY wrote on Fri, Aug 14, 2009 at 10:52:35PM CEST:
> > > => gcc/testsuite/ada/acats/run_all.sh
> > 
> > > 3/ Here is the point I find surprising: the "ps fauxww" run in the
> > > second "if" show that even if the script is fully sequential
> > > at least one gnatmake subprocess (collect-ld) is still marked as running 
> > > *in parallel* with the ps command in the subsequent "if" of the script!

Sounds like http://thread.gmane.org/gmane.comp.shells.bash.bugs/11990
and the NEWS for bash-3.2 contains this entry:

l.  Several fixes to the code that manages the list of terminated jobs and
    their exit statuses, and the list of active and recently-terminated jobs
    to avoid pid aliasing/wraparound and allocation errors.

I'd try out a newer bash version.

Cheers,
Ralf

Re: Need some Unix and /bin/sh expertise for GCC testsuite

[Laurent GUERBY]

On Sat, 2009-08-15 at 07:53 +0200, Ralf Wildenhues wrote:
> > > * Laurent GUERBY wrote on Fri, Aug 14, 2009 at 10:52:35PM CEST:
> > > > => gcc/testsuite/ada/acats/run_all.sh
> > > 
> > > > 3/ Here is the point I find surprising: the "ps fauxww" run in the
> > > > second "if" show that even if the script is fully sequential
> > > > at least one gnatmake subprocess (collect-ld) is still marked as running 
> > > > *in parallel* with the ps command in the subsequent "if" of the script!
> 
> Sounds like http://thread.gmane.org/gmane.comp.shells.bash.bugs/11990
> and the NEWS for bash-3.2 contains this entry:
> 
> l.  Several fixes to the code that manages the list of terminated jobs and
>     their exit statuses, and the list of active and recently-terminated jobs
>     to avoid pid aliasing/wraparound and allocation errors.
> 
> I'd try out a newer bash version.

Good catch! The script shown in the discussion is just like mine and the
order of magnitude of occurrence is the same.

Since upgrading bash will not be an option for everyone, I will propose
a patch that "sleep" a bit if gnatmake succeeds and the executable is
still not present or empty, I'm testing:

      # workaround bash process management bug
      trycount=0
      while [ $trycount -le 30 ]; do
          trycount=$(expr $trycount + 1)
          if [ -s $dir/tests/$chapter/$i/$binmain -a -x $dir/tests/$chapter/$i/$binmain ]; then
             break
          else
             sleep 1
          fi
      done

Thanks again for your help,

Laurent

Re: Need some Unix and /bin/sh expertise for GCC testsuite

[Andreas Schwab]

Laurent GUERBY <laurent@guerby.net> writes:

> Any idea of why /bin/sh is running stuff in parallel instead
> of sequential? 

Have you tried set -x?

Andreas.

-- 
Andreas Schwab, schwab@linux-m68k.org
GPG Key fingerprint = 58CA 54C7 6D53 942B 1756  01D3 44D5 214B 8276 4ED5
"And now for something completely different."

Re: Need some Unix and /bin/sh expertise for GCC testsuite

[Laurent GUERBY]

On Fri, 2009-08-14 at 23:36 +0200, Andreas Schwab wrote:
> Laurent GUERBY <laurent@guerby.net> writes:
> 
> > Any idea of why /bin/sh is running stuff in parallel instead
> > of sequential? 
> 
> Have you tried set -x?

IIRC I tried at first but it didn't gave me useful information,
everything looked "normal", then I switched to more invasive
logging including three "ps fauxww" and "ls -l".

On the statistical side over the past three monthes there were 17
occurrences of this issue:

-rw-r--r-- 1 guerby guerby  29623 2009-05-21 18:05 psfauxw1-c48004d-20090521T180512
-rw-r--r-- 1 guerby guerby  36904 2009-05-21 22:57 psfauxw1-d4a002b-20090521T225738
-rw-r--r-- 1 guerby guerby  31810 2009-05-23 21:45 psfauxw1-d4a002b-20090523T214538
-rw-r--r-- 1 guerby guerby  29774 2009-05-29 05:15 psfauxw1-d4a002b-20090529T051533
-rw-r--r-- 1 guerby guerby  30467 2009-07-02 17:06 psfauxw1-cxaa005-20090702T170643
-rw-r--r-- 1 guerby guerby  64559 2009-07-03 08:15 psfauxw1-cxaa017-20090703T081509
-rw-r--r-- 1 guerby guerby  30227 2009-07-03 13:13 psfauxw1-d4a002a-20090703T131307
-rw-r--r-- 1 guerby guerby  30280 2009-07-03 22:43 psfauxw1-cb3003a-20090703T224359
-rw-r--r-- 1 guerby guerby  29442 2009-07-12 03:57 psfauxw1-cb1001a-20090712T035707
-rw-r--r-- 1 guerby guerby  30361 2009-07-23 03:33 psfauxw1-cb20a02-20090723T033340
-rw-r--r-- 1 guerby guerby  30361 2009-07-23 03:42 psfauxw1-cz1103a-20090723T034235
-rw-r--r-- 1 guerby guerby  30443 2009-07-27 01:02 psfauxw1-c48004d-20090727T010248
-rw-r--r-- 1 guerby guerby  30112 2009-07-30 02:03 psfauxw1-cz1102a-20090730T020304
-rw-r--r-- 1 guerby guerby  34507 2009-08-02 04:34 psfauxw1-cd1009o-20090802T043428
-rw-r--r-- 1 guerby guerby  37807 2009-08-08 11:08 psfauxw1-d4a002a-20090808T110858
-rw-r--r-- 1 guerby guerby  38340 2009-08-09 16:52 psfauxw1-c48004d-20090809T165214
-rw-r--r-- 1 guerby guerby  38319 2009-08-13 20:28 psfauxw1-c48005b-20090813T202815

Since the machine runs on average 5 bootstrap+check a day and that ACATS
has 2315 tests, it's a rate of failure of ~ 17 per one million individual test run.
But it's at least one spurious FAIL in about 4% of bootstrap+check.

Laurent