[Qemu-devel] intermittent make check failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Qemu-devel] intermittent make check failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Peter Maydell]

I got a make check failure on aarch64 host running a sparc64 test:


TEST: tests/prom-env-test... (pid=13573)
  /sparc64/prom-env/sun4u:                                             **
ERROR:/home/pm215/qemu/translate-common.c:34:tcg_handle_interrupt:
assertion failed: (qemu_mutex_iothread_locked())
Broken pipe
FAIL
GTester: last random seed: R02Sa5fa983185fe5e65cfb5b7fcb39ed3d1
(pid=13579)
FAIL: tests/prom-env-test

This is with commit 9514f2648ca05b3.

It didn't reproduce on a rerun of 'make check' and it didn't
look like the merge in question was particularly relevant to
the failure, so I went ahead and pushed it to master.

I'm (perhaps unfairly) assuming that this is fallout from MTTCG
landing. (prom-env-test is one of the handful of tests in
'make check' that actually runs TCG code.)

thanks
-- PMM

Re: [Qemu-devel] intermittent make check failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Thomas Huth]

On 28.02.2017 20:10, Peter Maydell wrote:
> I got a make check failure on aarch64 host running a sparc64 test:
> 
> TEST: tests/prom-env-test... (pid=13573)
>   /sparc64/prom-env/sun4u:                                             **
> ERROR:/home/pm215/qemu/translate-common.c:34:tcg_handle_interrupt:
> assertion failed: (qemu_mutex_iothread_locked())
> Broken pipe
> FAIL
> GTester: last random seed: R02Sa5fa983185fe5e65cfb5b7fcb39ed3d1
> (pid=13579)
> FAIL: tests/prom-env-test
> 
> This is with commit 9514f2648ca05b3.
> 
> It didn't reproduce on a rerun of 'make check' and it didn't
> look like the merge in question was particularly relevant to
> the failure, so I went ahead and pushed it to master.
> 
> I'm (perhaps unfairly) assuming that this is fallout from MTTCG
> landing. (prom-env-test is one of the handful of tests in
> 'make check' that actually runs TCG code.)

Maybe worth mentioning that the prom-env test for sparc64 has just been
enabled a couple of commits ago (6b591ad613010f13). There was an issue
with that test for the sparc64 target last year, but IIRC it only
affected 32-bit hosts and has been fixed, so I think/hope this is a
different issue now...

 Thomas

Re: [Qemu-devel] intermittent make check failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Kevin Wolf]

Am 28.02.2017 um 20:10 hat Peter Maydell geschrieben:
> I got a make check failure on aarch64 host running a sparc64 test:

Probably completely unrelated, but while we're at it...

For me, tests/vhost-user-test has been hanging for check-qtest-i386
occasionally in the past few days. Has anyone else seen this?

Kevin

Re: [Qemu-devel] intermittent make check failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Thomas Huth]

On 28.02.2017 20:30, Thomas Huth wrote:
> On 28.02.2017 20:10, Peter Maydell wrote:
>> I got a make check failure on aarch64 host running a sparc64 test:
>>
>> TEST: tests/prom-env-test... (pid=13573)
>>   /sparc64/prom-env/sun4u:                                             **
>> ERROR:/home/pm215/qemu/translate-common.c:34:tcg_handle_interrupt:
>> assertion failed: (qemu_mutex_iothread_locked())
>> Broken pipe
>> FAIL
>> GTester: last random seed: R02Sa5fa983185fe5e65cfb5b7fcb39ed3d1
>> (pid=13579)
>> FAIL: tests/prom-env-test
>>
>> This is with commit 9514f2648ca05b3.
>>
>> It didn't reproduce on a rerun of 'make check' and it didn't
>> look like the merge in question was particularly relevant to
>> the failure, so I went ahead and pushed it to master.
>>
>> I'm (perhaps unfairly) assuming that this is fallout from MTTCG
>> landing. (prom-env-test is one of the handful of tests in
>> 'make check' that actually runs TCG code.)
> 
> Maybe worth mentioning that the prom-env test for sparc64 has just been
> enabled a couple of commits ago (6b591ad613010f13). There was an issue
> with that test for the sparc64 target last year, but IIRC it only
> affected 32-bit hosts and has been fixed, so I think/hope this is a
> different issue now...

OK, I think this is definitively not related to the prom-env test, but
to MTTCG (or something else in TCG): I can reproduce this problem
reliably when I run QEMU in s390 mode with the Moon Buggy disk image
from the QEMU advent calendar
(http://www.qemu-advent-calendar.org/2014/download/s390-moon-buggy.tar.xz):

qemu-system-s390x -nographic -kernel s390-bb.kernel \
                  -initrd s390-moon-buggy.initrd

... starts the kernel, but aborts very soon with:

ERROR:qemu/translate-common.c:34:tcg_handle_interrupt: assertion failed:
(qemu_mutex_iothread_locked())
Aborted (core dumped)

 Thomas

Re: [Qemu-devel] intermittent make check failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Mark Cave-Ayland]

On 28/02/17 21:28, Thomas Huth wrote:

>> Maybe worth mentioning that the prom-env test for sparc64 has just been
>> enabled a couple of commits ago (6b591ad613010f13). There was an issue
>> with that test for the sparc64 target last year, but IIRC it only
>> affected 32-bit hosts and has been fixed, so I think/hope this is a
>> different issue now...
> 
> OK, I think this is definitively not related to the prom-env test, but
> to MTTCG (or something else in TCG): I can reproduce this problem
> reliably when I run QEMU in s390 mode with the Moon Buggy disk image
> from the QEMU advent calendar
> (http://www.qemu-advent-calendar.org/2014/download/s390-moon-buggy.tar.xz):
> 
> qemu-system-s390x -nographic -kernel s390-bb.kernel \
>                   -initrd s390-moon-buggy.initrd
> 
> ... starts the kernel, but aborts very soon with:
> 
> ERROR:qemu/translate-common.c:34:tcg_handle_interrupt: assertion failed:
> (qemu_mutex_iothread_locked())
> Aborted (core dumped)

FWIW I've spent some time running the "make check" regression tests
locally this evening and I can't seem to reproduce the failure here on
my normal qemu-system-ppc/qemu-system-sparc/qemu-system-sparc64 setup.


ATB,

Mark.

Re: [Qemu-devel] intermittent make check failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Mark Cave-Ayland]

On 28/02/17 21:35, Mark Cave-Ayland wrote:
> On 28/02/17 21:28, Thomas Huth wrote:
> 
>>> Maybe worth mentioning that the prom-env test for sparc64 has just been
>>> enabled a couple of commits ago (6b591ad613010f13). There was an issue
>>> with that test for the sparc64 target last year, but IIRC it only
>>> affected 32-bit hosts and has been fixed, so I think/hope this is a
>>> different issue now...
>>
>> OK, I think this is definitively not related to the prom-env test, but
>> to MTTCG (or something else in TCG): I can reproduce this problem
>> reliably when I run QEMU in s390 mode with the Moon Buggy disk image
>> from the QEMU advent calendar
>> (http://www.qemu-advent-calendar.org/2014/download/s390-moon-buggy.tar.xz):
>>
>> qemu-system-s390x -nographic -kernel s390-bb.kernel \
>>                   -initrd s390-moon-buggy.initrd
>>
>> ... starts the kernel, but aborts very soon with:
>>
>> ERROR:qemu/translate-common.c:34:tcg_handle_interrupt: assertion failed:
>> (qemu_mutex_iothread_locked())
>> Aborted (core dumped)
> 
> FWIW I've spent some time running the "make check" regression tests
> locally this evening and I can't seem to reproduce the failure here on
> my normal qemu-system-ppc/qemu-system-sparc/qemu-system-sparc64 setup.

However I can reproduce it consistently booting my OpenBIOS test images
under qemu-system-sparc:

$ ./qemu-system-sparc -cdrom debian-40r4a-sparc-netinst.iso -boot d
qemu-system-sparc: -cdrom
/home/build/src/qemu/image/sparc32/debian-40r4a-sparc-netinst.iso:
warning: bus=0,unit=2 is deprecated with this machine type
**
ERROR:/home/build/src/qemu/git/qemu/translate-common.c:34:tcg_handle_interrupt:
assertion failed: (qemu_mutex_iothread_locked())
Aborted


ATB,

Mark.

Re: [Qemu-devel] intermittent make check failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Dr. David Alan Gilbert]

* Kevin Wolf (kwolf@redhat.com) wrote:
> Am 28.02.2017 um 20:10 hat Peter Maydell geschrieben:
> > I got a make check failure on aarch64 host running a sparc64 test:
> 
> Probably completely unrelated, but while we're at it...
> 
> For me, tests/vhost-user-test has been hanging for check-qtest-i386
> occasionally in the past few days. Has anyone else seen this?

Yes, there's a fix from Marc-André for that.

Dave

> Kevin
> 
--
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK

Re: [Qemu-devel] intermittent make check failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Alex Bennée]

Peter Maydell <peter.maydell@linaro.org> writes:

> I got a make check failure on aarch64 host running a sparc64 test:
>
>
> TEST: tests/prom-env-test... (pid=13573)
>   /sparc64/prom-env/sun4u:                                             **
> ERROR:/home/pm215/qemu/translate-common.c:34:tcg_handle_interrupt:
> assertion failed: (qemu_mutex_iothread_locked())

So the assertions where added with MTTCG. The design specifies which
bits should be protected by the BQL and cpu->interrupt_request is one of
them. This is because cpu->interrupt_request is often a cross-vCPU
action (one vCPU triggering an interrupt on another) so there is a
chance of racing if not protected.

It's odd this is showing up on a aarch64 host though when it didn't hit
on my x86_64 host while testing.

As most of this stuff is triggered by hardware emulation the BQL should
be in effect when handling MMIO for device emulation. There where other
entry points in ARM which could trigger stuff which is why we add
locking for things like ARM_CP_IO which are co-processor register
accesses which trigger other things in the system.

What will be useful for all these reports is the backtrace. Then it's
fairly simple to identify the thing triggering the interrupt and
identify the correct place for the locking.

Having said that on some setups we are seeing very high BQL contention
so maybe it will be simpler to move this stuff to atomic updates. I
believe Paolo has some patches on the list.

> Broken pipe
> FAIL
> GTester: last random seed: R02Sa5fa983185fe5e65cfb5b7fcb39ed3d1
> (pid=13579)
> FAIL: tests/prom-env-test
>
> This is with commit 9514f2648ca05b3.
>
> It didn't reproduce on a rerun of 'make check' and it didn't
> look like the merge in question was particularly relevant to
> the failure, so I went ahead and pushed it to master.
>
> I'm (perhaps unfairly) assuming that this is fallout from MTTCG
> landing. (prom-env-test is one of the handful of tests in
> 'make check' that actually runs TCG code.)

