Re: [Qemu-ppc] [Qemu-devel] [PULL 075/118] macio: handle non-block ATAPI DMA transfers

[BALATON Zoltan]

On Wed, 25 Jun 2014, Mark Cave-Ayland wrote:
> On 24/06/14 11:53, BALATON Zoltan wrote:
> > > All I can say is that debugging this stuff isn't easy, particularly
> > > with MorphOS which has some rather unusual behaviours. But what we
> > > really need from you now over the next few days is for you to compare
> > > the debug output between the working and non-working cases and figure
> > > out if we can fix this in time for the 2.1 release. You have
> > > everything you need (including my acceptance test of booting both
> > > MorphOS and Darwin ISOs), so time to take a deep breath and begin what
> > > should be a challenging yet ultimately rewarding debugging process :)
> >
> > I'm still working on finding a solution for the exception problems with
> > OpenBIOS that prevent MorphOS from working and I failed to understand
> > the whole working of macio, DBDMA and the whole block layer so far but I
> > can try to debug it. Can you tell how to reproduce the problem with
> > Darwin? The Darwin images don't seem to work with -M mac99 either before
> > or after the patch so no regressions there.
>
> It's fairly simple to reproduce here:
>
> qemu-system-ppc -M g3beige -cdrom darwinppc-602.iso -boot d
> qemu-system-ppc -M g3beige -cdrom darwinppc-801.iso -boot d
> qemu-system-ppc -M mac99 -cdrom darwinppc-801.iso -boot d
>
> For -M g3beige then darwinppc-602.iso tends to hang just after the "ADB 
> present" line just before it finds the CDROM.
>
> Rather annoyingly it seems to be a lot trickier to reproduce today than it 
> was with my original tests, currently 1 in 8 boots compared to 1 in 3 when I 
> did the OpenBIOS tests. Delays introduced by enabling debugging in 
> pmac_ide_transfer() seem to make it easier to trigger, as does compiling with 
> -O0 -g (slower) and also dropping the kernel FS cache.
>
> Maybe it's an existing timing bug that happens to be exacerbated by the 
> patch? :/

For me darwinppc-602.iso seems to more consistently hang although it did 
boot once but I had no debug logs that time. The diff between a boot with 
the last two patches reverted (your non-block ATAPI patch and Alex's async 
remainder) and HEAD shows this in case it gives a hint to someone:

--- debug-console.log.nopatch
+++ debug-console.log.fail
 ATAPI limit=0x0 packet: bb 00 ff ff 00 00 00 00 00 00 00 00
 ATAPI limit=0xfffe packet: 43 02 00 00 00 00 00 ff fe 80 00 00
 reply: tx_size=48 elem_tx_size=0 index=0
 byte_count_limit=65534
 status=0x58
 reply: tx_size=0 elem_tx_size=0 index=48
 status=0x50
 ATAPI limit=0x30 packet: 43 02 00 00 00 00 00 00 30 80 00 00
 reply: tx_size=48 elem_tx_size=0 index=0
 byte_count_limit=48
 status=0x58
 reply: tx_size=0 elem_tx_size=0 index=48
 status=0x50
 DBDMA: readl 0x0000000000000d04 => 0x00000000
 DBDMA: channel 0x1a reg 0x1
 DBDMA: writel 0x0000000000000d08 <= 0x00000000
 DBDMA: channel 0x1a reg 0x2
 DBDMA: writel 0x0000000000000d0c <= 0x011f8010
 DBDMA: channel 0x1a reg 0x3
 DBDMA: dbdma_cmdptr_load 0x011f8010
 DBDMA: writel 0x0000000000000d00 <= 0x90009000
 DBDMA: channel 0x1a reg 0x0
 DBDMA:     status 0x00009400
 DBDMA: DBDMA_run_bh
 DBDMA: channel_run
-dbdma_cmd 0x7fc7142f0560
+dbdma_cmd 0x7f58257f4b48
     req_count 0x0930
     command 0x2000
-    phy_addr 0x017ca000
+    phy_addr 0x017cb000
     cmd_dep 0x00000000
     res_count 0x0000
     xfer_status 0x0000
 DBDMA: start_input
-DBDMA: addr 0x17ca000 key 0x0
+DBDMA: addr 0x17cb000 key 0x0

-waiting for data (0x3 - 0x930 - 50)
-ATAPI limit=0x930 packet: be 00 00 00 00 00 00 00 01 f8 00 00
-read dma: LBA=0 nb_sectors=1
-
-DBDMA: DBDMA_run_bh
-DBDMA: channel_run
-dbdma_cmd 0x7fc7142f0560
-    req_count 0x0930
-    command 0x2000
-    phy_addr 0x017ca000
-    cmd_dep 0x00000000
-    res_count 0x0000
-    xfer_status 0x0000
-DBDMA: start_input
-DBDMA: addr 0x17ca000 key 0x0
-
-io_buffer_size = 0
-remainder: 0 io->len: 2352 size: 2352
-precopying unaligned 304 bytes to 0x17ca800
-io->len = 0x800
-set remainder to: 0
-sector_num=0 size=2352, cmd_cmd=0
-io_buffer_size = 0x930
-remainder: 0 io->len: 0 size: 0
-end of transfer
-end of DMA
-done DMA
+non-block ATAPI DMA transfer size: 0
+end of non-block ATAPI DMA transfer
 DBDMA: dbdma_end
 DBDMA: conditional_wait
 DBDMA: dbdma_cmdptr_save 0x011f8010
