Re: qemu-arm-static under amd64: example of stuck looping atomic_cmpset_int while building graphics/poppler-qt5 [problem not found]

2019-01-01 Thread Mark Millard via freebsd-ports
[I was wrong: it is code elimination, not motion. volatile is
not a fix.]

On 2019-Jan-1, at 19:37, Mark Millard  wrote:

> [It looks to me like the assembler code has some code moved out of the
> loop that it should not be (by intent). It appears that calling
> tcmpset_32 does not prevent code motion to before the call and
> the variable involved was not declared volatile.]
> 
> On 2019-Jan-1, at 18:43, Mark Millard  wrote:
> 
>> The below showed up for poudiere-devel bulk getting stuck using one FreeBSD
>> cpu while building graphics/poppler-qt5 . This is not a kevent hang-up, 
>> unlike
>> the last hang-up that I analyzed. I do not yet know how repeatable this is
>> but the original hang-up and the one experiment the below is from.
>> 
>> From top:
>> 
>> PID USERNAMETHR PRI NICE   SIZERES SWAP STATEC   TIME CPU 
>> COMMAND
>> 12789 root  4  520   166M33M0 uwait6  36:06  97.22% 
>> /usr/local/bin/qemu-arm-static /usr/local/bin/cmake -E cmake_autogen 
>> /wrkdirs/usr/ports/graphics/poppler-qt5/work/poppler-0
>> 
>> Note: The vast margority of the 36:06 has been stuck in the uwait loop 
>> involved.
>> 
>> From ps -auxd:
>> 
>> root   940750.0  0.0  12932  3552  1  S+   10:420:01.21 |
>>`-- sh -e /usr/local/share/poudriere/bulk.sh -jFBSDFSSDjailArmV7 -w 
>> graphics/poppler-qt5
>> root19440.0  0.0  12932  3540  1  I+   10:420:00.00 |
>>  |-- sh -e /usr/local/share/poudriere/bulk.sh -jFBSDFSSDjailArmV7 -w 
>> graphics/poppler-qt5
>> root19570.0  0.0  12932  3556  1  I10:420:00.04 |
>>  |-- sh: poudriere[FBSDFSSDjailArmV7-default][01]: build_pkg 
>> (poppler-qt5-0.72.0) (sh)
>> root   123280.0  0.0  12932  3548  1  I10:490:00.00 |
>>  | `-- sh: poudriere[FBSDFSSDjailArmV7-default][01]: build_pkg 
>> (poppler-qt5-0.72.0) (sh)
>> root   123290.0  0.0  10328  1756  1  IJ   10:490:00.01 |
>>  |   `-- /usr/bin/make -C /usr/ports/graphics/poppler-qt5 stage
>> root   123500.0  0.0   9860  1248  1  IJ   10:490:00.00 |
>>  | `-- /usr/bin/make -f Makefile 
>> DESTDIR=/wrkdirs/usr/ports/graphics/poppler-qt5/work/stage install
>> root   123530.0  0.0  10236  1664  1  IJ   10:490:00.05 |
>>  |   `-- /nxb-bin/usr/bin/make -f CMakeFiles/Makefile2 qt5/all
>> root   127870.0  0.0   9856  1236  1  IJ   10:500:00.00 |
>>  | `-- /nxb-bin/usr/bin/make -f 
>> qt5/tests/CMakeFiles/check_qt5_attachments_autogen.dir/build.make qt5/test
>> root   12789  100.0  0.0 169868 33528  1  IJ   10:50   36:35.26 |
>>  |   `-- /usr/local/bin/qemu-arm-static /usr/local/bin/cmake 
>> -E cmake_autogen /wrkdirs/usr/ports/graphics/
>> root   944230.0  0.0  12932  3484  1  S+   10:420:12.91 |
>>  `-- sh -e /usr/local/share/poudriere/bulk.sh -jFBSDFSSDjailArmV7 -w 
>> graphics/poppler-qt5
>> 
>> 
>> (gdb) attach 12789
>> Attaching to process 12789
>> Reading symbols from 
>> /usr/local/poudriere/data/.m/FBSDFSSDjailArmV7-default/01/usr/local/bin/qemu-arm-static...done.
>> [New LWP 101168 of process 12789]
>> [New LWP 101178 of process 12789]
>> [New LWP 101499 of process 12789]
>> [Switching to LWP 100304 of process 12789]
>> _umtx_op () at _umtx_op.S:3
>> 3RSYSCALL(_umtx_op)
>> (gdb) info threads
>> Id   Target Id   Frame 
>> * 1LWP 100304 of process 12789 _umtx_op () at _umtx_op.S:3
>> 2LWP 101168 of process 12789 _umtx_op_err () at 
>> /usr/src/lib/libthr/arch/amd64/amd64/_umtx_op_err.S:37
>> 3LWP 101178 of process 12789 _umtx_op () at _umtx_op.S:3
>> 4LWP 101499 of process 12789 0x60051c26 in atomic_cmpset_int 
>> (dst=, expect=, src=536870912) at 
>> /usr/include/machine/atomic.h:220
>> (gdb) thread 4
>> [Switching to thread 4 (LWP 101499 of process 12789)]
>> #0  0x60051c26 in atomic_cmpset_int (dst=, 
>> expect=, src=536870912) at /usr/include/machine/atomic.h:220
>> 220  ATOMIC_CMPSET(int);
>> 
>> (gdb) bt
>> #0  0x60051c26 in atomic_cmpset_int (dst=, 
>> expect=, src=536870912) at /usr/include/machine/atomic.h:220
>> #1  tcmpset_32 (addr=, a=, b=536870912) at 
>> /wrkdirs/usr/ports/emulators/qemu-user-static/work/qemu-bsd-user-4ef7d07/bsd-user/freebsd/os-thread.c:178
>> #2  freebsd_rw_unlock (target_addr=4108246528) at 
>> /wrkdirs/usr/ports/emulators/qemu-user-static/work/qemu-bsd-user-4ef7d07/bsd-user/freebsd/os-thread.c:1264
>> #3  0x6004ab33 in do_freebsd__umtx_op (obj=, 
>> op=536870912, val=, uaddr=, 
>> target_time=)
>>   at 
>> /wrkdirs/usr/ports/emulators/qemu-user-static/work/qemu-bsd-user-4ef7d07/bsd-user/freebsd/os-thread.h:474
>> #4  0x60041b83 in do_freebsd_syscall (cpu_env=0x86159b118, num=454, 
>> arg1=, arg2=, arg3=, arg4=0, 
>> arg5=0, arg6=-184411592, arg7=-199471616, 
>>   arg8=-1622188640) at 
>> 