Well I was hoping for a fairly incident free merge but I guess that's
why we have a softfreeze. The assertions where added so any areas where
the design is violated can be picked up pretty quickly which they seem
to be doing their job.

--
Alex Bennée

Re: [Qemu-devel] intermittent make check failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Mark Cave-Ayland]

On 01/03/17 11:36, Alex Bennée wrote:

> Peter Maydell <peter.maydell@linaro.org> writes:
> 
>> I got a make check failure on aarch64 host running a sparc64 test:
>>
>>
>> TEST: tests/prom-env-test... (pid=13573)
>>   /sparc64/prom-env/sun4u:                                             **
>> ERROR:/home/pm215/qemu/translate-common.c:34:tcg_handle_interrupt:
>> assertion failed: (qemu_mutex_iothread_locked())
> 
> So the assertions where added with MTTCG. The design specifies which
> bits should be protected by the BQL and cpu->interrupt_request is one of
> them. This is because cpu->interrupt_request is often a cross-vCPU
> action (one vCPU triggering an interrupt on another) so there is a
> chance of racing if not protected.
> 
> It's odd this is showing up on a aarch64 host though when it didn't hit
> on my x86_64 host while testing.
> 
> As most of this stuff is triggered by hardware emulation the BQL should
> be in effect when handling MMIO for device emulation. There where other
> entry points in ARM which could trigger stuff which is why we add
> locking for things like ARM_CP_IO which are co-processor register
> accesses which trigger other things in the system.
> 
> What will be useful for all these reports is the backtrace. Then it's
> fairly simple to identify the thing triggering the interrupt and
> identify the correct place for the locking.

Hi Alex,

Here's the backtrace from my test case of qemu-system-sparc running on
an x86_64 host that I posted yesterday:


$ gdb --args ./qemu-system-sparc -cdrom
/home/build/src/qemu/image/sparc32/debian-40r4a-sparc-netinst.iso -boot d
GNU gdb (GDB) 7.4.1-debian
Copyright (C) 2012 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-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /home/build/rel-qemu-git/bin/qemu-system-sparc...done.
(gdb) r
Starting program: /home/build/rel-qemu-git/bin/qemu-system-sparc -cdrom
/home/build/src/qemu/image/sparc32/debian-40r4a-sparc-netinst.iso -boot d
warning: no loadable sections found in added symbol-file system-supplied
DSO at 0x7ffff7ffa000
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[New Thread 0x7fffe9eee700 (LWP 18040)]
[New Thread 0x7fffe66d6700 (LWP 18041)]
[New Thread 0x7fffe5ed5700 (LWP 18042)]
qemu-system-sparc: -cdrom
/home/build/src/qemu/image/sparc32/debian-40r4a-sparc-netinst.iso:
warning: bus=0,unit=2 is deprecated with this machine type
[Thread 0x7fffe66d6700 (LWP 18041) exited]
[New Thread 0x7fffe66d6700 (LWP 18043)]
**
ERROR:/home/build/src/qemu/git/qemu/translate-common.c:34:tcg_handle_interrupt:
assertion failed: (qemu_mutex_iothread_locked())

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x7fffe5ed5700 (LWP 18042)]
0x00007ffff2939125 in *__GI_raise (sig=<optimized out>) at
../nptl/sysdeps/unix/sysv/linux/raise.c:64



64      ../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) thread apply all bt

Thread 5 (Thread 0x7fffe66d6700 (LWP 18043)):
#0  sem_timedwait () at
../nptl/sysdeps/unix/sysv/linux/x86_64/sem_timedwait.S:106
#1  0x000055555591435c in qemu_sem_timedwait (sem=0x5555561ad408,
ms=10000) at util/qemu-thread-posix.c:255
#2  0x000055555590cb51 in worker_thread (opaque=0x5555561ad3a0) at
util/thread-pool.c:92
#3  0x00007ffff2c9ab50 in start_thread (arg=<optimized out>) at
pthread_create.c:304
#4  0x00007ffff29e4fbd in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#5  0x0000000000000000 in ?? ()

Thread 4 (Thread 0x7fffe5ed5700 (LWP 18042)):
#0  0x00007ffff2939125 in *__GI_raise (sig=<optimized out>) at
../nptl/sysdeps/unix/sysv/linux/raise.c:64
#1  0x00007ffff293c3a0 in *__GI_abort () at abort.c:92
#2  0x00007ffff407e477 in g_assertion_message () from
/lib/x86_64-linux-gnu/libglib-2.0.so.0
#3  0x00007ffff407e994 in g_assertion_message_expr () from
/lib/x86_64-linux-gnu/libglib-2.0.so.0
#4  0x000055555561b54f in tcg_handle_interrupt (cpu=0x5555561b3af0,
mask=2) at /home/build/src/qemu/git/qemu/translate-common.c:34
#5  0x00005555556a8e7d in cpu_interrupt (cpu=0x5555561b3af0, mask=2) at
/home/build/src/qemu/git/qemu/include/qom/cpu.h:801
#6  0x00005555556a95ec in cpu_check_irqs (env=0x5555561bbd80) at
/home/build/src/qemu/git/qemu/hw/sparc/sun4m.c:157
#7  0x00005555556be063 in cpu_put_psr (env=0x5555561bbd80, val=76554214)
at /home/build/src/qemu/git/qemu/target/sparc/win_helper.c:89
#8  0x00005555556be3bd in helper_wrpsr (env=0x5555561bbd80,
new_psr=76554214) at
/home/build/src/qemu/git/qemu/target/sparc/win_helper.c:156
#9  0x00007fffe71cd75c in code_gen_buffer ()
#10 0x000055555561a3e6 in cpu_tb_exec (cpu=0x5555561b3af0,
itb=0x7fffe68618b0) at /home/build/src/qemu/git/qemu/cpu-exec.c:165
#11 0x000055555561b176 in cpu_loop_exec_tb (cpu=0x5555561b3af0,
tb=0x7fffe68618b0, last_tb=0x7fffe5ed4988, tb_exit=0x7fffe5ed4984,
sc=0x7fffe5ed49a0) at /home/build/src/qemu/git/qemu/cpu-exec.c:584
#12 0x000055555561b484 in cpu_exec (cpu=0x5555561b3af0) at
/home/build/src/qemu/git/qemu/cpu-exec.c:686
#13 0x0000555555654bb9 in tcg_cpu_exec (cpu=0x5555561b3af0) at
/home/build/src/qemu/git/qemu/cpus.c:1251
#14 0x0000555555654e8c in qemu_tcg_rr_cpu_thread_fn (arg=0x5555561b3af0)
at /home/build/src/qemu/git/qemu/cpus.c:1347
#15 0x00007ffff2c9ab50 in start_thread (arg=<optimized out>) at
pthread_create.c:304
#16 0x00007ffff29e4fbd in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#17 0x0000000000000000 in ?? ()

Thread 2 (Thread 0x7fffe9eee700 (LWP 18040)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:39
#1  0x00005555559144fe in qemu_futex_wait (f=0x555556117664,
val=4294967295) at /home/build/src/qemu/git/qemu/include/qemu/futex.h:26
#2  0x00005555559146a6 in qemu_event_wait (ev=0x555556117664) at
util/qemu-thread-posix.c:399
#3  0x000055555592c936 in call_rcu_thread (opaque=0x0) at util/rcu.c:249
#4  0x00007ffff2c9ab50 in start_thread (arg=<optimized out>) at
pthread_create.c:304
#5  0x00007ffff29e4fbd in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#6  0x0000000000000000 in ?? ()

Thread 1 (Thread 0x7ffff7ed6ba0 (LWP 18037)):
#0  0x00007ffff29da431 in ppoll (fds=<optimized out>, nfds=<optimized
out>, timeout=<optimized out>, sigmask=<optimized out>) at
../sysdeps/unix/sysv/linux/ppoll.c:58
#1  0x000055555590e22d in qemu_poll_ns (fds=0x55555969a880, nfds=5,
timeout=3689801) at util/qemu-timer.c:333
#2  0x000055555590f69f in os_host_main_loop_wait (timeout=3689801) at
util/main-loop.c:254
#3  0x000055555590f779 in main_loop_wait (nonblocking=0) at
util/main-loop.c:508
#4  0x00005555556d6aae in main_loop () at vl.c:1897
#5  0x00005555556dec9d in main (argc=5, argv=0x7fffffffea48,
envp=0x7fffffffea78) at vl.c:4675


HTH,

Mark.

Re: [Qemu-devel] intermittent make check failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Alex Bennée]

Mark Cave-Ayland <mark.cave-ayland@ilande.co.uk> writes:

