Re: Strange ATA problems

Re: Strange ATA problems

[Tejun Heo]

[cc'ing linux-ide and Robert Hancock and quoting whole body]

Christoph Anton Mitterer wrote:
> Hi Tejun.
> 
> 
> On Sat, 2007-12-15 at 00:16 +0900, Tejun Heo wrote:
>> Do you have log with timestamp?  It's difficult to tell what's going on
>> without knowing what happened when.
> Ah sorry,... I've completely missed that... perhaps those two problems
> were not related (at least there's so much time between).

Then those two events are unrelated.

> Dec 13 17:05:51 fermat kernel: NVRM: loading NVIDIA UNIX x86_64 Kernel
> Module  100.14.19  Wed Sep 12 14:08:38 PDT 2007
> Dec 13 17:12:36 fermat kernel: usb 1-1: new high speed USB device using
> ehci_hcd and address 5
> Dec 13 17:12:36 fermat kernel: usb 1-1: configuration #1 chosen from 1
> choice
> Dec 13 17:12:36 fermat kernel: scsi6 : SCSI emulation for USB Mass
> Storage devices
> Dec 13 17:12:36 fermat kernel: usb-storage: device found at 5
> Dec 13 17:12:36 fermat kernel: usb-storage: waiting for device to settle
> before scanning
> Dec 13 17:12:41 fermat kernel: scsi 6:0:0:0: CD-ROM            PLEXTOR
> DVD-ROM PX-130A  1.03 PQ: 0 ANSI: 0 CCS
> Dec 13 17:12:41 fermat kernel: sr0: scsi3-mmc drive: 0x/50x cd/rw
> xa/form2 cdda tray
> Dec 13 17:12:41 fermat kernel: sr 6:0:0:0: Attached scsi CD-ROM sr0
> Dec 13 17:12:41 fermat kernel: sr 6:0:0:0: Attached scsi generic sg3
> type 5
> Dec 13 17:12:41 fermat kernel: usb-storage: device scan complete
> Dec 13 17:13:33 fermat kernel: end_request: I/O error, dev sr0, sector
> 308688
> Dec 13 17:13:33 fermat kernel: Buffer I/O error on device sr0, logical
> block 77172
> Dec 13 17:13:33 fermat kernel: Buffer I/O error on device sr0, logical
> block 77173
> Dec 13 17:13:33 fermat kernel: end_request: I/O error, dev sr0, sector
> 308688
> Dec 13 17:13:33 fermat kernel: Buffer I/O error on device sr0, logical
> block 77172
> Dec 13 17:13:33 fermat kernel: Buffer I/O error on device sr0, logical
> block 77173
> Dec 13 17:13:33 fermat kernel: end_request: I/O error, dev sr0, sector
> 308816
> Dec 13 17:13:33 fermat kernel: Buffer I/O error on device sr0, logical
> block 77204
> Dec 13 17:13:33 fermat kernel: Buffer I/O error on device sr0, logical
> block 77205
> Dec 13 17:13:33 fermat kernel: end_request: I/O error, dev sr0, sector
> 308816
> Dec 13 17:13:33 fermat kernel: Buffer I/O error on device sr0, logical
> block 77204
> Dec 13 17:13:33 fermat kernel: Buffer I/O error on device sr0, logical
> block 77205
> Dec 13 17:18:32 fermat kernel: UDF-fs: No VRS found
> Dec 13 18:09:43 fermat kernel: tun0: Disabled Privacy Extensions
> Dec 14 01:06:33 fermat kernel: usb 1-1: USB disconnect, address 5
> Dec 14 01:06:33 fermat kernel: ata1: EH in ADMA mode, notifier 0x0
> notifier_error 0x0 gen_ctl 0x1501000 status 0x400 next cpb count 0x0
> next
>  cpb idx 0x0
> Dec 14 01:06:33 fermat kernel: ata1: CPB 0: ctl_flags 0x1f, resp_flags
> 0x2
> Dec 14 01:06:33 fermat kernel: ata1: CPB 1: ctl_flags 0x1f, resp_flags
> 0x2
> Dec 14 01:06:33 fermat kernel: ata1: CPB 2: ctl_flags 0x1f, resp_flags
> 0x2
> Dec 14 01:06:33 fermat kernel: ata1: CPB 3: ctl_flags 0x1f, resp_flags
> 0x2
> Dec 14 01:06:33 fermat kernel: ata1: CPB 4: ctl_flags 0x1f, resp_flags
> 0x2
> Dec 14 01:06:33 fermat kernel: ata1: CPB 5: ctl_flags 0x1f, resp_flags
> 0x2
> Dec 14 01:06:33 fermat kernel: ata1: CPB 6: ctl_flags 0x1f, resp_flags
> 0x2
> Dec 14 01:06:33 fermat kernel: ata1: CPB 7: ctl_flags 0x1f, resp_flags
> 0x2
> Dec 14 01:06:33 fermat kernel: ata1: CPB 8: ctl_flags 0x1f, resp_flags
> 0x2
> Dec 14 01:06:33 fermat kernel: ata1: CPB 9: ctl_flags 0x1f, resp_flags
> 0x2
> Dec 14 01:06:33 fermat kernel: ata1: CPB 10: ctl_flags 0x1f, resp_flags
> 0x2
> Dec 14 01:06:33 fermat kernel: ata1: timeout waiting for ADMA IDLE,
> stat=0x400
> Dec 14 01:06:33 fermat kernel: ata1.00: exception Emask 0x0 SAct 0x7ff
> SErr 0x0 action 0x2 frozen
> Dec 14 01:06:33 fermat kernel: ata1.00: cmd
> 61/10:00:2e:07:a8/01:00:0b:00:00/40 tag 0 cdb 0x0 data 139264 out
> Dec 14 01:06:33 fermat kernel:          res
> 40/00:01:00:4f:c2/00:00:00:00:00/00 Emask 0x4 (timeout)
> Dec 14 01:06:33 fermat kernel: ata1.00: cmd
> 61/18:08:07:3f:02/00:00:00:00:00/40 tag 1 cdb 0x0 data 12288 out
> Dec 14 01:06:33 fermat kernel:          res
> 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> Dec 14 01:06:33 fermat kernel: ata1.00: cmd
> 61/08:10:b6:a8:23/00:00:0d:00:00/40 tag 2 cdb 0x0 data 4096 out
> Dec 14 01:06:33 fermat kernel:          res
> 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> Dec 14 01:06:33 fermat kernel: ata1.00: cmd
> 61/08:18:f6:37:68/00:00:0d:00:00/40 tag 3 cdb 0x0 data 4096 out
> Dec 14 01:06:33 fermat kernel:          res
> 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> Dec 14 01:06:33 fermat kernel: ata1.00: cmd
> 61/08:20:9e:32:a1/00:00:0d:00:00/40 tag 4 cdb 0x0 data 4096 out
> Dec 14 01:06:33 fermat kernel:          res
> 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> Dec 14 01:06:33 fermat kernel: ata1.00: cmd
> 61/08:28:4f:00:dc/00:00:02:00:00/40 tag 5 cdb 0x0 data 4096 out
> Dec 14 01:06:33 fermat kernel:          res
> 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> Dec 14 01:06:33 fermat kernel: ata1.00: cmd
> 61/08:30:6f:00:dc/00:00:02:00:00/40 tag 6 cdb 0x0 data 4096 out
> Dec 14 01:06:33 fermat kernel:          res
> 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> Dec 14 01:06:33 fermat kernel: ata1.00: cmd
> 61/08:38:3f:03:2c/00:00:05:00:00/40 tag 7 cdb 0x0 data 4096 out
> Dec 14 01:06:33 fermat kernel:          res
> 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> Dec 14 01:06:33 fermat kernel: ata1.00: cmd
> 61/08:40:36:ea:72/00:00:0d:00:00/40 tag 8 cdb 0x0 data 4096 out
> Dec 14 01:06:33 fermat kernel:          res
> 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> Dec 14 01:06:33 fermat kernel: ata1.00: cmd
> 61/08:48:7f:00:c4/00:00:05:00:00/40 tag 9 cdb 0x0 data 4096 out
> Dec 14 01:06:33 fermat kernel:          res
> 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> Dec 14 01:06:33 fermat kernel: ata1.00: cmd
> 61/08:50:47:02:d8/00:00:05:00:00/40 tag 10 cdb 0x0 data 4096 out
> Dec 14 01:06:33 fermat kernel:          res
> 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
> Dec 14 01:06:33 fermat kernel: ata1: soft resetting port
> Dec 14 01:06:33 fermat kernel: ata1: SATA link up 3.0 Gbps (SStatus 123
> SControl 300)
> Dec 14 01:06:33 fermat kernel: ata1.00: configured for UDMA/133
> Dec 14 01:06:33 fermat kernel: ata1: EH complete
> Dec 14 01:06:33 fermat kernel: sd 0:0:0:0: [sda] 488397168 512-byte
> hardware sectors (250059 MB)
> Dec 14 01:06:33 fermat kernel: sd 0:0:0:0: [sda] Write Protect is off
> Dec 14 01:06:33 fermat kernel: sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
> Dec 14 01:06:33 fermat kernel: sd 0:0:0:0: [sda] Write cache: enabled,
> read cache: enabled, doesn't support DPO or FUA
> Dec 14 01:27:45 fermat kernel: Kernel logging (proc) stopped.
> 
> 
> 
>> Also, please post the result of
>> 'cat /proc/interrupts'.
>            CPU0       CPU1       CPU2       CPU3       
>   0:        393       1181      82962    4513047   IO-APIC-edge
> timer
>   1:          0          0          0          2   IO-APIC-edge
> i8042
>   6:          0          0          0          5   IO-APIC-edge
> floppy
>   8:          0          0          0          0   IO-APIC-edge      rtc
>   9:          0          0          0          0   IO-APIC-fasteoi
> acpi
>  12:          0         84       1376     210883   IO-APIC-edge
> i8042
>  14:          0          3         17       1220   IO-APIC-edge
> ide0
>  18:          0         64       4964     300769   IO-APIC-fasteoi
> nvidia
>  19:          0          0          0          3   IO-APIC-fasteoi
> ohci1394
>  20:          0          0          0          4   IO-APIC-fasteoi
> ehci_hcd:usb1
>  21:          0          0          1        165   IO-APIC-fasteoi
> sata_nv
>  22:          0         44       1856     165693   IO-APIC-fasteoi
> sata_nv, NVidia CK804
>  23:          0        117       8565     452639   IO-APIC-fasteoi
> ohci_hcd:usb3, eth1
>  24:          0         37       3710     185125   IO-APIC-fasteoi
> ICE1724
>  30:          3       1833      52841   18139903   IO-APIC-fasteoi
> ioc0, ehci_hcd:usb2
>  31:          0          0          0         45   IO-APIC-fasteoi
> ioc1
>  55:        129     530948          1         81   IO-APIC-fasteoi
> eth2
> NMI:          0          0          0          0 
> LOC:    4597004    4596930    4596860    4596786 
> ERR:          0
> 
> 
>> If your USB cdrom is bus powered and you yanked it, it could have caused
>> fluctuation in power which in turn can cause disruption on serial ATA
>> bus leading to transmission error and timeouts.  There are other
>> possibilities but this kind of thing does happen often with SATA.  Those
>> highspeed low-voltage serial links are very susceptible to interferences.
> Well,.. it actually "worked" again when I unplugged it, but the errors
> from the cdrom above are probably unrelated..
> 
> 
>> As long as EH recovered it properly, there's nothing to worry about.
> What does that mean?

That means unless the problem continues to occur repeatedly, you don't
have to worry about it.

-- 
tejun

Re: Strange ATA problems

[Robert Hancock]

Tejun Heo wrote:
>> Dec 14 01:06:33 fermat kernel: ata1: EH in ADMA mode, notifier 0x0
>> notifier_error 0x0 gen_ctl 0x1501000 status 0x400 next cpb count 0x0
>> next
>>  cpb idx 0x0
>> Dec 14 01:06:33 fermat kernel: ata1: CPB 0: ctl_flags 0x1f, resp_flags
>> 0x2
>> Dec 14 01:06:33 fermat kernel: ata1: CPB 1: ctl_flags 0x1f, resp_flags
>> 0x2
>> Dec 14 01:06:33 fermat kernel: ata1: CPB 2: ctl_flags 0x1f, resp_flags
>> 0x2
>> Dec 14 01:06:33 fermat kernel: ata1: CPB 3: ctl_flags 0x1f, resp_flags
>> 0x2
>> Dec 14 01:06:33 fermat kernel: ata1: CPB 4: ctl_flags 0x1f, resp_flags
>> 0x2
>> Dec 14 01:06:33 fermat kernel: ata1: CPB 5: ctl_flags 0x1f, resp_flags
>> 0x2
>> Dec 14 01:06:33 fermat kernel: ata1: CPB 6: ctl_flags 0x1f, resp_flags
>> 0x2
>> Dec 14 01:06:33 fermat kernel: ata1: CPB 7: ctl_flags 0x1f, resp_flags
>> 0x2
>> Dec 14 01:06:33 fermat kernel: ata1: CPB 8: ctl_flags 0x1f, resp_flags
>> 0x2
>> Dec 14 01:06:33 fermat kernel: ata1: CPB 9: ctl_flags 0x1f, resp_flags
>> 0x2
>> Dec 14 01:06:33 fermat kernel: ata1: CPB 10: ctl_flags 0x1f, resp_flags
>> 0x2

CPB flags stuck at 0x2 indicates that the controller issued the command 
to the drive and is waiting for completion. Usually seems to indicate 
some kind of SATA communication problem.

>>> If your USB cdrom is bus powered and you yanked it, it could have caused
>>> fluctuation in power which in turn can cause disruption on serial ATA
>>> bus leading to transmission error and timeouts.  There are other
>>> possibilities but this kind of thing does happen often with SATA.  Those
>>> highspeed low-voltage serial links are very susceptible to interferences.
>> Well,.. it actually "worked" again when I unplugged it, but the errors
>> from the cdrom above are probably unrelated..
>>
>>
>>> As long as EH recovered it properly, there's nothing to worry about.
>> What does that mean?
> 
> That means unless the problem continues to occur repeatedly, you don't
> have to worry about it.
> 

Yes, if it didn't recur, was likely just a transient glitch.

-- 
Robert Hancock      Saskatoon, SK, Canada
To email, remove "nospam" from hancockr@nospamshaw.ca
Home Page: http://www.roberthancock.com/

Re: Strange ATA problems

[Christoph Anton Mitterer]

[-- Attachment #1: Type: text/plain, Size: 66 bytes --]

Thanks for all your help :-)

Best wishes from Munich,
Chris.

[-- Attachment #2: smime.p7s --]
[-- Type: application/x-pkcs7-signature, Size: 5108 bytes --]