-DBDMA: xfer_status 0x00008400 res_count 0x0000
+DBDMA: xfer_status 0x00008400 res_count 0x0930
 DBDMA: conditional_interrupt
 DBDMA: conditional_branch
 DBDMA: dbdma_cmdptr_load 0x011f8020
 DBDMA: channel_run
-dbdma_cmd 0x7fc7142f0560
+dbdma_cmd 0x7f58257f4b48
     req_count 0x0000
     command 0x6030
     phy_addr 0x00000000
     cmd_dep 0x00000000
     res_count 0x0000
     xfer_status 0x0000
 DBDMA: conditional_wait
 DBDMA: dbdma_cmdptr_save 0x011f8020
 DBDMA: xfer_status 0x00008400 res_count 0x0000
 DBDMA: conditional_interrupt
 DBDMA: conditional_interrupt: raise
 DBDMA: conditional_branch
 DBDMA: dbdma_cmdptr_load 0x011f8030
 DBDMA: DBDMA_run_bh
 DBDMA: channel_run
-dbdma_cmd 0x7fc7142f0560
+dbdma_cmd 0x7f58257f4b48
     req_count 0x0000
     command 0x7000
     phy_addr 0x00000000
     cmd_dep 0x00000000
     res_count 0x0000
     xfer_status 0x0000
-DBDMA: writel 0x0000000000000d00 <= 0xa0002000
-DBDMA: channel 0x1a reg 0x0
-DBDMA:     status 0x00000000
-DBDMA: readl 0x0000000000000d04 => 0x00000000
-DBDMA: channel 0x1a reg 0x1
-DBDMA: readl 0x0000000000000d04 => 0x00000000
-DBDMA: channel 0x1a reg 0x1
-DBDMA: writel 0x0000000000000d08 <= 0x00000000
-DBDMA: channel 0x1a reg 0x2
-DBDMA: writel 0x0000000000000d0c <= 0x011f8010
-DBDMA: channel 0x1a reg 0x3
-DBDMA: dbdma_cmdptr_load 0x011f8010
-DBDMA: writel 0x0000000000000d00 <= 0x90009000
-DBDMA: channel 0x1a reg 0x0
-DBDMA:     status 0x00009400
-DBDMA: DBDMA_run_bh
-DBDMA: channel_run
-dbdma_cmd 0x7fc7142f0560
-    req_count 0x0800
-    command 0x2000
-    phy_addr 0x01526800
-    cmd_dep 0x00000000
-    res_count 0x0000
-    xfer_status 0x0000
-DBDMA: start_input
-DBDMA: addr 0x1526800 key 0x0
-
-waiting for data (0x1 - 0x800 - 58)
-ATAPI limit=0x800 packet: 28 00 00 00 00 00 00 00 01 00 00 00
+ATAPI limit=0x930 packet: be 00 00 00 00 00 00 00 01 f8 00 00
 read dma: LBA=0 nb_sectors=1

 DBDMA: DBDMA_run_bh
-DBDMA: channel_run
-dbdma_cmd 0x7fc7142f0560
-    req_count 0x0800
-    command 0x2000
-    phy_addr 0x01526800
-    cmd_dep 0x00000000
-    res_count 0x0000
-    xfer_status 0x0000
-DBDMA: start_input
-DBDMA: addr 0x1526800 key 0x0
-
-io_buffer_size = 0
-remainder: 0 io->len: 2048 size: 2048
-io->len = 0x800
-set remainder to: 0
-sector_num=0 size=2048, cmd_cmd=0
-io_buffer_size = 0x800
-remainder: 0 io->len: 0 size: 0
-end of transfer
-end of DMA
-done DMA
-DBDMA: dbdma_end
-DBDMA: conditional_wait
-DBDMA: dbdma_cmdptr_save 0x011f8010
-DBDMA: xfer_status 0x00008400 res_count 0x0000
-DBDMA: conditional_interrupt
-DBDMA: conditional_branch

I'm not sure but could it be that it mistakes a transfer to a non-block 
transfer for some reason?

> Notes:
> Darwin 6.02 doesn't support -M mac99 (always hangs) AFAICT.
> Darwin 8.01 works but with -M mac99 IDE detection can take up to 30s or so.

I thought both of these hung but I did not wait 30 seconds.

Regards,
BALATON Zoltan