Re: [Qemu-devel] [Qemu-ppc] macio ide question/bug report

[BALATON Zoltan <balaton@eik.bme.hu>]

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