> On 01/03/17 11:36, Alex Bennée wrote:
>
>> Peter Maydell <peter.maydell@linaro.org> writes:
>>
>>> I got a make check failure on aarch64 host running a sparc64 test:
>>>
>>>
>>> TEST: tests/prom-env-test... (pid=13573)
>>>   /sparc64/prom-env/sun4u:                                             **
>>> ERROR:/home/pm215/qemu/translate-common.c:34:tcg_handle_interrupt:
>>> assertion failed: (qemu_mutex_iothread_locked())
>>
>> So the assertions where added with MTTCG. The design specifies which
>> bits should be protected by the BQL and cpu->interrupt_request is one of
>> them. This is because cpu->interrupt_request is often a cross-vCPU
>> action (one vCPU triggering an interrupt on another) so there is a
>> chance of racing if not protected.
>>
>> It's odd this is showing up on a aarch64 host though when it didn't hit
>> on my x86_64 host while testing.
>>
>> As most of this stuff is triggered by hardware emulation the BQL should
>> be in effect when handling MMIO for device emulation. There where other
>> entry points in ARM which could trigger stuff which is why we add
>> locking for things like ARM_CP_IO which are co-processor register
>> accesses which trigger other things in the system.
>>
>> What will be useful for all these reports is the backtrace. Then it's
>> fairly simple to identify the thing triggering the interrupt and
>> identify the correct place for the locking.
>
> Hi Alex,
>
> Here's the backtrace from my test case of qemu-system-sparc running on
> an x86_64 host that I posted yesterday:
>
>
> $ gdb --args ./qemu-system-sparc -cdrom
> /home/build/src/qemu/image/sparc32/debian-40r4a-sparc-netinst.iso -boot d
> GNU gdb (GDB) 7.4.1-debian
> Copyright (C) 2012 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-linux-gnu".
> For bug reporting instructions, please see:
> <http://www.gnu.org/software/gdb/bugs/>...
> Reading symbols from /home/build/rel-qemu-git/bin/qemu-system-sparc...done.
> (gdb) r
> Starting program: /home/build/rel-qemu-git/bin/qemu-system-sparc -cdrom
> /home/build/src/qemu/image/sparc32/debian-40r4a-sparc-netinst.iso -boot d
> warning: no loadable sections found in added symbol-file system-supplied
> DSO at 0x7ffff7ffa000
> [Thread debugging using libthread_db enabled]
> Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
> [New Thread 0x7fffe9eee700 (LWP 18040)]
> [New Thread 0x7fffe66d6700 (LWP 18041)]
> [New Thread 0x7fffe5ed5700 (LWP 18042)]
> qemu-system-sparc: -cdrom
> /home/build/src/qemu/image/sparc32/debian-40r4a-sparc-netinst.iso:
> warning: bus=0,unit=2 is deprecated with this machine type
> [Thread 0x7fffe66d6700 (LWP 18041) exited]
> [New Thread 0x7fffe66d6700 (LWP 18043)]
> **
> ERROR:/home/build/src/qemu/git/qemu/translate-common.c:34:tcg_handle_interrupt:
> assertion failed: (qemu_mutex_iothread_locked())
>
> Program received signal SIGABRT, Aborted.
> [Switching to Thread 0x7fffe5ed5700 (LWP 18042)]
> 0x00007ffff2939125 in *__GI_raise (sig=<optimized out>) at
> ../nptl/sysdeps/unix/sysv/linux/raise.c:64
>
>
>
> 64      ../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory.
> (gdb) thread apply all bt
>
> Thread 5 (Thread 0x7fffe66d6700 (LWP 18043)):
> #0  sem_timedwait () at
> ../nptl/sysdeps/unix/sysv/linux/x86_64/sem_timedwait.S:106
> #1  0x000055555591435c in qemu_sem_timedwait (sem=0x5555561ad408,
> ms=10000) at util/qemu-thread-posix.c:255
> #2  0x000055555590cb51 in worker_thread (opaque=0x5555561ad3a0) at
> util/thread-pool.c:92
> #3  0x00007ffff2c9ab50 in start_thread (arg=<optimized out>) at
> pthread_create.c:304
> #4  0x00007ffff29e4fbd in clone () at
> ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
> #5  0x0000000000000000 in ?? ()
>
> Thread 4 (Thread 0x7fffe5ed5700 (LWP 18042)):
> #0  0x00007ffff2939125 in *__GI_raise (sig=<optimized out>) at
> ../nptl/sysdeps/unix/sysv/linux/raise.c:64
> #1  0x00007ffff293c3a0 in *__GI_abort () at abort.c:92
> #2  0x00007ffff407e477 in g_assertion_message () from
> /lib/x86_64-linux-gnu/libglib-2.0.so.0
> #3  0x00007ffff407e994 in g_assertion_message_expr () from
> /lib/x86_64-linux-gnu/libglib-2.0.so.0
> #4  0x000055555561b54f in tcg_handle_interrupt (cpu=0x5555561b3af0,
> mask=2) at /home/build/src/qemu/git/qemu/translate-common.c:34
> #5  0x00005555556a8e7d in cpu_interrupt (cpu=0x5555561b3af0, mask=2) at
> /home/build/src/qemu/git/qemu/include/qom/cpu.h:801
> #6  0x00005555556a95ec in cpu_check_irqs (env=0x5555561bbd80) at
> /home/build/src/qemu/git/qemu/hw/sparc/sun4m.c:157

Am I correct assuming all the helper functions themselves are concerned
with the vCPU environment they are running in? If so it looking like
cpu_check_irqs() would be the place to wrap the BQL lock in.

I'll make the change and test against your test case.

> #7  0x00005555556be063 in cpu_put_psr (env=0x5555561bbd80, val=76554214)
> at /home/build/src/qemu/git/qemu/target/sparc/win_helper.c:89
> #8  0x00005555556be3bd in helper_wrpsr (env=0x5555561bbd80,
> new_psr=76554214) at
> /home/build/src/qemu/git/qemu/target/sparc/win_helper.c:156
> #9  0x00007fffe71cd75c in code_gen_buffer ()
> #10 0x000055555561a3e6 in cpu_tb_exec (cpu=0x5555561b3af0,
> itb=0x7fffe68618b0) at /home/build/src/qemu/git/qemu/cpu-exec.c:165
> #11 0x000055555561b176 in cpu_loop_exec_tb (cpu=0x5555561b3af0,
> tb=0x7fffe68618b0, last_tb=0x7fffe5ed4988, tb_exit=0x7fffe5ed4984,
> sc=0x7fffe5ed49a0) at /home/build/src/qemu/git/qemu/cpu-exec.c:584
> #12 0x000055555561b484 in cpu_exec (cpu=0x5555561b3af0) at
> /home/build/src/qemu/git/qemu/cpu-exec.c:686
> #13 0x0000555555654bb9 in tcg_cpu_exec (cpu=0x5555561b3af0) at
> /home/build/src/qemu/git/qemu/cpus.c:1251
> #14 0x0000555555654e8c in qemu_tcg_rr_cpu_thread_fn (arg=0x5555561b3af0)
> at /home/build/src/qemu/git/qemu/cpus.c:1347
> #15 0x00007ffff2c9ab50 in start_thread (arg=<optimized out>) at
> pthread_create.c:304
> #16 0x00007ffff29e4fbd in clone () at
> ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
> #17 0x0000000000000000 in ?? ()
>
> Thread 2 (Thread 0x7fffe9eee700 (LWP 18040)):
> #0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:39
> #1  0x00005555559144fe in qemu_futex_wait (f=0x555556117664,
> val=4294967295) at /home/build/src/qemu/git/qemu/include/qemu/futex.h:26
> #2  0x00005555559146a6 in qemu_event_wait (ev=0x555556117664) at
> util/qemu-thread-posix.c:399
> #3  0x000055555592c936 in call_rcu_thread (opaque=0x0) at util/rcu.c:249
> #4  0x00007ffff2c9ab50 in start_thread (arg=<optimized out>) at
> pthread_create.c:304
> #5  0x00007ffff29e4fbd in clone () at
> ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
> #6  0x0000000000000000 in ?? ()
>
> Thread 1 (Thread 0x7ffff7ed6ba0 (LWP 18037)):
> #0  0x00007ffff29da431 in ppoll (fds=<optimized out>, nfds=<optimized
> out>, timeout=<optimized out>, sigmask=<optimized out>) at
> ../sysdeps/unix/sysv/linux/ppoll.c:58
> #1  0x000055555590e22d in qemu_poll_ns (fds=0x55555969a880, nfds=5,
> timeout=3689801) at util/qemu-timer.c:333
> #2  0x000055555590f69f in os_host_main_loop_wait (timeout=3689801) at
> util/main-loop.c:254
> #3  0x000055555590f779 in main_loop_wait (nonblocking=0) at
> util/main-loop.c:508
> #4  0x00005555556d6aae in main_loop () at vl.c:1897
> #5  0x00005555556dec9d in main (argc=5, argv=0x7fffffffea48,
> envp=0x7fffffffea78) at vl.c:4675
>
>
> HTH,
>
> Mark.


--
Alex Bennée

Re: [Qemu-devel] intermittent make check failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Peter Maydell]

On 1 March 2017 at 11:36, Alex Bennée <alex.bennee@linaro.org> wrote:
> What will be useful for all these reports is the backtrace. Then it's
> fairly simple to identify the thing triggering the interrupt and
> identify the correct place for the locking.

Unfortunately all I get for build tests is the log output
from 'make check'. I dunno if there's a way to get asserts
to print backtraces automatically.

thanks
-- PMM

Re: [Qemu-devel] intermittent make check failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Mark Cave-Ayland]

On 01/03/17 12:41, Alex Bennée wrote:

>> Here's the backtrace from my test case of qemu-system-sparc running on
>> an x86_64 host that I posted yesterday:
>>
>>
>> $ gdb --args ./qemu-system-sparc -cdrom
>> /home/build/src/qemu/image/sparc32/debian-40r4a-sparc-netinst.iso -boot d
>> GNU gdb (GDB) 7.4.1-debian
>> Copyright (C) 2012 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-linux-gnu".
>> For bug reporting instructions, please see:
>> <http://www.gnu.org/software/gdb/bugs/>...
>> Reading symbols from /home/build/rel-qemu-git/bin/qemu-system-sparc...done.
>> (gdb) r
>> Starting program: /home/build/rel-qemu-git/bin/qemu-system-sparc -cdrom
>> /home/build/src/qemu/image/sparc32/debian-40r4a-sparc-netinst.iso -boot d
>> warning: no loadable sections found in added symbol-file system-supplied
>> DSO at 0x7ffff7ffa000
>> [Thread debugging using libthread_db enabled]
>> Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
>> [New Thread 0x7fffe9eee700 (LWP 18040)]
>> [New Thread 0x7fffe66d6700 (LWP 18041)]
>> [New Thread 0x7fffe5ed5700 (LWP 18042)]
>> qemu-system-sparc: -cdrom
>> /home/build/src/qemu/image/sparc32/debian-40r4a-sparc-netinst.iso:
>> warning: bus=0,unit=2 is deprecated with this machine type
>> [Thread 0x7fffe66d6700 (LWP 18041) exited]
>> [New Thread 0x7fffe66d6700 (LWP 18043)]
>> **
>> ERROR:/home/build/src/qemu/git/qemu/translate-common.c:34:tcg_handle_interrupt:
>> assertion failed: (qemu_mutex_iothread_locked())
>>
>> Program received signal SIGABRT, Aborted.
>> [Switching to Thread 0x7fffe5ed5700 (LWP 18042)]
>> 0x00007ffff2939125 in *__GI_raise (sig=<optimized out>) at
>> ../nptl/sysdeps/unix/sysv/linux/raise.c:64
>>
>>
>>
>> 64      ../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory.
>> (gdb) thread apply all bt
>>
>> Thread 5 (Thread 0x7fffe66d6700 (LWP 18043)):
>> #0  sem_timedwait () at
>> ../nptl/sysdeps/unix/sysv/linux/x86_64/sem_timedwait.S:106
>> #1  0x000055555591435c in qemu_sem_timedwait (sem=0x5555561ad408,
>> ms=10000) at util/qemu-thread-posix.c:255
>> #2  0x000055555590cb51 in worker_thread (opaque=0x5555561ad3a0) at
>> util/thread-pool.c:92
>> #3  0x00007ffff2c9ab50 in start_thread (arg=<optimized out>) at
>> pthread_create.c:304
>> #4  0x00007ffff29e4fbd in clone () at
>> ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
>> #5  0x0000000000000000 in ?? ()
>>
>> Thread 4 (Thread 0x7fffe5ed5700 (LWP 18042)):
>> #0  0x00007ffff2939125 in *__GI_raise (sig=<optimized out>) at
>> ../nptl/sysdeps/unix/sysv/linux/raise.c:64
>> #1  0x00007ffff293c3a0 in *__GI_abort () at abort.c:92
>> #2  0x00007ffff407e477 in g_assertion_message () from
>> /lib/x86_64-linux-gnu/libglib-2.0.so.0
>> #3  0x00007ffff407e994 in g_assertion_message_expr () from
>> /lib/x86_64-linux-gnu/libglib-2.0.so.0
>> #4  0x000055555561b54f in tcg_handle_interrupt (cpu=0x5555561b3af0,
>> mask=2) at /home/build/src/qemu/git/qemu/translate-common.c:34
>> #5  0x00005555556a8e7d in cpu_interrupt (cpu=0x5555561b3af0, mask=2) at
>> /home/build/src/qemu/git/qemu/include/qom/cpu.h:801
>> #6  0x00005555556a95ec in cpu_check_irqs (env=0x5555561bbd80) at
>> /home/build/src/qemu/git/qemu/hw/sparc/sun4m.c:157
> 
> Am I correct assuming all the helper functions themselves are concerned
> with the vCPU environment they are running in? If so it looking like
> cpu_check_irqs() would be the place to wrap the BQL lock in.
> 
> I'll make the change and test against your test case.

