On Tue, 11 May 2010, Jonas Schwertfeger wrote:
> On 05/07/2010 05:03 PM, Alan Stern wrote:
> > Hmm. I'm not sure I believe this data. For a while (starting with
> > 2.6.33) the usbmon implementation didn't work right with EHCI -- it
> > looked in the transfer buffer before the DMA-unmapping was done, so on
> > a system with>= 4 GB of memory it wouldn't always see the data. The
> > fix for this was merged only within the last week or so.
> >
> > Can you repeat the USB-2.0 test but this time doing "rmmod ehci-hcd"
> > beforehand?
>
> I could not remove that module (I assume it is compiled into the kernel)
> so I limited the memory the kernel can see to 1GB. You were right, now
> there is actually useful data in the trace. Here it is:
Great! This is just what we need.
> ffff88001bb82840 685088867 S Bo:1:003:2 -115 31 = 55534243 c9000000
> 00020000 80001085 082e0000 00010000 00000000 40ec00
That's an IDENTIFY DEVICE command being sent to the device,
corresponding to the start of the hdparm debugging log:
outgoing cdb: 85 08 2e 00 00 00 01 00 00 00 00 00 00 40 ec 00
> ffff88001bb82840 685088982 C Bo:1:003:2 0 31 >
> ffff88001bbc3d80 685089045 S Bi:1:003:1 -115 512 <
> ffff88001bbc3d80 685094708 C Bi:1:003:1 0 512 = 4000ff3f 37c81000
> 00000000 3f000000 00000000 32534d35 394a5a30 30313237
These are the first 32 bytes of the reply. (If necessary we could get
all 512 bytes.) But at this point the hdparm debugging log says:
data: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
That certainly seems strange. The reply data should be there.
> ffff88001bb82840 685094763 S Bi:1:003:1 -115 13 <
> ffff88001bb82840 685094814 C Bi:1:003:1 0 13 = 55534253 c9000000 00000000 00
And the status value is 0, indicating no problems. Nevertheless,
hdparm reported:
SG_IO: ATA_16 status=0x0, host_status=0x0, driver_status=0x0
SG_IO: bad response (not CHECK_CONDITION)
Presumably this is because it saw all 0's instead of the actual data.
Apart from that, it is what one would expect.
> ffff88001bb82840 685095024 S Bo:1:003:2 -115 31 = 55534243 ca000000
> 00020000 80001085 082e0000 00010000 00000000 40a100
This is an IDENTIFY PACKET DEVICE command, corresponding to the next
two lines in the hdparm log:
Trying legacy HDIO_DRIVE_CMD
outgoing cdb: 85 08 2e 00 00 00 01 00 00 00 00 00 00 40 a1 00
> ffff88001bb82840 685095207 C Bo:1:003:2 0 31 >
> ffff88001bbc3d80 685095260 S Bi:1:003:1 -115 512 <
> ffff88001bbc3d80 685095457 C Bi:1:003:1 -32 0
> ffff88001bb82840 685095509 S Co:1:003:0 s 02 01 0000 0081 0000 0
> ffff88001bb82840 685095561 C Co:1:003:0 0 0
> ffff88001bb82840 685095614 S Bi:1:003:1 -115 13 <
> ffff88001bb82840 685095699 C Bi:1:003:1 0 13 = 55534253 ca000000 00020000 01
The device sends back no data, a Residue value of 512, and Check
Condition status.
> ffff88001bb82840 685095768 S Bo:1:003:2 -115 31 = 55534243 cb000000
> 60000000 80000603 00000060 00000000 00000000 000000
This is the REQUEST SENSE command automatically generated by the
usb-storage driver.
> ffff88001bb82840 685095817 C Bo:1:003:2 0 31 >
> ffff88001bbc3d80 685095885 S Bi:1:003:1 -115 96 <
> ffff88001bbc3d80 685096082 C Bi:1:003:1 0 96 = 720b0000 0000000e
> 090c0004 00010000 00000000 40510000 00000000 00000000
And these are the first 32 sense data bytes. Here's what hdparm had to
say:
data: 40 00 ff 3f 37 c8 10 00 00 00 00 00 3f 00 00 00
SG_IO: ATA_16 status=0x2, host_status=0x0, driver_status=0x8
SG_IO: sb[]: 72 0b 00 00 00 00 00 0e 09 0c 00 04 00 01 00 00 00 00 00
00 40 51 00 00 00 00 00 00 00 00 00 00
SG_IO: desc[]: 09 0c 00 04 00 01 00 00 00 00 00 00
ATA_16 stat=51 err=04 nsect=01 lbal=00 lbam=00 lbah=00 dev=40
I/O error, ata_op=0xa1 ata_status=0x51 ata_error=0x04
Notice that the "data" line contains the data from the previous
command! The status and sense buffer ("sb") values appear correct.
> ffff88001bb82840 685096136 S Bi:1:003:1 -115 13 <
> ffff88001bb82840 685096207 C Bi:1:003:1 0 13 = 55534253 cb000000 00000000 00
That's the status from the REQUEST SENSE.
> ffff88001bb82840 685097822 S Bo:1:003:2 -115 31 = 55534243 cc000000
> 00100000 80000a28 00000000 00000008 00000000 000000
This is a READ(10) command, asking for 8 blocks of data starting at
block 0.
> ffff88001bb82840 685097947 C Bo:1:003:2 0 31 >
> ffff880010e52a80 685098002 S Bi:1:003:1 -115 4096 <
> ffff880010e52a80 685106944 C Bi:1:003:1 0 4096 = fab80010 8ed0bc00
> b0b80000 8ed88ec0 fbbe007c bf0006b9 0002f3a4 ea210600
And that's the start of the first block of data. It looks normal
enough.
> ffff88001bb82840 685106999 S Bi:1:003:1 -115 13 <
> ffff88001bb82840 685107075 C Bi:1:003:1 0 13 = 55534253 cc000000 00000000 00
So overall, something is messing up with regard to the data coming back
from the device. hdparm sees the data for the first command as being
the response to the second command. It could be a problem in the
kernel or a problem in hdparm.
No doubt hdparm is easier to check up on. Mark, could this be some
sort of simple programming error?
Alan Stern
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
