New: SCSI: timing out command for dvd drive

Bug 11817 [email protected] 3 participants 12 messages Oct 24, 2008 – Oct 25, 2008 SCSI

Share & tools

[email protected]

author

2008-10-24 12:56 UTC #0 lore raw

http://bugzilla.kernel.org/show_bug.cgi?id=11817

           Summary: SCSI: timing out command for dvd drive
           Product: IO/Storage
           Version: 2.5
     KernelVersion: 2.6.28-rc1
          Platform: All
        OS/Version: Linux
              Tree: Mainline
            Status: NEW
          Severity: normal
          Priority: P1
         Component: SCSI
        AssignedTo: [email protected]
        ReportedBy: [email protected]

Latest working kernel version: 2.6.27
Earliest failing kernel version: 2.6.28-rc1
Distribution: Gentoo
Hardware Environment: Dell Latitude E6500
Problem Description:
I tried 2.6.28-rc1 today and the boot is delayed by scsi timeouts. It does work if I remove my dvd drive before booting.

dmesg:

Oct 24 12:07:12 jtb [    0.743466] Driver 'sd' needs updating - please use
bus_type methods
Oct 24 12:07:12 jtb [    0.743492] Driver 'sr' needs updating - please use
bus_type methods
Oct 24 12:07:12 jtb [    0.743555] ahci 0000:00:1f.2: version 3.0
Oct 24 12:07:12 jtb [    0.743564] ahci 0000:00:1f.2: PCI INT D -> GSI 19
(level, low) -> IRQ 19
Oct 24 12:07:12 jtb [    0.743596] ahci 0000:00:1f.2: irq 42 for MSI/MSI-X
Oct 24 12:07:12 jtb [    0.743666] ahci 0000:00:1f.2: AHCI 0001.0200 32 slots 4
ports 3 Gbps 0x33 impl RAID mode
Oct 24 12:07:12 jtb [    0.743668] ahci 0000:00:1f.2: flags: 64bit ncq sntf
stag pm led clo pmp pio slum part ems
Oct 24 12:07:12 jtb [    0.743673] ahci 0000:00:1f.2: setting latency timer to
64
Oct 24 12:07:12 jtb [    0.743820] scsi0 : ahci
Oct 24 12:07:12 jtb [    0.743899] scsi1 : ahci
Oct 24 12:07:12 jtb [    0.743958] scsi2 : ahci
Oct 24 12:07:12 jtb [    0.744012] scsi3 : ahci
Oct 24 12:07:12 jtb [    0.744066] scsi4 : ahci
Oct 24 12:07:12 jtb [    0.744120] scsi5 : ahci
Oct 24 12:07:12 jtb [    0.744564] ata1: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1c900 irq 42
Oct 24 12:07:12 jtb [    0.744568] ata2: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1c980 irq 42
Oct 24 12:07:12 jtb [    0.744569] ata3: DUMMY
Oct 24 12:07:12 jtb [    0.744570] ata4: DUMMY
Oct 24 12:07:12 jtb [    0.744572] ata5: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1cb00 irq 42
Oct 24 12:07:12 jtb [    0.744575] ata6: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1cb80 irq 42
Oct 24 12:07:12 jtb [    1.063351] ata1: SATA link up 1.5 Gbps (SStatus 113
SControl 300)
Oct 24 12:07:12 jtb [    1.068536] ata1.00: ATA-8: SAMSUNG HM250JI, HS100-08,
max UDMA7
Oct 24 12:07:12 jtb [    1.068538] ata1.00: 488397168 sectors, multi 0: LBA48
NCQ (depth 31/32)
Oct 24 12:07:12 jtb [    1.075477] ata1.00: configured for UDMA/133
Oct 24 12:07:12 jtb [    1.406682] ata2: SATA link up 1.5 Gbps (SStatus 113
SControl 300)
Oct 24 12:07:12 jtb [    1.409289] ata2.00: ATAPI: PLDS DVD+/-RW DU-8A2S, 4D12,
max UDMA/100
Oct 24 12:07:12 jtb [    1.412791] ata2.00: configured for UDMA/100
Oct 24 12:07:12 jtb [    1.746681] ata5: SATA link down (SStatus 0 SControl
300)
Oct 24 12:07:12 jtb [    2.080014] ata6: SATA link down (SStatus 0 SControl
300)
Oct 24 12:07:12 jtb [    2.093410] scsi 0:0:0:0: Direct-Access     ATA     
SAMSUNG HM250JI  HS10 PQ: 0 ANSI: 5
Oct 24 12:07:12 jtb [    2.093516] sd 0:0:0:0: [sda] 488397168 512-byte
hardware sectors: (250 GB/232 GiB)
Oct 24 12:07:12 jtb [    2.093527] sd 0:0:0:0: [sda] Write Protect is off
Oct 24 12:07:12 jtb [    2.093529] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
Oct 24 12:07:12 jtb [    2.093547] sd 0:0:0:0: [sda] Write cache: enabled, read
cache: enabled, doesn't support DPO or FUA
Oct 24 12:07:12 jtb [    2.093592] sd 0:0:0:0: [sda] 488397168 512-byte
hardware sectors: (250 GB/232 GiB)
Oct 24 12:07:12 jtb [    2.093603] sd 0:0:0:0: [sda] Write Protect is off
Oct 24 12:07:12 jtb [    2.093605] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
Oct 24 12:07:12 jtb [    2.093622] sd 0:0:0:0: [sda] Write cache: enabled, read
cache: enabled, doesn't support DPO or FUA
Oct 24 12:07:12 jtb [    2.093625]  sda: sda1 sda2 sda3
Oct 24 12:07:12 jtb [    2.132082] sd 0:0:0:0: [sda] Attached SCSI disk
Oct 24 12:07:12 jtb [    2.132157] sd 0:0:0:0: Attached scsi generic sg0 type 0
Oct 24 12:07:12 jtb [   24.136670] scsi 1:0:0:0: timing out command, waited 22s
Oct 24 12:07:12 jtb [   46.246667] scsi 1:0:0:0: timing out command, waited 22s
Oct 24 12:07:12 jtb [   68.356665] scsi 1:0:0:0: timing out command, waited 22s
Oct 24 12:07:12 jtb [   90.466663] scsi 1:0:0:0: timing out command, waited 22s
Oct 24 12:07:12 jtb [  112.576661] scsi 1:0:0:0: timing out command, waited 22s
Oct 24 12:07:12 jtb [  134.686658] scsi 1:0:0:0: timing out command, waited 22s
Oct 24 12:07:12 jtb [  134.686714] ata2: WARNING: synchronous SCSI scan failed
without making any progress,
Oct 24 12:07:12 jtb [  134.686715]                   switching to async
Oct 24 12:07:12 jtb [  134.686876] Initializing USB Mass Storage driver...

