* RE: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) [not found] ` <20110628095723.GC3386@htj.dyndns.org> @ 2011-06-30 17:53 ` Derry Bryson 2011-07-12 15:01 ` tj 0 siblings, 1 reply; 35+ messages in thread From: Derry Bryson @ 2011-06-30 17:53 UTC (permalink / raw) To: tj@kernel.org; +Cc: linux-ide@vger.kernel.org Thanks for the quick response. > -----Original Message----- > From: Tejun Heo [mailto:htejun@gmail.com] On Behalf Of tj@kernel.org > Sent: Tuesday, June 28, 2011 2:57 AM > To: Derry Bryson > Subject: Re: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) > > Hello, > > Can you please cc linux-ide@vger.kernel.org when replying? > > On Mon, Jun 27, 2011 at 06:02:23PM +0000, Derry Bryson wrote: > > I found this thread from around 2.5 years ago describing the same > > problem I am having in only in kernel 2.6.38 (ubuntu 11.04): > > > > http://marc.info/?l=linux-ide&m=122373892631645&w=2 > > > > The thread seemed to stop with you sending another patch to be > > tested and nothing more after that. Was this ever fixed? > > Hmm... it seems like the last test patch didn't get replied and I > forgot about it. Can you please provide the following information? > > * Detailed sequence of actions to trigger the problem. > Hardware: Silicon Image 3124 PCI card in computer connected eSATA to an external drive enclosure with a Silicon Image 3726 port multiplier chip with 5 removable drive trays (http://high-rely.com/HR3/includes/HighRely/5BayMT/5BayMT.php) containing 5 various hard drives. To create the problem I simply turn off a drive bay and wait for it to be removed from the system. Then turn the drive bay back on and usually the drive will not reconnect without several cycles of turning it off and on. Note the drives always seem to come up fine on boot with the external drive bays already powered on and if I power cycle the drive bays with the computer on and booted. I have included info from kern.log below showing turning the bay on and off before and after I patched the kernel. I first applied the patch from your previous email and changed the second timing value to 1000 and that makes it work. It also works if you leave the timing values alone and up the retries (i.e ATA_EH_PMP_LINK_TRIES) from 3 to 5. It seems to me the drives are taking a long (relatively) time to spin up and either way all we are doing is giving it more time to spin up. Is there some way to know it is spinning up and wait for that rather than just trying to reset the controller over and over? Also I notice from the kernel log that the 'hotplugged' flag is only set the first time it does the hard reset and is then cleared. If this didn't get cleared it may work that way as well. All of this only fixes the problem until an slower drive comes out. >From the SMART info on the drives for the WD 3TB that fails the spin up value was 188 vs. a Seagate 160GB that was 87. I believe these values are in milliseconds so we can see that the drive that fails takes much longer to spin up. > * dmesg output after hotplug failure w/ CONFIG_PRINTK_TIME set > including boot messages. > Here is dmesg from boot (kernel 2.6.32): [ 0.000000] Initializing cgroup subsys cpuset [ 0.000000] Initializing cgroup subsys cpu [ 0.000000] Linux version 2.6.32-21-generic (buildd@yellow) (gcc version 4.4.3 (Ubuntu 4.4.3-4ubuntu5) ) #32-Ubuntu SMP Fri Apr 16 08:09:38 UTC 2010 (Ubuntu 2.6.32-21.32-generic 2.6.32.11+drm33.2) [ 0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-2.6.32-21-generic root=UUID=4091bfa7-5a4a-45c4-8b6f-a364fdce5a47 ro quiet nomodeset text [ 0.000000] KERNEL supported cpus: [ 0.000000] Intel GenuineIntel [ 0.000000] AMD AuthenticAMD [ 0.000000] Centaur CentaurHauls [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: 0000000000000000 - 000000000008f000 (usable) [ 0.000000] BIOS-e820: 000000000008f000 - 0000000000090000 (reserved) [ 0.000000] BIOS-e820: 0000000000090000 - 000000000009c800 (usable) [ 0.000000] BIOS-e820: 000000000009c800 - 00000000000a0000 (reserved) [ 0.000000] BIOS-e820: 00000000000e0000 - 0000000000100000 (reserved) [ 0.000000] BIOS-e820: 0000000000100000 - 000000003ee98000 (usable) [ 0.000000] BIOS-e820: 000000003ee98000 - 000000003eebf000 (reserved) [ 0.000000] BIOS-e820: 000000003eebf000 - 000000003ef47000 (usable) [ 0.000000] BIOS-e820: 000000003ef47000 - 000000003efbf000 (ACPI NVS) [ 0.000000] BIOS-e820: 000000003efbf000 - 000000003eff1000 (usable) [ 0.000000] BIOS-e820: 000000003eff1000 - 000000003efff000 (ACPI data) [ 0.000000] BIOS-e820: 000000003efff000 - 000000003f000000 (usable) [ 0.000000] BIOS-e820: 000000003f000000 - 0000000040000000 (reserved) [ 0.000000] BIOS-e820: 00000000f8000000 - 00000000fc000000 (reserved) [ 0.000000] BIOS-e820: 00000000fff00000 - 0000000100000000 (reserved) [ 0.000000] DMI 2.5 present. [ 0.000000] last_pfn = 0x3f000 max_arch_pfn = 0x400000000 [ 0.000000] MTRR default type: uncachable [ 0.000000] MTRR fixed ranges enabled: [ 0.000000] 00000-9FFFF write-back [ 0.000000] A0000-BFFFF uncachable [ 0.000000] C0000-DFFFF write-protect [ 0.000000] E0000-FFFFF uncachable [ 0.000000] MTRR variable ranges enabled: [ 0.000000] 0 base 000000000 mask FC0000000 write-back [ 0.000000] 1 base 03F000000 mask FFF000000 uncachable [ 0.000000] 2 base 0FFFF0000 mask FFFFF0000 write-protect [ 0.000000] 3 base 0FFF10000 mask FFFFF0000 write-protect [ 0.000000] 4 base 0FFF20000 mask FFFFF0000 write-protect [ 0.000000] 5 disabled [ 0.000000] 6 disabled [ 0.000000] x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106 [ 0.000000] e820 update range: 0000000000001000 - 0000000000006000 (usable) ==> (reserved) [ 0.000000] Scanning 1 areas for low memory corruption [ 0.000000] modified physical RAM map: [ 0.000000] modified: 0000000000000000 - 0000000000001000 (usable) [ 0.000000] modified: 0000000000001000 - 0000000000006000 (reserved) [ 0.000000] modified: 0000000000006000 - 000000000008f000 (usable) [ 0.000000] modified: 000000000008f000 - 0000000000090000 (reserved) [ 0.000000] modified: 0000000000090000 - 000000000009c800 (usable) [ 0.000000] modified: 000000000009c800 - 00000000000a0000 (reserved) [ 0.000000] modified: 00000000000e0000 - 0000000000100000 (reserved) [ 0.000000] modified: 0000000000100000 - 000000003ee98000 (usable) [ 0.000000] modified: 000000003ee98000 - 000000003eebf000 (reserved) [ 0.000000] modified: 000000003eebf000 - 000000003ef47000 (usable) [ 0.000000] modified: 000000003ef47000 - 000000003efbf000 (ACPI NVS) [ 0.000000] modified: 000000003efbf000 - 000000003eff1000 (usable) [ 0.000000] modified: 000000003eff1000 - 000000003efff000 (ACPI data) [ 0.000000] modified: 000000003efff000 - 000000003f000000 (usable) [ 0.000000] modified: 000000003f000000 - 0000000040000000 (reserved) [ 0.000000] modified: 00000000f8000000 - 00000000fc000000 (reserved) [ 0.000000] modified: 00000000fff00000 - 0000000100000000 (reserved) [ 0.000000] initial memory mapped : 0 - 20000000 [ 0.000000] init_memory_mapping: 0000000000000000-000000003f000000 [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] 0000000000 - 003f000000 page 2M [ 0.000000] kernel direct mapping tables up to 3f000000 @ 8000-a000 [ 0.000000] RAMDISK: 2eb40000 - 2f331b3e [ 0.000000] ACPI: RSDP 00000000000f2060 00024 (v02 INTEL ) [ 0.000000] ACPI: XSDT 000000003effe120 0004C (v01 INTEL D525MW 0000004E 01000013) [ 0.000000] ACPI: FACP 000000003effd000 000F4 (v03 INTEL D525MW 0000004E MSFT 0100000D) [ 0.000000] ACPI: DSDT 000000003eff9000 03796 (v01 INTEL D525MW 0000004E MSFT 0100000D) [ 0.000000] ACPI: FACS 000000003ef87000 00040 [ 0.000000] ACPI: APIC 000000003eff8000 00084 (v02 INTEL D525MW 0000004E MSFT 0100000D) [ 0.000000] ACPI: MCFG 000000003eff7000 0003C (v01 INTEL D525MW 0000004E MSFT 0100000D) [ 0.000000] ACPI: HPET 000000003eff6000 00038 (v01 INTEL D525MW 0000004E MSFT 0100000D) [ 0.000000] ACPI: SSDT 000000003eff2000 0377C (v01 INTEL D525MW 0000004E MSFT 0100000D) [ 0.000000] ACPI: Local APIC address 0xfee00000 [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at 0000000000000000-000000003f000000 [ 0.000000] Bootmem setup node 0 0000000000000000-000000003f000000 [ 0.000000] NODE_DATA [0000000000008000 - 000000000000cfff] [ 0.000000] bootmap [000000000000d000 - 0000000000014dff] pages 8 [ 0.000000] (6 early reservations) ==> bootmem [0000000000 - 003f000000] [ 0.000000] #0 [0000000000 - 0000001000] BIOS data page ==> [0000000000 - 0000001000] [ 0.000000] #1 [0000006000 - 0000008000] TRAMPOLINE ==> [0000006000 - 0000008000] [ 0.000000] #2 [0001000000 - 0001a29e64] TEXT DATA BSS ==> [0001000000 - 0001a29e64] [ 0.000000] #3 [002eb40000 - 002f331b3e] RAMDISK ==> [002eb40000 - 002f331b3e] [ 0.000000] #4 [000009c800 - 0000100000] BIOS reserved ==> [000009c800 - 0000100000] [ 0.000000] #5 [0001a2a000 - 0001a2a19e] BRK ==> [0001a2a000 - 0001a2a19e] [ 0.000000] found SMP MP-table at [ffff8800000fbe70] fbe70 [ 0.000000] [ffffea0000000000-ffffea0000dfffff] PMD -> [ffff880002000000-ffff880002dfffff] on node 0 [ 0.000000] Zone PFN ranges: [ 0.000000] DMA 0x00000000 -> 0x00001000 [ 0.000000] DMA32 0x00001000 -> 0x00100000 [ 0.000000] Normal 0x00100000 -> 0x00100000 [ 0.000000] Movable zone start PFN for each node [ 0.000000] early_node_map[7] active PFN ranges [ 0.000000] 0: 0x00000000 -> 0x00000001 [ 0.000000] 0: 0x00000006 -> 0x0000008f [ 0.000000] 0: 0x00000090 -> 0x0000009c [ 0.000000] 0: 0x00000100 -> 0x0003ee98 [ 0.000000] 0: 0x0003eebf -> 0x0003ef47 [ 0.000000] 0: 0x0003efbf -> 0x0003eff1 [ 0.000000] 0: 0x0003efff -> 0x0003f000 [ 0.000000] On node 0 totalpages: 257769 [ 0.000000] DMA zone: 56 pages used for memmap [ 0.000000] DMA zone: 102 pages reserved [ 0.000000] DMA zone: 3832 pages, LIFO batch:0 [ 0.000000] DMA32 zone: 3472 pages used for memmap [ 0.000000] DMA32 zone: 250307 pages, LIFO batch:31 [ 0.000000] ACPI: PM-Timer IO Port: 0x408 [ 0.000000] ACPI: Local APIC address 0xfee00000 [ 0.000000] ACPI: LAPIC (acpi_id[0x01] lapic_id[0x00] enabled) [ 0.000000] ACPI: LAPIC (acpi_id[0x02] lapic_id[0x01] enabled) [ 0.000000] ACPI: LAPIC (acpi_id[0x03] lapic_id[0x02] enabled) [ 0.000000] ACPI: LAPIC (acpi_id[0x04] lapic_id[0x03] enabled) [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0x01] high level lint[0x1]) [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0x02] high level lint[0x1]) [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0x03] high level lint[0x1]) [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0x04] high level lint[0x1]) [ 0.000000] ACPI: IOAPIC (id[0x08] address[0xfec00000] gsi_base[0]) [ 0.000000] IOAPIC[0]: apic_id 8, version 32, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: IRQ0 used by override. [ 0.000000] ACPI: IRQ2 used by override. [ 0.000000] ACPI: IRQ9 used by override. [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] SMP: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] nr_irqs_gsi: 24 [ 0.000000] PM: Registered nosave memory: 0000000000001000 - 0000000000006000 [ 0.000000] PM: Registered nosave memory: 000000000008f000 - 0000000000090000 [ 0.000000] PM: Registered nosave memory: 000000000009c000 - 000000000009d000 [ 0.000000] PM: Registered nosave memory: 000000000009d000 - 00000000000a0000 [ 0.000000] PM: Registered nosave memory: 00000000000a0000 - 00000000000e0000 [ 0.000000] PM: Registered nosave memory: 00000000000e0000 - 0000000000100000 [ 0.000000] PM: Registered nosave memory: 000000003ee98000 - 000000003eebf000 [ 0.000000] PM: Registered nosave memory: 000000003ef47000 - 000000003efbf000 [ 0.000000] PM: Registered nosave memory: 000000003eff1000 - 000000003efff000 [ 0.000000] Allocating PCI resources starting at 40000000 (gap: 40000000:b8000000) [ 0.000000] Booting paravirtualized kernel on bare hardware [ 0.000000] NR_CPUS:64 nr_cpumask_bits:64 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] PERCPU: Embedded 30 pages/cpu @ffff880001c00000 s91544 r8192 d23144 u524288 [ 0.000000] pcpu-alloc: s91544 r8192 d23144 u524288 alloc=1*2097152 [ 0.000000] pcpu-alloc: [0] 0 1 2 3 [ 0.000000] Built 1 zonelists in Node order, mobility grouping on. Total pages: 254139 [ 0.000000] Policy zone: DMA32 [ 0.000000] Kernel command line: BOOT_IMAGE=/boot/vmlinuz-2.6.32-21-generic root=UUID=4091bfa7-5a4a-45c4-8b6f-a364fdce5a47 ro quiet nomodeset text [ 0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes) [ 0.000000] Initializing CPU#0 [ 0.000000] Checking aperture... [ 0.000000] No AGP bridge found [ 0.000000] Calgary: detecting Calgary via BIOS EBDA area [ 0.000000] Calgary: Unable to locate Rio Grande table in EBDA - bailing! [ 0.000000] Memory: 997568k/1032192k available (5409k kernel code, 1116k absent, 33508k reserved, 2976k data, 876k init) [ 0.000000] SLUB: Genslabs=14, HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] Hierarchical RCU implementation. [ 0.000000] NR_IRQS:4352 nr_irqs:440 [ 0.000000] Extended CMOS year: 2000 [ 0.000000] Console: colour VGA+ 80x25 [ 0.000000] console [tty0] enabled [ 0.000000] allocated 10485760 bytes of page_cgroup [ 0.000000] please try 'cgroup_disable=memory' option if you don't want memory cgroups [ 0.000000] hpet clockevent registered [ 0.000000] HPET: 3 timers in total, 0 timers will be used for per-cpu timer [ 0.000000] Fast TSC calibration using PIT [ 0.000000] Detected 1799.930 MHz processor. [ 0.010012] Calibrating delay loop (skipped), value calculated using timer frequency.. 3599.86 BogoMIPS (lpj=17999300) [ 0.010075] Security Framework initialized [ 0.010116] AppArmor: AppArmor initialized [ 0.010389] Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes) [ 0.011295] Inode-cache hash table entries: 65536 (order: 7, 524288 bytes) [ 0.011705] Mount-cache hash table entries: 256 [ 0.012011] Initializing cgroup subsys ns [ 0.012022] Initializing cgroup subsys cpuacct [ 0.012032] Initializing cgroup subsys memory [ 0.012048] Initializing cgroup subsys devices [ 0.012054] Initializing cgroup subsys freezer [ 0.012060] Initializing cgroup subsys net_cls [ 0.012102] CPU: L1 I cache: 32K, L1 D cache: 24K [ 0.012109] CPU: L2 cache: 512K [ 0.012116] CPU 0/0x0 -> Node 0 [ 0.012120] CPU: Physical Processor ID: 0 [ 0.012125] CPU: Processor Core ID: 0 [ 0.012131] mce: CPU supports 5 MCE banks [ 0.012145] CPU0: Thermal monitoring enabled (TM1) [ 0.012154] using mwait in idle threads. [ 0.012159] Performance Events: Atom events, Intel PMU driver. [ 0.012172] ... version: 3 [ 0.012176] ... bit width: 40 [ 0.012180] ... generic registers: 2 [ 0.012185] ... value mask: 000000ffffffffff [ 0.012190] ... max period: 000000007fffffff [ 0.012194] ... fixed-purpose events: 3 [ 0.012199] ... event mask: 0000000700000003 [ 0.020473] ACPI: Core revision 20090903 [ 0.045502] ftrace: converting mcount calls to 0f 1f 44 00 00 [ 0.045513] ftrace: allocating 22518 entries in 89 pages [ 0.050117] Setting APIC routing to flat [ 0.050511] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.159362] CPU0: Intel(R) Atom(TM) CPU D525 @ 1.80GHz stepping 0a [ 0.160000] Booting processor 1 APIC 0x1 ip 0x6000 [ 0.020000] Initializing CPU#1 [ 0.020000] CPU: L1 I cache: 32K, L1 D cache: 24K [ 0.020000] CPU: L2 cache: 512K [ 0.020000] CPU 1/0x1 -> Node 0 [ 0.020000] CPU: Physical Processor ID: 0 [ 0.020000] CPU: Processor Core ID: 0 [ 0.020000] CPU1: Thermal monitoring enabled (TM1) [ 0.310094] CPU1: Intel(R) Atom(TM) CPU D525 @ 1.80GHz stepping 0a [ 0.310110] checking TSC synchronization [CPU#0 -> CPU#1]: passed. [ 0.320239] Booting processor 2 APIC 0x2 ip 0x6000 [ 0.020000] Initializing CPU#2 [ 0.020000] CPU: L1 I cache: 32K, L1 D cache: 24K [ 0.020000] CPU: L2 cache: 512K [ 0.020000] CPU 2/0x2 -> Node 0 [ 0.020000] CPU: Physical Processor ID: 0 [ 0.020000] CPU: Processor Core ID: 1 [ 0.020000] CPU2: Thermal monitoring enabled (TM1) [ 0.480106] CPU2: Intel(R) Atom(TM) CPU D525 @ 1.80GHz stepping 0a [ 0.480119] checking TSC synchronization [CPU#0 -> CPU#2]: passed. [ 0.490180] Booting processor 3 APIC 0x3 ip 0x6000 [ 0.020000] Initializing CPU#3 [ 0.020000] CPU: L1 I cache: 32K, L1 D cache: 24K [ 0.020000] CPU: L2 cache: 512K [ 0.020000] CPU 3/0x3 -> Node 0 [ 0.020000] CPU: Physical Processor ID: 0 [ 0.020000] CPU: Processor Core ID: 1 [ 0.020000] CPU3: Thermal monitoring enabled (TM1) [ 0.650071] CPU3: Intel(R) Atom(TM) CPU D525 @ 1.80GHz stepping 0a [ 0.650086] checking TSC synchronization [CPU#0 -> CPU#3]: passed. [ 0.660026] Brought up 4 CPUs [ 0.660032] Total of 4 processors activated (14400.32 BogoMIPS). [ 0.661297] CPU0 attaching sched-domain: [ 0.661306] domain 0: span 0-1 level SIBLING [ 0.661311] groups: 0 (cpu_power = 589) 1 (cpu_power = 589) [ 0.661323] domain 1: span 0-1 level MC [ 0.661328] groups: 0-1 (cpu_power = 1178) [ 0.661337] domain 2: span 0-3 level CPU [ 0.661342] groups: 0-1 (cpu_power = 1178) 2-3 (cpu_power = 1178) [ 0.661358] CPU1 attaching sched-domain: [ 0.661362] domain 0: span 0-1 level SIBLING [ 0.661367] groups: 1 (cpu_power = 589) 0 (cpu_power = 589) [ 0.661378] domain 1: span 0-1 level MC [ 0.661383] groups: 0-1 (cpu_power = 1178) [ 0.661391] domain 2: span 0-3 level CPU [ 0.661396] groups: 0-1 (cpu_power = 1178) 2-3 (cpu_power = 1178) [ 0.661409] CPU2 attaching sched-domain: [ 0.661413] domain 0: span 2-3 level SIBLING [ 0.661418] groups: 2 (cpu_power = 589) 3 (cpu_power = 589) [ 0.661429] domain 1: span 2-3 level MC [ 0.661434] groups: 2-3 (cpu_power = 1178) [ 0.661442] domain 2: span 0-3 level CPU [ 0.661447] groups: 2-3 (cpu_power = 1178) 0-1 (cpu_power = 1178) [ 0.661459] CPU3 attaching sched-domain: [ 0.661463] domain 0: span 2-3 level SIBLING [ 0.661468] groups: 3 (cpu_power = 589) 2 (cpu_power = 589) [ 0.661479] domain 1: span 2-3 level MC [ 0.661484] groups: 2-3 (cpu_power = 1178) [ 0.661492] domain 2: span 0-3 level CPU [ 0.661497] groups: 2-3 (cpu_power = 1178) 0-1 (cpu_power = 1178) [ 0.661887] devtmpfs: initialized [ 0.661887] regulator: core version 0.5 [ 0.661887] Time: 16:26:02 Date: 06/30/11 [ 0.661887] NET: Registered protocol family 16 [ 0.661887] Trying to unpack rootfs image as initramfs... [ 0.661887] ACPI FADT declares the system doesn't support PCIe ASPM, so disable it [ 0.661887] ACPI: bus type pci registered [ 0.661887] PCI: MCFG configuration 0: base f8000000 segment 0 buses 0 - 63 [ 0.661887] PCI: MCFG area at f8000000 reserved in E820 [ 0.665227] PCI: Using MMCONFIG at f8000000 - fbffffff [ 0.665231] PCI: Using configuration type 1 for base access [ 0.670113] bio: create slab <bio-0> at 0 [ 0.671192] ACPI: EC: Look up EC in DSDT [ 0.683502] ACPI: BIOS _OSI(Linux) query ignored [ 0.684727] ACPI: Interpreter enabled [ 0.684737] ACPI: (supports S0 S1 S3 S4 S5) [ 0.684793] ACPI: Using IOAPIC for interrupt routing [ 0.693989] ACPI: No dock devices found. [ 0.694388] ACPI: PCI Root Bridge [PCI0] (0000:00) [ 0.694532] pci 0000:00:02.0: reg 10 32bit mmio: [0xf0300000-0xf037ffff] [ 0.694542] pci 0000:00:02.0: reg 14 io port: [0x30c0-0x30c7] [ 0.694550] pci 0000:00:02.0: reg 18 32bit mmio pref: [0xe0000000-0xefffffff] [ 0.694558] pci 0000:00:02.0: reg 1c 32bit mmio: [0xf0200000-0xf02fffff] [ 0.694687] pci 0000:00:1b.0: reg 10 64bit mmio: [0xf0380000-0xf0383fff] [ 0.694755] pci 0000:00:1b.0: PME# supported from D0 D3hot D3cold [ 0.694764] pci 0000:00:1b.0: PME# disabled [ 0.694872] pci 0000:00:1c.0: PME# supported from D0 D3hot D3cold [ 0.694880] pci 0000:00:1c.0: PME# disabled [ 0.694980] pci 0000:00:1c.1: PME# supported from D0 D3hot D3cold [ 0.694987] pci 0000:00:1c.1: PME# disabled [ 0.695090] pci 0000:00:1c.2: PME# supported from D0 D3hot D3cold [ 0.695097] pci 0000:00:1c.2: PME# disabled [ 0.695195] pci 0000:00:1c.3: PME# supported from D0 D3hot D3cold [ 0.695203] pci 0000:00:1c.3: PME# disabled [ 0.695291] pci 0000:00:1d.0: reg 20 io port: [0x3080-0x309f] [ 0.695372] pci 0000:00:1d.1: reg 20 io port: [0x3060-0x307f] [ 0.695448] pci 0000:00:1d.2: reg 20 io port: [0x3040-0x305f] [ 0.695547] pci 0000:00:1d.3: reg 20 io port: [0x3020-0x303f] [ 0.695641] pci 0000:00:1d.7: reg 10 32bit mmio: [0xf0384400-0xf03847ff] [ 0.695715] pci 0000:00:1d.7: PME# supported from D0 D3hot D3cold [ 0.695723] pci 0000:00:1d.7: PME# disabled [ 0.695973] pci 0000:00:1f.2: reg 10 io port: [0x30b8-0x30bf] [ 0.695984] pci 0000:00:1f.2: reg 14 io port: [0x30cc-0x30cf] [ 0.695995] pci 0000:00:1f.2: reg 18 io port: [0x30b0-0x30b7] [ 0.696005] pci 0000:00:1f.2: reg 1c io port: [0x30c8-0x30cb] [ 0.696016] pci 0000:00:1f.2: reg 20 io port: [0x30a0-0x30af] [ 0.696027] pci 0000:00:1f.2: reg 24 32bit mmio: [0xf0384000-0xf03843ff] [ 0.696067] pci 0000:00:1f.2: PME# supported from D3hot [ 0.696073] pci 0000:00:1f.2: PME# disabled [ 0.696142] pci 0000:00:1f.3: reg 20 io port: [0x3000-0x301f] [ 0.696252] pci 0000:01:00.0: reg 10 io port: [0x2000-0x20ff] [ 0.696283] pci 0000:01:00.0: reg 18 64bit mmio pref: [0xf0004000-0xf0004fff] [ 0.696305] pci 0000:01:00.0: reg 20 64bit mmio pref: [0xf0000000-0xf0003fff] [ 0.696370] pci 0000:01:00.0: supports D1 D2 [ 0.696375] pci 0000:01:00.0: PME# supported from D0 D1 D2 D3hot D3cold [ 0.696384] pci 0000:01:00.0: PME# disabled [ 0.696489] pci 0000:00:1c.0: bridge io port: [0x2000-0x2fff] [ 0.696503] pci 0000:00:1c.0: bridge 64bit mmio pref: [0xf0000000-0xf00fffff] [ 0.696817] pci 0000:05:00.0: reg 10 64bit mmio: [0xf0108000-0xf010807f] [ 0.696836] pci 0000:05:00.0: reg 18 64bit mmio: [0xf0100000-0xf0107fff] [ 0.696848] pci 0000:05:00.0: reg 20 io port: [0x1000-0x100f] [ 0.696867] pci 0000:05:00.0: reg 30 32bit mmio pref: [0xfff80000-0xffffffff] [ 0.696905] pci 0000:05:00.0: supports D1 D2 [ 0.696982] pci 0000:00:1e.0: transparent bridge [ 0.696990] pci 0000:00:1e.0: bridge io port: [0x1000-0x1fff] [ 0.696998] pci 0000:00:1e.0: bridge 32bit mmio: [0xf0100000-0xf01fffff] [ 0.697043] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT] [ 0.697404] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.P32_._PRT] [ 0.697631] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PEX0._PRT] [ 0.697781] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PEX1._PRT] [ 0.697931] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PEX2._PRT] [ 0.698081] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PEX3._PRT] [ 0.707426] ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 5 7 9 10 *11 12) [ 0.707661] ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 5 7 9 10 11 12) *0, disabled. [ 0.707893] ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 5 7 *9 10 11 12) [ 0.708125] ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 5 7 9 10 *11 12) [ 0.708353] ACPI: PCI Interrupt Link [LNKE] (IRQs 3 4 5 7 9 *10 11 12) [ 0.708584] ACPI: PCI Interrupt Link [LNKF] (IRQs 3 4 5 7 9 10 11 12) *0, disabled. [ 0.708813] ACPI: PCI Interrupt Link [LNKG] (IRQs 3 4 5 7 *9 10 11 12) [ 0.709042] ACPI: PCI Interrupt Link [LNKH] (IRQs 3 4 5 7 9 *10 11 12) [ 0.709286] vgaarb: device added: PCI:0000:00:02.0,decodes=io+mem,owns=io+mem,locks=none [ 0.709311] vgaarb: loaded [ 0.709566] SCSI subsystem initialized [ 0.709664] libata version 3.00 loaded. [ 0.710080] usbcore: registered new interface driver usbfs [ 0.710115] usbcore: registered new interface driver hub [ 0.710163] usbcore: registered new device driver usb [ 0.710181] ACPI: WMI: Mapper loaded [ 0.710181] PCI: Using ACPI for IRQ routing [ 0.710424] NetLabel: Initializing [ 0.710429] NetLabel: domain hash size = 128 [ 0.710433] NetLabel: protocols = UNLABELED CIPSOv4 [ 0.710459] NetLabel: unlabeled traffic allowed by default [ 0.710557] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.710568] hpet0: 3 comparators, 64-bit 14.318180 MHz counter [ 0.740051] Switching to clocksource tsc [ 0.745755] AppArmor: AppArmor Filesystem Enabled [ 0.745810] pnp: PnP ACPI init [ 0.745855] ACPI: bus type pnp registered [ 0.751957] pnp: PnP ACPI: found 13 devices [ 0.751965] ACPI: ACPI bus type pnp unregistered [ 0.751999] system 00:01: iomem range 0xf8000000-0xfbffffff has been reserved [ 0.752009] system 00:01: iomem range 0xfed14000-0xfed17fff has been reserved [ 0.752019] system 00:01: iomem range 0xfed18000-0xfed18fff has been reserved [ 0.752028] system 00:01: iomem range 0xfed19000-0xfed19fff has been reserved [ 0.752038] system 00:01: iomem range 0xfed1c000-0xfed1ffff has been reserved [ 0.752047] system 00:01: iomem range 0xc0000-0xdffff has been reserved [ 0.752056] system 00:01: iomem range 0xe0000-0xfffff could not be reserved [ 0.752066] system 00:01: iomem range 0xfff00000-0xffffffff has been reserved [ 0.752089] system 00:06: ioport range 0x500-0x53f has been reserved [ 0.752098] system 00:06: ioport range 0x400-0x47f has been reserved [ 0.752107] system 00:06: ioport range 0x680-0x6ff has been reserved [ 0.752116] system 00:06: ioport range 0x295-0x296 has been reserved [ 0.757264] pci 0000:05:00.0: BAR 6: address space collision on of device [0xfff80000-0xffffffff] [ 0.757372] pci 0000:00:1c.0: PCI bridge, secondary bus 0000:01 [ 0.757381] pci 0000:00:1c.0: IO window: 0x2000-0x2fff [ 0.757393] pci 0000:00:1c.0: MEM window: 0x40000000-0x403fffff [ 0.757404] pci 0000:00:1c.0: PREFETCH window: 0x000000f0000000-0x000000f00fffff [ 0.757418] pci 0000:00:1c.1: PCI bridge, secondary bus 0000:02 [ 0.757426] pci 0000:00:1c.1: IO window: 0x4000-0x4fff [ 0.757438] pci 0000:00:1c.1: MEM window: 0x40400000-0x405fffff [ 0.757449] pci 0000:00:1c.1: PREFETCH window: 0x00000040600000-0x000000407fffff [ 0.757462] pci 0000:00:1c.2: PCI bridge, secondary bus 0000:03 [ 0.757471] pci 0000:00:1c.2: IO window: 0x5000-0x5fff [ 0.757482] pci 0000:00:1c.2: MEM window: 0x40800000-0x409fffff [ 0.757493] pci 0000:00:1c.2: PREFETCH window: 0x00000040a00000-0x00000040bfffff [ 0.757507] pci 0000:00:1c.3: PCI bridge, secondary bus 0000:04 [ 0.757515] pci 0000:00:1c.3: IO window: 0x6000-0x6fff [ 0.757526] pci 0000:00:1c.3: MEM window: 0x40c00000-0x40dfffff [ 0.757537] pci 0000:00:1c.3: PREFETCH window: 0x00000040e00000-0x00000040ffffff [ 0.757554] pci 0000:00:1e.0: PCI bridge, secondary bus 0000:05 [ 0.757563] pci 0000:00:1e.0: IO window: 0x1000-0x1fff [ 0.757575] pci 0000:00:1e.0: MEM window: 0xf0100000-0xf01fffff [ 0.757587] pci 0000:00:1e.0: PREFETCH window: 0x41000000-0x410fffff [ 0.757624] alloc irq_desc for 17 on node -1 [ 0.757631] alloc kstat_irqs on node -1 [ 0.757649] pci 0000:00:1c.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17 [ 0.757663] pci 0000:00:1c.0: setting latency timer to 64 [ 0.757683] pci 0000:00:1c.1: enabling device (0000 -> 0003) [ 0.757694] alloc irq_desc for 16 on node -1 [ 0.757700] alloc kstat_irqs on node -1 [ 0.757713] pci 0000:00:1c.1: PCI INT B -> GSI 16 (level, low) -> IRQ 16 [ 0.757727] pci 0000:00:1c.1: setting latency timer to 64 [ 0.757747] pci 0000:00:1c.2: enabling device (0000 -> 0003) [ 0.757757] alloc irq_desc for 18 on node -1 [ 0.757763] alloc kstat_irqs on node -1 [ 0.757775] pci 0000:00:1c.2: PCI INT C -> GSI 18 (level, low) -> IRQ 18 [ 0.757787] pci 0000:00:1c.2: setting latency timer to 64 [ 0.757804] pci 0000:00:1c.3: enabling device (0000 -> 0003) [ 0.757814] alloc irq_desc for 19 on node -1 [ 0.757820] alloc kstat_irqs on node -1 [ 0.757830] pci 0000:00:1c.3: PCI INT D -> GSI 19 (level, low) -> IRQ 19 [ 0.757843] pci 0000:00:1c.3: setting latency timer to 64 [ 0.757858] pci 0000:00:1e.0: setting latency timer to 64 [ 0.757869] pci_bus 0000:00: resource 0 io: [0x00-0xffff] [ 0.757877] pci_bus 0000:00: resource 1 mem: [0x000000-0xffffffffffffffff] [ 0.757886] pci_bus 0000:01: resource 0 io: [0x2000-0x2fff] [ 0.757893] pci_bus 0000:01: resource 1 mem: [0x40000000-0x403fffff] [ 0.757901] pci_bus 0000:01: resource 2 pref mem [0xf0000000-0xf00fffff] [ 0.757910] pci_bus 0000:02: resource 0 io: [0x4000-0x4fff] [ 0.757917] pci_bus 0000:02: resource 1 mem: [0x40400000-0x405fffff] [ 0.757925] pci_bus 0000:02: resource 2 pref mem [0x40600000-0x407fffff] [ 0.757933] pci_bus 0000:03: resource 0 io: [0x5000-0x5fff] [ 0.757941] pci_bus 0000:03: resource 1 mem: [0x40800000-0x409fffff] [ 0.757949] pci_bus 0000:03: resource 2 pref mem [0x40a00000-0x40bfffff] [ 0.757957] pci_bus 0000:04: resource 0 io: [0x6000-0x6fff] [ 0.757964] pci_bus 0000:04: resource 1 mem: [0x40c00000-0x40dfffff] [ 0.757972] pci_bus 0000:04: resource 2 pref mem [0x40e00000-0x40ffffff] [ 0.757980] pci_bus 0000:05: resource 0 io: [0x1000-0x1fff] [ 0.757988] pci_bus 0000:05: resource 1 mem: [0xf0100000-0xf01fffff] [ 0.757996] pci_bus 0000:05: resource 2 pref mem [0x41000000-0x410fffff] [ 0.758003] pci_bus 0000:05: resource 3 io: [0x00-0xffff] [ 0.758011] pci_bus 0000:05: resource 4 mem: [0x000000-0xffffffffffffffff] [ 0.758106] NET: Registered protocol family 2 [ 0.758441] IP route cache hash table entries: 32768 (order: 6, 262144 bytes) [ 0.759916] TCP established hash table entries: 131072 (order: 9, 2097152 bytes) [ 0.761787] TCP bind hash table entries: 65536 (order: 8, 1048576 bytes) [ 0.762486] TCP: Hash tables configured (established 131072 bind 65536) [ 0.762496] TCP reno registered [ 0.762817] NET: Registered protocol family 1 [ 0.762873] pci 0000:00:02.0: Boot video device [ 0.780390] Scanning for low memory corruption every 60 seconds [ 0.780787] audit: initializing netlink socket (disabled) [ 0.780813] type=2000 audit(1309451161.779:1): initialized [ 0.799307] HugeTLB registered 2 MB page size, pre-allocated 0 pages [ 0.804122] VFS: Disk quotas dquot_6.5.2 [ 0.804317] Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.806404] fuse init (API version 7.13) [ 0.806706] msgmni has been set to 1948 [ 0.807474] alg: No test for stdrng (krng) [ 0.807670] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 253) [ 0.807681] io scheduler noop registered [ 0.807687] io scheduler anticipatory registered [ 0.807692] io scheduler deadline registered [ 0.807808] io scheduler cfq registered (default) [ 0.808155] alloc irq_desc for 24 on node -1 [ 0.808162] alloc kstat_irqs on node -1 [ 0.808184] pcieport 0000:00:1c.0: irq 24 for MSI/MSI-X [ 0.808204] pcieport 0000:00:1c.0: setting latency timer to 64 [ 0.808472] alloc irq_desc for 25 on node -1 [ 0.808478] alloc kstat_irqs on node -1 [ 0.808497] pcieport 0000:00:1c.1: irq 25 for MSI/MSI-X [ 0.808514] pcieport 0000:00:1c.1: setting latency timer to 64 [ 0.808767] alloc irq_desc for 26 on node -1 [ 0.808774] alloc kstat_irqs on node -1 [ 0.808791] pcieport 0000:00:1c.2: irq 26 for MSI/MSI-X [ 0.808808] pcieport 0000:00:1c.2: setting latency timer to 64 [ 0.809095] alloc irq_desc for 27 on node -1 [ 0.809102] alloc kstat_irqs on node -1 [ 0.809121] pcieport 0000:00:1c.3: irq 27 for MSI/MSI-X [ 0.809139] pcieport 0000:00:1c.3: setting latency timer to 64 [ 0.809391] pci_hotplug: PCI Hot Plug PCI Core version: 0.5 [ 0.809707] pciehp: PCI Express Hot Plug Controller Driver version: 0.4 [ 0.809958] input: Sleep Button as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0C0E:00/input/input0 [ 0.809977] ACPI: Sleep Button [SLPB] [ 0.810132] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input1 [ 0.810141] ACPI: Power Button [PWRF] [ 0.812256] Monitor-Mwait will be used to enter C-1 state [ 0.812342] processor LNXCPU:00: registered as cooling_device0 [ 0.813666] processor LNXCPU:01: registered as cooling_device1 [ 0.815089] processor LNXCPU:02: registered as cooling_device2 [ 0.817193] processor LNXCPU:03: registered as cooling_device3 [ 0.823337] Linux agpgart interface v0.103 [ 0.823416] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 0.823573] serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A [ 0.823736] serial8250: ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A [ 0.824241] 00:09: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A [ 0.824462] 00:0a: ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A [ 0.826893] brd: module loaded [ 0.828050] loop: module loaded [ 0.828286] input: Macintosh mouse button emulation as /devices/virtual/input/input2 [ 0.829238] Fixed MDIO Bus: probed [ 0.829479] PPP generic driver version 2.4.2 [ 0.829589] tun: Universal TUN/TAP device driver, 1.6 [ 0.829594] tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com> [ 0.829786] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver [ 0.829835] alloc irq_desc for 23 on node -1 [ 0.829840] alloc kstat_irqs on node -1 [ 0.829853] ehci_hcd 0000:00:1d.7: PCI INT A -> GSI 23 (level, low) -> IRQ 23 [ 0.829884] ehci_hcd 0000:00:1d.7: setting latency timer to 64 [ 0.829891] ehci_hcd 0000:00:1d.7: EHCI Host Controller [ 0.829982] ehci_hcd 0000:00:1d.7: new USB bus registered, assigned bus number 1 [ 0.830016] ehci_hcd 0000:00:1d.7: using broken periodic workaround [ 0.830033] ehci_hcd 0000:00:1d.7: debug port 1 [ 0.833912] ehci_hcd 0000:00:1d.7: cache line size of 32 is not supported [ 0.833943] ehci_hcd 0000:00:1d.7: irq 23, io mem 0xf0384400 [ 0.849299] ehci_hcd 0000:00:1d.7: USB 2.0 started, EHCI 1.00 [ 0.849494] usb usb1: configuration #1 chosen from 1 choice [ 0.849558] hub 1-0:1.0: USB hub found [ 0.849575] hub 1-0:1.0: 8 ports detected [ 0.849710] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver [ 0.849743] uhci_hcd: USB Universal Host Controller Interface driver [ 0.849807] uhci_hcd 0000:00:1d.0: PCI INT A -> GSI 23 (level, low) -> IRQ 23 [ 0.849821] uhci_hcd 0000:00:1d.0: setting latency timer to 64 [ 0.849828] uhci_hcd 0000:00:1d.0: UHCI Host Controller [ 0.849915] uhci_hcd 0000:00:1d.0: new USB bus registered, assigned bus number 2 [ 0.849954] uhci_hcd 0000:00:1d.0: irq 23, io base 0x00003080 [ 0.850156] usb usb2: configuration #1 chosen from 1 choice [ 0.850219] hub 2-0:1.0: USB hub found [ 0.850235] hub 2-0:1.0: 2 ports detected [ 0.850333] uhci_hcd 0000:00:1d.1: PCI INT B -> GSI 19 (level, low) -> IRQ 19 [ 0.850347] uhci_hcd 0000:00:1d.1: setting latency timer to 64 [ 0.850353] uhci_hcd 0000:00:1d.1: UHCI Host Controller [ 0.850434] uhci_hcd 0000:00:1d.1: new USB bus registered, assigned bus number 3 [ 0.850492] uhci_hcd 0000:00:1d.1: irq 19, io base 0x00003060 [ 0.850695] usb usb3: configuration #1 chosen from 1 choice [ 0.850756] hub 3-0:1.0: USB hub found [ 0.850772] hub 3-0:1.0: 2 ports detected [ 0.850870] uhci_hcd 0000:00:1d.2: PCI INT C -> GSI 18 (level, low) -> IRQ 18 [ 0.850882] uhci_hcd 0000:00:1d.2: setting latency timer to 64 [ 0.850889] uhci_hcd 0000:00:1d.2: UHCI Host Controller [ 0.850972] uhci_hcd 0000:00:1d.2: new USB bus registered, assigned bus number 4 [ 0.851019] uhci_hcd 0000:00:1d.2: irq 18, io base 0x00003040 [ 0.851240] usb usb4: configuration #1 chosen from 1 choice [ 0.851302] hub 4-0:1.0: USB hub found [ 0.851318] hub 4-0:1.0: 2 ports detected [ 0.851416] uhci_hcd 0000:00:1d.3: PCI INT D -> GSI 16 (level, low) -> IRQ 16 [ 0.851428] uhci_hcd 0000:00:1d.3: setting latency timer to 64 [ 0.851435] uhci_hcd 0000:00:1d.3: UHCI Host Controller [ 0.851522] uhci_hcd 0000:00:1d.3: new USB bus registered, assigned bus number 5 [ 0.851578] uhci_hcd 0000:00:1d.3: irq 16, io base 0x00003020 [ 0.851784] usb usb5: configuration #1 chosen from 1 choice [ 0.851846] hub 5-0:1.0: USB hub found [ 0.851861] hub 5-0:1.0: 2 ports detected [ 0.852066] PNP: No PS/2 controller found. Probing ports directly. [ 0.855200] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 0.855217] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 0.855436] mice: PS/2 mouse device common for all mice [ 0.855672] rtc_cmos 00:03: RTC can wake from S4 [ 0.855765] rtc_cmos 00:03: rtc core: registered rtc_cmos as rtc0 [ 0.855807] rtc0: alarms up to one month, y3k, 114 bytes nvram, hpet irqs [ 0.856107] device-mapper: uevent: version 1.0.3 [ 0.856390] device-mapper: ioctl: 4.15.0-ioctl (2009-04-01) initialised: dm-devel@redhat.com [ 0.856717] device-mapper: multipath: version 1.1.0 loaded [ 0.856724] device-mapper: multipath round-robin: version 1.0.0 loaded [ 0.857373] cpuidle: using governor ladder [ 0.857378] cpuidle: using governor menu [ 0.858141] TCP cubic registered [ 0.858464] NET: Registered protocol family 10 [ 0.859531] lo: Disabled Privacy Extensions [ 0.860143] NET: Registered protocol family 17 [ 0.860923] ACPI Exception: AE_NOT_FOUND, Evaluating _PSS (20090903/processor_perflib-264) [ 0.860998] ACPI Exception: AE_NOT_FOUND, Evaluating _PSS (20090903/processor_perflib-264) [ 0.861068] ACPI Exception: AE_NOT_FOUND, Evaluating _PSS (20090903/processor_perflib-264) [ 0.861138] ACPI Exception: AE_NOT_FOUND, Evaluating _PSS (20090903/processor_perflib-264) [ 0.861356] PM: Resume from disk failed. [ 0.861381] registered taskstats version 1 [ 0.861941] Magic number: 15:326:440 [ 0.862016] pcieport 0000:00:1c.1: hash matches [ 0.862082] rtc_cmos 00:03: setting system clock to 2011-06-30 16:26:02 UTC (1309451162) [ 0.862089] BIOS EDD facility v0.16 2004-Jun-25, 0 devices found [ 0.862093] EDD information not available. [ 1.032580] Freeing initrd memory: 8134k freed [ 1.038080] Freeing unused kernel memory: 876k freed [ 1.038484] Write protecting the kernel read-only data: 7680k [ 1.075712] udev: starting version 151 [ 1.148143] r8169 Gigabit Ethernet driver 2.3LK-NAPI loaded [ 1.148194] r8169 0000:01:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16 [ 1.148272] r8169 0000:01:00.0: setting latency timer to 64 [ 1.148286] r8169 0000:01:00.0: unknown MAC, using family default [ 1.148365] alloc irq_desc for 28 on node -1 [ 1.148372] alloc kstat_irqs on node -1 [ 1.148403] r8169 0000:01:00.0: irq 28 for MSI/MSI-X [ 1.150141] eth0: RTL8168b/8111b at 0xffffc900001f6000, 70:71:bc:cc:e8:37, XID 0c200000 IRQ 28 [ 1.203136] sata_sil24 0000:05:00.0: version 1.1 [ 1.203177] alloc irq_desc for 20 on node -1 [ 1.203186] alloc kstat_irqs on node -1 [ 1.203205] sata_sil24 0000:05:00.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20 [ 1.220752] scsi0 : sata_sil24 [ 1.221356] ahci 0000:00:1f.2: version 3.0 [ 1.221395] ahci 0000:00:1f.2: PCI INT A -> GSI 18 (level, low) -> IRQ 18 [ 1.221484] alloc irq_desc for 29 on node -1 [ 1.221492] alloc kstat_irqs on node -1 [ 1.221518] ahci 0000:00:1f.2: irq 29 for MSI/MSI-X [ 1.221598] ahci: SSS flag set, parallel bus scan disabled [ 1.221655] ahci 0000:00:1f.2: AHCI 0001.0100 32 slots 4 ports 3 Gbps 0x3 impl SATA mode [ 1.221667] ahci 0000:00:1f.2: flags: 64bit ncq stag pm led clo pio slum part [ 1.221681] ahci 0000:00:1f.2: setting latency timer to 64 [ 1.221903] scsi1 : sata_sil24 [ 1.222240] scsi2 : ahci [ 1.222410] scsi3 : sata_sil24 [ 1.222576] scsi4 : ahci [ 1.222945] scsi5 : ahci [ 1.222957] scsi6 : sata_sil24 [ 1.223160] ata1: SATA max UDMA/100 host m128@0xf0108000 port 0xf0100000 irq 20 [ 1.223173] ata2: SATA max UDMA/100 host m128@0xf0108000 port 0xf0102000 irq 20 [ 1.223184] ata3: SATA max UDMA/100 host m128@0xf0108000 port 0xf0104000 irq 20 [ 1.223195] ata4: SATA max UDMA/100 host m128@0xf0108000 port 0xf0106000 irq 20 [ 1.223457] scsi7 : ahci [ 1.224040] ata5: SATA max UDMA/133 abar m1024@0xf0384000 port 0xf0384100 irq 29 [ 1.224052] ata6: SATA max UDMA/133 abar m1024@0xf0384000 port 0xf0384180 irq 29 [ 1.224060] ata7: DUMMY [ 1.224064] ata8: DUMMY [ 1.400033] usb 5-1: new low speed USB device using uhci_hcd and address 2 [ 1.570039] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 1.573889] usb 5-1: configuration #1 chosen from 1 choice [ 1.575809] ata5.00: ATA-8: SAMSUNG HD103SJ, 1AJ100E5, max UDMA/133 [ 1.575820] ata5.00: 1953525168 sectors, multi 16: LBA48 NCQ (depth 31/32), AA [ 1.581679] ata5.00: configured for UDMA/133 [ 1.613318] usbcore: registered new interface driver hiddev [ 1.627277] input: USB CAT5 as /devices/pci0000:00/0000:00:1d.3/usb5/5-1/5-1:1.0/input/input3 [ 1.627620] generic-usb 0003:0D3D:0040.0001: input,hidraw0: USB HID v1.00 Keyboard [USB CAT5] on usb-0000:00:1d.3-1/input0 [ 1.643201] input: USB CAT5 as /devices/pci0000:00/0000:00:1d.3/usb5/5-1/5-1:1.1/input/input4 [ 1.643656] generic-usb 0003:0D3D:0040.0002: input,hidraw1: USB HID v1.00 Mouse [USB CAT5] on usb-0000:00:1d.3-1/input1 [ 1.643718] usbcore: registered new interface driver usbhid [ 1.643812] usbhid: v2.6:USB HID core driver [ 3.440046] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 3.440365] ata1.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports, feat 0x1/0x9 [ 3.440691] ata1.00: hard resetting link [ 3.790423] ata1.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 3.790468] ata1.01: hard resetting link [ 4.140414] ata1.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 4.140458] ata1.02: hard resetting link [ 4.490411] ata1.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 4.490455] ata1.03: hard resetting link [ 4.840412] ata1.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 4.840456] ata1.04: hard resetting link [ 5.190412] ata1.04: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 5.190456] ata1.05: hard resetting link [ 5.540423] ata1.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) [ 5.546901] ata1.00: ATA-7: SAMSUNG HD154UI, 1AG01118, max UDMA7 [ 5.546909] ata1.00: 2930277168 sectors, multi 16: LBA48 NCQ (depth 31/32) [ 5.553492] ata1.00: configured for UDMA/100 [ 5.557739] ata1.01: ATA-8: WDC WD30EZRS-00J99B0, 80.00A80, max UDMA/133 [ 5.557746] ata1.01: 5860533168 sectors, multi 0: LBA48 NCQ (depth 31/32) [ 5.562773] ata1.01: configured for UDMA/100 [ 5.606008] ata1.02: ATA-7: ST3160815AS, 4.AAB, max UDMA/133 [ 5.606014] ata1.02: 312581808 sectors, multi 0: LBA48 NCQ (depth 31/32) [ 5.664350] ata1.02: configured for UDMA/100 [ 5.668688] ata1.03: ATA-8: WDC WD30EZRX-00MMMB0, 80.00A80, max UDMA/133 [ 5.668695] ata1.03: 5860533168 sectors, multi 0: LBA48 NCQ (depth 31/32) [ 5.673712] ata1.03: configured for UDMA/100 [ 5.674959] ata1.04: ATA-8: ST320005XXXX, CC34, max UDMA/133 [ 5.674966] ata1.04: 3907029168 sectors, multi 0: LBA48 NCQ (depth 31/32) [ 5.676421] ata1.04: configured for UDMA/100 [ 5.676506] ata1: EH complete [ 5.676720] scsi 0:0:0:0: Direct-Access ATA SAMSUNG HD154UI 1AG0 PQ: 0 ANSI: 5 [ 5.677246] sd 0:0:0:0: Attached scsi generic sg0 type 0 [ 5.677299] sd 0:0:0:0: [sda] 2930277168 512-byte logical blocks: (1.50 TB/1.36 TiB) [ 5.677437] sd 0:0:0:0: [sda] Write Protect is off [ 5.677444] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00 [ 5.677519] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [ 5.677739] scsi 0:1:0:0: Direct-Access ATA WDC WD30EZRS-00J 80.0 PQ: 0 ANSI: 5 [ 5.677904] sda: [ 5.678115] sd 0:1:0:0: Attached scsi generic sg1 type 0 [ 5.678169] sd 0:1:0:0: [sdb] 5860533168 512-byte logical blocks: (3.00 TB/2.72 TiB) [ 5.678176] sd 0:1:0:0: [sdb] 4096-byte physical blocks [ 5.678316] sd 0:1:0:0: [sdb] Write Protect is off [ 5.678324] sd 0:1:0:0: [sdb] Mode Sense: 00 3a 00 00 [ 5.678393] sd 0:1:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [ 5.678640] scsi 0:2:0:0: Direct-Access ATA ST3160815AS 4.AA PQ: 0 ANSI: 5 [ 5.678766] sdb: [ 5.679070] sd 0:2:0:0: Attached scsi generic sg2 type 0 [ 5.679094] sd 0:2:0:0: [sdc] 312581808 512-byte logical blocks: (160 GB/149 GiB) [ 5.679229] sd 0:2:0:0: [sdc] Write Protect is off [ 5.679236] sd 0:2:0:0: [sdc] Mode Sense: 00 3a 00 00 [ 5.679309] sd 0:2:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [ 5.679596] scsi 0:3:0:0: Direct-Access ATA WDC WD30EZRX-00M 80.0 PQ: 0 ANSI: 5 [ 5.679689] sdc: [ 5.680191] sd 0:3:0:0: [sdd] 5860533168 512-byte logical blocks: (3.00 TB/2.72 TiB) [ 5.680198] sd 0:3:0:0: [sdd] 4096-byte physical blocks [ 5.680322] sd 0:3:0:0: Attached scsi generic sg3 type 0 [ 5.680333] sd 0:3:0:0: [sdd] Write Protect is off [ 5.680340] sd 0:3:0:0: [sdd] Mode Sense: 00 3a 00 00 [ 5.680411] sd 0:3:0:0: [sdd] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [ 5.680692] scsi 0:4:0:0: Direct-Access ATA ST320005XXXX CC34 PQ: 0 ANSI: 5 [ 5.680800] sdd: [ 5.681284] sd 0:4:0:0: [sde] 3907029168 512-byte logical blocks: (2.00 TB/1.81 TiB) [ 5.681412] sd 0:4:0:0: Attached scsi generic sg4 type 0 [ 5.681421] sd 0:4:0:0: [sde] Write Protect is off [ 5.681433] sd 0:4:0:0: [sde] Mode Sense: 00 3a 00 00 [ 5.681510] sd 0:4:0:0: [sde] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [ 5.682021] sde: sda1 [ 5.688373] sd 0:0:0:0: [sda] Attached SCSI disk [ 5.705952] sde1 [ 5.706920] sd 0:4:0:0: [sde] Attached SCSI disk [ 5.712379] sdc1 [ 5.713104] sd 0:2:0:0: [sdc] Attached SCSI disk [ 6.153657] sdd1 sdd2 [ 6.154817] sd 0:3:0:0: [sdd] Attached SCSI disk [ 6.271972] sdb1 [ 6.272961] sd 0:1:0:0: [sdb] Attached SCSI disk [ 7.770043] ata2: SATA link down (SStatus 0 SControl 0) [ 9.860042] ata3: SATA link down (SStatus 0 SControl 0) [ 11.950049] ata4: SATA link down (SStatus 0 SControl 0) [ 11.950306] scsi 2:0:0:0: Direct-Access ATA SAMSUNG HD103SJ 1AJ1 PQ: 0 ANSI: 5 [ 11.950703] sd 2:0:0:0: [sdf] 1953525168 512-byte logical blocks: (1.00 TB/931 GiB) [ 11.950744] sd 2:0:0:0: Attached scsi generic sg5 type 0 [ 11.950874] sd 2:0:0:0: [sdf] Write Protect is off [ 11.950883] sd 2:0:0:0: [sdf] Mode Sense: 00 3a 00 00 [ 11.950966] sd 2:0:0:0: [sdf] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [ 11.951373] sdf: sdf1 sdf2 [ 11.962694] sd 2:0:0:0: [sdf] Attached SCSI disk [ 12.300035] ata6: SATA link down (SStatus 0 SControl 300) [ 12.462166] EXT4-fs (sdf1): INFO: recovery required on readonly filesystem [ 12.462176] EXT4-fs (sdf1): write access will be enabled during recovery [ 12.507173] EXT4-fs (sdf1): recovery complete [ 12.507429] EXT4-fs (sdf1): mounted filesystem with ordered data mode [ 16.095233] udev: starting version 151 [ 16.157763] agpgart-intel 0000:00:00.0: Intel IGD Chipset [ 16.158170] agpgart-intel 0000:00:00.0: detected 8188K stolen memory [ 16.174205] agpgart-intel 0000:00:00.0: AGP aperture is 256M @ 0xe0000000 [ 16.175406] lp: driver loaded but no devices found [ 16.325386] [drm] Initialized drm 1.1.0 20060810 [ 16.365337] parport_pc 00:08: reported by Plug and Play ACPI [ 16.365408] parport0: PC-style at 0x378, irq 7 [PCSPP] [ 16.442672] type=1505 audit(1309451178.080:2): operation="profile_load" pid=504 name="/sbin/dhclient3" [ 16.443546] type=1505 audit(1309451178.080:3): operation="profile_load" pid=504 name="/usr/lib/NetworkManager/nm-dhcp-client.action" [ 16.444103] type=1505 audit(1309451178.080:4): operation="profile_load" pid=504 name="/usr/lib/connman/scripts/dhclient-script" [ 16.444341] lp0: using parport0 (interrupt-driven). [ 16.477145] type=1505 audit(1309451178.110:5): operation="profile_load" pid=579 name="/usr/sbin/ntpd" [ 16.638979] pci 0000:00:02.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16 [ 16.638992] pci 0000:00:02.0: setting latency timer to 64 [ 16.681503] ppdev: user-space parallel port driver [ 16.688167] alloc irq_desc for 30 on node -1 [ 16.688175] alloc kstat_irqs on node -1 [ 16.688197] pci 0000:00:02.0: irq 30 for MSI/MSI-X [ 16.689350] [drm] Initialized i915 1.6.0 20080730 for 0000:00:02.0 on minor 0 [ 16.698628] vga16fb: initializing [ 16.698642] vga16fb: mapped to 0xffff8800000a0000 [ 16.699123] fb0: VGA16 VGA frame buffer device [ 16.787391] r8169: eth0: link up [ 16.787404] r8169: eth0: link up [ 16.880165] Console: switching to colour frame buffer device 80x30 [ 17.133529] alloc irq_desc for 22 on node -1 [ 17.133539] alloc kstat_irqs on node -1 [ 17.133559] HDA Intel 0000:00:1b.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22 [ 17.133644] HDA Intel 0000:00:1b.0: setting latency timer to 64 [ 17.227825] type=1505 audit(1309451178.860:6): operation="profile_load" pid=899 name="/usr/share/gdm/guest-session/Xsession" [ 17.231057] type=1505 audit(1309451178.860:7): operation="profile_replace" pid=900 name="/sbin/dhclient3" [ 17.231678] type=1505 audit(1309451178.860:8): operation="profile_replace" pid=900 name="/usr/lib/NetworkManager/nm-dhcp-client.action" [ 17.231970] type=1505 audit(1309451178.860:9): operation="profile_replace" pid=900 name="/usr/lib/connman/scripts/dhclient-script" [ 17.237602] type=1505 audit(1309451178.870:10): operation="profile_load" pid=901 name="/usr/bin/evince" [ 17.244718] type=1505 audit(1309451178.880:11): operation="profile_load" pid=901 name="/usr/bin/evince-previewer" [ 17.293714] hda_codec: ALC662 rev1: BIOS auto-probing. [ 17.295479] input: HDA Digital PCBeep as /devices/pci0000:00/0000:00:1b.0/input/input5 [ 17.509763] RPC: Registered udp transport module. [ 17.509772] RPC: Registered tcp transport module. [ 17.509778] RPC: Registered tcp NFSv4.1 backchannel transport module. >From kern.log after turning off bay before patch: Jun 30 09:27:05 HR-NETSWAP kernel: [ 63.691846] ata1.03: exception Emask 0x10 SAct 0x0 SErr 0x4010000 action 0xf Jun 30 09:27:05 HR-NETSWAP kernel: [ 63.703423] ata1.03: SError: { PHYRdyChg DevExch } Jun 30 09:27:05 HR-NETSWAP kernel: [ 63.709248] ata1.03: hard resetting link Jun 30 09:27:06 HR-NETSWAP kernel: [ 64.450399] ata1.03: SATA link down (SStatus 0 SControl 320) Jun 30 09:27:11 HR-NETSWAP kernel: [ 69.450022] ata1.03: hard resetting link Jun 30 09:27:11 HR-NETSWAP kernel: [ 69.800421] ata1.03: SATA link down (SStatus 0 SControl 320) Jun 30 09:27:11 HR-NETSWAP kernel: [ 69.800563] ata1.03: limiting SATA link speed to 1.5 Gbps Jun 30 09:27:16 HR-NETSWAP kernel: [ 74.800066] ata1.03: hard resetting link Jun 30 09:27:16 HR-NETSWAP kernel: [ 75.150392] ata1.03: SATA link down (SStatus 0 SControl 310) Jun 30 09:27:16 HR-NETSWAP kernel: [ 75.150504] ata1.03: disabled Jun 30 09:27:16 HR-NETSWAP kernel: [ 75.150622] ata1: EH complete Jun 30 09:27:16 HR-NETSWAP kernel: [ 75.150632] ata1.03: detaching (SCSI 0:3:0:0) Jun 30 09:27:16 HR-NETSWAP kernel: [ 75.181719] sd 0:3:0:0: [sdd] Synchronizing SCSI cache Jun 30 09:27:16 HR-NETSWAP kernel: [ 75.182940] sd 0:3:0:0: [sdd] Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK Jun 30 09:27:16 HR-NETSWAP kernel: [ 75.182952] sd 0:3:0:0: [sdd] Stopping disk Jun 30 09:27:16 HR-NETSWAP kernel: [ 75.182990] sd 0:3:0:0: [sdd] START_STOP FAILED Jun 30 09:27:16 HR-NETSWAP kernel: [ 75.182997] sd 0:3:0:0: [sdd] Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK >From kern.log after turning bay on before patch: Jun 30 09:28:20 HR-NETSWAP kernel: [ 139.105594] ata1.03: exception Emask 0x10 SAct 0x0 SErr 0x4050000 action 0xf Jun 30 09:28:20 HR-NETSWAP kernel: [ 139.111769] ata1.03: SError: { PHYRdyChg CommWake DevExch } Jun 30 09:28:20 HR-NETSWAP kernel: [ 139.118130] ata1.03: hard resetting link Jun 30 09:28:21 HR-NETSWAP kernel: [ 139.951641] ata1.03: SATA link up 1.5 Gbps (SStatus 113 SControl 320) Jun 30 09:28:21 HR-NETSWAP kernel: [ 139.951747] ata1.03: failed to IDENTIFY (I/O error, err_mask=0x11) Jun 30 09:28:21 HR-NETSWAP kernel: [ 139.951756] ata1.15: hard resetting link Jun 30 09:28:23 HR-NETSWAP kernel: [ 142.170048] ata1.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) Jun 30 09:28:23 HR-NETSWAP kernel: [ 142.170324] ata1.00: hard resetting link Jun 30 09:28:24 HR-NETSWAP kernel: [ 142.521646] ata1.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) Jun 30 09:28:24 HR-NETSWAP kernel: [ 142.521692] ata1.01: hard resetting link Jun 30 09:28:24 HR-NETSWAP kernel: [ 142.871638] ata1.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 09:28:24 HR-NETSWAP kernel: [ 142.871682] ata1.02: hard resetting link Jun 30 09:28:24 HR-NETSWAP kernel: [ 143.220413] ata1.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 09:28:26 HR-NETSWAP kernel: [ 144.950035] ata1.03: hard resetting link Jun 30 09:28:26 HR-NETSWAP kernel: [ 145.300399] ata1.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 09:28:26 HR-NETSWAP kernel: [ 145.300444] ata1.04: hard resetting link Jun 30 09:28:27 HR-NETSWAP kernel: [ 145.650410] ata1.04: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 09:28:27 HR-NETSWAP kernel: [ 145.650455] ata1.05: hard resetting link Jun 30 09:28:27 HR-NETSWAP kernel: [ 146.000393] ata1.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) Jun 30 09:28:27 HR-NETSWAP kernel: [ 146.013474] ata1.00: configured for UDMA/100 Jun 30 09:28:27 HR-NETSWAP kernel: [ 146.022600] ata1.01: configured for UDMA/100 Jun 30 09:28:27 HR-NETSWAP kernel: [ 146.129262] ata1.02: configured for UDMA/100 Jun 30 09:28:27 HR-NETSWAP kernel: [ 146.129331] ata1.03: failed to IDENTIFY (I/O error, err_mask=0x11) Jun 30 09:28:27 HR-NETSWAP kernel: [ 146.129341] ata1.15: hard resetting link Jun 30 09:28:29 HR-NETSWAP kernel: [ 148.340049] ata1.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) Jun 30 09:28:29 HR-NETSWAP kernel: [ 148.340321] ata1.00: hard resetting link Jun 30 09:28:30 HR-NETSWAP kernel: [ 148.710385] ata1.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) Jun 30 09:28:30 HR-NETSWAP kernel: [ 148.710431] ata1.01: hard resetting link Jun 30 09:28:30 HR-NETSWAP kernel: [ 149.071617] ata1.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 09:28:30 HR-NETSWAP kernel: [ 149.071661] ata1.02: hard resetting link Jun 30 09:28:31 HR-NETSWAP kernel: [ 149.441636] ata1.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 09:28:31 HR-NETSWAP kernel: [ 150.300034] ata1.03: hard resetting link Jun 30 09:28:32 HR-NETSWAP kernel: [ 150.654706] ata1.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 09:28:32 HR-NETSWAP kernel: [ 150.654750] ata1.04: hard resetting link Jun 30 09:28:32 HR-NETSWAP kernel: [ 151.000367] ata1.04: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 09:28:32 HR-NETSWAP kernel: [ 151.000409] ata1.05: hard resetting link Jun 30 09:28:32 HR-NETSWAP kernel: [ 151.350388] ata1.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) Jun 30 09:28:33 HR-NETSWAP kernel: [ 151.363470] ata1.00: configured for UDMA/100 Jun 30 09:28:33 HR-NETSWAP kernel: [ 151.373200] ata1.01: configured for UDMA/100 Jun 30 09:28:33 HR-NETSWAP kernel: [ 151.460635] ata1.02: configured for UDMA/100 Jun 30 09:28:33 HR-NETSWAP kernel: [ 151.460701] ata1.03: failed to IDENTIFY (I/O error, err_mask=0x11) Jun 30 09:28:33 HR-NETSWAP kernel: [ 151.460709] ata1.03: failed to recover link after 3 tries, disabling Jun 30 09:28:33 HR-NETSWAP kernel: [ 151.460717] ata1.15: hard resetting link Jun 30 09:28:35 HR-NETSWAP kernel: [ 153.684422] ata1.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) Jun 30 09:28:35 HR-NETSWAP kernel: [ 154.034292] ata1.00: hard resetting link Jun 30 09:28:36 HR-NETSWAP kernel: [ 154.380389] ata1.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) Jun 30 09:28:36 HR-NETSWAP kernel: [ 154.380433] ata1.01: hard resetting link Jun 30 09:28:36 HR-NETSWAP kernel: [ 154.734289] ata1.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 09:28:36 HR-NETSWAP kernel: [ 154.734333] ata1.02: hard resetting link Jun 30 09:28:36 HR-NETSWAP kernel: [ 155.070389] ata1.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 09:28:37 HR-NETSWAP kernel: [ 156.000035] ata1.04: hard resetting link Jun 30 09:28:37 HR-NETSWAP kernel: [ 156.354373] ata1.04: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 09:28:37 HR-NETSWAP kernel: [ 156.354419] ata1.05: hard resetting link Jun 30 09:28:38 HR-NETSWAP kernel: [ 156.700389] ata1.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) Jun 30 09:28:38 HR-NETSWAP kernel: [ 156.713473] ata1.00: configured for UDMA/100 Jun 30 09:28:38 HR-NETSWAP kernel: [ 156.722797] ata1.01: configured for UDMA/100 Jun 30 09:28:38 HR-NETSWAP kernel: [ 156.817016] ata1.02: configured for UDMA/100 Jun 30 09:28:38 HR-NETSWAP kernel: [ 156.819785] ata1.04: configured for UDMA/100 Jun 30 09:28:38 HR-NETSWAP kernel: [ 156.819871] ata1: EH complete >From kern.log after turning bay off after patch (changed ATA_EH_PMP_LINK_TRIES from 3 to 5): Jun 30 10:01:56 HR-NETSWAP kernel: [ 69.805574] ata1.03: exception Emask 0x10 SAct 0x0 SErr 0x4010000 action 0xf Jun 30 10:01:56 HR-NETSWAP kernel: [ 69.814603] ata1.03: SError: { PHYRdyChg DevExch } Jun 30 10:01:56 HR-NETSWAP kernel: [ 69.823948] ata1.03: hard resetting link Jun 30 10:01:56 HR-NETSWAP kernel: [ 69.823969] ata1.03: XXXX hardreset hotplugged = true Jun 30 10:01:56 HR-NETSWAP kernel: [ 69.823976] ata1.03: XXX0 hardreset debounce 25 500 2000 Jun 30 10:01:56 HR-NETSWAP kernel: [ 69.823981] ata1.03: XXX1 hardreset debounce 25 500 2000 Jun 30 10:01:57 HR-NETSWAP kernel: [ 70.570402] ata1.03: SATA link down (SStatus 0 SControl 320) Jun 30 10:02:02 HR-NETSWAP kernel: [ 75.570028] ata1.03: hard resetting link Jun 30 10:02:02 HR-NETSWAP kernel: [ 75.570051] ata1.03: XXXX hardreset hotplugged = false Jun 30 10:02:02 HR-NETSWAP kernel: [ 75.570057] ata1.03: XXX0 hardreset debounce 5 100 2000 Jun 30 10:02:02 HR-NETSWAP kernel: [ 75.570062] ata1.03: XXX1 hardreset debounce 5 100 2000 Jun 30 10:02:02 HR-NETSWAP kernel: [ 75.921656] ata1.03: SATA link down (SStatus 0 SControl 320) Jun 30 10:02:02 HR-NETSWAP kernel: [ 75.921799] ata1.03: limiting SATA link speed to 1.5 Gbps Jun 30 10:02:07 HR-NETSWAP kernel: [ 80.920028] ata1.03: hard resetting link Jun 30 10:02:07 HR-NETSWAP kernel: [ 80.920050] ata1.03: XXXX hardreset hotplugged = false Jun 30 10:02:07 HR-NETSWAP kernel: [ 80.920056] ata1.03: XXX0 hardreset debounce 5 100 2000 Jun 30 10:02:07 HR-NETSWAP kernel: [ 80.920062] ata1.03: XXX1 hardreset debounce 5 100 2000 Jun 30 10:02:07 HR-NETSWAP kernel: [ 81.270394] ata1.03: SATA link down (SStatus 0 SControl 310) Jun 30 10:02:07 HR-NETSWAP kernel: [ 81.270507] ata1.03: disabled Jun 30 10:02:07 HR-NETSWAP kernel: [ 81.270627] ata1: EH complete Jun 30 10:02:07 HR-NETSWAP kernel: [ 81.270638] ata1.03: detaching (SCSI 0:3:0:0) Jun 30 10:02:07 HR-NETSWAP kernel: [ 81.300423] sd 0:3:0:0: [sdd] Synchronizing SCSI cache Jun 30 10:02:07 HR-NETSWAP kernel: [ 81.300587] sd 0:3:0:0: [sdd] Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK Jun 30 10:02:07 HR-NETSWAP kernel: [ 81.300601] sd 0:3:0:0: [sdd] Stopping disk Jun 30 10:02:07 HR-NETSWAP kernel: [ 81.300642] sd 0:3:0:0: [sdd] START_STOP FAILED Jun 30 10:02:07 HR-NETSWAP kernel: [ 81.300649] sd 0:3:0:0: [sdd] Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK >From kern.log after turning bay on after patch (changed ATA_EH_PMP_LINK_TRIES from 3 to 5): Jun 30 10:02:16 HR-NETSWAP kernel: [ 90.353682] ata1.03: exception Emask 0x10 SAct 0x0 SErr 0x4050000 action 0xf Jun 30 10:02:16 HR-NETSWAP kernel: [ 90.365393] ata1.03: SError: { PHYRdyChg CommWake DevExch } Jun 30 10:02:16 HR-NETSWAP kernel: [ 90.377061] ata1.03: hard resetting link Jun 30 10:02:16 HR-NETSWAP kernel: [ 90.377083] ata1.03: XXXX hardreset hotplugged = true Jun 30 10:02:16 HR-NETSWAP kernel: [ 90.377089] ata1.03: XXX0 hardreset debounce 25 500 2000 Jun 30 10:02:16 HR-NETSWAP kernel: [ 90.377094] ata1.03: XXX1 hardreset debounce 25 500 2000 Jun 30 10:02:17 HR-NETSWAP kernel: [ 91.120398] ata1.03: SATA link up 3.0 Gbps (SStatus 123 SControl 320) Jun 30 10:02:17 HR-NETSWAP kernel: [ 91.120506] ata1.03: failed to IDENTIFY (I/O error, err_mask=0x11) Jun 30 10:02:17 HR-NETSWAP kernel: [ 91.120516] ata1.15: hard resetting link Jun 30 10:02:19 HR-NETSWAP kernel: [ 93.340047] ata1.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) Jun 30 10:02:19 HR-NETSWAP kernel: [ 93.340329] ata1.00: hard resetting link Jun 30 10:02:19 HR-NETSWAP kernel: [ 93.340349] ata1.00: XXXX hardreset hotplugged = false Jun 30 10:02:19 HR-NETSWAP kernel: [ 93.340355] ata1.00: XXX0 hardreset debounce 5 100 2000 Jun 30 10:02:19 HR-NETSWAP kernel: [ 93.340360] ata1.00: XXX1 hardreset debounce 5 100 2000 Jun 30 10:02:20 HR-NETSWAP kernel: [ 93.690395] ata1.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) Jun 30 10:02:20 HR-NETSWAP kernel: [ 93.690440] ata1.01: hard resetting link Jun 30 10:02:20 HR-NETSWAP kernel: [ 93.690460] ata1.01: XXXX hardreset hotplugged = false Jun 30 10:02:20 HR-NETSWAP kernel: [ 93.690465] ata1.01: XXX0 hardreset debounce 5 100 2000 Jun 30 10:02:20 HR-NETSWAP kernel: [ 93.690471] ata1.01: XXX1 hardreset debounce 5 100 2000 Jun 30 10:02:20 HR-NETSWAP kernel: [ 94.040391] ata1.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 10:02:20 HR-NETSWAP kernel: [ 94.040436] ata1.02: hard resetting link Jun 30 10:02:20 HR-NETSWAP kernel: [ 94.040456] ata1.02: XXXX hardreset hotplugged = false Jun 30 10:02:20 HR-NETSWAP kernel: [ 94.040461] ata1.02: XXX0 hardreset debounce 5 100 2000 Jun 30 10:02:20 HR-NETSWAP kernel: [ 94.040467] ata1.02: XXX1 hardreset debounce 5 100 2000 Jun 30 10:02:21 HR-NETSWAP kernel: [ 94.390453] ata1.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 10:02:22 HR-NETSWAP kernel: [ 96.120024] ata1.03: hard resetting link Jun 30 10:02:22 HR-NETSWAP kernel: [ 96.120046] ata1.03: XXXX hardreset hotplugged = false Jun 30 10:02:22 HR-NETSWAP kernel: [ 96.120052] ata1.03: XXX0 hardreset debounce 5 100 2000 Jun 30 10:02:22 HR-NETSWAP kernel: [ 96.120058] ata1.03: XXX1 hardreset debounce 5 100 2000 Jun 30 10:02:23 HR-NETSWAP kernel: [ 96.470398] ata1.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 10:02:23 HR-NETSWAP kernel: [ 96.470446] ata1.04: hard resetting link Jun 30 10:02:23 HR-NETSWAP kernel: [ 96.470467] ata1.04: XXXX hardreset hotplugged = false Jun 30 10:02:23 HR-NETSWAP kernel: [ 96.470472] ata1.04: XXX0 hardreset debounce 5 100 2000 Jun 30 10:02:23 HR-NETSWAP kernel: [ 96.470478] ata1.04: XXX1 hardreset debounce 5 100 2000 Jun 30 10:02:23 HR-NETSWAP kernel: [ 96.821674] ata1.04: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 10:02:23 HR-NETSWAP kernel: [ 96.821720] ata1.05: hard resetting link Jun 30 10:02:23 HR-NETSWAP kernel: [ 96.821744] ata1.05: XXXX hardreset hotplugged = false Jun 30 10:02:23 HR-NETSWAP kernel: [ 96.821750] ata1.05: XXX0 hardreset debounce 5 100 2000 Jun 30 10:02:23 HR-NETSWAP kernel: [ 96.821756] ata1.05: XXX1 hardreset debounce 5 100 2000 Jun 30 10:02:23 HR-NETSWAP kernel: [ 97.170399] ata1.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) Jun 30 10:02:23 HR-NETSWAP kernel: [ 97.183479] ata1.00: configured for UDMA/100 Jun 30 10:02:23 HR-NETSWAP kernel: [ 97.192728] ata1.01: configured for UDMA/100 Jun 30 10:02:23 HR-NETSWAP kernel: [ 97.298289] ata1.02: configured for UDMA/100 Jun 30 10:02:23 HR-NETSWAP kernel: [ 97.298356] ata1.03: failed to IDENTIFY (I/O error, err_mask=0x11) Jun 30 10:02:23 HR-NETSWAP kernel: [ 97.298366] ata1.15: hard resetting link Jun 30 10:02:26 HR-NETSWAP kernel: [ 99.510055] ata1.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) Jun 30 10:02:26 HR-NETSWAP kernel: [ 99.510330] ata1.00: hard resetting link Jun 30 10:02:26 HR-NETSWAP kernel: [ 99.510350] ata1.00: XXXX hardreset hotplugged = false Jun 30 10:02:26 HR-NETSWAP kernel: [ 99.510356] ata1.00: XXX0 hardreset debounce 5 100 2000 Jun 30 10:02:26 HR-NETSWAP kernel: [ 99.510361] ata1.00: XXX1 hardreset debounce 5 100 2000 Jun 30 10:02:26 HR-NETSWAP kernel: [ 99.860387] ata1.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) Jun 30 10:02:26 HR-NETSWAP kernel: [ 99.860430] ata1.01: hard resetting link Jun 30 10:02:26 HR-NETSWAP kernel: [ 99.860450] ata1.01: XXXX hardreset hotplugged = false Jun 30 10:02:26 HR-NETSWAP kernel: [ 99.860455] ata1.01: XXX0 hardreset debounce 5 100 2000 Jun 30 10:02:26 HR-NETSWAP kernel: [ 99.860461] ata1.01: XXX1 hardreset debounce 5 100 2000 Jun 30 10:02:26 HR-NETSWAP kernel: [ 100.211693] ata1.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 10:02:26 HR-NETSWAP kernel: [ 100.211741] ata1.02: hard resetting link Jun 30 10:02:26 HR-NETSWAP kernel: [ 100.211771] ata1.02: XXXX hardreset hotplugged = false Jun 30 10:02:26 HR-NETSWAP kernel: [ 100.211777] ata1.02: XXX0 hardreset debounce 5 100 2000 Jun 30 10:02:26 HR-NETSWAP kernel: [ 100.211783] ata1.02: XXX1 hardreset debounce 5 100 2000 Jun 30 10:02:27 HR-NETSWAP kernel: [ 100.560373] ata1.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 10:02:28 HR-NETSWAP kernel: [ 101.470023] ata1.03: hard resetting link Jun 30 10:02:28 HR-NETSWAP kernel: [ 101.470044] ata1.03: XXXX hardreset hotplugged = false Jun 30 10:02:28 HR-NETSWAP kernel: [ 101.470050] ata1.03: XXX0 hardreset debounce 5 100 2000 Jun 30 10:02:28 HR-NETSWAP kernel: [ 101.470056] ata1.03: XXX1 hardreset debounce 5 100 2000 Jun 30 10:02:28 HR-NETSWAP kernel: [ 101.820366] ata1.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 10:02:28 HR-NETSWAP kernel: [ 101.820409] ata1.04: hard resetting link Jun 30 10:02:28 HR-NETSWAP kernel: [ 101.820428] ata1.04: XXXX hardreset hotplugged = false Jun 30 10:02:28 HR-NETSWAP kernel: [ 101.820434] ata1.04: XXX0 hardreset debounce 5 100 2000 Jun 30 10:02:28 HR-NETSWAP kernel: [ 101.820439] ata1.04: XXX1 hardreset debounce 5 100 2000 Jun 30 10:02:28 HR-NETSWAP kernel: [ 102.170367] ata1.04: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 10:02:28 HR-NETSWAP kernel: [ 102.170409] ata1.05: hard resetting link Jun 30 10:02:28 HR-NETSWAP kernel: [ 102.170429] ata1.05: XXXX hardreset hotplugged = false Jun 30 10:02:28 HR-NETSWAP kernel: [ 102.170434] ata1.05: XXX0 hardreset debounce 5 100 2000 Jun 30 10:02:28 HR-NETSWAP kernel: [ 102.170440] ata1.05: XXX1 hardreset debounce 5 100 2000 Jun 30 10:02:29 HR-NETSWAP kernel: [ 102.521676] ata1.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) Jun 30 10:02:29 HR-NETSWAP kernel: [ 102.534788] ata1.00: configured for UDMA/100 Jun 30 10:02:29 HR-NETSWAP kernel: [ 102.544981] ata1.01: configured for UDMA/100 Jun 30 10:02:29 HR-NETSWAP kernel: [ 102.637647] ata1.02: configured for UDMA/100 Jun 30 10:02:29 HR-NETSWAP kernel: [ 102.637732] ata1.03: failed to IDENTIFY (I/O error, err_mask=0x11) Jun 30 10:02:29 HR-NETSWAP kernel: [ 102.637744] ata1.15: hard resetting link Jun 30 10:02:31 HR-NETSWAP kernel: [ 104.851295] ata1.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) Jun 30 10:02:31 HR-NETSWAP kernel: [ 104.851565] ata1.00: hard resetting link Jun 30 10:02:31 HR-NETSWAP kernel: [ 104.851585] ata1.00: XXXX hardreset hotplugged = false Jun 30 10:02:31 HR-NETSWAP kernel: [ 104.851591] ata1.00: XXX0 hardreset debounce 5 100 2000 Jun 30 10:02:31 HR-NETSWAP kernel: [ 104.851597] ata1.00: XXX1 hardreset debounce 5 100 2000 Jun 30 10:02:31 HR-NETSWAP kernel: [ 105.200371] ata1.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) Jun 30 10:02:31 HR-NETSWAP kernel: [ 105.200414] ata1.01: hard resetting link Jun 30 10:02:31 HR-NETSWAP kernel: [ 105.200434] ata1.01: XXXX hardreset hotplugged = false Jun 30 10:02:31 HR-NETSWAP kernel: [ 105.200440] ata1.01: XXX0 hardreset debounce 5 100 2000 Jun 30 10:02:31 HR-NETSWAP kernel: [ 105.200446] ata1.01: XXX1 hardreset debounce 5 100 2000 Jun 30 10:02:32 HR-NETSWAP kernel: [ 105.550374] ata1.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 10:02:32 HR-NETSWAP kernel: [ 105.550417] ata1.02: hard resetting link Jun 30 10:02:32 HR-NETSWAP kernel: [ 105.550437] ata1.02: XXXX hardreset hotplugged = false Jun 30 10:02:32 HR-NETSWAP kernel: [ 105.550442] ata1.02: XXX0 hardreset debounce 5 100 2000 Jun 30 10:02:32 HR-NETSWAP kernel: [ 105.550448] ata1.02: XXX1 hardreset debounce 5 100 2000 Jun 30 10:02:32 HR-NETSWAP kernel: [ 105.901675] ata1.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 10:02:33 HR-NETSWAP kernel: [ 106.821277] ata1.03: hard resetting link Jun 30 10:02:33 HR-NETSWAP kernel: [ 106.821299] ata1.03: XXXX hardreset hotplugged = false Jun 30 10:02:33 HR-NETSWAP kernel: [ 106.821305] ata1.03: XXX0 hardreset debounce 5 100 2000 Jun 30 10:02:33 HR-NETSWAP kernel: [ 106.821310] ata1.03: XXX1 hardreset debounce 5 100 2000 Jun 30 10:02:33 HR-NETSWAP kernel: [ 107.170377] ata1.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 10:02:33 HR-NETSWAP kernel: [ 107.170421] ata1.04: hard resetting link Jun 30 10:02:33 HR-NETSWAP kernel: [ 107.170441] ata1.04: XXXX hardreset hotplugged = false Jun 30 10:02:33 HR-NETSWAP kernel: [ 107.170447] ata1.04: XXX0 hardreset debounce 5 100 2000 Jun 30 10:02:33 HR-NETSWAP kernel: [ 107.170453] ata1.04: XXX1 hardreset debounce 5 100 2000 Jun 30 10:02:34 HR-NETSWAP kernel: [ 107.520377] ata1.04: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Jun 30 10:02:34 HR-NETSWAP kernel: [ 107.520420] ata1.05: hard resetting link Jun 30 10:02:34 HR-NETSWAP kernel: [ 107.520440] ata1.05: XXXX hardreset hotplugged = false Jun 30 10:02:34 HR-NETSWAP kernel: [ 107.520446] ata1.05: XXX0 hardreset debounce 5 100 2000 Jun 30 10:02:34 HR-NETSWAP kernel: [ 107.520451] ata1.05: XXX1 hardreset debounce 5 100 2000 Jun 30 10:02:34 HR-NETSWAP kernel: [ 107.870381] ata1.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) Jun 30 10:02:34 HR-NETSWAP kernel: [ 107.883447] ata1.00: configured for UDMA/100 Jun 30 10:02:34 HR-NETSWAP kernel: [ 107.893209] ata1.01: configured for UDMA/100 Jun 30 10:02:34 HR-NETSWAP kernel: [ 107.985315] ata1.02: configured for UDMA/100 Jun 30 10:02:34 HR-NETSWAP kernel: [ 108.009122] ata1.03: ATA-8: WDC WD30EZRX-00MMMB0, 80.00A80, max UDMA/133 Jun 30 10:02:34 HR-NETSWAP kernel: [ 108.009129] ata1.03: 5860533168 sectors, multi 0: LBA48 NCQ (depth 31/32) Jun 30 10:02:34 HR-NETSWAP kernel: [ 108.014862] ata1.03: configured for UDMA/100 Jun 30 10:02:34 HR-NETSWAP kernel: [ 108.017593] ata1.04: configured for UDMA/100 Jun 30 10:02:34 HR-NETSWAP kernel: [ 108.017672] ata1: EH complete Jun 30 10:02:34 HR-NETSWAP kernel: [ 108.020238] scsi 0:3:0:0: Direct-Access ATA WDC WD30EZRX-00M 80.0 PQ: 0 ANSI: 5 Jun 30 10:02:34 HR-NETSWAP kernel: [ 108.020715] sd 0:3:0:0: [sdd] 5860533168 512-byte logical blocks: (3.00 TB/2.72 TiB) Jun 30 10:02:34 HR-NETSWAP kernel: [ 108.020723] sd 0:3:0:0: [sdd] 4096-byte physical blocks Jun 30 10:02:34 HR-NETSWAP kernel: [ 108.020875] sd 0:3:0:0: [sdd] Write Protect is off Jun 30 10:02:34 HR-NETSWAP kernel: [ 108.020882] sd 0:3:0:0: [sdd] Mode Sense: 00 3a 00 00 Jun 30 10:02:34 HR-NETSWAP kernel: [ 108.020953] sd 0:3:0:0: [sdd] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA Jun 30 10:02:34 HR-NETSWAP kernel: [ 108.020999] sd 0:3:0:0: Attached scsi generic sg3 type 0 Jun 30 10:02:34 HR-NETSWAP kernel: [ 108.021384] sdd: sdd1 sdd2 Jun 30 10:02:34 HR-NETSWAP kernel: [ 108.072613] sd 0:3:0:0: [sdd] Attached SCSI disk >From the above we can see it finally connecting on the 4th try. > * hdparm -I output of the drive. > Info for two of the drives that fail regularly: Drive 1 Western Digital 3TB: /dev/sdb: ATA device, with non-removable media Model Number: WDC WD30EZRS-00J99B0 Serial Number: WD-WCAWZ0038962 Firmware Revision: 80.00A80 Transport: Serial, SATA 1.0a, SATA II Extensions, SATA Rev 2.5, SATA Rev 2.6 Standards: Supported: 8 7 6 5 Likely used: 8 Configuration: Logical max current cylinders 16383 16383 heads 16 16 sectors/track 63 63 -- CHS current addressable sectors: 16514064 LBA user addressable sectors: 268435455 LBA48 user addressable sectors: 5860533168 Logical Sector size: 512 bytes Physical Sector size: 4096 bytes Logical Sector-0 offset: 0 bytes device size with M = 1024*1024: 2861588 MBytes device size with M = 1000*1000: 3000592 MBytes (3000 GB) cache/buffer size = unknown Capabilities: LBA, IORDY(can be disabled) Queue depth: 32 Standby timer values: spec'd by Standard, with device specific minimum R/W multiple sector transfer: Max = 16 Current = 0 Recommended acoustic management value: 128, current value: 254 DMA: mdma0 mdma1 mdma2 udma0 udma1 udma2 udma3 udma4 *udma5 udma6 Cycle time: min=120ns recommended=120ns PIO: pio0 pio1 pio2 pio3 pio4 Cycle time: no flow control=120ns IORDY flow control=120ns Commands/features: Enabled Supported: * SMART feature set Security Mode feature set * Power Management feature set * Write cache * Look-ahead * Host Protected Area feature set * WRITE_BUFFER command * READ_BUFFER command * NOP cmd * DOWNLOAD_MICROCODE Power-Up In Standby feature set * SET_FEATURES required to spinup after power up SET_MAX security extension Automatic Acoustic Management feature set * 48-bit Address feature set * Device Configuration Overlay feature set * Mandatory FLUSH_CACHE * FLUSH_CACHE_EXT * SMART error logging * SMART self-test * General Purpose Logging feature set * 64-bit World wide name * {READ,WRITE}_DMA_EXT_GPL commands * Segmented DOWNLOAD_MICROCODE * Gen1 signaling speed (1.5Gb/s) * Gen2 signaling speed (3.0Gb/s) * Native Command Queueing (NCQ) * Host-initiated interface power management * Phy event counters * NCQ priority information DMA Setup Auto-Activate optimization * Software settings preservation * SMART Command Transport (SCT) feature set * SCT LBA Segment Access (AC2) * SCT Features Control (AC4) * SCT Data Tables (AC5) unknown 206[12] (vendor specific) unknown 206[13] (vendor specific) Security: Master password revision code = 65534 supported not enabled not locked not frozen not expired: security count supported: enhanced erase 508min for SECURITY ERASE UNIT. 508min for ENHANCED SECURITY ERASE UNIT. Logical Unit WWN Device Identifier: 50014ee2afe03ed4 NAA : 5 IEEE OUI : 0014ee Unique ID : 2afe03ed4 Checksum: correct Drive 2 Samsung 1.5 TB: /dev/sda: ATA device, with non-removable media Model Number: SAMSUNG HD154UI Serial Number: S1XWJ9BB102098 Firmware Revision: 1AG01118 Standards: Used: ATA-8-ACS revision 3b Supported: 7 6 5 4 Configuration: Logical max current cylinders 16383 16383 heads 16 16 sectors/track 63 63 -- CHS current addressable sectors: 16514064 LBA user addressable sectors: 268435455 LBA48 user addressable sectors: 2930277168 Logical/Physical Sector size: 512 bytes device size with M = 1024*1024: 1430799 MBytes device size with M = 1000*1000: 1500301 MBytes (1500 GB) cache/buffer size = unknown Capabilities: LBA, IORDY(can be disabled) Queue depth: 32 Standby timer values: spec'd by Standard, no device specific minimum R/W multiple sector transfer: Max = 16 Current = 0 Advanced power management level: 254 Recommended acoustic management value: 254, current value: 0 DMA: mdma0 mdma1 mdma2 udma0 udma1 udma2 udma3 udma4 *udma5 udma6 udma7 Cycle time: min=120ns recommended=120ns PIO: pio0 pio1 pio2 pio3 pio4 Cycle time: no flow control=120ns IORDY flow control=120ns Commands/features: Enabled Supported: * SMART feature set Security Mode feature set * Power Management feature set * Write cache * Look-ahead * Host Protected Area feature set * WRITE_BUFFER command * READ_BUFFER command * NOP cmd * DOWNLOAD_MICROCODE * Advanced Power Management feature set Power-Up In Standby feature set * SET_FEATURES required to spinup after power up SET_MAX security extension Automatic Acoustic Management feature set * 48-bit Address feature set * Device Configuration Overlay feature set * Mandatory FLUSH_CACHE * FLUSH_CACHE_EXT * SMART error logging * SMART self-test Media Card Pass-Through * General Purpose Logging feature set * 64-bit World wide name * WRITE_UNCORRECTABLE_EXT command * {READ,WRITE}_DMA_EXT_GPL commands * Segmented DOWNLOAD_MICROCODE * Gen1 signaling speed (1.5Gb/s) * Gen2 signaling speed (3.0Gb/s) * Native Command Queueing (NCQ) * Host-initiated interface power management * Phy event counters * NCQ priority information DMA Setup Auto-Activate optimization Device-initiated interface power management * Software settings preservation * SMART Command Transport (SCT) feature set * SCT Long Sector Access (AC1) * SCT LBA Segment Access (AC2) * SCT Error Recovery Control (AC3) * SCT Features Control (AC4) * SCT Data Tables (AC5) Security: Master password revision code = 65534 supported not enabled not locked not frozen not expired: security count supported: enhanced erase 324min for SECURITY ERASE UNIT. 324min for ENHANCED SECURITY ERASE UNIT. Logical Unit WWN Device Identifier: 50024e92046e42ff NAA : 5 IEEE OUI : 0024e9 Unique ID : 2046e42ff Checksum: correct > Thanks. > If need more info or want me to do more tests please let me know. Thanks. Derry Bryson Sr. Software Engineer Highly Reliable Systems www.High-Rely.com "Making Backup Invisible" Phone: 775.329.5139 X129 Fax: 775.370.1001 Sales & Support: 877.384.6838 This e-mail and any files transmitted with it are the property of Highly Reliable Systems, Inc. This (email) information is confidential, and is intended solely for the use of the individual or entity to whom this e-mail is addressed. If you are not one of the named recipient(s) or otherwise have reason to believe that you have received this message in error, please notify the sender and delete this message immediately from your computer. Any other use, disclosure, retention, dissemination, forwarding, printing, distribution or copying of this e-mail is strictly prohibited. ^ permalink raw reply [flat|nested] 35+ messages in thread
* Re: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) 2011-06-30 17:53 ` Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) Derry Bryson @ 2011-07-12 15:01 ` tj 2011-07-12 19:21 ` Derry Bryson 0 siblings, 1 reply; 35+ messages in thread From: tj @ 2011-07-12 15:01 UTC (permalink / raw) To: Derry Bryson; +Cc: linux-ide@vger.kernel.org Sorry about the long delay. On Thu, Jun 30, 2011 at 05:53:32PM +0000, Derry Bryson wrote: > I have included info from kern.log below showing turning the bay on and off before and > after I patched the kernel. kern.log tends to be too cluttered with extra timestamps. Can you please use 'dmesg -c' after each phase of testing? printk timestamps included there should be enough. > I first applied the patch from your previous email and changed the > second timing value to 1000 and that makes it work. It also works > if you leave the timing values alone and up the retries (i.e > ATA_EH_PMP_LINK_TRIES) from 3 to 5. It seems to me the drives are > taking a long (relatively) time to spin up and either way all we are > doing is giving it more time to spin up. That's debouncing timing. It doesn't have much to do with spinning up. Spinning up can take over ten seconds. PHY is usually ready well under a sec once power is applied. The reason why libata stops waiting during reset is because PHY flickers - it comes up and then goes out again. libata EH already debounces to work around these glitches but it seems this 'flickering' is larger scale than libata parameters expect. One suspicion I have is that the PSU in the enclosure isn't stable enough to maintain PHY state while multiples drives are powering up. If this is the case, PHYs may keep flickering well over a second which libata doesn't expect them to. Beefing up the PSU (or using a second PSU to power some of the harddrives) and see whether anything changes would be a good way to test it. > Is there some way to know it is spinning up and wait for that rather > than just trying to reset the controller over and over? Also I > notice from the kernel log that the 'hotplugged' flag is only set > the first time it does the hard reset and is then cleared. If this > didn't get cleared it may work that way as well. All of this only > fixes the problem until an slower drive comes out. The hotplugged timing is supposed to kick in only once after a hotplug event as some PHYs tend to take longer time to lock on after hotplug event. > From the SMART info on the drives for the WD 3TB that fails the spin > up value was 188 vs. a Seagate 160GB that was 87. I believe these > values are in milliseconds so we can see that the drive that fails > takes much longer to spin up. That's more likely centisecs instead of millisecs. 8.7sec would be about normal for regular drives. 18.8 isn't too far off for large ones with more platters. The more important thing probably is that the WD 3TB drive is likely to draw much more power than the smaller one taxing the PSU in the enclosure which could have been designed to have just enough power for more regular drives. > Jun 30 10:02:26 HR-NETSWAP kernel: [ 99.510350] ata1.00: XXXX hardreset hotplugged = false > Jun 30 10:02:26 HR-NETSWAP kernel: [ 99.510356] ata1.00: XXX0 hardreset debounce 5 100 2000 > Jun 30 10:02:26 HR-NETSWAP kernel: [ 99.510361] ata1.00: XXX1 hardreset debounce 5 100 2000 So if you bump the second timing value to 1000, it works without retrying? Can you please post kernel log w/ that change? Thanks. -- tejun ^ permalink raw reply [flat|nested] 35+ messages in thread
* RE: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) 2011-07-12 15:01 ` tj @ 2011-07-12 19:21 ` Derry Bryson 2011-07-13 13:34 ` tj 0 siblings, 1 reply; 35+ messages in thread From: Derry Bryson @ 2011-07-12 19:21 UTC (permalink / raw) To: tj@kernel.org; +Cc: linux-ide@vger.kernel.org > -----Original Message----- > From: Tejun Heo [mailto:htejun@gmail.com] On Behalf Of tj@kernel.org > Sent: Tuesday, July 12, 2011 8:01 AM > To: Derry Bryson > Cc: linux-ide@vger.kernel.org > Subject: Re: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) > > Sorry about the long delay. > > On Thu, Jun 30, 2011 at 05:53:32PM +0000, Derry Bryson wrote: > > I have included info from kern.log below showing turning the bay on > and off before and > > after I patched the kernel. > > kern.log tends to be too cluttered with extra timestamps. Can you > please use 'dmesg -c' after each phase of testing? printk timestamps > included there should be enough. > Will do in the future. > > I first applied the patch from your previous email and changed the > > second timing value to 1000 and that makes it work. It also works > > if you leave the timing values alone and up the retries (i.e > > ATA_EH_PMP_LINK_TRIES) from 3 to 5. It seems to me the drives are > > taking a long (relatively) time to spin up and either way all we are > > doing is giving it more time to spin up. > > That's debouncing timing. It doesn't have much to do with spinning > up. Spinning up can take over ten seconds. PHY is usually ready well > under a sec once power is applied. The reason why libata stops > waiting during reset is because PHY flickers - it comes up and then > goes out again. libata EH already debounces to work around these > glitches but it seems this 'flickering' is larger scale than libata > parameters expect. > > One suspicion I have is that the PSU in the enclosure isn't stable > enough to maintain PHY state while multiples drives are powering up. > If this is the case, PHYs may keep flickering well over a second which > libata doesn't expect them to. Beefing up the PSU (or using a second > PSU to power some of the harddrives) and see whether anything changes > would be a good way to test it. > I doubt it is a PSU issue for a couple of reasons: 1) all drives (5) are detected properly if I power the unit (external hard drive box, not computer) off and on, and 2) it fails the same way with only 1 drive in the unit. I will, however, try to test with a larger power supply tomorrow. > > Is there some way to know it is spinning up and wait for that rather > > than just trying to reset the controller over and over? Also I > > notice from the kernel log that the 'hotplugged' flag is only set > > the first time it does the hard reset and is then cleared. If this > > didn't get cleared it may work that way as well. All of this only > > fixes the problem until an slower drive comes out. > > The hotplugged timing is supposed to kick in only once after a hotplug > event as some PHYs tend to take longer time to lock on after hotplug > event. > > > From the SMART info on the drives for the WD 3TB that fails the spin > > up value was 188 vs. a Seagate 160GB that was 87. I believe these > > values are in milliseconds so we can see that the drive that fails > > takes much longer to spin up. > > That's more likely centisecs instead of millisecs. 8.7sec would be > about normal for regular drives. 18.8 isn't too far off for large > ones with more platters. The more important thing probably is that > the WD 3TB drive is likely to draw much more power than the smaller > one taxing the PSU in the enclosure which could have been designed to > have just enough power for more regular drives. > > > Jun 30 10:02:26 HR-NETSWAP kernel: [ 99.510350] ata1.00: XXXX > hardreset hotplugged = false > > Jun 30 10:02:26 HR-NETSWAP kernel: [ 99.510356] ata1.00: XXX0 > hardreset debounce 5 100 2000 > > Jun 30 10:02:26 HR-NETSWAP kernel: [ 99.510361] ata1.00: XXX1 > hardreset debounce 5 100 2000 > > So if you bump the second timing value to 1000, it works without > retrying? Can you please post kernel log w/ that change? > No, bumping the second timing value to 1000 does not cause it to work without retrying. Even bumping it up to 10000 does not work without retries (only bumping to 10000 on the first hotplug reset). Upping the number of retries to 5 without changing any timing works (on the 4th try) and changing the second timing value to 1000 without changing the number of retries works. It works if we try long enough (i.e. enough times or longer each time). Below are logs from hotplugging a Samsung 160GB and a WD 3TB drives with a kernel with stock timing values but retries changed from 3 to 5 with only the one drive installed. 160GB Samsung: [ 363.846588] ata5.00: exception Emask 0x10 SAct 0x0 SErr 0x4050000 action 0xf [ 363.856174] ata5.00: SError: { PHYRdyChg CommWake DevExch } [ 363.865884] ata5.00: hard resetting link [ 364.610400] ata5.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 364.610506] ata5.00: failed to IDENTIFY (I/O error, err_mask=0x11) [ 364.610515] ata5.15: hard resetting link [ 366.830050] ata5.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 369.610115] ata5.00: hard resetting link [ 369.960400] ata5.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 369.960446] ata5.01: hard resetting link [ 370.310393] ata5.01: SATA link down (SStatus 0 SControl 320) [ 370.310468] ata5.02: hard resetting link [ 370.660390] ata5.02: SATA link down (SStatus 0 SControl 320) [ 370.660467] ata5.03: hard resetting link [ 371.010405] ata5.03: SATA link down (SStatus 0 SControl 320) [ 371.010482] ata5.04: hard resetting link [ 371.360395] ata5.04: SATA link down (SStatus 0 SControl 320) [ 371.360471] ata5.05: hard resetting link [ 371.710398] ata5.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) [ 371.754495] ata5.00: ATA-7: ST3160815AS, 4.AAB, max UDMA/133 [ 371.754503] ata5.00: 312581808 sectors, multi 0: LBA48 NCQ (depth 31/32) [ 371.812838] ata5.00: configured for UDMA/100 [ 371.812925] ata5: EH complete [ 371.813118] scsi 2:0:0:0: Direct-Access ATA ST3160815AS 4.AA PQ: 0 ANSI: 5 [ 371.813561] sd 2:0:0:0: [sdb] 312581808 512-byte logical blocks: (160 GB/149 GiB) [ 371.813583] sd 2:0:0:0: Attached scsi generic sg1 type 0 [ 371.813732] sd 2:0:0:0: [sdb] Write Protect is off [ 371.813739] sd 2:0:0:0: [sdb] Mode Sense: 00 3a 00 00 [ 371.813810] sd 2:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [ 371.814219] sdb: sdb1 [ 371.861659] sd 2:0:0:0: [sdb] Attached SCSI disk 3TB WD: [ 1359.196664] ata5.00: exception Emask 0x10 SAct 0x0 SErr 0x4050000 action 0xf [ 1359.206398] ata5.00: SError: { PHYRdyChg CommWake DevExch } [ 1359.216282] ata5.00: hard resetting link [ 1359.960533] ata5.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 1359.960664] ata5.00: failed to IDENTIFY (I/O error, err_mask=0x11) [ 1359.960673] ata5.15: hard resetting link [ 1362.180058] ata5.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 1364.960050] ata5.00: hard resetting link [ 1365.320463] ata5.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 1365.320513] ata5.01: hard resetting link [ 1365.670458] ata5.01: SATA link down (SStatus 0 SControl 320) [ 1365.670536] ata5.02: hard resetting link [ 1366.020447] ata5.02: SATA link down (SStatus 0 SControl 320) [ 1366.020531] ata5.03: hard resetting link [ 1366.370447] ata5.03: SATA link down (SStatus 0 SControl 320) [ 1366.370529] ata5.04: hard resetting link [ 1366.720449] ata5.04: SATA link down (SStatus 0 SControl 320) [ 1366.720532] ata5.05: hard resetting link [ 1367.071698] ata5.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) [ 1367.071811] ata5.00: failed to IDENTIFY (I/O error, err_mask=0x11) [ 1367.071821] ata5.15: hard resetting link [ 1369.290060] ata5.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 1370.320045] ata5.00: hard resetting link [ 1370.670447] ata5.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 1372.070031] ata5.05: hard resetting link [ 1372.420462] ata5.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) [ 1372.420576] ata5.00: failed to IDENTIFY (I/O error, err_mask=0x11) [ 1372.420585] ata5.15: hard resetting link [ 1374.640051] ata5.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 1375.670038] ata5.00: hard resetting link [ 1376.020452] ata5.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 1376.020500] ata5.01: hard resetting link [ 1376.370454] ata5.01: SATA link down (SStatus 0 SControl 320) [ 1376.370535] ata5.02: hard resetting link [ 1376.730451] ata5.02: SATA link down (SStatus 0 SControl 320) [ 1376.730530] ata5.03: hard resetting link [ 1377.080467] ata5.03: SATA link down (SStatus 0 SControl 320) [ 1377.080545] ata5.04: hard resetting link [ 1377.430455] ata5.04: SATA link down (SStatus 0 SControl 320) [ 1377.430538] ata5.05: hard resetting link [ 1377.780454] ata5.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) [ 1377.804656] ata5.00: ATA-8: WDC WD30EZRX-00MMMB0, 80.00A80, max UDMA/133 [ 1377.804664] ata5.00: 5860533168 sectors, multi 0: LBA48 NCQ (depth 31/32) [ 1377.812240] ata5.00: configured for UDMA/100 [ 1377.812332] ata5: EH complete [ 1377.812529] scsi 4:0:0:0: Direct-Access ATA WDC WD30EZRX-00M 80.0 PQ: 0 ANSI: 5 [ 1377.813010] sd 4:0:0:0: Attached scsi generic sg1 type 0 [ 1377.813029] sd 4:0:0:0: [sdb] 5860533168 512-byte logical blocks: (3.00 TB/2.72 TiB) [ 1377.813047] sd 4:0:0:0: [sdb] 4096-byte physical blocks [ 1377.813191] sd 4:0:0:0: [sdb] Write Protect is off [ 1377.813199] sd 4:0:0:0: [sdb] Mode Sense: 00 3a 00 00 [ 1377.813271] sd 4:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [ 1377.813854] sdb: sdb1 sdb2 [ 1377.856633] sd 4:0:0:0: [sdb] Attached SCSI disk Here is a full power up with 5 drives installed showing all drives coming up, just for fun: [ 681.406102] ata5: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0xe frozen [ 681.414150] ata5: irq_stat 0x00a00080, device exchanged [ 681.422507] ata5: hard resetting link [ 683.640045] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 683.640317] ata5.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports, feat 0x1/0x9 [ 683.640571] ata5.00: hard resetting link [ 683.990395] ata5.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 683.990440] ata5.01: hard resetting link [ 684.340399] ata5.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 684.340444] ata5.02: hard resetting link [ 684.690366] ata5.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 684.690408] ata5.03: hard resetting link [ 685.040398] ata5.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 685.040440] ata5.04: hard resetting link [ 685.390396] ata5.04: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 685.390440] ata5.05: hard resetting link [ 685.740398] ata5.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) [ 685.740504] ata5.00: failed to IDENTIFY (I/O error, err_mask=0x11) [ 685.740514] ata5.15: hard resetting link [ 687.960045] ata5.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 688.990039] ata5.00: hard resetting link [ 689.340400] ata5.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 689.340447] ata5.01: hard resetting link [ 689.690371] ata5.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 689.690413] ata5.02: hard resetting link [ 690.040396] ata5.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 690.040441] ata5.03: hard resetting link [ 690.390394] ata5.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 690.390438] ata5.04: hard resetting link [ 690.740392] ata5.04: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 690.740436] ata5.05: hard resetting link [ 691.090370] ata5.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) [ 691.129944] ata5.00: ATA-7: ST3160815AS, 4.AAB, max UDMA/133 [ 691.129951] ata5.00: 312581808 sectors, multi 0: LBA48 NCQ (depth 31/32) [ 691.188279] ata5.00: configured for UDMA/100 [ 691.188349] ata5.01: failed to IDENTIFY (I/O error, err_mask=0x11) [ 691.188359] ata5.15: hard resetting link [ 693.400046] ata5.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 693.400334] ata5.00: hard resetting link [ 693.750395] ata5.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 694.690041] ata5.01: hard resetting link [ 695.040389] ata5.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 695.040432] ata5.02: hard resetting link [ 695.390390] ata5.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 695.390434] ata5.03: hard resetting link [ 695.740410] ata5.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 695.740454] ata5.04: hard resetting link [ 696.090370] ata5.04: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 696.090412] ata5.05: hard resetting link [ 696.440402] ata5.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) [ 696.528113] ata5.00: configured for UDMA/100 [ 696.528182] ata5.01: failed to IDENTIFY (I/O error, err_mask=0x11) [ 696.528191] ata5.15: hard resetting link [ 698.740047] ata5.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 698.740324] ata5.00: hard resetting link [ 699.090372] ata5.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 700.040037] ata5.01: hard resetting link [ 700.390398] ata5.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 700.390444] ata5.02: hard resetting link [ 700.740390] ata5.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 700.740434] ata5.03: hard resetting link [ 701.090372] ata5.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 701.090413] ata5.04: hard resetting link [ 701.440397] ata5.04: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 701.440442] ata5.05: hard resetting link [ 701.800393] ata5.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) [ 701.892633] ata5.00: configured for UDMA/100 [ 701.893390] ata5.01: ATA-8: ST33000651AS, CC44, max UDMA/133 [ 701.893397] ata5.01: 5860533168 sectors, multi 0: LBA48 NCQ (depth 31/32) [ 701.894287] ata5.01: configured for UDMA/100 [ 701.989689] ata5.02: ATA-8: WDC WD30EZRX-00MMMB0, 80.00A80, max UDMA/133 [ 701.989697] ata5.02: 5860533168 sectors, multi 0: LBA48 NCQ (depth 31/32) [ 701.997716] ata5.02: configured for UDMA/100 [ 702.003298] ata5.03: ATA-8: SAMSUNG HD502HJ, 1AJ10001, max UDMA/133 [ 702.003305] ata5.03: 976773168 sectors, multi 0: LBA48 NCQ (depth 31/32) [ 702.009010] ata5.03: configured for UDMA/100 [ 702.010263] ata5.04: ATA-8: ST320005XXXX, CC34, max UDMA/133 [ 702.010270] ata5.04: 3907029168 sectors, multi 0: LBA48 NCQ (depth 31/32) [ 702.011718] ata5.04: configured for UDMA/100 [ 702.011801] ata5: EH complete [ 702.011991] scsi 2:0:0:0: Direct-Access ATA ST3160815AS 4.AA PQ: 0 ANSI: 5 [ 702.012429] sd 2:0:0:0: [sdb] 312581808 512-byte logical blocks: (160 GB/149 GiB) [ 702.012445] sd 2:0:0:0: Attached scsi generic sg1 type 0 [ 702.012576] sd 2:0:0:0: [sdb] Write Protect is off [ 702.012583] sd 2:0:0:0: [sdb] Mode Sense: 00 3a 00 00 [ 702.012666] sd 2:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [ 702.013093] scsi 2:1:0:0: Direct-Access ATA ST33000651AS CC44 PQ: 0 ANSI: 5 [ 702.013112] sdb: [ 702.013617] sd 2:1:0:0: Attached scsi generic sg2 type 0 [ 702.013657] sd 2:1:0:0: [sdc] 5860533168 512-byte logical blocks: (3.00 TB/2.72 TiB) [ 702.013909] sd 2:1:0:0: [sdc] Write Protect is off [ 702.013920] sd 2:1:0:0: [sdc] Mode Sense: 00 3a 00 00 [ 702.014006] sd 2:1:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [ 702.014593] sdc: [ 702.015383] scsi 2:2:0:0: Direct-Access ATA WDC WD30EZRX-00M 80.0 PQ: 0 ANSI: 5 [ 702.015994] sd 2:2:0:0: Attached scsi generic sg3 type 0 [ 702.016399] scsi 2:3:0:0: Direct-Access ATA SAMSUNG HD502HJ 1AJ1 PQ: 0 ANSI: 5 [ 702.016899] sd 2:3:0:0: Attached scsi generic sg4 type 0 [ 702.017521] scsi 2:4:0:0: Direct-Access ATA ST320005XXXX CC34 PQ: 0 ANSI: 5 [ 702.018030] sd 2:4:0:0: Attached scsi generic sg5 type 0 [ 702.019837] sd 2:2:0:0: [sdd] 5860533168 512-byte logical blocks: (3.00 TB/2.72 TiB) [ 702.019847] sd 2:2:0:0: [sdd] 4096-byte physical blocks [ 702.020042] sd 2:2:0:0: [sdd] Write Protect is off [ 702.020062] sd 2:2:0:0: [sdd] Mode Sense: 00 3a 00 00 [ 702.020173] sd 2:2:0:0: [sdd] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [ 702.022614] sdd: [ 702.024184] sd 2:3:0:0: [sde] 976773168 512-byte logical blocks: (500 GB/465 GiB) [ 702.024378] sd 2:3:0:0: [sde] Write Protect is off [ 702.024388] sd 2:3:0:0: [sde] Mode Sense: 00 3a 00 00 [ 702.024482] sd 2:3:0:0: [sde] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [ 702.025055] sde: [ 702.028267] sd 2:4:0:0: [sdf] 3907029168 512-byte logical blocks: (2.00 TB/1.81 TiB) [ 702.030132] sd 2:4:0:0: [sdf] Write Protect is off [ 702.030146] sd 2:4:0:0: [sdf] Mode Sense: 00 3a 00 00 [ 702.030299] sd 2:4:0:0: [sdf] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [ 702.030853] sdf: sdb1 [ 702.033306] sde1 [ 702.033525] sd 2:0:0:0: [sdb] Attached SCSI disk [ 702.034960] sd 2:3:0:0: [sde] Attached SCSI disk [ 702.044906] sdf1 [ 702.080787] sd 2:4:0:0: [sdf] Attached SCSI disk [ 702.081308] sdd1 sdd2 [ 702.082147] sdc1 sdc2 [ 702.083703] sd 2:1:0:0: [sdc] Attached SCSI disk [ 702.083726] sd 2:2:0:0: [sdd] Attached SCSI disk I don't know what to try next. Thanks, Derry Bryson Sr. Software Engineer Highly Reliable Systems www.High-Rely.com "Making Backup Invisible" Phone: 775.329.5139 X129 Fax: 775.370.1001 Sales & Support: 877.384.6838 This e-mail and any files transmitted with it are the property of Highly Reliable Systems, Inc. This (email) information is confidential, and is intended solely for the use of the individual or entity to whom this e-mail is addressed. If you are not one of the named recipient(s) or otherwise have reason to believe that you have received this message in error, please notify the sender and delete this message immediately from your computer. Any other use, disclosure, retention, dissemination, forwarding, printing, distribution or copying of this e-mail is strictly prohibited. ^ permalink raw reply [flat|nested] 35+ messages in thread
* Re: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) 2011-07-12 19:21 ` Derry Bryson @ 2011-07-13 13:34 ` tj 2011-07-13 14:39 ` tj 0 siblings, 1 reply; 35+ messages in thread From: tj @ 2011-07-13 13:34 UTC (permalink / raw) To: Derry Bryson; +Cc: linux-ide@vger.kernel.org Hello, On Tue, Jul 12, 2011 at 07:21:17PM +0000, Derry Bryson wrote: > > One suspicion I have is that the PSU in the enclosure isn't stable > > enough to maintain PHY state while multiples drives are powering up. > > If this is the case, PHYs may keep flickering well over a second which > > libata doesn't expect them to. Beefing up the PSU (or using a second > > PSU to power some of the harddrives) and see whether anything changes > > would be a good way to test it. > > I doubt it is a PSU issue for a couple of reasons: 1) all drives (5) are > detected properly if I power the unit (external hard drive box, not computer) > off and on, and 2) it fails the same way with only 1 drive in the unit. > > I will, however, try to test with a larger power supply tomorrow. I see. Yeah, it doesn't seem to be PHY flickering. It looks like IDENTIFY is failing before disk finishes spinning up, which isn't the correct behavior. SRST is supposed to wait for disk spin up completion. I don't know why sil24 softreset is failing without waiting for spinup. I'll see whether I can reproduce the problem here. Thank you. -- tejun ^ permalink raw reply [flat|nested] 35+ messages in thread
* Re: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) 2011-07-13 13:34 ` tj @ 2011-07-13 14:39 ` tj 2011-07-13 16:23 ` Derry Bryson 0 siblings, 1 reply; 35+ messages in thread From: tj @ 2011-07-13 14:39 UTC (permalink / raw) To: Derry Bryson; +Cc: linux-ide@vger.kernel.org Hello, again. On Wed, Jul 13, 2011 at 03:34:25PM +0200, tj@kernel.org wrote: > I see. Yeah, it doesn't seem to be PHY flickering. It looks like > IDENTIFY is failing before disk finishes spinning up, which isn't the > correct behavior. SRST is supposed to wait for disk spin up > completion. I don't know why sil24 softreset is failing without > waiting for spinup. I'll see whether I can reproduce the problem > here. I played with it a bit but couldn't reproduce the problem; however, PMP EH does lack per-device retry back-off. On host ports, when reset/identification fails for whatever reason, retry is backed off such that even if controller/device interaction is faulty during spin up, EH always retries after sufficient time is given to the device. With PMP EH, this logic is missing partly because PMP EH sometimes already takes too long and partly because tracking the timestamps seemed a bit complex during the initial implementation. So, this definitely contributes to why PMP EH fails to work around the misinteraction between the drive and port and should probably be improved, but let's also find out why the controller isn't waiting for the drive after issuing IDENTIFY. Can you please apply the following patch, reproduce the problem and report the kernel log? Thank you. diff --git a/drivers/ata/sata_sil24.c b/drivers/ata/sata_sil24.c index 06c564e..cbd3475 100644 --- a/drivers/ata/sata_sil24.c +++ b/drivers/ata/sata_sil24.c @@ -896,6 +896,9 @@ static unsigned int sil24_qc_issue(struct ata_queued_cmd *qc) dma_addr_t paddr; void __iomem *activate; + if (qc->tf.command == ATA_CMD_ID_ATA) + ata_dev_printk(qc->dev, KERN_INFO, "issuing IDENTIFY\n"); + paddr = pp->cmd_block_dma + tag * sizeof(*pp->cmd_block); activate = port + PORT_CMD_ACTIVATE + tag * 8; @@ -1081,9 +1084,12 @@ static void sil24_error_intr(struct ata_port *ap) } /* record error info */ - if (qc) + if (qc) { + if (qc->tf.command == ATA_CMD_ID_ATA) + ata_dev_printk(qc->dev, KERN_INFO, "IDENTIFY failed, irq_stat=%#0x cerr=%u\n", + irq_stat, cerr); qc->err_mask |= err_mask; - else + } else ehi->err_mask |= err_mask; ehi->action |= action; ^ permalink raw reply related [flat|nested] 35+ messages in thread
* RE: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) 2011-07-13 14:39 ` tj @ 2011-07-13 16:23 ` Derry Bryson 2011-07-14 7:14 ` tj 0 siblings, 1 reply; 35+ messages in thread From: Derry Bryson @ 2011-07-13 16:23 UTC (permalink / raw) To: tj@kernel.org; +Cc: linux-ide@vger.kernel.org Hi: Here is the result after the patch of hotplugging WD 3TB drive (only drive): [ 92.201163] ata1.02: exception Emask 0x10 SAct 0x0 SErr 0x4050000 action 0xf [ 92.210719] ata1.02: SError: { PHYRdyChg CommWake DevExch } [ 92.220365] ata1.02: hard resetting link [ 92.980398] ata1.02: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 92.980449] ata1.02: issuing IDENTIFY [ 92.980476] ata1.02: IDENTIFY failed, irq_stat=0x60002 cerr=4 [ 92.980517] ata1.02: failed to IDENTIFY (I/O error, err_mask=0x11) [ 92.980526] ata1.15: hard resetting link [ 95.200045] ata1.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 95.200327] ata1.00: hard resetting link [ 95.640059] ata1.00: link resume succeeded after 1 retries [ 95.760404] ata1.00: SATA link down (SStatus 0 SControl 310) [ 95.760481] ata1.01: hard resetting link [ 96.110392] ata1.01: SATA link down (SStatus 0 SControl 320) [ 97.980042] ata1.02: hard resetting link [ 98.330391] ata1.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 98.330437] ata1.03: hard resetting link [ 98.680386] ata1.03: SATA link down (SStatus 0 SControl 320) [ 98.680461] ata1.04: hard resetting link [ 99.030393] ata1.04: SATA link down (SStatus 0 SControl 320) [ 99.030468] ata1.05: hard resetting link [ 99.390388] ata1.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) [ 99.390438] ata1.02: issuing IDENTIFY [ 99.390464] ata1.02: IDENTIFY failed, irq_stat=0x60002 cerr=4 [ 99.390506] ata1.02: failed to IDENTIFY (I/O error, err_mask=0x11) [ 99.390515] ata1.15: hard resetting link [ 101.610048] ata1.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 101.610325] ata1.00: hard resetting link [ 102.050070] ata1.00: link resume succeeded after 1 retries [ 102.170389] ata1.00: SATA link down (SStatus 0 SControl 310) [ 102.170466] ata1.01: hard resetting link [ 102.520390] ata1.01: SATA link down (SStatus 0 SControl 320) [ 103.330025] ata1.02: hard resetting link [ 103.680391] ata1.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 104.390026] ata1.05: hard resetting link [ 104.740391] ata1.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) [ 104.740442] ata1.02: issuing IDENTIFY [ 104.740468] ata1.02: IDENTIFY failed, irq_stat=0x60002 cerr=4 [ 104.740510] ata1.02: failed to IDENTIFY (I/O error, err_mask=0x11) [ 104.740518] ata1.15: hard resetting link [ 106.960046] ata1.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 106.960329] ata1.00: hard resetting link [ 107.400059] ata1.00: link resume succeeded after 1 retries [ 107.520397] ata1.00: SATA link down (SStatus 0 SControl 310) [ 107.520472] ata1.01: hard resetting link [ 107.870392] ata1.01: SATA link down (SStatus 0 SControl 320) [ 108.680021] ata1.02: hard resetting link [ 109.030393] ata1.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 109.030439] ata1.03: hard resetting link [ 109.380397] ata1.03: SATA link down (SStatus 0 SControl 320) [ 109.380473] ata1.04: hard resetting link [ 109.730395] ata1.04: SATA link down (SStatus 0 SControl 320) [ 109.741269] ata1.05: hard resetting link [ 110.090393] ata1.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) [ 110.090443] ata1.02: issuing IDENTIFY [ 110.118499] ata1.02: ATA-8: WDC WD30EZRX-00MMMB0, 80.00A80, max UDMA/133 [ 110.118506] ata1.02: 5860533168 sectors, multi 0: LBA48 NCQ (depth 31/32) [ 110.118642] ata1.02: issuing IDENTIFY [ 110.123817] ata1.02: configured for UDMA/100 [ 110.123904] ata1: EH complete [ 110.124108] scsi 0:2:0:0: Direct-Access ATA WDC WD30EZRX-00M 80.0 PQ: 0 ANSI: 5 [ 110.124554] sd 0:2:0:0: [sda] 5860533168 512-byte logical blocks: (3.00 TB/2.72 TiB) [ 110.124578] sd 0:2:0:0: Attached scsi generic sg0 type 0 [ 110.124596] sd 0:2:0:0: [sda] 4096-byte physical blocks [ 110.124735] sd 0:2:0:0: [sda] Write Protect is off [ 110.124742] sd 0:2:0:0: [sda] Mode Sense: 00 3a 00 00 [ 110.124813] sd 0:2:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [ 110.125220] sda: sda1 sda2 [ 110.170313] sd 0:2:0:0: [sda] Attached SCSI disk [ 110.172439] ata1.02: issuing IDENTIFY [ 110.250997] ata1.02: issuing IDENTIFY [ 110.274885] ata1.02: issuing IDENTIFY > -----Original Message----- > From: Tejun Heo [mailto:htejun@gmail.com] On Behalf Of tj@kernel.org > Sent: Wednesday, July 13, 2011 7:40 AM > To: Derry Bryson > Cc: linux-ide@vger.kernel.org > Subject: Re: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) > > Hello, again. > > On Wed, Jul 13, 2011 at 03:34:25PM +0200, tj@kernel.org wrote: > > I see. Yeah, it doesn't seem to be PHY flickering. It looks like > > IDENTIFY is failing before disk finishes spinning up, which isn't the > > correct behavior. SRST is supposed to wait for disk spin up > > completion. I don't know why sil24 softreset is failing without > > waiting for spinup. I'll see whether I can reproduce the problem > > here. > > I played with it a bit but couldn't reproduce the problem; however, > PMP EH does lack per-device retry back-off. On host ports, when > reset/identification fails for whatever reason, retry is backed off > such that even if controller/device interaction is faulty during spin > up, EH always retries after sufficient time is given to the device. > With PMP EH, this logic is missing partly because PMP EH sometimes > already takes too long and partly because tracking the timestamps > seemed a bit complex during the initial implementation. > > So, this definitely contributes to why PMP EH fails to work around the > misinteraction between the drive and port and should probably be > improved, but let's also find out why the controller isn't waiting for > the drive after issuing IDENTIFY. Can you please apply the following > patch, reproduce the problem and report the kernel log? > > Thank you. > > diff --git a/drivers/ata/sata_sil24.c b/drivers/ata/sata_sil24.c > index 06c564e..cbd3475 100644 > --- a/drivers/ata/sata_sil24.c > +++ b/drivers/ata/sata_sil24.c > @@ -896,6 +896,9 @@ static unsigned int sil24_qc_issue(struct > ata_queued_cmd *qc) > dma_addr_t paddr; > void __iomem *activate; > > + if (qc->tf.command == ATA_CMD_ID_ATA) > + ata_dev_printk(qc->dev, KERN_INFO, "issuing IDENTIFY\n"); > + > paddr = pp->cmd_block_dma + tag * sizeof(*pp->cmd_block); > activate = port + PORT_CMD_ACTIVATE + tag * 8; > > @@ -1081,9 +1084,12 @@ static void sil24_error_intr(struct ata_port > *ap) > } > > /* record error info */ > - if (qc) > + if (qc) { > + if (qc->tf.command == ATA_CMD_ID_ATA) > + ata_dev_printk(qc->dev, KERN_INFO, "IDENTIFY > failed, irq_stat=%#0x cerr=%u\n", > + irq_stat, cerr); > qc->err_mask |= err_mask; > - else > + } else > ehi->err_mask |= err_mask; > > ehi->action |= action; > > > ----- > No virus found in this message. > Checked by AVG - www.avg.com > Version: 10.0.1390 / Virus Database: 1516/3761 - Release Date: 07/12/11 Derry Bryson Sr. Software Engineer Highly Reliable Systems www.High-Rely.com "Making Backup Invisible" Phone: 775.329.5139 X129 Fax: 775.370.1001 Sales & Support: 877.384.6838 This e-mail and any files transmitted with it are the property of Highly Reliable Systems, Inc. This (email) information is confidential, and is intended solely for the use of the individual or entity to whom this e-mail is addressed. If you are not one of the named recipient(s) or otherwise have reason to believe that you have received this message in error, please notify the sender and delete this message immediately from your computer. Any other use, disclosure, retention, dissemination, forwarding, printing, distribution or copying of this e-mail is strictly prohibited. ^ permalink raw reply [flat|nested] 35+ messages in thread
* Re: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) 2011-07-13 16:23 ` Derry Bryson @ 2011-07-14 7:14 ` tj 2011-07-14 17:37 ` Derry Bryson 0 siblings, 1 reply; 35+ messages in thread From: tj @ 2011-07-14 7:14 UTC (permalink / raw) To: Derry Bryson; +Cc: linux-ide@vger.kernel.org Hello, On Wed, Jul 13, 2011 at 04:23:27PM +0000, Derry Bryson wrote: > [ 92.980476] ata1.02: IDENTIFY failed, irq_stat=0x60002 cerr=4 The controller is saying that it failed to transmit command FIS because PHYRDY state changed, so that is PHY flickering. Can you please bump the second debounce timing to 1000 (not only the first one but always) and see whether the failure pattern changes? Thanks. -- tejun ^ permalink raw reply [flat|nested] 35+ messages in thread
* RE: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) 2011-07-14 7:14 ` tj @ 2011-07-14 17:37 ` Derry Bryson 2011-07-21 9:00 ` tj 0 siblings, 1 reply; 35+ messages in thread From: Derry Bryson @ 2011-07-14 17:37 UTC (permalink / raw) To: tj@kernel.org; +Cc: linux-ide@vger.kernel.org Hi: Dmesg with second timing value set to 1000 always, hotplugging WD 3TB drive: [ 139.145917] ata5.00: exception Emask 0x10 SAct 0x0 SErr 0x4050000 action 0xf [ 139.156180] ata5.00: SError: { PHYRdyChg CommWake DevExch } [ 139.166619] ata5.00: hard resetting link [ 139.166639] ata5.00: XXXX hardreset hotplugged = true [ 139.166646] ata5.00: XXX0 hardreset debounce 25 500 2000 [ 139.166651] ata5.00: XXX1 hardreset debounce 25 1000 2000 [ 140.430401] ata5.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 140.430453] ata5.00: issuing IDENTIFY [ 140.430480] ata5.00: IDENTIFY failed, irq_stat=0x60002 cerr=4 [ 140.430521] ata5.00: failed to IDENTIFY (I/O error, err_mask=0x11) [ 140.430532] ata5.15: hard resetting link [ 142.650047] ata5.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 145.431276] ata5.00: hard resetting link [ 145.431298] ata5.00: XXXX hardreset hotplugged = false [ 145.431304] ata5.00: XXX0 hardreset debounce 5 100 2000 [ 145.431310] ata5.00: XXX1 hardreset debounce 5 1000 2000 [ 146.690413] ata5.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 146.690461] ata5.01: hard resetting link [ 146.690481] ata5.01: XXXX hardreset hotplugged = false [ 146.690487] ata5.01: XXX0 hardreset debounce 5 100 2000 [ 146.690492] ata5.01: XXX1 hardreset debounce 5 1000 2000 [ 147.940402] ata5.01: SATA link down (SStatus 0 SControl 320) [ 147.940481] ata5.02: hard resetting link [ 147.940501] ata5.02: XXXX hardreset hotplugged = false [ 147.940507] ata5.02: XXX0 hardreset debounce 5 100 2000 [ 147.940513] ata5.02: XXX1 hardreset debounce 5 1000 2000 [ 149.190398] ata5.02: SATA link down (SStatus 0 SControl 320) [ 149.190476] ata5.03: hard resetting link [ 149.190497] ata5.03: XXXX hardreset hotplugged = false [ 149.190503] ata5.03: XXX0 hardreset debounce 5 100 2000 [ 149.190508] ata5.03: XXX1 hardreset debounce 5 1000 2000 [ 150.440399] ata5.03: SATA link down (SStatus 0 SControl 320) [ 150.440478] ata5.04: hard resetting link [ 150.440499] ata5.04: XXXX hardreset hotplugged = false [ 150.440505] ata5.04: XXX0 hardreset debounce 5 100 2000 [ 150.440510] ata5.04: XXX1 hardreset debounce 5 1000 2000 [ 151.690410] ata5.04: SATA link down (SStatus 0 SControl 320) [ 151.690488] ata5.05: hard resetting link [ 151.690509] ata5.05: XXXX hardreset hotplugged = false [ 151.690515] ata5.05: XXX0 hardreset debounce 5 100 2000 [ 151.690520] ata5.05: XXX1 hardreset debounce 5 1000 2000 [ 152.940399] ata5.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) [ 152.940451] ata5.00: issuing IDENTIFY [ 152.940477] ata5.00: IDENTIFY failed, irq_stat=0x60002 cerr=4 [ 152.940518] ata5.00: failed to IDENTIFY (I/O error, err_mask=0x11) [ 152.940529] ata5.15: hard resetting link [ 155.160047] ata5.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 155.160327] ata5.00: hard resetting link [ 155.160347] ata5.00: XXXX hardreset hotplugged = false [ 155.160353] ata5.00: XXX0 hardreset debounce 5 100 2000 [ 155.160358] ata5.00: XXX1 hardreset debounce 5 1000 2000 [ 156.410398] ata5.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 157.940026] ata5.05: hard resetting link [ 157.940048] ata5.05: XXXX hardreset hotplugged = false [ 157.940054] ata5.05: XXX0 hardreset debounce 5 100 2000 [ 157.940059] ata5.05: XXX1 hardreset debounce 5 1000 2000 [ 159.190398] ata5.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) [ 159.190450] ata5.00: issuing IDENTIFY [ 159.199553] ata5.00: ATA-8: WDC WD30EZRX-00MMMB0, 80.00A80, max UDMA/133 [ 159.199560] ata5.00: 5860533168 sectors, multi 0: LBA48 NCQ (depth 31/32) [ 159.199702] ata5.00: issuing IDENTIFY [ 159.205571] ata5.00: configured for UDMA/100 [ 159.205661] ata5: EH complete [ 159.205857] scsi 4:0:0:0: Direct-Access ATA WDC WD30EZRX-00M 80.0 PQ: 0 ANSI: 5 [ 159.206297] sd 4:0:0:0: [sdb] 5860533168 512-byte logical blocks: (3.00 TB/2.72 TiB) [ 159.206305] sd 4:0:0:0: [sdb] 4096-byte physical blocks [ 159.206319] sd 4:0:0:0: Attached scsi generic sg1 type 0 [ 159.206440] sd 4:0:0:0: [sdb] Write Protect is off [ 159.206447] sd 4:0:0:0: [sdb] Mode Sense: 00 3a 00 00 [ 159.206519] sd 4:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [ 159.206938] sdb: sdb1 sdb2 [ 159.251508] sd 4:0:0:0: [sdb] Attached SCSI disk [ 159.254218] ata5.00: issuing IDENTIFY [ 159.330233] ata5.00: issuing IDENTIFY [ 159.350570] ata5.00: issuing IDENTIFY > -----Original Message----- > From: Tejun Heo [mailto:htejun@gmail.com] On Behalf Of tj@kernel.org > Sent: Thursday, July 14, 2011 12:15 AM > To: Derry Bryson > Cc: linux-ide@vger.kernel.org > Subject: Re: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) > > Hello, > > On Wed, Jul 13, 2011 at 04:23:27PM +0000, Derry Bryson wrote: > > [ 92.980476] ata1.02: IDENTIFY failed, irq_stat=0x60002 cerr=4 > > The controller is saying that it failed to transmit command FIS > because PHYRDY state changed, so that is PHY flickering. Can you > please bump the second debounce timing to 1000 (not only the first one > but always) and see whether the failure pattern changes? > > Thanks. > > -- > tejun > Derry Bryson Sr. Software Engineer Highly Reliable Systems www.High-Rely.com "Making Backup Invisible" Phone: 775.329.5139 X129 Fax: 775.370.1001 Sales & Support: 877.384.6838 This e-mail and any files transmitted with it are the property of Highly Reliable Systems, Inc. This (email) information is confidential, and is intended solely for the use of the individual or entity to whom this e-mail is addressed. If you are not one of the named recipient(s) or otherwise have reason to believe that you have received this message in error, please notify the sender and delete this message immediately from your computer. Any other use, disclosure, retention, dissemination, forwarding, printing, distribution or copying of this e-mail is strictly prohibited. ^ permalink raw reply [flat|nested] 35+ messages in thread
* Re: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) 2011-07-14 17:37 ` Derry Bryson @ 2011-07-21 9:00 ` tj 2011-07-21 16:22 ` Derry Bryson 0 siblings, 1 reply; 35+ messages in thread From: tj @ 2011-07-21 9:00 UTC (permalink / raw) To: Derry Bryson; +Cc: linux-ide@vger.kernel.org On Thu, Jul 14, 2011 at 05:37:37PM +0000, Derry Bryson wrote: > Hi: > > Dmesg with second timing value set to 1000 always, hotplugging WD 3TB drive: > > [ 139.145917] ata5.00: exception Emask 0x10 SAct 0x0 SErr 0x4050000 action 0xf > [ 139.156180] ata5.00: SError: { PHYRdyChg CommWake DevExch } > [ 139.166619] ata5.00: hard resetting link > [ 140.430401] ata5.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) > [ 140.430453] ata5.00: issuing IDENTIFY > [ 140.430480] ata5.00: IDENTIFY failed, irq_stat=0x60002 cerr=4 > [ 140.430521] ata5.00: failed to IDENTIFY (I/O error, err_mask=0x11) ... > [ 145.431276] ata5.00: hard resetting link > [ 145.431298] ata5.00: XXXX hardreset hotplugged = false > [ 145.431304] ata5.00: XXX0 hardreset debounce 5 100 2000 > [ 145.431310] ata5.00: XXX1 hardreset debounce 5 1000 2000 > [ 146.690413] ata5.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) ... > [ 152.940451] ata5.00: issuing IDENTIFY > [ 152.940477] ata5.00: IDENTIFY failed, irq_stat=0x60002 cerr=4 > [ 152.940518] ata5.00: failed to IDENTIFY (I/O error, err_mask=0x11) So, no change. Weird. I think we need to implement retry backoff properly anyways but am still wondering why probing failure behaves differently for you. I'll try with similar drive but maybe it's difference in PMP firmware? Thanks. -- tejun ^ permalink raw reply [flat|nested] 35+ messages in thread
* RE: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) 2011-07-21 9:00 ` tj @ 2011-07-21 16:22 ` Derry Bryson 2011-07-22 9:50 ` tj 0 siblings, 1 reply; 35+ messages in thread From: Derry Bryson @ 2011-07-21 16:22 UTC (permalink / raw) To: tj@kernel.org; +Cc: linux-ide@vger.kernel.org Tejun: Here are the specs on the port multiplier board: Lycom ST-126RM (http://www.lycom.com.tw/) Sil3726 chip revision 17 EEPROM FW Version: 1.0114 Also there is another problem: ports that are not connected at power on are ignored until a port that was connected at power on is hotplugged. So, for instance, if I turn the unit on with only a drive on the first port, the other four ports will not work and I don't even see kernel messages when hotplugging until I hotplug the first port. I haven't looked into this yet, but it would seem the driver must be disabling the ports and they are not looked at again until the hard reset is performed. Let me know if I can help in any way. Thanks, Derry Bryson Sr. Software Engineer Highly Reliable Systems www.High-Rely.com "Making Backup Invisible" Phone: 775.329.5139 X129 Fax: 775.370.1001 Sales & Support: 877.384.6838 This e-mail and any files transmitted with it are the property of Highly Reliable Systems, Inc. This (email) information is confidential, and is intended solely for the use of the individual or entity to whom this e-mail is addressed. If you are not one of the named recipient(s) or otherwise have reason to believe that you have received this message in error, please notify the sender and delete this message immediately from your computer. Any other use, disclosure, retention, dissemination, forwarding, printing, distribution or copying of this e-mail is strictly prohibited. > -----Original Message----- > From: Tejun Heo [mailto:htejun@gmail.com] On Behalf Of tj@kernel.org > Sent: Thursday, July 21, 2011 2:00 AM > To: Derry Bryson > Cc: linux-ide@vger.kernel.org > Subject: Re: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) > > On Thu, Jul 14, 2011 at 05:37:37PM +0000, Derry Bryson wrote: > > Hi: > > > > Dmesg with second timing value set to 1000 always, hotplugging WD 3TB > drive: > > > > [ 139.145917] ata5.00: exception Emask 0x10 SAct 0x0 SErr 0x4050000 > action 0xf > > [ 139.156180] ata5.00: SError: { PHYRdyChg CommWake DevExch } > > [ 139.166619] ata5.00: hard resetting link > > [ 140.430401] ata5.00: SATA link up 3.0 Gbps (SStatus 123 SControl > 320) > > [ 140.430453] ata5.00: issuing IDENTIFY > > [ 140.430480] ata5.00: IDENTIFY failed, irq_stat=0x60002 cerr=4 > > [ 140.430521] ata5.00: failed to IDENTIFY (I/O error, err_mask=0x11) > ... > > [ 145.431276] ata5.00: hard resetting link > > [ 145.431298] ata5.00: XXXX hardreset hotplugged = false > > [ 145.431304] ata5.00: XXX0 hardreset debounce 5 100 2000 > > [ 145.431310] ata5.00: XXX1 hardreset debounce 5 1000 2000 > > [ 146.690413] ata5.00: SATA link up 3.0 Gbps (SStatus 123 SControl > 320) > ... > > [ 152.940451] ata5.00: issuing IDENTIFY > > [ 152.940477] ata5.00: IDENTIFY failed, irq_stat=0x60002 cerr=4 > > [ 152.940518] ata5.00: failed to IDENTIFY (I/O error, err_mask=0x11) > > So, no change. Weird. I think we need to implement retry backoff > properly anyways but am still wondering why probing failure behaves > differently for you. I'll try with similar drive but maybe it's > difference in PMP firmware? > > Thanks. > > -- > tejun > > > ----- > No virus found in this message. > Checked by AVG - www.avg.com > Version: 10.0.1390 / Virus Database: 1518/3777 - Release Date: 07/20/11 ^ permalink raw reply [flat|nested] 35+ messages in thread
* Re: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) 2011-07-21 16:22 ` Derry Bryson @ 2011-07-22 9:50 ` tj 2011-07-22 17:29 ` Derry Bryson 2011-07-22 19:34 ` Derry Bryson 0 siblings, 2 replies; 35+ messages in thread From: tj @ 2011-07-22 9:50 UTC (permalink / raw) To: Derry Bryson; +Cc: linux-ide@vger.kernel.org Hello, On Thu, Jul 21, 2011 at 04:22:07PM +0000, Derry Bryson wrote: > Here are the specs on the port multiplier board: > > Lycom ST-126RM (http://www.lycom.com.tw/) > Sil3726 chip revision 17 > EEPROM FW Version: 1.0114 > > Also there is another problem: ports that are not connected at power on > are ignored until a port that was connected at power on is hotplugged. So, > for instance, if I turn the unit on with only a drive on the first port, the > other four ports will not work and I don't even see kernel messages when > hotplugging until I hotplug the first port. I haven't looked into this yet, > but it would seem the driver must be disabling the ports and they are not > looked at again until the hard reset is performed. That's most likely the sil pmp itself. It has been known to show erratic behavior if the first port is not occupied during power up. I don't know whether later firmware updates fixed that tho. Can you get hold of a marvell PMP and see how it behaves? Thanks. -- tejun ^ permalink raw reply [flat|nested] 35+ messages in thread
* RE: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) 2011-07-22 9:50 ` tj @ 2011-07-22 17:29 ` Derry Bryson 2011-07-22 19:34 ` Derry Bryson 1 sibling, 0 replies; 35+ messages in thread From: Derry Bryson @ 2011-07-22 17:29 UTC (permalink / raw) To: tj@kernel.org; +Cc: linux-ide@vger.kernel.org > -----Original Message----- > From: Tejun Heo [mailto:htejun@gmail.com] On Behalf Of tj@kernel.org > Sent: Friday, July 22, 2011 2:51 AM > To: Derry Bryson > Cc: linux-ide@vger.kernel.org > Subject: Re: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) > > Hello, > > On Thu, Jul 21, 2011 at 04:22:07PM +0000, Derry Bryson wrote: > > Here are the specs on the port multiplier board: > > > > Lycom ST-126RM (http://www.lycom.com.tw/) > > Sil3726 chip revision 17 > > EEPROM FW Version: 1.0114 > > > > Also there is another problem: ports that are not connected at power > on > > are ignored until a port that was connected at power on is > hotplugged. So, > > for instance, if I turn the unit on with only a drive on the first > port, the > > other four ports will not work and I don't even see kernel messages > when > > hotplugging until I hotplug the first port. I haven't looked into > this yet, > > but it would seem the driver must be disabling the ports and they are > not > > looked at again until the hard reset is performed. > > That's most likely the sil pmp itself. It has been known to show > erratic behavior if the first port is not occupied during power up. I > don't know whether later firmware updates fixed that tho. Can you get > hold of a marvell PMP and see how it behaves? > That may well be a problem, but is not the problem in this case since it is not limited to port 0. Seems like the sil driver or pmp code in the kernel is disabling the ports that are not connected at pmp power on and not looking at them again until we hotplug one of the ports that was connected and cause a hard reset or something like that. For instance, I turn off the pmp unit and connect drives to ports 0, 1, and 2 then power on the unit. Linux sees the pmp unit and finds the three drives. Then I connect a drive to port 3 and Linux reports nothing. No interrupts, no nothing. Same with port 4. However if I connect a drive to port 3 or 4 (or both) and hotplug the a drive on any of ports 0, 1, or 2 now the drives are detected after the hard reset. This hardware works fine under Windows, hotplugging drives and powering the unit off and on, etc. using the same Sil3124 eSATA PCI controller. No problems, so I think the hardware is okay. I don't know of nor have a Marvell PMP, but I do have another Sil3726 PMP board with newer firmware and a board with a JMicron PMP that I am going to test with. Thanks for your help. Derry Bryson Sr. Software Engineer Highly Reliable Systems www.High-Rely.com "Making Backup Invisible" Phone: 775.329.5139 X129 Fax: 775.370.1001 Sales & Support: 877.384.6838 This e-mail and any files transmitted with it are the property of Highly Reliable Systems, Inc. This (email) information is confidential, and is intended solely for the use of the individual or entity to whom this e-mail is addressed. If you are not one of the named recipient(s) or otherwise have reason to believe that you have received this message in error, please notify the sender and delete this message immediately from your computer. Any other use, disclosure, retention, dissemination, forwarding, printing, distribution or copying of this e-mail is strictly prohibited. ^ permalink raw reply [flat|nested] 35+ messages in thread
* RE: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) 2011-07-22 9:50 ` tj 2011-07-22 17:29 ` Derry Bryson @ 2011-07-22 19:34 ` Derry Bryson 2011-07-30 12:54 ` tj 1 sibling, 1 reply; 35+ messages in thread From: Derry Bryson @ 2011-07-22 19:34 UTC (permalink / raw) To: tj@kernel.org; +Cc: linux-ide@vger.kernel.org I did some testing with a PMP board containing a Sil3726 with firmware Version 1.0124 and a PMP/Raid board with a JMicron 393 configured as PMP only. I am connecting to a Sil3124 esata pci controller. The Sil3726 board acted the same as the previous Sil3726 board with the 1.0114 firmware. The JMicron board worked much better. It works properly with a stock kernel and does not fail the IDENTIFY after hotplugging and does not require retries. It seems to wait for the drive to spin up before doing anything so it works properly the first time without retries or hard resets. The only problem I saw was that it seemed to not work at all a couple of times if not powered up/connected before booting Linux. Couldn't see it at all, even after several power cycles and unplugging/pluggin esata cable. I need to test this more as it is inconsistent and may have to do with the Sil3124 controller rather than the JMicron PMP. Derry Bryson Sr. Software Engineer Highly Reliable Systems www.High-Rely.com "Making Backup Invisible" Phone: 775.329.5139 X129 Fax: 775.370.1001 Sales & Support: 877.384.6838 This e-mail and any files transmitted with it are the property of Highly Reliable Systems, Inc. This (email) information is confidential, and is intended solely for the use of the individual or entity to whom this e-mail is addressed. If you are not one of the named recipient(s) or otherwise have reason to believe that you have received this message in error, please notify the sender and delete this message immediately from your computer. Any other use, disclosure, retention, dissemination, forwarding, printing, distribution or copying of this e-mail is strictly prohibited. > -----Original Message----- > From: Tejun Heo [mailto:htejun@gmail.com] On Behalf Of tj@kernel.org > Sent: Friday, July 22, 2011 2:51 AM > To: Derry Bryson > Cc: linux-ide@vger.kernel.org > Subject: Re: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) > > Hello, > > On Thu, Jul 21, 2011 at 04:22:07PM +0000, Derry Bryson wrote: > > Here are the specs on the port multiplier board: > > > > Lycom ST-126RM (http://www.lycom.com.tw/) > > Sil3726 chip revision 17 > > EEPROM FW Version: 1.0114 > > > > Also there is another problem: ports that are not connected at power > on > > are ignored until a port that was connected at power on is > hotplugged. So, > > for instance, if I turn the unit on with only a drive on the first > port, the > > other four ports will not work and I don't even see kernel messages > when > > hotplugging until I hotplug the first port. I haven't looked into > this yet, > > but it would seem the driver must be disabling the ports and they are > not > > looked at again until the hard reset is performed. > > That's most likely the sil pmp itself. It has been known to show > erratic behavior if the first port is not occupied during power up. I > don't know whether later firmware updates fixed that tho. Can you get > hold of a marvell PMP and see how it behaves? > > Thanks. > > -- > tejun > > > ----- > No virus found in this message. > Checked by AVG - www.avg.com > Version: 10.0.1390 / Virus Database: 1518/3779 - Release Date: 07/21/11 ^ permalink raw reply [flat|nested] 35+ messages in thread
* Re: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) 2011-07-22 19:34 ` Derry Bryson @ 2011-07-30 12:54 ` tj 2011-09-30 21:54 ` Mike I 0 siblings, 1 reply; 35+ messages in thread From: tj @ 2011-07-30 12:54 UTC (permalink / raw) To: Derry Bryson; +Cc: linux-ide@vger.kernel.org Hello, On Fri, Jul 22, 2011 at 07:34:37PM +0000, Derry Bryson wrote: > I did some testing with a PMP board containing a Sil3726 with firmware > Version 1.0124 and a PMP/Raid board with a JMicron 393 configured as > PMP only. I am connecting to a Sil3124 esata pci controller. > > The Sil3726 board acted the same as the previous Sil3726 board with the 1.0114 > firmware. > > The JMicron board worked much better. It works properly with a stock > kernel and does not fail the IDENTIFY after hotplugging and does > not require retries. It seems to wait for the drive to spin up before > doing anything so it works properly the first time without retries or > hard resets. Interesting, that's the behavior I see w/ my 3726 but all my PMPs are very old, so I guess it has changed since then. A bit too lazy to hook it up to windows machine to check firmware version ATM. :) > The only problem I saw was that it seemed to not work at all a > couple of times if not powered up/connected before booting Linux. > Couldn't see it at all, even after several power cycles and > unplugging/pluggin esata cable. I need to test this more as it is > inconsistent and may have to do with the Sil3124 controller rather > than the JMicron PMP. How did that go? Thanks. -- tejun ^ permalink raw reply [flat|nested] 35+ messages in thread
* Re: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) 2011-07-30 12:54 ` tj @ 2011-09-30 21:54 ` Mike I 2011-10-06 5:48 ` Gwendal Grignou 0 siblings, 1 reply; 35+ messages in thread From: Mike I @ 2011-09-30 21:54 UTC (permalink / raw) To: linux-ide tj <at> kernel.org <tj <at> kernel.org> writes: > > Hello, > > How did that go? > > Thanks. > Like Derry who started this thread, I too had seen an old thread from October/November 2008 with what appeared to be no resolution to this problem. Now, finding this thread, again, with no apparent resolution to this problem. I'm currently running Ubuntu 10.04 (lucid), kernel 2.6.32-33-generic. I've no experience with applying these git patches, and my searching to figure out how it works have not helped. I'm using an Addonics eSATA PCI-X controller with the SiI3124 chipset, and I have an Addonics PM in an external enclosure, with a 5 bay/tray DAS. Some of my drives give me this problem: (this occurs for me with pretty much ALL Samsung hard drives) [12888.470308] ata9.01: exception Emask 0x10 SAct 0x0 SErr 0x4050000 action 0xf [12888.470313] ata9.01: SError: { PHYRdyChg CommWake DevExch } [12888.470385] ata9.01: hard resetting link [12889.211597] ata9.01: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [12889.211686] ata9.01: failed to IDENTIFY (I/O error, err_mask=0x11) [12889.211692] ata9.15: hard resetting link [12891.430086] ata9.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [12891.430397] ata9.00: hard resetting link [12891.780786] ata9.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [12894.211103] ata9.01: hard resetting link [12894.560424] ata9.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [12894.560466] ata9.02: hard resetting link [12894.914176] ata9.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [12894.914222] ata9.03: hard resetting link [12895.264141] ata9.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [12895.264169] ata9.04: hard resetting link [12895.612930] ata9.04: SATA link down (SStatus 0 SControl 320) [12895.613007] ata9.05: hard resetting link [12895.964143] ata9.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) [12896.065908] ata9.00: configured for UDMA/100 [12896.065970] ata9.01: failed to IDENTIFY (I/O error, err_mask=0x11) [12896.065977] ata9.15: hard resetting link [12898.283804] ata9.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [12898.284128] ata9.00: hard resetting link [12898.634174] ata9.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [12899.562524] ata9.01: hard resetting link [12899.914147] ata9.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [12899.914180] ata9.02: hard resetting link [12900.261682] ata9.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [12900.261724] ata9.03: hard resetting link [12900.610413] ata9.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [12900.961283] ata9.05: hard resetting link [12901.310385] ata9.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) [12901.397241] ata9.00: configured for UDMA/100 [12901.397300] ata9.01: failed to IDENTIFY (I/O error, err_mask=0x11) [12901.397305] ata9.01: failed to recover link after 3 tries, disabling [12901.397311] ata9.15: hard resetting link [12903.613694] ata9.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [12903.960564] ata9.00: hard resetting link [12904.311125] ata9.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [12905.260154] ata9.02: hard resetting link [12905.602929] ata9.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [12905.611319] ata9.03: hard resetting link [12905.962555] ata9.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [12905.962592] ata9.04: hard resetting link [12906.312931] ata9.04: SATA link down (SStatus 0 SControl 320) [12906.313004] ata9.05: hard resetting link [12906.660409] ata9.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) [12906.753619] ata9.00: configured for UDMA/100 [12906.766586] ata9.02: configured for UDMA/100 [12906.771917] ata9.03: configured for UDMA/100 [12907.121462] ata9: EH complete If I hot plug the same drive using a port directly off my mobo(no PM in the mix), I get this result(drive connects/mounts/works): [27997.097104] ata5: exception Emask 0x10 SAct 0x0 SErr 0x4050000 action 0xe frozen [27997.097108] ata5: irq_stat 0x00400040, connection status changed [27997.097111] ata5: SError: { PHYRdyChg CommWake DevExch } [27997.097116] ata5: hard resetting link [28007.147622] ata5: softreset failed (device not ready) [28007.147627] ata5: hard resetting link [28010.630028] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [28010.748595] ata5.00: ATA-7: SAMSUNG HD154UI, 1AG01118, max UDMA7 [28010.748599] ata5.00: 2930277168 sectors, multi 0: LBA48 NCQ (depth 31/32) [28010.755227] ata5.00: configured for UDMA/133 [28010.755237] ata5: EH complete [28010.756338] scsi 4:0:0:0: Direct-Access ATA SAMSUNG HD154UI 1AG0 PQ: 0 ANSI: 5 [28010.756475] sd 4:0:0:0: Attached scsi generic sg10 type 0 [28010.756572] sd 4:0:0:0: [sdj] 2930277168 512-byte logical blocks: (1.50 TB/1.36 TiB) [28010.756613] sd 4:0:0:0: [sdj] Write Protect is off [28010.756616] sd 4:0:0:0: [sdj] Mode Sense: 00 3a 00 00 [28010.756636] sd 4:0:0:0: [sdj] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [28010.756760] sdj: sdj1 [28010.816161] sd 4:0:0:0: [sdj] Attached SCSI disk I've been using Ubuntu for a few years now, and have been living with the problem...working around it with USB docking stations and such. But, I'd really hope to see/find this problem worked out. Thoughts/tips/suggestions? Since I'm pretty much a novice when it comes to patching, a link to a guide for git patching would be appreciated too. Thank You, Mike ^ permalink raw reply [flat|nested] 35+ messages in thread
* Re: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) 2011-09-30 21:54 ` Mike I @ 2011-10-06 5:48 ` Gwendal Grignou 2011-10-06 6:03 ` [PATCH] libata: Allow SOFT_RESET for Sil3726 Gwendal Grignou ` (2 more replies) 0 siblings, 3 replies; 35+ messages in thread From: Gwendal Grignou @ 2011-10-06 5:48 UTC (permalink / raw) To: Mike I; +Cc: linux-ide I think I know what is going on. One of your disks at least is slow to spinup. Due to a bug/feature in silicon image disk controller and pmp, at bring up we can not issue a SOFT_RESET and wait for the disk to spinup and then continue. That why we set ATA_LFLAG_NO_SRST in sata_pmp_quirks(). So what happen is we go into a function that issue identify, but we fail, the disk is not ready [it is spinning up], so we retry. 3 times. From the first hard reset: 12888.470385, to the time you got the final error: 12901.397305 ~ 12.9s In the second case, your controller can send SOFT_RESET and wait for the device to respond. Time for the disk to spinup: 28010.630028 - 27997.097116 ~ 13.5s As you can see, you are borderline with the PMP, but the controller did not "wait" enough in the first case. Given the spinup time varies with drive, age, time since last spin-up..., it may work one day and fail the next. To work around the problem, I have a patch that consist of allowing the silicon image control to send a reset, but if it fails, we spin for a fixed amount of time and retry. This is not very nice, it is a better design to wait for event that waiting a fixed amount of time. You may have to alter ATA_LFLAG_WAIT_SRST to use the first bit available. Can you try with the following patch? Thanks, Gwendal. diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c index 228740f..b98b02d 100644 --- a/drivers/ata/libata-eh.c +++ b/drivers/ata/libata-eh.c @@ -2798,7 +2798,14 @@ int ata_eh_reset(struct ata_link *link, int classify, sata_scr_read(link, SCR_STATUS, &sstatus)) rc = -ERESTART; - if (rc == -ERESTART || try >= max_tries) + if (try >= max_tries) + goto out; + + /* Some PMP will not serve SRST until the disk is spunup, + * if the controller can not wait for the PMP to acknowledge the frame, + * wait here */ + if (rc == -ERESTART && + !((lflags & ATA_LFLAG_WAIT_SRST) && (reset == softreset))) goto out; now = jiffies; @@ -2813,6 +2820,8 @@ int ata_eh_reset(struct ata_link *link, int classify, delta = schedule_timeout_uninterruptible(delta); } + if (rc == -ERESTART) + goto out; if (try == max_tries - 1) { sata_down_spd_limit(link, 0); if (slave) diff --git a/drivers/ata/libata-pmp.c b/drivers/ata/libata-pmp.c index 00305f4..d21ad7d 100644 --- a/drivers/ata/libata-pmp.c +++ b/drivers/ata/libata-pmp.c @@ -325,13 +351,11 @@ static void sata_pmp_quirks(struct ata_port *ap) if (vendor == 0x1095 && devid == 0x3726) { /* sil3726 quirks */ ata_for_each_link(link, ap, EDGE) { - /* Class code report is unreliable and SRST - * times out under certain configurations. - */ + /* Class code report is unreliable */ + /* PMP does not forward SRST until the drive spins up */ if (link->pmp < 5) - link->flags |= ATA_LFLAG_NO_SRST | - ATA_LFLAG_ASSUME_ATA; - + link->flags |= ATA_LFLAG_ASSUME_ATA | + ATA_LFLAG_WAIT_SRST; /* port 5 is for SEMB device and it doesn't like SRST */ if (link->pmp == 5) link->flags |= ATA_LFLAG_NO_SRST | diff --git a/include/linux/libata.h b/include/linux/libata.h index b2f2003..3a18caa 100644 --- a/include/linux/libata.h +++ b/include/linux/libata.h @@ -172,6 +172,7 @@ enum { ATA_LFLAG_NO_RETRY = (1 << 5), /* don't retry this link */ ATA_LFLAG_DISABLED = (1 << 6), /* link is disabled */ ATA_LFLAG_SW_ACTIVITY = (1 << 7), /* keep activity stats */ + ATA_LFLAG_WAIT_SRST = (1 << 8), /* add delay when SRST fails */ /* struct ata_port flags */ ATA_FLAG_SLAVE_POSS = (1 << 0), /* host supports slave dev */ On Fri, Sep 30, 2011 at 2:54 PM, Mike I <mihrcke@gmail.com> wrote: > > tj <at> kernel.org <tj <at> kernel.org> writes: > > > > > Hello, > > > > How did that go? > > > > Thanks. > > > > Like Derry who started this thread, I too had seen an old thread from > October/November 2008 with what appeared to be no resolution to this problem. > Now, finding this thread, again, with no apparent resolution to this problem. > > I'm currently running Ubuntu 10.04 (lucid), kernel 2.6.32-33-generic. I've no > experience with applying these git patches, and my searching to figure out how > it works have not helped. > > I'm using an Addonics eSATA PCI-X controller with the SiI3124 chipset, and I > have an Addonics PM in an external enclosure, with a 5 bay/tray DAS. Some of > my drives give me this problem: (this occurs for me with pretty much ALL > Samsung hard drives) > [12888.470308] ata9.01: exception Emask 0x10 SAct 0x0 SErr 0x4050000 action 0xf > [12888.470313] ata9.01: SError: { PHYRdyChg CommWake DevExch } > [12888.470385] ata9.01: hard resetting link > [12889.211597] ata9.01: SATA link up 3.0 Gbps (SStatus 123 SControl 320) > [12889.211686] ata9.01: failed to IDENTIFY (I/O error, err_mask=0x11) > [12889.211692] ata9.15: hard resetting link > [12891.430086] ata9.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) > [12891.430397] ata9.00: hard resetting link > [12891.780786] ata9.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) > [12894.211103] ata9.01: hard resetting link > [12894.560424] ata9.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) > [12894.560466] ata9.02: hard resetting link > [12894.914176] ata9.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) > [12894.914222] ata9.03: hard resetting link > [12895.264141] ata9.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) > [12895.264169] ata9.04: hard resetting link > [12895.612930] ata9.04: SATA link down (SStatus 0 SControl 320) > [12895.613007] ata9.05: hard resetting link > [12895.964143] ata9.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) > [12896.065908] ata9.00: configured for UDMA/100 > [12896.065970] ata9.01: failed to IDENTIFY (I/O error, err_mask=0x11) > [12896.065977] ata9.15: hard resetting link > [12898.283804] ata9.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) > [12898.284128] ata9.00: hard resetting link > [12898.634174] ata9.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) > [12899.562524] ata9.01: hard resetting link > [12899.914147] ata9.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) > [12899.914180] ata9.02: hard resetting link > [12900.261682] ata9.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) > [12900.261724] ata9.03: hard resetting link > [12900.610413] ata9.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) > [12900.961283] ata9.05: hard resetting link > [12901.310385] ata9.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) > [12901.397241] ata9.00: configured for UDMA/100 > [12901.397300] ata9.01: failed to IDENTIFY (I/O error, err_mask=0x11) > [12901.397305] ata9.01: failed to recover link after 3 tries, disabling > [12901.397311] ata9.15: hard resetting link > [12903.613694] ata9.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) > [12903.960564] ata9.00: hard resetting link > [12904.311125] ata9.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) > [12905.260154] ata9.02: hard resetting link > [12905.602929] ata9.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) > [12905.611319] ata9.03: hard resetting link > [12905.962555] ata9.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) > [12905.962592] ata9.04: hard resetting link > [12906.312931] ata9.04: SATA link down (SStatus 0 SControl 320) > [12906.313004] ata9.05: hard resetting link > [12906.660409] ata9.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) > [12906.753619] ata9.00: configured for UDMA/100 > [12906.766586] ata9.02: configured for UDMA/100 > [12906.771917] ata9.03: configured for UDMA/100 > [12907.121462] ata9: EH complete > > If I hot plug the same drive using a port directly off my mobo(no PM in the > mix), I get this result(drive connects/mounts/works): > [27997.097104] ata5: exception Emask 0x10 SAct 0x0 SErr 0x4050000 action > 0xe frozen > [27997.097108] ata5: irq_stat 0x00400040, connection status changed > [27997.097111] ata5: SError: { PHYRdyChg CommWake DevExch } > [27997.097116] ata5: hard resetting link > [28007.147622] ata5: softreset failed (device not ready) > [28007.147627] ata5: hard resetting link > [28010.630028] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300) > [28010.748595] ata5.00: ATA-7: SAMSUNG HD154UI, 1AG01118, max UDMA7 > [28010.748599] ata5.00: 2930277168 sectors, multi 0: LBA48 NCQ (depth 31/32) > [28010.755227] ata5.00: configured for UDMA/133 > [28010.755237] ata5: EH complete > [28010.756338] scsi 4:0:0:0: Direct-Access ATA SAMSUNG HD154UI 1AG0 > PQ: 0 ANSI: 5 > [28010.756475] sd 4:0:0:0: Attached scsi generic sg10 type 0 > [28010.756572] sd 4:0:0:0: [sdj] 2930277168 512-byte logical blocks: (1.50 > TB/1.36 TiB) > [28010.756613] sd 4:0:0:0: [sdj] Write Protect is off > [28010.756616] sd 4:0:0:0: [sdj] Mode Sense: 00 3a 00 00 > [28010.756636] sd 4:0:0:0: [sdj] Write cache: enabled, read cache: enabled, > doesn't support DPO or FUA > [28010.756760] sdj: sdj1 > [28010.816161] sd 4:0:0:0: [sdj] Attached SCSI disk > > I've been using Ubuntu for a few years now, and have been living with the > problem...working around it with USB docking stations and such. But, I'd > really hope to see/find this problem worked out. > > Thoughts/tips/suggestions? Since I'm pretty much a novice when it comes to > patching, a link to a guide for git patching would be appreciated too. > > Thank You, > Mike > > -- > To unsubscribe from this list: send the line "unsubscribe linux-ide" in > the body of a message to majordomo@vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html ^ permalink raw reply related [flat|nested] 35+ messages in thread
* [PATCH] libata: Allow SOFT_RESET for Sil3726 2011-10-06 5:48 ` Gwendal Grignou @ 2011-10-06 6:03 ` Gwendal Grignou 2011-10-06 8:03 ` Tejun Heo 2011-10-06 10:42 ` [PATCH] libata: Allow SOFT_RESET for Sil3726 Sergei Shtylyov [not found] ` <CAMHSBOV8rSW3jumpx8URZrgo8w1He9zruP7yAOw7uhQOaAj3Xg@mail.gmail.com> 2011-10-08 18:25 ` Michael Ihrcke 2 siblings, 2 replies; 35+ messages in thread From: Gwendal Grignou @ 2011-10-06 6:03 UTC (permalink / raw) To: mihrcke; +Cc: linux-ide, Gwendal Grignou Allow controllers to send SOFT_RESET to Sil3726 PMP. This PMP does not accept frames until the drive connected to its port spins up. Some controller [Sil3132 family] can not wait for the drive to spinup and fails the reset, leading to unnecessary speed downgrade. Not allowing to send SOFT_RESET can lead some drive slow to spinup to be ignored and produces weird error messages. This fix allows the error handler to wait if the controller is unable to send a SOFT_RESET. Change-Id: I7eeea152facb4b76e5c69cfde5ef8188874fbaba Signed-off-by: Gwendal Grignou <gwendal@google.com> --- drivers/ata/libata-eh.c | 11 ++++++++++- drivers/ata/libata-pmp.c | 10 ++++------ include/linux/libata.h | 1 + 3 files changed, 15 insertions(+), 7 deletions(-) diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c index 49af350..60223c3 100644 --- a/drivers/ata/libata-eh.c +++ b/drivers/ata/libata-eh.c @@ -2805,7 +2805,14 @@ int ata_eh_reset(struct ata_link *link, int classify, sata_scr_read(link, SCR_STATUS, &sstatus)) rc = -ERESTART; - if (rc == -ERESTART || try >= max_tries) + if (try >= max_tries) + goto out; + + /* Some PMP will not serve SRST until the disk is spunup, + * if the controller can not wait for the PMP to acknowledge the frame, + * wait here */ + if (rc == -ERESTART && + !((lflags & ATA_LFLAG_WAIT_SRST) && (reset == softreset))) goto out; now = jiffies; @@ -2820,6 +2827,8 @@ int ata_eh_reset(struct ata_link *link, int classify, delta = schedule_timeout_uninterruptible(delta); } + if (rc == -ERESTART) + goto out; if (try == max_tries - 1) { sata_down_spd_limit(link, 0); if (slave) diff --git a/drivers/ata/libata-pmp.c b/drivers/ata/libata-pmp.c index ad0e71d..5fbbe2f 100644 --- a/drivers/ata/libata-pmp.c +++ b/drivers/ata/libata-pmp.c @@ -365,13 +365,11 @@ static void sata_pmp_quirks(struct ata_port *ap) if (vendor == 0x1095 && devid == 0x3726) { /* sil3726 quirks */ ata_for_each_link(link, ap, EDGE) { - /* Class code report is unreliable and SRST - * times out under certain configurations. - */ + /* Class code report is unreliable */ + /* PMP does not forward SRST until the drive spins up */ if (link->pmp < 5) - link->flags |= ATA_LFLAG_NO_SRST | - ATA_LFLAG_ASSUME_ATA; - + link->flags |= ATA_LFLAG_ASSUME_ATA | + ATA_LFLAG_WAIT_SRST; /* port 5 is for SEMB device and it doesn't like SRST */ if (link->pmp == 5) link->flags |= ATA_LFLAG_NO_SRST | diff --git a/include/linux/libata.h b/include/linux/libata.h index 14b9f50..4577ed2 100644 --- a/include/linux/libata.h +++ b/include/linux/libata.h @@ -173,6 +173,7 @@ enum { ATA_LFLAG_DISABLED = (1 << 6), /* link is disabled */ ATA_LFLAG_SW_ACTIVITY = (1 << 7), /* keep activity stats */ ATA_LFLAG_PHYOFF = (1 << 8), /* phy is powered off */ + ATA_LFLAG_WAIT_SRST = (1 << 9), /* add delay when SRST fails */ /* struct ata_port flags */ ATA_FLAG_SLAVE_POSS = (1 << 0), /* host supports slave dev */ -- 1.7.3.1 ^ permalink raw reply related [flat|nested] 35+ messages in thread
* Re: [PATCH] libata: Allow SOFT_RESET for Sil3726 2011-10-06 6:03 ` [PATCH] libata: Allow SOFT_RESET for Sil3726 Gwendal Grignou @ 2011-10-06 8:03 ` Tejun Heo 2011-10-06 20:44 ` Gwendal Grignou 2011-10-06 10:42 ` [PATCH] libata: Allow SOFT_RESET for Sil3726 Sergei Shtylyov 1 sibling, 1 reply; 35+ messages in thread From: Tejun Heo @ 2011-10-06 8:03 UTC (permalink / raw) To: Gwendal Grignou; +Cc: mihrcke, linux-ide Hello, Gwendal. Which tree is this patch against? On Wed, Oct 05, 2011 at 11:03:57PM -0700, Gwendal Grignou wrote: > Allow controllers to send SOFT_RESET to Sil3726 PMP. > This PMP does not accept frames until the drive connected to > its port spins up. Do you mean until the device sets RDY by sending D2H Reg FIS? > Some controller [Sil3132 family] can not wait for the drive to spinup > and fails the reset, leading to unnecessary speed downgrade. > Not allowing to send SOFT_RESET can lead some drive slow to spinup > to be ignored and produces weird error messages. Yeap, I agree this is nasty. > @@ -2805,7 +2805,14 @@ int ata_eh_reset(struct ata_link *link, int classify, > sata_scr_read(link, SCR_STATUS, &sstatus)) > rc = -ERESTART; > > - if (rc == -ERESTART || try >= max_tries) > + if (try >= max_tries) > + goto out; > + > + /* Some PMP will not serve SRST until the disk is spunup, > + * if the controller can not wait for the PMP to acknowledge the frame, > + * wait here */ > + if (rc == -ERESTART && > + !((lflags & ATA_LFLAG_WAIT_SRST) && (reset == softreset))) > goto out; > > now = jiffies; > @@ -2820,6 +2827,8 @@ int ata_eh_reset(struct ata_link *link, int classify, > delta = schedule_timeout_uninterruptible(delta); > } > > + if (rc == -ERESTART) > + goto out; So, now libata waits for full reset period before proceeding to reset PMP. Hmmm... yeah, it makes sense. Unfortunately, the only way to achieve spinup wait in this case is waiting blindly and libata's reset timeouts are configured to accomodate drive spinup times. PMP SCR failure kinda destroys those blind wait periods. I'm not too sure about ATA_LFLAG_WAIT_SRST. I don't think making the new behavior default would hurt. Can you please post before & after logs? Thank you. -- tejun ^ permalink raw reply [flat|nested] 35+ messages in thread
* Re: [PATCH] libata: Allow SOFT_RESET for Sil3726 2011-10-06 8:03 ` Tejun Heo @ 2011-10-06 20:44 ` Gwendal Grignou 2011-10-06 22:10 ` Tejun Heo 0 siblings, 1 reply; 35+ messages in thread From: Gwendal Grignou @ 2011-10-06 20:44 UTC (permalink / raw) To: Tejun Heo; +Cc: mihrcke, linux-ide, derry On Thu, Oct 6, 2011 at 1:03 AM, Tejun Heo <htejun@gmail.com> wrote: > Hello, Gwendal. > > Which tree is this patch against? I am using 2.6.34. I try to have this mail follow the thread "RE: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726)", Derry started. It did not work, sorry. I will rebase the ata-dev branch soon - and clean up the patch following Sergei comments. > > On Wed, Oct 05, 2011 at 11:03:57PM -0700, Gwendal Grignou wrote: >> Allow controllers to send SOFT_RESET to Sil3726 PMP. >> This PMP does not accept frames until the drive connected to >> its port spins up. > > Do you mean until the device sets RDY by sending D2H Reg FIS? Yes. Until the device sends the async D2H Reg FIS indicating the drive spun up, the MPM does not accept the SoftRest FIS from the controller. On most controller, that fine, the controller state machine keeps retrying, but on Sil3132 it stops after a second or so and send an error back to the driver. > >> Some controller [Sil3132 family] can not wait for the drive to spinup >> and fails the reset, leading to unnecessary speed downgrade. >> Not allowing to send SOFT_RESET can lead some drive slow to spinup >> to be ignored and produces weird error messages. > > Yeap, I agree this is nasty. > >> @@ -2805,7 +2805,14 @@ int ata_eh_reset(struct ata_link *link, int classify, >> sata_scr_read(link, SCR_STATUS, &sstatus)) >> rc = -ERESTART; >> >> - if (rc == -ERESTART || try >= max_tries) >> + if (try >= max_tries) >> + goto out; >> + >> + /* Some PMP will not serve SRST until the disk is spunup, >> + * if the controller can not wait for the PMP to acknowledge the frame, >> + * wait here */ >> + if (rc == -ERESTART && >> + !((lflags & ATA_LFLAG_WAIT_SRST) && (reset == softreset))) >> goto out; >> >> now = jiffies; >> @@ -2820,6 +2827,8 @@ int ata_eh_reset(struct ata_link *link, int classify, >> delta = schedule_timeout_uninterruptible(delta); >> } >> >> + if (rc == -ERESTART) >> + goto out; > > So, now libata waits for full reset period before proceeding to reset > PMP. Hmmm... yeah, it makes sense. Unfortunately, the only way to > achieve spinup wait in this case is waiting blindly and libata's reset > timeouts are configured to accomodate drive spinup times. PMP SCR > failure kinda destroys those blind wait periods. Yes, I totally agree this blind wait is not clean. Normally we would wait until an event occurs [async FIS] and have the timeout just for the error case. Here we wait [10s] because we think the device is spinning up. > > I'm not too sure about ATA_LFLAG_WAIT_SRST. I don't think making the > new behavior default would hurt. I see your point. But if there is no PMP, Sil3132 is behaving, there is no need of this logic. > > Can you please post before & after logs? There are 2 problem with the current solution: - by not waiting for device spin up, we basically disabled staggered spinup: we send hard reset to all port very fast. That may put burden on enclosure with weak power supplies. - as Derry found out, disk which are slow to spin up can be ignored by the kernel. From my experience: Before: Apr 11 13:29:23 cigg22 kernel: ata5.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports, feat 0x1/0x9 Apr 11 13:29:23 cigg22 kernel: ata5.00: hard resetting link Apr 11 13:29:23 cigg22 kernel: ata5.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) Apr 11 13:29:23 cigg22 kernel: ata5.01: hard resetting link ... Apr 11 13:29:23 cigg22 kernel: ata5.04: SATA link up 3.0 Gbps (SStatus 123 SControl 300) Apr 11 13:29:23 cigg22 kernel: ata5.05: hard resetting link Apr 11 13:29:23 cigg22 kernel: ata5.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) Apr 11 13:29:23 cigg22 kernel: ata5.00: failed to IDENTIFY (I/O error, err_mask=0x11) Apr 11 13:29:23 cigg22 kernel: ata5.15: hard resetting link Apr 11 13:29:23 cigg22 kernel: ata5: controller in dubious state, performing PORT_RST Apr 11 13:29:23 cigg22 kernel: ata5.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) Apr 11 13:29:23 cigg22 kernel: ata5.00: hard resetting link Apr 11 13:29:23 cigg22 kernel: ata5.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) ... We are hoping that by the time it takes to hard reset 5 ports, the disks would have spun up. After: Sep 12 12:40:38 pnkv6 kern.info kernel: ata7: SATA link up 3.0 Gbps (SStatus 123 SControl 0) Sep 12 12:40:38 pnkv6 kern.info kernel: ata7.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports, feat 0x1/0x9 Sep 12 12:40:38 pnkv6 kern.info kernel: ata7.00: hard resetting link Sep 12 12:40:38 pnkv6 kern.err kernel: ata7.00: softreset failed (SRST command error) Sep 12 12:40:38 pnkv6 kern.warn kernel: ata7.00: failed to read SCR 0 (Emask=0x40) Sep 12 12:40:38 pnkv6 kern.warn kernel: ata7.00: reset failed (errno=-85), retrying in 10 secs <<< this allows the disk to spin up >>> Sep 12 12:40:48 pnkv6 kern.err kernel: ata7.00: reset failed, giving up Sep 12 12:40:48 pnkv6 kern.info kernel: ata7.15: hard resetting link Sep 12 12:40:48 pnkv6 kern.warn kernel: ata7: controller in dubious state, performing PORT_RST Sep 12 12:40:50 pnkv6 kern.info kernel: ata7.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) Sep 12 12:40:50 pnkv6 kern.info kernel: ata7.00: hard resetting link Sep 12 12:40:50 pnkv6 kern.info kernel: ata7.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) Sep 12 12:40:50 pnkv6 kern.info kernel: ata7.01: hard resetting link > > Thank you. > > -- > tejun > ^ permalink raw reply [flat|nested] 35+ messages in thread
* Re: [PATCH] libata: Allow SOFT_RESET for Sil3726 2011-10-06 20:44 ` Gwendal Grignou @ 2011-10-06 22:10 ` Tejun Heo 2011-10-12 14:03 ` Mark Lord 0 siblings, 1 reply; 35+ messages in thread From: Tejun Heo @ 2011-10-06 22:10 UTC (permalink / raw) To: Gwendal Grignou; +Cc: mihrcke, linux-ide, derry Hello, On Thu, Oct 06, 2011 at 01:44:27PM -0700, Gwendal Grignou wrote: > Yes. Until the device sends the async D2H Reg FIS indicating the drive > spun up, the MPM does not accept the SoftRest FIS from the controller. > On most controller, that fine, the controller state machine keeps > retrying, but on Sil3132 it stops after a second or so and send an > error back to the driver. I see. > > So, now libata waits for full reset period before proceeding to reset > > PMP. Hmmm... yeah, it makes sense. Unfortunately, the only way to > > achieve spinup wait in this case is waiting blindly and libata's reset > > timeouts are configured to accomodate drive spinup times. PMP SCR > > failure kinda destroys those blind wait periods. > > Yes, I totally agree this blind wait is not clean. Normally we would > wait until an event occurs [async FIS] and have the timeout just for > the error case. > Here we wait [10s] because we think the device is spinning up. Yes but that's exactly how the reset timeouts are set up. They're supposed to provide reasonable spinup timeouts when the proper wait mechanisms can't do so and here it becomes a problem because the blind timeouts are circumvented by SCR read failure handling. > > I'm not too sure about ATA_LFLAG_WAIT_SRST. I don't think making the > > new behavior default would hurt. > > I see your point. But if there is no PMP, Sil3132 is behaving, there > is no need of this logic. Yes, sure, the behavior is necessary iff PMP is attached as that's only time SCR read failure can occur anyway and I think it would generally be a good idea to always enforce the blind timeouts if PMP is attached, so no need for ATA_LFLAG_WAIT_SRST. > > Can you please post before & after logs? > There are 2 problem with the current solution: > - by not waiting for device spin up, we basically disabled staggered > spinup: we send hard reset to all port very fast. > That may put burden on enclosure with weak power supplies. > - as Derry found out, disk which are slow to spin up can be ignored by > the kernel. Looks pretty good to me. Nice spotting. Thanks a lot for tracking it down and coming up with good solution. :) -- tejun ^ permalink raw reply [flat|nested] 35+ messages in thread
* Re: [PATCH] libata: Allow SOFT_RESET for Sil3726 2011-10-06 22:10 ` Tejun Heo @ 2011-10-12 14:03 ` Mark Lord 2011-10-20 0:02 ` [PATCH] [libata]Issue SRST to Sil3726 PMP Gwendal Grignou ` (5 more replies) 0 siblings, 6 replies; 35+ messages in thread From: Mark Lord @ 2011-10-12 14:03 UTC (permalink / raw) To: Tejun Heo; +Cc: Gwendal Grignou, mihrcke, linux-ide, derry On 11-10-06 06:10 PM, Tejun Heo wrote: > Hello, > > On Thu, Oct 06, 2011 at 01:44:27PM -0700, Gwendal Grignou wrote: >> Yes. Until the device sends the async D2H Reg FIS indicating the drive >> spun up, the MPM does not accept the SoftRest FIS from the controller. >> On most controller, that fine, the controller state machine keeps >> retrying, but on Sil3132 it stops after a second or so and send an >> error back to the driver. > > I see. > >>> So, now libata waits for full reset period before proceeding to reset >>> PMP. Hmmm... yeah, it makes sense. Unfortunately, the only way to >>> achieve spinup wait in this case is waiting blindly and libata's reset >>> timeouts are configured to accomodate drive spinup times. PMP SCR >>> failure kinda destroys those blind wait periods. >> >> Yes, I totally agree this blind wait is not clean. Normally we would >> wait until an event occurs [async FIS] and have the timeout just for >> the error case. >> Here we wait [10s] because we think the device is spinning up. > > Yes but that's exactly how the reset timeouts are set up. They're > supposed to provide reasonable spinup timeouts when the proper wait > mechanisms can't do so and here it becomes a problem because the blind > timeouts are circumvented by SCR read failure handling. > >>> I'm not too sure about ATA_LFLAG_WAIT_SRST. I don't think making the >>> new behavior default would hurt. >> >> I see your point. But if there is no PMP, Sil3132 is behaving, there >> is no need of this logic. > > Yes, sure, the behavior is necessary iff PMP is attached as that's > only time SCR read failure can occur anyway and I think it would > generally be a good idea to always enforce the blind timeouts if PMP > is attached, so no need for ATA_LFLAG_WAIT_SRST. I wonder if this same logic is more generally applicable for PMP rather than sil3132 specific? What I've read thus far in this thread sounds very much like the issues I see here with PMPs not working on JMB and Marvell controllers (where they USED to work fine). Gwendal, have you got a version of that patch which applies the same change globally rather than only for sil3132? I'd like to try it out here. Thanks ^ permalink raw reply [flat|nested] 35+ messages in thread
* [PATCH] [libata]Issue SRST to Sil3726 PMP 2011-10-12 14:03 ` Mark Lord @ 2011-10-20 0:02 ` Gwendal Grignou 2011-10-20 0:02 ` Gwendal Grignou ` (4 subsequent siblings) 5 siblings, 0 replies; 35+ messages in thread From: Gwendal Grignou @ 2011-10-20 0:02 UTC (permalink / raw) To: htejun, kernel, mihrcke, derry; +Cc: linux-ide, Gwendal Grignou By issuing SRST, . We re enable staggered spin up . We allow slow disks to spin up while we are still in initial error handler However, some controller fails sending SRST while the disk is spinning up behind the port multiplier. To avoid slow disk to be ignored, or link to be downgraded unnecessarily, wait 10s if SRST fails before resetting the ATA port. With a Sil3132. Before the patch: [ 236.184036] ata4.15: hard resetting link [ 236.184038] ata4: controller in dubious state, performing PORT_RST [ 238.338048] ata4.15: SATA link up 1.5 Gbps (SStatus 113 SControl 10) [ 239.549102] ata4.00: hard resetting link [ 239.854315] ata4.00: SATA link up 1.5 Gbps (SStatus 113 SControl 310) [ 239.854344] ata4.01: hard resetting link [ 240.159316] ata4.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 240.159344] ata4.02: hard resetting link [ 240.464316] ata4.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 240.464343] ata4.03: hard resetting link [ 240.769314] ata4.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 240.769342] ata4.04: hard resetting link [ 241.074316] ata4.04: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 241.074344] ata4.05: hard resetting link [ 241.379314] ata4.05: SATA link up 1.5 Gbps (SStatus 113 SControl 310) [ 241.382672] ata4.00: configured for UDMA/100 [ 241.492027] ata4.01: failed to IDENTIFY (I/O error, err_mask=0x11) [ 241.492030] ata4.01: revalidation failed (errno=-5) [ 241.492033] ata4.15: hard resetting link After the patch: [ 19.436422] ata4.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports, feat 0x1/0x9 [ 19.454715] ata4.00: hard resetting link [ 19.880032] ata4.00: softreset failed (SRST command error) [ 19.880048] ata4.00: failed to read SCR 0 (Emask=0x40) [ 19.880051] ata4.00: reset failed (errno=-85), retrying in 10 secs [ 29.454092] ata4.00: reset failed, giving up [ 29.454099] ata4.15: hard resetting link [ 29.454102] ata4: controller in dubious state, performing PORT_RST [ 31.608046] ata4.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 31.608431] ata4.00: hard resetting link [ 31.924284] ata4.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 31.924335] ata4.01: hard resetting link [ 32.350029] ata4.01: softreset failed (SRST command error) [ 32.460032] ata4.01: failed to read SCR 0 (Emask=0x1) [ 32.460036] ata4.01: reset failed (errno=-85), retrying in 10 secs [ 41.924139] ata4.01: reset failed, giving up [ 41.924146] ata4.15: hard resetting link [ 41.924148] ata4: controller in dubious state, performing PORT_RST [ 44.078047] ata4.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 44.078384] ata4.00: hard resetting link Patch also tested with Marvel 7042 and Sil3726. Gwendal Grignou (1): [libata]Issue SRST to Sil3726 PMP drivers/ata/libata-eh.c | 12 +++++++++++- drivers/ata/libata-pmp.c | 7 ++----- 2 files changed, 13 insertions(+), 6 deletions(-) -- 1.7.3.1 ^ permalink raw reply [flat|nested] 35+ messages in thread
* [PATCH] [libata]Issue SRST to Sil3726 PMP 2011-10-12 14:03 ` Mark Lord 2011-10-20 0:02 ` [PATCH] [libata]Issue SRST to Sil3726 PMP Gwendal Grignou @ 2011-10-20 0:02 ` Gwendal Grignou 2011-10-20 0:07 ` Tejun Heo 2011-10-20 0:17 ` Gwendal Grignou ` (3 subsequent siblings) 5 siblings, 1 reply; 35+ messages in thread From: Gwendal Grignou @ 2011-10-20 0:02 UTC (permalink / raw) To: htejun, kernel, mihrcke, derry; +Cc: linux-ide, Gwendal Grignou Reenable sending SRST to devices connected behind a Sil3726 PMP. This allow staggered spinups and handles drives that spins up slowly. While the drives spin up, the PMP will not accept SRST. Most controller reissues the reset until the drive is ready, while some [Sil3124] returns an error. In ata_eh_error, wait 10s before reset the ATA port and try again. --- drivers/ata/libata-eh.c | 12 +++++++++++- drivers/ata/libata-pmp.c | 7 ++----- 2 files changed, 13 insertions(+), 6 deletions(-) diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c index c021186..927d750 100644 --- a/drivers/ata/libata-eh.c +++ b/drivers/ata/libata-eh.c @@ -2882,7 +2882,7 @@ int ata_eh_reset(struct ata_link *link, int classify, sata_scr_read(link, SCR_STATUS, &sstatus)) rc = -ERESTART; - if (rc == -ERESTART || try >= max_tries) { + if (try >= max_tries) { /* * Thaw host port even if reset failed, so that the port * can be retried on the next phy event. This risks @@ -2908,6 +2908,16 @@ int ata_eh_reset(struct ata_link *link, int classify, ata_eh_acquire(ap); } + /* + * While disks spinup behind PMP, some controllers fail sending SRST. + * They need to be reset - as well as the PMP - before retrying. + */ + if (rc == -ERESTART) { + if (ata_is_host_link(link)) + ata_eh_thaw_port(ap); + goto out; + } + if (try == max_tries - 1) { sata_down_spd_limit(link, 0); if (slave) diff --git a/drivers/ata/libata-pmp.c b/drivers/ata/libata-pmp.c index 3eb2b81..183643f 100644 --- a/drivers/ata/libata-pmp.c +++ b/drivers/ata/libata-pmp.c @@ -388,12 +388,9 @@ static void sata_pmp_quirks(struct ata_port *ap) /* link reports offline after LPM */ link->flags |= ATA_LFLAG_NO_LPM; - /* Class code report is unreliable and SRST - * times out under certain configurations. - */ + /* Class code report is unreliable. */ if (link->pmp < 5) - link->flags |= ATA_LFLAG_NO_SRST | - ATA_LFLAG_ASSUME_ATA; + link->flags |= ATA_LFLAG_ASSUME_ATA; /* port 5 is for SEMB device and it doesn't like SRST */ if (link->pmp == 5) -- 1.7.3.1 ^ permalink raw reply related [flat|nested] 35+ messages in thread
* Re: [PATCH] [libata]Issue SRST to Sil3726 PMP 2011-10-20 0:02 ` Gwendal Grignou @ 2011-10-20 0:07 ` Tejun Heo 2011-10-20 0:28 ` Gwendal Grignou 0 siblings, 1 reply; 35+ messages in thread From: Tejun Heo @ 2011-10-20 0:07 UTC (permalink / raw) To: Gwendal Grignou; +Cc: kernel, mihrcke, derry, linux-ide Hello, On Wed, Oct 19, 2011 at 05:02:42PM -0700, Gwendal Grignou wrote: > Reenable sending SRST to devices connected behind a Sil3726 PMP. > This allow staggered spinups and handles drives that spins up slowly. > > While the drives spin up, the PMP will not accept SRST. > Most controller reissues the reset until the drive is ready, while > some [Sil3124] returns an error. > In ata_eh_error, wait 10s before reset the ATA port and try again. While I agree with the change, the description doesn't seem too accurate. * The behavior change applies to all PMPs. * I hope 3726 change is in a separate patch. * It waits for reset deadline which currently happens to be 10s. Thanks. -- tejun ^ permalink raw reply [flat|nested] 35+ messages in thread
* Re: [PATCH] [libata]Issue SRST to Sil3726 PMP 2011-10-20 0:07 ` Tejun Heo @ 2011-10-20 0:28 ` Gwendal Grignou 0 siblings, 0 replies; 35+ messages in thread From: Gwendal Grignou @ 2011-10-20 0:28 UTC (permalink / raw) To: Tejun Heo; +Cc: kernel, mihrcke, derry, linux-ide On Wed, Oct 19, 2011 at 5:07 PM, Tejun Heo <htejun@gmail.com> wrote: > Hello, > > On Wed, Oct 19, 2011 at 05:02:42PM -0700, Gwendal Grignou wrote: >> Reenable sending SRST to devices connected behind a Sil3726 PMP. >> This allow staggered spinups and handles drives that spins up slowly. >> >> While the drives spin up, the PMP will not accept SRST. >> Most controller reissues the reset until the drive is ready, while >> some [Sil3124] returns an error. >> In ata_eh_error, wait 10s before reset the ATA port and try again. > > While I agree with the change, the description doesn't seem too > accurate. > > * The behavior change applies to all PMPs. I just re-enable SRST for Sil3726, not the other PMPs. For the other ones where ATA_LFLAG_NO_SRST is still set, we will not issue softreset and therefore will not try to access the spining disk until we send the first identify. For the other PMP where SRST was allowed, I guess the Sil3132 controller would have offline the disks or downgrade the speed unnecessarily. > > * I hope 3726 change is in a separate patch. > > * It waits for reset deadline which currently happens to be 10s. That's correct. I update the description. Gwendal. > > Thanks. > > -- > tejun > ^ permalink raw reply [flat|nested] 35+ messages in thread
* [PATCH] [libata]Issue SRST to Sil3726 PMP 2011-10-12 14:03 ` Mark Lord 2011-10-20 0:02 ` [PATCH] [libata]Issue SRST to Sil3726 PMP Gwendal Grignou 2011-10-20 0:02 ` Gwendal Grignou @ 2011-10-20 0:17 ` Gwendal Grignou 2011-10-20 0:17 ` Gwendal Grignou ` (2 subsequent siblings) 5 siblings, 0 replies; 35+ messages in thread From: Gwendal Grignou @ 2011-10-20 0:17 UTC (permalink / raw) To: htejun, kernel, mihrcke, derry; +Cc: linux-ide, Gwendal Grignou By issuing SRST, . We re enable staggered spin up . We allow slow disks to spin up while we are still in initial error handler However, some controller fails sending SRST while the disk is spinning up behind the port multiplier. To avoid slow disk to be ignored, or link to be downgraded unnecessarily, wait 10s if SRST fails before resetting the ATA port. With a Sil3132. Before the patch: [ 236.184036] ata4.15: hard resetting link [ 236.184038] ata4: controller in dubious state, performing PORT_RST [ 238.338048] ata4.15: SATA link up 1.5 Gbps (SStatus 113 SControl 10) [ 239.549102] ata4.00: hard resetting link [ 239.854315] ata4.00: SATA link up 1.5 Gbps (SStatus 113 SControl 310) [ 239.854344] ata4.01: hard resetting link [ 240.159316] ata4.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 240.159344] ata4.02: hard resetting link [ 240.464316] ata4.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 240.464343] ata4.03: hard resetting link [ 240.769314] ata4.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 240.769342] ata4.04: hard resetting link [ 241.074316] ata4.04: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 241.074344] ata4.05: hard resetting link [ 241.379314] ata4.05: SATA link up 1.5 Gbps (SStatus 113 SControl 310) [ 241.382672] ata4.00: configured for UDMA/100 [ 241.492027] ata4.01: failed to IDENTIFY (I/O error, err_mask=0x11) [ 241.492030] ata4.01: revalidation failed (errno=-5) [ 241.492033] ata4.15: hard resetting link After the patch: [ 19.436422] ata4.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports, feat 0x1/0x9 [ 19.454715] ata4.00: hard resetting link [ 19.880032] ata4.00: softreset failed (SRST command error) [ 19.880048] ata4.00: failed to read SCR 0 (Emask=0x40) [ 19.880051] ata4.00: reset failed (errno=-85), retrying in 10 secs [ 29.454092] ata4.00: reset failed, giving up [ 29.454099] ata4.15: hard resetting link [ 29.454102] ata4: controller in dubious state, performing PORT_RST [ 31.608046] ata4.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 31.608431] ata4.00: hard resetting link [ 31.924284] ata4.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 31.924335] ata4.01: hard resetting link [ 32.350029] ata4.01: softreset failed (SRST command error) [ 32.460032] ata4.01: failed to read SCR 0 (Emask=0x1) [ 32.460036] ata4.01: reset failed (errno=-85), retrying in 10 secs [ 41.924139] ata4.01: reset failed, giving up [ 41.924146] ata4.15: hard resetting link [ 41.924148] ata4: controller in dubious state, performing PORT_RST [ 44.078047] ata4.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 44.078384] ata4.00: hard resetting link Patch also tested with Marvel 7042 and Sil3726. Signed off version. Gwendal Grignou (1): [libata]Issue SRST to Sil3726 PMP drivers/ata/libata-eh.c | 12 +++++++++++- drivers/ata/libata-pmp.c | 7 ++----- 2 files changed, 13 insertions(+), 6 deletions(-) -- 1.7.3.1 ^ permalink raw reply [flat|nested] 35+ messages in thread
* [PATCH] [libata]Issue SRST to Sil3726 PMP 2011-10-12 14:03 ` Mark Lord ` (2 preceding siblings ...) 2011-10-20 0:17 ` Gwendal Grignou @ 2011-10-20 0:17 ` Gwendal Grignou 2011-10-20 0:35 ` [PATCH] [libata]Send SRST to disks behind " Gwendal Grignou 2011-10-20 0:35 ` [PATCH] [libata]Issue SRST to Disks behind Sil3726 Gwendal Grignou 5 siblings, 0 replies; 35+ messages in thread From: Gwendal Grignou @ 2011-10-20 0:17 UTC (permalink / raw) To: htejun, kernel, mihrcke, derry; +Cc: linux-ide, Gwendal Grignou Reenable sending SRST to devices connected behind a Sil3726 PMP. This allow staggered spinups and handles drives that spins up slowly. While the drives spin up, the PMP will not accept SRST. Most controller reissues the reset until the drive is ready, while some [Sil3124] returns an error. In ata_eh_error, wait 10s before reset the ATA port and try again. Signed-off-by: Gwendal Grignou <gwendal@google.com> --- drivers/ata/libata-eh.c | 12 +++++++++++- drivers/ata/libata-pmp.c | 7 ++----- 2 files changed, 13 insertions(+), 6 deletions(-) diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c index c021186..927d750 100644 --- a/drivers/ata/libata-eh.c +++ b/drivers/ata/libata-eh.c @@ -2882,7 +2882,7 @@ int ata_eh_reset(struct ata_link *link, int classify, sata_scr_read(link, SCR_STATUS, &sstatus)) rc = -ERESTART; - if (rc == -ERESTART || try >= max_tries) { + if (try >= max_tries) { /* * Thaw host port even if reset failed, so that the port * can be retried on the next phy event. This risks @@ -2908,6 +2908,16 @@ int ata_eh_reset(struct ata_link *link, int classify, ata_eh_acquire(ap); } + /* + * While disks spinup behind PMP, some controllers fail sending SRST. + * They need to be reset - as well as the PMP - before retrying. + */ + if (rc == -ERESTART) { + if (ata_is_host_link(link)) + ata_eh_thaw_port(ap); + goto out; + } + if (try == max_tries - 1) { sata_down_spd_limit(link, 0); if (slave) diff --git a/drivers/ata/libata-pmp.c b/drivers/ata/libata-pmp.c index 3eb2b81..183643f 100644 --- a/drivers/ata/libata-pmp.c +++ b/drivers/ata/libata-pmp.c @@ -388,12 +388,9 @@ static void sata_pmp_quirks(struct ata_port *ap) /* link reports offline after LPM */ link->flags |= ATA_LFLAG_NO_LPM; - /* Class code report is unreliable and SRST - * times out under certain configurations. - */ + /* Class code report is unreliable. */ if (link->pmp < 5) - link->flags |= ATA_LFLAG_NO_SRST | - ATA_LFLAG_ASSUME_ATA; + link->flags |= ATA_LFLAG_ASSUME_ATA; /* port 5 is for SEMB device and it doesn't like SRST */ if (link->pmp == 5) -- 1.7.3.1 ^ permalink raw reply related [flat|nested] 35+ messages in thread
* [PATCH] [libata]Send SRST to disks behind Sil3726 PMP. 2011-10-12 14:03 ` Mark Lord ` (3 preceding siblings ...) 2011-10-20 0:17 ` Gwendal Grignou @ 2011-10-20 0:35 ` Gwendal Grignou 2011-10-20 0:35 ` [PATCH] [libata]Issue SRST to Disks behind Sil3726 Gwendal Grignou 5 siblings, 0 replies; 35+ messages in thread From: Gwendal Grignou @ 2011-10-20 0:35 UTC (permalink / raw) To: htejun, kernel, mihrcke, derry; +Cc: linux-ide, Gwendal Grignou By issuing SRST, . We re enable staggered spin up . We allow slow disks to spin up while we are still in initial error handler However, some controller fails sending SRST while the disk is spinning up behind the port multiplier. To avoid slow disk to be ignored, or link to be downgraded unnecessarily, wait for the reset deadline if SRST fails before resetting the ATA port. With a Sil3132. Before the patch: [ 236.184036] ata4.15: hard resetting link [ 236.184038] ata4: controller in dubious state, performing PORT_RST [ 238.338048] ata4.15: SATA link up 1.5 Gbps (SStatus 113 SControl 10) [ 239.549102] ata4.00: hard resetting link [ 239.854315] ata4.00: SATA link up 1.5 Gbps (SStatus 113 SControl 310) [ 239.854344] ata4.01: hard resetting link [ 240.159316] ata4.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 240.159344] ata4.02: hard resetting link [ 240.464316] ata4.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 240.464343] ata4.03: hard resetting link [ 240.769314] ata4.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 240.769342] ata4.04: hard resetting link [ 241.074316] ata4.04: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 241.074344] ata4.05: hard resetting link [ 241.379314] ata4.05: SATA link up 1.5 Gbps (SStatus 113 SControl 310) [ 241.382672] ata4.00: configured for UDMA/100 [ 241.492027] ata4.01: failed to IDENTIFY (I/O error, err_mask=0x11) [ 241.492030] ata4.01: revalidation failed (errno=-5) [ 241.492033] ata4.15: hard resetting link After the patch: [ 19.436422] ata4.15: Port Multiplier 1.1, 0x1095:0x3726 r23, 6 ports, feat 0x1/0x9 [ 19.454715] ata4.00: hard resetting link [ 19.880032] ata4.00: softreset failed (SRST command error) [ 19.880048] ata4.00: failed to read SCR 0 (Emask=0x40) [ 19.880051] ata4.00: reset failed (errno=-85), retrying in 10 secs [ 29.454092] ata4.00: reset failed, giving up [ 29.454099] ata4.15: hard resetting link [ 29.454102] ata4: controller in dubious state, performing PORT_RST [ 31.608046] ata4.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 31.608431] ata4.00: hard resetting link [ 31.924284] ata4.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 31.924335] ata4.01: hard resetting link [ 32.350029] ata4.01: softreset failed (SRST command error) [ 32.460032] ata4.01: failed to read SCR 0 (Emask=0x1) [ 32.460036] ata4.01: reset failed (errno=-85), retrying in 10 secs [ 41.924139] ata4.01: reset failed, giving up [ 41.924146] ata4.15: hard resetting link [ 41.924148] ata4: controller in dubious state, performing PORT_RST [ 44.078047] ata4.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 44.078384] ata4.00: hard resetting link Patch also tested with Marvel 7042 and Sil3726. Gwendal Grignou (1): [libata]Issue SRST to Sil3726 PMP drivers/ata/libata-eh.c | 12 +++++++++++- drivers/ata/libata-pmp.c | 7 ++----- 2 files changed, 13 insertions(+), 6 deletions(-) -- 1.7.3.1 ^ permalink raw reply [flat|nested] 35+ messages in thread
* [PATCH] [libata]Issue SRST to Disks behind Sil3726 2011-10-12 14:03 ` Mark Lord ` (4 preceding siblings ...) 2011-10-20 0:35 ` [PATCH] [libata]Send SRST to disks behind " Gwendal Grignou @ 2011-10-20 0:35 ` Gwendal Grignou 2011-10-20 0:37 ` Tejun Heo 5 siblings, 1 reply; 35+ messages in thread From: Gwendal Grignou @ 2011-10-20 0:35 UTC (permalink / raw) To: htejun, kernel, mihrcke, derry; +Cc: linux-ide, Gwendal Grignou Reenable sending SRST to devices connected behind a Sil3726 PMP. This allow staggered spinups and handles drives that spins up slowly. While the drives spin up, the PMP will not accept SRST. Most controllers reissue the reset until the drive is ready, while some [Sil3124] returns an error. In ata_eh_error, wait for the next reset deadline before resetting the ATA port and trying again. Signed-off-by: Gwendal Grignou <gwendal@google.com> --- drivers/ata/libata-eh.c | 12 +++++++++++- drivers/ata/libata-pmp.c | 7 ++----- 2 files changed, 13 insertions(+), 6 deletions(-) diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c index c021186..927d750 100644 --- a/drivers/ata/libata-eh.c +++ b/drivers/ata/libata-eh.c @@ -2882,7 +2882,7 @@ int ata_eh_reset(struct ata_link *link, int classify, sata_scr_read(link, SCR_STATUS, &sstatus)) rc = -ERESTART; - if (rc == -ERESTART || try >= max_tries) { + if (try >= max_tries) { /* * Thaw host port even if reset failed, so that the port * can be retried on the next phy event. This risks @@ -2908,6 +2908,16 @@ int ata_eh_reset(struct ata_link *link, int classify, ata_eh_acquire(ap); } + /* + * While disks spinup behind PMP, some controllers fail sending SRST. + * They need to be reset - as well as the PMP - before retrying. + */ + if (rc == -ERESTART) { + if (ata_is_host_link(link)) + ata_eh_thaw_port(ap); + goto out; + } + if (try == max_tries - 1) { sata_down_spd_limit(link, 0); if (slave) diff --git a/drivers/ata/libata-pmp.c b/drivers/ata/libata-pmp.c index 3eb2b81..183643f 100644 --- a/drivers/ata/libata-pmp.c +++ b/drivers/ata/libata-pmp.c @@ -388,12 +388,9 @@ static void sata_pmp_quirks(struct ata_port *ap) /* link reports offline after LPM */ link->flags |= ATA_LFLAG_NO_LPM; - /* Class code report is unreliable and SRST - * times out under certain configurations. - */ + /* Class code report is unreliable. */ if (link->pmp < 5) - link->flags |= ATA_LFLAG_NO_SRST | - ATA_LFLAG_ASSUME_ATA; + link->flags |= ATA_LFLAG_ASSUME_ATA; /* port 5 is for SEMB device and it doesn't like SRST */ if (link->pmp == 5) -- 1.7.3.1 ^ permalink raw reply related [flat|nested] 35+ messages in thread
* Re: [PATCH] [libata]Issue SRST to Disks behind Sil3726 2011-10-20 0:35 ` [PATCH] [libata]Issue SRST to Disks behind Sil3726 Gwendal Grignou @ 2011-10-20 0:37 ` Tejun Heo 0 siblings, 0 replies; 35+ messages in thread From: Tejun Heo @ 2011-10-20 0:37 UTC (permalink / raw) To: Gwendal Grignou; +Cc: kernel, mihrcke, derry, linux-ide On Wed, Oct 19, 2011 at 05:35:53PM -0700, Gwendal Grignou wrote: > Reenable sending SRST to devices connected behind a Sil3726 PMP. > This allow staggered spinups and handles drives that spins up slowly. > > While the drives spin up, the PMP will not accept SRST. > Most controllers reissue the reset until the drive is ready, while > some [Sil3124] returns an error. > In ata_eh_error, wait for the next reset deadline before resetting the ATA > port and trying again. > > > Signed-off-by: Gwendal Grignou <gwendal@google.com> Acked-by: Tejun Heo <tj@kernel.org> I hope this can be applied to other controllers too as the failure mode should be similar for all SIMG PMPs. Thanks. -- tejun ^ permalink raw reply [flat|nested] 35+ messages in thread
* Re: [PATCH] libata: Allow SOFT_RESET for Sil3726 2011-10-06 6:03 ` [PATCH] libata: Allow SOFT_RESET for Sil3726 Gwendal Grignou 2011-10-06 8:03 ` Tejun Heo @ 2011-10-06 10:42 ` Sergei Shtylyov 1 sibling, 0 replies; 35+ messages in thread From: Sergei Shtylyov @ 2011-10-06 10:42 UTC (permalink / raw) To: Gwendal Grignou; +Cc: mihrcke, linux-ide Hello. On 06-10-2011 10:03, Gwendal Grignou wrote: > Allow controllers to send SOFT_RESET to Sil3726 PMP. > This PMP does not accept frames until the drive connected to > its port spins up. > Some controller [Sil3132 family] can not wait for the drive to spinup > and fails the reset, leading to unnecessary speed downgrade. > Not allowing to send SOFT_RESET can lead some drive slow to spinup > to be ignored and produces weird error messages. > This fix allows the error handler to wait if the controller is unable > to send a SOFT_RESET. > Change-Id: I7eeea152facb4b76e5c69cfde5ef8188874fbaba Please get rid of this line, it has no place in the upstream commit. > Signed-off-by: Gwendal Grignou<gwendal@google.com> > --- > drivers/ata/libata-eh.c | 11 ++++++++++- > drivers/ata/libata-pmp.c | 10 ++++------ > include/linux/libata.h | 1 + > 3 files changed, 15 insertions(+), 7 deletions(-) > diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c > index 49af350..60223c3 100644 > --- a/drivers/ata/libata-eh.c > +++ b/drivers/ata/libata-eh.c > @@ -2805,7 +2805,14 @@ int ata_eh_reset(struct ata_link *link, int classify, > sata_scr_read(link, SCR_STATUS,&sstatus)) > rc = -ERESTART; > > - if (rc == -ERESTART || try>= max_tries) > + if (try>= max_tries) > + goto out; > + > + /* Some PMP will not serve SRST until the disk is spunup, > + * if the controller can not wait for the PMP to acknowledge the frame, > + * wait here */ The preferred multi-line comment style: /* * bla * bla */ > + if (rc == -ERESTART&& > + !((lflags& ATA_LFLAG_WAIT_SRST)&& (reset == softreset))) > goto out; > > now = jiffies; [...] > diff --git a/drivers/ata/libata-pmp.c b/drivers/ata/libata-pmp.c > index ad0e71d..5fbbe2f 100644 > --- a/drivers/ata/libata-pmp.c > +++ b/drivers/ata/libata-pmp.c > @@ -365,13 +365,11 @@ static void sata_pmp_quirks(struct ata_port *ap) > if (vendor == 0x1095&& devid == 0x3726) { > /* sil3726 quirks */ > ata_for_each_link(link, ap, EDGE) { > - /* Class code report is unreliable and SRST > - * times out under certain configurations. > - */ > + /* Class code report is unreliable */ > + /* PMP does not forward SRST until the drive spins up */ > if (link->pmp < 5) > - link->flags |= ATA_LFLAG_NO_SRST | > - ATA_LFLAG_ASSUME_ATA; > - Why remove the empty line? > + link->flags |= ATA_LFLAG_ASSUME_ATA | > + ATA_LFLAG_WAIT_SRST; > /* port 5 is for SEMB device and it doesn't like SRST */ > if (link->pmp == 5) > link->flags |= ATA_LFLAG_NO_SRST | WBR, Sergei ^ permalink raw reply [flat|nested] 35+ messages in thread
[parent not found: <CAMHSBOV8rSW3jumpx8URZrgo8w1He9zruP7yAOw7uhQOaAj3Xg@mail.gmail.com>]
* Re: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) [not found] ` <CAMHSBOV8rSW3jumpx8URZrgo8w1He9zruP7yAOw7uhQOaAj3Xg@mail.gmail.com> @ 2011-10-06 6:07 ` Gwendal Grignou 0 siblings, 0 replies; 35+ messages in thread From: Gwendal Grignou @ 2011-10-06 6:07 UTC (permalink / raw) To: Mike I; +Cc: linux-ide Forgot to remove make it plain text, sorry for the spam. Gwendal. On Wed, Oct 5, 2011 at 11:05 PM, Gwendal Grignou <gwendal@google.com> wrote: > > Forgot gmail is not great to send patches, used git send-email instead. > Gwendal. > > On Wed, Oct 5, 2011 at 10:48 PM, Gwendal Grignou <gwendal@google.com> wrote: >> >> I think I know what is going on. One of your disks at least is slow to >> spinup. Due to a bug/feature in silicon image disk controller and pmp, >> at bring up we can not issue a SOFT_RESET and wait for the disk to >> spinup and then continue. >> That why we set ATA_LFLAG_NO_SRST in sata_pmp_quirks(). >> So what happen is we go into a function that issue identify, but we >> fail, the disk is not ready [it is spinning up], so we retry. >> 3 times. >> >> From the first hard reset: 12888.470385, to the time you got the final >> error: 12901.397305 ~ 12.9s >> In the second case, your controller can send SOFT_RESET and wait for >> the device to respond. >> Time for the disk to spinup: >> 28010.630028 - 27997.097116 ~ 13.5s >> As you can see, you are borderline with the PMP, but the controller >> did not "wait" enough in the first case. >> Given the spinup time varies with drive, age, time since last >> spin-up..., it may work one day and fail the next. >> To work around the problem, I have a patch that consist of allowing >> the silicon image control to send a reset, but if it fails, we spin >> for a fixed amount of time and retry. This is not very nice, it is a >> better design to wait for event that waiting a fixed amount of time. >> You may have to alter ATA_LFLAG_WAIT_SRST to use the first bit available. >> >> Can you try with the following patch? >> >> Thanks, >> Gwendal. >> >> diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c >> index 228740f..b98b02d 100644 >> --- a/drivers/ata/libata-eh.c >> +++ b/drivers/ata/libata-eh.c >> @@ -2798,7 +2798,14 @@ int ata_eh_reset(struct ata_link *link, int classify, >> sata_scr_read(link, SCR_STATUS, &sstatus)) >> rc = -ERESTART; >> >> - if (rc == -ERESTART || try >= max_tries) >> + if (try >= max_tries) >> + goto out; >> + >> + /* Some PMP will not serve SRST until the disk is spunup, >> + * if the controller can not wait for the PMP to acknowledge the frame, >> + * wait here */ >> + if (rc == -ERESTART && >> + !((lflags & ATA_LFLAG_WAIT_SRST) && (reset == softreset))) >> goto out; >> >> now = jiffies; >> @@ -2813,6 +2820,8 @@ int ata_eh_reset(struct ata_link *link, int classify, >> delta = schedule_timeout_uninterruptible(delta); >> } >> >> + if (rc == -ERESTART) >> + goto out; >> if (try == max_tries - 1) { >> sata_down_spd_limit(link, 0); >> if (slave) >> diff --git a/drivers/ata/libata-pmp.c b/drivers/ata/libata-pmp.c >> index 00305f4..d21ad7d 100644 >> --- a/drivers/ata/libata-pmp.c >> +++ b/drivers/ata/libata-pmp.c >> @@ -325,13 +351,11 @@ static void sata_pmp_quirks(struct ata_port *ap) >> if (vendor == 0x1095 && devid == 0x3726) { >> /* sil3726 quirks */ >> ata_for_each_link(link, ap, EDGE) { >> - /* Class code report is unreliable and SRST >> - * times out under certain configurations. >> - */ >> + /* Class code report is unreliable */ >> + /* PMP does not forward SRST until the drive spins up */ >> if (link->pmp < 5) >> - link->flags |= ATA_LFLAG_NO_SRST | >> - ATA_LFLAG_ASSUME_ATA; >> - >> + link->flags |= ATA_LFLAG_ASSUME_ATA | >> + ATA_LFLAG_WAIT_SRST; >> /* port 5 is for SEMB device and it doesn't like SRST */ >> if (link->pmp == 5) >> link->flags |= ATA_LFLAG_NO_SRST | >> diff --git a/include/linux/libata.h b/include/linux/libata.h >> index b2f2003..3a18caa 100644 >> --- a/include/linux/libata.h >> +++ b/include/linux/libata.h >> @@ -172,6 +172,7 @@ enum { >> ATA_LFLAG_NO_RETRY = (1 << 5), /* don't retry this link */ >> ATA_LFLAG_DISABLED = (1 << 6), /* link is disabled */ >> ATA_LFLAG_SW_ACTIVITY = (1 << 7), /* keep activity stats */ >> + ATA_LFLAG_WAIT_SRST = (1 << 8), /* add delay when SRST fails */ >> >> /* struct ata_port flags */ >> ATA_FLAG_SLAVE_POSS = (1 << 0), /* host supports slave dev */ >> >> >> On Fri, Sep 30, 2011 at 2:54 PM, Mike I <mihrcke@gmail.com> wrote: >> > >> > tj <at> kernel.org <tj <at> kernel.org> writes: >> > >> > > >> > > Hello, >> > > >> > > How did that go? >> > > >> > > Thanks. >> > > >> > >> > Like Derry who started this thread, I too had seen an old thread from >> > October/November 2008 with what appeared to be no resolution to this problem. >> > Now, finding this thread, again, with no apparent resolution to this problem. >> > >> > I'm currently running Ubuntu 10.04 (lucid), kernel 2.6.32-33-generic. I've no >> > experience with applying these git patches, and my searching to figure out how >> > it works have not helped. >> > >> > I'm using an Addonics eSATA PCI-X controller with the SiI3124 chipset, and I >> > have an Addonics PM in an external enclosure, with a 5 bay/tray DAS. Some of >> > my drives give me this problem: (this occurs for me with pretty much ALL >> > Samsung hard drives) >> > [12888.470308] ata9.01: exception Emask 0x10 SAct 0x0 SErr 0x4050000 action 0xf >> > [12888.470313] ata9.01: SError: { PHYRdyChg CommWake DevExch } >> > [12888.470385] ata9.01: hard resetting link >> > [12889.211597] ata9.01: SATA link up 3.0 Gbps (SStatus 123 SControl 320) >> > [12889.211686] ata9.01: failed to IDENTIFY (I/O error, err_mask=0x11) >> > [12889.211692] ata9.15: hard resetting link >> > [12891.430086] ata9.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) >> > [12891.430397] ata9.00: hard resetting link >> > [12891.780786] ata9.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) >> > [12894.211103] ata9.01: hard resetting link >> > [12894.560424] ata9.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) >> > [12894.560466] ata9.02: hard resetting link >> > [12894.914176] ata9.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) >> > [12894.914222] ata9.03: hard resetting link >> > [12895.264141] ata9.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) >> > [12895.264169] ata9.04: hard resetting link >> > [12895.612930] ata9.04: SATA link down (SStatus 0 SControl 320) >> > [12895.613007] ata9.05: hard resetting link >> > [12895.964143] ata9.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) >> > [12896.065908] ata9.00: configured for UDMA/100 >> > [12896.065970] ata9.01: failed to IDENTIFY (I/O error, err_mask=0x11) >> > [12896.065977] ata9.15: hard resetting link >> > [12898.283804] ata9.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) >> > [12898.284128] ata9.00: hard resetting link >> > [12898.634174] ata9.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) >> > [12899.562524] ata9.01: hard resetting link >> > [12899.914147] ata9.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) >> > [12899.914180] ata9.02: hard resetting link >> > [12900.261682] ata9.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) >> > [12900.261724] ata9.03: hard resetting link >> > [12900.610413] ata9.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) >> > [12900.961283] ata9.05: hard resetting link >> > [12901.310385] ata9.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) >> > [12901.397241] ata9.00: configured for UDMA/100 >> > [12901.397300] ata9.01: failed to IDENTIFY (I/O error, err_mask=0x11) >> > [12901.397305] ata9.01: failed to recover link after 3 tries, disabling >> > [12901.397311] ata9.15: hard resetting link >> > [12903.613694] ata9.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) >> > [12903.960564] ata9.00: hard resetting link >> > [12904.311125] ata9.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) >> > [12905.260154] ata9.02: hard resetting link >> > [12905.602929] ata9.02: SATA link up 3.0 Gbps (SStatus 123 SControl 300) >> > [12905.611319] ata9.03: hard resetting link >> > [12905.962555] ata9.03: SATA link up 3.0 Gbps (SStatus 123 SControl 300) >> > [12905.962592] ata9.04: hard resetting link >> > [12906.312931] ata9.04: SATA link down (SStatus 0 SControl 320) >> > [12906.313004] ata9.05: hard resetting link >> > [12906.660409] ata9.05: SATA link up 1.5 Gbps (SStatus 113 SControl 320) >> > [12906.753619] ata9.00: configured for UDMA/100 >> > [12906.766586] ata9.02: configured for UDMA/100 >> > [12906.771917] ata9.03: configured for UDMA/100 >> > [12907.121462] ata9: EH complete >> > >> > If I hot plug the same drive using a port directly off my mobo(no PM in the >> > mix), I get this result(drive connects/mounts/works): >> > [27997.097104] ata5: exception Emask 0x10 SAct 0x0 SErr 0x4050000 action >> > 0xe frozen >> > [27997.097108] ata5: irq_stat 0x00400040, connection status changed >> > [27997.097111] ata5: SError: { PHYRdyChg CommWake DevExch } >> > [27997.097116] ata5: hard resetting link >> > [28007.147622] ata5: softreset failed (device not ready) >> > [28007.147627] ata5: hard resetting link >> > [28010.630028] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300) >> > [28010.748595] ata5.00: ATA-7: SAMSUNG HD154UI, 1AG01118, max UDMA7 >> > [28010.748599] ata5.00: 2930277168 sectors, multi 0: LBA48 NCQ (depth 31/32) >> > [28010.755227] ata5.00: configured for UDMA/133 >> > [28010.755237] ata5: EH complete >> > [28010.756338] scsi 4:0:0:0: Direct-Access ATA SAMSUNG HD154UI 1AG0 >> > PQ: 0 ANSI: 5 >> > [28010.756475] sd 4:0:0:0: Attached scsi generic sg10 type 0 >> > [28010.756572] sd 4:0:0:0: [sdj] 2930277168 512-byte logical blocks: (1.50 >> > TB/1.36 TiB) >> > [28010.756613] sd 4:0:0:0: [sdj] Write Protect is off >> > [28010.756616] sd 4:0:0:0: [sdj] Mode Sense: 00 3a 00 00 >> > [28010.756636] sd 4:0:0:0: [sdj] Write cache: enabled, read cache: enabled, >> > doesn't support DPO or FUA >> > [28010.756760] sdj: sdj1 >> > [28010.816161] sd 4:0:0:0: [sdj] Attached SCSI disk >> > >> > I've been using Ubuntu for a few years now, and have been living with the >> > problem...working around it with USB docking stations and such. But, I'd >> > really hope to see/find this problem worked out. >> > >> > Thoughts/tips/suggestions? Since I'm pretty much a novice when it comes to >> > patching, a link to a guide for git patching would be appreciated too. >> > >> > Thank You, >> > Mike >> > >> > -- >> > To unsubscribe from this list: send the line "unsubscribe linux-ide" in >> > the body of a message to majordomo@vger.kernel.org >> > More majordomo info at http://vger.kernel.org/majordomo-info.html > ^ permalink raw reply [flat|nested] 35+ messages in thread
* Re: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) 2011-10-06 5:48 ` Gwendal Grignou 2011-10-06 6:03 ` [PATCH] libata: Allow SOFT_RESET for Sil3726 Gwendal Grignou [not found] ` <CAMHSBOV8rSW3jumpx8URZrgo8w1He9zruP7yAOw7uhQOaAj3Xg@mail.gmail.com> @ 2011-10-08 18:25 ` Michael Ihrcke 2011-10-12 2:06 ` Michael Ihrcke 2 siblings, 1 reply; 35+ messages in thread From: Michael Ihrcke @ 2011-10-08 18:25 UTC (permalink / raw) To: Gwendal Grignou; +Cc: linux-ide Thank you... Will this require a complete kernel recompile? Or is there an easier way to include this patch? I have little to no experience with working with patches at this level. I've been doing research on how to use this patch, and I'm close, but, I'm not sure if I need to attack compiling a kernel, or if I can somehow just patch libata or something like that? Thank you, Mike On Thu, Oct 6, 2011 at 12:48 AM, Gwendal Grignou <gwendal@google.com> wrote: > > I think I know what is going on. One of your disks at least is slow to > spinup. Due to a bug/feature in silicon image disk controller and pmp, > at bring up we can not issue a SOFT_RESET and wait for the disk to > spinup and then continue. > That why we set ATA_LFLAG_NO_SRST in sata_pmp_quirks(). > So what happen is we go into a function that issue identify, but we > fail, the disk is not ready [it is spinning up], so we retry. > 3 times. > > From the first hard reset: 12888.470385, to the time you got the final > error: 12901.397305 ~ 12.9s > In the second case, your controller can send SOFT_RESET and wait for > the device to respond. > Time for the disk to spinup: > 28010.630028 - 27997.097116 ~ 13.5s > As you can see, you are borderline with the PMP, but the controller > did not "wait" enough in the first case. > Given the spinup time varies with drive, age, time since last > spin-up..., it may work one day and fail the next. > To work around the problem, I have a patch that consist of allowing > the silicon image control to send a reset, but if it fails, we spin > for a fixed amount of time and retry. This is not very nice, it is a > better design to wait for event that waiting a fixed amount of time. > You may have to alter ATA_LFLAG_WAIT_SRST to use the first bit available. > > Can you try with the following patch? > > Thanks, > Gwendal. > > diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c > index 228740f..b98b02d 100644 > --- a/drivers/ata/libata-eh.c > +++ b/drivers/ata/libata-eh.c > @@ -2798,7 +2798,14 @@ int ata_eh_reset(struct ata_link *link, int classify, > sata_scr_read(link, SCR_STATUS, &sstatus)) > rc = -ERESTART; > > - if (rc == -ERESTART || try >= max_tries) > + if (try >= max_tries) > + goto out; > + > + /* Some PMP will not serve SRST until the disk is spunup, > + * if the controller can not wait for the PMP to acknowledge the frame, > + * wait here */ > + if (rc == -ERESTART && > + !((lflags & ATA_LFLAG_WAIT_SRST) && (reset == softreset))) > goto out; > > now = jiffies; > @@ -2813,6 +2820,8 @@ int ata_eh_reset(struct ata_link *link, int classify, > delta = schedule_timeout_uninterruptible(delta); > } > > + if (rc == -ERESTART) > + goto out; > if (try == max_tries - 1) { > sata_down_spd_limit(link, 0); > if (slave) > diff --git a/drivers/ata/libata-pmp.c b/drivers/ata/libata-pmp.c > index 00305f4..d21ad7d 100644 > --- a/drivers/ata/libata-pmp.c > +++ b/drivers/ata/libata-pmp.c > @@ -325,13 +351,11 @@ static void sata_pmp_quirks(struct ata_port *ap) > if (vendor == 0x1095 && devid == 0x3726) { > /* sil3726 quirks */ > ata_for_each_link(link, ap, EDGE) { > - /* Class code report is unreliable and SRST > - * times out under certain configurations. > - */ > + /* Class code report is unreliable */ > + /* PMP does not forward SRST until the drive spins up */ > if (link->pmp < 5) > - link->flags |= ATA_LFLAG_NO_SRST | > - ATA_LFLAG_ASSUME_ATA; > - > + link->flags |= ATA_LFLAG_ASSUME_ATA | > + ATA_LFLAG_WAIT_SRST; > /* port 5 is for SEMB device and it doesn't like SRST */ > if (link->pmp == 5) > link->flags |= ATA_LFLAG_NO_SRST | > diff --git a/include/linux/libata.h b/include/linux/libata.h > index b2f2003..3a18caa 100644 > --- a/include/linux/libata.h > +++ b/include/linux/libata.h > @@ -172,6 +172,7 @@ enum { > ATA_LFLAG_NO_RETRY = (1 << 5), /* don't retry this link */ > ATA_LFLAG_DISABLED = (1 << 6), /* link is disabled */ > ATA_LFLAG_SW_ACTIVITY = (1 << 7), /* keep activity stats */ > + ATA_LFLAG_WAIT_SRST = (1 << 8), /* add delay when SRST fails */ > > /* struct ata_port flags */ > ATA_FLAG_SLAVE_POSS = (1 << 0), /* host supports slave dev */ > > ^ permalink raw reply [flat|nested] 35+ messages in thread
* Re: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) 2011-10-08 18:25 ` Michael Ihrcke @ 2011-10-12 2:06 ` Michael Ihrcke 2011-10-13 2:09 ` Mike I 0 siblings, 1 reply; 35+ messages in thread From: Michael Ihrcke @ 2011-10-12 2:06 UTC (permalink / raw) To: Gwendal Grignou; +Cc: linux-ide Thanks again for the help, but, I could use a little more instruction... I've figured out how to apply the patch to the source, and compiled the libata-pmp, and libata-eh modules(/drivers/ata), but, I cannot figure out what to do from here. The libata-pmp driver/module does not seem to be loaded on my system to begin with...maybe this was part of my problem. On Sat, Oct 8, 2011 at 1:25 PM, Michael Ihrcke <mihrcke@gmail.com> wrote: > Thank you... > > Will this require a complete kernel recompile? > Or is there an easier way to include this patch? > > I have little to no experience with working with patches at this level. > I've been doing research on how to use this patch, and I'm close, but, I'm not > sure if I need to attack compiling a kernel, or if I can somehow just patch > libata or something like that? > > Thank you, > Mike > > On Thu, Oct 6, 2011 at 12:48 AM, Gwendal Grignou <gwendal@google.com> wrote: >> >> I think I know what is going on. One of your disks at least is slow to >> spinup. Due to a bug/feature in silicon image disk controller and pmp, >> at bring up we can not issue a SOFT_RESET and wait for the disk to >> spinup and then continue. >> That why we set ATA_LFLAG_NO_SRST in sata_pmp_quirks(). >> So what happen is we go into a function that issue identify, but we >> fail, the disk is not ready [it is spinning up], so we retry. >> 3 times. >> >> From the first hard reset: 12888.470385, to the time you got the final >> error: 12901.397305 ~ 12.9s >> In the second case, your controller can send SOFT_RESET and wait for >> the device to respond. >> Time for the disk to spinup: >> 28010.630028 - 27997.097116 ~ 13.5s >> As you can see, you are borderline with the PMP, but the controller >> did not "wait" enough in the first case. >> Given the spinup time varies with drive, age, time since last >> spin-up..., it may work one day and fail the next. >> To work around the problem, I have a patch that consist of allowing >> the silicon image control to send a reset, but if it fails, we spin >> for a fixed amount of time and retry. This is not very nice, it is a >> better design to wait for event that waiting a fixed amount of time. >> You may have to alter ATA_LFLAG_WAIT_SRST to use the first bit available. >> >> Can you try with the following patch? >> >> Thanks, >> Gwendal. >> >> diff --git a/drivers/ata/libata-eh.c b/drivers/ata/libata-eh.c >> index 228740f..b98b02d 100644 >> --- a/drivers/ata/libata-eh.c >> +++ b/drivers/ata/libata-eh.c >> @@ -2798,7 +2798,14 @@ int ata_eh_reset(struct ata_link *link, int classify, >> sata_scr_read(link, SCR_STATUS, &sstatus)) >> rc = -ERESTART; >> >> - if (rc == -ERESTART || try >= max_tries) >> + if (try >= max_tries) >> + goto out; >> + >> + /* Some PMP will not serve SRST until the disk is spunup, >> + * if the controller can not wait for the PMP to acknowledge the frame, >> + * wait here */ >> + if (rc == -ERESTART && >> + !((lflags & ATA_LFLAG_WAIT_SRST) && (reset == softreset))) >> goto out; >> >> now = jiffies; >> @@ -2813,6 +2820,8 @@ int ata_eh_reset(struct ata_link *link, int classify, >> delta = schedule_timeout_uninterruptible(delta); >> } >> >> + if (rc == -ERESTART) >> + goto out; >> if (try == max_tries - 1) { >> sata_down_spd_limit(link, 0); >> if (slave) >> diff --git a/drivers/ata/libata-pmp.c b/drivers/ata/libata-pmp.c >> index 00305f4..d21ad7d 100644 >> --- a/drivers/ata/libata-pmp.c >> +++ b/drivers/ata/libata-pmp.c >> @@ -325,13 +351,11 @@ static void sata_pmp_quirks(struct ata_port *ap) >> if (vendor == 0x1095 && devid == 0x3726) { >> /* sil3726 quirks */ >> ata_for_each_link(link, ap, EDGE) { >> - /* Class code report is unreliable and SRST >> - * times out under certain configurations. >> - */ >> + /* Class code report is unreliable */ >> + /* PMP does not forward SRST until the drive spins up */ >> if (link->pmp < 5) >> - link->flags |= ATA_LFLAG_NO_SRST | >> - ATA_LFLAG_ASSUME_ATA; >> - >> + link->flags |= ATA_LFLAG_ASSUME_ATA | >> + ATA_LFLAG_WAIT_SRST; >> /* port 5 is for SEMB device and it doesn't like SRST */ >> if (link->pmp == 5) >> link->flags |= ATA_LFLAG_NO_SRST | >> diff --git a/include/linux/libata.h b/include/linux/libata.h >> index b2f2003..3a18caa 100644 >> --- a/include/linux/libata.h >> +++ b/include/linux/libata.h >> @@ -172,6 +172,7 @@ enum { >> ATA_LFLAG_NO_RETRY = (1 << 5), /* don't retry this link */ >> ATA_LFLAG_DISABLED = (1 << 6), /* link is disabled */ >> ATA_LFLAG_SW_ACTIVITY = (1 << 7), /* keep activity stats */ >> + ATA_LFLAG_WAIT_SRST = (1 << 8), /* add delay when SRST fails */ >> >> /* struct ata_port flags */ >> ATA_FLAG_SLAVE_POSS = (1 << 0), /* host supports slave dev */ >> >> > ^ permalink raw reply [flat|nested] 35+ messages in thread
* Re: Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) 2011-10-12 2:06 ` Michael Ihrcke @ 2011-10-13 2:09 ` Mike I 0 siblings, 0 replies; 35+ messages in thread From: Mike I @ 2011-10-13 2:09 UTC (permalink / raw) To: linux-ide Working much better now...this is what I get when I hot plug a drive that was giving me problems before: [ 211.873069] ata3.01: exception Emask 0x10 SAct 0x0 SErr 0x4050000 action 0xf [ 211.873075] ata3.01: SError: { PHYRdyChg CommWake DevExch } [ 211.873181] ata3.01: limiting SATA link speed to 1.5 Gbps [ 211.873188] ata3.01: hard resetting link [ 212.750032] ata3.01: softreset failed (SRST command error) [ 212.850022] ata3.01: failed to read SCR 0 (Emask=0x1) [ 212.850026] ata3.01: reset failed (errno=-85), retrying in 10 secs [ 221.870023] ata3.01: reset failed, giving up [ 221.870029] ata3.15: hard resetting link [ 221.870032] ata3: controller in dubious state, performing PORT_RST [ 224.140057] ata3.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 224.140364] ata3.02: limiting SATA link speed to 1.5 Gbps [ 224.140402] ata3.03: limiting SATA link speed to 1.5 Gbps [ 224.140440] ata3.04: limiting SATA link speed to 1.5 Gbps [ 224.140477] ata3.05: limiting SATA link speed to 1.5 Gbps [ 224.140481] ata3.00: hard resetting link [ 224.550272] ata3.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 224.550311] ata3.01: hard resetting link [ 225.020043] ata3.01: softreset failed (SRST command error) [ 225.020069] ata3.01: failed to read SCR 0 (Emask=0x40) [ 225.020073] ata3.01: reset failed (errno=-85), retrying in 10 secs [ 234.550024] ata3.01: reset failed, giving up [ 234.550032] ata3.15: hard resetting link [ 234.550036] ata3: controller in dubious state, performing PORT_RST [ 236.810049] ata3.15: SATA link up 3.0 Gbps (SStatus 123 SControl 0) [ 236.810336] ata3.00: hard resetting link [ 237.230271] ata3.00: SATA link up 3.0 Gbps (SStatus 123 SControl 320) [ 237.230310] ata3.01: hard resetting link [ 237.920270] ata3.01: SATA link up 3.0 Gbps (SStatus 123 SControl 300) [ 237.920309] ata3.02: hard resetting link [ 238.270420] ata3.02: SATA link down (SStatus 0 SControl 310) [ 238.270492] ata3.03: hard resetting link [ 238.610434] ata3.03: SATA link down (SStatus 0 SControl 310) [ 238.610504] ata3.04: hard resetting link [ 238.960436] ata3.04: SATA link down (SStatus 0 SControl 310) [ 238.960508] ata3.05: hard resetting link [ 239.310401] ata3.05: SATA link up 1.5 Gbps (SStatus 113 SControl 310) [ 239.413575] ata3.00: configured for UDMA/100 [ 239.420008] ata3.01: ATA-7: SAMSUNG HD154UI, 1AG01118, max UDMA7 [ 239.420012] ata3.01: 2930277168 sectors, multi 0: LBA48 NCQ (depth 31/32) [ 239.426691] ata3.01: configured for UDMA/100 [ 239.426763] ata3: EH complete [ 239.426967] scsi 2:1:0:0: Direct-Access ATA SAMSUNG HD154UI 1AG0 PQ: 0 ANSI: 5 [ 239.427123] sd 2:1:0:0: Attached scsi generic sg6 type 0 [ 239.427138] sd 2:1:0:0: [sde] 2930277168 512-byte logical blocks: (1.50 TB/1.36 TiB) [ 239.427182] sd 2:1:0:0: [sde] Write Protect is off [ 239.427185] sd 2:1:0:0: [sde] Mode Sense: 00 3a 00 00 [ 239.427206] sd 2:1:0:0: [sde] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [ 239.427348] sde: sde1 [ 239.581901] sd 2:1:0:0: [sde] Attached SCSI disk Thank you, Mike ^ permalink raw reply [flat|nested] 35+ messages in thread
end of thread, other threads:[~2011-10-20 0:37 UTC | newest]
Thread overview: 35+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
[not found] <359604ECF8F440408B9634E6146249B42923805F@mail.scl.local>
[not found] ` <20110628095723.GC3386@htj.dyndns.org>
2011-06-30 17:53 ` Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) Derry Bryson
2011-07-12 15:01 ` tj
2011-07-12 19:21 ` Derry Bryson
2011-07-13 13:34 ` tj
2011-07-13 14:39 ` tj
2011-07-13 16:23 ` Derry Bryson
2011-07-14 7:14 ` tj
2011-07-14 17:37 ` Derry Bryson
2011-07-21 9:00 ` tj
2011-07-21 16:22 ` Derry Bryson
2011-07-22 9:50 ` tj
2011-07-22 17:29 ` Derry Bryson
2011-07-22 19:34 ` Derry Bryson
2011-07-30 12:54 ` tj
2011-09-30 21:54 ` Mike I
2011-10-06 5:48 ` Gwendal Grignou
2011-10-06 6:03 ` [PATCH] libata: Allow SOFT_RESET for Sil3726 Gwendal Grignou
2011-10-06 8:03 ` Tejun Heo
2011-10-06 20:44 ` Gwendal Grignou
2011-10-06 22:10 ` Tejun Heo
2011-10-12 14:03 ` Mark Lord
2011-10-20 0:02 ` [PATCH] [libata]Issue SRST to Sil3726 PMP Gwendal Grignou
2011-10-20 0:02 ` Gwendal Grignou
2011-10-20 0:07 ` Tejun Heo
2011-10-20 0:28 ` Gwendal Grignou
2011-10-20 0:17 ` Gwendal Grignou
2011-10-20 0:17 ` Gwendal Grignou
2011-10-20 0:35 ` [PATCH] [libata]Send SRST to disks behind " Gwendal Grignou
2011-10-20 0:35 ` [PATCH] [libata]Issue SRST to Disks behind Sil3726 Gwendal Grignou
2011-10-20 0:37 ` Tejun Heo
2011-10-06 10:42 ` [PATCH] libata: Allow SOFT_RESET for Sil3726 Sergei Shtylyov
[not found] ` <CAMHSBOV8rSW3jumpx8URZrgo8w1He9zruP7yAOw7uhQOaAj3Xg@mail.gmail.com>
2011-10-06 6:07 ` Problem w/ hotplug on sata_sil24 w/ PMP (sil3726) Gwendal Grignou
2011-10-08 18:25 ` Michael Ihrcke
2011-10-12 2:06 ` Michael Ihrcke
2011-10-13 2:09 ` Mike I
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).