Bug 12975 - ata2: lots of error messages, but OS still running well
Summary: ata2: lots of error messages, but OS still running well
Status: CLOSED UNREPRODUCIBLE
Alias: None
Product: IO/Storage
Classification: Unclassified
Component: Serial ATA (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: Jeff Garzik
URL:
Keywords:
Depends on:
Blocks: 12398
  Show dependency tree
 
Reported: 2009-03-30 08:03 UTC by Peter Teoh
Modified: 2009-07-15 09:58 UTC (History)
4 users (show)

See Also:
Kernel Version: 2.6.29 (linus tree)
Subsystem:
Regression: Yes
Bisected commit-id:

Attachments
messages.log (199.55 KB, text/plain)
2009-04-06 19:49 UTC, Tejun Heo 		Details
sense-debug.patch (951 bytes, patch)
2009-04-14 10:41 UTC, Tejun Heo 		Details | Diff
full dmesg (122.17 KB, text/plain)
2009-07-09 13:26 UTC, Thomas Creutz 		Details
Add an attachment (proposed patch, testcase, etc.)

Description Peter Teoh 2009-03-30 08:03:33 UTC 
After booting up my dmesg showed the following message, but otherwise everything else seemed working and ok:

[drm] writeback test succeeded in 1 usecs
eth1: no IPv6 routers present
CPU0 attaching NULL sched-domain.
CPU0 attaching NULL sched-domain.
fuse init (API version 7.11)
CPU0 attaching NULL sched-domain.
CPU0 attaching NULL sched-domain.
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
ata2.00: cmd a0/00:00:00:0c:00/00:00:00:00:00/a0 tag 0 pio 16396 in
         cdb 43 00 00 00 00 00 00 00  0c 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
ata2.00: status: { DRDY ERR }
sr0: CDROM (ioctl) error, command: Read TOC/PMA/ATIP 43 00 00 00 00 00 00 00 0c 00
sr: Sense Key : Aborted Command [current] [descriptor]
sr: Add. Sense: No additional sense information
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
ata2.00: BMDMA stat 0x25
ata2.00: cmd a0/01:00:00:fe:00/00:00:00:00:00/a0 tag 0 dma 16640 in
         cdb 12 01 00 00 fe 00 00 00  00 00 00 00 00 00 00 00
         res 51/54:03:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
ata2.00: status: { DRDY ERR }
ata2.00: qc timeout (cmd 0xa0)
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
ata2.00: cmd a0/00:00:00:0c:00/00:00:00:00:00/a0 tag 0 pio 16396 in
         cdb 43 00 00 00 00 00 00 00  0c 40 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x5 (timeout)
ata2.00: status: { DRDY ERR }
ata2: link is slow to respond, please be patient (ready=0)
ata2: device not ready (errno=-16), forcing hardreset
ata2: soft resetting link
ata2.00: configured for UDMA/33
ata2: EH complete
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
ata2.00: status: { DRDY ERR }
ata2.00: qc timeout (cmd 0xa0)
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x5 (timeout)
ata2.00: status: { DRDY ERR }
ata2: link is slow to respond, please be patient (ready=0)
ata2: device not ready (errno=-16), forcing hardreset
ata2: soft resetting link
ata2.00: configured for UDMA/33
ata2: EH complete
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
ata2.00: status: { DRDY ERR }
b44: eth0: Link is up at 100 Mbps, full duplex.
b44: eth0: Flow control is off for TX and off for RX.
ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
eth0: no IPv6 routers present
ata2.00: qc timeout (cmd 0xa0)
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
ata2.00: cmd a0/00:00:00:d2:00/00:00:00:00:00/a0 tag 0 pio 16596 in
         cdb 46 01 00 00 00 00 00 00  d2 00 00 00 00 00 00 00
         res 51/04:01:01:14:eb/00:00:00:00:00/a0 Emask 0x5 (timeout)
ata2.00: status: { DRDY ERR }
ata2: link is slow to respond, please be patient (ready=0)
ata2: device not ready (errno=-16), forcing hardreset
ata2: soft resetting link
ata2.00: configured for UDMA/33
ata2: EH complete
CPU0 attaching NULL sched-domain.
CPU0 attaching NULL sched-domain.
CPU0 attaching NULL sched-domain.
CPU0 attaching NULL sched-domain.
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
ata2.00: status: { DRDY ERR }
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
ata2.00: status: { DRDY ERR }
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
ata2.00: status: { DRDY ERR }
ata2.00: qc timeout (cmd 0xa0)
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x5 (timeout)
ata2.00: status: { DRDY ERR }
ata2: link is slow to respond, please be patient (ready=0)
ata2: device not ready (errno=-16), forcing hardreset
ata2: soft resetting link
ata2.00: configured for UDMA/33
ata2: EH complete
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
ata2.00: status: { DRDY ERR }
CPU0 attaching NULL sched-domain.
CPU0 attaching NULL sched-domain.
CPU0 attaching NULL sched-domain.
CPU0 attaching NULL sched-domain.
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
ata2.00: cmd a0/00:00:00:08:00/00:00:00:00:00/a0 tag 0 pio 16392 in
         cdb 25 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
ata2.00: status: { DRDY ERR }
ata2.00: qc timeout (cmd 0xa0)
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
ata2.00: cmd a0/00:00:00:08:00/00:00:00:00:00/a0 tag 0 pio 16392 in
         cdb 25 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x5 (timeout)
ata2.00: status: { DRDY ERR }
ata2: link is slow to respond, please be patient (ready=0)
ata2: device not ready (errno=-16), forcing hardreset
ata2: soft resetting link
ata2.00: configured for UDMA/33
ata2: EH complete
ata2.00: qc timeout (cmd 0xa0)
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
ata2.00: cmd a0/00:00:00:08:00/00:00:00:00:00/a0 tag 0 pio 16392 in
         cdb 46 00 00 00 00 00 00 00  08 00 00 00 00 00 00 00
         res 51/04:01:01:14:eb/00:00:00:00:00/a0 Emask 0x5 (timeout)
ata2.00: status: { DRDY ERR }
ata2: link is slow to respond, please be patient (ready=0)
ata2: device not ready (errno=-16), forcing hardreset
ata2: soft resetting link
ata2.00: configured for UDMA/33
ata2: EH complete
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
ata2.00: status: { DRDY ERR }
ata2.00: qc timeout (cmd 0xa0)
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x5 (timeout)
ata2.00: status: { DRDY ERR }
ata2: link is slow to respond, please be patient (ready=0)
ata2: device not ready (errno=-16), forcing hardreset
ata2: soft resetting link
ata2.00: configured for UDMA/33
ata2: EH complete
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
ata2.00: status: { DRDY ERR }
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/04:01:01:60:00/00:00:00:00:00/a0 Emask 0x1 (device error)
ata2.00: status: { DRDY ERR }
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 58/00:02:00:12:00/00:00:00:00:00/a0 Emask 0x2 (HSM violation)
ata2.00: status: { DRDY DRQ }
ata2: soft resetting link
ata2.00: configured for UDMA/33
ata2: EH complete
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
ata2.00: cmd a0/00:00:00:08:00/00:00:00:00:00/a0 tag 0 pio 16392 in
         cdb 25 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
ata2.00: status: { DRDY ERR }
ata2.00: qc timeout (cmd 0xa0)
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x5 (timeout)
ata2.00: status: { DRDY ERR }
ata2: link is slow to respond, please be patient (ready=0)
ata2: device not ready (errno=-16), forcing hardreset
ata2: soft resetting link
ata2.00: configured for UDMA/33
ata2: EH complete
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
ata2.00: BMDMA stat 0x25
ata2.00: cmd a0/01:00:00:fe:00/00:00:00:00:00/a0 tag 0 dma 16640 in
         cdb 12 01 00 00 fe 00 00 00  00 00 00 00 00 00 00 00
         res 51/54:03:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
ata2.00: status: { DRDY ERR }
ata2.00: qc timeout (cmd 0xa0)
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
ata2.00: cmd a0/00:00:00:0c:00/00:00:00:00:00/a0 tag 0 pio 16396 in
         cdb 43 00 00 00 00 00 00 00  0c 40 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x5 (timeout)
ata2.00: status: { DRDY ERR }
ata2: link is slow to respond, please be patient (ready=0)
ata2: device not ready (errno=-16), forcing hardreset
ata2: soft resetting link
ata2.00: configured for UDMA/33
ata2: EH complete
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
ata2.00: status: { DRDY ERR }
ata2.00: qc timeout (cmd 0xa0)
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x5 (timeout)
ata2.00: status: { DRDY ERR }
ata2: link is slow to respond, please be patient (ready=0)
ata2: device not ready (errno=-16), forcing hardreset
ata2: soft resetting link
ata2.00: configured for UDMA/33
ata2: EH complete
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
ata2.00: status: { DRDY ERR }
ata2.00: qc timeout (cmd 0xa0)
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x5 (timeout)
ata2.00: status: { DRDY ERR }
ata2: link is slow to respond, please be patient (ready=0)
ata2: device not ready (errno=-16), forcing hardreset
ata2: soft resetting link
ata2.00: configured for UDMA/33
ata2: EH complete
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6
ata2.00: BMDMA stat 0x25
ata2.00: cmd a0/01:00:00:fe:00/00:00:00:00:00/a0 tag 0 dma 16640 in
         cdb 12 01 00 00 fe 00 00 00  00 00 00 00 00 00 00 00
         res d1/54:03:00:00:00/00:00:00:00:00/a0 Emask 0x3 (HSM violation)
ata2.00: status: { Busy }
ata2: soft resetting link
ata2.00: configured for UDMA/33
ata2: EH complete
ata2.00: qc timeout (cmd 0xa0)
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
ata2.00: cmd a0/00:00:00:08:00/00:00:00:00:00/a0 tag 0 pio 16392 in
         cdb 46 00 00 00 00 00 00 00  08 00 00 00 00 00 00 00
         res 51/04:01:01:14:eb/00:00:00:00:00/a0 Emask 0x5 (timeout)
ata2.00: status: { DRDY ERR }
ata2: link is slow to respond, please be patient (ready=0)
ata2: device not ready (errno=-16), forcing hardreset
ata2: soft resetting link
ata2.00: configured for UDMA/33
ata2: EH complete
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
ata2.00: cmd a0/00:00:00:08:00/00:00:00:00:00/a0 tag 0 pio 16392 in
         cdb 25 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
ata2.00: status: { DRDY ERR }
ata2.00: qc timeout (cmd 0xa0)
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
ata2.00: cmd a0/00:00:00:08:00/00:00:00:00:00/a0 tag 0 pio 16392 in
         cdb 25 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x5 (timeout)
ata2.00: status: { DRDY ERR }
ata2: link is slow to respond, please be patient (ready=0)
ata2: device not ready (errno=-16), forcing hardreset
ata2: soft resetting link
ata2.00: configured for UDMA/33
ata2: EH complete
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
ata2.00: status: { DRDY ERR }
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
ata2.00: status: { DRDY ERR }
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
ata2.00: cmd a0/00:00:00:08:00/00:00:00:00:00/a0 tag 0 pio 16392 in
         cdb 4a 01 00 00 10 00 00 00  08 00 00 00 00 00 00 00
         res 40/00:03:00:00:00/00:00:00:00:00/a0 Emask 0x4 (timeout)
ata2.00: status: { DRDY }
ata2: link is slow to respond, please be patient (ready=0)
ata2: device not ready (errno=-16), forcing hardreset
ata2: soft resetting link
ata2.00: configured for UDMA/33
ata2: EH complete
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
ata2.00: status: { DRDY ERR }

Previous rc version of kernel does not seemed to generate these messages.   Where/who generated these errors - harddisk drivers?

Thanks.
Comment 1 Andrew Morton 2009-04-01 23:24:54 UTC 
Reassigned to ata, marked as a regression.
Comment 2 Tejun Heo 2009-04-02 00:05:08 UTC 
Strange.  Can you please attach full kernel log including boot messages?
Comment 3 Peter Teoh 2009-04-02 07:39:03 UTC 
Sorry, this interface does not allow more than 65535 characters, so here it is:

http://pastebin.com/f218b3add

reboot over two different days.

Thanks.
Comment 4 Tejun Heo 2009-04-06 19:49:36 UTC 
Created attachment 20836 [details]
messages.log

It's usually better to attach log files.  Fetching the log and attaching.
Comment 5 Tejun Heo 2009-04-14 10:41:43 UTC 
Created attachment 20971 [details]
sense-debug.patch

Can you please apply the attached patch and post the resulting kernel log?  Thanks.
Comment 6 Peter Teoh 2009-04-16 00:00:48 UTC 
Thank you Tejun Heo.   After you patch came out, i was frantically trying to duplicate the bug again, including rebooting into the same past kernel, all on the same machine.   To no avail.   Both past version and current 2.6.30-rc1 linus git tree version has no such "ata2....." kind of error statement in dmesg.

Question:   Is this error possible arising from instrumenting other parts of the kernel codes?   (eg, the vfs_read() interface)?

#
Mar 30 11:13:21 coffeegold kernel: ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x0
#
Mar 30 11:13:21 coffeegold kernel: ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
#
Mar 30 11:13:21 coffeegold kernel:         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
#
Mar 30 11:13:21 coffeegold kernel:         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x1 (device error)
#
Mar 30 11:13:21 coffeegold kernel: ata2.00: status: { DRDY ERR }
#
Mar 30 11:13:26 coffeegold kernel: ata2.00: qc timeout (cmd 0xa0)
#
Mar 30 11:13:26 coffeegold kernel: ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
#
Mar 30 11:13:26 coffeegold kernel: ata2.00: cmd a0/00:00:00:00:00/00:00:00:00:00/a0 tag 0
#
Mar 30 11:13:26 coffeegold kernel:         cdb 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00
#
Mar 30 11:13:26 coffeegold kernel:         res 51/20:03:00:00:00/00:00:00:00:00/a0 Emask 0x5 (timeout)
#
Mar 30 11:13:26 coffeegold kernel: ata2.00: status: { DRDY ERR }
#
Mar 30 11:13:31 coffeegold kernel: ata2: link is slow to respond, please be patient (ready=0)
#
Mar 30 11:13:35 coffeegold dhclient: DHCPREQUEST on eth0 to 192.168.0.20 port 67
#
Mar 30 11:13:35 coffeegold dhclient: DHCPACK from 192.168.0.20
#
Mar 30 11:13:35 coffeegold dhclient: bound to 192.168.128.245 -- renewal in 257 seconds.
#
Mar 30 11:13:36 coffeegold kernel: ata2: device not ready (errno=-16), forcing hardreset
#
Mar 30 11:13:36 coffeegold kernel: ata2: soft resetting link
#
Mar 30 11:13:36 coffeegold kernel: ata2.00: configured for UDMA/33
#
Mar 30 11:13:36 coffeegold kernel: ata2: EH complete
#
Mar 30 11:17:14 coffeegold kernel: ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6
#
Mar 30 11:17:14 coffeegold kernel: ata2.00: BMDMA stat 0x25
#
Mar 30 11:17:14 coffeegold kernel: ata2.00: cmd a0/01:00:00:fe:00/00:00:00:00:00/a0 tag 0 dma 16640 in
#
Mar 30 11:17:14 coffeegold kernel:         cdb 12 01 00 00 fe 00 00 00  00 00 00 00 00 00 00 00
#
Mar 30 11:17:14 coffeegold kernel:         res d1/54:03:00:00:00/00:00:00:00:00/a0 Emask 0x3 (HSM violation)
#
Mar 30 11:17:14 coffeegold kernel: ata2.00: status: { Busy }
#
Mar 30 11:17:14 coffeegold kernel: ata2: soft resetting link
#
Mar 30 11:17:14 coffeegold kernel: ata2.00: configured for UDMA/33
#
Mar 30 11:17:14 coffeegold kernel: ata2: EH complete

As I was reading this drivers/ata/libata-eh.c:

 546         /* synchronize with host lock and sort out timeouts */
 547 
 548         /* For new EH, all qcs are finished in one of three ways -
 549          * normal completion, error completion, and SCSI timeout.
 550          * Both completions can race against SCSI timeout.  When normal
 551          * completion wins, the qc never reaches EH.  When error
 552          * completion wins, the qc has ATA_QCFLAG_FAILED set.
 553          *
 554          * When SCSI timeout wins, things are a bit more complex.
 555          * Normal or error completion can occur after the timeout but
 556          * before this point.  In such cases, both types of
 557          * completions are honored.  A scmd is determined to have
 558          * timed out iff its associated qc is active and not failed.
 559          */

I suspect it may be due to a slight increase in overheads in processing the instrumented vfs_read(), giving rise to timing delays.  Correct?

Apologize for the effort spent.   U can close this bug report.   Thanks.
Comment 7 Tejun Heo 2009-04-19 08:48:52 UTC 
Hmm.... I don't think it's something which depends on timing but you never know.  Well, please keep an eye on it and if it occurs again, reopen this bug report.  Thanks.
Comment 8 Thomas Creutz 2009-07-09 13:26:08 UTC 
hi.. I have also this messages on my system (running current Ubuntu 9.04 with kernel image 2.6.28-13-generic, but also on Ubuntu 8.10 I had this problems)

I have also very bad performance when I have heavy harddisk activity (copy files, running vmware....)

I try to recompile the module and attach the log
Comment 9 Thomas Creutz 2009-07-09 13:26:40 UTC 
Created attachment 22293 [details]
full dmesg
Comment 10 Tejun Heo 2009-07-15 08:30:26 UTC 
Thomas, can you please file a separate bug report and attach results from 2.6.30?

Thankks.
Comment 11 Thomas Creutz 2009-07-15 09:58:55 UTC 
hm.. ok.
Note You need to log in before you can comment on or make changes to this bug.