For the window helpers, definitely yes - each SPARC vCPU contains a
large bank of registers of which the current window is a pointer as to
which register set is currently active. The current window itself is
controlled by a special register called CWP (current window pointer)
which is part of the PSR register in 32-bit CPUs or a standalone
register for 64-bit CPUs.

I ran out of time yesterday to run through all my SPARC64 tests, however
if this is the case then the issue will definitely appear in
qemu-system-sparc64 which seems to be supported by people seeing
intermittent failures in prom-env-test.


ATB,

Mark.

Re: [Qemu-devel] intermittent make check failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Alex Bennée]

Mark Cave-Ayland <mark.cave-ayland@ilande.co.uk> writes:

> On 01/03/17 12:41, Alex Bennée wrote:
>
>>> Here's the backtrace from my test case of qemu-system-sparc running on
>>> an x86_64 host that I posted yesterday:
>>>
>>>
>>> $ gdb --args ./qemu-system-sparc -cdrom
>>> /home/build/src/qemu/image/sparc32/debian-40r4a-sparc-netinst.iso -boot d
>>> GNU gdb (GDB) 7.4.1-debian
>>> Copyright (C) 2012 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-linux-gnu".
>>> For bug reporting instructions, please see:
>>> <http://www.gnu.org/software/gdb/bugs/>...
>>> Reading symbols from /home/build/rel-qemu-git/bin/qemu-system-sparc...done.
>>> (gdb) r
>>> Starting program: /home/build/rel-qemu-git/bin/qemu-system-sparc -cdrom
>>> /home/build/src/qemu/image/sparc32/debian-40r4a-sparc-netinst.iso -boot d
>>> warning: no loadable sections found in added symbol-file system-supplied
>>> DSO at 0x7ffff7ffa000
>>> [Thread debugging using libthread_db enabled]
>>> Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
>>> [New Thread 0x7fffe9eee700 (LWP 18040)]
>>> [New Thread 0x7fffe66d6700 (LWP 18041)]
>>> [New Thread 0x7fffe5ed5700 (LWP 18042)]
>>> qemu-system-sparc: -cdrom
>>> /home/build/src/qemu/image/sparc32/debian-40r4a-sparc-netinst.iso:
>>> warning: bus=0,unit=2 is deprecated with this machine type
>>> [Thread 0x7fffe66d6700 (LWP 18041) exited]
>>> [New Thread 0x7fffe66d6700 (LWP 18043)]
>>> **
>>> ERROR:/home/build/src/qemu/git/qemu/translate-common.c:34:tcg_handle_interrupt:
>>> assertion failed: (qemu_mutex_iothread_locked())
>>>
>>> Program received signal SIGABRT, Aborted.
>>> [Switching to Thread 0x7fffe5ed5700 (LWP 18042)]
>>> 0x00007ffff2939125 in *__GI_raise (sig=<optimized out>) at
>>> ../nptl/sysdeps/unix/sysv/linux/raise.c:64
>>>
>>>
>>>
>>> 64      ../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory.
>>> (gdb) thread apply all bt
>>>
>>> Thread 5 (Thread 0x7fffe66d6700 (LWP 18043)):
>>> #0  sem_timedwait () at
>>> ../nptl/sysdeps/unix/sysv/linux/x86_64/sem_timedwait.S:106
>>> #1  0x000055555591435c in qemu_sem_timedwait (sem=0x5555561ad408,
>>> ms=10000) at util/qemu-thread-posix.c:255
>>> #2  0x000055555590cb51 in worker_thread (opaque=0x5555561ad3a0) at
>>> util/thread-pool.c:92
>>> #3  0x00007ffff2c9ab50 in start_thread (arg=<optimized out>) at
>>> pthread_create.c:304
>>> #4  0x00007ffff29e4fbd in clone () at
>>> ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
>>> #5  0x0000000000000000 in ?? ()
>>>
>>> Thread 4 (Thread 0x7fffe5ed5700 (LWP 18042)):
>>> #0  0x00007ffff2939125 in *__GI_raise (sig=<optimized out>) at
>>> ../nptl/sysdeps/unix/sysv/linux/raise.c:64
>>> #1  0x00007ffff293c3a0 in *__GI_abort () at abort.c:92
>>> #2  0x00007ffff407e477 in g_assertion_message () from
>>> /lib/x86_64-linux-gnu/libglib-2.0.so.0
>>> #3  0x00007ffff407e994 in g_assertion_message_expr () from
>>> /lib/x86_64-linux-gnu/libglib-2.0.so.0
>>> #4  0x000055555561b54f in tcg_handle_interrupt (cpu=0x5555561b3af0,
>>> mask=2) at /home/build/src/qemu/git/qemu/translate-common.c:34
>>> #5  0x00005555556a8e7d in cpu_interrupt (cpu=0x5555561b3af0, mask=2) at
>>> /home/build/src/qemu/git/qemu/include/qom/cpu.h:801
>>> #6  0x00005555556a95ec in cpu_check_irqs (env=0x5555561bbd80) at
>>> /home/build/src/qemu/git/qemu/hw/sparc/sun4m.c:157
>>
>> Am I correct assuming all the helper functions themselves are concerned
>> with the vCPU environment they are running in? If so it looking like
>> cpu_check_irqs() would be the place to wrap the BQL lock in.
>>
>> I'll make the change and test against your test case.
>
> For the window helpers, definitely yes - each SPARC vCPU contains a
> large bank of registers of which the current window is a pointer as to
> which register set is currently active. The current window itself is
> controlled by a special register called CWP (current window pointer)
> which is part of the PSR register in 32-bit CPUs or a standalone
> register for 64-bit CPUs.

Actually looking at where cpu_check_irq is I've pushed the BQL wraps
higher up:

  https://github.com/stsquad/qemu/commit/f52e01bf4d3415ce4fad54cbb491f6c30a8e1903

The reasoning is HW emulation code can expect to be run under the BQL.
Anything triggered by MMIO for example will automatically have the lock.
The problem is helpers which trigger hardware actions (ARM has ARM_CP_IO
for this). We talk about this in the design document:

  http://git.qemu-project.org/?p=qemu.git;a=blob;f=docs/multi-thread-tcg.txt;h=a99b4564c6258576acfa141f51f4b80131969519;hb=HEAD#l201

> I ran out of time yesterday to run through all my SPARC64 tests, however
> if this is the case then the issue will definitely appear in
> qemu-system-sparc64 which seems to be supported by people seeing
> intermittent failures in prom-env-test.

So I made the change to both sparc and sparc64 in the above commit.

I haven't managed to run into the intermittent trigger yet. How do I run
the test directly?

  make tests/prom-env-test

Just makes the test case and

  ./tests/prom-env-test
**
ERROR:tests/libqtest.c:589:qtest_get_arch: assertion failed: (qemu != NULL)
Aborted (core dumped)


>
>
> ATB,
>
> Mark.


--
Alex Bennée

Re: [Qemu-devel] intermittent make check failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Mark Cave-Ayland]

On 01/03/17 15:19, Alex Bennée wrote:

> Actually looking at where cpu_check_irq is I've pushed the BQL wraps
> higher up:
> 
>   https://github.com/stsquad/qemu/commit/f52e01bf4d3415ce4fad54cbb491f6c30a8e1903
> 
> The reasoning is HW emulation code can expect to be run under the BQL.
> Anything triggered by MMIO for example will automatically have the lock.
> The problem is helpers which trigger hardware actions (ARM has ARM_CP_IO
> for this). We talk about this in the design document:
> 
>   http://git.qemu-project.org/?p=qemu.git;a=blob;f=docs/multi-thread-tcg.txt;h=a99b4564c6258576acfa141f51f4b80131969519;hb=HEAD#l201
> 
>> I ran out of time yesterday to run through all my SPARC64 tests, however
>> if this is the case then the issue will definitely appear in
>> qemu-system-sparc64 which seems to be supported by people seeing
>> intermittent failures in prom-env-test.
> 
> So I made the change to both sparc and sparc64 in the above commit.
> 
> I haven't managed to run into the intermittent trigger yet. How do I run
> the test directly?
> 
>   make tests/prom-env-test
> 
> Just makes the test case and
> 
>   ./tests/prom-env-test
> **
> ERROR:tests/libqtest.c:589:qtest_get_arch: assertion failed: (qemu != NULL)
> Aborted (core dumped)

Yeah, I couldn't work out how to run a single test either so ended up
cycling through a complete set of "make check" runs in order to try and
provoke the assert(), and despite all this I was still unable to
reproduce the "make check" error locally.

Fortunately with the debian-40r4a-sparc-netinst.iso I was able to
reproduce it fairly easily under qemu-system-sparc so I'd suggest that
you go that route. If you can't find anywhere that hosts that particular
image for testing, do contact me off-list and I'll temporarily upload it
somewhere for you.


ATB,

Mark.

Re: [Qemu-devel] intermittent make check failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Peter Maydell]

On 1 March 2017 at 15:19, Alex Bennée <alex.bennee@linaro.org> wrote:
> I haven't managed to run into the intermittent trigger yet. How do I run
> the test directly?
>
>   make tests/prom-env-test
>
> Just makes the test case and
>
>   ./tests/prom-env-test
> **
> ERROR:tests/libqtest.c:589:qtest_get_arch: assertion failed: (qemu != NULL)
> Aborted (core dumped)

