Re: [Qemu-ppc] How to debug crash in TCG code?

[BALATON Zoltan]

Hello,

I'm still trying to debug a crash that I don't understand why is
happening and how to debug it further. Any hints are apreciated. I've 
described the problem previously in
http://lists.nongnu.org/archive/html/qemu-ppc/2017-08/msg00249.html
but I've dug deeper now, here's what I've found.

I'm running with -accel tcg,thread=single -singlestep so it does not seem 
to be a multi threading problem. The seg fault happens when U-Boot running 
on the emulated embedded PPC SoC accesses a PCI device but after several 
successful iteration of the same access so it seems to be some internal 
inconsistency that arrises while QEMU is running, not something generally 
broken. It is also dependent on code run by the client or QEMU, so e.g. it 
disappears when I enable -d in_asm or use a different U-Boot version. I'm 
not sure what exactly causes the bug to happen or disappear but I can 
reproduce it reliably with certain images at the same place. It always 
happens during io_readx or io_writex. Here's the info I could get with a 
debugger with some additional debug and trace messages enabled:

Here's the PCI device detected by U-Boot and BARs mapped:
The device is implemended here:
http://lists.nongnu.org/archive/html/qemu-ppc/2017-08/msg00246.html

address@hidden:pci_cfg_read sii3112 01:0 @0xe -> 0x0
tlb_set_page_with_attrs: vaddr=0ffb0800 paddr=0x000000000ffb0800 prot=7 idx=1
tlb_set_page_with_attrs: vaddr=0ff73c00 paddr=0x000000000ff73c00 prot=7 idx=1
address@hidden:pci_cfg_read sii3112 01:0 @0x0 -> 0x1095
address@hidden:pci_cfg_read sii3112 01:0 @0x2 -> 0x3112
address@hidden:pci_cfg_read sii3112 01:0 @0xa -> 0x104
tlb_set_page_with_attrs: vaddr=0ff74000 paddr=0x000000000ff74000 prot=7 idx=1
address@hidden:pci_cfg_read sii3112 01:0 @0xa -> 0x104
address@hidden:pci_cfg_read sii3112 01:0 @0x4 -> 0x0
address@hidden:pci_cfg_write sii3112 01:0 @0x10 <- 0xffffffff
address@hidden:pci_cfg_read sii3112 01:0 @0x10 -> 0xfffffff9
address@hidden:pci_cfg_write sii3112 01:0 @0x10 <- 0x1000
tlb_set_page_with_attrs: vaddr=0ff74800 paddr=0x000000000ff74800 prot=7 idx=1
address@hidden:pci_cfg_write sii3112 01:0 @0x14 <- 0xffffffff
address@hidden:pci_cfg_read sii3112 01:0 @0x14 -> 0xfffffffd
address@hidden:pci_cfg_write sii3112 01:0 @0x14 <- 0x1008
address@hidden:pci_cfg_write sii3112 01:0 @0x18 <- 0xffffffff
address@hidden:pci_cfg_read sii3112 01:0 @0x18 -> 0xfffffff9
address@hidden:pci_cfg_write sii3112 01:0 @0x18 <- 0x1010
address@hidden:pci_cfg_write sii3112 01:0 @0x1c <- 0xffffffff
address@hidden:pci_cfg_read sii3112 01:0 @0x1c -> 0xfffffffd
address@hidden:pci_cfg_write sii3112 01:0 @0x1c <- 0x1018
address@hidden:pci_cfg_write sii3112 01:0 @0x20 <- 0xffffffff
address@hidden:pci_cfg_read sii3112 01:0 @0x20 -> 0xfffffff1
address@hidden:pci_cfg_write sii3112 01:0 @0x20 <- 0x1020
address@hidden:pci_cfg_write sii3112 01:0 @0x24 <- 0xffffffff
address@hidden:pci_cfg_read sii3112 01:0 @0x24 -> 0xfffffe00
address@hidden:pci_cfg_write sii3112 01:0 @0x24 <- 0x80000000
address@hidden:pci_cfg_write sii3112 01:0 @0x4 <- 0x7
address@hidden:pci_update_mappings_add d=0x55aca57d3ce0 00:01.0 0,0x1000+0x8
tlb_flush_nocheck: (count: 23)
address@hidden:pci_update_mappings_add d=0x55aca57d3ce0 00:01.0 1,0x1008+0x4
tlb_flush_nocheck: (count: 24)
address@hidden:pci_update_mappings_add d=0x55aca57d3ce0 00:01.0 2,0x1010+0x8
tlb_flush_nocheck: (count: 25)
address@hidden:pci_update_mappings_add d=0x55aca57d3ce0 00:01.0 3,0x1018+0x4
tlb_flush_nocheck: (count: 26)
address@hidden:pci_update_mappings_add d=0x55aca57d3ce0 00:01.0 4,0x1020+0x10
tlb_flush_nocheck: (count: 27)
address@hidden:pci_update_mappings_add d=0x55aca57d3ce0 00:01.0 
5,0x80000000+0x200

