[Qemu-devel] lm32: tcg_handle_interrupt: assertion failed: (qemu_mutex_iothread_locked())

["Philippe Mathieu-Daudé" <f4bug@amsat.org>]

[-- Attachment #1: Type: text/plain, Size: 17738 bytes --]

Hi Paolo and Michael,

Using LM32 images from http://milkymist.walle.cc/README.qemu
(Whether http://milkymist.walle.cc/updates/2012-03-01/flickernoise or
the flash image) I get:

$ lm32-softmmu/qemu-system-lm32 -M milkymist -kernel flickernoise \
    -d int,guest_errors,trace:lm32\*
16363@1525743492.227513:lm32_pic_set_im im 0x00000000
16363@1525743492.227525:lm32_pic_lower_irq Lower CPU interrupt
16363@1525743492.481203:lm32_pic_interrupt Set IRQ0 0
16363@1525743492.481221:lm32_pic_lower_irq Lower CPU interrupt
16363@1525743492.556285:lm32_pic_get_im im 0x00000000
16363@1525743492.556295:lm32_pic_set_im im 0x00000001
16363@1525743492.556297:lm32_pic_lower_irq Lower CPU interrupt
16363@1525743492.556361:lm32_pic_interrupt Set IRQ0 0
16363@1525743492.556364:lm32_pic_lower_irq Lower CPU interrupt
16363@1525743492.556557:lm32_pic_get_im im 0x00000001
16363@1525743492.556570:lm32_pic_set_im im 0x00000005
16363@1525743492.556572:lm32_pic_lower_irq Lower CPU interrupt
16363@1525743492.559682:lm32_pic_get_im im 0x00000005
16363@1525743492.559687:lm32_pic_set_im im 0x00008005
16363@1525743492.559689:lm32_pic_lower_irq Lower CPU interrupt
16363@1525743492.560139:lm32_pic_get_im im 0x00008005
16363@1525743492.560142:lm32_pic_set_im im 0x00008015
16363@1525743492.560144:lm32_pic_lower_irq Lower CPU interrupt
16363@1525743492.560167:lm32_pic_get_im im 0x00008015
16363@1525743492.560169:lm32_pic_set_im im 0x00008035
16363@1525743492.560170:lm32_pic_lower_irq Lower CPU interrupt
16363@1525743492.560181:lm32_pic_get_im im 0x00008035
16363@1525743492.560183:lm32_pic_set_im im 0x00008075
16363@1525743492.560185:lm32_pic_lower_irq Lower CPU interrupt
16363@1525743492.560196:lm32_pic_get_im im 0x00008075
16363@1525743492.560198:lm32_pic_set_im im 0x000080f5
16363@1525743492.560199:lm32_pic_lower_irq Lower CPU interrupt
16363@1525743492.560413:lm32_pic_get_im im 0x000080f5
16363@1525743492.560417:lm32_pic_set_im im 0x000081f5
16363@1525743492.560418:lm32_pic_lower_irq Lower CPU interrupt
16363@1525743492.560590:lm32_pic_get_im im 0x000081f5
16363@1525743492.560593:lm32_pic_set_im im 0x000083f5
16363@1525743492.560594:lm32_pic_lower_irq Lower CPU interrupt
16363@1525743492.560935:lm32_pic_get_im im 0x000083f5
16363@1525743492.560938:lm32_pic_set_im im 0x0000c3f5
16363@1525743492.560939:lm32_pic_lower_irq Lower CPU interrupt
16363@1525743492.561088:lm32_pic_get_im im 0x0000c3f5
16363@1525743492.561091:lm32_pic_set_im im 0x0000d3f5
16363@1525743492.561092:lm32_pic_lower_irq Lower CPU interrupt
16363@1525743492.562372:lm32_pic_get_im im 0x0000d3f5
16363@1525743492.562376:lm32_pic_set_im im 0x0000f3f5
16363@1525743492.562377:lm32_pic_lower_irq Lower CPU interrupt
16363@1525743492.562983:lm32_pic_get_im im 0x0000f3f5
16363@1525743492.562988:lm32_pic_set_im im 0x0000f3f7
16363@1525743492.562989:lm32_pic_lower_irq Lower CPU interrupt
16363@1525743492.566610:lm32_pic_interrupt Set IRQ2 1
16363@1525743492.566621:lm32_pic_raise_irq Raise CPU interrupt
16363@1525743492.566624:lm32_pic_interrupt Set IRQ2 0
16363@1525743492.566626:lm32_pic_raise_irq Raise CPU interrupt
exception at pc=4016e6c0 type=6
IN: PC=400000c0 start
16363@1525743492.567928:lm32_pic_get_ip ip 0x00000004
16363@1525743492.567932:lm32_pic_get_im im 0x0000f3f7
ie=00000002 (IE=0 EIE=1 BIE=0) im=0000f3f7 ip=00000004
eba=40000000 deba=00000000
r00=00000000 r01=00000001 r02=408fcfc0 r03=00000000
r04=00000000 r05=40127944 r06=00000003 r07=00000004
r08=6f6c6500 r09=00000002 r10=00000004 r11=408fcf00
r12=00000000 r13=00000000 r14=00000000 r15=00000000
r16=00000000 r17=00000000 r18=00000000 r19=00000000
r20=00000000 r21=00000000 r22=00000000 r23=00000000
r24=00000000 r25=00000000 r26=401f931c r27=40906f7c
r28=40906f70 r29=4016e698 r30=4016e6c0 r31=00000000


16363@1525743492.568052:lm32_pic_get_ip ip 0x00000004
16363@1525743492.568055:lm32_pic_get_im im 0x0000f3f7
16363@1525743492.568248:lm32_pic_set_ip ip 0x00000004
16363@1525743492.568251:lm32_pic_lower_irq Lower CPU interrupt
16363@1525743492.576609:lm32_pic_interrupt Set IRQ2 1
16363@1525743492.576618:lm32_pic_raise_irq Raise CPU interrupt
16363@1525743492.576622:lm32_pic_interrupt Set IRQ2 0
16363@1525743492.576624:lm32_pic_raise_irq Raise CPU interrupt
exception at pc=400fa15c type=6
IN: PC=400000c0 start
16363@1525743492.576652:lm32_pic_get_ip ip 0x00000004
16363@1525743492.576657:lm32_pic_get_im im 0x0000f3f7
ie=00000002 (IE=0 EIE=1 BIE=0) im=0000f3f7 ip=00000004
eba=40000000 deba=00000000
r00=00000000 r01=00000000 r02=00000000 r03=4090f13c
r04=00000000 r05=400fa15c r06=40902270 r07=00000000
r08=6e000000 r09=00000020 r10=0000000f r11=418fc3e0
r12=418fc514 r13=00000000 r14=00000000 r15=00000000
r16=00000000 r17=00000000 r18=00000000 r19=00000000
r20=00000000 r21=00000000 r22=00000000 r23=00000000
r24=00000000 r25=401f89d0 r26=401f931c r27=4090f530
r28=4090f130 r29=40124b90 r30=400fa15c r31=00000000


16363@1525743492.576700:lm32_pic_get_ip ip 0x00000004
16363@1525743492.576704:lm32_pic_get_im im 0x0000f3f7
16363@1525743492.576711:lm32_pic_set_ip ip 0x00000004
16363@1525743492.576714:lm32_pic_lower_irq Lower CPU interrupt
16363@1525743492.578691:lm32_pic_interrupt Set IRQ0 0
16363@1525743492.578699:lm32_pic_lower_irq Lower CPU interrupt
16363@1525743492.586572:lm32_pic_interrupt Set IRQ0 1
16363@1525743492.586582:lm32_pic_raise_irq Raise CPU interrupt
16363@1525743492.586627:lm32_pic_interrupt Set IRQ2 1
16363@1525743492.586632:lm32_pic_raise_irq Raise CPU interrupt
16363@1525743492.586635:lm32_pic_interrupt Set IRQ2 0
16363@1525743492.586648:lm32_pic_raise_irq Raise CPU interrupt
exception at pc=401086e4 type=6
IN: PC=400000c0 start
16363@1525743492.586713:lm32_pic_get_ip ip 0x00000005
16363@1525743492.586716:lm32_pic_get_im im 0x0000f3f7
ie=00000002 (IE=0 EIE=1 BIE=0) im=0000f3f7 ip=00000005
eba=40000000 deba=00000000
r00=00000000 r01=00000000 r02=e0000000 r03=0000000d
r04=400f9f40 r05=408fd028 r06=00000002 r07=00000000
r08=00000003 r09=00000000 r10=4090f8a8 r11=418fc118
r12=00000003 r13=fffffffe r14=00000002 r15=00000001
r16=401c14ac r17=00000001 r18=00000001 r19=00000000
r20=00000000 r21=00000000 r22=00000000 r23=00000000
r24=00000000 r25=401f89d0 r26=401f931c r27=418fca90
r28=4090ea94 r29=40108710 r30=401086e4 r31=00000000


16363@1525743492.586741:lm32_pic_get_ip ip 0x00000005
16363@1525743492.586743:lm32_pic_get_im im 0x0000f3f7
16363@1525743492.586857:lm32_pic_interrupt Set IRQ0 0
16363@1525743492.586860:lm32_pic_raise_irq Raise CPU interrupt
16363@1525743492.587192:lm32_pic_set_ip ip 0x00000001
16363@1525743492.587195:lm32_pic_raise_irq Raise CPU interrupt
**
ERROR:qemu/accel/tcg/tcg-all.c:42:tcg_handle_interrupt: assertion
failed: (qemu_mutex_iothread_locked())

$ lm32-softmmu/qemu-system-lm32 -M milkymist -kernel flickernoise \
    -d in_asm,int,guest_errors,trace:\*,trace:-object_\* 2>&1 | tail -40
0x400fc83c:  78 01 40 0f    orhi     r1, r0, 0x400f
0x400fc840:  34 02 00 0f    mvi      r2, 15
0x400fc844:  37 83 00 10    addi     r3, sp, 16
0x400fc848:  38 21 c5 b8    ori      r1, r1, 0xc5b8
0x400fc84c:  f8 00 9b c2    calli    40123754
16390@1525743546.714083:translate_block tb:0x7fb98fe027c0,
pc:0x400fc83c, tb_code:0x7fb98fe02840
16390@1525743546.714101:qemu_mutex_unlock released mutex 0x55e869b01428
(qemu/accel/tcg/translate-all.c:197)
16390@1525743546.714104:qemu_mutex_lock waiting on mutex 0x55e869af3660
(qemu/cpus.c:1765)
16390@1525743546.714106:qemu_mutex_locked taken mutex 0x55e869af3660
(qemu/cpus.c:1765)
16390@1525743546.714109:qemu_mutex_unlock released mutex 0x55e869af3660
(qemu/cpus.c:1773)
16390@1525743546.714114:guest_mem_before_exec cpu=0x55e86b632fd0
vaddr=0x00000000408fb000 info=26
16390@1525743546.714116:qemu_mutex_lock waiting on mutex 0x55e869af3660
(qemu/cpus.c:1765)
16390@1525743546.714118:qemu_mutex_locked taken mutex 0x55e869af3660
(qemu/cpus.c:1765)
16390@1525743546.714120:qemu_mutex_unlock released mutex 0x55e869af3660
(qemu/cpus.c:1773)
16390@1525743546.714122:guest_mem_before_exec cpu=0x55e86b632fd0
vaddr=0x00000000408f84c8 info=10
16390@1525743546.714124:guest_mem_before_exec cpu=0x55e86b632fd0
vaddr=0x00000000408fb0c0 info=10
16390@1525743546.714125:guest_mem_before_exec cpu=0x55e86b632fd0
vaddr=0x00000000408fb010 info=26
16390@1525743546.714127:guest_mem_before_exec cpu=0x55e86b632fd0
vaddr=0x00000000408fb0c0 info=26
16390@1525743546.714128:qemu_mutex_lock waiting on mutex 0x55e869af3660
(qemu/cpus.c:1765)
16390@1525743546.714130:qemu_mutex_locked taken mutex 0x55e869af3660
(qemu/cpus.c:1765)
16390@1525743546.714132:qemu_mutex_unlock released mutex 0x55e869af3660
(qemu/cpus.c:1773)
16390@1525743546.714134:guest_mem_before_exec cpu=0x55e86b632fd0
vaddr=0x00000000408fb000 info=10
16390@1525743546.714135:qemu_mutex_lock waiting on mutex 0x55e869af3660
(qemu/cpus.c:1765)
16390@1525743546.714137:qemu_mutex_locked taken mutex 0x55e869af3660
(qemu/cpus.c:1765)
16390@1525743546.714139:qemu_mutex_unlock released mutex 0x55e869af3660
(qemu/cpus.c:1773)
16390@1525743546.714141:qemu_mutex_lock waiting on mutex 0x55e869b01428
(qemu/accel/tcg/translate-all.c:189)
16390@1525743546.714143:qemu_mutex_locked taken mutex 0x55e869b01428
(qemu/accel/tcg/translate-all.c:189)

0x400fc850:  34 01 00 0f    mvi      r1, 15
0x400fc854:  fb ff fa 92    calli    400fb29c
16390@1525743546.714155:translate_block tb:0x7fb98fe028c0,
pc:0x400fc850, tb_code:0x7fb98fe02940
16390@1525743546.714170:qemu_mutex_unlock released mutex 0x55e869b01428
(qemu/accel/tcg/translate-all.c:197)
16390@1525743546.714172:qemu_mutex_lock waiting on mutex 0x55e869af3660
(qemu/cpus.c:1765)
16390@1525743546.714174:qemu_mutex_locked taken mutex 0x55e869af3660
(qemu/cpus.c:1765)
16390@1525743546.714176:qemu_mutex_unlock released mutex 0x55e869af3660
(qemu/cpus.c:1773)
16390@1525743546.714179:lm32_pic_get_im im 0x00000005
16390@1525743546.714181:lm32_pic_set_im im 0x00008005
16390@1525743546.714183:lm32_pic_raise_irq Raise CPU interrupt
**
ERROR:qemu/accel/tcg/tcg-all.c:42:tcg_handle_interrupt: assertion
failed: (qemu_mutex_iothread_locked())

$lm32-softmmu/qemu-system-lm32 -M milkymist \
    -pflash flash-2012-07-09.img \
    -d in_asm,int,guest_errors,trace:\*,trace:-object_\* 2>&1 | tail -40
0x00866c28:  58 40 00 00    sw       (r2+0), r0
0x00866c2c:  78 02 e0 00    orhi     r2, r0, 0xe000
0x00866c30:  58 41 00 00    sw       (r2+0), r1
0x00866c34:  d0 24 00 00    wcsr     im, r4
16512@1525743851.406891:translate_block tb:0x7f856cfd0d00, pc:0x866c28,
tb_code:0x7f856cfd0d80
16512@1525743851.406910:qemu_mutex_unlock released mutex 0x5576313a7428
(qemu/accel/tcg/translate-all.c:197)
16512@1525743851.406912:guest_mem_before_exec cpu=0x557631fac0d0
vaddr=0x0000000044000434 info=26
16512@1525743851.406914:guest_mem_before_exec cpu=0x557631fac0d0
vaddr=0x00000000e0000000 info=26
16512@1525743851.406916:qemu_mutex_lock waiting on mutex 0x557631399660
(qemu/cpus.c:1765)
16512@1525743851.406918:qemu_mutex_locked taken mutex 0x557631399660
(qemu/cpus.c:1765)
16512@1525743851.406921:memory_region_subpage_write cpu 0 mr
0x5576321d07d0 offset 0x0 value 0x56 size 4
16512@1525743851.406924:memory_region_ops_write cpu 0 mr 0x557631fec500
addr 0x60000000 value 0x56 size 4
16512@1525743851.406926:milkymist_uart_memory_write addr 0x00000000
value 0x00000056
16512@1525743851.406928:qemu_mutex_lock waiting on mutex 0x557631f8ec18
(qemu/chardev/char.c:109)
16512@1525743851.406931:qemu_mutex_locked taken mutex 0x557631f8ec18
(qemu/chardev/char.c:109)
16512@1525743851.406941:qemu_mutex_unlock released mutex 0x557631f8ec18
(qemu/chardev/char.c:130)
16512@1525743851.406943:milkymist_uart_raise_irq Raise IRQ
16512@1525743851.406944:qemu_mutex_lock waiting on mutex 0x557631399660
(qemu/cpus.c:1765)
16512@1525743851.406946:lm32_pic_interrupt Set IRQ0 1
16512@1525743851.406954:lm32_pic_lower_irq Lower CPU interrupt
16512@1525743851.406957:qemu_mutex_unlock released mutex 0x557631399660
(qemu/cpus.c:1773)
16512@1525743851.406959:qemu_mutex_locked taken mutex 0x557631399660
(qemu/cpus.c:1765)
16512@1525743851.406960:lm32_pic_set_im im 0x00000001
16512@1525743851.406967:lm32_pic_raise_irq Raise CPU interrupt
16512@1525743851.406964:lockcnt_fast_path_attempt lockcnt 0x557631f131cc
fast path 0->4
16512@1525743851.406974:lockcnt_fast_path_success lockcnt 0x557631f131cc
fast path 0->4 succeeded
16512@1525743851.406978:lockcnt_fast_path_attempt lockcnt 0x557631f11e1c
fast path 0->4
16512@1525743851.406982:lockcnt_fast_path_success lockcnt 0x557631f11e1c
fast path 0->4 succeeded
**
ERROR:qemu/accel/tcg/tcg-all.c:42:tcg_handle_interrupt: assertion
failed: (qemu_mutex_iothread_locked())
16512@1525743851.406987:qemu_mutex_lock waiting on mutex 0x557631f11bc8
(qemu/util/qemu-timer.c:520)
16512@1525743851.406991:qemu_mutex_locked taken mutex 0x557631f11bc8
(qemu/util/qemu-timer.c:520)
16512@1525743851.406995:qemu_mutex_unlock released mutex 0x557631f11bc8
(qemu/util/qemu-timer.c:523)
16512@1525743851.406999:qemu_mutex_lock waiting on mutex 0x557631f11c38
(qemu/util/qemu-timer.c:520)
16512@1525743851.407003:qemu_mutex_locked taken mutex 0x557631f11c38
(qemu/util/qemu-timer.c:520)
16512@1525743851.407007:qemu_mutex_unlock released mutex 0x557631f11c38
(qemu/util/qemu-timer.c:523)
16512@1525743851.407011:qemu_mutex_lock waiting on mutex 0x5576313b8fa0
(qemu/vl.c:769)
16512@1525743851.407015:qemu_mutex_locked taken mutex 0x5576313b8fa0
(qemu/vl.c:769)
16512@1525743851.407019:qemu_mutex_unlock released mutex 0x5576313b8fa0
(qemu/vl.c:772)
16512@1525743851.407023:qemu_mutex_lock waiting on mutex 0x557631f11bc8
(qemu/util/qemu-timer.c:234)
16512@1525743851.407027:qemu_mutex_locked taken mutex 0x557631f11bc8
(qemu/util/qemu-timer.c:234)
16512@1525743851.407031:qemu_mutex_unlock released mutex 0x557631f11bc8
(qemu/util/qemu-timer.c:240)
16512@1525743851.407035:qemu_mutex_lock waiting on mutex 0x557631f11c38
(qemu/util/qemu-timer.c:234)
16512@1525743851.407039:qemu_mutex_locked taken mutex 0x557631f11c38
(qemu/util/qemu-timer.c:234)
16512@1525743851.407043:qemu_mutex_unlock released mutex 0x557631f11c38
(qemu/util/qemu-timer.c:240)
16512@1525743851.407052:qemu_mutex_unlock released mutex 0x557631399660
(qemu/cpus.c:1773)

(gdb) bt
#0  0x00007fe1640b7e7b in __GI_raise (sig=sig@entry=6) at
../sysdeps/unix/sysv/linux/raise.c:51
#1  0x00007fe1640b9231 in __GI_abort () at abort.c:79
#2  0x00007fe17d5eefa5 in g_assertion_message () at
/usr/lib/x86_64-linux-gnu/libglib-2.0.so.0
#3  0x00007fe17d5ef00a in g_assertion_message_expr () at
/usr/lib/x86_64-linux-gnu/libglib-2.0.so.0
#4  0x0000559d92ace7d5 in tcg_handle_interrupt (cpu=0x559d93aa35d0,
mask=2) at qemu/accel/tcg/tcg-all.c:42
#5  0x0000559d92af1b3c in cpu_interrupt (cpu=0x559d93aa35d0, mask=2) at
qemu/include/qom/cpu.h:848
#6  0x0000559d92af2516 in cpu_irq_handler (opaque=0x559d93aa35d0, irq=0,
level=1) at qemu/hw/lm32/milkymist.c:59
#7  0x0000559d92b6639d in qemu_set_irq (irq=0x559d93a0f250, level=1) at
qemu/hw/core/irq.c:45
#8  0x0000559d92b76d5f in qemu_irq_raise (irq=0x559d93a0f250) at
qemu/include/hw/irq.h:16
#9  0x0000559d92b7723e in update_irq (s=0x559d93adba00) at
qemu/hw/intc/lm32_pic.c:51
#10 0x0000559d92b7738e in lm32_pic_set_im (d=0x559d93adba00, im=1) at
qemu/hw/intc/lm32_pic.c:82
#11 0x0000559d92af72e0 in helper_wcsr_im (env=0x559d93aab870, im=1) at
qemu/target/lm32/op_helper.c:105
#12 0x00007fe155e250ca in code_gen_buffer ()
#13 0x0000559d92adec8e in cpu_tb_exec (cpu=0x559d93aa35d0,
itb=0x7fe155e24fc0 <code_gen_buffer+49043>)
    at qemu/accel/tcg/cpu-exec.c:169