These tests all need a bunch of environment variables set (notably
the one that tells it which QEMU binary to run). If you run
'make check V=1' it prints out all the command lines and then
you can cut-n-paste the one you're interested in from that
(and trim down any other tests it's running in the process).

thanks
-- PMM

Re: [Qemu-devel] intermittent make check failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Thomas Huth]

On 01.03.2017 16:19, Alex Bennée wrote:
> 
> Mark Cave-Ayland <mark.cave-ayland@ilande.co.uk> writes:
> 
>> On 01/03/17 12:41, Alex Bennée wrote:
>>
>>>> Here's the backtrace from my test case of qemu-system-sparc running on
>>>> an x86_64 host that I posted yesterday:
>>>>
>>>>
>>>> $ gdb --args ./qemu-system-sparc -cdrom
>>>> /home/build/src/qemu/image/sparc32/debian-40r4a-sparc-netinst.iso -boot d
>>>> GNU gdb (GDB) 7.4.1-debian
>>>> Copyright (C) 2012 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-linux-gnu".
>>>> For bug reporting instructions, please see:
>>>> <http://www.gnu.org/software/gdb/bugs/>...
>>>> Reading symbols from /home/build/rel-qemu-git/bin/qemu-system-sparc...done.
>>>> (gdb) r
>>>> Starting program: /home/build/rel-qemu-git/bin/qemu-system-sparc -cdrom
>>>> /home/build/src/qemu/image/sparc32/debian-40r4a-sparc-netinst.iso -boot d
>>>> warning: no loadable sections found in added symbol-file system-supplied
>>>> DSO at 0x7ffff7ffa000
>>>> [Thread debugging using libthread_db enabled]
>>>> Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
>>>> [New Thread 0x7fffe9eee700 (LWP 18040)]
>>>> [New Thread 0x7fffe66d6700 (LWP 18041)]
>>>> [New Thread 0x7fffe5ed5700 (LWP 18042)]
>>>> qemu-system-sparc: -cdrom
>>>> /home/build/src/qemu/image/sparc32/debian-40r4a-sparc-netinst.iso:
>>>> warning: bus=0,unit=2 is deprecated with this machine type
>>>> [Thread 0x7fffe66d6700 (LWP 18041) exited]
>>>> [New Thread 0x7fffe66d6700 (LWP 18043)]
>>>> **
>>>> ERROR:/home/build/src/qemu/git/qemu/translate-common.c:34:tcg_handle_interrupt:
>>>> assertion failed: (qemu_mutex_iothread_locked())
>>>>
>>>> Program received signal SIGABRT, Aborted.
>>>> [Switching to Thread 0x7fffe5ed5700 (LWP 18042)]
>>>> 0x00007ffff2939125 in *__GI_raise (sig=<optimized out>) at
>>>> ../nptl/sysdeps/unix/sysv/linux/raise.c:64
>>>>
>>>>
>>>>
>>>> 64      ../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory.
>>>> (gdb) thread apply all bt
>>>>
>>>> Thread 5 (Thread 0x7fffe66d6700 (LWP 18043)):
>>>> #0  sem_timedwait () at
>>>> ../nptl/sysdeps/unix/sysv/linux/x86_64/sem_timedwait.S:106
>>>> #1  0x000055555591435c in qemu_sem_timedwait (sem=0x5555561ad408,
>>>> ms=10000) at util/qemu-thread-posix.c:255
>>>> #2  0x000055555590cb51 in worker_thread (opaque=0x5555561ad3a0) at
>>>> util/thread-pool.c:92
>>>> #3  0x00007ffff2c9ab50 in start_thread (arg=<optimized out>) at
>>>> pthread_create.c:304
>>>> #4  0x00007ffff29e4fbd in clone () at
>>>> ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
>>>> #5  0x0000000000000000 in ?? ()
>>>>
>>>> Thread 4 (Thread 0x7fffe5ed5700 (LWP 18042)):
>>>> #0  0x00007ffff2939125 in *__GI_raise (sig=<optimized out>) at
>>>> ../nptl/sysdeps/unix/sysv/linux/raise.c:64
>>>> #1  0x00007ffff293c3a0 in *__GI_abort () at abort.c:92
>>>> #2  0x00007ffff407e477 in g_assertion_message () from
>>>> /lib/x86_64-linux-gnu/libglib-2.0.so.0
>>>> #3  0x00007ffff407e994 in g_assertion_message_expr () from
>>>> /lib/x86_64-linux-gnu/libglib-2.0.so.0
>>>> #4  0x000055555561b54f in tcg_handle_interrupt (cpu=0x5555561b3af0,
>>>> mask=2) at /home/build/src/qemu/git/qemu/translate-common.c:34
>>>> #5  0x00005555556a8e7d in cpu_interrupt (cpu=0x5555561b3af0, mask=2) at
>>>> /home/build/src/qemu/git/qemu/include/qom/cpu.h:801
>>>> #6  0x00005555556a95ec in cpu_check_irqs (env=0x5555561bbd80) at
>>>> /home/build/src/qemu/git/qemu/hw/sparc/sun4m.c:157
>>>
>>> Am I correct assuming all the helper functions themselves are concerned
>>> with the vCPU environment they are running in? If so it looking like
>>> cpu_check_irqs() would be the place to wrap the BQL lock in.
>>>
>>> I'll make the change and test against your test case.
>>
>> For the window helpers, definitely yes - each SPARC vCPU contains a
>> large bank of registers of which the current window is a pointer as to
>> which register set is currently active. The current window itself is
>> controlled by a special register called CWP (current window pointer)
>> which is part of the PSR register in 32-bit CPUs or a standalone
>> register for 64-bit CPUs.
> 
> Actually looking at where cpu_check_irq is I've pushed the BQL wraps
> higher up:
> 
>   https://github.com/stsquad/qemu/commit/f52e01bf4d3415ce4fad54cbb491f6c30a8e1903
> 
> The reasoning is HW emulation code can expect to be run under the BQL.
> Anything triggered by MMIO for example will automatically have the lock.
> The problem is helpers which trigger hardware actions (ARM has ARM_CP_IO
> for this). We talk about this in the design document:
> 
>   http://git.qemu-project.org/?p=qemu.git;a=blob;f=docs/multi-thread-tcg.txt;h=a99b4564c6258576acfa141f51f4b80131969519;hb=HEAD#l201
> 
>> I ran out of time yesterday to run through all my SPARC64 tests, however
>> if this is the case then the issue will definitely appear in
>> qemu-system-sparc64 which seems to be supported by people seeing
>> intermittent failures in prom-env-test.
> 
> So I made the change to both sparc and sparc64 in the above commit.
> 
> I haven't managed to run into the intermittent trigger yet. How do I run
> the test directly?
> 
>   make tests/prom-env-test
> 
> Just makes the test case and
> 
>   ./tests/prom-env-test
> **
> ERROR:tests/libqtest.c:589:qtest_get_arch: assertion failed: (qemu != NULL)
> Aborted (core dumped)

QTEST_QEMU_BINARY=sparc64-softmmu/qemu-system-sparc64 \
 tests/prom-env-test

... that should do the job here.
(or use "make check-qtest-sparc64" to run all sparc64 tests)

 Thomas

Re: [Qemu-devel] s390x failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Thomas Huth]

On 01.03.2017 12:36, Alex Bennée wrote:
> 
> Peter Maydell <peter.maydell@linaro.org> writes:
> 
>> I got a make check failure on aarch64 host running a sparc64 test:
>>
>>
>> TEST: tests/prom-env-test... (pid=13573)
>>   /sparc64/prom-env/sun4u:                                             **
>> ERROR:/home/pm215/qemu/translate-common.c:34:tcg_handle_interrupt:
>> assertion failed: (qemu_mutex_iothread_locked())
> 
> So the assertions where added with MTTCG. The design specifies which
> bits should be protected by the BQL and cpu->interrupt_request is one of
> them. This is because cpu->interrupt_request is often a cross-vCPU
> action (one vCPU triggering an interrupt on another) so there is a
> chance of racing if not protected.
> 
> It's odd this is showing up on a aarch64 host though when it didn't hit
> on my x86_64 host while testing.
> 
> As most of this stuff is triggered by hardware emulation the BQL should
> be in effect when handling MMIO for device emulation. There where other
> entry points in ARM which could trigger stuff which is why we add
> locking for things like ARM_CP_IO which are co-processor register
> accesses which trigger other things in the system.
> 
> What will be useful for all these reports is the backtrace. Then it's
> fairly simple to identify the thing triggering the interrupt and
> identify the correct place for the locking.

Here are the backtraces from the s390x moon buggy image:

Thread 3 (Thread 0x7fffdc608700 (LWP 14468)):
#0  0x00007ffff18ef1d7 in raise () at /lib64/libc.so.6
#1  0x00007ffff18f08c8 in abort () at /lib64/libc.so.6
#2  0x00007ffff2f642a5 in g_assertion_message () at /lib64/libglib-2.0.so.0
#3  0x00007ffff2f6433a in g_assertion_message_expr () at /lib64/libglib-2.0.so.0
#4  0x000055555560bd31 in tcg_handle_interrupt (cpu=0x55555612fc40, mask=2) at /home/thuth/devel/qemu/translate-common.c:34
#5  0x000055555568fe03 in css_do_ssch (sch=sch@entry=0x5555561740d0, orb=orb@entry=0x7fffdc607400)
    at /home/thuth/devel/qemu/hw/s390x/css.c:945
#6  0x00005555556b99ad in ioinst_handle_ssch (cpu=0x55555612fc40, reg1=<optimized out>, ipb=<optimized out>)
    at /home/thuth/devel/qemu/target/s390x/ioinst.c:238
#7  0x00007fffe60957be in code_gen_buffer ()
#8  0x000055555560b49d in cpu_exec (itb=<optimized out>, itb=<optimized out>, cpu=0x7fffe52dc790)
    at /home/thuth/devel/qemu/cpu-exec.c:165
#9  0x000055555560b49d in cpu_exec (sc=0x7fffdc6079b0, tb_exit=<synthetic pointer>, last_tb=<synthetic pointer>, tb=<optimized out>, cpu=0x7fffe52dc790) at /home/thuth/devel/qemu/cpu-exec.c:584
#10 0x000055555560b49d in cpu_exec (cpu=cpu@entry=0x55555612fc40) at /home/thuth/devel/qemu/cpu-exec.c:686
#11 0x000055555563677a in tcg_cpu_exec (cpu=0x55555612fc40) at /home/thuth/devel/qemu/cpus.c:1251
#12 0x0000555555636ab4 in qemu_tcg_rr_cpu_thread_fn (arg=<optimized out>) at /home/thuth/devel/qemu/cpus.c:1347
#13 0x00007ffff53b3dc5 in start_thread () at /lib64/libpthread.so.0
#14 0x00007ffff19b173d in clone () at /lib64/libc.so.6