The same with dvd drive removed:

Oct 24 12:28:02 jtb [    0.743457] Driver 'sd' needs updating - please use
bus_type methods
Oct 24 12:28:02 jtb [    0.743482] Driver 'sr' needs updating - please use
bus_type methods
Oct 24 12:28:02 jtb [    0.743543] ahci 0000:00:1f.2: version 3.0
Oct 24 12:28:02 jtb [    0.743552] ahci 0000:00:1f.2: PCI INT D -> GSI 19
(level, low) -> IRQ 19
Oct 24 12:28:02 jtb [    0.743584] ahci 0000:00:1f.2: irq 42 for MSI/MSI-X
Oct 24 12:28:02 jtb [    0.743652] ahci 0000:00:1f.2: AHCI 0001.0200 32 slots 4
ports 3 Gbps 0x33 impl RAID mode
Oct 24 12:28:02 jtb [    0.743655] ahci 0000:00:1f.2: flags: 64bit ncq sntf
stag pm led clo pmp pio slum part ems
Oct 24 12:28:02 jtb [    0.743659] ahci 0000:00:1f.2: setting latency timer to
64
Oct 24 12:28:02 jtb [    0.743804] scsi0 : ahci
Oct 24 12:28:02 jtb [    0.743881] scsi1 : ahci
Oct 24 12:28:02 jtb [    0.743933] scsi2 : ahci
Oct 24 12:28:02 jtb [    0.743985] scsi3 : ahci
Oct 24 12:28:02 jtb [    0.744040] scsi4 : ahci
Oct 24 12:28:02 jtb [    0.744093] scsi5 : ahci
Oct 24 12:28:02 jtb [    0.744533] ata1: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1c900 irq 42
Oct 24 12:28:02 jtb [    0.744536] ata2: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1c980 irq 42
Oct 24 12:28:02 jtb [    0.744538] ata3: DUMMY
Oct 24 12:28:02 jtb [    0.744539] ata4: DUMMY
Oct 24 12:28:02 jtb [    0.744541] ata5: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1cb00 irq 42
Oct 24 12:28:02 jtb [    0.744544] ata6: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1cb80 irq 42
Oct 24 12:28:02 jtb [    1.063351] ata1: SATA link up 1.5 Gbps (SStatus 113
SControl 300)
Oct 24 12:28:02 jtb [    1.068536] ata1.00: ATA-8: SAMSUNG HM250JI, HS100-08,
max UDMA7
Oct 24 12:28:02 jtb [    1.068538] ata1.00: 488397168 sectors, multi 0: LBA48
NCQ (depth 31/32)
Oct 24 12:28:02 jtb [    1.075469] ata1.00: configured for UDMA/133
Oct 24 12:28:02 jtb [    1.406681] ata2: SATA link down (SStatus 0 SControl
300)
Oct 24 12:28:02 jtb [    1.740014] ata5: SATA link down (SStatus 0 SControl
300)
Oct 24 12:28:02 jtb [    2.073347] ata6: SATA link down (SStatus 0 SControl
300)
Oct 24 12:28:02 jtb [    2.086746] scsi 0:0:0:0: Direct-Access     ATA     
SAMSUNG HM250JI  HS10 PQ: 0 ANSI: 5
Oct 24 12:28:02 jtb [    2.086857] sd 0:0:0:0: [sda] 488397168 512-byte
hardware sectors: (250 GB/232 GiB)
Oct 24 12:28:02 jtb [    2.086869] sd 0:0:0:0: [sda] Write Protect is off
Oct 24 12:28:02 jtb [    2.086870] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
Oct 24 12:28:02 jtb [    2.086888] sd 0:0:0:0: [sda] Write cache: enabled, read
cache: enabled, doesn't support DPO or FUA
Oct 24 12:28:02 jtb [    2.086932] sd 0:0:0:0: [sda] 488397168 512-byte
hardware sectors: (250 GB/232 GiB)
Oct 24 12:28:02 jtb [    2.086943] sd 0:0:0:0: [sda] Write Protect is off
Oct 24 12:28:02 jtb [    2.086945] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
Oct 24 12:28:02 jtb [    2.086962] sd 0:0:0:0: [sda] Write cache: enabled, read
cache: enabled, doesn't support DPO or FUA
Oct 24 12:28:02 jtb [    2.086965]  sda: sda1 sda2 sda3
Oct 24 12:28:02 jtb [    2.135048] sd 0:0:0:0: [sda] Attached SCSI disk
Oct 24 12:28:02 jtb [    2.135121] sd 0:0:0:0: Attached scsi generic sg0 type 0
Oct 24 12:28:02 jtb [    2.135180] Initializing USB Mass Storage driver...