(BAR0-4 are alias memory regions to BAR5 so all access should go to BAR5 
at the end even if U-Boot accesses it through BAR0-4)
Here U-Boot starts using the device:

tlb_set_page_with_attrs: vaddr=dec00000 paddr=0x0000000c0ec00000 prot=3 idx=1
address@hidden:pci_cfg_read ppc4xx-host-bridge 00:0 @0xe -> 0x0
address@hidden:pci_cfg_read ppc4xx-host-bridge 00:0 @0x0 -> 0x1014
address@hidden:pci_cfg_read ppc4xx-host-bridge 00:0 @0x2 -> 0x27f
address@hidden:pci_cfg_read sii3112 01:0 @0xe -> 0x0
address@hidden:pci_cfg_read sii3112 01:0 @0x0 -> 0x1095
address@hidden:pci_cfg_read sii3112 01:0 @0x2 -> 0x3112
tlb_set_page_with_attrs: vaddr=00000800 paddr=0x0000000000000800 prot=7 idx=1
tlb_set_page_with_attrs: vaddr=0ff6f000 paddr=0x000000000ff6f000 prot=7 idx=1
tlb_set_page_with_attrs: vaddr=0ff74000 paddr=0x000000000ff74000 prot=7 idx=1
tlb_set_page_with_attrs: vaddr=0ff73c00 paddr=0x000000000ff73c00 prot=7 idx=1
tlb_set_page_with_attrs: vaddr=0ffb0c00 paddr=0x000000000ffb0c00 prot=7 idx=1
address@hidden:pci_cfg_write sii3112 01:0 @0x4 <- 0x7
address@hidden:pci_cfg_read sii3112 01:0 @0x8 -> 0x1040001
address@hidden:pci_cfg_write sii3112 01:0 @0xc <- 0x1
address@hidden:pci_cfg_read sii3112 01:0 @0x10 -> 0x1001
address@hidden:pci_cfg_read sii3112 01:0 @0x18 -> 0x1011
tlb_set_page_with_attrs: vaddr=0ffa3800 paddr=0x000000000ffa3800 prot=7 idx=1

And can talk to the device emulation:

tlb_set_page_with_attrs: vaddr=0ff89000 paddr=0x000000000ff89000 prot=7 idx=1
tlb_set_page_with_attrs: vaddr=d8001000 paddr=0x0000000c08001000 prot=3 idx=1
address@hidden:sii3112_write bmdma: write (size 1) 0x86 : 0xe0

Address 0x86 in BAR5 is accessed via vaddr d8001006 which is an alias via BAR0

tlb_set_page_with_attrs: vaddr=0ff8a400 paddr=0x000000000ff8a400 prot=7 idx=1
tlb_set_page_with_attrs: vaddr=0ffa3400 paddr=0x000000000ffa3400 prot=7 idx=1
tlb_set_page_with_attrs: vaddr=0ffc7800 paddr=0x000000000ffc7800 prot=7 idx=1
tlb_set_page_with_attrs: vaddr=d8001000 paddr=0x0000000c08001000 prot=3 idx=1
address@hidden:sii3112_set_irq channel 0 level 0
address@hidden:sii3112_read bmdma: read (size 1) 0x87 : 0x50
tlb_set_page_with_attrs: vaddr=0ff6f000 paddr=0x000000000ff6f000 prot=7 idx=1
tlb_set_page_with_attrs: vaddr=0df6d000 paddr=0x000000000df6d000 prot=7 idx=1
tlb_set_page_with_attrs: vaddr=0ffc0800 paddr=0x000000000ffc0800 prot=7 idx=1
tlb_set_page_with_attrs: vaddr=0ff87800 paddr=0x000000000ff87800 prot=7 idx=1
address@hidden:sii3112_write bmdma: write (size 1) 0xc6 : 0xe0
tlb_set_page_with_attrs: vaddr=d8001000 paddr=0x0000000c08001000 prot=3 idx=1
address@hidden:sii3112_set_irq channel 1 level 0
address@hidden:sii3112_read bmdma: read (size 1) 0xc7 : 0x00
tlb_set_page_with_attrs: vaddr=0ff8a400 paddr=0x000000000ff8a400 prot=7 idx=1

