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
--
To unsubscribe from this list: send the line "unsubscribe linux-ide" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
