Bugs item #2482759, was opened at 2009-01-02 21:03 Message generated for change (Comment added) made by aketzu You can respond by visiting: https://sourceforge.net/tracker/?func=detail&atid=893831&aid=2482759&group_id=180599
Please note that this message will contain a full copy of the comment thread, including the initial issue submission, for this request, not just the latest update. Category: None Group: None Status: Open Resolution: None Priority: 5 Private: No Submitted By: Ryan Bair (ryandbair) Assigned to: Nobody/Anonymous (nobody) Summary: Windows SCSI errors Initial Comment: When starting up a fresh install of Windows Server 2003 R2 x64, I get errors similar to the following... scsi-disk: Command: lun=0 tag=0x0 data=0x12 0x01 0x00 0x00 0xff 0x00 scsi-disk: Inquiry (len 255) scsi-disk: Inquiry EVPD[Supported pages] buffer size 255 scsi-disk: Read buf_len=7 scsi-disk: Read sector_count=0 scsi-disk: Command complete tag=0x0 status=0 sense=0 lsi_scsi: error: Unhandled writeb 0xff = 0x0 lsi_scsi: error: Unhandled writeb 0x100 = 0x0 lsi_scsi: error: Unhandled writeb 0x101 = 0x0 lsi_scsi: error: Unhandled writeb 0x102 = 0x0 While these errors are happening on boot, the animated bar continues to scroll. The errors continue for about a minute and then everything suddenly kicks into gear and the machine continues to boot. This also happens while trying to get partition information through the device properties in the device manager and through the disk management mmc snapin. I'm running kvm-82 on Debian Lenny AMD64. The disk is a 20GB virtual SCSI, raw format. Here's the command I'm using to run KVM. kvm -m 1024 -smp 2 -drive file=system.img,if=scsi,boot=on -localtime --vnc 127.0.0.1:0 &> ../win2k3x64.log ---------------------------------------------------------------------- Comment By: Anssi Kolehmainen (aketzu) Date: 2009-01-06 12:58 Message: With that patch Win2k8 64bit install seems to work pretty nicely. Only thing is that just in the end installer freezes for few seconds. Log shows that SCRIPTS has gotten into infinite loop: [1231238098.644651] scsi-disk: Command: lun=0 tag=0x100e1 data=0x28 0x00 0x00 0x13 0x4b 0xb0 0x00 0x00 0x88 0x00 [1231238098.644655] scsi-disk: Read (sector 1264560, count 136) [1231238098.644658] scsi-disk: Read sector_count=136 ... [1231238098.706945] scsi-disk: Command complete tag=0x100e1 status=0 sense=0 ... [1231238098.765279] lsi_scsi: Jump to 0xf0022068 [1231238098.765282] lsi_scsi: SCRIPTS dsp=f0022068 opcode f11c0004 arg 00000000 [1231238098.765285] lsi_scsi: Load reg 0x1c size 4 addr 0x3fc70b58 = 3fc721e0 [1231238098.765288] lsi_scsi: Write reg 1c = e0 [1231238098.765291] lsi_scsi: Write reg 1d = 21 [1231238098.765293] lsi_scsi: Write reg 1e = c7 [1231238098.765296] lsi_scsi: Write reg 1f = 3f [1231238098.765299] lsi_scsi: SCRIPTS dsp=f0022070 opcode 721c0000 arg 00000000 [1231238098.765302] lsi_scsi: Read reg 0x1c OR data8=0x00 sfbr=0xe0 [1231238098.765305] lsi_scsi: Read reg 1c (=e0) [1231238098.765308] lsi_scsi: SCRIPTS dsp=f0022078 opcode 80840000 arg ffffffe8 [1231238098.765311] lsi_scsi: Compare data 0xe0 & 0xff != 0x0 [1231238098.765314] lsi_scsi: Jump to 0xf0022068 [1231238098.765316] lsi_scsi: SCRIPTS dsp=f0022068 opcode f11c0004 arg 00000000 [1231238098.765319] lsi_scsi: Load reg 0x1c size 4 addr 0x3fc70b58 = 3fc721e0 [1231238098.765322] lsi_scsi: Write reg 1c = e0 [1231238098.765325] lsi_scsi: Write reg 1d = 21 [1231238098.765328] lsi_scsi: Write reg 1e = c7 [1231238098.765331] lsi_scsi: Write reg 1f = 3f [1231238098.765333] lsi_scsi: SCRIPTS dsp=f0022070 opcode 721c0000 arg 00000000 [1231238098.765336] lsi_scsi: Read reg 0x1c OR data8=0x00 sfbr=0xe0 [1231238098.765340] lsi_scsi: Read reg 1c (=e0) [1231238098.765342] lsi_scsi: SCRIPTS dsp=f0022078 opcode 80840000 arg ffffffe8 [1231238098.765345] lsi_scsi: Compare data 0xe0 & 0xff != 0x0 [1231238098.765354] lsi_scsi: Jump to 0xf0022068 ... [1231238098.816065] lsi_scsi: SCSI Interrupt 0x0004 prev 0x0000 [1231238098.816069] lsi_scsi: SCRIPTS execution stopped Though timestamps tell that isn't the main delay. There is about five seconds of just 'Read reg 14' and then Windows does reset on the adapter. Tried Win2k3 (32-bit) with that patch and it seemed to work just fine. But when I tried to trigger bad status move error I've been getting earlier it resulted in 'Unimplemented message 0x77' error. Further digging out the cause I noticed that when writing data at some point Windows decides it wants to reset the adapter (probably because there is no Command complete message within few ms of Write data message). [1231235738.961354] scsi-disk: Write data tag=0x1009d [1231235738.961361] lsi_scsi: SCRIPTS execution stopped [1231235738.961409] lsi_scsi: Read reg 4f (=02) [1231235738.961926] lsi_scsi: Read reg 4f (=02) [1231235738.962442] lsi_scsi: Read reg 4f (=02) [1231235738.962957] lsi_scsi: Read reg 4f (=02) [1231235738.963472] lsi_scsi: Read reg 4f (=02) [1231235738.963480] lsi_scsi: Read reg 4f (=02) [1231235738.963489] lsi_scsi: Write reg 14 = 40 [1231235738.963493] lsi_scsi: Reset ..etc Interesting thing is that the command complete for pre-reset write arrives much later... [1231235738.966962] scsi-disk: Read sector_count=0 [1231235738.966965] scsi-disk: Command complete tag=0x10083 status=0 sense=0 ..snip.. [1231235738.967663] scsi-disk: Read sector_count=0 [1231235738.967666] scsi-disk: Command complete tag=0x1003c status=0 sense=0 ..snip.. [1231235738.971199] scsi-disk: Command complete tag=0x1009d status=0 sense=0 [1231235738.971205] lsi_scsi: Command complete sense=0 And then it does some command complete processing but since most of the data has just been reset it doesn't do anything good... With patch for not triggering phase mismatch the 'Bad Status move' error turns into: [1231235738.971438] lsi_scsi: SCRIPTS dsp=f00228a4 opcode 1e000000 arg 00000028 [1231235738.971442] lsi_scsi: MSG out len=655360 [1231235738.971445] lsi_scsi: MSG: Disconnect [1231235738.971447] lsi_scsi: MSG: Disconnect [1231235738.971450] lsi_scsi: MSG: Disconnect .. snip many MSG: Disconnect :) [1231235739.146850] lsi_scsi: Read reg 0 (=ca) [1231235739.146853] lsi_scsi: Select LUN 2 [1231235739.146856] lsi_scsi: Read reg 1 (=00) [1231235739.146859] lsi_scsi: MSG: Disconnect [1231235739.146862] lsi_scsi: Read reg 2 (=00) [1231235739.146864] lsi_scsi: MSG: Disconnect [1231235739.146867] lsi_scsi: Read reg 3 (=77) [1231235739.146870] lsi_scsi: error: Unimplemented message 0x77 ---------------------------------------------------------------------- Comment By: Ryan Harper (ryan_harper) Date: 2009-01-06 07:08 Message: So, it seems the issue (reason for the lenghty timeouts) is we're triggering a phase mismatch when we're returning EVPD, and Mode Sense data since we only provide a subset of data. Observe the following trace: scsi-disk: Command: lun=0 tag=0x0 data=0x12 0x01 0x00 0x00 0xff 0x00 scsi-disk: Inquiry (len 255) scsi-disk: Inquiry EVPD[Supported pages] buffer size 255 lsi_scsi: lsi_set_phase: transition 2 -> 1 scsi-disk: Read buf_len=7 lsi_scsi: Data ready tag=0x0 len=7 lsi_scsi: SCRIPTS dsp=f2002180 opcode 818b0000 arg 00000020 lsi_scsi: Compare phase 1 == 1 lsi_scsi: Jump to 0xf20021a8 lsi_scsi: SCRIPTS dsp=f20021a8 opcode f11c0004 arg 00000004 lsi_scsi: Load reg 0x1c size 4 addr 0x03527044 = 03527078 lsi_scsi: SCRIPTS dsp=f20021b0 opcode e01c0004 arg f20021c4 lsi_scsi: Store reg 0x1c size 4 addr 0xf20021c4 lsi_scsi: SCRIPTS dsp=f20021b8 opcode 7a570100 arg 00000000 lsi_scsi: Read-Modify-Write reg 0x57 OR data8=0x01 sfbr=0x12 lsi_scsi: SCRIPTS dsp=f20021c0 opcode 88080000 arg 03527078 lsi_scsi: Call 0x03527078 lsi_scsi: SCRIPTS dsp=03527078 opcode 99020000 arg 00000020 lsi_scsi: Compare phase 1 != 1 lsi_scsi: Control condition failed lsi_scsi: SCRIPTS dsp=03527080 opcode 090000ff arg 031c7410 lsi_scsi: DMA addr=0x00000000031c7410 len=7 scsi-disk: Read sector_count=0 scsi-disk: Command complete tag=0x0 status=0 sense=0 lsi_scsi: Command complete sense=0 lsi_scsi: Data phase mismatch jump to f2002714 shortly later we're into the unhandled writes at 0xff, etc. Now, notice the guest has set up a 255 byte buffer in the command we've decoded. This also implies that s->dbc is set to 255. In scsi-disk.c we fill out the code page details and use 7 bytes, set in r->buf_len. The lsi device DMAs this data, and when it is done, we're in lsi_command_complete(). Notice: if (s->waiting && s->dbc != 0) { /* Raise phase mismatch for short transfers. */ lsi_bad_phase(s, out, PHASE_ST); After the DMA operation, s->dbc is 255 - 7, thus we're triggering the phase mismatch. Ideally, what we want to do instead is to switch from DATA_IN phase (DMA'ing from disk to guest RAM) to status phase but without error. That is, it isn't an error to transfer only 7 bytes. As a hack, I set r->buf_len of the EVPD and Mode Sense commands to the submitted len which avoids the call to lsi_bad_status(). The result is no long timeout before the installer proceeds. I'll work on a proper fix, but this patch works around the issue in win64. Untested anywhere else (ie, may break other guests): diff --git a/hw/lsi53c895a.c b/hw/lsi53c895a.c index 81d5672..c42feac 100644 --- a/hw/lsi53c895a.c +++ b/hw/lsi53c895a.c @@ -638,12 +638,7 @@ static void lsi_command_complete(void *opaque, int reason, uint32_t tag, DPRINTF("Command complete sense=%d\n", (int)arg); s->sense = arg; s->command_complete = 2; - if (s->waiting && s->dbc != 0) { - /* Raise phase mismatch for short transfers. */ - lsi_bad_phase(s, out, PHASE_ST); - } else { - lsi_set_phase(s, PHASE_ST); - } + lsi_set_phase(s, PHASE_ST); lsi_resume_script(s); return; } ---------------------------------------------------------------------- Comment By: Ryan Harper (ryan_harper) Date: 2009-01-06 01:16 Message: Yeah, that's a fair point, I haven't figured out exactly what those writes are for. It could be some other bug throwing off the SCRIPTS and causing the write to reserved offsets, however, 64-bit windows does enabled 64-bit Direct Block moves which require a 3rd Dword fetch, hence the ->dsp+=4. ---------------------------------------------------------------------- Comment By: Anssi Kolehmainen (aketzu) Date: 2009-01-06 01:00 Message: Why write to checksum and user data and never read anything? I didn't spot any remarks what writing the checksum might accomplish. This time I made (bad) assumption that if the 3rd dword contains anything else than 0 it must be next opcode and we shouldn't dsp=+4... Now it formats the drive properly and install succeeds (writing about 8-15mb/s with logging on and 10-20mb/s with logging off). Although after install Windows Boot Manager barfs that boot configuration couldn't be read and refuses to boot (but that might be caused by some other incompatibility). ---------------------------------------------------------------------- Comment By: Ryan Harper (ryan_harper) Date: 2009-01-05 23:24 Message: As for serial eeprom, you can look at the tech manual[1], section 2.4 if you want to read why it's poking at those offsets. 1. http://www.lsi.com/DistributionSystem/AssetDocument/files/docs/techdocs/storage_stand_prod/SCSIControllers/lsi53c895a_tech_manual.pdf ---------------------------------------------------------------------- Comment By: Ryan Harper (ryan_harper) Date: 2009-01-05 23:18 Message: It does start quicker, but formatting fails on 64-bit windows if you don't use 64-bit DMA mode. ---------------------------------------------------------------------- Comment By: Anssi Kolehmainen (aketzu) Date: 2009-01-05 23:12 Message: What a better way to spend the night than debug SCSI problems :) kvm-82, win2k8-64 install dvd and some hacking... The startup freezes for a while (log below). Why would driver want to write to eeprom memory? Maybe because that scripts pointer goes wrong? [1231186859.686061] lsi_scsi: SCRIPTS dsp=f00221e0 opcode 878b0000 arg 0000007c [1231186859.686064] lsi_scsi: Compare phase 7 == 7 [1231186859.686066] lsi_scsi: Jump to 0xf0022264 [1231186859.686069] lsi_scsi: SCRIPTS dsp=f0022264 opcode 0f000001 arg 3fc56890 [1231186859.686072] lsi_scsi: Message in len=1/1 [1231186859.686074] lsi_scsi: SCRIPTS dsp=f0022270 opcode fffffdb4 arg 808c0004 [1231186859.686079] lsi_scsi: Load reg 0xff size 4 addr 0x3f518044 = 00000000 [1231186859.686083] lsi_scsi: Write reg ff = 00 [1231186859.686085] lsi_scsi: Write reg 100 = 00 [1231186859.686087] lsi_scsi: Write reg 101 = 00 [1231186859.686089] lsi_scsi: Write reg 102 = 00 [1231186859.686092] lsi_scsi: SCRIPTS dsp=f0022278 opcode 00000068 arg 808c0002 [1231186859.686094] lsi_scsi: DMA no data available [1231186859.686097] lsi_scsi: SCRIPTS execution stopped [1231186870.546702] lsi_scsi: Write reg 40 = 00 Well, that seems to be the case... lsi_dma_64bit() returns true, s->dsp is incremented extra 0x4 and we skip one half instruction... Commenting out s->dsp+=4 (and other instructions around line 973) and the installer starts in a flash as seen below. [1231188815.759843] lsi_scsi: SCRIPTS dsp=f00221e0 opcode 878b0000 arg 0000007c [1231188815.759846] lsi_scsi: Compare phase 7 == 7 [1231188815.759849] lsi_scsi: Jump to 0xf0022264 [1231188815.759852] lsi_scsi: SCRIPTS dsp=f0022264 opcode 0f000001 arg 3fc6f890 [1231188815.759855] lsi_scsi: Message in len=1/1 [1231188815.759858] lsi_scsi: SCRIPTS dsp=f002226c opcode 808c0000 arg fffffdb4 [1231188815.759861] lsi_scsi: Compare data 0x0 & 0xff == 0x0 [1231188815.759864] lsi_scsi: Jump to 0xf0022028 ---------------------------------------------------------------------- Comment By: Ryan Harper (ryan_harper) Date: 2009-01-05 18:03 Message: Fair enough. In my testing, I've not seen such long timeouts. A couple minutes during installation, and a handful of seconds on boot. ---------------------------------------------------------------------- Comment By: Ryan Bair (ryandbair) Date: 2009-01-05 17:34 Message: While everything still works it certainly does affect the usability of Windows guests on SCSI. Freezing all SCSI disk I/O for 20 minutes (new record!) when opening the disk management snap-in and adding up to 5 minutes to the Windows boot time really makes it unusable. I can understand it might not be the highest priority at the moment, but I wouldn't put it too far down the list either. ---------------------------------------------------------------------- Comment By: Ryan Harper (ryan_harper) Date: 2009-01-05 04:11 Message: Yeah, it's worth keeping open so we at least track that it is an open issue. It is harmless AFAICT, so no plans to implement the eeprom interface unless it prevents functionality. We've got lots of other issues to fix in the scsi layer. ---------------------------------------------------------------------- Comment By: Ryan Bair (ryandbair) Date: 2009-01-05 04:05 Message: Thanks, as far as I can see this is the first time the bug has been reported on the tracker so I will keep this bug open. Are there any workarounds or a planned fixes for this issue? ---------------------------------------------------------------------- Comment By: Ryan Harper (ryan_harper) Date: 2009-01-05 03:44 Message: lsi_scsi: error: Unhandled writeb 0xff = 0x0 lsi_scsi: error: Unhandled writeb 0x100 = 0x0 lsi_scsi: error: Unhandled writeb 0x101 = 0x0 lsi_scsi: error: Unhandled writeb 0x102 = 0x0 These are known error messages. Looks like the windows driver is poking at the serial eeprom interface for loading SSVID/SSID but that's not implemented, hence the error message. ---------------------------------------------------------------------- You can respond by visiting: https://sourceforge.net/tracker/?func=detail&atid=893831&aid=2482759&group_id=180599 -- To unsubscribe from this list: send the line "unsubscribe kvm" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html