Accessing the device seems to work, it identifies the connected ATAPI CD 
emulation and can read from it, until it hits null pointer:

tlb_set_page_with_attrs: vaddr=0ff89800 paddr=0x000000000ff89800 prot=7 idx=1
address@hidden:sii3112_read bmdma: read (size 1) 0x82 : 0x02
address@hidden:sii3112_read bmdma: read (size 2) 0x80 : 0x8005
address@hidden:sii3112_read bmdma: read (size 2) 0x80 : 0x2100
address@hidden:sii3112_read bmdma: read (size 2) 0x80 : 0x1f
address@hidden:sii3112_read bmdma: read (size 2) 0x80 : 0x00
address@hidden:sii3112_read bmdma: read (size 2) 0x80 : 0x4551
address@hidden:sii3112_read bmdma: read (size 2) 0x80 : 0x554d
address@hidden:sii3112_read bmdma: read (size 2) 0x80 : 0x2020
address@hidden:sii3112_read bmdma: read (size 2) 0x80 : 0x2020
address@hidden:sii3112_read bmdma: read (size 2) 0x80 : 0x4551
address@hidden:sii3112_read bmdma: read (size 2) 0x80 : 0x554d
address@hidden:sii3112_read bmdma: read (size 2) 0x80 : 0x4420
address@hidden:sii3112_read bmdma: read (size 2) 0x80 : 0x4456
address@hidden:sii3112_read bmdma: read (size 2) 0x80 : 0x522d
address@hidden:sii3112_read bmdma: read (size 2) 0x80 : 0x4d4f
address@hidden:sii3112_read bmdma: read (size 2) 0x80 : 0x2020
address@hidden:sii3112_read bmdma: read (size 2) 0x80 : 0x2020
address@hidden:sii3112_read bmdma: read (size 2) 0x80 : 0x2e32
address@hidden:sii3112_set_irq channel 0 level 1
address@hidden:sii3112_set_irq channel 0 level 1
address@hidden:sii3112_read bmdma: read (size 2) 0x80 : 0x2b35
address@hidden:sii3112_set_irq channel 0 level 0
address@hidden:sii3112_read bmdma: read (size 1) 0x87 : 0x50
tlb_set_page_with_attrs: vaddr=0ff89c00 paddr=0x000000000ff89c00 prot=7 idx=1
tlb_set_page_with_attrs: vaddr=0ff8a000 paddr=0x000000000ff8a000 prot=7 idx=1
tlb_set_page_with_attrs: vaddr=0ff89400 paddr=0x000000000ff89400 prot=7 idx=1
tlb_set_page_with_attrs: vaddr=d8001000 paddr=0x0000000c08001000 prot=3 idx=1
address@hidden:sii3112_write bmdma: write (size 1) 0x86 : 0xe0
address@hidden:sii3112_set_irq channel 0 level 0
address@hidden:sii3112_read bmdma: read (size 1) 0x87 : 0x50
address@hidden:sii3112_write bmdma: write (size 1) 0x81 : 0x00
address@hidden:sii3112_write bmdma: write (size 1) 0x82 : 0x00
address@hidden:sii3112_write bmdma: write (size 1) 0x83 : 0x00
address@hidden:sii3112_write bmdma: write (size 1) 0x84 : 0x00
address@hidden:sii3112_write bmdma: write (size 1) 0x85 : 0x00
address@hidden:sii3112_write bmdma: write (size 1) 0x86 : 0xe0
address@hidden:sii3112_write bmdma: write (size 1) 0x87 : 0xa0
address@hidden:sii3112_set_irq channel 0 level 0
address@hidden:sii3112_read bmdma: read (size 1) 0x87 : 0x58
address@hidden:sii3112_write bmdma: write (size 2) 0x80 : 0x1b
address@hidden:sii3112_write bmdma: write (size 2) 0x80 : 0x00
address@hidden:sii3112_write bmdma: write (size 2) 0x80 : 0x03
address@hidden:sii3112_write bmdma: write (size 2) 0x80 : 0x00
address@hidden:sii3112_write bmdma: write (size 2) 0x80 : 0x00
address@hidden:sii3112_write bmdma: write (size 2) 0x80 : 0x00
address@hidden:sii3112_set_irq channel 0 level 1
address@hidden:sii3112_set_irq channel 0 level 0
address@hidden:sii3112_read bmdma: read (size 1) 0x87 : 0x50
address@hidden:sii3112_read bmdma: read (size 1) 0x85 : 0x00
address@hidden:sii3112_read bmdma: read (size 1) 0x84 : 0x00
address@hidden:sii3112_set_irq channel 0 level 0
address@hidden:sii3112_read bmdma: read (size 1) 0x87 : 0x50
tlb_set_page_with_attrs: vaddr=d8001000 paddr=0x0000000c08001000 prot=3 idx=1
Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7fffe87f7700 (LWP 4761)]
0x00005555557f4bc4 in io_writex (env=0x7fffe88002a0, iotlbentry=0x7fffe8811d60, 
mmu_idx=1, val=224, addr=3623882758, retaddr=140737099010411,
    size=1) at accel/tcg/cputlb.c:803
    803    if (mr->global_locking && !qemu_mutex_iothread_locked()) {
(gdb) bt
#0  0x00005555557f4bc4 in io_writex (env=0x7fffe88002a0, 
iotlbentry=0x7fffe8811d60, mmu_idx=1, val=224, addr=3623882758, 
retaddr=140737099010411,
    size=1) at accel/tcg/cputlb.c:803