Thread 2 (Thread 0x7fffe82b5700 (LWP 14467)):
#0  0x00007ffff19abbf9 in syscall () at /lib64/libc.so.6
#1  0x0000555555853896 in qemu_event_wait (val=<optimized out>, f=<optimized out>)
    at /home/thuth/devel/qemu/include/qemu/futex.h:26
#2  0x0000555555853896 in qemu_event_wait (ev=ev@entry=0x555556082284 <rcu_call_ready_event>)
    at /home/thuth/devel/qemu/util/qemu-thread-posix.c:399
#3  0x000055555586243e in call_rcu_thread (opaque=<optimized out>) at /home/thuth/devel/qemu/util/rcu.c:249
#4  0x00007ffff53b3dc5 in start_thread () at /lib64/libpthread.so.0
#5  0x00007ffff19b173d in clone () at /lib64/libc.so.6

Thread 1 (Thread 0x7ffff7f91c00 (LWP 14463)):
#0  0x00007ffff19a6ebf in ppoll () at /lib64/libc.so.6
#1  0x000055555584f819 in qemu_poll_ns (__ss=0x0, __timeout=0x7fffffffda20, __nfds=<optimized out>, __fds=<optimized out>)
    at /usr/include/bits/poll2.h:77
#2  0x000055555584f819 in qemu_poll_ns (fds=<optimized out>, nfds=<optimized out>, timeout=timeout@entry=9897590)
    at /home/thuth/devel/qemu/util/qemu-timer.c:333
#3  0x00005555558505e8 in main_loop_wait (timeout=9897590) at /home/thuth/devel/qemu/util/main-loop.c:254
#4  0x00005555558505e8 in main_loop_wait (nonblocking=<optimized out>) at /home/thuth/devel/qemu/util/main-loop.c:508
#5  0x00005555555f83b9 in main () at /home/thuth/devel/qemu/vl.c:1897
#6  0x00005555555f83b9 in main (argc=<optimized out>, argv=<optimized out>, envp=<optimized out>)
    at /home/thuth/devel/qemu/vl.c:4675

 HTH2,
  Thomas

Re: [Qemu-devel] intermittent make check failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Alex Bennée]

Mark Cave-Ayland <mark.cave-ayland@ilande.co.uk> writes:

> On 01/03/17 15:19, Alex Bennée wrote:
>
>> Actually looking at where cpu_check_irq is I've pushed the BQL wraps
>> higher up:
>>
>>   https://github.com/stsquad/qemu/commit/f52e01bf4d3415ce4fad54cbb491f6c30a8e1903
>>
>> The reasoning is HW emulation code can expect to be run under the BQL.
>> Anything triggered by MMIO for example will automatically have the lock.
>> The problem is helpers which trigger hardware actions (ARM has ARM_CP_IO
>> for this). We talk about this in the design document:
>>
>>   http://git.qemu-project.org/?p=qemu.git;a=blob;f=docs/multi-thread-tcg.txt;h=a99b4564c6258576acfa141f51f4b80131969519;hb=HEAD#l201
>>
>>> I ran out of time yesterday to run through all my SPARC64 tests, however
>>> if this is the case then the issue will definitely appear in
>>> qemu-system-sparc64 which seems to be supported by people seeing
>>> intermittent failures in prom-env-test.
>>
>> So I made the change to both sparc and sparc64 in the above commit.
>>
>> I haven't managed to run into the intermittent trigger yet. How do I run
>> the test directly?
>>
>>   make tests/prom-env-test
>>
>> Just makes the test case and
>>
>>   ./tests/prom-env-test
>> **
>> ERROR:tests/libqtest.c:589:qtest_get_arch: assertion failed: (qemu != NULL)
>> Aborted (core dumped)
>
> Yeah, I couldn't work out how to run a single test either so ended up
> cycling through a complete set of "make check" runs in order to try and
> provoke the assert(), and despite all this I was still unable to
> reproduce the "make check" error locally.
>
> Fortunately with the debian-40r4a-sparc-netinst.iso I was able to
> reproduce it fairly easily under qemu-system-sparc so I'd suggest that
> you go that route. If you can't find anywhere that hosts that particular
> image for testing, do contact me off-list and I'll temporarily upload it
> somewhere for you.

It's OK I reproduced with the current etch iso. I have a patch in my
tree that seems to work. I'll post once I've checked for any other
places that need it.

--
Alex Bennée

Re: [Qemu-devel] s390x failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Alex Bennée]

Thomas Huth <thuth@redhat.com> writes:

> On 01.03.2017 12:36, Alex Bennée wrote:
>>
>> Peter Maydell <peter.maydell@linaro.org> writes:
>>
>>> I got a make check failure on aarch64 host running a sparc64 test:
>>>
>>>
>>> TEST: tests/prom-env-test... (pid=13573)
>>>   /sparc64/prom-env/sun4u:                                             **
>>> ERROR:/home/pm215/qemu/translate-common.c:34:tcg_handle_interrupt:
>>> assertion failed: (qemu_mutex_iothread_locked())
>>
>> So the assertions where added with MTTCG. The design specifies which
>> bits should be protected by the BQL and cpu->interrupt_request is one of
>> them. This is because cpu->interrupt_request is often a cross-vCPU
>> action (one vCPU triggering an interrupt on another) so there is a
>> chance of racing if not protected.
>>
>> It's odd this is showing up on a aarch64 host though when it didn't hit
>> on my x86_64 host while testing.
>>
>> As most of this stuff is triggered by hardware emulation the BQL should
>> be in effect when handling MMIO for device emulation. There where other
>> entry points in ARM which could trigger stuff which is why we add
>> locking for things like ARM_CP_IO which are co-processor register
>> accesses which trigger other things in the system.
>>
>> What will be useful for all these reports is the backtrace. Then it's
>> fairly simple to identify the thing triggering the interrupt and
>> identify the correct place for the locking.
>
> Here are the backtraces from the s390x moon buggy image:
>
> Thread 3 (Thread 0x7fffdc608700 (LWP 14468)):
> #0  0x00007ffff18ef1d7 in raise () at /lib64/libc.so.6
> #1  0x00007ffff18f08c8 in abort () at /lib64/libc.so.6
> #2  0x00007ffff2f642a5 in g_assertion_message () at /lib64/libglib-2.0.so.0
> #3  0x00007ffff2f6433a in g_assertion_message_expr () at /lib64/libglib-2.0.so.0
> #4  0x000055555560bd31 in tcg_handle_interrupt (cpu=0x55555612fc40, mask=2) at /home/thuth/devel/qemu/translate-common.c:34
> #5  0x000055555568fe03 in css_do_ssch (sch=sch@entry=0x5555561740d0, orb=orb@entry=0x7fffdc607400)
>     at /home/thuth/devel/qemu/hw/s390x/css.c:945
> #6  0x00005555556b99ad in ioinst_handle_ssch (cpu=0x55555612fc40, reg1=<optimized out>, ipb=<optimized out>)
>     at /home/thuth/devel/qemu/target/s390x/ioinst.c:238

Already fixed in my tree ;-)

  https://github.com/stsquad/qemu/tree/mttcg/post-merge-fixes-v2

with:

  https://github.com/stsquad/qemu/commit/24b0b124c58682e33f11ce2d3d53924e92d8745f

> #7  0x00007fffe60957be in code_gen_buffer ()
> #8  0x000055555560b49d in cpu_exec (itb=<optimized out>, itb=<optimized out>, cpu=0x7fffe52dc790)
>     at /home/thuth/devel/qemu/cpu-exec.c:165
> #9  0x000055555560b49d in cpu_exec (sc=0x7fffdc6079b0, tb_exit=<synthetic pointer>, last_tb=<synthetic pointer>, tb=<optimized out>, cpu=0x7fffe52dc790) at /home/thuth/devel/qemu/cpu-exec.c:584
> #10 0x000055555560b49d in cpu_exec (cpu=cpu@entry=0x55555612fc40) at /home/thuth/devel/qemu/cpu-exec.c:686
> #11 0x000055555563677a in tcg_cpu_exec (cpu=0x55555612fc40) at /home/thuth/devel/qemu/cpus.c:1251
> #12 0x0000555555636ab4 in qemu_tcg_rr_cpu_thread_fn (arg=<optimized out>) at /home/thuth/devel/qemu/cpus.c:1347
> #13 0x00007ffff53b3dc5 in start_thread () at /lib64/libpthread.so.0
> #14 0x00007ffff19b173d in clone () at /lib64/libc.so.6
>
> Thread 2 (Thread 0x7fffe82b5700 (LWP 14467)):
> #0  0x00007ffff19abbf9 in syscall () at /lib64/libc.so.6
> #1  0x0000555555853896 in qemu_event_wait (val=<optimized out>, f=<optimized out>)
>     at /home/thuth/devel/qemu/include/qemu/futex.h:26
> #2  0x0000555555853896 in qemu_event_wait (ev=ev@entry=0x555556082284 <rcu_call_ready_event>)
>     at /home/thuth/devel/qemu/util/qemu-thread-posix.c:399
> #3  0x000055555586243e in call_rcu_thread (opaque=<optimized out>) at /home/thuth/devel/qemu/util/rcu.c:249
> #4  0x00007ffff53b3dc5 in start_thread () at /lib64/libpthread.so.0
> #5  0x00007ffff19b173d in clone () at /lib64/libc.so.6
>
> Thread 1 (Thread 0x7ffff7f91c00 (LWP 14463)):
> #0  0x00007ffff19a6ebf in ppoll () at /lib64/libc.so.6
> #1  0x000055555584f819 in qemu_poll_ns (__ss=0x0, __timeout=0x7fffffffda20, __nfds=<optimized out>, __fds=<optimized out>)
>     at /usr/include/bits/poll2.h:77
> #2  0x000055555584f819 in qemu_poll_ns (fds=<optimized out>, nfds=<optimized out>, timeout=timeout@entry=9897590)
>     at /home/thuth/devel/qemu/util/qemu-timer.c:333
> #3  0x00005555558505e8 in main_loop_wait (timeout=9897590) at /home/thuth/devel/qemu/util/main-loop.c:254
> #4  0x00005555558505e8 in main_loop_wait (nonblocking=<optimized out>) at /home/thuth/devel/qemu/util/main-loop.c:508
> #5  0x00005555555f83b9 in main () at /home/thuth/devel/qemu/vl.c:1897
> #6  0x00005555555f83b9 in main (argc=<optimized out>, argv=<optimized out>, envp=<optimized out>)
>     at /home/thuth/devel/qemu/vl.c:4675
>
>  HTH2,
>   Thomas