Re: qemu-arm-static under amd64: example of stuck looping atomic_cmpset_int while building graphics/poppler-qt5 [problem possibly found]

2019-01-01 Thread Mark Millard via freebsd-ports
[It looks to me like the assembler code has some code moved out of the
loop that it should not be (by intent). It appears that calling
tcmpset_32 does not prevent code motion to before the call and
the variable involved was not declared volatile.]

On 2019-Jan-1, at 18:43, Mark Millard  wrote:

> The below showed up for poudiere-devel bulk getting stuck using one FreeBSD
> cpu while building graphics/poppler-qt5 . This is not a kevent hang-up, unlike
> the last hang-up that I analyzed. I do not yet know how repeatable this is
> but the original hang-up and the one experiment the below is from.
> 
> From top:
> 
>  PID USERNAMETHR PRI NICE   SIZERES SWAP STATEC   TIME CPU 
> COMMAND
> 12789 root  4  520   166M33M0 uwait6  36:06  97.22% 
> /usr/local/bin/qemu-arm-static /usr/local/bin/cmake -E cmake_autogen 
> /wrkdirs/usr/ports/graphics/poppler-qt5/work/poppler-0
> 
> Note: The vast margority of the 36:06 has been stuck in the uwait loop 
> involved.
> 
> From ps -auxd:
> 
> root   940750.0  0.0  12932  3552  1  S+   10:420:01.21 | 
>   `-- sh -e /usr/local/share/poudriere/bulk.sh -jFBSDFSSDjailArmV7 -w 
> graphics/poppler-qt5
> root19440.0  0.0  12932  3540  1  I+   10:420:00.00 | 
> |-- sh -e /usr/local/share/poudriere/bulk.sh -jFBSDFSSDjailArmV7 -w 
> graphics/poppler-qt5
> root19570.0  0.0  12932  3556  1  I10:420:00.04 | 
> |-- sh: poudriere[FBSDFSSDjailArmV7-default][01]: build_pkg 
> (poppler-qt5-0.72.0) (sh)
> root   123280.0  0.0  12932  3548  1  I10:490:00.00 | 
> | `-- sh: poudriere[FBSDFSSDjailArmV7-default][01]: build_pkg 
> (poppler-qt5-0.72.0) (sh)
> root   123290.0  0.0  10328  1756  1  IJ   10:490:00.01 | 
> |   `-- /usr/bin/make -C /usr/ports/graphics/poppler-qt5 stage
> root   123500.0  0.0   9860  1248  1  IJ   10:490:00.00 | 
> | `-- /usr/bin/make -f Makefile 
> DESTDIR=/wrkdirs/usr/ports/graphics/poppler-qt5/work/stage install
> root   123530.0  0.0  10236  1664  1  IJ   10:490:00.05 | 
> |   `-- /nxb-bin/usr/bin/make -f CMakeFiles/Makefile2 qt5/all
> root   127870.0  0.0   9856  1236  1  IJ   10:500:00.00 | 
> | `-- /nxb-bin/usr/bin/make -f 
> qt5/tests/CMakeFiles/check_qt5_attachments_autogen.dir/build.make qt5/test
> root   12789  100.0  0.0 169868 33528  1  IJ   10:50   36:35.26 | 
> |   `-- /usr/local/bin/qemu-arm-static /usr/local/bin/cmake 
> -E cmake_autogen /wrkdirs/usr/ports/graphics/
> root   944230.0  0.0  12932  3484  1  S+   10:420:12.91 | 
> `-- sh -e /usr/local/share/poudriere/bulk.sh -jFBSDFSSDjailArmV7 -w 
> graphics/poppler-qt5
> 
> 
> (gdb) attach 12789
> Attaching to process 12789
> Reading symbols from 
> /usr/local/poudriere/data/.m/FBSDFSSDjailArmV7-default/01/usr/local/bin/qemu-arm-static...done.
> [New LWP 101168 of process 12789]
> [New LWP 101178 of process 12789]
> [New LWP 101499 of process 12789]
> [Switching to LWP 100304 of process 12789]
> _umtx_op () at _umtx_op.S:3
> 3 RSYSCALL(_umtx_op)
> (gdb) info threads
>  Id   Target Id   Frame 
> * 1LWP 100304 of process 12789 _umtx_op () at _umtx_op.S:3
>  2LWP 101168 of process 12789 _umtx_op_err () at 
> /usr/src/lib/libthr/arch/amd64/amd64/_umtx_op_err.S:37
>  3LWP 101178 of process 12789 _umtx_op () at _umtx_op.S:3
>  4LWP 101499 of process 12789 0x60051c26 in atomic_cmpset_int 
> (dst=, expect=, src=536870912) at 
> /usr/include/machine/atomic.h:220
> (gdb) thread 4
> [Switching to thread 4 (LWP 101499 of process 12789)]
> #0  0x60051c26 in atomic_cmpset_int (dst=, 
> expect=, src=536870912) at /usr/include/machine/atomic.h:220
> 220   ATOMIC_CMPSET(int);
> 
> (gdb) bt
> #0  0x60051c26 in atomic_cmpset_int (dst=, 
> expect=, src=536870912) at /usr/include/machine/atomic.h:220
> #1  tcmpset_32 (addr=, a=, b=536870912) at 
> /wrkdirs/usr/ports/emulators/qemu-user-static/work/qemu-bsd-user-4ef7d07/bsd-user/freebsd/os-thread.c:178
> #2  freebsd_rw_unlock (target_addr=4108246528) at 
> /wrkdirs/usr/ports/emulators/qemu-user-static/work/qemu-bsd-user-4ef7d07/bsd-user/freebsd/os-thread.c:1264
> #3  0x6004ab33 in do_freebsd__umtx_op (obj=, 
> op=536870912, val=, uaddr=, 
> target_time=)
>at 
> /wrkdirs/usr/ports/emulators/qemu-user-static/work/qemu-bsd-user-4ef7d07/bsd-user/freebsd/os-thread.h:474
> #4  0x60041b83 in do_freebsd_syscall (cpu_env=0x86159b118, num=454, 
> arg1=, arg2=, arg3=, arg4=0, 
> arg5=0, arg6=-184411592, arg7=-199471616, 
>arg8=-1622188640) at 
> /wrkdirs/usr/ports/emulators/qemu-user-static/work/qemu-bsd-user-4ef7d07/bsd-user/syscall.c:1364
> #5  0x600392f0 in target_cpu_loop (env=0x86159b118) at 
>