WARNING - OLD ARCHIVES

This is an archived copy of the Xen.org mailing list, which we have preserved to ensure that existing links to archives are not broken. The live archive, which contains the latest emails, can be found at http://lists.xen.org/
   
 
 
Xen 		  
Home Products Support Community News
 
   
 

xen-devel

[Top] [All Lists]
<prev [Date] next>
[Advanced]
 <prev [Thread] next>

[Xen-devel] Re: Help interpreting AHCI failure messages

from [Jeremy Fitzhardinge] [Permanent Link][Original]
To: Tejun Heo <htejun@xxxxxxxxx>
Subject: [Xen-devel] Re: Help interpreting AHCI failure messages
From: Jeremy Fitzhardinge <jeremy@xxxxxxxx>
Date: Fri, 19 Dec 2008 08:30:00 -0800
Cc: Robert Hancock <hancockr@xxxxxxx>, Xen-devel <xen-devel@xxxxxxxxxxxxxxxxxxx>, Jeff Garzik <jeff@xxxxxxxxxx>, Linux Kernel Mailing List <linux-kernel@xxxxxxxxxxxxxxx>, IDE/ATA development list <linux-ide@xxxxxxxxxxxxxxx>, Gerd Hoffmann <kraxel@xxxxxxxxxx>
Delivery-date: Fri, 19 Dec 2008 08:30:34 -0800
Envelope-to: www-data@xxxxxxxxxxxxxxxxxxx
In-reply-to: <49446DD0.3030600@xxxxxxxxx>
List-help: <mailto:xen-devel-request@lists.xensource.com?subject=help>
List-id: Xen developer discussion <xen-devel.lists.xensource.com>
List-post: <mailto:xen-devel@lists.xensource.com>
List-subscribe: <http://lists.xensource.com/mailman/listinfo/xen-devel>, <mailto:xen-devel-request@lists.xensource.com?subject=subscribe>
List-unsubscribe: <http://lists.xensource.com/mailman/listinfo/xen-devel>, <mailto:xen-devel-request@lists.xensource.com?subject=unsubscribe>
References: <4942D651.1050306@xxxxxxxx> <4943317C.8000807@xxxxxxx> <49434EC9.4070408@xxxxxxxx> <49446DD0.3030600@xxxxxxxxx>
Sender: xen-devel-bounces@xxxxxxxxxxxxxxxxxxx
User-agent: Thunderbird 2.0.0.18 (X11/20081119) 
Tejun Heo wrote:

Hello,

Jeremy Fitzhardinge wrote:

xen_set_ioapic_routing: irq 31 gsi 18 vector 184 ioapic 0 pin 18
triggering 0 polarity 1ahci 0000:00:1f.2: PCI INT C -> GSI 18 (level,
low) -> IRQ 31
xen: PCI device 0000:00:1f.2 pin 3 -> irq 31
ahci 0000:00:1f.2: AHCI 0001.0200 32 slots 6 ports 3 Gbps 0x27 impl
SATA mode
ahci 0000:00:1f.2: flags: 64bit ncq sntf pm led clo pmp pio slum part
ems
scsi0 : ahci
scsi1 : ahci
scsi2 : ahci
scsi3 : ahci
scsi4 : ahci
scsi5 : ahci
ata1: SATA max UDMA/133 abar m2048@0xff970000 port 0xff970100 irq 31
ata2: SATA max UDMA/133 abar m2048@0xff970000 port 0xff970180 irq 31
ata3: SATA max UDMA/133 abar m2048@0xff970000 port 0xff970200 irq 31
ata4: DUMMY
ata5: DUMMY
ata6: SATA max UDMA/133 abar m2048@0xff970000 port 0xff970380 irq 31
ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata1.00: qc timeout (cmd 0xec)
ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4)
ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata1.00: qc timeout (cmd 0xec)
ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4)
ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata1.00: qc timeout (cmd 0xec)
ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4)


This strongly suggests IRQ delivery problem.


ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)


But yes this contradicts that.


I'm wondering if you can give me a clue as to what might be failing
on the AHCI side to give these symptoms, so I have some idea where I
need to fix things in my code?

