[Qemu-ppc] macio ide question/bug report

On 15/05/14 18:28, BALATON Zoltan wrote:

>> 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

(lots cut)

So that looks like the correct request based upon it's size so what 
happened when you stepped into pmac_ide_atapi_transfer_cb()...?

> 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

Sadly I've now found that this isn't the case (email to the qemu-devel 
list to follow, but I've run out of time today) :(

> 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?

Well my understanding is that it's impossible to boot a MorphOS image 
directly and requires all sorts of tricks with debuggers etc. Unless you 
can provide a "run this and it breaks" test case, then the time barrier 
for trying to fix bugs like this is exceptionally high.

You mention that you don't understand the fields and sizes, so explain 
which ones you don't understand and ask. Search around for guides to how 
ATAPI/IDE works, and compare with gdb output to find the correlation 
with the IDEState variables. Have you tried looking at the header file 
for cpu_physical_memory_write()? Even to someone who had never seen this 
function before Alex's patches, it seems fairly obvious how the API 
should work.

I'm afraid that there really is no alternative to spending the time 
getting stuck into the code, experimenting, adding printf()'s in 
exciting places, and then asking specific questions to the mailing list.

> 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.)

Please see above. FWIW based upon the your gdb output I've put together 
the following patch which compiles, but that's all I can vouch for it. 
Further testing and debugging will have to be done by you, although I 
will try and respond to specific questions where possible.


ATB,

Mark.

On Thu, 15 May 2014, Mark Cave-Ayland wrote:
> On 15/05/14 18:28, BALATON Zoltan wrote:
>> #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
>
> (lots cut)
>
> So that looks like the correct request based upon it's size so what happened 
> when you stepped into pmac_ide_atapi_transfer_cb()...?

Did not follow it to the end because we know it would fail and the sense 
value returned seems to be just a remnant of previous failures as can be 
seen from the structures I've printed.

