Bug 516177

Well, this is not that easy to debug but I know the Qemu SCSI controller implementation is using some USB implementation stuff as well as LSI53C895A PCI-to-Ultra2-SCSI controller [*] implementation in hw/lsi53c985a.c therefore there are many options that may introduce the issue. Unfortunately the debugging of qemu-dm process is not that easy because even with optimalizations disabled in the .rpmmacros of user that compiles the qemu-dm I can't get it compile not optimized for debugging with gdb. According to LSI53C985A specifications there is a SCRIPTS processor which is also implemented there in the lsi_execute_script() function. The scsi_read_data() function is called from lsi_do_dma(LSIState *s, int out) function only which according to it's 'out' parameter calls the scsi_read_data() or scsi_write_data() for the current device on the LSI53C895A controller implementation so I need to investigate many parts of the code by now with a lot of debug output messages to analyze the data.

From what I know, the current path is:
call 

Data are coming to the LSI controller which calls the SCRIPTS processor in lsi_execute_script() -> lsi_do_dma() either for data input (read) or data output (write) when corresponding phase is required -> scsi_{read|write}_data() -> bdrv_aio_{read|write}(completion='scsi_read_complete') -> bdrv_aio_{read|write}() -> raw_aio_{read|write}() -> this returns acb->common object (type BlockDriverAIOCB)

I am currently working on this one since yesterday and my guess it that something is trying to access the data when it's not ready yet. In synchronous transfers it expected the data to be available (which is nothing bad since it was synchronous) but when doing the asynchronous transfer there is probably the problem of data access to something that has not been read yet.

Michal

* http://www.lsi.com/DistributionSystem/AssetDocument/files/docs/techdocs/storage_stand_prod/SCSIControllers/lsi53c895a_tech_manual.pdf

Well, I did a fresh start with those patches with reading all the possible SCSI/LSI documentations to get to know why it's not working and I guess I know what the problem might be there - the problem is the asynchronous access. It happens in case of RHEL-5 i386 guest as well but only sometimes. Here's the output when I connected disk device as /dev/sda and tried to use fdisk on the disk:

# fdisk /dev/sda

Command (m for help): q

# fdisk /dev/sda
Device contains neither a valid DOS partition table, nor Sun, SGI or OSF disklabel
Building a new DOS disklabel. Changes will remain in memory only,
until you decide to write them. After that, of course, the previous
content won't be recoverable.

Warning: invalid flag 0x0000 of partition table 4 will be corrected by w(rite)

Command (m for help): p

Disk /dev/sda: 1073 MB, 1073741824 bytes
34 heads, 61 sectors/track, 1011 cylinders
Units = cylinders of 2074 * 512 = 1061888 bytes

   Device Boot      Start         End      Blocks   Id  System

Command (m for help): q

# fdisk /dev/sda

Command (m for help): p

Disk /dev/sda: 1073 MB, 1073741824 bytes
34 heads, 61 sectors/track, 1011 cylinders
Units = cylinders of 2074 * 512 = 1061888 bytes

   Device Boot      Start         End      Blocks   Id  System
/dev/sda1               1        1011     1048376+  83  Linux

...

In the first case it was seeing the partition on the drive in a correct way but in the second case (tried about 5 seconds after the first one with no operation done to the disk) it was not seeing the partition at all but in the third case (done about another 5 to 10 seconds later) was showing the partition right. This is the problem I've been afraid of when considering asynchronous I/O is being used. I'm still working on this one and I think it may need some proper/better message handling to send the completion message after it's really completed and not before it. This is the issue there I think. I don't know whether I'm on the right way to solve this one but it's most likely the asynchronous access issue according to my testing with RHEL-5 i386 FV guest so I'll focus on working out this issue next week.

Michal

