[Bug libgomp/100352] New: libgomp.fortran/async_io_1.f90 -O0 execution test

[Bug libgomp/100352] New: libgomp.fortran/async_io_1.f90 -O0 execution test

[vries at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=100352

            Bug ID: 100352
           Summary: libgomp.fortran/async_io_1.f90   -O0  execution test
           Product: gcc
           Version: 11.0
            Status: UNCONFIRMED
          Severity: normal
          Priority: P3
         Component: libgomp
          Assignee: unassigned at gcc dot gnu.org
          Reporter: vries at gcc dot gnu.org
                CC: jakub at gcc dot gnu.org
  Target Milestone: ---

On openSUSE Leap 15.2, I see:
...
FAIL: libgomp.fortran/async_io_1.f90   -O0  execution test
FAIL: libgomp.fortran/async_io_1.f90   -O1  execution test
FAIL: libgomp.fortran/async_io_1.f90   -O2  execution test
FAIL: libgomp.fortran/async_io_1.f90   -O3 -fomit-frame-pointer -funroll-loops
-fpeel-loops -ftracer -finline-functions  execution test
FAIL: libgomp.fortran/async_io_1.f90   -O3 -g  execution test
FAIL: libgomp.fortran/async_io_1.f90   -Os  execution test
FAIL: libgomp.fortran/async_io_4.f90   -O0  execution test
FAIL: libgomp.fortran/async_io_4.f90   -O1  execution test
FAIL: libgomp.fortran/async_io_4.f90   -O2  execution test
FAIL: libgomp.fortran/async_io_4.f90   -O3 -fomit-frame-pointer -funroll-loops
-fpeel-loops -ftracer -finline-functions  execution test
FAIL: libgomp.fortran/async_io_4.f90   -O3 -g  execution test
FAIL: libgomp.fortran/async_io_4.f90   -Os  execution test
FAIL: libgomp.fortran/async_io_9.f90   -O0  execution test
FAIL: libgomp.fortran/async_io_9.f90   -O1  execution test
FAIL: libgomp.fortran/async_io_9.f90   -O2  execution test
FAIL: libgomp.fortran/async_io_9.f90   -O3 -fomit-frame-pointer -funroll-loops
-fpeel-loops -ftracer -finline-functions  execution test
FAIL: libgomp.fortran/async_io_9.f90   -O3 -g  execution test
FAIL: libgomp.fortran/async_io_9.f90   -Os  execution test
...

First FAIL in more detail:
...
Execution timeout is: 300
spawn [open ...]^M

Program received signal SIGSEGV: Segmentation fault - invalid memory reference.

Program received signal SIGSEGV: Segmentation fault - invalid memory reference.

Backtrace for this error:

Backtrace for this error:
#0  0x7f8fb4ead49f in ???
#0  0x7f8fb4ead49f in ???
        at
/usr/src/debug/glibc-2.26-lp152.26.6.1.x86_64/signal/../sysdeps/unix/sysv/linux/x8\
6_64/sigaction.c:0
        at
/usr/src/debug/glibc-2.26-lp152.26.6.1.x86_64/signal/../sysdeps/unix/sysv/linux/x8\
6_64/sigaction.c:0
#1  0x7f8fb5243930 in _xend
        at ../sysdeps/unix/sysv/linux/x86/elision-unlock.c:33
#2  0x7f8fb5243930 in __lll_unlock_elision
        at ../sysdeps/unix/sysv/linux/x86/elision-unlock.c:29
#1  0x7f8fb5243930 in _xend
        at ../sysdeps/unix/sysv/linux/x86/elision-unlock.c:33
#2  0x7f8fb5243930 in __lll_unlock_elision
        at ../sysdeps/unix/sysv/linux/x86/elision-unlock.c:29
#3  0x7f8fb5ef1b02 in __gthread_mutex_unlock
        at ../libgcc/gthr-default.h:779
#3  0x7f8fb5ef1b02 in __gthread_mutex_unlock
        at ../libgcc/gthr-default.h:779
#4  0x401331 in ???
#5  0x401c3f in ???
#6  0x7f8fb4e98349 in __libc_start_main
        at ../csu/libc-start.c:308
#7  0x400e79 in ???
        at ../sysdeps/x86_64/start.S:120
#8  0xffffffffffffffff in ???
FAIL: libgomp.fortran/async_io_1.f90   -O0  execution test
...

[Bug libgomp/100352] libgomp.fortran/async_io_1.f90 -O0 execution test

[vries at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=100352

--- Comment #1 from Tom de Vries <vries at gcc dot gnu.org> ---
Build at commit b9bc4467cc7 "tree-optimization/96513 - add testcase for fixed
bug".

Gcc configured like this:
...
$ ./build/gcc/xgcc -v
Using built-in specs.
COLLECT_GCC=./build/gcc/xgcc
Target: x86_64-pc-linux-gnu
Configured with: /home/vries/gcc_versions/devel/src/configure
--disable-bootstrap --enable-languages=c,c++,fortran --disable-multilib
--prefix=/home/vries/gcc_versions/devel/install CFLAGS='-O0 -g -Wall'
CXXFLAGS='-O0 -g -Wall'
Thread model: posix
Supported LTO compression algorithms: zlib zstd
gcc version 12.0.0 20210430 (experimental) (GCC) 
...

[Bug libgomp/100352] libgomp.fortran/async_io_1.f90 -O0 execution test

[vries at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=100352

--- Comment #2 from Tom de Vries <vries at gcc dot gnu.org> ---
More complete backtrace using reproduction on command line:
...
Thread 1 "async_io_1.exe" received signal SIGSEGV, Segmentation fault.
__lll_unlock_elision (lock=0x6069d0, private=0)
    at ../sysdeps/unix/sysv/linux/x86/elision-unlock.c:29
29          _xend();
(gdb) bt
#0  __lll_unlock_elision (lock=0x6069d0, private=0)
    at ../sysdeps/unix/sysv/linux/x86/elision-unlock.c:29
#1  0x00007ffff7b64b03 in __gthread_mutex_unlock (__mutex=0x6069d0)
    at ../libgcc/gthr-default.h:779
#2  0x00007ffff7b65e5c in _gfortrani_unlock_unit (u=0x6068f0)
    at /home/vries/gcc_versions/devel/src/libgfortran/io/unit.c:772
#3  0x00007ffff7b6445e in _gfortran_st_write_done (dtp=0x7fffffffd5e0)
    at /home/vries/gcc_versions/devel/src/libgfortran/io/transfer.c:4496
#4  0x000000000040116a in MAIN__ ()
#5  0x0000000000401af0 in main ()
...

OK, se we're hitting this case: unlocking a free lock:
...
(gdb) l
24      __lll_unlock_elision(int *lock, int private)
25      {
26        /* When the lock was free we're in a transaction.
27           When you crash here you unlocked a free lock.  */
28        if (*lock == 0)
29          _xend();
30        else
31          lll_unlock ((*lock), private);
32        return 0;
33      }
...

[Bug libgomp/100352] libgomp.fortran/async_io_1.f90 -O0 execution test

[vries at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=100352

--- Comment #3 from Tom de Vries <vries at gcc dot gnu.org> ---
Minimal example:
...
program main
  implicit none
  open (10, file='a.dat', asynchronous="yes")
  write (10,*,asynchronous="yes") 4, 3
end program
...

[Bug libgomp/100352] libgomp.fortran/async_io_1.f90 -O0 execution test

[vries at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=100352

--- Comment #4 from Tom de Vries <vries at gcc dot gnu.org> ---
Going through the lock lifetime using backtraces:
...
(gdb) watch ((pthread_mutex_t *) 0x6059d0)->__data.__lock 
Hardware watchpoint 2: ((pthread_mutex_t *) 0x6059d0)->__data.__lock
...

I. Locked from _gfortran_st_open:
...
(gdb) c
Continuing.
Hardware watchpoint 2: ((pthread_mutex_t *) 0x6059d0)->__data.__lock

Old value = 0
New value = 1
0x00007ffff6eb6896 in __lll_lock_elision (futex=0x6059d0,
adapt_count=<optimized out>, 
    private=0) at ../sysdeps/unix/sysv/linux/x86/elision-lock.c:106
106       return LLL_LOCK ((*futex), private);
(gdb) bt
#0  0x00007ffff6eb6896 in __lll_lock_elision (futex=0x6059d0,
adapt_count=<optimized out>, 
    private=0) at ../sysdeps/unix/sysv/linux/x86/elision-lock.c:106
#1  0x00007ffff7b64aaf in __gthread_mutex_lock (__mutex=0x6059d0)
    at ../libgcc/gthr-default.h:749
#2  0x00007ffff7b64e47 in insert_unit (n=10)
    at /home/vries/gcc_versions/devel/src/libgfortran/io/unit.c:244
#3  0x00007ffff7b65128 in get_gfc_unit (n=10, do_create=1)
    at /home/vries/gcc_versions/devel/src/libgfortran/io/unit.c:356
#4  0x00007ffff7b652d8 in _gfortrani_find_or_create_unit (n=10)
    at /home/vries/gcc_versions/devel/src/libgfortran/io/unit.c:421
#5  0x00007ffff7b58941 in _gfortran_st_open (opp=0x7fffffffd630)
    at /home/vries/gcc_versions/devel/src/libgfortran/io/open.c:889
#6  0x00000000004007f1 in MAIN__ ()
#7  0x00000000004008b7 in main ()
...

II. Unlocked from _gfortran_st_open:
...
(gdb) c
Continuing.
[New Thread 0x7ffff66bf700 (LWP 19890)]

Thread 1 "async_io_1.exe" hit Hardware watchpoint 2: ((pthread_mutex_t *)
0x6059d0)->__data.__lock

Old value = 1
New value = 0
0x00007ffff6eb690c in __lll_unlock_elision (lock=0x6059d0, private=0)
    at ../sysdeps/unix/sysv/linux/x86/elision-unlock.c:31
31          lll_unlock ((*lock), private);
(gdb) bt
#0  0x00007ffff6eb690c in __lll_unlock_elision (lock=0x6059d0, private=0)
    at ../sysdeps/unix/sysv/linux/x86/elision-unlock.c:31
#1  0x00007ffff7b64b03 in __gthread_mutex_unlock (__mutex=0x6059d0)
    at ../libgcc/gthr-default.h:779
#2  0x00007ffff7b65e5c in _gfortrani_unlock_unit (u=0x6058f0)
    at /home/vries/gcc_versions/devel/src/libgfortran/io/unit.c:772
#3  0x00007ffff7b58980 in _gfortran_st_open (opp=0x7fffffffd630)
    at /home/vries/gcc_versions/devel/src/libgfortran/io/open.c:894
#4  0x00000000004007f1 in MAIN__ ()
#5  0x00000000004008b7 in main ()
...

III. Locked from _gfortran_st_write:
...
(gdb) c
Continuing.

Thread 1 "async_io_1.exe" hit Hardware watchpoint 2: ((pthread_mutex_t *)
0x6059d0)->__data.__lock

Old value = 0
New value = 1
__lll_trylock_elision (futex=futex@entry=0x6059d0,
adapt_count=adapt_count@entry=0x6059e6)
    at ../sysdeps/unix/sysv/linux/x86/elision-trylock.c:75
75      }
(gdb) bt
#0  __lll_trylock_elision (futex=futex@entry=0x6059d0, 
    adapt_count=adapt_count@entry=0x6059e6)
    at ../sysdeps/unix/sysv/linux/x86/elision-trylock.c:75
#1  0x00007ffff6ead297 in __GI___pthread_mutex_trylock (mutex=0x6059d0)
    at ../nptl/pthread_mutex_trylock.c:71
#2  0x00007ffff7b64ad9 in __gthread_mutex_trylock (__mutex=0x6059d0)
    at ../libgcc/gthr-default.h:758
#3  0x00007ffff7b651d2 in get_gfc_unit (n=10, do_create=1)
    at /home/vries/gcc_versions/devel/src/libgfortran/io/unit.c:380
#4  0x00007ffff7b6588c in _gfortrani_get_unit (dtp=0x7fffffffd630, do_create=1)
    at /home/vries/gcc_versions/devel/src/libgfortran/io/unit.c:576
#5  0x00007ffff7b60d6d in data_transfer_init (dtp=0x7fffffffd630, read_flag=0)
    at /home/vries/gcc_versions/devel/src/libgfortran/io/transfer.c:2851
#6  0x00007ffff7b64154 in _gfortran_st_write (dtp=0x7fffffffd630)
    at /home/vries/gcc_versions/devel/src/libgfortran/io/transfer.c:4410
#7  0x000000000040083f in MAIN__ ()
#8  0x00000000004008b7 in main ()
...

IV: Unlocked from _gfortran_st_write_done:
...
(gdb) c
Continuing.

Thread 1 "async_io_1.exe" hit Hardware watchpoint 2: ((pthread_mutex_t *)
0x6059d0)->__data.__lock

Old value = 1
New value = 0
0x00007ffff6eb690c in __lll_unlock_elision (lock=0x6059d0, private=0)
    at ../sysdeps/unix/sysv/linux/x86/elision-unlock.c:31
31          lll_unlock ((*lock), private);
(gdb) bt
#0  0x00007ffff6eb690c in __lll_unlock_elision (lock=0x6059d0, private=0)
    at ../sysdeps/unix/sysv/linux/x86/elision-unlock.c:31
#1  0x00007ffff7b64b03 in __gthread_mutex_unlock (__mutex=0x6059d0)
    at ../libgcc/gthr-default.h:779
#2  0x00007ffff7b65e5c in _gfortrani_unlock_unit (u=0x6058f0)
    at /home/vries/gcc_versions/devel/src/libgfortran/io/unit.c:772
#3  0x00007ffff7b6445e in _gfortran_st_write_done (dtp=0x7fffffffd630)
    at /home/vries/gcc_versions/devel/src/libgfortran/io/transfer.c:4496
#4  0x0000000000400880 in MAIN__ ()
#5  0x00000000004008b7 in main ()
...

V. Unlocked again, from _gfortrani_st_write_done_worker:
...
(gdb) c
Continuing.

Thread 2 "async_io_1.exe" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7ffff66bf700 (LWP 19890)]
__lll_unlock_elision (lock=0x6059d0, private=0)
    at ../sysdeps/unix/sysv/linux/x86/elision-unlock.c:29
29          _xend();
(gdb) bt
#0  __lll_unlock_elision (lock=0x6059d0, private=0)
    at ../sysdeps/unix/sysv/linux/x86/elision-unlock.c:29
#1  0x00007ffff7b64b03 in __gthread_mutex_unlock (__mutex=0x6059d0)
    at ../libgcc/gthr-default.h:779
#2  0x00007ffff7b65e5c in _gfortrani_unlock_unit (u=0x6058f0)
    at /home/vries/gcc_versions/devel/src/libgfortran/io/unit.c:772
#3  0x00007ffff7b6434e in _gfortrani_st_write_done_worker (dtp=0x608170)
    at /home/vries/gcc_versions/devel/src/libgfortran/io/transfer.c:4466
#4  0x00007ffff7b71a99 in async_io (arg=0x6058f0)
    at /home/vries/gcc_versions/devel/src/libgfortran/io/async.c:120
#5  0x00007ffff6eaa4f9 in start_thread (arg=0x7ffff66bf700) at
pthread_create.c:465
#6  0x00007ffff6be2ecf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:95

[Bug libgomp/100352] libgomp.fortran/async_io_1.f90 -O0 execution test

[vries at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=100352

Tom de Vries <vries at gcc dot gnu.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |burnus at gcc dot gnu.org

--- Comment #5 from Tom de Vries <vries at gcc dot gnu.org> ---
Tobias, could you take a look?

[Bug libgomp/100352] [11/12 Regression] libgomp.fortran/async_io_1.f90 -O0 execution test

[burnus at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=100352

Tobias Burnus <burnus at gcc dot gnu.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
   Last reconfirmed|                            |2021-05-01
   Target Milestone|---                         |11.2
            Summary|libgomp.fortran/async_io_1. |[11/12 Regression]
                   |f90   -O0  execution test   |libgomp.fortran/async_io_1.
                   |                            |f90   -O0  execution test
     Ever confirmed|0                           |1
             Status|UNCONFIRMED                 |NEW

--- Comment #6 from Tobias Burnus <burnus at gcc dot gnu.org> ---
For debugging, it helps:

(a) to compile with -fsanitize=address,undefined
    or (here) -fsanitize=thread
(b) to comment '#undef DEBUG_ASYNC' in libgfortran/io/async.h


Issue introduced for PR99529 in
r11-7647-ga6e9633ccb593937fceec67fafc2afe5d518d735

Patch:

diff --git a/libgfortran/io/async.c b/libgfortran/io/async.c
index d216ace1947..247008ca801 100644
--- a/libgfortran/io/async.c
+++ b/libgfortran/io/async.c
@@ -120 +120 @@ async_io (void *arg)
-                 st_write_done_worker (au->pdt);
+                 st_write_done_worker (au->pdt, false);
@@ -126 +126 @@ async_io (void *arg)
-                 st_read_done_worker (au->pdt);
+                 st_read_done_worker (au->pdt, false);
diff --git a/libgfortran/io/io.h b/libgfortran/io/io.h
index e0007c6bfe5..3355bc2fd8d 100644
--- a/libgfortran/io/io.h
+++ b/libgfortran/io/io.h
@@ -1086 +1086 @@ extern void
-st_write_done_worker (st_parameter_dt *);
+st_write_done_worker (st_parameter_dt *, bool);
@@ -1090 +1090 @@ extern void
-st_read_done_worker (st_parameter_dt *);
+st_read_done_worker (st_parameter_dt *, bool);
diff --git a/libgfortran/io/transfer.c b/libgfortran/io/transfer.c
index 71a935652e3..36e35b48cd3 100644
--- a/libgfortran/io/transfer.c
+++ b/libgfortran/io/transfer.c
@@ -4340 +4340 @@ void
-st_read_done_worker (st_parameter_dt *dtp)
+st_read_done_worker (st_parameter_dt *dtp, bool unlock)
@@ -4370 +4370,2 @@ st_read_done_worker (st_parameter_dt *dtp)
-   unlock_unit (dtp->u.p.current_unit);
+   if (unlock)
+     unlock_unit (dtp->u.p.current_unit);
@@ -4397 +4398 @@ st_read_done (st_parameter_dt *dtp)
-       st_read_done_worker (dtp);  /* Calls unlock_unit.  */
+       st_read_done_worker (dtp, true);  /* Calls unlock_unit.  */
@@ -4415 +4416 @@ void
-st_write_done_worker (st_parameter_dt *dtp)
+st_write_done_worker (st_parameter_dt *dtp, bool unlock)
@@ -4466 +4467,2 @@ st_write_done_worker (st_parameter_dt *dtp)
-   unlock_unit (dtp->u.p.current_unit);
+   if (unlock)
+     unlock_unit (dtp->u.p.current_unit);
@@ -4499 +4501 @@ st_write_done (st_parameter_dt *dtp)
-       st_write_done_worker (dtp);  /* Calls unlock_unit.  */
+       st_write_done_worker (dtp, true);  /* Calls unlock_unit.  */

[Bug libgomp/100352] [11/12 Regression] libgomp.fortran/async_io_1.f90 -O0 execution test

[cvs-commit at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=100352

--- Comment #7 from CVS Commits <cvs-commit at gcc dot gnu.org> ---
The master branch has been updated by Tobias Burnus <burnus@gcc.gnu.org>:

https://gcc.gnu.org/g:a13a50047ef1814a7bda2392f728bf28f81b17ce

commit r12-344-ga13a50047ef1814a7bda2392f728bf28f81b17ce
Author: Tobias Burnus <tobias@codesourcery.com>
Date:   Sun May 2 18:16:17 2021 +0200

    Fortran: Async I/O - avoid unlocked unlocking [PR100352]

    Follow up to PR100352, which moved unit unlocking to st_*_done_worker to
    avoid lock order reversal; however, as async_io uses a different lock,
    the (unlocked locked) unit lock shall not be unlocked there.

    libgfortran/ChangeLog:

            PR libgomp/100352
            * io/transfer.c (st_read_done_worker, st_write_done_worker): Add
new
            arg whether to unlock unit.
            (st_read_done, st_write_done): Call it with true.
            * io/async.c (async_io): Call it with false.
            * io/io.h (st_write_done_worker, st_read_done_worker): Update
prototype.

[Bug libgomp/100352] [11/12 Regression] libgomp.fortran/async_io_1.f90 -O0 execution test

[cvs-commit at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=100352

--- Comment #8 from CVS Commits <cvs-commit at gcc dot gnu.org> ---
The releases/gcc-11 branch has been updated by Tobias Burnus
<burnus@gcc.gnu.org>:

https://gcc.gnu.org/g:107ca5c2fd6dcb53c3cba788ae388e7e4e789ed8

commit r11-8343-g107ca5c2fd6dcb53c3cba788ae388e7e4e789ed8
Author: Tobias Burnus <tobias@codesourcery.com>
Date:   Sun May 2 18:16:17 2021 +0200

    Fortran: Async I/O - avoid unlocked unlocking [PR100352]

    Follow up to PR100352, which moved unit unlocking to st_*_done_worker to
    avoid lock order reversal; however, as async_io uses a different lock,
    the (unlocked locked) unit lock shall not be unlocked there.

    libgfortran/ChangeLog:

            PR libgomp/100352
            * io/transfer.c (st_read_done_worker, st_write_done_worker): Add
new
            arg whether to unlock unit.
            (st_read_done, st_write_done): Call it with true.
            * io/async.c (async_io): Call it with false.
            * io/io.h (st_write_done_worker, st_read_done_worker): Update
prototype.

    (cherry picked from commit a13a50047ef1814a7bda2392f728bf28f81b17ce)

[Bug libgomp/100352] [11/12 Regression] libgomp.fortran/async_io_1.f90 -O0 execution test

[burnus at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=100352

--- Comment #9 from Tobias Burnus <burnus at gcc dot gnu.org> ---
(In reply to CVS Commits from comment #8)
>     Follow up to PR100352,

That's this PR and not the one which caused it. Correct is (comment #6):

> Issue introduced for PR99529 in
> r11-7647-ga6e9633ccb593937fceec67fafc2afe5d518d735

 * * *

Close as FIXED (in GCC 12 and 11).

Thanks for the report! See PR100371 for follow ups.

[Bug libgomp/100352] [11/12 Regression] libgomp.fortran/async_io_1.f90 -O0 execution test

[rguenth at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=100352

Richard Biener <rguenth at gcc dot gnu.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
   Target Milestone|11.2                        |11.3

--- Comment #10 from Richard Biener <rguenth at gcc dot gnu.org> ---
GCC 11.2 is being released, retargeting bugs to GCC 11.3

[Bug libgomp/100352] [11/12 Regression] libgomp.fortran/async_io_1.f90 -O0 execution test

[tkoenig at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=100352

Thomas Koenig <tkoenig at gcc dot gnu.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
         Resolution|---                         |FIXED

--- Comment #11 from Thomas Koenig <tkoenig at gcc dot gnu.org> ---
(In reply to Tobias Burnus from comment #9)

> Close as FIXED (in GCC 12 and 11).
> 
> Thanks for the report! See PR100371 for follow ups.

Really closing :-)