--
Alex Bennée

Re: [Qemu-devel] xtensa failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Thomas Huth]

On 01.03.2017 12:36, Alex Bennée wrote:
> 
> Peter Maydell <peter.maydell@linaro.org> writes:
> 
>> I got a make check failure on aarch64 host running a sparc64 test:
>>
>>
>> TEST: tests/prom-env-test... (pid=13573)
>>   /sparc64/prom-env/sun4u:                                             **
>> ERROR:/home/pm215/qemu/translate-common.c:34:tcg_handle_interrupt:
>> assertion failed: (qemu_mutex_iothread_locked())
[...]
> What will be useful for all these reports is the backtrace. Then it's
> fairly simple to identify the thing triggering the interrupt and
> identify the correct place for the locking.

xtensa-softmmu crashes, too:

#0  0x00007ffff18ef1d7 in raise () at /lib64/libc.so.6
#1  0x00007ffff18f08c8 in abort () at /lib64/libc.so.6
#2  0x00007ffff2f642a5 in g_assertion_message () at /lib64/libglib-2.0.so.0
#3  0x00007ffff2f6433a in g_assertion_message_expr () at /lib64/libglib-2.0.so.0
#4  0x00005555555e5411 in tcg_handle_interrupt (cpu=0x555555fec400, mask=2) at /home/thuth/devel/qemu/translate-common.c:34
#5  0x000055555563d2e7 in check_interrupts (mask=2, cpu=0x555555fec400) at /home/thuth/devel/qemu/include/qom/cpu.h:801
#6  0x000055555563d2e7 in check_interrupts (env=0x555555ff4690) at /home/thuth/devel/qemu/hw/xtensa/pic_cpu.c:44
#7  0x00007fffe5ab66da in code_gen_buffer ()
#8  0x00005555555e4a51 in cpu_exec (itb=<optimized out>, itb=<optimized out>, cpu=0x7fffe51bf3c0)
    at /home/thuth/devel/qemu/cpu-exec.c:165
#9  0x00005555555e4a51 in cpu_exec (sc=0x7fffe51bc9b0, tb_exit=<synthetic pointer>, last_tb=<synthetic pointer>, tb=<optimized out>, cpu=0x7fffe51bf3c0) at /home/thuth/devel/qemu/cpu-exec.c:584
#10 0x00005555555e4a51 in cpu_exec (cpu=cpu@entry=0x555555fec400) at /home/thuth/devel/qemu/cpu-exec.c:686
#11 0x000055555560e89a in tcg_cpu_exec (cpu=0x555555fec400) at /home/thuth/devel/qemu/cpus.c:1251
#12 0x000055555560ebd4 in qemu_tcg_rr_cpu_thread_fn (arg=<optimized out>) at /home/thuth/devel/qemu/cpus.c:1347
#13 0x00007ffff53b3dc5 in start_thread () at /lib64/libpthread.so.0
#14 0x00007ffff19b173d in clone () at /lib64/libc.so.6

IIRC I once downloaded that image from http://wiki.qemu-project.org/Testing/System_Images

 Thomas

Re: [Qemu-devel] xtensa failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Alex Bennée]

Thomas Huth <thuth@redhat.com> writes:

> On 01.03.2017 12:36, Alex Bennée wrote:
>>
>> Peter Maydell <peter.maydell@linaro.org> writes:
>>
>>> I got a make check failure on aarch64 host running a sparc64 test:
>>>
>>>
>>> TEST: tests/prom-env-test... (pid=13573)
>>>   /sparc64/prom-env/sun4u:                                             **
>>> ERROR:/home/pm215/qemu/translate-common.c:34:tcg_handle_interrupt:
>>> assertion failed: (qemu_mutex_iothread_locked())
> [...]
>> What will be useful for all these reports is the backtrace. Then it's
>> fairly simple to identify the thing triggering the interrupt and
>> identify the correct place for the locking.
>
> xtensa-softmmu crashes, too:
>
> #0  0x00007ffff18ef1d7 in raise () at /lib64/libc.so.6
> #1  0x00007ffff18f08c8 in abort () at /lib64/libc.so.6
> #2  0x00007ffff2f642a5 in g_assertion_message () at /lib64/libglib-2.0.so.0
> #3  0x00007ffff2f6433a in g_assertion_message_expr () at /lib64/libglib-2.0.so.0
> #4  0x00005555555e5411 in tcg_handle_interrupt (cpu=0x555555fec400, mask=2) at /home/thuth/devel/qemu/translate-common.c:34
> #5  0x000055555563d2e7 in check_interrupts (mask=2, cpu=0x555555fec400) at /home/thuth/devel/qemu/include/qom/cpu.h:801
> #6  0x000055555563d2e7 in check_interrupts (env=0x555555ff4690) at /home/thuth/devel/qemu/hw/xtensa/pic_cpu.c:44
> #7  0x00007fffe5ab66da in code_gen_buffer ()
> #8  0x00005555555e4a51 in cpu_exec (itb=<optimized out>, itb=<optimized out>, cpu=0x7fffe51bf3c0)
>     at /home/thuth/devel/qemu/cpu-exec.c:165
> #9  0x00005555555e4a51 in cpu_exec (sc=0x7fffe51bc9b0, tb_exit=<synthetic pointer>, last_tb=<synthetic pointer>, tb=<optimized out>, cpu=0x7fffe51bf3c0) at /home/thuth/devel/qemu/cpu-exec.c:584
> #10 0x00005555555e4a51 in cpu_exec (cpu=cpu@entry=0x555555fec400) at /home/thuth/devel/qemu/cpu-exec.c:686
> #11 0x000055555560e89a in tcg_cpu_exec (cpu=0x555555fec400) at /home/thuth/devel/qemu/cpus.c:1251
> #12 0x000055555560ebd4 in qemu_tcg_rr_cpu_thread_fn (arg=<optimized out>) at /home/thuth/devel/qemu/cpus.c:1347
> #13 0x00007ffff53b3dc5 in start_thread () at /lib64/libpthread.so.0
> #14 0x00007ffff19b173d in clone () at /lib64/libc.so.6
>
> IIRC I once downloaded that image from http://wiki.qemu-project.org/Testing/System_Images

Ok this is fixed with:

  https://github.com/stsquad/qemu/commit/dcce964cec4b9519d31a1791e1996c6bb3c186b8

However I ran into another problem. Code generation leads to a tlb_fill
which runs afoul of a nested tb_lock(). I'm pretty sure the front-end is
using the wrong thing to fetch code:

  #0  0x00007fffdf2c5428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
  #1  0x00007fffdf2c702a in __GI_abort () at abort.c:89
  #2  0x00007fffdf2bdbd7 in __assert_fail_base (fmt=<optimised out>, assertion=assertion@entry=0x5555558b3256 "!have_tb_lock", file=file@entry=0x5555558b31e0 "/home/alex/lsrc/qemu/qemu.git/translate-all.c", line=line@entry=165, function=function@entry=0x5555558b3588 <__PRETTY_FUNCTION__.26299> "tb_lock") at assert.c:92
  #3  0x00007fffdf2bdc82 in __GI___assert_fail (assertion=0x5555558b3256 "!have_tb_lock", file=0x5555558b31e0 "/home/alex/lsrc/qemu/qemu.git/translate-all.c", line=165, function=0x5555558b3588 <__PRETTY_FUNCTION__.26299> "tb_lock") at assert.c:101
  #4  0x00005555555da9c7 in tb_lock () at /home/alex/lsrc/qemu/qemu.git/translate-all.c:165
  #5  0x00005555555daec0 in cpu_restore_state (cpu=0x5555560ff4f0, retaddr=0) at /home/alex/lsrc/qemu/qemu.git/translate-all.c:336
  #6  0x00005555556652d5 in tlb_fill (cs=0x5555560ff4f0, vaddr=537034752, access_type=MMU_INST_FETCH, mmu_idx=1, retaddr=0) at /home/alex/lsrc/qemu/qemu.git/target/xtensa/op_helper.c:73
  #7  0x0000555555636b21 in helper_ret_ldb_cmmu (env=0x555556107780, addr=537034752, oi=1, retaddr=0) at /home/alex/lsrc/qemu/qemu.git/softmmu_template.h:127
  #8  0x0000555555657638 in cpu_ldub_code_ra (env=0x555556107780, ptr=537034752, retaddr=0) at /home/alex/lsrc/qemu/qemu.git/include/exec/cpu_ldst_template.h:102
  #9  0x00005555556576aa in cpu_ldub_code (env=0x555556107780, ptr=537034752) at /home/alex/lsrc/qemu/qemu.git/include/exec/cpu_ldst_template.h:114
  #10 0x00005555556596c8 in disas_xtensa_insn (env=0x555556107780, dc=0x7fffcca0f4f0) at /home/alex/lsrc/qemu/qemu.git/target/xtensa/translate.c:1052
  #11 0x00005555556646d1 in gen_intermediate_code (env=0x555556107780, tb=0x7fffccc7d770) at /home/alex/lsrc/qemu/qemu.git/target/xtensa/translate.c:3214
  #12 0x00005555555dbf00 in tb_gen_code (cpu=0x5555560ff4f0, pc=537034751, cs_base=0, flags=229393, cflags=0) at /home/alex/lsrc/qemu/qemu.git/translate-all.c:1281
  #13 0x00005555555de436 in tb_find (cpu=0x5555560ff4f0, last_tb=0x0, tb_exit=0) at /home/alex/lsrc/qemu/qemu.git/cpu-exec.c:370
  #14 0x00005555555decaa in cpu_exec (cpu=0x5555560ff4f0) at /home/alex/lsrc/qemu/qemu.git/cpu-exec.c:685
  #15 0x0000555555610643 in tcg_cpu_exec (cpu=0x5555560ff4f0) at /home/alex/lsrc/qemu/qemu.git/cpus.c:1254
  #16 0x00005555556108b8 in qemu_tcg_rr_cpu_thread_fn (arg=0x5555560ff4f0) at /home/alex/lsrc/qemu/qemu.git/cpus.c:1350
  #17 0x00007fffdf6606ba in start_thread (arg=0x7fffcca12700) at pthread_create.c:333
  #18 0x00007fffdf39682d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109


--
Alex Bennée

Re: [Qemu-devel] xtensa failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Peter Maydell]