#1  0x00005555557f5673 in io_writeb (env=0x7fffe88002a0, mmu_idx=1, index=4, 
val=224 '\340', addr=3623882758, retaddr=140737099010411)
    at accel/tcg/softmmu_template.h:265
#2  0x00005555557f57ff in helper_ret_stb_mmu (env=0x7fffe88002a0, 
addr=3623882758, val=224 '\340', oi=1, retaddr=140737099010411)
    at accel/tcg/softmmu_template.h:300
#3  0x00007fffe8cb116b in code_gen_buffer ()
#4  0x00005555557fdaf1 in cpu_tb_exec (cpu=0x7fffe87f8010, itb=0x7fffe8cb0780 
<code_gen_buffer+3753814>)
    at accel/tcg/cpu-exec.c:166
#5  0x00005555557fe936 in cpu_loop_exec_tb (cpu=0x7fffe87f8010, tb=0x7fffe8cb0780 
<code_gen_buffer+3753814>, last_tb=0x7fffe87f6af8,
    tb_exit=0x7fffe87f6af4) at accel/tcg/cpu-exec.c:613
#6  0x00005555557fec29 in cpu_exec (cpu=0x7fffe87f8010) at 
accel/tcg/cpu-exec.c:711
#7  0x00005555557c7a05 in tcg_cpu_exec (cpu=0x7fffe87f8010) at qemu/cpus.c:1270
#8  0x00005555557c7c3c in qemu_tcg_rr_cpu_thread_fn (arg=0x7fffe87f8010) at 
qemu/cpus.c:1365
#9  0x00007ffff78cd5bd in start_thread () from /lib64/libpthread.so.0
#10 0x00007ffff42d062d in clone () from /lib64/libc.so.6
(gdb) p mr
$1 = (MemoryRegion *) 0x0
(gdb) p/x addr
$2 = 0xd8001006
(gdb) p *iotlbentry
$3 = {addr = 18446744070085669013, attrs = {unspecified = 1, secure = 0, user = 
0, requester_id = 0}}
(gdb) p/x iotlbentry->addr
$4 = 0xffffffff27fff095
(gdb) up
#1  0x00005555557f5673 in io_writeb (env=0x7fffe88002a0, mmu_idx=1, index=4, 
val=224 '\340', addr=3623882758, retaddr=140737099010411)
    at accel/tcg/softmmu_template.h:265