(In reply to comment #5)
> Well, I did a fresh start with those patches with reading all the possible
> SCSI/LSI documentations to get to know why it's not working and I guess I know
> what the problem might be there - the problem is the asynchronous access. It
> happens in case of RHEL-5 i386 guest as well but only sometimes. Here's the
> output when I connected disk device as /dev/sda and tried to use fdisk on the
> disk:
> 
> # fdisk /dev/sda
> 
> Command (m for help): q
> 
> # fdisk /dev/sda
> Device contains neither a valid DOS partition table, nor Sun, SGI or OSF
> disklabel
> Building a new DOS disklabel. Changes will remain in memory only,
> until you decide to write them. After that, of course, the previous
> content won't be recoverable.
> 
> Warning: invalid flag 0x0000 of partition table 4 will be corrected by w(rite)
> 
> Command (m for help): p
> 

Well, the problem here is missing polling in the original patch. However, rewrite of the code was necessary because this code was not applicable to the current codebase we have. Also, the issue presented here is that bad that is prevents the write call to physical memory using the cpu_physical_memory_write() function to a good address because of the following code in the lsi_do_dma() function:
...
scsi_read_data(s->current_dev, buf, n);
cpu_physical_memory_write(addr, buf, n);
...
This expects the scsi_read_data transfer to be synchronous and when making it asynchronous and adding code to poll and wait - something like following:
...
ret = scsi_read_data(s->current_dev, buf, n);
if (ret == 3) {
    qemu_aio_poll();
    while ((ret = scsi_pending_get(s->current_dev)) > 0)
         qemu_aio_poll();
}
cpu_physical_memory_write(addr, buf, n);
...
it's the same like when we have synchronous scsi_read_data() function. Since there's count variable in the function lsi_do_dma() itself and read at the specific address defined as:
...
addr += n;
count -= n;
...
(i.e. incrementing address to be read and decrementing remaining count to read) we should have the implementation done at the end of lsi_do_dma() function in my opinion. This should increase the performance which is the goal for AIO implementation. I was unable to make Rik's implementation working.

Michal

One more thing to mention, I with the original Rik's patches for AIO I am trying to create a new partition using RHEL-5 i386 and I am able to create the partition but when I use mkfs on this partition and try to mount it, it returns errors:

# mount /dev/sda1 /mnt/test
EXT3-fs error (device sda1): ext3_check_descriptors: Block bitmap for group 0 not in group (block 32772)!
EXT3-fs: group descriptors corrupted!
mount: wrong fs type, bad option, bad superblock on /dev/sda1,
       missing codepage or other error
       In some cases useful info is found in syslog - try
       dmesg | tail  or so

so that's the reason why I did the fresh start.

Michal

(In reply to comment #7)
> One more thing to mention, I with the original Rik's patches for AIO I am
> trying to create a new partition using RHEL-5 i386 and I am able to create the
> partition but when I use mkfs on this partition and try to mount it, it returns
> errors:
> 
> # mount /dev/sda1 /mnt/test
> EXT3-fs error (device sda1): ext3_check_descriptors: Block bitmap for group 0
> not in group (block 32772)!
> EXT3-fs: group descriptors corrupted!
> mount: wrong fs type, bad option, bad superblock on /dev/sda1,
>        missing codepage or other error
>        In some cases useful info is found in syslog - try
>        dmesg | tail  or so
> 
> so that's the reason why I did the fresh start.
> 
> Michal    

Well, I managed to make it working for RHEL-5 guest (tried with RHEL-5 i386 guest) but it's having issues with Windows Vista, Windows XP and Windows 2003. The problem may be within the WinAPI format implementation expecting the data transfer to be synchronous and I am seeing many partial sector write operations here. Problem on Windows XP (both x86 and x64) was absence of 0x2F operation of SCSI controller which is basically VERIFY(10) operation (according to Wikipedia). When I did modify the code to simply ignore this operation (which should mean that everything is OK but unfortunately I can't find any good SCSI bus specification to check for both input and output specifications of this command. With adding support to ignore this command the SCSI drive formatting was appearing to be working but it hang on 100% of format and it was showing many entries in the debug log - i.e. read and/or write operations on some sector for some bigger count so it created a deadlock there. What I'm investigating right now is why does *not* the sector number change if it should according to the code.

Here are some examples:
 Windows Vista x86 - Write 256 sectors starting with sector_num = 128
 Windows XP x86 - Write 128 sectors starting with sector_num = 95
 Windows XP x86 - Write 128 sectors starting with sector_num = 95

Note: All the guests have been using LSI53C895A controller, no PV drivers to use the current SCSI device implementation which is not used when using PV drivers. Also, Windows guests were showing 2 drives that are uninitialized - one for LSI SCSI controller and second for PV drivers but I think it may have been caused by my modifications done to the ioemu.

Michal

Ok. This issue was never discovered on the Linux guest (RHEL-5 i386) for neither format partition nor write file operation. But it's very common even for formatting on Windows systems (but not for write).

From my investigation it appears that there's a deadlock since there are many scsi command (handled by scsi_send_command() function in hw/scsi-disk.c) for read/write operations. This is called by lsi_do_command() in LSI53C895A controller for the data read from dnad address of LSIState structure which is called from lsi_execute_script(), i.e. LSI SCRIPTS processor. There are 4 paths going to the SCRIPTS processor:
1) lsi_reg_writeb(offset = 0x14) for ISTAT0 SIGP signal when waiting state is 1 and this way it's woken by SIGP signal
2) lsi_reg_writeb(offset = 0x2f) for DSP[24:31] for no DMODE_MAN dmode and istat1 not having LSI_ISTAT1_SRUN bit
3) lsi_reg_writeb(offset = 0x3b) for DCNTL, i.e. LSI_DCNTL_STD bit being set and LSI_ISTAT1_SRUN not being set
4) lsi_command_complete for waiting state set to DMA operation in progress (2)