On 1 March 2017 at 20:32, Alex Bennée <alex.bennee@linaro.org> wrote:
> However I ran into another problem. Code generation leads to a tlb_fill
> which runs afoul of a nested tb_lock(). I'm pretty sure the front-end is
> using the wrong thing to fetch code:

Isn't that the expected (if admittedly kinda dumb) thing where
when we fail a code load during translation it causes us
to attempt a recursive translation before we finally
figure out that it really isn't going to work and longjump
right out to the top level? It's silly and we should
probably at some point figure out a way to do it more
cleanly, but it doesn't actually cause any problem pre-MTTCG...

thanks
-- PMM

Re: [Qemu-devel] mips failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Yongbok Kim]

On 01/03/2017 18:41, Thomas Huth wrote:
> On 01.03.2017 12:36, Alex Bennée wrote:
>>
>> Peter Maydell <peter.maydell@linaro.org> writes:
>>
>>> I got a make check failure on aarch64 host running a sparc64 test:
>>>
>>>
>>> TEST: tests/prom-env-test... (pid=13573)
>>>   /sparc64/prom-env/sun4u:                                             **
>>> ERROR:/home/pm215/qemu/translate-common.c:34:tcg_handle_interrupt:
>>> assertion failed: (qemu_mutex_iothread_locked())
> [...]
>> What will be useful for all these reports is the backtrace. Then it's
>> fairly simple to identify the thing triggering the interrupt and
>> identify the correct place for the locking.
> 
> xtensa-softmmu crashes, too:
> 



Hi,

mips softmmu crashes as well.

**
ERROR:/user/ygk/qemu/master/translate-common.c:34:tcg_handle_interrupt:
assertion failed: (qemu_mutex_iothread_locked())

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x7fffc986d700 (LWP 17296)]
0x00007ffff5690635 in raise () from /lib64/libc.so.6
Missing separate debuginfos, use: debuginfo-install
bzip2-libs-1.0.5-7.el6_0.x86_64 glib2-2.28.8-4.el6.x86_64
glibc-2.12-1.132.el6_5.4.x86_64 libgcc-4.4.7-11.el6.x86_64
libstdc++-4.4.7-11.el6.x86_64 z
lib-1.2.3-29.el6.x86_64
(gdb) where
#0  0x00007ffff5690635 in raise () from /lib64/libc.so.6
#1  0x00007ffff5691e15 in abort () from /lib64/libc.so.6
#2  0x00007ffff6416324 in g_assertion_message () from /lib64/libglib-2.0.so.0
#3  0x00007ffff64168f0 in g_assertion_message_expr () from
/lib64/libglib-2.0.so.0
#4  0x00007ffff7578a6f in tcg_handle_interrupt (cpu=0x7ffff8aba600, mask=2)
at /user/ygk/qemu/master/translate-common.c:34
#5  0x00007ffff7659b2e in cpu_interrupt (cpu=0x7ffff8aba600, mask=2) at
/user/ygk/qemu/master/include/qom/cpu.h:801
#6  0x00007ffff7659c5c in cpu_mips_irq_request (opaque=0x7ffff8aba600,
irq=7, level=1) at /user/ygk/qemu/master/hw/mips/mips_int.c:55
#7  0x00007ffff77b9f3d in qemu_set_irq (irq=0x7ffff8aecc10, level=1) at
/user/ygk/qemu/master/hw/core/irq.c:45
#8  0x00007ffff765937c in qemu_irq_raise (irq=0x7ffff8aecc10) at
/user/ygk/qemu/master/include/hw/irq.h:16
#9  0x00007ffff76596ea in cpu_mips_timer_expire (env=0x7ffff8ac2890) at
/user/ygk/qemu/master/hw/mips/cputimer.c:73
#10 0x00007ffff7659789 in cpu_mips_get_count (env=0x7ffff8ac2890) at
/user/ygk/qemu/master/hw/mips/cputimer.c:87
#11 0x00007ffff76d2056 in helper_mfc0_count (env=0x7ffff8ac2890) at
/user/ygk/qemu/master/target/mips/op_helper.c:830
#12 0x00007fffd4e328b1 in code_gen_buffer ()
#13 0x00007ffff75778f1 in cpu_tb_exec (cpu=0x7ffff8aba600,
itb=0x7fffcb37d9f0) at /user/ygk/qemu/master/cpu-exec.c:165
#14 0x00007ffff75786ca in cpu_loop_exec_tb (cpu=0x7ffff8aba600,
tb=0x7fffcb37d9f0, last_tb=0x7fffc986caa0, tb_exit=0x7fffc986cab0,
sc=0x7fffc986ca80) at /user/ygk/qemu/master/cpu-exec.c:584
#15 0x00007ffff757899a in cpu_exec (cpu=0x7ffff8aba600) at
/user/ygk/qemu/master/cpu-exec.c:686
#16 0x00007ffff75b4495 in tcg_cpu_exec (cpu=0x7ffff8aba600) at
/user/ygk/qemu/master/cpus.c:1251
#17 0x00007ffff75b4769 in qemu_tcg_rr_cpu_thread_fn (arg=0x7ffff8aba600) at
/user/ygk/qemu/master/cpus.c:1347
#18 0x00007ffff59f99d1 in start_thread () from /lib64/libpthread.so.0
#19 0x00007ffff574686d in clone () from /lib64/libc.so.6
(gdb)

Regards,
Yongbok

Re: [Qemu-devel] mips failure: "tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())"

[Alex Bennée]

Yongbok Kim <yongbok.kim@imgtec.com> writes:

> On 01/03/2017 18:41, Thomas Huth wrote:
>> On 01.03.2017 12:36, Alex Bennée wrote:
>>>
>>> Peter Maydell <peter.maydell@linaro.org> writes:
>>>
>>>> I got a make check failure on aarch64 host running a sparc64 test:
>>>>
>>>>
>>>> TEST: tests/prom-env-test... (pid=13573)
>>>>   /sparc64/prom-env/sun4u:                                             **
>>>> ERROR:/home/pm215/qemu/translate-common.c:34:tcg_handle_interrupt:
>>>> assertion failed: (qemu_mutex_iothread_locked())
>> [...]
>>> What will be useful for all these reports is the backtrace. Then it's
>>> fairly simple to identify the thing triggering the interrupt and
>>> identify the correct place for the locking.
>>
>> xtensa-softmmu crashes, too:
>>
>
>
>
> Hi,
>
> mips softmmu crashes as well.
>
> **
> ERROR:/user/ygk/qemu/master/translate-common.c:34:tcg_handle_interrupt:
> assertion failed: (qemu_mutex_iothread_locked())

So in my next series I'm going to downgrade these assertions to
--enable-debug-tcg builds as otherwise its going to be a bit
whack-a-mole frontends that have yet to be converted to be MTTCG
capable.

That said:

>
> Program received signal SIGABRT, Aborted.
> [Switching to Thread 0x7fffc986d700 (LWP 17296)]
> 0x00007ffff5690635 in raise () from /lib64/libc.so.6
> Missing separate debuginfos, use: debuginfo-install
> bzip2-libs-1.0.5-7.el6_0.x86_64 glib2-2.28.8-4.el6.x86_64
> glibc-2.12-1.132.el6_5.4.x86_64 libgcc-4.4.7-11.el6.x86_64
> libstdc++-4.4.7-11.el6.x86_64 z
> lib-1.2.3-29.el6.x86_64
> (gdb) where
> #0  0x00007ffff5690635 in raise () from /lib64/libc.so.6
> #1  0x00007ffff5691e15 in abort () from /lib64/libc.so.6
> #2  0x00007ffff6416324 in g_assertion_message () from /lib64/libglib-2.0.so.0
> #3  0x00007ffff64168f0 in g_assertion_message_expr () from
> /lib64/libglib-2.0.so.0
> #4  0x00007ffff7578a6f in tcg_handle_interrupt (cpu=0x7ffff8aba600, mask=2)
> at /user/ygk/qemu/master/translate-common.c:34
> #5  0x00007ffff7659b2e in cpu_interrupt (cpu=0x7ffff8aba600, mask=2) at
> /user/ygk/qemu/master/include/qom/cpu.h:801
> #6  0x00007ffff7659c5c in cpu_mips_irq_request (opaque=0x7ffff8aba600,
> irq=7, level=1) at /user/ygk/qemu/master/hw/mips/mips_int.c:55
> #7  0x00007ffff77b9f3d in qemu_set_irq (irq=0x7ffff8aecc10, level=1) at
> /user/ygk/qemu/master/hw/core/irq.c:45
> #8  0x00007ffff765937c in qemu_irq_raise (irq=0x7ffff8aecc10) at
> /user/ygk/qemu/master/include/hw/irq.h:16
> #9  0x00007ffff76596ea in cpu_mips_timer_expire (env=0x7ffff8ac2890) at
> /user/ygk/qemu/master/hw/mips/cputimer.c:73
> #10 0x00007ffff7659789 in cpu_mips_get_count (env=0x7ffff8ac2890) at
> /user/ygk/qemu/master/hw/mips/cputimer.c:87

This is the division between cpu emulation and hw emulation where the
BQL should be taken. So I think helper_mfc0_count and helper_rdhwr_cc
should wrap their calls into the HW emulation with a BQL lock.

> #11 0x00007ffff76d2056 in helper_mfc0_count (env=0x7ffff8ac2890) at
> /user/ygk/qemu/master/target/mips/op_helper.c:830
> #12 0x00007fffd4e328b1 in code_gen_buffer ()
> #13 0x00007ffff75778f1 in cpu_tb_exec (cpu=0x7ffff8aba600,
> itb=0x7fffcb37d9f0) at /user/ygk/qemu/master/cpu-exec.c:165
> #14 0x00007ffff75786ca in cpu_loop_exec_tb (cpu=0x7ffff8aba600,
> tb=0x7fffcb37d9f0, last_tb=0x7fffc986caa0, tb_exit=0x7fffc986cab0,
> sc=0x7fffc986ca80) at /user/ygk/qemu/master/cpu-exec.c:584
> #15 0x00007ffff757899a in cpu_exec (cpu=0x7ffff8aba600) at
> /user/ygk/qemu/master/cpu-exec.c:686
> #16 0x00007ffff75b4495 in tcg_cpu_exec (cpu=0x7ffff8aba600) at
> /user/ygk/qemu/master/cpus.c:1251
> #17 0x00007ffff75b4769 in qemu_tcg_rr_cpu_thread_fn (arg=0x7ffff8aba600) at
> /user/ygk/qemu/master/cpus.c:1347
> #18 0x00007ffff59f99d1 in start_thread () from /lib64/libpthread.so.0
> #19 0x00007ffff574686d in clone () from /lib64/libc.so.6
> (gdb)
>
> Regards,
> Yongbok


--
Alex Bennée