>> 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
>
> Sadly I've now found that this isn't the case (email to the qemu-devel list 
> to follow, but I've run out of time today) :(

OK, I'm back to the HEAD version and testing with that with your patch 
applied.

> Well my understanding is that it's impossible to boot a MorphOS image 
> directly and requires all sorts of tricks with debuggers etc. Unless you can 
> provide a "run this and it breaks" test case, then the time barrier for 
> trying to fix bugs like this is exceptionally high.

Unfortunately it is not straightforward to test with MorphOS but I think 
it could be reproduced with other OS-es if they can be made to do a read 
TOC with DMA. I can try to find a way to reproduce it with Linux but 
hopefully we can get to the end of it now. (I think we are close.)

> You mention that you don't understand the fields and sizes, so explain which 
> ones you don't understand and ask. Search around for guides to how ATAPI/IDE

The ones used in pmac_ide_atapi_transfer_cb(). It's not clear to me where 
is the source buffer where is the destination and what is the correct 
lenght to use. Your patch helps but it's not correct yet. See below.

> Please see above. FWIW based upon the your gdb output I've put together the 
> following patch which compiles, but that's all I can vouch for it. Further 
> testing and debugging will have to be done by you, although I will try and 
> respond to specific questions where possible.

Thanks a lot. I've tested your patch and it comes closer but not quite 
there yet. Running it in a debugger I've seen this:

Breakpoint 1, pmac_ide_transfer (io=0x5555563d1068) at hw/ide/macio.c:340
340	{
(gdb) n
341	    MACIOIDEState *m = io->opaque;
342	    IDEState *s = idebus_active_if(&m->bus);
344	    MACIO_DPRINTF("pmac_ide_transfer%s lba=%x, buffer_index=%x, len=%x\n",
pmac_ide_transfer(ATAPI) lba=ffffffff, buffer_index=0, len=324
348	    s->io_buffer_size = 0;
349	    if (s->drive_kind == IDE_CD) {
350	        bdrv_acct_start(s->bs, &s->acct, io->len, BDRV_ACCT_READ);
351	        pmac_ide_atapi_transfer_cb(io, 0);
(gdb) s
pmac_ide_atapi_transfer_cb (opaque=0x5555563d1068, ret=0) at hw/ide/macio.c:55
55	{
56	    DBDMA_io *io = opaque;
57	    MACIOIDEState *m = io->opaque;
58	    IDEState *s = idebus_active_if(&m->bus);
61	    if (ret < 0) {
69	    if (!m->dma_active) {
77	    MACIO_DPRINTF("io_buffer_size = %#x\n", s->io_buffer_size);
io_buffer_size = 0
79	    if (s->io_buffer_size > 0) {
90	    s->io_buffer_size = MIN(io->len, s->packet_transfer_size);
92	    MACIO_DPRINTF("remainder: %d io->len: %d size: %d\n", io->remainder_len,
remainder: 0 io->len: 804 size: 20
94	    if (io->remainder_len && io->len) {
114	    if (s->packet_transfer_size && s->lba == -1) {
115	        MACIO_DPRINTF("non-IO ATAPI DMA transfer size: %d\n", io->len);
non-IO ATAPI DMA transfer size: 804
117	        cpu_physical_memory_write(io->addr, s->io_buffer, io->len);
(gdb) x/40x s->io_buffer
0x7ffff7e4e800:	0x01011200	0x00011400	0x00000000	0x00aa1600
0x7ffff7e4e810:	0xc8b80100	0x00000000	0x00000000	0x00000000
0x7ffff7e4e820:	0x2e300000	0x20202020	0x02000003	0x322e0004
0x7ffff7e4e830:	0x3530302e	0x51452020	0x20444d55	0x2d525644
0x7ffff7e4e840:	0x20204f4d	0x20202020	0x20202020	0x20202020
0x7ffff7e4e850:	0x20202020	0x20202020	0x20202020	0x00002020
0x7ffff7e4e860:	0x03000001	0x00000000	0x00070000	0x00000000
0x7ffff7e4e870:	0x00000000	0x00000000	0x00000000	0x00070007
0x7ffff7e4e880:	0x00b40003	0x012c00b4	0x000000b4	0x001e0000
0x7ffff7e4e890:	0x0000001e	0x00000000	0x00000000	0x00000000
(gdb) n
118	        s->packet_transfer_size -= io->len;
(gdb) p s->packet_transfer_size
$2 = 20
(gdb) n
119	        MACIO_DPRINTF("end of non-IO ATAPI DMA transfer\n");
end of non-IO ATAPI DMA transfer
122	    if (!s->packet_transfer_size) {
(gdb) p s->io_buffer_size
$3 = 20
(gdb) l
117	        cpu_physical_memory_write(io->addr, s->io_buffer, io->len);
118	        s->packet_transfer_size -= io->len;
119	        MACIO_DPRINTF("end of non-IO ATAPI DMA transfer\n");
120	    }
121
122	    if (!s->packet_transfer_size) {
123	        MACIO_DPRINTF("end of transfer\n");
124	        ide_atapi_cmd_ok(s);
125	        m->dma_active = false;
126	    }
127
128	    if (io->len == 0) {
129	        MACIO_DPRINTF("end of DMA\n");
130	        goto done;
131	    }
132
133	    /* launch next transfer */
134
135	    /* handle unaligned accesses first, get them over with and only do the
136	       remaining bulk transfer using our async DMA helpers */
(gdb) c
Continuing.
precopying unaligned 292 bytes to 0xe4f064
io->len = 0x200
set remainder to: -804
sector_num=-4 size=-784, cmd_cmd=0
atapi_cmd_error: sense=0x5 asc=0x21
done DMA
DBDMA: dbdma_end
DBDMA: conditional_wait
DBDMA: dbdma_cmdptr_save 0x00e51bb0
DBDMA: xfer_status 0x00008400 res_count 0x0000
DBDMA: conditional_interrupt
DBDMA: conditional_branch
DBDMA: dbdma_cmdptr_load 0x00e51bc0
DBDMA: channel_run
dbdma_cmd 0x5555563d12b0
     req_count 0x0000
     command 0x7000
     phy_addr 0x00000000
     cmd_dep 0x00000000
     res_count 0x0000
     xfer_status 0x0000
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

So it still fails but maybe only because the wrong size is used (io->len). 
(That's what I meant when I said these values are not clear to me and very 
confusing.) Do you think that replacing io->len in your patch with 
s->io_buffer_size would be the correct thing to do?

Regards,
BALATON Zoltan

On Thu, 15 May 2014, BALATON Zoltan wrote:
> confusing.) Do you think that replacing io->len in your patch with 
> s->io_buffer_size would be the correct thing to do?

Probably that's not enough. I've tried it and then it gets to here:

end of non-IO ATAPI DMA transfer
122	    if (!s->packet_transfer_size) {
(gdb) p s->packet_transfer_size
$1 = 0
(gdb) n
123	        MACIO_DPRINTF("end of transfer\n");
end of transfer
124	        ide_atapi_cmd_ok(s);
125	        m->dma_active = false;
128	    if (io->len == 0) {
(gdb) p io->len
$2 = 804
(gdb) l
123	        MACIO_DPRINTF("end of transfer\n");
124	        ide_atapi_cmd_ok(s);
125	        m->dma_active = false;
126	    }
127
128	    if (io->len == 0) {
129	        MACIO_DPRINTF("end of DMA\n");
130	        goto done;
131	    }
132
133	    /* launch next transfer */
134
135	    /* handle unaligned accesses first, get them over with and only do the
136	       remaining bulk transfer using our async DMA helpers */
137	    unaligned = io->len & 0x1ff;
138	    if (unaligned) {
139	        int sector_num = (s->lba << 2) + (s->io_buffer_index >> 9);
140	        int nsector = io->len >> 9;
141
142	        MACIO_DPRINTF("precopying unaligned %d bytes to %#" HWADDR_PRIx "\n",
(gdb) c
Continuing.
precopying unaligned 292 bytes to 0xe4f50c
io->len = 0x200
set remainder to: -20
sector_num=-4 size=0, cmd_cmd=0
atapi_cmd_error: sense=0x5 asc=0x21
done DMA
DBDMA: dbdma_end

Regards,
BALATON Zoltan

On Thu, 15 May 2014, BALATON Zoltan wrote:
> On Thu, 15 May 2014, BALATON Zoltan wrote:
>> confusing.) Do you think that replacing io->len in your patch with 
>> s->io_buffer_size would be the correct thing to do?
>
> Probably that's not enough. I've tried it and then it gets to here:

I should've also included these lines too to make it more clear what did I 
change:

114	    if (s->packet_transfer_size && s->lba == -1) {
115	        MACIO_DPRINTF("non-IO ATAPI DMA transfer size: %d\n", io->len);
non-IO ATAPI DMA transfer size: 804
117	        cpu_physical_memory_write(io->addr, s->io_buffer, s->io_buffer_size);
118	        s->packet_transfer_size -= s->io_buffer_size;
119	        MACIO_DPRINTF("end of non-IO ATAPI DMA transfer\n");

> end of non-IO ATAPI DMA transfer
> 122	    if (!s->packet_transfer_size) {
> (gdb) p s->packet_transfer_size
> $1 = 0
> (gdb) n
> 123	        MACIO_DPRINTF("end of transfer\n");
> end of transfer
> 124	        ide_atapi_cmd_ok(s);
> 125	        m->dma_active = false;
> 128	    if (io->len == 0) {
> (gdb) p io->len
> $2 = 804
> (gdb) l
> 123	        MACIO_DPRINTF("end of transfer\n");
> 124	        ide_atapi_cmd_ok(s);
> 125	        m->dma_active = false;
> 126	    }
> 127
> 128	    if (io->len == 0) {
> 129	        MACIO_DPRINTF("end of DMA\n");
> 130	        goto done;
> 131	    }
> 132
> 133	    /* launch next transfer */
> 134
> 135	    /* handle unaligned accesses first, get them over with and only 
> do the
> 136	       remaining bulk transfer using our async DMA helpers */
> 137	    unaligned = io->len & 0x1ff;
> 138	    if (unaligned) {
> 139	        int sector_num = (s->lba << 2) + (s->io_buffer_index >> 9);
> 140	        int nsector = io->len >> 9;
> 141
> 142	        MACIO_DPRINTF("precopying unaligned %d bytes to %#" 
> HWADDR_PRIx "\n",
> (gdb) c
> Continuing.
> precopying unaligned 292 bytes to 0xe4f50c
> io->len = 0x200
> set remainder to: -20
> sector_num=-4 size=0, cmd_cmd=0
> atapi_cmd_error: sense=0x5 asc=0x21
> done DMA
> DBDMA: dbdma_end
>
> Regards,
> BALATON Zoltan
>