Long story short, it's path is:

lsi_reg_writeb() | lsi_command_complete() -> lsi_execute_script() -> lsi_do_command() -> scsi_send_command()

Honestly, I was thinking it's caused by missing instruction for verify command but yesterday, working on this assumption, I was having tough luck to make it working. Adding this instruction to the ioemu it took pretty long to format and the debug output was showing the write operation of 128 sectors starting from sector number 95 [scsi-disk: Write (sector 95, count 128)], after this there was a deadlock operation of read on the very same sector for the very same count. It's trying to read it indefinitely with no luck so it creates a deadlock. I am still working on this one but I'm just giving update how it's working. Unfortunately looking at the upstream doesn't help much since it's being impossible to backport because of number of patches and different codebase.

(In reply to comment #9)
> Ok. This issue was never discovered on the Linux guest (RHEL-5 i386) for
> neither format partition nor write file operation. But it's very common even
> for formatting on Windows systems (but not for write).
> 
> From my investigation it appears that there's a deadlock since there are many
> scsi command (handled by scsi_send_command() function in hw/scsi-disk.c) for
> read/write operations. This is called by lsi_do_command() in LSI53C895A
> controller for the data read from dnad address of LSIState structure which is
> called from lsi_execute_script(), i.e. LSI SCRIPTS processor. There are 4 paths
> going to the SCRIPTS processor:
> 1) lsi_reg_writeb(offset = 0x14) for ISTAT0 SIGP signal when waiting state is 1
> and this way it's woken by SIGP signal
> 2) lsi_reg_writeb(offset = 0x2f) for DSP[24:31] for no DMODE_MAN dmode and
> istat1 not having LSI_ISTAT1_SRUN bit
> 3) lsi_reg_writeb(offset = 0x3b) for DCNTL, i.e. LSI_DCNTL_STD bit being set
> and LSI_ISTAT1_SRUN not being set
> 4) lsi_command_complete for waiting state set to DMA operation in progress (2)
> 
> Long story short, it's path is:
> 
> lsi_reg_writeb() | lsi_command_complete() -> lsi_execute_script() ->
> lsi_do_command() -> scsi_send_command()
> 
> Honestly, I was thinking it's caused by missing instruction for verify command
> but yesterday, working on this assumption, I was having tough luck to make it
> working. Adding this instruction to the ioemu it took pretty long to format and
> the debug output was showing the write operation of 128 sectors starting from
> sector number 95 [scsi-disk: Write (sector 95, count 128)], after this there
> was a deadlock operation of read on the very same sector for the very same
> count. It's trying to read it indefinitely with no luck so it creates a
> deadlock. I am still working on this one but I'm just giving update how it's
> working. Unfortunately looking at the upstream doesn't help much since it's
> being impossible to backport because of number of patches and different
> codebase.    