#14 0x0000559d92adf9e1 in cpu_loop_exec_tb (cpu=0x559d93aa35d0,
tb=0x7fe155e24fc0 <code_gen_buffer+49043>, last_tb=0x7fe154e13608,
tb_exit=0x7fe154e13604) at qemu/accel/tcg/cpu-exec.c:626
#15 0x0000559d92adfcd3 in cpu_exec (cpu=0x559d93aa35d0) at
qemu/accel/tcg/cpu-exec.c:734
#16 0x0000559d92aa29cf in tcg_cpu_exec (cpu=0x559d93aa35d0) at
qemu/cpus.c:1362
#17 0x0000559d92aa2bfb in qemu_tcg_rr_cpu_thread_fn (arg=0x559d93aa35d0)
at qemu/cpus.c:1461
#18 0x00007fe1644445aa in start_thread (arg=0x7fe154e16700) at
pthread_create.c:463
#19 0x00007fe164179cbf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:95
(gdb) info thr
  Id   Target Id         Frame
* 1    Thread 0x7fe154e16700 (LWP 16587) __GI_raise (sig=sig@entry=6) at
../sysdeps/unix/sysv/linux/raise.c:51
  2    Thread 0x7fe155e18700 (LWP 16585) 0x00007fe16444cf62 in
