| Message ID | alpine.LMD.2.02.1405101411590.4345@jedlik.phy.bme.hu |
|---|---|
| State | New |
| Headers | show |
On 10/05/14 13:30, BALATON Zoltan wrote: > That patch would be 80fc95d8bdaf3392106b131a97ca701fd374489a in QEMU > master. I've tried reverting it and Darwin still boots (without -M > mac99) up to the point where it asks to install as before but I don't > know how good a test is this as I'm not sure it does unaligned accesses > up to this point. I see accesses like this: > > pmac_ide_transfer(ATAPI) lba=ffffffff, buffer_index=30, len=930 > pmac_ide_transfer(ATAPI) lba=0, buffer_index=0, len=930 Here is an example of an unaligned access, where the length is not a multiple of 0x200 (512 bytes) which was required for the block layer DMA APIs at the time it was written. If you can get to the same point with the patch reverted, then it means Kevin's patchset for byte-level rather than sector-level granularity for block requests is working. What's important is the sum of the start_input size descriptors now matches the size of the ATA request, so the dma_* callbacks can now be used directly with byte precision rather than clobbering the memory up to the next multiple of 0x200. > This however does not fix MorphOS which fails as before. I've tried this > patch too (on top of the previous revert) but that did not work either: > > diff --git a/hw/ide/macio.c b/hw/ide/macio.c > index d3395f4..bce14fc 100644 > --- a/hw/ide/macio.c > +++ b/hw/ide/macio.c > @@ -56,6 +56,7 @@ static void pmac_ide_atapi_transfer_cb(void *opaque, > int ret) > DBDMA_io *io = opaque; > MACIOIDEState *m = io->opaque; > IDEState *s = idebus_active_if(&m->bus); > + int64_t sector_num; > > if (ret < 0) { > m->aiocb = NULL; > @@ -107,13 +108,16 @@ static void pmac_ide_atapi_transfer_cb(void > *opaque, int r > qemu_sglist_add(&s->sg, io->addr, io->len); > io->addr += io->len; > io->len = 0; > - > - MACIO_DPRINTF("sector_num=%d size=%d, cmd_cmd=%d\n", > - (s->lba << 2) + (s->io_buffer_index >> 9), > + if (s->lba >= 0) > + sector_num = (s->lba << 2) + (s->io_buffer_index >> 9); > + else > + sector_num = s->lba; > + MACIO_DPRINTF("sector_num=%ld size=%d, cmd_cmd=%d\n", > + sector_num, > s->packet_transfer_size, s->dma_cmd); > > m->aiocb = dma_bdrv_read(s->bs, &s->sg, > - (int64_t)(s->lba << 2) + > (s->io_buffer_index >> 9) > + sector_num, > pmac_ide_atapi_transfer_cb, io); > return; > > This still produces an error in MorphOS as before: > > DBDMA: writel 0x0000000000000d0c <= 0x00e5ac80 > DBDMA: channel 0x1a reg 0x3 > DBDMA: dbdma_cmdptr_load 0x00e5ac80 > ATAPI limit=0x8000 packet: 43 00 00 00 00 00 00 03 24 00 00 00 > > DBDMA: DBDMA_run_bh > DBDMA: writel 0x0000000000000d00 <= 0x80008000 > DBDMA: channel 0x1a reg 0x0 > DBDMA: status 0x00008400 > DBDMA: readl 0x0000000000000d00 => 0x80008000 > DBDMA: channel 0x1a reg 0x0 > DBDMA: DBDMA_run_bh > DBDMA: channel_run > dbdma_cmd 0x7f7dddff5ae0 > req_count 0x0324 > command 0x3000 > phy_addr 0x00e7dddc > cmd_dep 0x00000000 > res_count 0x0000 > xfer_status 0x0000 > DBDMA: start_input > DBDMA: addr 0xe7dddc key 0x0 > pmac_ide_transfer(ATAPI) lba=ffffffff, buffer_index=0, len=324 ^^^^^ > io_buffer_size = 0 > io->len = 0x324 > sector_num=-1 size=20, cmd_cmd=0 > atapi_cmd_error: sense=0x5 asc=0x21 > done DMA > DBDMA: dbdma_end > > Interestingly a similar read works for Darwin which does this: > > 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 0x7ffa05173c60 > req_count 0x0930 > command 0x2000 > phy_addr 0x017cc000 > cmd_dep 0x00000000 > res_count 0x0000 > xfer_status 0x0000 > DBDMA: start_input > DBDMA: addr 0x17cc000 key 0x0 > pmac_ide_transfer(ATAPI) lba=ffffffff, buffer_index=30, len=930 > 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 0x7ffa05173c60 > req_count 0x0930 > command 0x2000 > phy_addr 0x017cc000 > cmd_dep 0x00000000 > res_count 0x0000 > xfer_status 0x0000 > DBDMA: start_input > DBDMA: addr 0x17cc000 key 0x0 > pmac_ide_transfer(ATAPI) lba=0, buffer_index=0, len=930 > io_buffer_size = 0 > io->len = 0x930 > sector_num=0 size=2352, cmd_cmd=0 > io_buffer_size = 0x930 > end of transfer > end of DMA > done DMA > DBDMA: dbdma_end From the limited block layer knowledge I have, it seems that lba == -1 is a default value meaning the ATA request hasn't been submitted. Take a look at the lines I marked above: it looks to me as if in the 2nd request, the DMA controller is running but realises that it is still waiting for the ATA request to complete before continuing which is why you see "waiting for data" followed by that ATAPI packet. In your first case, pmac_ide_transfer() incorrectly believes the ATA request has already completed which is why it tries to continue and then chokes on the invalid lba value of -1. HTH, Mark.
On Mon, 12 May 2014, Mark Cave-Ayland wrote: > On 10/05/14 13:30, BALATON Zoltan wrote: >> That patch would be 80fc95d8bdaf3392106b131a97ca701fd374489a in QEMU >> master. I've tried reverting it and Darwin still boots (without -M >> mac99) up to the point where it asks to install as before but I don't >> know how good a test is this as I'm not sure it does unaligned accesses >> up to this point. I see accesses like this: >> >> pmac_ide_transfer(ATAPI) lba=ffffffff, buffer_index=30, len=930 >> pmac_ide_transfer(ATAPI) lba=0, buffer_index=0, len=930 > > Here is an example of an unaligned access, where the length is not a multiple > of 0x200 (512 bytes) which was required for the block layer DMA APIs at the > time it was written. If you can get to the same point with the patch > reverted, then it means Kevin's patchset for byte-level rather than > sector-level granularity for block requests is working. These logs were with the above commit reverted so it's probably not needed any more. I've tried booting Darwin 6.0.2, Darwin 8.0.1 up to the installation (did not install it) and Finnix 109 and they seem to work as before. > What's important is the sum of the start_input size descriptors now matches > the size of the ATA request, so the dma_* callbacks can now be used directly > with byte precision rather than clobbering the memory up to the next multiple > of 0x200. > >> This however does not fix MorphOS which fails as before. I've tried this >> patch too (on top of the previous revert) but that did not work either: >> >> diff --git a/hw/ide/macio.c b/hw/ide/macio.c >> index d3395f4..bce14fc 100644 >> --- a/hw/ide/macio.c >> +++ b/hw/ide/macio.c >> @@ -56,6 +56,7 @@ static void pmac_ide_atapi_transfer_cb(void *opaque, >> int ret) >> DBDMA_io *io = opaque; >> MACIOIDEState *m = io->opaque; >> IDEState *s = idebus_active_if(&m->bus); >> + int64_t sector_num; >> >> if (ret < 0) { >> m->aiocb = NULL; >> @@ -107,13 +108,16 @@ static void pmac_ide_atapi_transfer_cb(void >> *opaque, int r >> qemu_sglist_add(&s->sg, io->addr, io->len); >> io->addr += io->len; >> io->len = 0; >> - >> - MACIO_DPRINTF("sector_num=%d size=%d, cmd_cmd=%d\n", >> - (s->lba << 2) + (s->io_buffer_index >> 9), >> + if (s->lba >= 0) >> + sector_num = (s->lba << 2) + (s->io_buffer_index >> 9); >> + else >> + sector_num = s->lba; >> + MACIO_DPRINTF("sector_num=%ld size=%d, cmd_cmd=%d\n", >> + sector_num, >> s->packet_transfer_size, s->dma_cmd); >> >> m->aiocb = dma_bdrv_read(s->bs, &s->sg, >> - (int64_t)(s->lba << 2) + >> (s->io_buffer_index >> 9) >> + sector_num, >> pmac_ide_atapi_transfer_cb, io); >> return; >> >> This still produces an error in MorphOS as before: >> >> DBDMA: writel 0x0000000000000d0c <= 0x00e5ac80 >> DBDMA: channel 0x1a reg 0x3 >> DBDMA: dbdma_cmdptr_load 0x00e5ac80 >> ATAPI limit=0x8000 packet: 43 00 00 00 00 00 00 03 24 00 00 00 >> >> DBDMA: DBDMA_run_bh >> DBDMA: writel 0x0000000000000d00 <= 0x80008000 >> DBDMA: channel 0x1a reg 0x0 >> DBDMA: status 0x00008400 >> DBDMA: readl 0x0000000000000d00 => 0x80008000 >> DBDMA: channel 0x1a reg 0x0 >> DBDMA: DBDMA_run_bh >> DBDMA: channel_run >> dbdma_cmd 0x7f7dddff5ae0 >> req_count 0x0324 >> command 0x3000 >> phy_addr 0x00e7dddc >> cmd_dep 0x00000000 >> res_count 0x0000 >> xfer_status 0x0000 >> DBDMA: start_input >> DBDMA: addr 0xe7dddc key 0x0 >> pmac_ide_transfer(ATAPI) lba=ffffffff, buffer_index=0, len=324 > > ^^^^^ > >> io_buffer_size = 0 >> io->len = 0x324 >> sector_num=-1 size=20, cmd_cmd=0 >> atapi_cmd_error: sense=0x5 asc=0x21 >> done DMA >> DBDMA: dbdma_end >> >> Interestingly a similar read works for Darwin which does this: >> >> 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 0x7ffa05173c60 >> req_count 0x0930 >> command 0x2000 >> phy_addr 0x017cc000 >> cmd_dep 0x00000000 >> res_count 0x0000 >> xfer_status 0x0000 >> DBDMA: start_input >> DBDMA: addr 0x17cc000 key 0x0 >> pmac_ide_transfer(ATAPI) lba=ffffffff, buffer_index=30, len=930 >> 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 0x7ffa05173c60 >> req_count 0x0930 >> command 0x2000 >> phy_addr 0x017cc000 >> cmd_dep 0x00000000 >> res_count 0x0000 >> xfer_status 0x0000 >> DBDMA: start_input >> DBDMA: addr 0x17cc000 key 0x0 >> pmac_ide_transfer(ATAPI) lba=0, buffer_index=0, len=930 >> io_buffer_size = 0 >> io->len = 0x930 >> sector_num=0 size=2352, cmd_cmd=0 >> io_buffer_size = 0x930 >> end of transfer >> end of DMA >> done DMA >> DBDMA: dbdma_end > > From the limited block layer knowledge I have, it seems that lba == -1 is a > default value meaning the ATA request hasn't been submitted. I don't know but according to hw/ide/atapi.c lba=-1 is a special value meaning that no sector needs to be read but only the results are requested. I don't know if this is only an atapi thing or how the block layer handles it but I believe that it is used for reading the TOC from the disk. > Take a look at the lines I marked above: it looks to me as if in the 2nd > request, the DMA controller is running but realises that it is still waiting > for the ATA request to complete before continuing which is why you see > "waiting for data" followed by that ATAPI packet. In your first case, > pmac_ide_transfer() incorrectly believes the ATA request has already > completed which is why it tries to continue and then chokes on the invalid > lba value of -1. MorphOS and Darwin are definitely doing things differently. I hope someone who understands what is happening can explain it why one of them works while the other doesn't. Regards, BALATON Zoltan
On 12/05/14 20:32, BALATON Zoltan wrote: > On Mon, 12 May 2014, Mark Cave-Ayland wrote: >> On 10/05/14 13:30, BALATON Zoltan wrote: >>> That patch would be 80fc95d8bdaf3392106b131a97ca701fd374489a in QEMU >>> master. I've tried reverting it and Darwin still boots (without -M >>> mac99) up to the point where it asks to install as before but I don't >>> know how good a test is this as I'm not sure it does unaligned accesses >>> up to this point. I see accesses like this: >>> >>> pmac_ide_transfer(ATAPI) lba=ffffffff, buffer_index=30, len=930 >>> pmac_ide_transfer(ATAPI) lba=0, buffer_index=0, len=930 >> >> Here is an example of an unaligned access, where the length is not a >> multiple of 0x200 (512 bytes) which was required for the block layer >> DMA APIs at the time it was written. If you can get to the same point >> with the patch reverted, then it means Kevin's patchset for byte-level >> rather than sector-level granularity for block requests is working. > > These logs were with the above commit reverted so it's probably not > needed any more. I've tried booting Darwin 6.0.2, Darwin 8.0.1 up to the > installation (did not install it) and Finnix 109 and they seem to work > as before. Okay that's definitely an improvement on what's there already :) When I find a moment, I'll try some local testing here and see if it's worth submitting a patch. >>> This still produces an error in MorphOS as before: >>> >>> DBDMA: writel 0x0000000000000d0c <= 0x00e5ac80 >>> DBDMA: channel 0x1a reg 0x3 >>> DBDMA: dbdma_cmdptr_load 0x00e5ac80 >>> ATAPI limit=0x8000 packet: 43 00 00 00 00 00 00 03 24 00 00 00 >>> >>> DBDMA: DBDMA_run_bh >>> DBDMA: writel 0x0000000000000d00 <= 0x80008000 >>> DBDMA: channel 0x1a reg 0x0 >>> DBDMA: status 0x00008400 >>> DBDMA: readl 0x0000000000000d00 => 0x80008000 >>> DBDMA: channel 0x1a reg 0x0 >>> DBDMA: DBDMA_run_bh >>> DBDMA: channel_run >>> dbdma_cmd 0x7f7dddff5ae0 >>> req_count 0x0324 >>> command 0x3000 >>> phy_addr 0x00e7dddc >>> cmd_dep 0x00000000 >>> res_count 0x0000 >>> xfer_status 0x0000 >>> DBDMA: start_input >>> DBDMA: addr 0xe7dddc key 0x0 >>> pmac_ide_transfer(ATAPI) lba=ffffffff, buffer_index=0, len=324 >> >> ^^^^^ >> >>> io_buffer_size = 0 >>> io->len = 0x324 >>> sector_num=-1 size=20, cmd_cmd=0 >>> atapi_cmd_error: sense=0x5 asc=0x21 >>> done DMA >>> DBDMA: dbdma_end (cut) > MorphOS and Darwin are definitely doing things differently. I hope > someone who understands what is happening can explain it why one of them > works while the other doesn't. Which I hope is what I'm trying to do? From hw/ide/atapi.c you can see that command 0x43 is read the TOC which according to atapi_cmd_table should call cmd_read_toc_pma_atip(). You can see that in your MorphOS case you are getting a line with a "atapi_cmd_error" prefix which indicates that something is calling ide_atapi_cmd_error() to return an error code instead of ide_atapi_cmd_reply() which would output the "reply" prefix as seen in your Darwin case. So you need to step through these functions in QEMU in order to see why your ATAPI command is failing. HTH, Mark.
On Mon, 12 May 2014, Mark Cave-Ayland wrote: > On 12/05/14 20:32, BALATON Zoltan wrote: > (cut) > >> MorphOS and Darwin are definitely doing things differently. I hope >> someone who understands what is happening can explain it why one of them >> works while the other doesn't. > > Which I hope is what I'm trying to do? From hw/ide/atapi.c you can see that Yes, your comments and advise are helping a lot. Thank you. > command 0x43 is read the TOC which according to atapi_cmd_table should call > cmd_read_toc_pma_atip(). You can see that in your MorphOS case you are > getting a line with a "atapi_cmd_error" prefix which indicates that something > is calling ide_atapi_cmd_error() to return an error code instead of > ide_atapi_cmd_reply() which would output the "reply" prefix as seen in your > Darwin case. So you need to step through these functions in QEMU in order to > see why your ATAPI command is failing. I've tried doing this and it seems that the cmd_read_toc_pma_atip function returns all right (via the case 0 path) with a 20 byte result array and calls ide_atapi_cmd_reply which takes the DMA path as s->atapi_dma is set to 1 and the error comes from somewhere during trying to DMA the result back to the client. I could not follow it so I've only got a backtrace from where ide_atapi_cmd_error is called: DBDMA: DBDMA_run_bh DBDMA: writel 0x0000000000000d00 <= 0x80008000 DBDMA: channel 0x1a reg 0x0 DBDMA: status 0x00008400 DBDMA: readl 0x0000000000000d00 => 0x80008000 DBDMA: channel 0x1a reg 0x0 DBDMA: DBDMA_run_bh DBDMA: channel_run dbdma_cmd 0x5555563cccb0 req_count 0x0324 command 0x3000 phy_addr 0x00e17e4c cmd_dep 0x00000000 res_count 0x0000 xfer_status 0x0000 DBDMA: start_input DBDMA: addr 0xe17e4c key 0x0 pmac_ide_transfer(ATAPI) lba=ffffffff, buffer_index=0, len=324 io_buffer_size = 0 io->len = 0x324 sector_num=-1 size=20, cmd_cmd=0 [Switching to Thread 0x7ffff7fc5900 (LWP 6462)] Breakpoint 2, ide_atapi_cmd_error (s=0x5555563cb238, sense_key=5, asc=33) at hw/ide/atapi.c:141 141 { (gdb) bt #0 ide_atapi_cmd_error (s=0x5555563cb238, sense_key=5, asc=33) at hw/ide/atapi.c:141 #1 0x00005555556cecf5 in ide_atapi_io_error (s=0x5555563cb238, ret=-5) at hw/ide/atapi.c:160 #2 0x00005555556d9d01 in pmac_ide_atapi_transfer_cb (opaque=0x5555563ccc68, ret=-5) at hw/ide/macio.c:64 #3 0x00005555556780d2 in dma_complete (dbs=0x5555563ab840, ret=-5) at dma-helpers.c:121 #4 0x00005555556781db in dma_bdrv_cb (opaque=0x5555563ab840, ret=-5) at dma-helpers.c:149 #5 0x0000555555614dd1 in bdrv_co_em_bh (opaque=0x5555563b5000) at block.c:4602 #6 0x00005555555f8170 in aio_bh_poll (ctx=0x55555637fc00) at async.c:81 #7 0x00005555555f7dc9 in aio_poll (ctx=0x55555637fc00, blocking=false) at aio-posix.c:188 #8 0x00005555555f8587 in aio_ctx_dispatch (source=0x55555637fc00, callback= 0x0, user_data=0x0) at async.c:205 #9 0x00007ffff78ca6d5 in g_main_context_dispatch () from /lib64/libglib-2.0.so.0 #10 0x00005555557a0f42 in glib_pollfds_poll () at main-loop.c:190 #11 0x00005555557a1042 in os_host_main_loop_wait (timeout=0) at main-loop.c:235 #12 0x00005555557a1115 in main_loop_wait (nonblocking=1) at main-loop.c:484 #13 0x0000555555844190 in main_loop () at vl.c:2075 #14 0x000055555584bc23 in main (argc=30, argv=0x7fffffffdc88, envp= 0x7fffffffdd80) at vl.c:4556 Do you have any idea how to debug this further or does this help to tell where is the problem? (I think the question is where does the -5 return value come from?) Regards, BALATON Zoltan
On 14/05/14 00:02, BALATON Zoltan wrote: >> command 0x43 is read the TOC which according to atapi_cmd_table should >> call cmd_read_toc_pma_atip(). You can see that in your MorphOS case >> you are getting a line with a "atapi_cmd_error" prefix which indicates >> that something is calling ide_atapi_cmd_error() to return an error >> code instead of ide_atapi_cmd_reply() which would output the "reply" >> prefix as seen in your Darwin case. So you need to step through these >> functions in QEMU in order to see why your ATAPI command is failing. > > I've tried doing this and it seems that the cmd_read_toc_pma_atip > function returns all right (via the case 0 path) with a 20 byte result > array and calls ide_atapi_cmd_reply which takes the DMA path as > s->atapi_dma is set to 1 and the error comes from somewhere during > trying to DMA the result back to the client. I could not follow it so > I've only got a backtrace from where ide_atapi_cmd_error is called: So this basically confirms that the DMA errors out because s->lba == -1 in the macio callback. FWIW you should probably ensure that DEBUG_IDE_ATAPI is enabled when posting logs in future as this helps show the interaction between the two systems. > Do you have any idea how to debug this further or does this help to tell > where is the problem? (I think the question is where does the -5 return > value come from?) Well from this the cause is fairly easy to spot: ide_atapi_cmd_reply() sets s->lba == -1 when called from cmd_read_toc_pma_atip(). And since as you correctly point out this is a DMA request, it invokes the start_dma function in macio's dbdma_ops (ide_dbdma_start), which kicks the DBDMA engine into life. I think the issue here is related to the fact that reading a TOC doesn't actually involve reading physical blocks from disk (as the TOC is placed directly in the buffer) and so the dma_bdrv_* functions shouldn't actually be invoked in the first place. And because of the DBDMA setup, ide_atapi_cmd_read_dma_cb() can't be used which is why pmac_ide_transfer_cb() needs to do a lot of similar work itself. Maybe you can find some clues there as to what the logic should be? HTH, Mark.
On Wed, 14 May 2014, Mark Cave-Ayland wrote: > On 14/05/14 00:02, BALATON Zoltan wrote: >>> command 0x43 is read the TOC which according to atapi_cmd_table should >>> call cmd_read_toc_pma_atip(). You can see that in your MorphOS case >>> you are getting a line with a "atapi_cmd_error" prefix which indicates >>> that something is calling ide_atapi_cmd_error() to return an error >>> code instead of ide_atapi_cmd_reply() which would output the "reply" >>> prefix as seen in your Darwin case. So you need to step through these >>> functions in QEMU in order to see why your ATAPI command is failing. >> >> I've tried doing this and it seems that the cmd_read_toc_pma_atip >> function returns all right (via the case 0 path) with a 20 byte result >> array and calls ide_atapi_cmd_reply which takes the DMA path as >> s->atapi_dma is set to 1 and the error comes from somewhere during >> trying to DMA the result back to the client. I could not follow it so >> I've only got a backtrace from where ide_atapi_cmd_error is called: > > So this basically confirms that the DMA errors out because s->lba == -1 in > the macio callback. FWIW you should probably ensure that DEBUG_IDE_ATAPI is > enabled when posting logs in future as this helps show the interaction > between the two systems. The logs I've posted are with DEBUG_IDE_ATAPI, DEBUG_DBDMA and DEBUG_MACIO already enabled... >> Do you have any idea how to debug this further or does this help to tell >> where is the problem? (I think the question is where does the -5 return >> value come from?) > > Well from this the cause is fairly easy to spot: ide_atapi_cmd_reply() sets > s->lba == -1 when called from cmd_read_toc_pma_atip(). And since as you > correctly point out this is a DMA request, it invokes the start_dma function > in macio's dbdma_ops (ide_dbdma_start), which kicks the DBDMA engine into > life. > > I think the issue here is related to the fact that reading a TOC doesn't > actually involve reading physical blocks from disk (as the TOC is placed > directly in the buffer) and so the dma_bdrv_* functions shouldn't actually be > invoked in the first place. And because of the DBDMA setup, > ide_atapi_cmd_read_dma_cb() can't be used which is why pmac_ide_transfer_cb() > needs to do a lot of similar work itself. Maybe you can find some clues there > as to what the logic should be? I'm afraid I still can't understand it. Is there a way to trace the path after DBDMA engine is kicked? Where should I break to get some insight on what is happening? (Maybe it's a dbdma bug not a macio one.) Regards, BALATON Zoltan
On 14/05/14 12:10, BALATON Zoltan wrote: >>> I've tried doing this and it seems that the cmd_read_toc_pma_atip >>> function returns all right (via the case 0 path) with a 20 byte result >>> array and calls ide_atapi_cmd_reply which takes the DMA path as >>> s->atapi_dma is set to 1 and the error comes from somewhere during >>> trying to DMA the result back to the client. I could not follow it so >>> I've only got a backtrace from where ide_atapi_cmd_error is called: >> >> So this basically confirms that the DMA errors out because s->lba == >> -1 in the macio callback. FWIW you should probably ensure that >> DEBUG_IDE_ATAPI is enabled when posting logs in future as this helps >> show the interaction between the two systems. > > The logs I've posted are with DEBUG_IDE_ATAPI, DEBUG_DBDMA and > DEBUG_MACIO already enabled... Well sure, but not the ones in your last email - I had to go back several mails back into the thread to pull them out. Bear in mind the high volume of these lists means that a lot of people who could help won't have the time to do this. >>> Do you have any idea how to debug this further or does this help to tell >>> where is the problem? (I think the question is where does the -5 return >>> value come from?) >> >> Well from this the cause is fairly easy to spot: ide_atapi_cmd_reply() >> sets s->lba == -1 when called from cmd_read_toc_pma_atip(). And since >> as you correctly point out this is a DMA request, it invokes the >> start_dma function in macio's dbdma_ops (ide_dbdma_start), which kicks >> the DBDMA engine into life. >> >> I think the issue here is related to the fact that reading a TOC >> doesn't actually involve reading physical blocks from disk (as the TOC >> is placed directly in the buffer) and so the dma_bdrv_* functions >> shouldn't actually be invoked in the first place. And because of the >> DBDMA setup, ide_atapi_cmd_read_dma_cb() can't be used which is why >> pmac_ide_transfer_cb() needs to do a lot of similar work itself. Maybe >> you can find some clues there as to what the logic should be? > > I'm afraid I still can't understand it. Is there a way to trace the path > after DBDMA engine is kicked? Where should I break to get some insight > on what is happening? (Maybe it's a dbdma bug not a macio one.) Which part is it that's still confusing you? Putting breakpoints on pmac_ide_transfer() and pmac_ide_atapi_transfer_cb() will show you the iterations on each DMA request (be sure to compare against a "known good" example to understand how it should work first). If you can give more detail as to which bits are confusing, I will try my best to explain them. ATB, Mark.
On Wed, 14 May 2014, Mark Cave-Ayland wrote: > On 14/05/14 12:10, BALATON Zoltan wrote: >> The logs I've posted are with DEBUG_IDE_ATAPI, DEBUG_DBDMA and >> DEBUG_MACIO already enabled... > > Well sure, but not the ones in your last email - I had to go back several > mails back into the thread to pull them out. Bear in mind the high volume of > these lists means that a lot of people who could help won't have the time to > do this. All the logs I posted in this thread were with these debug options enabled. Maybe the beginning was missing as I only included the logs from the failing dma reply because before that I was tracing to see that the TOC was read and about to be returned so I did not include those logs again. (They were in the previous mail though.) I'm including them again below this time. > Which part is it that's still confusing you? Putting breakpoints on > pmac_ide_transfer() and pmac_ide_atapi_transfer_cb() will show you the > iterations on each DMA request (be sure to compare against a "known good" > example to understand how it should work first). If you can give more detail > as to which bits are confusing, I will try my best to explain them. Looking at the backtrace: #0 ide_atapi_cmd_error (s=0x5555563cb238, sense_key=5, asc=33) at hw/ide/atapi.c:141 #1 0x00005555556cecf5 in ide_atapi_io_error (s=0x5555563cb238, ret=-5) at hw/ide/atapi.c:160 #2 0x00005555556d9d01 in pmac_ide_atapi_transfer_cb (opaque=0x5555563ccc68, ret=-5) at hw/ide/macio.c:64 #3 0x00005555556780d2 in dma_complete (dbs=0x5555563ab840, ret=-5) at dma-helpers.c:121 #4 0x00005555556781db in dma_bdrv_cb (opaque=0x5555563ab840, ret=-5) at dma-helpers.c:149 #5 0x0000555555614dd1 in bdrv_co_em_bh (opaque=0x5555563b5000) at block.c:4602 #6 0x00005555555f8170 in aio_bh_poll (ctx=0x55555637fc00) at async.c:81 #7 0x00005555555f7dc9 in aio_poll (ctx=0x55555637fc00, blocking=false) at aio-posix.c:188 #8 0x00005555555f8587 in aio_ctx_dispatch (source=0x55555637fc00, callback= 0x0, user_data=0x0) at async.c:205 #9 0x00007ffff78ca6d5 in g_main_context_dispatch () from /lib64/libglib-2.0.so.0 #10 0x00005555557a0f42 in glib_pollfds_poll () at main-loop.c:190 #11 0x00005555557a1042 in os_host_main_loop_wait (timeout=0) at main-loop.c:235 #12 0x00005555557a1115 in main_loop_wait (nonblocking=1) at main-loop.c:484 #13 0x0000555555844190 in main_loop () at vl.c:2075 #14 0x000055555584bc23 in main (argc=30, argv=0x7fffffffdc88, envp= 0x7fffffffdd80) at vl.c:4556 shows that pmac_ide_atapi_transfer_cb is called with ret=-5 which is why it fails, so putting a breakpoint there is too late. What I don't understand is where this -5 value comes from. I don't have a known good example because Darwin reads the TOC differently (probably before enabling DMA, I did not trace it more than the logs I've included earlier though) and MorphOS always fails. Here are the logs of all requests MorphOS does up to the failing ReadTOC again: ATAPI limit=0x8000 packet: 00 00 00 00 00 00 00 00 00 00 00 00 ATAPI limit=0x8000 packet: 12 00 00 00 24 00 00 00 00 00 00 00 reply: tx_size=36 elem_tx_size=0 index=0 byte_count_limit=32768 status=0x58 reply: tx_size=0 elem_tx_size=0 index=36 status=0x50 ATAPI limit=0x8000 packet: 1b 00 00 00 01 00 00 00 00 00 00 00 ATAPI limit=0x8000 packet: 00 00 00 00 00 00 00 00 00 00 00 00 ATAPI limit=0x8000 packet: 25 00 00 00 00 00 00 00 00 00 00 00 reply: tx_size=8 elem_tx_size=0 index=0 byte_count_limit=32768 status=0x58 reply: tx_size=0 elem_tx_size=0 index=8 status=0x50 ATAPI limit=0x8000 packet: 5a 00 05 00 00 00 00 00 30 00 00 00 atapi_cmd_error: sense=0x5 asc=0x24 ATAPI limit=0x8000 packet: 5a 00 04 00 00 00 00 00 28 00 00 00 atapi_cmd_error: sense=0x5 asc=0x24 ATAPI limit=0x8000 packet: 5a 00 03 00 00 00 00 00 28 00 00 00 atapi_cmd_error: sense=0x5 asc=0x24 ATAPI limit=0x8000 packet: 5a 00 3f 00 00 00 00 01 02 00 00 00 atapi_cmd_error: sense=0x5 asc=0x24 ATAPI limit=0x8000 packet: 51 00 00 00 00 00 00 00 22 00 00 00 reply: tx_size=34 elem_tx_size=0 index=0 byte_count_limit=32768 status=0x58 reply: tx_size=0 elem_tx_size=0 index=34 status=0x50 DBDMA: writel 0x0000000000000d0c <= 0x00e4e960 DBDMA: channel 0x1a reg 0x3 DBDMA: dbdma_cmdptr_load 0x00e4e960 ATAPI limit=0x8000 packet: 43 00 00 00 00 00 00 03 24 00 00 00 DBDMA: DBDMA_run_bh DBDMA: writel 0x0000000000000d00 <= 0x80008000 DBDMA: channel 0x1a reg 0x0 DBDMA: status 0x00008400 DBDMA: readl 0x0000000000000d00 => 0x80008000 DBDMA: channel 0x1a reg 0x0 DBDMA: DBDMA_run_bh DBDMA: channel_run dbdma_cmd 0x7f8f93662ee0 req_count 0x0324 command 0x3000 phy_addr 0x00e4f30c cmd_dep 0x00000000 res_count 0x0000 xfer_status 0x0000 DBDMA: start_input DBDMA: addr 0xe4f30c key 0x0 pmac_ide_transfer(ATAPI) lba=ffffffff, buffer_index=0, len=324 io_buffer_size = 0 io->len = 0x324 sector_num=-1 size=20, cmd_cmd=0 atapi_cmd_error: sense=0x5 asc=0x21 done DMA DBDMA: dbdma_end DBDMA: conditional_wait DBDMA: dbdma_cmdptr_save 0x00e4e960 DBDMA: xfer_status 0x00008400 res_count 0x0000 DBDMA: conditional_interrupt DBDMA: conditional_branch DBDMA: dbdma_cmdptr_load 0x00e4e970 DBDMA: channel_run dbdma_cmd 0x7f8f93662ee0 req_count 0x0000 command 0x7000 phy_addr 0x00000000 cmd_dep 0x00000000 res_count 0x0000 xfer_status 0x0000 DBDMA: readl 0x0000000000000d04 => 0x00008000 DBDMA: channel 0x1a reg 0x1 DBDMA: writel 0x0000000000000d00 <= 0x98000000 DBDMA: channel 0x1a reg 0x0 DBDMA: status 0x00000000 ATAPI limit=0x8000 packet: 00 00 00 00 00 00 00 00 00 00 00 00 ATAPI limit=0x8000 packet: 00 00 00 00 00 00 00 00 00 00 00 00 and here are the corresponding debug logs from MorphOS that shows what is it trying to do: Dev_Inquiry@idemacio2.device-0: DiskPort 0x200a9310 Dev_Inquiry@idemacio2.device-0: ATAPI Dev_InquirySCSI@idemacio2.device-0: Dev_InquirySCSI@idemacio2.device-0: Send TestDrive Dev_InquirySCSI@idemacio2.device-0: 1st TestDrive Status 0 Dev_InquirySCSI@idemacio2.device-0: Send Inquiry Dev_InquirySCSI@idemacio2.device-0: No IOError Dev_InquirySCSI@idemacio2.device-0: Unit is there physically Dev_InquirySCSI@idemacio2.device-0: DriveGeometry Dev_SetUnitBlockSize@idemacio2.device-0: SectorSize 2048 Dev_SetUnitBlockSize@idemacio2.device-0: SectorSize 2048 SectorShift 11 SectorShiftHighMask 0xffe00000 Dev_InquirySCSI@idemacio2.device-0: Set Removable Dev_InquirySCSI@idemacio2.device-0: Send StartUnit Dev_InquirySCSI@idemacio2.device-0: StartMotor IOError 0 SCSIError 0x0 Dev_InquirySCSI@idemacio2.device-0: Sense [0] 0x00000000000000000000000000000000 Dev_InquirySCSI@idemacio2.device-0: TestUnitReady IOError 0 SCSIError 0x0 Dev_InquirySCSI@idemacio2.device-0: Sense[0] 0x00000000000000000000000000000000 Dev_InquirySCSI@idemacio2.device-0: StartUnit done Dev_InquirySCSI@idemacio2.device-0: TstDrive IOError 0 SCSIError 0x0 Dev_Capacity@idemacio2.device-0: Dev_Capacity@idemacio2.device-0: DeviceType 5 needs Capacity Dev_Capacity16@idemacio2.device-0: Dev_Capacity16@idemacio2.device-0: Send Capacity16 Dev_Capacity16@idemacio2.device-0: IOError -4 SCSIError 0x0 Dev_Capacity10@idemacio2.device-0: Dev_Capacity10@idemacio2.device-0: Send Capacity Dev_Capacity10@idemacio2.device-0: Status ok Dev_Capacity10@idemacio2.device-0: SectorCount 112839 (0x1b8c7) Dev_Capacity10@idemacio2.device-0: SectorSize 2048 Dev_Capacity10@idemacio2.device-0: ignore for CDROM..too dangerous with Atapi returning random crap Dev_Capacity10@idemacio2.device-0: TotalSectors 112839 Dev_Capacity10@idemacio2.device-0: SectorSize 2048 Dev_Capacity@idemacio2.device-0: Capacity10 ok Dev_Capacity@idemacio2.device-0: Send ModeSense(Flex Disk Page) Dev_ModeSense@idemacio2.device-0: Page 5 Length 32 Flags 0x0 PageOffset 0x200cae98 Dev_ModeSense@idemacio2.device-0: Use ModeSense10 Dev_ModeSense@idemacio2.device-0: Final Length 48 Offset 16 Dev_Capacity@idemacio2.device-0: ModeSense error 45 Dev_Capacity@idemacio2.device-0: Send ModeSense(Rigid Disk Geometry Page) Dev_ModeSense@idemacio2.device-0: Page 4 Length 24 Flags 0x0 PageOffset 0x200cae98 Dev_ModeSense@idemacio2.device-0: Use ModeSense10 Dev_ModeSense@idemacio2.device-0: Final Length 40 Offset 16 Dev_Capacity@idemacio2.device-0: ModeSense error 45 Dev_Capacity@idemacio2.device-0: Send ModeSense(Format Page) Dev_ModeSense@idemacio2.device-0: Page 3 Length 24 Flags 0x0 PageOffset 0x200cae98 Dev_ModeSense@idemacio2.device-0: Use ModeSense10 Dev_ModeSense@idemacio2.device-0: Final Length 40 Offset 16 Dev_Capacity@idemacio2.device-0: ModeSense error 45 Dev_Capacity@idemacio2.device-0: No ModeHeader yet Dev_Capacity@idemacio2.device-0: Send ModeSense(Parameter Header) Dev_ModeSense@idemacio2.device-0: Page 63 Length 242 Flags 0x0 PageOffset 0x200cae98 Dev_ModeSense@idemacio2.device-0: Use ModeSense10 Dev_ModeSense@idemacio2.device-0: Final Length 258 Offset 16 Dev_Capacity@idemacio2.device-0: ModeSense error 45 Dev_InquirySCSI@idemacio2.device-0: Mark Unit is ready Dev_InquirySCSI@idemacio2.device-0: scan/mount partitions LibMountMountTagList@idemacio2.device-0: DeviceType 5 MountMode 0 LibMountMountTagList@idemacio2.device-0: mountable devicetype LibMountMountTagList@idemacio2.device-0: Mount CD Mount_MountCD@idemacio2.device-0: DiskPort 0x2004bf60 Mount_MountCD@idemacio2.device-0: Device 0x200a7f64 <idemacio2.device> Unit 0x20078654 UnitNum 0 Mount_MountCD@idemacio2.device-0: Check for bootable disc... Mount_GetDiscInfo@idemacio2.device-0: Mount_GetDiscInfo@idemacio2.device-0: MyDiscInfoData 0x200abe84 Mount_GetDiscInfo@idemacio2.device-0: GetDiscInfo io_Error(0) Mount_GetDiscInfo@idemacio2.device-0: Flags 0xe FirstTrack 1 Mount_GetDiscInfo@idemacio2.device-0: Sessions 1 Mount_GetDiscInfo@idemacio2.device-0: FirstTrackLastSession 1 Mount_GetDiscInfo@idemacio2.device-0: Flags1 0x20 DiscType 0 Mount_GetDiscInfo@idemacio2.device-0: DiscID <> DiscBarCode <> Mount_GetDiscInfo@idemacio2.device-0: ok Mount_MountCD@idemacio2.device-0: MyDiscInfoData 0x200abe84 Length 32 Mount_GetTOC@idemacio2.device-0: Locate ISO descriptor Mount_GetTOC@idemacio2.device-0: READ_TOC io_Error(45) Mount_GetTOC@idemacio2.device-0: failed Mount_MountCD@idemacio2.device-0: no toc data Regards, BALATON Zoltan
On 15/05/14 00:21, BALATON Zoltan wrote: >> Which part is it that's still confusing you? Putting breakpoints on >> pmac_ide_transfer() and pmac_ide_atapi_transfer_cb() will show you the >> iterations on each DMA request (be sure to compare against a "known >> good" example to understand how it should work first). If you can give >> more detail as to which bits are confusing, I will try my best to >> explain them. > > Looking at the backtrace: > > #0 ide_atapi_cmd_error (s=0x5555563cb238, sense_key=5, asc=33) > at hw/ide/atapi.c:141 > #1 0x00005555556cecf5 in ide_atapi_io_error (s=0x5555563cb238, ret=-5) > at hw/ide/atapi.c:160 > #2 0x00005555556d9d01 in pmac_ide_atapi_transfer_cb > (opaque=0x5555563ccc68, > ret=-5) at hw/ide/macio.c:64 > #3 0x00005555556780d2 in dma_complete (dbs=0x5555563ab840, ret=-5) > at dma-helpers.c:121 > #4 0x00005555556781db in dma_bdrv_cb (opaque=0x5555563ab840, ret=-5) > at dma-helpers.c:149 > #5 0x0000555555614dd1 in bdrv_co_em_bh (opaque=0x5555563b5000) at > block.c:4602 > #6 0x00005555555f8170 in aio_bh_poll (ctx=0x55555637fc00) at async.c:81 > #7 0x00005555555f7dc9 in aio_poll (ctx=0x55555637fc00, blocking=false) > at aio-posix.c:188 > #8 0x00005555555f8587 in aio_ctx_dispatch (source=0x55555637fc00, > callback= > 0x0, user_data=0x0) at async.c:205 > #9 0x00007ffff78ca6d5 in g_main_context_dispatch () > from /lib64/libglib-2.0.so.0 > #10 0x00005555557a0f42 in glib_pollfds_poll () at main-loop.c:190 > #11 0x00005555557a1042 in os_host_main_loop_wait (timeout=0) at > main-loop.c:235 > #12 0x00005555557a1115 in main_loop_wait (nonblocking=1) at main-loop.c:484 > #13 0x0000555555844190 in main_loop () at vl.c:2075 > #14 0x000055555584bc23 in main (argc=30, argv=0x7fffffffdc88, envp= > 0x7fffffffdd80) at vl.c:4556 > > shows that pmac_ide_atapi_transfer_cb is called with ret=-5 which is why > it fails, so putting a breakpoint there is too late. What I don't > understand is where this -5 value comes from. I don't have a known good > example because Darwin reads the TOC differently (probably before > enabling DMA, I did not trace it more than the logs I've included > earlier though) and MorphOS always fails. Have you noticed that the dma_bdrv_*() functions use a function pointer to pmac_ide_atapi_transfer_cb() as their callback function? The dma_bdrv_*() functions operate in a separate thread and then invoke the callback function when finished. The breakpoint you are hitting above is the invocation of pmac_ide_atapi_transfer_cb() as a result of the callback *after* the command has already failed, and not the invocation of pmac_ide_atapi_transfer_cb() which calls dma_bdrv_*() to setup the asynchronous transfer. Hence the DMA has already failed and the -5 value is being returned from the IDE code. I can only guess the reason this works with Darwin is because it is a non-DMA request. If you place a breakpoint on pmac_ide_transfer() then its invocation of pmac_ide_atapi_transfer_cb() should be the first iteration which sets up the DMA request, and the second invocation should be the (failing) callback from the dma_bdrv_*() functions. But as I mentioned before, I think the problem is that these functions shouldn't be called in the first place when requesting a TOC. HTH, Mark.
On Thu, 15 May 2014, Mark Cave-Ayland wrote: > On 15/05/14 00:21, BALATON Zoltan wrote: >>> Which part is it that's still confusing you? Putting breakpoints on >>> pmac_ide_transfer() and pmac_ide_atapi_transfer_cb() will show you the >>> iterations on each DMA request (be sure to compare against a "known >>> good" example to understand how it should work first). If you can give >>> more detail as to which bits are confusing, I will try my best to >>> explain them. >> >> Looking at the backtrace: >> >> #0 ide_atapi_cmd_error (s=0x5555563cb238, sense_key=5, asc=33) >> at hw/ide/atapi.c:141 >> #1 0x00005555556cecf5 in ide_atapi_io_error (s=0x5555563cb238, ret=-5) >> at hw/ide/atapi.c:160 >> #2 0x00005555556d9d01 in pmac_ide_atapi_transfer_cb >> (opaque=0x5555563ccc68, >> ret=-5) at hw/ide/macio.c:64 >> #3 0x00005555556780d2 in dma_complete (dbs=0x5555563ab840, ret=-5) >> at dma-helpers.c:121 >> #4 0x00005555556781db in dma_bdrv_cb (opaque=0x5555563ab840, ret=-5) >> at dma-helpers.c:149 >> #5 0x0000555555614dd1 in bdrv_co_em_bh (opaque=0x5555563b5000) at >> block.c:4602 >> #6 0x00005555555f8170 in aio_bh_poll (ctx=0x55555637fc00) at async.c:81 >> #7 0x00005555555f7dc9 in aio_poll (ctx=0x55555637fc00, blocking=false) >> at aio-posix.c:188 >> #8 0x00005555555f8587 in aio_ctx_dispatch (source=0x55555637fc00, >> callback= >> 0x0, user_data=0x0) at async.c:205 >> #9 0x00007ffff78ca6d5 in g_main_context_dispatch () >> from /lib64/libglib-2.0.so.0 >> #10 0x00005555557a0f42 in glib_pollfds_poll () at main-loop.c:190 >> #11 0x00005555557a1042 in os_host_main_loop_wait (timeout=0) at >> main-loop.c:235 >> #12 0x00005555557a1115 in main_loop_wait (nonblocking=1) at main-loop.c:484 >> #13 0x0000555555844190 in main_loop () at vl.c:2075 >> #14 0x000055555584bc23 in main (argc=30, argv=0x7fffffffdc88, envp= >> 0x7fffffffdd80) at vl.c:4556 >> >> shows that pmac_ide_atapi_transfer_cb is called with ret=-5 which is why >> it fails, so putting a breakpoint there is too late. What I don't >> understand is where this -5 value comes from. I don't have a known good >> example because Darwin reads the TOC differently (probably before >> enabling DMA, I did not trace it more than the logs I've included >> earlier though) and MorphOS always fails. > > Have you noticed that the dma_bdrv_*() functions use a function pointer to > pmac_ide_atapi_transfer_cb() as their callback function? The dma_bdrv_*() > functions operate in a separate thread and then invoke the callback function > when finished. > > The breakpoint you are hitting above is the invocation of > pmac_ide_atapi_transfer_cb() as a result of the callback *after* the command > has already failed, and not the invocation of pmac_ide_atapi_transfer_cb() > which calls dma_bdrv_*() to setup the asynchronous transfer. Hence the DMA > has already failed and the -5 value is being returned from the IDE code. I > can only guess the reason this works with Darwin is because it is a non-DMA > request. > > If you place a breakpoint on pmac_ide_transfer() then its invocation of > pmac_ide_atapi_transfer_cb() should be the first iteration which sets up the > DMA request, and the second invocation should be the (failing) callback from > the dma_bdrv_*() functions. But as I mentioned before, I think the problem is > that these functions shouldn't be called in the first place when requesting a > TOC. OK, I've done that and stopped at the first invocation of pmac_ide_atapi_transfer_cb. Here is a backtrace and the contents of some data structures: #0 pmac_ide_atapi_transfer_cb (opaque=0x5555563ccc68, ret=0) at hw/ide/macio.c:55 #1 0x00005555556da6d0 in pmac_ide_transfer (io=0x5555563ccc68) at hw/ide/macio.c:225 #2 0x00005555556eeee2 in start_input (ch=0x5555563ccc18, key=0, addr= 14777932, req_count=804, is_last=1) at hw/misc/macio/mac_dbdma.c:334 #3 0x00005555556ef444 in channel_run (ch=0x5555563ccc18) at hw/misc/macio/mac_dbdma.c:489 #4 0x00005555556ef599 in DBDMA_run (s=0x5555563cba40) at hw/misc/macio/mac_dbdma.c:531 #5 0x00005555556ef5f4 in DBDMA_run_bh (opaque=0x5555563cba40) at hw/misc/macio/mac_dbdma.c:542 #6 0x00005555555f8200 in aio_bh_poll (ctx=0x55555637fc00) at async.c:81 #7 0x00005555555f7e59 in aio_poll (ctx=0x55555637fc00, blocking=false) at aio-posix.c:188 #8 0x00005555555f8617 in aio_ctx_dispatch (source=0x55555637fc00, callback= 0x0, user_data=0x0) at async.c:205 #9 0x00007ffff78ca6d5 in g_main_context_dispatch () from /lib64/libglib-2.0.so.0 #10 0x00005555557a0fde in glib_pollfds_poll () at main-loop.c:190 #11 0x00005555557a10de in os_host_main_loop_wait (timeout=15883632) at main-loop.c:235 #12 0x00005555557a11b1 in main_loop_wait (nonblocking=0) at main-loop.c:484 #13 0x000055555584422c in main_loop () at vl.c:2075 #14 0x000055555584bcbf in main (argc=32, argv=0x7fffffffdc48, envp= 0x7fffffffdd50) at vl.c:4556 (gdb) p *io $5 = {opaque = 0x5555563c8db0, channel = 0x5555563ccc18, addr = 14777932, len = 804, is_last = 1, is_dma_out = 0, dma_end = 0x5555556eebf7 <dbdma_end>, processing = true} (gdb) p *m $4 = {parent_obj = {parent_obj = {parent_obj = {class = 0x555556357c20, free = 0x0, properties = {tqh_first = 0x5555563924c0, tqh_last = 0x5555563cd1d0}, ref = 6, parent = 0x5555563c3290}, id = 0x0, realized = true, opts = 0x0, hotplugged = 0, parent_bus = 0x555556384d30, num_gpio_out = 0, gpio_out = 0x0, num_gpio_in = 0, gpio_in = 0x0, child_bus = {lh_first = 0x5555563cb1b0}, num_child_bus = 1, instance_id_alias = -1, alias_required_for_version = 0}, num_irq = 2, irqs = { 0x0 <repeats 512 times>}, irqp = {0x5555563cb0d8, 0x5555563cb0e0, 0x0 <repeats 510 times>}, num_mmio = 1, mmio = {{addr = 18446744073709551615, memory = 0x5555563cb0e8}, {addr = 0, memory = 0x0} <repeats 31 times>}, num_pio = 0, pio = {0 <repeats 32 times>}}, irq = 0x5555563a2eb0, dma_irq = 0x5555563a2da8, mem = {ops = 0x555555dc6480 <pmac_ide_ops>, iommu_ops = 0x0, opaque = 0x5555563c8db0, owner = 0x5555563c8db0, parent = 0x5555563c3a28, size = {lo = 4096, hi = 0}, addr = 135168, destructor = 0x5555558ce04e <memory_region_destructor_none>, ram_addr = 18446744073709551615, subpage = false, terminates = true, romd_mode = true, ram = false, readonly = false, enabled = true, rom_device = false, warning_printed = false, flush_coalesced_mmio = false, alias = 0x0, alias_offset = 0, priority = 0, may_overlap = false, subregions = { tqh_first = 0x0, tqh_last = 0x5555563cb160}, subregions_link = { tqe_next = 0x5555563c8468, tqe_prev = 0x5555563c5ea0}, coalesced = { tqh_first = 0x0, tqh_last = 0x5555563cb180}, name = 0x5555563cd180 "pmac-ide", dirty_log_mask = 0 '\000', ioeventfd_nb = 0, ioeventfds = 0x0, iommu_notify = {notifiers = {lh_first = 0x0}}}, bus = { qbus = {obj = {class = 0x555556368cd0, free = 0x0, properties = { tqh_first = 0x555556392760, tqh_last = 0x555556392930}, ref = 2, parent = 0x5555563c8db0}, parent = 0x5555563c8db0, name = 0x5555563cd140 "ide.1", allow_hotplug = 0, hotplug_handler = 0x0, max_index = 1, realized = true, children = {tqh_first = 0x555556392890, tqh_last = 0x5555563928a0}, sibling = {le_next = 0x0, le_prev = 0x5555563c8e28}}, master = 0x5555563d6980, slave = 0x0, ifs = {{bus = 0x5555563cb1b0, unit = 0 '\000', drive_kind = IDE_CD, cylinders = 0, heads = 0, sectors = 0, chs_trans = 0, nb_sectors = 451360, mult_sectors = 16, identify_set = 1, identify_data = "\300\205", '\000' <repeats 18 times>, "MQ0000 3", ' ' <repeats 12 times>, "\003\000\000\002\004\000.2.005 EQUMD DVR-MO", ' ' <repeats 28 times>, "\000\000\001\000\000\003\000\000\000\000\000\000\a", '\000' <repeats 17 times>, "\a\000\a\000\003\000\264\000\264\000,\001\264\000\000\000\000\000\036\000\036", '\000' <repeats 15 times>, "\036", '\000' <repeats 15 times>, "?\001", '\000' <repeats 333 times>, drive_serial = 3, drive_serial_str = "QM00003", '\000' <repeats 13 times>, drive_model_str = "QEMU DVD-ROM", '\000' <repeats 28 times>, wwn = 0, feature = 1 '\001', error = 0 '\000', nsector = 1, sector = 0 '\000', lcyl = 0 '\000', hcyl = 128 '\200', hob_feature = 0 '\000', hob_nsector = 3 '\003', hob_sector = 0 '\000', hob_lcyl = 34 '"', hob_hcyl = 0 '\000', select = 160 '\240', status = 88 'X', lba48 = 0 '\000', bs = 0x555556393c40, version = "2.0.50\000\000", events = {eject_request = false, new_media = false}, sense_key = 5 '\005', asc = 36 '$', tray_open = false, tray_locked = false, cdrom_changed = 0 '\000', packet_transfer_size = 20, elementary_transfer_size = 0, io_buffer_index = 0, lba = -1, cd_sector_size = 2048, atapi_dma = 1, acct = {bytes = 804, start_time_ns = 26904886035916, type = BDRV_ACCT_READ}, pio_aiocb = 0x0, iov = {iov_base = 0x0, iov_len = 0}, qiov = {iov = 0x0, niov = 0, nalloc = 0, size = 0}, io_buffer_offset = 0, io_buffer_size = 0, sg = {sg = 0x0, nsg = 0, nalloc = 0, size = 0, dev = 0x0, as = 0x0}, req_nb_sectors = 0, end_transfer_func = 0x5555556d0ee3 <ide_atapi_cmd>, data_ptr = 0x7ffff7e4e80c "", data_end = 0x7ffff7e4e80c "", io_buffer = 0x7ffff7e4e800 "", io_buffer_total_len = 131076, cur_io_buffer_offset = 0, cur_io_buffer_len = 0, end_transfer_fn_idx = 0 '\000', sector_write_timer = 0x5555563b5fa0, irq_count = 0, ext_error = 0 '\000', mdata_size = 0, mdata_storage = 0x0, media_changed = 0, dma_cmd = IDE_DMA_READ, smart_enabled = 1 '\001', smart_autosave = 1 '\001', smart_errors = 0, smart_selftest_count = 0 '\000', smart_selftest_data = 0x5555563b8000 "", ncq_queues = 0}, {bus = 0x5555563cb1b0, unit = 1 '\001', drive_kind = IDE_HD, cylinders = 0, heads = 0, sectors = 0, chs_trans = 0, nb_sectors = 0, mult_sectors = 16, identify_set = 0, identify_data = '\000' <repeats 511 times>, drive_serial = 4, drive_serial_str = '\000' <repeats 20 times>, drive_model_str = '\000' <repeats 40 times>, wwn = 0, feature = 1 '\001', error = 1 '\001', nsector = 0, sector = 0 '\000', lcyl = 0 '\000', hcyl = 128 '\200', hob_feature = 0 '\000', hob_nsector = 0 '\000', hob_sector = 0 '\000', hob_lcyl = 0 '\000', hob_hcyl = 128 '\200', select = 176 '\260', status = 80 'P', lba48 = 0 '\000', bs = 0x0, version = "\000\000\000\000\000\000\000\000", events = { eject_request = false, new_media = false}, sense_key = 0 '\000', asc = 0 '\000', tray_open = false, tray_locked = false, cdrom_changed = 0 '\000', packet_transfer_size = 0, elementary_transfer_size = 0, io_buffer_index = 0, lba = 0, cd_sector_size = 0, atapi_dma = 0, acct = {bytes = 0, start_time_ns = 0, type = BDRV_ACCT_READ}, pio_aiocb = 0x0, iov = {iov_base = 0x0, iov_len = 0}, qiov = {iov = 0x0, niov = 0, nalloc = 0, size = 0}, io_buffer_offset = 0, io_buffer_size = 0, sg = {sg = 0x0, nsg = 0, nalloc = 0, size = 0, dev = 0x0, as = 0x0}, req_nb_sectors = 0, end_transfer_func = 0x5555556d7f17 <ide_dummy_transfer_stop>, data_ptr = 0x7ffff7e2d800 "\377\377\377\377", data_end = 0x7ffff7e2d800 "\377\377\377\377", io_buffer = 0x7ffff7e2d800 "\377\377\377\377", io_buffer_total_len = 131076, cur_io_buffer_offset = 0, cur_io_buffer_len = 0, end_transfer_fn_idx = 0 '\000', sector_write_timer = 0x5555563d6c50, irq_count = 0, ext_error = 0 '\000', mdata_size = 0, mdata_storage = 0x0, media_changed = 0, dma_cmd = IDE_DMA_READ, smart_enabled = 0 '\000', smart_autosave = 0 '\000', smart_errors = 0, smart_selftest_count = 0 '\000', smart_selftest_data = 0x5555563d7000 "", ncq_queues = 0}}, bus_id = 0, max_units = 2, dma = 0x5555563cb9e8, unit = 0 '\000', cmd = 8 '\b', irq = 0x5555563a2eb0, error_status = 0}, aiocb = 0x0, dma = {ops = 0x555555dc6560 <dbdma_ops>, iov = {iov_base = 0x0, iov_len = 0}, qiov = { iov = 0x0, niov = 0, nalloc = 0, size = 0}, aiocb = 0x0}, dbdma = 0x5555563cba40, dma_active = true} (gdb) p *s $6 = {bus = 0x5555563cb1b0, unit = 0 '\000', drive_kind = IDE_CD, cylinders = 0, heads = 0, sectors = 0, chs_trans = 0, nb_sectors = 451360, mult_sectors = 16, identify_set = 1, identify_data = "\300\205", '\000' <repeats 18 times>, "MQ0000 3", ' ' <repeats 12 times>, "\003\000\000\002\004\000.2.005 EQUMD DVR-MO", ' ' <repeats 28 times>, "\000\000\001\000\000\003\000\000\000\000\000\000\a", '\000' <repeats 17 times>, "\a\000\a\000\003\000\264\000\264\000,\001\264\000\000\000\000\000\036\000\036", '\000' <repeats 15 times>, "\036", '\000' <repeats 15 times>, "?\001", '\000' <repeats 333 times>, drive_serial = 3, drive_serial_str = "QM00003", '\000' <repeats 13 times>, drive_model_str = "QEMU DVD-ROM", '\000' <repeats 28 times>, wwn = 0, feature = 1 '\001', error = 0 '\000', nsector = 1, sector = 0 '\000', lcyl = 0 '\000', hcyl = 128 '\200', hob_feature = 0 '\000', hob_nsector = 3 '\003', hob_sector = 0 '\000', hob_lcyl = 34 '"', hob_hcyl = 0 '\000', select = 160 '\240', status = 88 'X', lba48 = 0 '\000', bs = 0x555556393c40, version = "2.0.50\000\000", events = {eject_request = false, new_media = false}, sense_key = 5 '\005', asc = 36 '$', tray_open = false, tray_locked = false, cdrom_changed = 0 '\000', packet_transfer_size = 20, elementary_transfer_size = 0, io_buffer_index = 0, lba = -1, cd_sector_size = 2048, atapi_dma = 1, acct = {bytes = 804, start_time_ns = 26904886035916, type = BDRV_ACCT_READ}, pio_aiocb = 0x0, iov = {iov_base = 0x0, iov_len = 0}, qiov = {iov = 0x0, niov = 0, nalloc = 0, size = 0}, io_buffer_offset = 0, io_buffer_size = 0, sg = {sg = 0x0, nsg = 0, nalloc = 0, size = 0, dev = 0x0, as = 0x0}, req_nb_sectors = 0, end_transfer_func = 0x5555556d0ee3 <ide_atapi_cmd>, data_ptr = 0x7ffff7e4e80c "", data_end = 0x7ffff7e4e80c "", io_buffer = 0x7ffff7e4e800 "", io_buffer_total_len = 131076, cur_io_buffer_offset = 0, cur_io_buffer_len = 0, end_transfer_fn_idx = 0 '\000', sector_write_timer = 0x5555563b5fa0, irq_count = 0, ext_error = 0 '\000', mdata_size = 0, mdata_storage = 0x0, media_changed = 0, dma_cmd = IDE_DMA_READ, smart_enabled = 1 '\001', smart_autosave = 1 '\001', smart_errors = 0, smart_selftest_count = 0 '\000', smart_selftest_data = 0x5555563b8000 "", ncq_queues = 0} My testing was done with commit 80fc95d8bdaf3392106b131a97ca701fd374489a already reverted as that was established before that it is not needed any more which simplifies pmac_ide_atapi_transfer_cb() quite a bit but I still can't understand the flow of this function and don't see where should I add a condition to handle this lba=-1 case that happens with READ_TOC using DMA. The reason I don't understand it is that the different fields (sizes and indexes) in these structures that are used in this callback don't make sense to me and I don't know how to use cpu_physical_memory_write() to copy data from the ide buffer to the guest memory as was suggested by Mark. Now that the problem is fairly well understood, wouldn't it be easier to one of you who understands what's happening to create a patch, instead of trying to explain all this to me? This part was last touched by Alexander Graf so I assume he knows how it works and it would not be too hard for him to fix it. I'm happy to help testing and providing more debugging info as needed but I'm not sure I want to detangle it and figure out the whole block layer and DBDMA without any documentation to be able to fix it myself. Would it be possible to find some time for it in the foreseeable future? (That might still be sooner than me wrapping my head around it.) Regards, BALATON Zoltan
diff --git a/hw/ide/macio.c b/hw/ide/macio.c index d3395f4..bce14fc 100644 --- a/hw/ide/macio.c +++ b/hw/ide/macio.c @@ -56,6 +56,7 @@ static void pmac_ide_atapi_transfer_cb(void *opaque, int ret) DBDMA_io *io = opaque; MACIOIDEState *m = io->opaque; IDEState *s = idebus_active_if(&m->bus); + int64_t sector_num; if (ret < 0) {