One more update, I've been testing this using SCSI drive with all the SCSI patches reverted and it was not working for formatting a drive in Windows environment either so this means this was apparently never working so the issue may be anywhere on it's path but I think it will be in either LSI bus controller or scsi-disk layer implementation. This is and never was the issue on Linux systems according to my testing so I guess the problem here is the Windows implementation of formatting in their API since they are not writing the full sectors and there are partial sector writes and this implementation may be buggy since I don't see this in case of Linux system but it's very common on Windows systems. So, according to my testing the SCSI AIO patch never made a regression or anything since it was always unable to format SCSI drive (I made a reverted version but it was not working either). Now, I am doing some investigation of partial sector write implementation to debug the problem.

Michal

Well, now I am pretty sure the problem is caused by the Windows SCSI drivers implementatiom since when I've turned on the LSI and SCSI debug logs and tested formatting a SCSI drive with both Linux and Windows systems to get the results. (It's working fine in Linux guests but not in Windows guests)

The key differences is that in Linux it was writing the data by sectors, len % 512 == 0. This passes correctly and there's a 'lsi_scsi: Command complete sense = 0' line in the log file after this is done. Also, Linux SCSI drivers are calling only Write() calls when doing disk format operation whereas Windows systems act differently - they combine write and read operation to confirm the data has been written to the disk (apparently) but the issue here is caused by fact they doesn't write full sectors. Even if there's a buffer to accumulate all the data and them flush them to sector when accumulated it's not working correctly.

Also, the debug logs are showing an issue of wrong phase meaning that the controller is unable to perform the requested action when the previous one is not the one that is expected. Therefore it does SCSI Interrupt, updates the IRQ level for levels 1 and 0, clears ATN ACK and then calls the operation (DMA out) again with the very same values for address, length and available data length so it tries to retry to operation with no luck which causes the Windows systems to report error when formatting the SCSI drives.

More investigation is still necessary but I hope to bring good news and a patch soon since now I know this is caused by LSI controller getting wrong instructions and therefore I *thinK* it could be workarounded in the LSI controller implementation.

Michal

Well, I did look at qemu-xen-unstable changesets in the Git and I was able to make it working but still with some issues which I am currently working on. There are about 5-6 that I've backported to make it working but there's still something missing so I'll investigate this further but I think I am very close to the final result. The main issue here was that for SCSI drives we need SCSI Tagged Command Queueing implemented which required me to backport it from upstream but this is not the only one patch to be implemented.

Michal

Created attachment 413819 [details]
SCSI and USB AIO support for Xen

Hi,
I've been working on this one for a long time and finally I am having the patch. The patch is basically a backport of nine xen-qemu-unstable patches with some modifications done as well. The main issue was absence of SCSI Tagged Command Queueing support [1] and also missing 64-bit Block Move support in LSI controller which made it not working with backporting just one patch, the SCSI and USB async IO support. The 64-bit Block Move support is necessary for 64-bit Windows guests which are unable to format the drive without the patch included. 

This patch has been tested using all the various Windows and Linux guests that does support LSI53C895A controller, including Windows 2003/XP both 32-bit and 64-bit, Windows Vista 32-bit and 64-bit/Windows 2008 and RHEL-5 guests (both 32-bit and 64-bit). All the testing was done using various read/write operations for multiple data files of ~100MB in size. Even the formatting was done using all the guests specified, including the 64-bit Windows guests so it resolves bug 552573 too.

I've also tested it with Windows 7 and Windows 2008 R2 but I was not able to see the SCSI controller here even without this patch applied so I guess the LSI drivers were dropped there for some reasons which results into SCSI devices not working on those guests.

Michal

[1] http://en.wikipedia.org/wiki/Tagged_Command_Queuing

Great! Do you have the nine patches split?