The timeouts would tend to suggest interrupts aren't getting through,
you can check /proc/interrupts and see if that IRQ has gotten any
interrupts at all..

Hm.  I think there might be more to it than that.  When I boot the
system with the controller in IDE mode, it has the same GSI/irq and it
works OK.

Furthermore, ata2 - which is sharing the same interrupt - seems to have
managed to read the DVD drive's information, so something must be
working.  But why is it failing for the disk?


Can you try irqpoll on it?
Here's a log of a run where everything works initially, but then it starts to fail (about half way into the log). ATA_DEBUG is enabled, so its pretty verbose. 

http://kraxel.fedorapeople.org/for-jeremy/xeni.log

Does anything stand out?

The part leading up to and including the failure is:

ata_sg_setup: 13 sg elements mapped
ata_scsi_dump_cdb: CDB (1:0,0,0) 28 00 05 b7 ad ee 00 00 20
ata_sg_setup: 4 sg elements mapped
ata_scsi_dump_cdb: CDB (1:0,0,0) 28 00 05 9a 31 be 00 00 40
ata_sg_setup: 8 sg elements mapped
ata_scsi_dump_cdb: CDB (1:0,0,0) 28 00 05 9f 82 5e 00 00 08
ata_sg_setup: 1 sg elements mapped
ata_scsi_dump_cdb: CDB (1:0,0,0) 28 00 05 b1 5a 26 00 00 08
ata_sg_setup: 1 sg elements mapped
ata_scsi_dump_cdb: CDB (1:0,0,0) 28 00 05 b1 a8 c6 00 00 10
ata_sg_setup: 2 sg elements mapped
ata_scsi_dump_cdb: CDB (2:0,0,0) 00 00 00 00 00 00 00 00 00
ata_scsi_timed_out: ENTER
ata_scsi_timed_out: EXIT, ret=0
ata_scsi_error: ENTER
ata_port_flush_task: ENTER
ata2: ata_port_flush_task: EXIT
ata_eh_link_autopsy: ENTER
atapi_eh_request_sense: ATAPI request sense
ata_sg_setup: 1 sg elements mapped
ata_port_flush_task: ENTER
ata2: ata_port_flush_task: EXIT
ata_eh_link_autopsy: EXIT
ata_eh_recover: ENTER
ata_eh_revalidate_and_attach: ENTER
ata_eh_recover: EXIT, rc=0
ata_scsi_error: EXIT
ata_scsi_dump_cdb: CDB (2:0,0,0) 00 00 00 00 00 00 00 00 00
ata_scsi_timed_out: ENTER
ata_scsi_timed_out: EXIT, ret=0
ata_scsi_error: ENTER
ata_port_flush_task: ENTER
ata2: ata_port_flush_task: EXIT
ata_eh_link_autopsy: ENTER
atapi_eh_request_sense: ATAPI request sense
ata_sg_setup: 1 sg elements mapped
ata_port_flush_task: ENTER
ata2: ata_port_flush_task: EXIT
__ata_port_freeze: ata2 port frozen
ata2.00: qc timeout (cmd 0xa0)
ata_eh_link_autopsy: EXIT
ata2.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
ata2.00: irq_stat 0x40000001
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/24:03:00:00:00/00:00:00:00:00/a0 Emask 0x5 (timeout)
ata2.00: status: { DRDY ERR }
ata_eh_recover: ENTER
__ata_port_freeze: ata2 port frozen
ata2: hard resetting link
ahci_hardreset: ENTER
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=-11
ata_dev_classify: found ATAPI device by sig
ahci_hardreset: EXIT, rc=-11, class=3
ahci_softreset: ENTER
ahci_do_softreset: ENTER
ata_dev_classify: found ATAPI device by sig
ahci_do_softreset: EXIT, class=3
ata_eh_thaw_port: ata2 port thawed
ata_std_postreset: ENTER
ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata2.00: ata_dev_read_id: ENTER
ata_sg_setup: 1 sg elements mapped
ata_port_flush_task: ENTER
ata2: ata_port_flush_task: EXIT
__ata_port_freeze: ata2 port frozen
ata2.00: qc timeout (cmd 0xa1)
ata2.00: failed to IDENTIFY (I/O error, err_mask=0x4)
ata2.00: revalidation failed (errno=-5)
ata_eh_revalidate_and_attach: EXIT rc=-5
__ata_port_freeze: ata2 port frozen
ata2: hard resetting link
ahci_hardreset: ENTER
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=-11
ata_dev_classify: found ATAPI device by sig
ahci_hardreset: EXIT, rc=-11, class=3
ahci_softreset: ENTER
ahci_do_softreset: ENTER
ata_dev_classify: found ATAPI device by sig
ahci_do_softreset: EXIT, class=3
ata_eh_thaw_port: ata2 port thawed
ata_std_postreset: ENTER
ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata2.00: ata_dev_read_id: ENTER
ata_sg_setup: 1 sg elements mapped
ata_port_flush_task: ENTER
ata2: ata_port_flush_task: EXIT
__ata_port_freeze: ata2 port frozen
ata2.00: qc timeout (cmd 0xa1)
ata2.00: failed to IDENTIFY (I/O error, err_mask=0x4)
ata2.00: revalidation failed (errno=-5)
ata_eh_revalidate_and_attach: EXIT rc=-5
__ata_port_freeze: ata2 port frozen
ata2: hard resetting link
ahci_hardreset: ENTER
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=-11
ata_dev_classify: found ATAPI device by sig
ahci_hardreset: EXIT, rc=-11, class=3
ahci_softreset: ENTER
ahci_do_softreset: ENTER
ata_dev_classify: found ATAPI device by sig
ahci_do_softreset: EXIT, class=3
ata_eh_thaw_port: ata2 port thawed
ata_std_postreset: ENTER
ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata2.00: ata_dev_read_id: ENTER
ata_sg_setup: 1 sg elements mapped
ata_scsi_timed_out: ENTER
ata_scsi_timed_out: EXIT, ret=0
ata_scsi_timed_out: ENTER
ata_scsi_timed_out: EXIT, ret=0
ata_scsi_timed_out: ENTER
ata_scsi_timed_out: EXIT, ret=0
ata_scsi_timed_out: ENTER
ata_scsi_timed_out: EXIT, ret=0
ata_scsi_timed_out: ENTER
ata_scsi_timed_out: EXIT, ret=0
ata_scsi_timed_out: ENTER
ata_scsi_timed_out: EXIT, ret=0
ata_scsi_timed_out: ENTER
ata_scsi_timed_out: EXIT, ret=0
ata_scsi_error: ENTER
ata_port_flush_task: ENTER
ata1: ata_port_flush_task: EXIT
__ata_port_freeze: ata1 port frozen
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata1.00: exception Emask 0x0 SAct 0xf7 SErr 0x0 action 0x6 frozen
ata1.00: cmd 60/20:00:ee:ad:b7/00:00:05:00:00/40 tag 0 ncq 16384 in
        res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