futex_abstimed_wait_cancelable (private=0, abstime=0x7fe155e15650,
expected=0,
    futex_word=0x559d93a89658) at
../sysdeps/unix/sysv/linux/futex-internal.h:205
  3    Thread 0x7fe158619700 (LWP 16584) syscall () at
../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
  4    Thread 0x7fe1807b3f80 (LWP 16582) 0x00007fe16416f6d6 in
__GI_ppoll (fds=0x559d93d73ce0, nfds=6, timeout=<optimized out>,
sigmask=0x0)
    at ../sysdeps/unix/sysv/linux/ppoll.c:39
  5    Thread 0x7fe13d38d700 (LWP 16588) 0x00007fe16416f5d9 in
__GI___poll (fds=0x559d93cff580, nfds=1, timeout=-1)
    at ../sysdeps/unix/sysv/linux/poll.c:29
  6    Thread 0x7fe155617700 (LWP 16586) 0x00007fe16416f6d6 in
__GI_ppoll (fds=0x7fe148000b20, nfds=1, timeout=<optimized out>,
sigmask=0x0)
    at ../sysdeps/unix/sysv/linux/ppoll.c:39
  7    Thread 0x7fe13cb8c700 (LWP 16589) 0x00007fe16416f5d9 in
__GI___poll (fds=0x559d93d11400, nfds=2, timeout=-1)
    at ../sysdeps/unix/sysv/linux/poll.c:29

Trying to bisect, same happens with v2.12.0 & v2.11.0, however I'm
unable to build v2.10.0 ...

Any idea what's going on?

Regards,

Phil.


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 833 bytes --]