265    return io_writex(env, iotlbentry, mmu_idx, val, addr, retaddr, 
DATA_SIZE);
(gdb) up
#2  0x00005555557f57ff in helper_ret_stb_mmu (env=0x7fffe88002a0, 
addr=3623882758, val=224 '\340', oi=1, retaddr=140737099010411)
    at accel/tcg/softmmu_template.h:300
300        glue(io_write, SUFFIX)(env, mmu_idx, index, val, addr, retaddr);
(gdb) l 260
255# endif
256#endif
257
258static inline void glue(io_write, SUFFIX)(CPUArchState *env,
259                                          size_t mmu_idx, size_t index,
260                                          DATA_TYPE val,
261                                          target_ulong addr,
262                                          uintptr_t retaddr)
263{
264    CPUIOTLBEntry *iotlbentry = &env->iotlb[mmu_idx][index];
265    return io_writex(env, iotlbentry, mmu_idx, val, addr, retaddr, 
DATA_SIZE);
266}
267
268void helper_le_st_name(CPUArchState *env, target_ulong addr, DATA_TYPE val,
269                       TCGMemOpIdx oi, uintptr_t retaddr)
270{
271    unsigned mmu_idx = get_mmuidx(oi);
272    int index = (addr >> TARGET_PAGE_BITS) & (CPU_TLB_SIZE - 1);
273    target_ulong tlb_addr = env->tlb_table[mmu_idx][index].addr_write;
274    unsigned a_bits = get_alignment_bits(get_memop(oi));
275    uintptr_t haddr;
276
277    if (addr & ((1 << a_bits) - 1)) {
278        cpu_unaligned_access(ENV_GET_CPU(env), addr, MMU_DATA_STORE,
279                             mmu_idx, retaddr);
280    }
281
282    /* If the TLB entry is for a different page, reload and try again.  */
283    if ((addr & TARGET_PAGE_MASK)
284        != (tlb_addr & (TARGET_PAGE_MASK | TLB_INVALID_MASK))) {
285        if (!VICTIM_TLB_HIT(addr_write, addr)) {
286            tlb_fill(ENV_GET_CPU(env), addr, MMU_DATA_STORE, mmu_idx, 
retaddr);
287        }
288        tlb_addr = env->tlb_table[mmu_idx][index].addr_write;
289    }
290
291    /* Handle an IO access.  */
292    if (unlikely(tlb_addr & ~TARGET_PAGE_MASK)) {
293        if ((addr & (DATA_SIZE - 1)) != 0) {
294            goto do_unaligned_access;
295        }
296
297        /* ??? Note that the io helpers always read data in the target
298           byte ordering.  We should push the LE/BE request down into io.  */
299        val = TGT_LE(val);
300        glue(io_write, SUFFIX)(env, mmu_idx, index, val, addr, retaddr);
301        return;
302    }
303
304    /* Handle slow unaligned access (it spans two pages or IO).  */
(gdb) p/x tlb_addr
$5 = 0xd8001080
(gdb) p/x env->tlb_table[mmu_idx][index]
$6 = {{{addr_read = 0xd8001080, addr_write = 0xd8001080, addr_code = 
0xffffffff, addend = 0xffffffff27fff000}, dummy = {0x80, 0x10, 0x0, 0xd8,
      0x80, 0x10, 0x0, 0xd8, 0xff, 0xff, 0xff, 0xff, 0xff, 0xff, 0xff, 0xff, 0x0, 
0xf0, 0xff, 0x27, 0xff <repeats 12 times>}}}

So as far as I understand the mmu_idx and index variables passed down to 
io_write are from env->tlb_table but are used on the env->iotlb array to 
get iotlbentry which seems to be invalid in this case (while apparently 
normally these are in sync and this works because several successful 
accesses precede this one causing the crash). Does anyone know if this is 
correct and how are these arrays can get out of sync causing this crash or 
what should be checked to find the problem here?

Thank you,
BALATON Zoltan