ata1.00: status: { DRDY }
ata1.00: cmd 60/08:08:86:8a:42/00:00:0f:00:00/40 tag 1 ncq 4096 in
        res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
ata1.00: status: { DRDY }
ata1.00: cmd 60/08:10:26:5a:b1/00:00:05:00:00/40 tag 2 ncq 4096 in
        res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
ata1.00: status: { DRDY }
ata1.00: cmd 60/08:20:26:db:7f/01:00:0f:00:00/40 tag 4 ncq 135168 in
        res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
ata1.00: status: { DRDY }
ata1.00: cmd 60/40:28:be:31:9a/00:00:05:00:00/40 tag 5 ncq 32768 in
        res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
ata1.00: status: { DRDY }
ata1.00: cmd 60/08:30:5e:82:9f/00:00:05:00:00/40 tag 6 ncq 4096 in
        res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
ata1.00: status: { DRDY }
ata1.00: cmd 60/10:38:c6:a8:b1/00:00:05:00:00/40 tag 7 ncq 8192 in
        res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
ata1.00: status: { DRDY }
ata_eh_recover: ENTER
__ata_port_freeze: ata1 port frozen
ata1: hard resetting link
ahci_hardreset: ENTER
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=-11
ata_dev_classify: found ATA device by sig
ahci_hardreset: EXIT, rc=-11, class=1
ahci_softreset: ENTER
ahci_do_softreset: ENTER
ata_dev_classify: found ATA device by sig
ahci_do_softreset: EXIT, class=1
ata_eh_thaw_port: ata1 port thawed
ata_std_postreset: ENTER
ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata1.00: ata_dev_read_id: ENTER
ata_sg_setup: 1 sg elements mapped
ata_port_flush_task: ENTER
ata1: ata_port_flush_task: EXIT
__ata_port_freeze: ata1 port frozen
ata1.00: qc timeout (cmd 0xec)
ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4)
ata1.00: revalidation failed (errno=-5)
ata_eh_revalidate_and_attach: EXIT rc=-5
__ata_port_freeze: ata1 port frozen
ata1: hard resetting link
ahci_hardreset: ENTER
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=-11
ata_dev_classify: found ATA device by sig
ahci_hardreset: EXIT, rc=-11, class=1
ahci_softreset: ENTER
ahci_do_softreset: ENTER
ata_dev_classify: found ATA device by sig
ahci_do_softreset: EXIT, class=1
ata_eh_thaw_port: ata1 port thawed
ata_std_postreset: ENTER
ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata1.00: ata_dev_read_id: ENTER
ata_sg_setup: 1 sg elements mapped
ata_port_flush_task: ENTER
ata1: ata_port_flush_task: EXIT
__ata_port_freeze: ata1 port frozen
ata1.00: qc timeout (cmd 0xec)
ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4)
ata1.00: revalidation failed (errno=-5)
ata_eh_revalidate_and_attach: EXIT rc=-5
__ata_port_freeze: ata1 port frozen
ata1: hard resetting link
ahci_hardreset: ENTER
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=-11
ata_dev_classify: found ATA device by sig
ahci_hardreset: EXIT, rc=-11, class=1
ahci_softreset: ENTER
ahci_do_softreset: ENTER
ata_dev_classify: found ATA device by sig
ahci_do_softreset: EXIT, class=1
ata_eh_thaw_port: ata1 port thawed
ata_std_postreset: ENTER
ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata1.00: ata_dev_read_id: ENTER
ata_sg_setup: 1 sg elements mapped
ata_port_flush_task: ENTER
ata2: ata_port_flush_task: EXIT
__ata_port_freeze: ata2 port frozen
ata2.00: qc timeout (cmd 0xa1)
ata2.00: failed to IDENTIFY (I/O error, err_mask=0x4)
ata2.00: revalidation failed (errno=-5)
ata_eh_revalidate_and_attach: EXIT rc=-5
ata2.00: disabled
ata_eh_revalidate_and_attach: ENTER
ata_eh_recover: EXIT, rc=0
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata_eh_recover: ENTER
__ata_port_freeze: ata2 port frozen
ata2: hard resetting link
ahci_hardreset: ENTER
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=-11
ata_dev_classify: found ATAPI device by sig
ahci_hardreset: EXIT, rc=-11, class=3
ahci_softreset: ENTER
ahci_do_softreset: ENTER
ata_dev_classify: found ATAPI device by sig
ahci_do_softreset: EXIT, class=3
ata_eh_thaw_port: ata2 port thawed
ata_std_postreset: ENTER
ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata_eh_recover: EXIT, rc=0
ata2: EH complete
ata_scsi_error: EXIT
ata_scsi_dump_cdb: CDB (2:0,0,0) 00 00 00 00 00 00 00 00 00
ata_scsi_dump_cdb: CDB (2:0,0,0) 12 00 00 00 24 00 00 00 00
ata_scsi_dump_cdb: CDB (2:0,0,0) 1e 00 00 00 00 00 00 00 00
ata_scsi_dump_cdb: CDB (2:0,0,0) 00 00 00 00 00 00 00 00 00
ata_scsi_dump_cdb: CDB (2:0,0,0) 12 00 00 00 fe 00 00 00 00
ata_scsi_dump_cdb: CDB (2:0,0,0) 1e 00 00 00 00 00 00 00 00
ata_scsi_dump_cdb: CDB (2:0,0,0) 00 00 00 00 00 00 00 00 00
ata_scsi_dump_cdb: CDB (2:0,0,0) 12 01 00 00 fe 00 00 00 00
ata_scsi_dump_cdb: CDB (2:0,0,0) 1e 00 00 00 00 00 00 00 00
ata_port_flush_task: ENTER
ata1: ata_port_flush_task: EXIT
__ata_port_freeze: ata1 port frozen
ata1.00: qc timeout (cmd 0xec)
ata1.00: failed to IDENTIFY (I/O error, err_mask=0x4)
ata1.00: revalidation failed (errno=-5)
ata_eh_revalidate_and_attach: EXIT rc=-5
ata1.00: disabled
ata_eh_revalidate_and_attach: ENTER
ata_eh_recover: EXIT, rc=0
ata_eh_link_autopsy: ENTER
ata_eh_link_autopsy: EXIT
ata_eh_recover: ENTER
__ata_port_freeze: ata1 port frozen
ata1: hard resetting link
ahci_hardreset: ENTER
sata_link_hardreset: ENTER
sata_link_hardreset: EXIT, rc=-11
ata_dev_classify: found ATA device by sig
ahci_hardreset: EXIT, rc=-11, class=1
ahci_softreset: ENTER
ahci_do_softreset: ENTER
ata_dev_classify: found ATA device by sig
ahci_do_softreset: EXIT, class=1
ata_eh_thaw_port: ata1 port thawed
ata_std_postreset: ENTER
ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
ata_std_postreset: EXIT
ata_eh_revalidate_and_attach: ENTER
ata_eh_recover: EXIT, rc=0
ata1: EH complete
ata_scsi_error: EXIT
ata_scsi_dump_cdb: CDB (1:0,0,0) 28 00 05 b1 a8 c6 00 00 10
sd 0:0:0:0: [sda] Result: hostbyte=DID_BAD_TARGET 
driverbyte=DRIVER_OK,SUGGEST_OK
end_request: I/O error, dev sda, sector 95529158
ata_scsi_dump_cdb: CDB (1:0,0,0) 28 00 05 9f 82 5e 00 00 08
sd 0:0:0:0: [sda] Result: hostbyte=DID_BAD_TARGET 
driverbyte=DRIVER_OK,SUGGEST_OK
end_request: I/O error, dev sda, sector 94339678
ata_scsi_dump_cdb: CDB (1:0,0,0) 28 00 05 9a 31 be 00 00 40
ata_scsi_dump_cdb: CDB (1:0,0,0) 28 00 0f 7f db 26 00 01 08
ata_scsi_dump_cdb: CDB (1:0,0,0) 28 00 05 b1 5a 26 00 00 08
ata_scsi_dump_cdb: CDB (1:0,0,0) 28 00 0f 42 8a 86 00 00 08
ata_scsi_dump_cdb: CDB (1:0,0,0) 28 00 05 b7 ad ee 00 00 20
sd 0:0:0:0: [sda] Result: hostbyte=DID_BAD_TARGET 
driverbyte=DRIVER_OK,SUGGEST_OK
end_request: I/O error, dev sda, sector 93991358
sd 0:0:0:0: [sda] Result: hostbyte=DID_BAD_TARGET 
driverbyte=DRIVER_OK,SUGGEST_OK
end_request: I/O error, dev sda, sector 260037414
sd 0:0:0:0: [sda] Result: hostbyte=DID_BAD_TARGET 
driverbyte=DRIVER_OK,SUGGEST_OK
end_request: I/O error, dev sda, sector 95509030


Thanks,
   J


_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxxxxxxxx
http://lists.xensource.com/xen-devel
[More with this subject...]
<Prev in Thread] Current Thread [Next in Thread>
Previous by Date:  [Xen-devel] Fourth release candidates for 3.2.3 and 3.3.1, Keir Fraser
Next by Date:  Re: [Xen-devel] XEN Proposal, Chris
Previous by Thread:  [Xen-devel] Fourth release candidates for 3.2.3 and 3.3.1, Keir Fraser
Next by Thread:  [Xen-devel] Re: Help interpreting AHCI failure messages, Andrew Lyon
Indexes:  [Date] [Thread] [Top] [All Lists]
 
   

Copyright , Citrix Systems Inc. All rights reserved. Legal and Privacy