Signature · 3 lines

Configure bugmail: http://bugzilla.kernel.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[email protected]

author

2008-10-24 12:58 UTC #1 lore raw

[Bug 11817] SCSI: timing out command for dvd drive

http://bugzilla.kernel.org/show_bug.cgi?id=11817

------- Comment #1 from [email protected] 2008-10-24 05:58 ------- Created an attachment (id=18425)
--> (http://bugzilla.kernel.org/attachment.cgi?id=18425&action=view)
2.6.28-rc1 config

It also happens without "Asynchronous SCSI scanning".

Signature · 3 lines

Configure bugmail: http://bugzilla.kernel.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[email protected]

author

2008-10-24 13:08 UTC #2 lore raw

[Bug 11817] SCSI: timing out command for dvd drive

In reply to [email protected]

http://bugzilla.kernel.org/show_bug.cgi?id=11817

------- Comment #2 from [email protected] 2008-10-24 06:08 ------- I tried libata.dma=0 in the kernel param.

It gets detected and hal keeps polling until I disable it.

Signature · 3 lines

Configure bugmail: http://bugzilla.kernel.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[email protected]

author

2008-10-24 15:39 UTC #3 lore raw

[Bug 11817] SCSI: timing out command for dvd drive

In reply to [email protected]

http://bugzilla.kernel.org/show_bug.cgi?id=11817

[email protected] changed:

What |Removed |Added
----------------------------------------------------------------------------
CC| |[email protected]

------- Comment #3 from [email protected] 2008-10-24 08:39 ------- Same problem here.

Signature · 3 lines

Configure bugmail: http://bugzilla.kernel.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

James Bottomley

maintainer

2008-10-24 15:55 UTC #4 lore raw

Re: [Bug 11817] SCSI: timing out command for dvd drive

Quoted 2 lines · On Fri, 2008-10-24 at 08:39 -0700, [email protected] wrote:

------- Comment #3 from [email protected] 2008-10-24 08:39 ------- Same problem here.

This is Jens' tag cockup:

http://marc.info/?t=122483204900001

Isn't it?

CDs are also no-NCQ devices.

James

[email protected]

author

2008-10-24 15:55 UTC #5 lore raw

[Bug 11817] SCSI: timing out command for dvd drive

In reply to [email protected]

http://bugzilla.kernel.org/show_bug.cgi?id=11817

------- Comment #4 from [email protected] 2008-10-24 08:55 -------
Reply-To: [email protected]

Quoted 2 lines · On Fri, 2008-10-24 at 08:39 -0700, [email protected] wrote:

------- Comment #3 from [email protected] 2008-10-24 08:39 ------- Same problem here.

This is Jens' tag cockup:

http://marc.info/?t=122483204900001

Isn't it?

CDs are also no-NCQ devices.

James

Signature · 3 lines

Configure bugmail: http://bugzilla.kernel.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[email protected]

author

2008-10-24 16:29 UTC #6 lore raw

[Bug 11817] SCSI: timing out command for dvd drive

In reply to [email protected]

http://bugzilla.kernel.org/show_bug.cgi?id=11817

------- Comment #5 from [email protected] 2008-10-24 09:28 ------- James, you are correct, this is the same problem. Applying the patch at
http://lkml.org/lkml/2008/10/24/102
made my system boot again. Thanks!

Signature · 3 lines

Configure bugmail: http://bugzilla.kernel.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[email protected]

author

2008-10-24 16:39 UTC #7 lore raw

[Bug 11817] SCSI: timing out command for dvd drive

In reply to [email protected]

http://bugzilla.kernel.org/show_bug.cgi?id=11817

------- Comment #6 from [email protected] 2008-10-24 09:38 -------
Reply-To: [email protected]

Quoted 88 lines · [email protected] wrote:

http://bugzilla.kernel.org/show_bug.cgi?id=11817

           Summary: SCSI: timing out command for dvd drive
           Product: IO/Storage
           Version: 2.5
     KernelVersion: 2.6.28-rc1
          Platform: All
        OS/Version: Linux
              Tree: Mainline
            Status: NEW
          Severity: normal
          Priority: P1
         Component: SCSI
        AssignedTo: [email protected]
        ReportedBy: [email protected]

dmesg:

Oct 24 12:07:12 jtb [    0.743466] Driver 'sd' needs updating - please use
bus_type methods
Oct 24 12:07:12 jtb [    0.743492] Driver 'sr' needs updating - please use
bus_type methods
Oct 24 12:07:12 jtb [    0.743555] ahci 0000:00:1f.2: version 3.0
Oct 24 12:07:12 jtb [    0.743564] ahci 0000:00:1f.2: PCI INT D -> GSI 19
(level, low) -> IRQ 19
Oct 24 12:07:12 jtb [    0.743596] ahci 0000:00:1f.2: irq 42 for MSI/MSI-X
Oct 24 12:07:12 jtb [    0.743666] ahci 0000:00:1f.2: AHCI 0001.0200 32 slots 4
ports 3 Gbps 0x33 impl RAID mode
Oct 24 12:07:12 jtb [    0.743668] ahci 0000:00:1f.2: flags: 64bit ncq sntf
stag pm led clo pmp pio slum part ems
Oct 24 12:07:12 jtb [    0.743673] ahci 0000:00:1f.2: setting latency timer to
64
Oct 24 12:07:12 jtb [    0.743820] scsi0 : ahci
Oct 24 12:07:12 jtb [    0.743899] scsi1 : ahci
Oct 24 12:07:12 jtb [    0.743958] scsi2 : ahci
Oct 24 12:07:12 jtb [    0.744012] scsi3 : ahci
Oct 24 12:07:12 jtb [    0.744066] scsi4 : ahci
Oct 24 12:07:12 jtb [    0.744120] scsi5 : ahci
Oct 24 12:07:12 jtb [    0.744564] ata1: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1c900 irq 42
Oct 24 12:07:12 jtb [    0.744568] ata2: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1c980 irq 42
Oct 24 12:07:12 jtb [    0.744569] ata3: DUMMY
Oct 24 12:07:12 jtb [    0.744570] ata4: DUMMY
Oct 24 12:07:12 jtb [    0.744572] ata5: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1cb00 irq 42
Oct 24 12:07:12 jtb [    0.744575] ata6: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1cb80 irq 42
Oct 24 12:07:12 jtb [    1.063351] ata1: SATA link up 1.5 Gbps (SStatus 113
SControl 300)
Oct 24 12:07:12 jtb [    1.068536] ata1.00: ATA-8: SAMSUNG HM250JI, HS100-08,
max UDMA7
Oct 24 12:07:12 jtb [    1.068538] ata1.00: 488397168 sectors, multi 0: LBA48
NCQ (depth 31/32)
Oct 24 12:07:12 jtb [    1.075477] ata1.00: configured for UDMA/133
Oct 24 12:07:12 jtb [    1.406682] ata2: SATA link up 1.5 Gbps (SStatus 113
SControl 300)
Oct 24 12:07:12 jtb [    1.409289] ata2.00: ATAPI: PLDS DVD+/-RW DU-8A2S, 4D12,
max UDMA/100
Oct 24 12:07:12 jtb [    1.412791] ata2.00: configured for UDMA/100
Oct 24 12:07:12 jtb [    1.746681] ata5: SATA link down (SStatus 0 SControl
300)
Oct 24 12:07:12 jtb [    2.080014] ata6: SATA link down (SStatus 0 SControl
300)
Oct 24 12:07:12 jtb [    2.093410] scsi 0:0:0:0: Direct-Access     ATA     
SAMSUNG HM250JI  HS10 PQ: 0 ANSI: 5
Oct 24 12:07:12 jtb [    2.093516] sd 0:0:0:0: [sda] 488397168 512-byte
hardware sectors: (250 GB/232 GiB)
Oct 24 12:07:12 jtb [    2.093527] sd 0:0:0:0: [sda] Write Protect is off
Oct 24 12:07:12 jtb [    2.093529] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
Oct 24 12:07:12 jtb [    2.093547] sd 0:0:0:0: [sda] Write cache: enabled, read
cache: enabled, doesn't support DPO or FUA
Oct 24 12:07:12 jtb [    2.093592] sd 0:0:0:0: [sda] 488397168 512-byte
hardware sectors: (250 GB/232 GiB)
Oct 24 12:07:12 jtb [    2.093603] sd 0:0:0:0: [sda] Write Protect is off
Oct 24 12:07:12 jtb [    2.093605] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
Oct 24 12:07:12 jtb [    2.093622] sd 0:0:0:0: [sda] Write cache: enabled, read
cache: enabled, doesn't support DPO or FUA
Oct 24 12:07:12 jtb [    2.093625]  sda: sda1 sda2 sda3

Quoted 8 lines

Oct 24 12:07:12 jtb [    2.132082] sd 0:0:0:0: [sda] Attached SCSI disk
Oct 24 12:07:12 jtb [    2.132157] sd 0:0:0:0: Attached scsi generic sg0 type 0
Oct 24 12:07:12 jtb [   24.136670] scsi 1:0:0:0: timing out command, waited 22s
Oct 24 12:07:12 jtb [   46.246667] scsi 1:0:0:0: timing out command, waited 22s
Oct 24 12:07:12 jtb [   68.356665] scsi 1:0:0:0: timing out command, waited 22s
Oct 24 12:07:12 jtb [   90.466663] scsi 1:0:0:0: timing out command, waited 22s
Oct 24 12:07:12 jtb [  112.576661] scsi 1:0:0:0: timing out command, waited 22s
Oct 24 12:07:12 jtb [  134.686658] scsi 1:0:0:0: timing out command, waited 22s

I think this caused due to my patch that adds the scsi_noretry_cmd check in scsi_decide_disposition. We saw this problem exposed in RHEL testing.

Basically what used to happen without my patch is that the command continuously timed out or we got an error, and we would eventually hit the cmd->retries and cmd->allowed check and the command would be failed fairly quietly in some code paths like during setup.

Now scsi_noretry_cmd is returning 0 and that causes us to retry the command until we hit the check:

         disposition = scsi_decide_disposition(cmd);
         if (disposition != SUCCESS &&
             time_before(cmd->jiffies_at_alloc + wait_for, jiffies)) {
                 sdev_printk(KERN_ERR, cmd->device,
                             "timing out command, waited %lus\n",
                             wait_for/HZ);
                 disposition = SUCCESS;
         }

in scsi_softirq_done so we now see this error message get printed out for the failure.

Is Mike Anderson's patches that removes scsi_noretry_cmd going to be merged? If so that will fix the problem. If not then I will make a different patch.

Signature · 3 lines

Configure bugmail: http://bugzilla.kernel.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

Mike Christie

2008-10-24 16:39 UTC #8 lore raw

In reply to [email protected]

Quoted 87 lines · [email protected] wrote:

http://bugzilla.kernel.org/show_bug.cgi?id=11817

           Summary: SCSI: timing out command for dvd drive
           Product: IO/Storage
           Version: 2.5
     KernelVersion: 2.6.28-rc1
          Platform: All
        OS/Version: Linux
              Tree: Mainline
            Status: NEW
          Severity: normal
          Priority: P1
         Component: SCSI
        AssignedTo: [email protected]
        ReportedBy: [email protected]

dmesg:

Oct 24 12:07:12 jtb [    0.743466] Driver 'sd' needs updating - please use
bus_type methods
Oct 24 12:07:12 jtb [    0.743492] Driver 'sr' needs updating - please use
bus_type methods
Oct 24 12:07:12 jtb [    0.743555] ahci 0000:00:1f.2: version 3.0
Oct 24 12:07:12 jtb [    0.743564] ahci 0000:00:1f.2: PCI INT D -> GSI 19
(level, low) -> IRQ 19
Oct 24 12:07:12 jtb [    0.743596] ahci 0000:00:1f.2: irq 42 for MSI/MSI-X
Oct 24 12:07:12 jtb [    0.743666] ahci 0000:00:1f.2: AHCI 0001.0200 32 slots 4
ports 3 Gbps 0x33 impl RAID mode
Oct 24 12:07:12 jtb [    0.743668] ahci 0000:00:1f.2: flags: 64bit ncq sntf
stag pm led clo pmp pio slum part ems
Oct 24 12:07:12 jtb [    0.743673] ahci 0000:00:1f.2: setting latency timer to
64
Oct 24 12:07:12 jtb [    0.743820] scsi0 : ahci
Oct 24 12:07:12 jtb [    0.743899] scsi1 : ahci
Oct 24 12:07:12 jtb [    0.743958] scsi2 : ahci
Oct 24 12:07:12 jtb [    0.744012] scsi3 : ahci
Oct 24 12:07:12 jtb [    0.744066] scsi4 : ahci
Oct 24 12:07:12 jtb [    0.744120] scsi5 : ahci
Oct 24 12:07:12 jtb [    0.744564] ata1: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1c900 irq 42
Oct 24 12:07:12 jtb [    0.744568] ata2: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1c980 irq 42
Oct 24 12:07:12 jtb [    0.744569] ata3: DUMMY
Oct 24 12:07:12 jtb [    0.744570] ata4: DUMMY
Oct 24 12:07:12 jtb [    0.744572] ata5: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1cb00 irq 42
Oct 24 12:07:12 jtb [    0.744575] ata6: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1cb80 irq 42
Oct 24 12:07:12 jtb [    1.063351] ata1: SATA link up 1.5 Gbps (SStatus 113
SControl 300)
Oct 24 12:07:12 jtb [    1.068536] ata1.00: ATA-8: SAMSUNG HM250JI, HS100-08,
max UDMA7
Oct 24 12:07:12 jtb [    1.068538] ata1.00: 488397168 sectors, multi 0: LBA48
NCQ (depth 31/32)
Oct 24 12:07:12 jtb [    1.075477] ata1.00: configured for UDMA/133
Oct 24 12:07:12 jtb [    1.406682] ata2: SATA link up 1.5 Gbps (SStatus 113
SControl 300)
Oct 24 12:07:12 jtb [    1.409289] ata2.00: ATAPI: PLDS DVD+/-RW DU-8A2S, 4D12,
max UDMA/100
Oct 24 12:07:12 jtb [    1.412791] ata2.00: configured for UDMA/100
Oct 24 12:07:12 jtb [    1.746681] ata5: SATA link down (SStatus 0 SControl
300)
Oct 24 12:07:12 jtb [    2.080014] ata6: SATA link down (SStatus 0 SControl
300)
Oct 24 12:07:12 jtb [    2.093410] scsi 0:0:0:0: Direct-Access     ATA     SAMSUNG HM250JI  HS10 PQ: 0 ANSI: 5
Oct 24 12:07:12 jtb [    2.093516] sd 0:0:0:0: [sda] 488397168 512-byte
hardware sectors: (250 GB/232 GiB)
Oct 24 12:07:12 jtb [    2.093527] sd 0:0:0:0: [sda] Write Protect is off
Oct 24 12:07:12 jtb [    2.093529] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
Oct 24 12:07:12 jtb [    2.093547] sd 0:0:0:0: [sda] Write cache: enabled, read
cache: enabled, doesn't support DPO or FUA
Oct 24 12:07:12 jtb [    2.093592] sd 0:0:0:0: [sda] 488397168 512-byte
hardware sectors: (250 GB/232 GiB)
Oct 24 12:07:12 jtb [    2.093603] sd 0:0:0:0: [sda] Write Protect is off
Oct 24 12:07:12 jtb [    2.093605] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
Oct 24 12:07:12 jtb [    2.093622] sd 0:0:0:0: [sda] Write cache: enabled, read
cache: enabled, doesn't support DPO or FUA
Oct 24 12:07:12 jtb [    2.093625]  sda: sda1 sda2 sda3

Quoted 8 lines

Oct 24 12:07:12 jtb [    2.132082] sd 0:0:0:0: [sda] Attached SCSI disk
Oct 24 12:07:12 jtb [    2.132157] sd 0:0:0:0: Attached scsi generic sg0 type 0
Oct 24 12:07:12 jtb [   24.136670] scsi 1:0:0:0: timing out command, waited 22s
Oct 24 12:07:12 jtb [   46.246667] scsi 1:0:0:0: timing out command, waited 22s
Oct 24 12:07:12 jtb [   68.356665] scsi 1:0:0:0: timing out command, waited 22s
Oct 24 12:07:12 jtb [   90.466663] scsi 1:0:0:0: timing out command, waited 22s
Oct 24 12:07:12 jtb [  112.576661] scsi 1:0:0:0: timing out command, waited 22s
Oct 24 12:07:12 jtb [  134.686658] scsi 1:0:0:0: timing out command, waited 22s

I think this caused due to my patch that adds the scsi_noretry_cmd check in scsi_decide_disposition. We saw this problem exposed in RHEL testing.

Now scsi_noretry_cmd is returning 0 and that causes us to retry the command until we hit the check:

        disposition = scsi_decide_disposition(cmd);
        if (disposition != SUCCESS &&
            time_before(cmd->jiffies_at_alloc + wait_for, jiffies)) {
                sdev_printk(KERN_ERR, cmd->device,
                            "timing out command, waited %lus\n",
                            wait_for/HZ);
                disposition = SUCCESS;
        }

in scsi_softirq_done so we now see this error message get printed out for the failure.

Is Mike Anderson's patches that removes scsi_noretry_cmd going to be merged? If so that will fix the problem. If not then I will make a different patch.

Mike Christie

2008-10-24 16:46 UTC #9 lore raw

Quoted 112 lines · Mike Christie

Quoted 87 lines · [email protected] wrote:

http://bugzilla.kernel.org/show_bug.cgi?id=11817

           Summary: SCSI: timing out command for dvd drive
           Product: IO/Storage
           Version: 2.5
     KernelVersion: 2.6.28-rc1
          Platform: All
        OS/Version: Linux
              Tree: Mainline
            Status: NEW
          Severity: normal
          Priority: P1
         Component: SCSI
        AssignedTo: [email protected]
        ReportedBy: [email protected]

dmesg:

Oct 24 12:07:12 jtb [    0.743466] Driver 'sd' needs updating - please use
bus_type methods
Oct 24 12:07:12 jtb [    0.743492] Driver 'sr' needs updating - please use
bus_type methods
Oct 24 12:07:12 jtb [    0.743555] ahci 0000:00:1f.2: version 3.0
Oct 24 12:07:12 jtb [    0.743564] ahci 0000:00:1f.2: PCI INT D -> GSI 19
(level, low) -> IRQ 19
Oct 24 12:07:12 jtb [    0.743596] ahci 0000:00:1f.2: irq 42 for MSI/MSI-X
Oct 24 12:07:12 jtb [    0.743666] ahci 0000:00:1f.2: AHCI 0001.0200 32 slots 4
ports 3 Gbps 0x33 impl RAID mode
Oct 24 12:07:12 jtb [    0.743668] ahci 0000:00:1f.2: flags: 64bit ncq sntf
stag pm led clo pmp pio slum part ems
Oct 24 12:07:12 jtb [    0.743673] ahci 0000:00:1f.2: setting latency timer to
64
Oct 24 12:07:12 jtb [    0.743820] scsi0 : ahci
Oct 24 12:07:12 jtb [    0.743899] scsi1 : ahci
Oct 24 12:07:12 jtb [    0.743958] scsi2 : ahci
Oct 24 12:07:12 jtb [    0.744012] scsi3 : ahci
Oct 24 12:07:12 jtb [    0.744066] scsi4 : ahci
Oct 24 12:07:12 jtb [    0.744120] scsi5 : ahci
Oct 24 12:07:12 jtb [    0.744564] ata1: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1c900 irq 42
Oct 24 12:07:12 jtb [    0.744568] ata2: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1c980 irq 42
Oct 24 12:07:12 jtb [    0.744569] ata3: DUMMY
Oct 24 12:07:12 jtb [    0.744570] ata4: DUMMY
Oct 24 12:07:12 jtb [    0.744572] ata5: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1cb00 irq 42
Oct 24 12:07:12 jtb [    0.744575] ata6: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1cb80 irq 42
Oct 24 12:07:12 jtb [    1.063351] ata1: SATA link up 1.5 Gbps (SStatus 113
SControl 300)
Oct 24 12:07:12 jtb [    1.068536] ata1.00: ATA-8: SAMSUNG HM250JI, HS100-08,
max UDMA7
Oct 24 12:07:12 jtb [    1.068538] ata1.00: 488397168 sectors, multi 0: LBA48
NCQ (depth 31/32)
Oct 24 12:07:12 jtb [    1.075477] ata1.00: configured for UDMA/133
Oct 24 12:07:12 jtb [    1.406682] ata2: SATA link up 1.5 Gbps (SStatus 113
SControl 300)
Oct 24 12:07:12 jtb [    1.409289] ata2.00: ATAPI: PLDS DVD+/-RW DU-8A2S, 4D12,
max UDMA/100
Oct 24 12:07:12 jtb [    1.412791] ata2.00: configured for UDMA/100
Oct 24 12:07:12 jtb [    1.746681] ata5: SATA link down (SStatus 0 SControl
300)
Oct 24 12:07:12 jtb [    2.080014] ata6: SATA link down (SStatus 0 SControl
300)
Oct 24 12:07:12 jtb [    2.093410] scsi 0:0:0:0: Direct-Access     ATA     SAMSUNG HM250JI  HS10 PQ: 0 ANSI: 5
Oct 24 12:07:12 jtb [    2.093516] sd 0:0:0:0: [sda] 488397168 512-byte
hardware sectors: (250 GB/232 GiB)
Oct 24 12:07:12 jtb [    2.093527] sd 0:0:0:0: [sda] Write Protect is off
Oct 24 12:07:12 jtb [    2.093529] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
Oct 24 12:07:12 jtb [    2.093547] sd 0:0:0:0: [sda] Write cache: enabled, read
cache: enabled, doesn't support DPO or FUA
Oct 24 12:07:12 jtb [    2.093592] sd 0:0:0:0: [sda] 488397168 512-byte
hardware sectors: (250 GB/232 GiB)
Oct 24 12:07:12 jtb [    2.093603] sd 0:0:0:0: [sda] Write Protect is off
Oct 24 12:07:12 jtb [    2.093605] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
Oct 24 12:07:12 jtb [    2.093622] sd 0:0:0:0: [sda] Write cache: enabled, read
cache: enabled, doesn't support DPO or FUA
Oct 24 12:07:12 jtb [    2.093625]  sda: sda1 sda2 sda3

Quoted 8 lines

Oct 24 12:07:12 jtb [    2.132082] sd 0:0:0:0: [sda] Attached SCSI disk
Oct 24 12:07:12 jtb [    2.132157] sd 0:0:0:0: Attached scsi generic sg0 type 0
Oct 24 12:07:12 jtb [   24.136670] scsi 1:0:0:0: timing out command, waited 22s
Oct 24 12:07:12 jtb [   46.246667] scsi 1:0:0:0: timing out command, waited 22s
Oct 24 12:07:12 jtb [   68.356665] scsi 1:0:0:0: timing out command, waited 22s
Oct 24 12:07:12 jtb [   90.466663] scsi 1:0:0:0: timing out command, waited 22s
Oct 24 12:07:12 jtb [  112.576661] scsi 1:0:0:0: timing out command, waited 22s
Oct 24 12:07:12 jtb [  134.686658] scsi 1:0:0:0: timing out command, waited 22s

I think this caused due to my patch that adds the scsi_noretry_cmd check in scsi_decide_disposition. We saw this problem exposed in RHEL testing.

Now scsi_noretry_cmd is returning 0 and that causes us to retry the command until we hit the check:

        disposition = scsi_decide_disposition(cmd);
        if (disposition != SUCCESS &&
            time_before(cmd->jiffies_at_alloc + wait_for, jiffies)) {
                sdev_printk(KERN_ERR, cmd->device,
                            "timing out command, waited %lus\n",
                            wait_for/HZ);
                disposition = SUCCESS;
        }

Quoted 2 lines

in scsi_softirq_done so we now see this error message get printed out for the failure.

Ignore this. In RHEL it was slightly different problem.

[email protected]

author

2008-10-24 16:45 UTC #10 lore raw

[Bug 11817] SCSI: timing out command for dvd drive

In reply to [email protected]

http://bugzilla.kernel.org/show_bug.cgi?id=11817

------- Comment #7 from [email protected] 2008-10-24 09:45 -------
Reply-To: [email protected]

Quoted 143 lines · Mike Christie

Quoted 120 lines · [email protected] wrote:

http://bugzilla.kernel.org/show_bug.cgi?id=11817

           Summary: SCSI: timing out command for dvd drive
           Product: IO/Storage
           Version: 2.5
     KernelVersion: 2.6.28-rc1
          Platform: All
        OS/Version: Linux
              Tree: Mainline
            Status: NEW
          Severity: normal
          Priority: P1
         Component: SCSI
        AssignedTo: [email protected]
        ReportedBy: [email protected]

dmesg:

Oct 24 12:07:12 jtb [    0.743466] Driver 'sd' needs updating - please 
use
bus_type methods
Oct 24 12:07:12 jtb [    0.743492] Driver 'sr' needs updating - please 
use
bus_type methods
Oct 24 12:07:12 jtb [    0.743555] ahci 0000:00:1f.2: version 3.0
Oct 24 12:07:12 jtb [    0.743564] ahci 0000:00:1f.2: PCI INT D -> GSI 19
(level, low) -> IRQ 19
Oct 24 12:07:12 jtb [    0.743596] ahci 0000:00:1f.2: irq 42 for 
MSI/MSI-X
Oct 24 12:07:12 jtb [    0.743666] ahci 0000:00:1f.2: AHCI 0001.0200 
32 slots 4
ports 3 Gbps 0x33 impl RAID mode
Oct 24 12:07:12 jtb [    0.743668] ahci 0000:00:1f.2: flags: 64bit ncq 
sntf
stag pm led clo pmp pio slum part ems
Oct 24 12:07:12 jtb [    0.743673] ahci 0000:00:1f.2: setting latency 
timer to
64
Oct 24 12:07:12 jtb [    0.743820] scsi0 : ahci
Oct 24 12:07:12 jtb [    0.743899] scsi1 : ahci
Oct 24 12:07:12 jtb [    0.743958] scsi2 : ahci
Oct 24 12:07:12 jtb [    0.744012] scsi3 : ahci
Oct 24 12:07:12 jtb [    0.744066] scsi4 : ahci
Oct 24 12:07:12 jtb [    0.744120] scsi5 : ahci
Oct 24 12:07:12 jtb [    0.744564] ata1: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1c900 irq 42
Oct 24 12:07:12 jtb [    0.744568] ata2: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1c980 irq 42
Oct 24 12:07:12 jtb [    0.744569] ata3: DUMMY
Oct 24 12:07:12 jtb [    0.744570] ata4: DUMMY
Oct 24 12:07:12 jtb [    0.744572] ata5: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1cb00 irq 42
Oct 24 12:07:12 jtb [    0.744575] ata6: SATA max UDMA/133 abar
m2048@0xfed1c800 port 0xfed1cb80 irq 42
Oct 24 12:07:12 jtb [    1.063351] ata1: SATA link up 1.5 Gbps 
(SStatus 113
SControl 300)
Oct 24 12:07:12 jtb [    1.068536] ata1.00: ATA-8: SAMSUNG HM250JI, 
HS100-08,
max UDMA7
Oct 24 12:07:12 jtb [    1.068538] ata1.00: 488397168 sectors, multi 
0: LBA48
NCQ (depth 31/32)
Oct 24 12:07:12 jtb [    1.075477] ata1.00: configured for UDMA/133
Oct 24 12:07:12 jtb [    1.406682] ata2: SATA link up 1.5 Gbps 
(SStatus 113
SControl 300)
Oct 24 12:07:12 jtb [    1.409289] ata2.00: ATAPI: PLDS DVD+/-RW 
DU-8A2S, 4D12,
max UDMA/100
Oct 24 12:07:12 jtb [    1.412791] ata2.00: configured for UDMA/100
Oct 24 12:07:12 jtb [    1.746681] ata5: SATA link down (SStatus 0 
SControl
300)
Oct 24 12:07:12 jtb [    2.080014] ata6: SATA link down (SStatus 0 
SControl
300)
Oct 24 12:07:12 jtb [    2.093410] scsi 0:0:0:0: Direct-Access     
ATA     SAMSUNG HM250JI  HS10 PQ: 0 ANSI: 5
Oct 24 12:07:12 jtb [    2.093516] sd 0:0:0:0: [sda] 488397168 512-byte
hardware sectors: (250 GB/232 GiB)
Oct 24 12:07:12 jtb [    2.093527] sd 0:0:0:0: [sda] Write Protect is off
Oct 24 12:07:12 jtb [    2.093529] sd 0:0:0:0: [sda] Mode Sense: 00 3a 
00 00
Oct 24 12:07:12 jtb [    2.093547] sd 0:0:0:0: [sda] Write cache: 
enabled, read
cache: enabled, doesn't support DPO or FUA
Oct 24 12:07:12 jtb [    2.093592] sd 0:0:0:0: [sda] 488397168 512-byte
hardware sectors: (250 GB/232 GiB)
Oct 24 12:07:12 jtb [    2.093603] sd 0:0:0:0: [sda] Write Protect is off
Oct 24 12:07:12 jtb [    2.093605] sd 0:0:0:0: [sda] Mode Sense: 00 3a 
00 00
Oct 24 12:07:12 jtb [    2.093622] sd 0:0:0:0: [sda] Write cache: 
enabled, read
cache: enabled, doesn't support DPO or FUA
Oct 24 12:07:12 jtb [    2.093625]  sda: sda1 sda2 sda3
Oct 24 12:07:12 jtb [    2.132082] sd 0:0:0:0: [sda] Attached SCSI disk
Oct 24 12:07:12 jtb [    2.132157] sd 0:0:0:0: Attached scsi generic 
sg0 type 0
Oct 24 12:07:12 jtb [   24.136670] scsi 1:0:0:0: timing out command, 
waited 22s
Oct 24 12:07:12 jtb [   46.246667] scsi 1:0:0:0: timing out command, 
waited 22s
Oct 24 12:07:12 jtb [   68.356665] scsi 1:0:0:0: timing out command, 
waited 22s
Oct 24 12:07:12 jtb [   90.466663] scsi 1:0:0:0: timing out command, 
waited 22s
Oct 24 12:07:12 jtb [  112.576661] scsi 1:0:0:0: timing out command, 
waited 22s
Oct 24 12:07:12 jtb [  134.686658] scsi 1:0:0:0: timing out command,

Quoted 1 line

waited 22s

I think this caused due to my patch that adds the scsi_noretry_cmd check in scsi_decide_disposition. We saw this problem exposed in RHEL testing.

Now scsi_noretry_cmd is returning 0 and that causes us to retry the command until we hit the check:

        disposition = scsi_decide_disposition(cmd);
        if (disposition != SUCCESS &&
            time_before(cmd->jiffies_at_alloc + wait_for, jiffies)) {
                sdev_printk(KERN_ERR, cmd->device,
                            "timing out command, waited %lus\n",
                            wait_for/HZ);
                disposition = SUCCESS;
        }

Quoted 3 lines

in scsi_softirq_done so we now see this error message get printed out for the failure.

Ignore this. In RHEL it was slightly different problem.

Signature · 3 lines

Configure bugmail: http://bugzilla.kernel.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[email protected]

author

2008-10-25 11:02 UTC #11 lore raw

[Bug 11817] SCSI: timing out command for dvd drive

In reply to [email protected]

http://bugzilla.kernel.org/show_bug.cgi?id=11817

[email protected] changed:

What |Removed |Added
----------------------------------------------------------------------------

             Status|NEW                         |CLOSED
         Resolution|                            |PATCH_ALREADY_AVAILABLE

------- Comment #8 from [email protected] 2008-10-25 04:01 ------- (In reply to comment #5)

Quoted 3 lines

James, you are correct, this is the same problem. Applying the patch at
http://lkml.org/lkml/2008/10/24/102
made my system boot again. Thanks!

same here. I close this bug - it's already included in the latest snapshot (Commit: e013e13bf605b9e6b702adffbe2853cfc60e7806)

Signature · 3 lines

Configure bugmail: http://bugzilla.kernel.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.