(In reply to comment #14)
> Great! Do you have the nine patches split?    

Well, I wanted to split it first but finally I don't know how could I split that so I do not have them split. Also, their git doesn't have gitweb so it may be really hard to see the original patches. Would you like me to put those original patches here as a tar-ed attachment?

Michal

Created attachment 415069 [details]
New version of my patch (joined git commits relevant to those patches)

Created attachment 415139 [details]
SCSI and USB AIO Patch v3

New version of my patch in form of joined git commits relevant to those patches. Since there is a bug 552573 about Win64 formatting it's not being added to those patches. Testing was done using Win32 and Linux i386 and x86_64 guests and it was working fine.

Michal

all tests seems fine now, except for there is some error message during rhel6-32bit hvm guest boot on xen3.0.3-115 32bit host

------------
ata_piix 0000:00:01.1: setting latency timer to 64
scsi0 : ata_piix
scsi1 : ata_piix
ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc000 irq 14
ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc008 irq 15
ata1.00: ATA-7: QEMU HARDDISK, 0.8.2, max UDMA/100
ata1.00: 16777216 sectors, multi 16: LBA48 
ata1.00: configured for MWDMA2
scsi 0:0:0:0: Direct-Access     ATA      QEMU HARDDISK    0.8. PQ: 0 ANSI: 5
  alloc irq_desc for 36 on node -1
  alloc kstat_irqs on node -1
sym53c8xx 0000:00:05.0: PCI INT A -> GSI 36 (level, low) -> IRQ 36
sym53c8xx 0000:00:05.0: setting latency timer to 64
sym0: <895a> rev 0x0 at pci 0000:00:05.0 irq 36
sym0: No NVRAM, ID 7, Fast-40, LVD, parity checking
sym0: SCSI BUS has been reset.
scsi2 : sym-2.2.3
sd 0:0:0:0: [sda] 16777216 512-byte logical blocks: (8.58 GB/8.00 GiB)
sd 0:0:0:0: [sda] Write Protect is off
sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
 sda: sda1 sda2
sd 0:0:0:0: [sda] Attached SCSI disk
Marking TSC unstable due to TSC halt in AMD C1E
System has AMD C1E enabled
Switch to broadcast mode on CPU0
Switching to clocksource acpi_pm
scsi scan: INQUIRY result too short (5), using 36
scsi 2:0:0:0: Direct-Access                                    PQ: 0 ANSI: 0
scsi 2:0:0:0: Information Units disabled by blacklist
scsi target2:0:0: Beginning Domain Validation
scsi target2:0:0: Ending Domain Validation
scsi scan: INQUIRY result too short (5), using 36
scsi scan: INQUIRY result too short (5), using 36
scsi 2:0:1:0: Direct-Access                                    PQ: 0 ANSI: 0
scsi 2:0:1:0: Information Units disabled by blacklist
scsi target2:0:1: Beginning Domain Validation
scsi target2:0:1: Ending Domain Validation
scsi scan: INQUIRY result too short (5), using 36
scsi scan: INQUIRY result too short (5), using 36
scsi 2:0:2:0: Direct-Access                                    PQ: 0 ANSI: 0
scsi 2:0:2:0: Information Units disabled by blacklist
scsi target2:0:2: Beginning Domain Validation
scsi target2:0:2: Ending Domain Validation
scsi scan: INQUIRY result too short (5), using 36
sd 2:0:0:0: [sdb] 2097152 512-byte logical blocks: (1.07 GB/1.00 GiB)
sd 2:0:0:0: [sdb] Write Protect is off
sd 2:0:0:0: [sdb] Mode Sense: 13 00 00 00
sd 2:0:0:0: [sdb] Got wrong page
sd 2:0:0:0: [sdb] Assuming drive cache: write through
sd 2:0:1:0: [sdc] 2097152 512-byte logical blocks: (1.07 GB/1.00 GiB)
sd 2:0:1:0: [sdc] Write Protect is off
sd 2:0:1:0: [sdc] Mode Sense: 13 00 00 00
sd 2:0:1:0: [sdc] Got wrong page
sd 2:0:1:0: [sdc] Assuming drive cache: write through
sd 2:0:0:0: [sdb] Got wrong page
sd 2:0:0:0: [sdb] Assuming drive cache: write through
 sdb:
sd 2:0:2:0: [sdd] 2097152 512-byte logical blocks: (1.07 GB/1.00 GiB)
sd 2:0:2:0: [sdd] Write Protect is off
sd 2:0:2:0: [sdd] Mode Sense: 13 00 00 00
sd 2:0:2:0: [sdd] Got wrong page
sd 2:0:2:0: [sdd] Assuming drive cache: write through
sd 2:0:2:0: [sdd] Got wrong page
sd 2:0:2:0: [sdd] Assuming drive cache: write through
sd 2:0:1:0: [sdc] Got wrong page
sd 2:0:1:0: [sdc] Assuming drive cache: write through
 sdc: sdb1
sd 2:0:0:0: [sdb] Got wrong page
sd 2:0:0:0: [sdb] Assuming drive cache: write through
sd 2:0:0:0: [sdb] Attached SCSI disk
 sdc1
sd 2:0:1:0: [sdc] Got wrong page
sd 2:0:1:0: [sdc] Assuming drive cache: write through
sd 2:0:1:0: [sdc] Attached SCSI disk
 sdd: sdd1
sd 2:0:2:0: [sdd] Got wrong page
sd 2:0:2:0: [sdd] Assuming drive cache: write through
sd 2:0:2:0: [sdd] Attached SCSI disk
dracut: Scanning devices sda2  for LVM logical volumes vg_virtlab6685200/lv_root vg_virtlab6685200/lv_swap 
dracut: inactive '/dev/vg_virtlab6685200/lv_root' [5.54 GiB] inherit
dracut: inactive '/dev/vg_virtlab6685200/lv_swap' [1.97 GiB] inherit
EXT4-fs (dm-0): INFO: recovery required on readonly filesystem
EXT4-fs (dm-0): write access will be enabled during recovery
EXT4-fs (dm-0): recovery complete
EXT4-fs (dm-0): mounted filesystem with ordered data mode
dracut: Mounted root filesystem /dev/mapper/vg_virtlab6685200-lv_root
dracut: Loading SELinux policy
SELinux:  Disabled at runtime.
SELinux:  Unregistering netfilter hooks
type=1404 audit(1282747038.513:2): selinux=0 auid=4294967295 ses=4294967295
dracut: /sbin/load_policy: Can't load policy: No such file or directory
dracut: Switching root
udev: starting version 147
piix4_smbus 0000:00:01.2: SMBus base address uninitialized - upgrade BIOS or use force_addr=0xaddr
sd 0:0:0:0: Attached scsi generic sg0 type 0
sd 2:0:0:0: Attached scsi generic sg1 type 0
sd 2:0:1:0: Attached scsi generic sg2 type 0
sd 2:0:2:0: Attached scsi generic sg3 type 0
----------------

scsi disk format, dd, file copy and iozone test is fine.
Michal, do you think these error msg is OK?

the error message in comment 32 can also be seen on rhel6 32/64bit guest on xen-3.0.3-115 x86_64 host.

> ...
> scsi disk format, dd, file copy and iozone test is fine.
> Michal, do you think these error msg is OK?

Well, I don't know what does those errors stand for but if the guest is working fine for all the operations used when testing (which are operations that are being used by a normal user I guess) I guess we could ignore those messages. Maybe it's something in the drivers itself (not saying it's a bug but maybe just something implemented in a different way not 100% complying with the specs or something). If it would make an issue when testing we should take care of that but if everything is working fine I guess we can ignore this.

Michal

The INQUIRY errors are a separate bug, and most likely not a regression.

filed a new bug for the error message in comment 32
https://bugzilla.redhat.com/show_bug.cgi?id=627551

verified this bug, as the error msg in comment 32 is not a regression and already submitted new bug for it

verified this bug, as the error msg in comment 32 is not a regression and already submitted new bug for it

An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on therefore solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.

http://rhn.redhat.com/errata/RHBA-2011-0031.html