Bug 42593

Summary: Lenovo Thinkpad T420 disk performance problems
Product: IO/Storage Reporter: Mikko Rapeli (mikko.rapeli)
Component: Serial ATAAssignee: Jeff Garzik (jgarzik)
Status: NEW ---    
Severity: normal CC: alan, szg00000, tj
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 3.0.16 Subsystem:
Regression: No Bisected commit-id:

Description Mikko Rapeli 2012-01-17 08:48:29 UTC
Submitting this to sata, 'cos I don't know better.

Debian squeeze userspace, kernel 3.0.x up till 3.0.16. Rootfs / is ext4 on an encrypted LVM with noatime to speed it up. Disk in use is:

# hdparm -i /dev/sda

/dev/sda:

 Model=ST320LT007-9ZV142, FwRev=0004LVM1, SerialNo=W0Q1FL5R
 Config={ HardSect NotMFM HdSw>15uSec Fixed DTR>10Mbs RotSpdTol>.5% }
 RawCHS=16383/16/63, TrkSize=0, SectSize=0, ECCbytes=4
 BuffType=unknown, BuffSize=16384kB, MaxMultSect=16, MultSect=16
 CurCHS=65535/1/63, CurSects=4128705, LBA=yes, LBAsects=625142448
 IORDY=on/off, tPIO={min:120,w/IORDY:120}, tDMA={min:120,rec:120}
 PIO modes:  pio0 pio1 pio2 pio3 pio4 
 DMA modes:  mdma0 mdma1 mdma2 
 UDMA modes: udma0 udma1 udma2 udma3 udma4 udma5 *udma6 
 AdvancedPM=yes: unknown setting WriteCache=enabled
 Drive conforms to: unknown:  ATA/ATAPI-3,4,5,6,7

 * signifies the current active mode

My Thinkpad T420 is suffering from terrible disk perfomance after a few days of uptime. I have no error messages in dmesg but everything grinds to a halt: Chromium browser takes tens of seconds to read fs cache, git fetch/pull takes tens of minutes, starting a new process or opening a file in vi may halt for a minute propably waiting for IO.

iotop does not show much disk IO going on when things grinds to a halt. dmesg does not show any problems. top shows that swap is not being used since there's 8 gigs of ram.

I tried to depict the issue with bonnie++. When the thing is dead slow after few days of uptime the results are:

$ /usr/sbin/bonnie++
Writing a byte at a time...done
Writing intelligently...done
Rewriting...done
Reading a byte at a time...done
Reading intelligently...done
start 'em...done...done...done...done...done...
Create files in sequential order...done.
Stat files in sequential order...done.
Delete files in sequential order...done.
Create files in random order...done.
Stat files in random order...done.
Delete files in random order...done.
Version  1.96       ------Sequential Output------ --Sequential Input- --Random-
Concurrency   1     -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- --Seeks--
Machine        Size K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP  /sec %CP
uldhcp1b029120  16G   851  85 40443   3 14298   1  3392  98 33558   1  20.6   0
Latency             12061us    7593ms   22273ms   13893us    5971ms   25971ms
Version  1.96       ------Sequential Create------ --------Random Create--------
uldhcp1b029120      -Create-- --Read--- -Delete-- -Create-- --Read--- -Delete--
              files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
                 16 24368  23 +++++ +++ +++++ +++ +++++ +++ +++++ +++ +++++ +++
Latency               122ms     550us     556us     329us      17us     575us

I don't know much about the numbers but the seek latency of 26 seconds does seem like the problem I have.

After a reboot bonnie shows more decent latency number (for the others I really can't tell) and I can actually think of git fetching stable tree and doing a kernel compile:

$ /usr/sbin/bonnie++
Writing a byte at a time...done
Writing intelligently...done
Rewriting...done
Reading a byte at a time...done
Reading intelligently...done
start 'em...done...done...done...done...done...
Create files in sequential order...done.
Stat files in sequential order...done.
Delete files in sequential order...done.
Create files in random order...done.
Stat files in random order...done.
Delete files in random order...done.
Version  1.96       ------Sequential Output------ --Sequential Input- --Random-
Concurrency   1     -Per Chr- --Block-- -Rewrite- -Per Chr- --Block-- --Seeks--
Machine        Size K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP  /sec %CP
uldhcp1b029120  16G   993  96 67022   5 30065   3  3380  95 101165   5 250.4   7
Latency             16786us     780ms     854ms   25240us   79041us     481ms
Version  1.96       ------Sequential Create------ --------Random Create--------
uldhcp1b029120      -Create-- --Read--- -Delete-- -Create-- --Read--- -Delete--
              files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
                 16 +++++ +++ +++++ +++ +++++ +++ +++++ +++ +++++ +++ +++++ +++
Latency             30067us     885us     693us     543us     106us     609us

The machine has these chips:

# lspci
00:00.0 Host bridge: Intel Corporation 2nd Generation Core Processor Family DRAM Controller (rev 09)
00:02.0 VGA compatible controller: Intel Corporation 2nd Generation Core Processor Family Integrated Graphics Controller (rev 09)
00:16.0 Communication controller: Intel Corporation 6 Series/C200 Series Chipset Family MEI Controller #1 (rev 04)
00:16.3 Serial controller: Intel Corporation 6 Series/C200 Series Chipset Family KT Controller (rev 04)
00:19.0 Ethernet controller: Intel Corporation 82579LM Gigabit Network Connection (rev 04)
00:1a.0 USB controller: Intel Corporation 6 Series/C200 Series Chipset Family USB Enhanced Host Controller #2 (rev 04)
00:1b.0 Audio device: Intel Corporation 6 Series/C200 Series Chipset Family High Definition Audio Controller (rev 04)
00:1c.0 PCI bridge: Intel Corporation 6 Series/C200 Series Chipset Family PCI Express Root Port 1 (rev b4)
00:1c.1 PCI bridge: Intel Corporation 6 Series/C200 Series Chipset Family PCI Express Root Port 2 (rev b4)
00:1c.3 PCI bridge: Intel Corporation 6 Series/C200 Series Chipset Family PCI Express Root Port 4 (rev b4)
00:1c.4 PCI bridge: Intel Corporation 6 Series/C200 Series Chipset Family PCI Express Root Port 5 (rev b4)
00:1d.0 USB controller: Intel Corporation 6 Series/C200 Series Chipset Family USB Enhanced Host Controller #1 (rev 04)
00:1f.0 ISA bridge: Intel Corporation QM67 Express Chipset Family LPC Controller (rev 04)
00:1f.2 SATA controller: Intel Corporation 6 Series/C200 Series Chipset Family 6 port SATA AHCI Controller (rev 04)
00:1f.3 SMBus: Intel Corporation 6 Series/C200 Series Chipset Family SMBus Controller (rev 04)
03:00.0 Network controller: Intel Corporation Centrino Advanced-N 6205 (rev 34)
0d:00.0 System peripheral: Ricoh Co Ltd Device e823 (rev 05)

I'd be happy to try different kernels with various debug options to nail down this problem. Any ideas?
Comment 1 Tejun Heo 2012-01-17 17:41:09 UTC
Can you please try "dd if=/dev/sda of=/dev/zero iflag=direct bs=1M count=100" when the system is in the slow state and post the output? Please also attach the output of dmesg. Thanks.
Comment 2 Mikko Rapeli 2012-01-17 17:49:00 UTC
(In reply to comment #1)
> Can you please try "dd if=/dev/sda of=/dev/zero iflag=direct bs=1M count=100"
> when the system is in the slow state and post the output? Please also attach
> the output of dmesg. Thanks.

Will try the dd thing once this hits again.

Here's dmesg on 3.0.17 after boot:


[    0.000000] Initializing cgroup subsys cpuset
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Linux version 3.0.17 (root@uldhcp1b029120) (gcc version 4.4.5 (Debian 4.4.5-8) ) #9 SMP Tue Jan 17 09:21:13 CET 2012
[    0.000000] Disabled fast string operations
[    0.000000] BIOS-provided physical RAM map:
[    0.000000]  BIOS-e820: 0000000000000000 - 000000000009d800 (usable)
[    0.000000]  BIOS-e820: 000000000009d800 - 00000000000a0000 (reserved)
[    0.000000]  BIOS-e820: 00000000000e0000 - 0000000000100000 (reserved)
[    0.000000]  BIOS-e820: 0000000000100000 - 0000000020000000 (usable)
[    0.000000]  BIOS-e820: 0000000020000000 - 0000000020200000 (reserved)
[    0.000000]  BIOS-e820: 0000000020200000 - 0000000040000000 (usable)
[    0.000000]  BIOS-e820: 0000000040000000 - 0000000040200000 (reserved)
[    0.000000]  BIOS-e820: 0000000040200000 - 00000000da99f000 (usable)
[    0.000000]  BIOS-e820: 00000000da99f000 - 00000000dae9f000 (reserved)
[    0.000000]  BIOS-e820: 00000000dae9f000 - 00000000daf9f000 (ACPI NVS)
[    0.000000]  BIOS-e820: 00000000daf9f000 - 00000000dafff000 (ACPI data)
[    0.000000]  BIOS-e820: 00000000dafff000 - 00000000db000000 (usable)
[    0.000000]  BIOS-e820: 00000000db000000 - 00000000dfa00000 (reserved)
[    0.000000]  BIOS-e820: 00000000f8000000 - 00000000fc000000 (reserved)
[    0.000000]  BIOS-e820: 00000000fec00000 - 00000000fec01000 (reserved)
[    0.000000]  BIOS-e820: 00000000fed08000 - 00000000fed09000 (reserved)
[    0.000000]  BIOS-e820: 00000000fed10000 - 00000000fed1a000 (reserved)
[    0.000000]  BIOS-e820: 00000000fed1c000 - 00000000fed20000 (reserved)
[    0.000000]  BIOS-e820: 00000000fee00000 - 00000000fee01000 (reserved)
[    0.000000]  BIOS-e820: 00000000ffd20000 - 0000000100000000 (reserved)
[    0.000000]  BIOS-e820: 0000000100000000 - 000000021e600000 (usable)
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] DMI 2.6 present.
[    0.000000] DMI: LENOVO 4236AC2/4236AC2, BIOS 83ET63WW (1.33 ) 07/29/2011
[    0.000000] e820 update range: 0000000000000000 - 0000000000010000 (usable) ==> (reserved)
[    0.000000] e820 remove range: 00000000000a0000 - 0000000000100000 (usable)
[    0.000000] last_pfn = 0x21e600 max_arch_pfn = 0x1000000
[    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-FFFFF write-protect
[    0.000000] MTRR variable ranges enabled:
[    0.000000]   0 base 0FFC00000 mask FFFC00000 write-protect
[    0.000000]   1 base 000000000 mask F80000000 write-back
[    0.000000]   2 base 080000000 mask FC0000000 write-back
[    0.000000]   3 base 0C0000000 mask FE0000000 write-back
[    0.000000]   4 base 0DC000000 mask FFC000000 uncachable
[    0.000000]   5 base 0DB000000 mask FFF000000 uncachable
[    0.000000]   6 base 100000000 mask F00000000 write-back
[    0.000000]   7 base 200000000 mask FE0000000 write-back
[    0.000000]   8 base 21F000000 mask FFF000000 uncachable
[    0.000000]   9 base 21E800000 mask FFF800000 uncachable
[    0.000000] x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106
[    0.000000] initial memory mapped : 0 - 02000000
[    0.000000] Base memory trampoline at [c0099000] 99000 size 16384
[    0.000000] init_memory_mapping: 0000000000000000-0000000037bfe000
[    0.000000]  0000000000 - 0000200000 page 4k
[    0.000000]  0000200000 - 0037a00000 page 2M
[    0.000000]  0037a00000 - 0037bfe000 page 4k
[    0.000000] kernel direct mapping tables up to 37bfe000 @ 1ffb000-2000000
[    0.000000] RAMDISK: 17521000 - 18040000
[    0.000000] ACPI: RSDP 000f00e0 00024 (v02 LENOVO)
[    0.000000] ACPI: XSDT daffe120 000AC (v01 LENOVO TP-83    00001330 PTEC 00000002)
[    0.000000] ACPI: FACP dafe8000 000F4 (v04 LENOVO TP-83    00001330 PTL  00000002)
[    0.000000] ACPI: DSDT dafeb000 0E3EA (v01 LENOVO TP-83    00001330 INTL 20061109)
[    0.000000] ACPI: FACS daf2d000 00040
[    0.000000] ACPI: SLIC daffd000 00176 (v01 LENOVO TP-83    00001330 PTEC 00000001)
[    0.000000] ACPI: SSDT daffc000 00249 (v01 LENOVO TP-SSDT2 00000200 INTL 20061109)
[    0.000000] ACPI: SSDT daffb000 00033 (v01 LENOVO TP-SSDT1 00000100 INTL 20061109)
[    0.000000] ACPI: SSDT daffa000 00797 (v01 LENOVO SataAhci 00001000 INTL 20061109)
[    0.000000] ACPI: HPET dafe7000 00038 (v01 LENOVO TP-83    00001330 PTL  00000002)
[    0.000000] ACPI: APIC dafe6000 00098 (v01 LENOVO TP-83    00001330 PTL  00000002)
[    0.000000] ACPI: MCFG dafe5000 0003C (v01 LENOVO TP-83    00001330 PTL  00000002)
[    0.000000] ACPI: ECDT dafe4000 00052 (v01 LENOVO TP-83    00001330 PTL  00000002)
[    0.000000] ACPI: ASF! dafea000 000A5 (v32 LENOVO TP-83    00001330 PTL  00000002)
[    0.000000] ACPI: TCPA dafe3000 00032 (v02    PTL   LENOVO 06040000 LNVO 00000001)
[    0.000000] ACPI: SSDT dafe2000 00A69 (v01  PmRef  Cpu0Ist 00003000 INTL 20061109)
[    0.000000] ACPI: SSDT dafe1000 00996 (v01  PmRef    CpuPm 00003000 INTL 20061109)
[    0.000000] ACPI: DMAR dafe0000 000E8 (v01 INTEL      SNB  00000001 INTL 00000001)
[    0.000000] ACPI: UEFI dafdf000 0003E (v01 LENOVO TP-83    00001330 PTL  00000002)
[    0.000000] ACPI: UEFI dafde000 00042 (v01 PTL      COMBUF 00000001 PTL  00000001)
[    0.000000] ACPI: UEFI dafdd000 00292 (v01 LENOVO TP-83    00001330 PTL  00000002)
[    0.000000] ACPI: Local APIC address 0xfee00000
[    0.000000] 7786MB HIGHMEM available.
[    0.000000] 891MB LOWMEM available.
[    0.000000]   mapped low ram: 0 - 37bfe000
[    0.000000]   low ram: 0 - 37bfe000
[    0.000000] Zone PFN ranges:
[    0.000000]   DMA      0x00000010 -> 0x00001000
[    0.000000]   Normal   0x00001000 -> 0x00037bfe
[    0.000000]   HighMem  0x00037bfe -> 0x0021e600
[    0.000000] Movable zone start PFN for each node
[    0.000000] early_node_map[6] active PFN ranges
[    0.000000]     0: 0x00000010 -> 0x0000009d
[    0.000000]     0: 0x00000100 -> 0x00020000
[    0.000000]     0: 0x00020200 -> 0x00040000
[    0.000000]     0: 0x00040200 -> 0x000da99f
[    0.000000]     0: 0x000dafff -> 0x000db000
[    0.000000]     0: 0x00100000 -> 0x0021e600
[    0.000000] On node 0 totalpages: 2067245
[    0.000000]   DMA zone: 32 pages used for memmap
[    0.000000]   DMA zone: 0 pages reserved
[    0.000000]   DMA zone: 3949 pages, LIFO batch:0
[    0.000000]   Normal zone: 1752 pages used for memmap
[    0.000000]   Normal zone: 221990 pages, LIFO batch:31
[    0.000000]   HighMem zone: 15573 pages used for memmap
[    0.000000]   HighMem zone: 1823949 pages, LIFO batch:31
[    0.000000] Using APIC driver default
[    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 (acpi_id[0x05] lapic_id[0x00] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x06] lapic_id[0x00] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x07] lapic_id[0x00] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x08] lapic_id[0x00] disabled)
[    0.000000] ACPI: LAPIC_NMI (acpi_id[0x00] high edge lint[0x1])
[    0.000000] ACPI: LAPIC_NMI (acpi_id[0x01] high edge lint[0x1])
[    0.000000] ACPI: IOAPIC (id[0x02] address[0xfec00000] gsi_base[0])
[    0.000000] IOAPIC[0]: apic_id 2, 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: 0x8086a301 base: 0xfed00000
[    0.000000] SMP: Allowing 8 CPUs, 4 hotplug CPUs
[    0.000000] nr_irqs_gsi: 40
[    0.000000] PM: Registered nosave memory: 000000000009d000 - 000000000009e000
[    0.000000] PM: Registered nosave memory: 000000000009e000 - 00000000000a0000
[    0.000000] PM: Registered nosave memory: 00000000000a0000 - 00000000000e0000
[    0.000000] PM: Registered nosave memory: 00000000000e0000 - 0000000000100000
[    0.000000] PM: Registered nosave memory: 0000000020000000 - 0000000020200000
[    0.000000] Allocating PCI resources starting at dfa00000 (gap: dfa00000:18600000)
[    0.000000] Booting paravirtualized kernel on bare hardware
[    0.000000] setup_percpu: NR_CPUS:8 nr_cpumask_bits:8 nr_cpu_ids:8 nr_node_ids:1
[    0.000000] PERCPU: Embedded 12 pages/cpu @f3800000 s26560 r0 d22592 u262144
[    0.000000] pcpu-alloc: s26560 r0 d22592 u262144 alloc=1*2097152
[    0.000000] pcpu-alloc: [0] 0 1 2 3 4 5 6 7 
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 2049888
[    0.000000] Kernel command line: BOOT_IMAGE=/vmlinuz-3.0.17 root=/dev/mapper/uldhcp1b029120-root ro quiet
[    0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Initializing CPU#0
[    0.000000] xsave/xrstor: enabled xstate_bv 0x7, cntxt size 0x340
[    0.000000] Initializing HighMem for node 0 (00037bfe:0021e600)
[    0.000000] Memory: 8179980k/8886272k available (3704k kernel code, 89000k reserved, 1617k data, 484k init, 7358088k highmem)
[    0.000000] virtual kernel memory layout:
[    0.000000]     fixmap  : 0xfff16000 - 0xfffff000   ( 932 kB)
[    0.000000]     pkmap   : 0xffc00000 - 0xffe00000   (2048 kB)
[    0.000000]     vmalloc : 0xf83fe000 - 0xffbfe000   ( 120 MB)
[    0.000000]     lowmem  : 0xc0000000 - 0xf7bfe000   ( 891 MB)
[    0.000000]       .init : 0xc1533000 - 0xc15ac000   ( 484 kB)
[    0.000000]       .data : 0xc139e2f1 - 0xc1532780   (1617 kB)
[    0.000000]       .text : 0xc1000000 - 0xc139e2f1   (3704 kB)
[    0.000000] Checking if this processor honours the WP bit even in supervisor mode...Ok.
[    0.000000] SLUB: Genslabs=15, HWalign=64, Order=0-3, MinObjects=0, CPUs=8, Nodes=1
[    0.000000] Hierarchical RCU implementation.
[    0.000000] NR_IRQS:2304 nr_irqs:744 16
[    0.000000] CPU 0 irqstacks, hard=f340c000 soft=f340e000
[    0.000000] Extended CMOS year: 2000
[    0.000000] Console: colour VGA+ 80x25
[    0.000000] console [tty0] enabled
[    0.000000] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
[    0.000000] ... MAX_LOCKDEP_SUBCLASSES:  8
[    0.000000] ... MAX_LOCK_DEPTH:          48
[    0.000000] ... MAX_LOCKDEP_KEYS:        8191
[    0.000000] ... CLASSHASH_SIZE:          4096
[    0.000000] ... MAX_LOCKDEP_ENTRIES:     16384
[    0.000000] ... MAX_LOCKDEP_CHAINS:      32768
[    0.000000] ... CHAINHASH_SIZE:          16384
[    0.000000]  memory used by lock dependency info: 3551 kB
[    0.000000]  per task-struct memory footprint: 1152 bytes
[    0.000000] hpet clockevent registered
[    0.000000] Fast TSC calibration using PIT
[    0.004000] Detected 2591.804 MHz processor.
[    0.000002] Calibrating delay loop (skipped), value calculated using timer frequency.. 5183.60 BogoMIPS (lpj=10367216)
[    0.000005] pid_max: default: 32768 minimum: 301
[    0.000032] Security Framework initialized
[    0.000035] SELinux:  Disabled at boot.
[    0.000053] Mount-cache hash table entries: 512
[    0.000305] Initializing cgroup subsys cpuacct
[    0.000312] Initializing cgroup subsys devices
[    0.000314] Initializing cgroup subsys freezer
[    0.000315] Initializing cgroup subsys net_cls
[    0.000346] Disabled fast string operations
[    0.000348] CPU: Physical Processor ID: 0
[    0.000350] CPU: Processor Core ID: 0
[    0.000354] ENERGY_PERF_BIAS: Set to 'normal', was 'performance'
[    0.000354] ENERGY_PERF_BIAS: View and update with x86_energy_perf_policy(8)
[    0.000357] mce: CPU supports 7 MCE banks
[    0.000368] CPU0: Thermal monitoring enabled (TM1)
[    0.000377] using mwait in idle threads.
[    0.001192] ACPI: Core revision 20110413
[    0.012720] ftrace: allocating 15881 entries in 32 pages
[    0.018281] Enabling APIC mode:  Flat.  Using 1 I/O APICs
[    0.018648] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[    0.058323] CPU0: Intel(R) Core(TM) i5-2540M CPU @ 2.60GHz stepping 07
[    0.164113] Performance Events: PEBS fmt1+, SandyBridge events, Intel PMU driver.
[    0.164119] ... version:                3
[    0.164120] ... bit width:              48
[    0.164121] ... generic registers:      4
[    0.164123] ... value mask:             0000ffffffffffff
[    0.164124] ... max period:             000000007fffffff
[    0.164125] ... fixed-purpose events:   3
[    0.164127] ... event mask:             000000070000000f
[    0.164380] lockdep: fixing up alternatives.
[    0.164422] CPU 1 irqstacks, hard=f34bc000 soft=f34be000
[    0.164425] Booting Node   0, Processors  #1
[    0.164427] smpboot cpu 1: start_ip = 99000
[    0.174687] Initializing CPU#1
[    0.252090] Disabled fast string operations
[    0.272278] lockdep: fixing up alternatives.
[    0.272298] CPU 2 irqstacks, hard=f34f0000 soft=f34f2000
[    0.272299]  #2
[    0.272301] smpboot cpu 2: start_ip = 99000
[    0.282532] Initializing CPU#2
[    0.360050] Disabled fast string operations
[    0.380176] lockdep: fixing up alternatives.
[    0.380196] CPU 3 irqstacks, hard=f34fc000 soft=f34fe000
[    0.380197]  #3
[    0.380199] smpboot cpu 3: start_ip = 99000
[    0.390429] Initializing CPU#3
[    0.468011] Disabled fast string operations
[    0.488099] Brought up 4 CPUs
[    0.488101] Total of 4 processors activated (20732.58 BogoMIPS).
[    0.490581] devtmpfs: initialized
[    0.490921] PM: Registering ACPI NVS region at dae9f000 (1048576 bytes)
[    0.491144] print_constraints: dummy: 
[    0.491174] Time:  8:51:47  Date: 01/17/12
[    0.491238] NET: Registered protocol family 16
[    0.491357] ACPI FADT declares the system doesn't support PCIe ASPM, so disable it
[    0.491362] ACPI: bus type pci registered
[    0.491612] PCI: MMCONFIG for domain 0000 [bus 00-3f] at [mem 0xf8000000-0xfbffffff] (base 0xf8000000)
[    0.491615] PCI: MMCONFIG at [mem 0xf8000000-0xfbffffff] reserved in E820
[    0.491617] PCI: Using MMCONFIG for extended config space
[    0.491618] PCI: Using configuration type 1 for base access
[    0.492197] bio: create slab <bio-0> at 0
[    0.496349] ACPI: EC: EC description table is found, configuring boot EC
[    0.505207] [Firmware Bug]: ACPI: BIOS _OSI(Linux) query ignored
[    0.540565] ACPI: SSDT dae8c018 008C0 (v01  PmRef  Cpu0Cst 00003001 INTL 20061109)
[    0.541600] ACPI: Dynamic OEM Table Load:
[    0.541603] ACPI: SSDT   (null) 008C0 (v01  PmRef  Cpu0Cst 00003001 INTL 20061109)
[    0.552316] ACPI: SSDT dae8da98 00303 (v01  PmRef    ApIst 00003000 INTL 20061109)
[    0.553393] ACPI: Dynamic OEM Table Load:
[    0.553396] ACPI: SSDT   (null) 00303 (v01  PmRef    ApIst 00003000 INTL 20061109)
[    0.564155] ACPI: SSDT dae8bd98 00119 (v01  PmRef    ApCst 00003000 INTL 20061109)
[    0.565189] ACPI: Dynamic OEM Table Load:
[    0.565191] ACPI: SSDT   (null) 00119 (v01  PmRef    ApCst 00003000 INTL 20061109)
[    0.576746] ACPI: Interpreter enabled
[    0.576749] ACPI: (supports S0 S3 S4 S5)
[    0.576777] ACPI: Using IOAPIC for interrupt routing
[    0.592577] ACPI: Power Resource [PUBS] (on)
[    0.597250] ACPI: EC: GPE = 0x11, I/O: command/status = 0x66, data = 0x62
[    0.598411] ACPI: ACPI Dock Station Driver: 2 docks/bays found
[    0.598413] HEST: Table not found.
[    0.598416] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    0.598544] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-fe])
[    0.598614] pci_root PNP0A08:00: host bridge window [io  0x0000-0x0cf7]
[    0.598616] pci_root PNP0A08:00: host bridge window [io  0x0d00-0xffff]
[    0.598618] pci_root PNP0A08:00: host bridge window [mem 0x000a0000-0x000bffff]
[    0.598621] pci_root PNP0A08:00: host bridge window [mem 0xdfa00000-0xfebfffff]
[    0.598623] pci_root PNP0A08:00: host bridge window [mem 0xfed40000-0xfed4bfff]
[    0.598640] pci 0000:00:00.0: [8086:0104] type 0 class 0x000600
[    0.598691] pci 0000:00:02.0: [8086:0126] type 0 class 0x000300
[    0.598705] pci 0000:00:02.0: reg 10: [mem 0xf0000000-0xf03fffff 64bit]
[    0.598713] pci 0000:00:02.0: reg 18: [mem 0xe0000000-0xefffffff 64bit pref]
[    0.598719] pci 0000:00:02.0: reg 20: [io  0x5000-0x503f]
[    0.598800] pci 0000:00:16.0: [8086:1c3a] type 0 class 0x000780
[    0.598837] pci 0000:00:16.0: reg 10: [mem 0xf2525000-0xf252500f 64bit]
[    0.598939] pci 0000:00:16.0: PME# supported from D0 D3hot D3cold
[    0.598944] pci 0000:00:16.0: PME# disabled
[    0.598980] pci 0000:00:16.3: [8086:1c3d] type 0 class 0x000700
[    0.599010] pci 0000:00:16.3: reg 10: [io  0x50b0-0x50b7]
[    0.599025] pci 0000:00:16.3: reg 14: [mem 0xf252c000-0xf252cfff]
[    0.599164] pci 0000:00:19.0: [8086:1502] type 0 class 0x000200
[    0.599197] pci 0000:00:19.0: reg 10: [mem 0xf2500000-0xf251ffff]
[    0.599210] pci 0000:00:19.0: reg 14: [mem 0xf252b000-0xf252bfff]
[    0.599225] pci 0000:00:19.0: reg 18: [io  0x5080-0x509f]
[    0.599321] pci 0000:00:19.0: PME# supported from D0 D3hot D3cold
[    0.599326] pci 0000:00:19.0: PME# disabled
[    0.599364] pci 0000:00:1a.0: [8086:1c2d] type 0 class 0x000c03
[    0.599396] pci 0000:00:1a.0: reg 10: [mem 0xf252a000-0xf252a3ff]
[    0.599517] pci 0000:00:1a.0: PME# supported from D0 D3hot D3cold
[    0.599522] pci 0000:00:1a.0: PME# disabled
[    0.599561] pci 0000:00:1b.0: [8086:1c20] type 0 class 0x000403
[    0.599588] pci 0000:00:1b.0: reg 10: [mem 0xf2520000-0xf2523fff 64bit]
[    0.599694] pci 0000:00:1b.0: PME# supported from D0 D3hot D3cold
[    0.599699] pci 0000:00:1b.0: PME# disabled
[    0.599734] pci 0000:00:1c.0: [8086:1c10] type 1 class 0x000604
[    0.599845] pci 0000:00:1c.0: PME# supported from D0 D3hot D3cold
[    0.599850] pci 0000:00:1c.0: PME# disabled
[    0.599888] pci 0000:00:1c.1: [8086:1c12] type 1 class 0x000604
[    0.600003] pci 0000:00:1c.1: PME# supported from D0 D3hot D3cold
[    0.600008] pci 0000:00:1c.1: PME# disabled
[    0.600046] pci 0000:00:1c.3: [8086:1c16] type 1 class 0x000604
[    0.600156] pci 0000:00:1c.3: PME# supported from D0 D3hot D3cold
[    0.600162] pci 0000:00:1c.3: PME# disabled
[    0.600200] pci 0000:00:1c.4: [8086:1c18] type 1 class 0x000604
[    0.600312] pci 0000:00:1c.4: PME# supported from D0 D3hot D3cold
[    0.600317] pci 0000:00:1c.4: PME# disabled
[    0.600368] pci 0000:00:1d.0: [8086:1c26] type 0 class 0x000c03
[    0.600401] pci 0000:00:1d.0: reg 10: [mem 0xf2529000-0xf25293ff]
[    0.600522] pci 0000:00:1d.0: PME# supported from D0 D3hot D3cold
[    0.600527] pci 0000:00:1d.0: PME# disabled
[    0.600562] pci 0000:00:1f.0: [8086:1c4f] type 0 class 0x000601
[    0.600740] pci 0000:00:1f.2: [8086:1c03] type 0 class 0x000106
[    0.600776] pci 0000:00:1f.2: reg 10: [io  0x50a8-0x50af]
[    0.600790] pci 0000:00:1f.2: reg 14: [io  0x50bc-0x50bf]
[    0.600804] pci 0000:00:1f.2: reg 18: [io  0x50a0-0x50a7]
[    0.600819] pci 0000:00:1f.2: reg 1c: [io  0x50b8-0x50bb]
[    0.600833] pci 0000:00:1f.2: reg 20: [io  0x5060-0x507f]
[    0.600848] pci 0000:00:1f.2: reg 24: [mem 0xf2528000-0xf25287ff]
[    0.600915] pci 0000:00:1f.2: PME# supported from D3hot
[    0.600921] pci 0000:00:1f.2: PME# disabled
[    0.600950] pci 0000:00:1f.3: [8086:1c22] type 0 class 0x000c05
[    0.600978] pci 0000:00:1f.3: reg 10: [mem 0xf2524000-0xf25240ff 64bit]
[    0.601018] pci 0000:00:1f.3: reg 20: [io  0xefa0-0xefbf]
[    0.601142] pci 0000:00:1c.0: PCI bridge to [bus 02-02]
[    0.601148] pci 0000:00:1c.0:   bridge window [io  0xf000-0x0000] (disabled)
[    0.601154] pci 0000:00:1c.0:   bridge window [mem 0xfff00000-0x000fffff] (disabled)
[    0.601163] pci 0000:00:1c.0:   bridge window [mem 0xfff00000-0x000fffff pref] (disabled)
[    0.601521] pci 0000:03:00.0: [8086:0085] type 0 class 0x000280
[    0.601782] pci 0000:03:00.0: reg 10: [mem 0xf2400000-0xf2401fff 64bit]
[    0.602819] pci 0000:03:00.0: PME# supported from D0 D3hot D3cold
[    0.602855] pci 0000:03:00.0: PME# disabled
[    0.603202] pci 0000:00:1c.1: PCI bridge to [bus 03-03]
[    0.603207] pci 0000:00:1c.1:   bridge window [io  0xf000-0x0000] (disabled)
[    0.603212] pci 0000:00:1c.1:   bridge window [mem 0xf2400000-0xf24fffff]
[    0.603222] pci 0000:00:1c.1:   bridge window [mem 0xfff00000-0x000fffff pref] (disabled)
[    0.603299] pci 0000:00:1c.3: PCI bridge to [bus 05-0c]
[    0.603304] pci 0000:00:1c.3:   bridge window [io  0x4000-0x4fff]
[    0.603310] pci 0000:00:1c.3:   bridge window [mem 0xf1c00000-0xf23fffff]
[    0.603319] pci 0000:00:1c.3:   bridge window [mem 0xf0400000-0xf0bfffff 64bit pref]
[    0.603467] pci 0000:0d:00.0: [1180:e823] type 0 class 0x000880
[    0.603497] pci 0000:0d:00.0: reg 10: [mem 0xf1400000-0xf14000ff]
[    0.603672] pci 0000:0d:00.0: supports D1 D2
[    0.603674] pci 0000:0d:00.0: PME# supported from D0 D1 D2 D3hot D3cold
[    0.603681] pci 0000:0d:00.0: PME# disabled
[    0.603753] pci 0000:00:1c.4: PCI bridge to [bus 0d-0d]
[    0.603758] pci 0000:00:1c.4:   bridge window [io  0x3000-0x3fff]
[    0.603763] pci 0000:00:1c.4:   bridge window [mem 0xf1400000-0xf1bfffff]
[    0.603773] pci 0000:00:1c.4:   bridge window [mem 0xf0c00000-0xf13fffff 64bit pref]
[    0.603807] pci_bus 0000:00: on NUMA node 0
[    0.603809] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
[    0.603943] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.EXP1._PRT]
[    0.603981] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.EXP2._PRT]
[    0.604014] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.EXP4._PRT]
[    0.604052] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.EXP5._PRT]
[    0.604217]  pci0000:00: Requesting ACPI _OSC control (0x1d)
[    0.604398]  pci0000:00: ACPI _OSC request failed (AE_SUPPORT), returned control mask: 0x0d
[    0.604400] ACPI _OSC control for PCIe not granted, disabling ASPM
[    0.607644] ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 5 6 7 9 10 *11)
[    0.607713] ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 5 6 7 9 10 *11)
[    0.607779] ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 5 6 7 9 10 *11)
[    0.607844] ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 5 6 7 9 *10 11)
[    0.607908] ACPI: PCI Interrupt Link [LNKE] (IRQs 3 4 5 6 7 9 *10 11)
[    0.607967] ACPI: PCI Interrupt Link [LNKF] (IRQs 3 4 5 6 7 9 10 11) *0, disabled.
[    0.608034] ACPI: PCI Interrupt Link [LNKG] (IRQs 3 4 5 6 *7 9 10 11)
[    0.608101] ACPI: PCI Interrupt Link [LNKH] (IRQs 3 4 5 6 *7 9 10 11)
[    0.608221] vgaarb: device added: PCI:0000:00:02.0,decodes=io+mem,owns=io+mem,locks=none
[    0.608235] vgaarb: loaded
[    0.608236] vgaarb: bridge control possible 0000:00:02.0
[    0.608283] PCI: Using ACPI for IRQ routing
[    0.610063] PCI: pci_cache_line_size set to 64 bytes
[    0.610167] reserve RAM buffer: 000000000009d800 - 000000000009ffff 
[    0.610169] reserve RAM buffer: 00000000da99f000 - 00000000dbffffff 
[    0.610172] reserve RAM buffer: 00000000db000000 - 00000000dbffffff 
[    0.610174] reserve RAM buffer: 000000021e600000 - 000000021fffffff 
[    0.610311] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0, 0, 0, 0, 0, 0
[    0.610317] hpet0: 8 comparators, 64-bit 14.318180 MHz counter
[    0.612342] Switching to clocksource hpet
[    0.614882] pnp: PnP ACPI init
[    0.614901] ACPI: bus type pnp registered
[    0.615291] pnp 00:00: [mem 0x00000000-0x0009ffff]
[    0.615293] pnp 00:00: [mem 0x000c0000-0x000c3fff]
[    0.615295] pnp 00:00: [mem 0x000c4000-0x000c7fff]
[    0.615297] pnp 00:00: [mem 0x000c8000-0x000cbfff]
[    0.615299] pnp 00:00: [mem 0x000cc000-0x000cffff]
[    0.615300] pnp 00:00: [mem 0x000d0000-0x000d3fff]
[    0.615302] pnp 00:00: [mem 0x000d4000-0x000d7fff]
[    0.615304] pnp 00:00: [mem 0x000d8000-0x000dbfff]
[    0.615305] pnp 00:00: [mem 0x000dc000-0x000dffff]
[    0.615307] pnp 00:00: [mem 0x000e0000-0x000e3fff]
[    0.615309] pnp 00:00: [mem 0x000e4000-0x000e7fff]
[    0.615310] pnp 00:00: [mem 0x000e8000-0x000ebfff]
[    0.615312] pnp 00:00: [mem 0x000ec000-0x000effff]
[    0.615313] pnp 00:00: [mem 0x000f0000-0x000fffff]
[    0.615315] pnp 00:00: [mem 0x00100000-0xdf9fffff]
[    0.615317] pnp 00:00: [mem 0xfec00000-0xfed3ffff]
[    0.615319] pnp 00:00: [mem 0xfed4c000-0xffffffff]
[    0.615383] system 00:00: [mem 0x00000000-0x0009ffff] could not be reserved
[    0.615386] system 00:00: [mem 0x000c0000-0x000c3fff] could not be reserved
[    0.615388] system 00:00: [mem 0x000c4000-0x000c7fff] could not be reserved
[    0.615390] system 00:00: [mem 0x000c8000-0x000cbfff] has been reserved
[    0.615393] system 00:00: [mem 0x000cc000-0x000cffff] has been reserved
[    0.615395] system 00:00: [mem 0x000d0000-0x000d3fff] has been reserved
[    0.615397] system 00:00: [mem 0x000d4000-0x000d7fff] has been reserved
[    0.615399] system 00:00: [mem 0x000d8000-0x000dbfff] has been reserved
[    0.615401] system 00:00: [mem 0x000dc000-0x000dffff] has been reserved
[    0.615403] system 00:00: [mem 0x000e0000-0x000e3fff] could not be reserved
[    0.615406] system 00:00: [mem 0x000e4000-0x000e7fff] could not be reserved
[    0.615408] system 00:00: [mem 0x000e8000-0x000ebfff] could not be reserved
[    0.615410] system 00:00: [mem 0x000ec000-0x000effff] could not be reserved
[    0.615413] system 00:00: [mem 0x000f0000-0x000fffff] could not be reserved
[    0.615415] system 00:00: [mem 0x00100000-0xdf9fffff] could not be reserved
[    0.615418] system 00:00: [mem 0xfec00000-0xfed3ffff] could not be reserved
[    0.615420] system 00:00: [mem 0xfed4c000-0xffffffff] could not be reserved
[    0.615424] system 00:00: Plug and Play ACPI device, IDs PNP0c01 (active)
[    0.615445] pnp 00:01: [bus 00-fe]
[    0.615447] pnp 00:01: [io  0x0cf8-0x0cff]
[    0.615449] pnp 00:01: [io  0x0000-0x0cf7 window]
[    0.615451] pnp 00:01: [io  0x0d00-0xffff window]
[    0.615452] pnp 00:01: [mem 0x000a0000-0x000bffff window]
[    0.615454] pnp 00:01: [mem 0x000c0000-0x000c3fff window]
[    0.615456] pnp 00:01: [mem 0x000c4000-0x000c7fff window]
[    0.615458] pnp 00:01: [mem 0x000c8000-0x000cbfff window]
[    0.615460] pnp 00:01: [mem 0x000cc000-0x000cffff window]
[    0.615462] pnp 00:01: [mem 0x000d0000-0x000d3fff window]
[    0.615463] pnp 00:01: [mem 0x000d4000-0x000d7fff window]
[    0.615465] pnp 00:01: [mem 0x000d8000-0x000dbfff window]
[    0.615467] pnp 00:01: [mem 0x000dc000-0x000dffff window]
[    0.615469] pnp 00:01: [mem 0x000e0000-0x000e3fff window]
[    0.615471] pnp 00:01: [mem 0x000e4000-0x000e7fff window]
[    0.615472] pnp 00:01: [mem 0x000e8000-0x000ebfff window]
[    0.615474] pnp 00:01: [mem 0x000ec000-0x000effff window]
[    0.615477] pnp 00:01: [mem 0xdfa00000-0xfebfffff window]
[    0.615479] pnp 00:01: [mem 0xfed40000-0xfed4bfff window]
[    0.615551] pnp 00:01: Plug and Play ACPI device, IDs PNP0a08 PNP0a03 (active)
[    0.615619] pnp 00:02: [io  0x0010-0x001f]
[    0.615620] pnp 00:02: [io  0x0090-0x009f]
[    0.615622] pnp 00:02: [io  0x0024-0x0025]
[    0.615624] pnp 00:02: [io  0x0028-0x0029]
[    0.615625] pnp 00:02: [io  0x002c-0x002d]
[    0.615627] pnp 00:02: [io  0x0030-0x0031]
[    0.615628] pnp 00:02: [io  0x0034-0x0035]
[    0.615630] pnp 00:02: [io  0x0038-0x0039]
[    0.615631] pnp 00:02: [io  0x003c-0x003d]
[    0.615633] pnp 00:02: [io  0x00a4-0x00a5]
[    0.615634] pnp 00:02: [io  0x00a8-0x00a9]
[    0.615636] pnp 00:02: [io  0x00ac-0x00ad]
[    0.615638] pnp 00:02: [io  0x00b0-0x00b5]
[    0.615639] pnp 00:02: [io  0x00b8-0x00b9]
[    0.615641] pnp 00:02: [io  0x00bc-0x00bd]
[    0.615642] pnp 00:02: [io  0x0050-0x0053]
[    0.615644] pnp 00:02: [io  0x0072-0x0077]
[    0.615645] pnp 00:02: [io  0x0400-0x047f]
[    0.615647] pnp 00:02: [io  0x0500-0x057f]
[    0.615648] pnp 00:02: [io  0x0800-0x080f]
[    0.615650] pnp 00:02: [io  0x15e0-0x15ef]
[    0.615652] pnp 00:02: [io  0x1600-0x167f]
[    0.615653] pnp 00:02: [mem 0xf8000000-0xfbffffff]
[    0.615655] pnp 00:02: [mem 0x00000000-0x00000fff]
[    0.615657] pnp 00:02: [mem 0xfed1c000-0xfed1ffff]
[    0.615659] pnp 00:02: [mem 0xfed10000-0xfed13fff]
[    0.615660] pnp 00:02: [mem 0xfed18000-0xfed18fff]
[    0.615662] pnp 00:02: [mem 0xfed19000-0xfed19fff]
[    0.615664] pnp 00:02: [mem 0xfed45000-0xfed4bfff]
[    0.615739] system 00:02: [io  0x0400-0x047f] has been reserved
[    0.615741] system 00:02: [io  0x0500-0x057f] has been reserved
[    0.615743] system 00:02: [io  0x0800-0x080f] has been reserved
[    0.615745] system 00:02: [io  0x15e0-0x15ef] has been reserved
[    0.615748] system 00:02: [io  0x1600-0x167f] has been reserved
[    0.615750] system 00:02: [mem 0xf8000000-0xfbffffff] has been reserved
[    0.615752] system 00:02: [mem 0x00000000-0x00000fff] could not be reserved
[    0.615755] system 00:02: [mem 0xfed1c000-0xfed1ffff] has been reserved
[    0.615757] system 00:02: [mem 0xfed10000-0xfed13fff] has been reserved
[    0.615759] system 00:02: [mem 0xfed18000-0xfed18fff] has been reserved
[    0.615762] system 00:02: [mem 0xfed19000-0xfed19fff] has been reserved
[    0.615764] system 00:02: [mem 0xfed45000-0xfed4bfff] has been reserved
[    0.615767] system 00:02: Plug and Play ACPI device, IDs PNP0c02 (active)
[    0.615812] pnp 00:03: [mem 0xfed00000-0xfed003ff]
[    0.615853] pnp 00:03: Plug and Play ACPI device, IDs PNP0103 (active)
[    0.615863] pnp 00:04: [io  0x0000-0x000f]
[    0.615865] pnp 00:04: [io  0x0080-0x008f]
[    0.615866] pnp 00:04: [io  0x00c0-0x00df]
[    0.615868] pnp 00:04: [dma 4]
[    0.615909] pnp 00:04: Plug and Play ACPI device, IDs PNP0200 (active)
[    0.615918] pnp 00:05: [io  0x0061]
[    0.615972] Switched to NOHz mode on CPU #0
[    0.615994] pnp 00:05: Plug and Play ACPI device, IDs PNP0800 (active)
[    0.616004] pnp 00:06: [io  0x00f0]
[    0.616012] pnp 00:06: [irq 13]
[    0.616028] Switched to NOHz mode on CPU #2
[    0.616054] pnp 00:06: Plug and Play ACPI device, IDs PNP0c04 (active)
[    0.616062] Switched to NOHz mode on CPU #3
[    0.616064] pnp 00:07: [io  0x0070-0x0071]
[    0.616070] pnp 00:07: [irq 8]
[    0.616077] Switched to NOHz mode on CPU #1
[    0.616118] pnp 00:07: Plug and Play ACPI device, IDs PNP0b00 (active)
[    0.616127] pnp 00:08: [io  0x0060]
[    0.616129] pnp 00:08: [io  0x0064]
[    0.616134] pnp 00:08: [irq 1]
[    0.616178] pnp 00:08: Plug and Play ACPI device, IDs PNP0303 (active)
[    0.616190] pnp 00:09: [irq 12]
[    0.616236] pnp 00:09: Plug and Play ACPI device, IDs LEN0015 PNP0f13 (active)
[    0.616271] pnp 00:0a: [mem 0xfed40000-0xfed44fff]
[    0.616317] pnp 00:0a: Plug and Play ACPI device, IDs SMO1200 PNP0c31 (active)
[    0.616847] pnp: PnP ACPI: found 11 devices
[    0.616849] ACPI: ACPI bus type pnp unregistered
[    0.653265] PCI: max bus depth: 1 pci_try_num: 2
[    0.653317] pci 0000:00:1c.0: PCI bridge to [bus 02-02]
[    0.653318] pci 0000:00:1c.0:   bridge window [io  disabled]
[    0.653326] pci 0000:00:1c.0:   bridge window [mem disabled]
[    0.653331] pci 0000:00:1c.0:   bridge window [mem pref disabled]
[    0.653340] pci 0000:00:1c.1: PCI bridge to [bus 03-03]
[    0.653342] pci 0000:00:1c.1:   bridge window [io  disabled]
[    0.653349] pci 0000:00:1c.1:   bridge window [mem 0xf2400000-0xf24fffff]
[    0.653355] pci 0000:00:1c.1:   bridge window [mem pref disabled]
[    0.653364] pci 0000:00:1c.3: PCI bridge to [bus 05-0c]
[    0.653367] pci 0000:00:1c.3:   bridge window [io  0x4000-0x4fff]
[    0.653375] pci 0000:00:1c.3:   bridge window [mem 0xf1c00000-0xf23fffff]
[    0.653380] pci 0000:00:1c.3:   bridge window [mem 0xf0400000-0xf0bfffff 64bit pref]
[    0.653390] pci 0000:00:1c.4: PCI bridge to [bus 0d-0d]
[    0.653393] pci 0000:00:1c.4:   bridge window [io  0x3000-0x3fff]
[    0.653400] pci 0000:00:1c.4:   bridge window [mem 0xf1400000-0xf1bfffff]
[    0.653406] pci 0000:00:1c.4:   bridge window [mem 0xf0c00000-0xf13fffff 64bit pref]
[    0.653428] pci 0000:00:1c.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[    0.653435] pci 0000:00:1c.0: setting latency timer to 64
[    0.653448] pci 0000:00:1c.1: PCI INT B -> GSI 17 (level, low) -> IRQ 17
[    0.653453] pci 0000:00:1c.1: setting latency timer to 64
[    0.653466] pci 0000:00:1c.3: PCI INT D -> GSI 19 (level, low) -> IRQ 19
[    0.653471] pci 0000:00:1c.3: setting latency timer to 64
[    0.653480] pci 0000:00:1c.4: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[    0.653485] pci 0000:00:1c.4: setting latency timer to 64
[    0.653489] pci_bus 0000:00: resource 4 [io  0x0000-0x0cf7]
[    0.653491] pci_bus 0000:00: resource 5 [io  0x0d00-0xffff]
[    0.653493] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff]
[    0.653495] pci_bus 0000:00: resource 7 [mem 0xdfa00000-0xfebfffff]
[    0.653497] pci_bus 0000:00: resource 8 [mem 0xfed40000-0xfed4bfff]
[    0.653499] pci_bus 0000:03: resource 1 [mem 0xf2400000-0xf24fffff]
[    0.653501] pci_bus 0000:05: resource 0 [io  0x4000-0x4fff]
[    0.653503] pci_bus 0000:05: resource 1 [mem 0xf1c00000-0xf23fffff]
[    0.653505] pci_bus 0000:05: resource 2 [mem 0xf0400000-0xf0bfffff 64bit pref]
[    0.653507] pci_bus 0000:0d: resource 0 [io  0x3000-0x3fff]
[    0.653508] pci_bus 0000:0d: resource 1 [mem 0xf1400000-0xf1bfffff]
[    0.653510] pci_bus 0000:0d: resource 2 [mem 0xf0c00000-0xf13fffff 64bit pref]
[    0.653543] NET: Registered protocol family 2
[    0.653633] IP route cache hash table entries: 32768 (order: 5, 131072 bytes)
[    0.653933] TCP established hash table entries: 131072 (order: 8, 1048576 bytes)
[    0.654226] TCP bind hash table entries: 65536 (order: 9, 2359296 bytes)
[    0.656438] TCP: Hash tables configured (established 131072 bind 65536)
[    0.656451] TCP reno registered
[    0.656456] UDP hash table entries: 512 (order: 3, 40960 bytes)
[    0.656495] UDP-Lite hash table entries: 512 (order: 3, 40960 bytes)
[    0.656652] NET: Registered protocol family 1
[    0.656668] pci 0000:00:02.0: Boot video device
[    0.656754] PCI: CLS 64 bytes, default 64
[    0.656826] Unpacking initramfs...
[    0.864650] Freeing initrd memory: 11388k freed
[    0.866573] DMAR: Host address width 36
[    0.866576] DMAR: DRHD base: 0x000000fed90000 flags: 0x0
[    0.866592] IOMMU 0: reg_base_addr fed90000 ver 1:0 cap c0000020e60262 ecap f0101a
[    0.866595] DMAR: DRHD base: 0x000000fed91000 flags: 0x1
[    0.866601] IOMMU 1: reg_base_addr fed91000 ver 1:0 cap c9008020660262 ecap f0105a
[    0.866602] DMAR: RMRR base: 0x000000dacd5000 end: 0x000000dacebfff
[    0.866604] DMAR: RMRR base: 0x000000db800000 end: 0x000000df9fffff
[    0.866606] DMAR: No ATSR found
[    0.867155] audit: initializing netlink socket (disabled)
[    0.867176] type=2000 audit(1326790306.712:1): initialized
[    0.884746] highmem bounce pool size: 64 pages
[    0.884751] HugeTLB registered 2 MB page size, pre-allocated 0 pages
[    0.897048] VFS: Disk quotas dquot_6.5.2
[    0.897125] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.897258] msgmni has been set to 1627
[    0.897557] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 253)
[    0.897563] io scheduler noop registered
[    0.897565] io scheduler deadline registered
[    0.897574] io scheduler cfq registered (default)
[    0.898154] intel_idle: MWAIT substates: 0x21120
[    0.898156] intel_idle: v0.4 model 0x2A
[    0.898157] intel_idle: lapic_timer_reliable_states 0xffffffff
[    0.898198] ERST: Table is not found!
[    0.898265] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    1.140441] serial 0000:00:16.3: PCI INT B -> GSI 19 (level, low) -> IRQ 19
[    1.160770] 0000:00:16.3: ttyS0 at I/O 0x50b0 (irq = 19) is a 16550A
[    1.208406] Linux agpgart interface v0.103
[    1.208594] agpgart-intel 0000:00:00.0: Intel Sandybridge Chipset
[    1.208673] agpgart-intel 0000:00:00.0: detected gtt size: 2097152K total, 262144K mappable
[    1.209598] agpgart-intel 0000:00:00.0: detected 65536K stolen memory
[    1.209725] agpgart-intel 0000:00:00.0: AGP aperture is 256M @ 0xe0000000
[    1.209879] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
[    1.212870] serio: i8042 KBD port at 0x60,0x64 irq 1
[    1.212885] serio: i8042 AUX port at 0x60,0x64 irq 12
[    1.213072] mousedev: PS/2 mouse device common for all mice
[    1.213157] rtc_cmos 00:07: RTC can wake from S4
[    1.213291] rtc_cmos 00:07: rtc core: registered rtc_cmos as rtc0
[    1.213329] rtc0: alarms up to one month, y3k, 114 bytes nvram, hpet irqs
[    1.213512] cpuidle: using governor ladder
[    1.213879] cpuidle: using governor menu
[    1.214308] TCP cubic registered
[    1.214456] NET: Registered protocol family 10
[    1.215339] Mobile IPv6
[    1.215342] NET: Registered protocol family 17
[    1.215348] Registering the dns_resolver key type
[    1.215409] Using IPI No-Shortcut mode
[    1.215502] PM: Hibernation image not present or could not be loaded.
[    1.215515] registered taskstats version 1
[    1.221155] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0
[    1.221420]   Magic number: 12:431:877
[    1.221494] rtc_cmos 00:07: setting system clock to 2012-01-17 08:51:47 UTC (1326790307)
[    1.221572] Initializing network drop monitor service
[    1.221773] Freeing unused kernel memory: 484k freed
[    1.222018] Write protecting the kernel text: 3708k
[    1.222106] Write protecting the kernel read-only data: 1352k
[    1.222108] NX-protecting the kernel data: 2436k
[    1.267838] udev[54]: starting version 164
[    1.288964] thermal LNXTHERM:00: registered as thermal_zone0
[    1.288968] ACPI: Thermal Zone [THM0] (60 C)
[    1.294563] e1000e: Intel(R) PRO/1000 Network Driver - 1.3.10-k2
[    1.294567] e1000e: Copyright(c) 1999 - 2011 Intel Corporation.
[    1.294618] e1000e 0000:00:19.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20
[    1.294631] e1000e 0000:00:19.0: setting latency timer to 64
[    1.294711] usbcore: registered new interface driver usbfs
[    1.294771] usbcore: registered new interface driver hub
[    1.294804] e1000e 0000:00:19.0: irq 40 for MSI/MSI-X
[    1.294845] usbcore: registered new device driver usb
[    1.295319] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    1.301936] SCSI subsystem initialized
[    1.304335] libata version 3.00 loaded.
[    1.322646] sdhci: Secure Digital Host Controller Interface driver
[    1.322649] sdhci: Copyright(c) Pierre Ossman
[    1.322956] sdhci-pci 0000:0d:00.0: SDHCI controller found [1180:e823] (rev 5)
[    1.322982] sdhci-pci 0000:0d:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[    1.323066] sdhci-pci 0000:0d:00.0: setting latency timer to 64
[    1.323103] mmc0: no vmmc regulator found
[    1.323183] Registered led device: mmc0::
[    1.323307] mmc0: SDHCI controller on PCI [0000:0d:00.0] using DMA
[    1.487980] e1000e 0000:00:19.0: eth0: (PCI Express:2.5GT/s:Width x1) 00:21:cc:68:10:5e
[    1.487983] e1000e 0000:00:19.0: eth0: Intel(R) PRO/1000 Network Connection
[    1.488026] e1000e 0000:00:19.0: eth0: MAC: 10, PHY: 11, PBA No: 1000FF-0FF
[    1.488082] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
[    1.488091] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
[    1.488102] ehci_hcd 0000:00:1a.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[    1.488131] ehci_hcd 0000:00:1a.0: setting latency timer to 64
[    1.488136] ehci_hcd 0000:00:1a.0: EHCI Host Controller
[    1.488282] ehci_hcd 0000:00:1a.0: new USB bus registered, assigned bus number 1
[    1.488342] ehci_hcd 0000:00:1a.0: debug port 2
[    1.492224] ehci_hcd 0000:00:1a.0: cache line size of 64 is not supported
[    1.492233] ehci_hcd 0000:00:1a.0: irq 16, io mem 0xf252a000
[    1.508153] ehci_hcd 0000:00:1a.0: USB 2.0 started, EHCI 1.00
[    1.508301] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    1.508304] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.508306] usb usb1: Product: EHCI Host Controller
[    1.508308] usb usb1: Manufacturer: Linux 3.0.17 ehci_hcd
[    1.508309] usb usb1: SerialNumber: 0000:00:1a.0
[    1.508546] hub 1-0:1.0: USB hub found
[    1.508555] hub 1-0:1.0: 3 ports detected
[    1.508693] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[    1.508698] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
[    1.508717] ehci_hcd 0000:00:1d.0: PCI INT A -> GSI 23 (level, low) -> IRQ 23
[    1.508741] ehci_hcd 0000:00:1d.0: setting latency timer to 64
[    1.508745] ehci_hcd 0000:00:1d.0: EHCI Host Controller
[    1.508756] ehci_hcd 0000:00:1d.0: new USB bus registered, assigned bus number 2
[    1.508790] ehci_hcd 0000:00:1d.0: debug port 2
[    1.512693] ehci_hcd 0000:00:1d.0: cache line size of 64 is not supported
[    1.512715] ehci_hcd 0000:00:1d.0: irq 23, io mem 0xf2529000
[    1.528140] ehci_hcd 0000:00:1d.0: USB 2.0 started, EHCI 1.00
[    1.528208] usb usb2: New USB device found, idVendor=1d6b, idProduct=0002
[    1.528210] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.528212] usb usb2: Product: EHCI Host Controller
[    1.528214] usb usb2: Manufacturer: Linux 3.0.17 ehci_hcd
[    1.528215] usb usb2: SerialNumber: 0000:00:1d.0
[    1.528401] hub 2-0:1.0: USB hub found
[    1.528408] hub 2-0:1.0: 3 ports detected
[    1.528527] ahci 0000:00:1f.2: version 3.0
[    1.528546] ahci 0000:00:1f.2: PCI INT B -> GSI 19 (level, low) -> IRQ 19
[    1.528628] ahci 0000:00:1f.2: irq 41 for MSI/MSI-X
[    1.528719] ahci: SSS flag set, parallel bus scan disabled
[    1.544181] ahci 0000:00:1f.2: AHCI 0001.0300 32 slots 6 ports 6 Gbps 0x1b impl SATA mode
[    1.544186] ahci 0000:00:1f.2: flags: 64bit ncq sntf ilck stag pm led clo pio slum part ems sxs apst 
[    1.544193] ahci 0000:00:1f.2: setting latency timer to 64
[    1.569167] scsi0 : ahci
[    1.569371] scsi1 : ahci
[    1.569512] scsi2 : ahci
[    1.569652] scsi3 : ahci
[    1.569792] scsi4 : ahci
[    1.569930] scsi5 : ahci
[    1.570606] ata1: SATA max UDMA/133 abar m2048@0xf2528000 port 0xf2528100 irq 41
[    1.570610] ata2: SATA max UDMA/133 abar m2048@0xf2528000 port 0xf2528180 irq 41
[    1.570612] ata3: DUMMY
[    1.570615] ata4: SATA max UDMA/133 abar m2048@0xf2528000 port 0xf2528280 irq 41
[    1.570618] ata5: SATA max UDMA/133 abar m2048@0xf2528000 port 0xf2528300 irq 41
[    1.570620] ata6: DUMMY
[    1.820086] usb 1-1: new high speed USB device number 2 using ehci_hcd
[    1.864082] Refined TSC clocksource calibration: 2591.580 MHz.
[    1.864088] Switching to clocksource tsc
[    1.888044] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[    1.889767] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[    1.889781] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[    1.889790] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[    1.907290] ata1.00: ATA-8: ST320LT007-9ZV142, 0004LVM1, max UDMA/133
[    1.907301] ata1.00: 625142448 sectors, multi 16: LBA48 NCQ (depth 31/32)
[    1.910611] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[    1.910624] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[    1.910634] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[    1.913550] ata1.00: configured for UDMA/133
[    1.913841] scsi 0:0:0:0: Direct-Access     ATA      ST320LT007-9ZV14 0004 PQ: 0 ANSI: 5
[    1.952552] usb 1-1: New USB device found, idVendor=8087, idProduct=0024
[    1.952571] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    1.952822] hub 1-1:1.0: USB hub found
[    1.952887] hub 1-1:1.0: 6 ports detected
[    2.064018] usb 2-1: new high speed USB device number 2 using ehci_hcd
[    2.196466] usb 2-1: New USB device found, idVendor=8087, idProduct=0024
[    2.196477] usb 2-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    2.196786] hub 2-1:1.0: USB hub found
[    2.196933] hub 2-1:1.0: 8 ports detected
[    2.231932] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[    2.234906] ata2.00: ACPI cmd e3/00:1f:00:00:00:a0 (IDLE) succeeded
[    2.235681] ata2.00: ACPI cmd e3/00:02:00:00:00:a0 (IDLE) succeeded
[    2.235694] ata2.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[    2.237609] ata2.00: ATAPI: MATSHITADVD-RAM UJ8A0A, SB02, max UDMA/100
[    2.241406] ata2.00: ACPI cmd e3/00:1f:00:00:00:a0 (IDLE) succeeded
[    2.242227] ata2.00: ACPI cmd e3/00:02:00:00:00:a0 (IDLE) succeeded
[    2.242240] ata2.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[    2.244159] ata2.00: configured for UDMA/100
[    2.248179] scsi 1:0:0:0: CD-ROM            MATSHITA DVD-RAM UJ8A0A   SB02 PQ: 0 ANSI: 5
[    2.268123] usb 1-1.3: new full speed USB device number 3 using ehci_hcd
[    2.361717] usb 1-1.3: New USB device found, idVendor=147e, idProduct=2016
[    2.361729] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    2.361736] usb 1-1.3: Product: Biometric Coprocessor
[    2.361741] usb 1-1.3: Manufacturer: UPEK
[    2.432075] usb 1-1.4: new full speed USB device number 4 using ehci_hcd
[    2.528667] usb 1-1.4: New USB device found, idVendor=0a5c, idProduct=217f
[    2.528679] usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    2.528686] usb 1-1.4: Product: Broadcom Bluetooth Device
[    2.528691] usb 1-1.4: Manufacturer: Broadcom Corp
[    2.528696] usb 1-1.4: SerialNumber: 9439E58DB14E
[    2.567822] ata4: SATA link down (SStatus 0 SControl 300)
[    2.600022] usb 1-1.6: new high speed USB device number 5 using ehci_hcd
[    2.698911] usb 1-1.6: New USB device found, idVendor=04f2, idProduct=b221
[    2.698923] usb 1-1.6: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    2.698929] usb 1-1.6: Product: Integrated Camera
[    2.698943] usb 1-1.6: Manufacturer: Chicony Electronics Co., Ltd.
[    2.771960] usb 2-1.1: new high speed USB device number 3 using ehci_hcd
[    2.864256] usb 2-1.1: New USB device found, idVendor=0424, idProduct=2514
[    2.864275] usb 2-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    2.864571] hub 2-1.1:1.0: USB hub found
[    2.864719] hub 2-1.1:1.0: 3 ports detected
[    2.887724] ata5: SATA link down (SStatus 0 SControl 300)
[    2.894055] sd 0:0:0:0: [sda] 625142448 512-byte logical blocks: (320 GB/298 GiB)
[    2.894058] sd 0:0:0:0: [sda] 4096-byte physical blocks
[    2.894138] sd 0:0:0:0: [sda] Write Protect is off
[    2.894141] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[    2.894172] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    2.896432] sr0: scsi3-mmc drive: 24x/24x writer dvd-ram cd/rw xa/form2 cdda tray
[    2.896442] cdrom: Uniform CD-ROM driver Revision: 3.20
[    2.896712] sr 1:0:0:0: Attached scsi CD-ROM sr0
[    2.938240]  sda: sda1 sda2 < sda5 >
[    2.938726] sd 0:0:0:0: [sda] Attached SCSI disk
[    2.941578] sd 0:0:0:0: Attached scsi generic sg0 type 0
[    2.941744] sr 1:0:0:0: Attached scsi generic sg1 type 5
[    3.135844] usb 2-1.1.1: new high speed USB device number 4 using ehci_hcd
[    3.227981] usb 2-1.1.1: New USB device found, idVendor=0424, idProduct=2640
[    3.227985] usb 2-1.1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.228399] hub 2-1.1.1:1.0: USB hub found
[    3.228475] hub 2-1.1.1:1.0: 3 ports detected
[    3.286956] device-mapper: uevent: version 1.0.3
[    3.287293] device-mapper: ioctl: 4.20.0-ioctl (2011-02-02) initialised: dm-devel@redhat.com
[    3.499726] usb 2-1.1.1.1: new high speed USB device number 5 using ehci_hcd
[    3.651136] usb 2-1.1.1.1: New USB device found, idVendor=0424, idProduct=4060
[    3.651147] usb 2-1.1.1.1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    3.651154] usb 2-1.1.1.1: Product: Ultra Fast Media Reader
[    3.651167] usb 2-1.1.1.1: Manufacturer: Generic
[    3.651169] usb 2-1.1.1.1: SerialNumber: F110A6008DA6
[    3.654784] Initializing USB Mass Storage driver...
[    3.655029] scsi6 : usb-storage 2-1.1.1.1:1.0
[    3.655188] usbcore: registered new interface driver usb-storage
[    3.655190] USB Mass Storage support registered.
[    3.723653] usb 2-1.1.1.2: new full speed USB device number 6 using ehci_hcd
[    3.817246] usb 2-1.1.1.2: New USB device found, idVendor=04b3, idProduct=301a
[    3.817258] usb 2-1.1.1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    3.817265] usb 2-1.1.1.2: Product: USB 1.1 2port downstream low power hub
[    3.817271] usb 2-1.1.1.2: Manufacturer: Lite-On Technology
[    3.818121] hub 2-1.1.1.2:1.0: USB hub found
[    3.818284] hub 2-1.1.1.2:1.0: 3 ports detected
[    3.903596] usb 2-1.1.1.3: new low speed USB device number 7 using ehci_hcd
[    3.999696] usb 2-1.1.1.3: New USB device found, idVendor=17ef, idProduct=601d
[    3.999707] usb 2-1.1.1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    3.999723] usb 2-1.1.1.3: Product: Lenovo Laser Mouse
[    3.999728] usb 2-1.1.1.3: Manufacturer: Primax
[    4.006657] input: Primax Lenovo Laser Mouse as /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.1/2-1.1.1/2-1.1.1.3/2-1.1.1.3:1.0/input/input1
[    4.006814] generic-usb 0003:17EF:601D.0001: input,hidraw0: USB HID v1.11 Mouse [Primax Lenovo Laser Mouse] on usb-0000:00:1d.0-1.1.1.3/input0
[    4.006838] usbcore: registered new interface driver usbhid
[    4.006840] usbhid: USB HID core driver
[    4.087529] usb 2-1.1.1.2.1: new full speed USB device number 8 using ehci_hcd
[    4.181139] usb 2-1.1.1.2.1: New USB device found, idVendor=04b3, idProduct=301b
[    4.181151] usb 2-1.1.1.2.1: New USB device strings: Mfr=1, Product=3, SerialNumber=0
[    4.181158] usb 2-1.1.1.2.1: Product: USB Productivity Option Keyboard( has the hub in # 1 )
[    4.181164] usb 2-1.1.1.2.1: Manufacturer: Lite-On Technology
[    4.183333] input: Lite-On Technology USB Productivity Option Keyboard( has the hub in # 1 ) as /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.1/2-1.1.1/2-1.1.1.2/2-1.1.1.2.1/2-1.1.1.2.1:1.0/input/input2
[    4.183465] generic-usb 0003:04B3:301B.0002: input,hidraw1: USB HID v1.10 Keyboard [Lite-On Technology USB Productivity Option Keyboard( has the hub in # 1 )] on usb-0000:00:1d.0-1.1.1.2.1/input0
[    4.185191] input: Lite-On Technology USB Productivity Option Keyboard( has the hub in # 1 ) as /devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.1/2-1.1.1/2-1.1.1.2/2-1.1.1.2.1/2-1.1.1.2.1:1.1/input/input3
[    4.185253] generic-usb 0003:04B3:301B.0003: input,hidraw2: USB HID v1.10 Device [Lite-On Technology USB Productivity Option Keyboard( has the hub in # 1 )] on usb-0000:00:1d.0-1.1.1.2.1/input1
[    4.662491] scsi 6:0:0:0: Direct-Access     Generic  Ultra HS-SD/MMC  1.82 PQ: 0 ANSI: 0
[    4.663253] sd 6:0:0:0: Attached scsi generic sg2 type 0
[    4.679016] sd 6:0:0:0: [sdb] Attached SCSI removable disk
[    8.286759] PM: Starting manual resume from disk
[    8.286762] PM: Hibernation image partition 254:2 present
[    8.286764] PM: Looking for hibernation image.
[    8.287287] PM: Image not found (code -22)
[    8.287289] PM: Hibernation image not present or could not be loaded.
[    8.304354] EXT4-fs (dm-1): INFO: recovery required on readonly filesystem
[    8.304358] EXT4-fs (dm-1): write access will be enabled during recovery
[   20.846898] EXT4-fs (dm-1): recovery complete
[   20.852484] EXT4-fs (dm-1): mounted filesystem with writeback data mode. Opts: (null)
[   24.372823] udev[379]: starting version 164
[   25.005491] ACPI: acpi_idle yielding to intel_idle
[   25.011008] Non-volatile memory driver v1.3
[   25.014575] input: Lid Switch as /devices/LNXSYSTM:00/device:00/PNP0C0D:00/input/input4
[   25.014748] ACPI: Lid Switch [LID]
[   25.014807] input: Sleep Button as /devices/LNXSYSTM:00/device:00/PNP0C0E:00/input/input5
[   25.014814] ACPI: Sleep Button [SLPB]
[   25.014900] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input6
[   25.014905] ACPI: Power Button [PWRF]
[   25.037796] ACPI: Battery Slot [BAT0] (battery present)
[   25.038481] ACPI: AC Adapter [AC] (on-line)
[   25.270425] i801_smbus 0000:00:1f.3: PCI INT C -> GSI 18 (level, low) -> IRQ 18
[   25.364003] wmi: Mapper loaded
[   25.434002] tpm_tis 00:0a: 1.2 TPM (device-id 0x0, rev-id 78)
[   25.619377] cfg80211: Calling CRDA to update world regulatory domain
[   25.756763] iwlagn: Intel(R) Wireless WiFi Link AGN driver for Linux, in-tree:
[   25.756767] iwlagn: Copyright(c) 2003-2011 Intel Corporation
[   25.756832] iwlagn 0000:03:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
[   25.756842] iwlagn 0000:03:00.0: setting latency timer to 64
[   25.756893] iwlagn 0000:03:00.0: Detected Intel(R) Centrino(R) Advanced-N 6205 AGN, REV=0xB0
[   25.767475] iwlagn 0000:03:00.0: device EEPROM VER=0x715, CALIB=0x6
[   25.767479] iwlagn 0000:03:00.0: Device SKU: 0Xb
[   25.767481] iwlagn 0000:03:00.0: Valid Tx ant: 0X3, Valid Rx ant: 0X3
[   25.767685] iwlagn 0000:03:00.0: Tunable channels: 13 802.11bg, 24 802.11a channels
[   25.767807] iwlagn 0000:03:00.0: irq 42 for MSI/MSI-X
[   25.799293] Synaptics Touchpad, model: 1, fw: 7.2, id: 0x1c0b1, caps: 0xd047b3/0xb40000/0xa0000
[   25.799302] serio: Synaptics pass-through port at isa0060/serio1/input0
[   25.820652] iwlagn 0000:03:00.0: request for firmware file 'iwlwifi-6000g2a-5.ucode' failed.
[   25.824344] iwlagn 0000:03:00.0: request for firmware file 'iwlwifi-6000g2a-4.ucode' failed.
[   25.824409] iwlagn 0000:03:00.0: no suitable firmware found!
[   25.824687] iwlagn 0000:03:00.0: PCI INT A disabled
[   25.849532] input: SynPS/2 Synaptics TouchPad as /devices/platform/i8042/serio1/input/input7
[   26.303752] Linux video capture interface: v2.00
[   26.361827] uvcvideo: Found UVC 1.00 device Integrated Camera (04f2:b221)
[   26.363263] input: Integrated Camera as /devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.6/1-1.6:1.0/input/input8
[   26.363360] usbcore: registered new interface driver uvcvideo
[   26.363363] USB Video Class driver (v1.1.0)
[   26.367046] thinkpad_acpi: ThinkPad ACPI Extras v0.24
[   26.367049] thinkpad_acpi: http://ibm-acpi.sf.net/
[   26.367052] thinkpad_acpi: ThinkPad BIOS 83ET63WW (1.33 ), EC unknown
[   26.367055] thinkpad_acpi: Lenovo ThinkPad T420, model 4236AC2
[   26.367992] thinkpad_acpi: detected a 8-level brightness capable ThinkPad
[   26.368137] thinkpad_acpi: radio switch found; radios are enabled
[   26.370597] thinkpad_acpi: rfkill switch tpacpi_bluetooth_sw: radio is unblocked
[   26.371002] Registered led device: tpacpi::thinklight
[   26.371092] Registered led device: tpacpi::power
[   26.371192] Registered led device: tpacpi::standby
[   26.371290] Registered led device: tpacpi::thinkvantage
[   26.371422] thinkpad_acpi: Standard ACPI backlight interface available, not loading native one
[   26.372264] thinkpad_acpi: Console audio control enabled, mode: monitor (read only)
[   26.373405] input: ThinkPad Extra Buttons as /devices/platform/thinkpad_acpi/input/input9
[   26.482943] Bluetooth: Core ver 2.16
[   26.483042] NET: Registered protocol family 31
[   26.483045] Bluetooth: HCI device and connection manager initialized
[   26.483109] Bluetooth: HCI socket layer initialized
[   26.594974] HDA Intel 0000:00:1b.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22
[   26.595056] HDA Intel 0000:00:1b.0: irq 42 for MSI/MSI-X
[   26.595102] HDA Intel 0000:00:1b.0: setting latency timer to 64
[   26.851847] Bluetooth: Generic Bluetooth USB driver ver 0.6
[   26.852281] usbcore: registered new interface driver btusb
[   26.875529] input: HDA Digital PCBeep as /devices/pci0000:00/0000:00:1b.0/input/input10
[   27.843952] EXT4-fs (dm-1): re-mounted. Opts: (null)
[   28.024589] EXT4-fs (dm-1): re-mounted. Opts: errors=remount-ro
[   28.346961] loop: module loaded
[   28.673878] Adding 6922232k swap on /dev/mapper/uldhcp1b029120-swap_1.  Priority:-1 extents:1 across:6922232k 
[   29.015246] EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: errors=remount-ro
[   30.220859] fuse init (API version 7.16)
[   32.249731] input: ACPI Virtual Keyboard Device as /devices/virtual/input/input11
[   32.397397] IBM TrackPoint firmware: 0x0e, buttons: 3/3
[   32.654150] input: TPPS/2 IBM TrackPoint as /devices/platform/i8042/serio1/serio2/input/input12
[   35.045670] e1000e 0000:00:19.0: irq 40 for MSI/MSI-X
[   35.101558] e1000e 0000:00:19.0: irq 40 for MSI/MSI-X
[   35.101756] ADDRCONF(NETDEV_UP): eth0: link is not ready
[   36.670771] e1000e: eth0 NIC Link is Up 100 Mbps Full Duplex, Flow Control: None
[   36.670776] e1000e 0000:00:19.0: eth0: 10/100 speed: disabling TSO
[   36.670897] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   37.779363] apm: BIOS not found.
[   39.114820] [drm] Initialized drm 1.1.0 20060810
[   39.161437] i915 0000:00:02.0: power state changed by ACPI to D0
[   39.161443] i915 0000:00:02.0: power state changed by ACPI to D0
[   39.161449] i915 0000:00:02.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[   39.161453] i915 0000:00:02.0: setting latency timer to 64
[   39.182716] mtrr: no more MTRRs available
[   39.182720] [drm] MTRR allocation failed.  Graphics performance may suffer.
[   39.184341] i915 0000:00:02.0: irq 43 for MSI/MSI-X
[   39.184350] [drm] Supports vblank timestamp caching Rev 1 (10.10.2010).
[   39.184353] [drm] Driver supports precise vblank timestamp query.
[   39.184489] vgaarb: device changed decodes: PCI:0000:00:02.0,olddecodes=io+mem,decodes=io+mem:owns=io+mem
[   39.389342] fbcon: inteldrmfb (fb0) is primary device
[   39.389511] Console: switching to colour frame buffer device 200x56
[   39.389553] fb0: inteldrmfb frame buffer device
[   39.389556] drm: registered panic notifier
[   39.414455] acpi device:01: registered as cooling_device4
[   39.414729] input: Video Bus as /devices/LNXSYSTM:00/device:00/PNP0A08:00/LNXVIDEO:00/input/input13
[   39.414849] ACPI: Video Device [VID] (multi-head: yes  rom: no  post: no)
[   39.415120] [drm] Initialized i915 1.6.0 20080730 for 0000:00:02.0 on minor 0
[   39.542157] [drm] Changing LVDS panel from (+hsync, +vsync) to (-hsync, -vsync)
[   39.802312] ip_tables: (C) 2000-2006 Netfilter Core Team
[   40.058318] lp: driver loaded but no devices found
[   40.156646] ppdev: user-space parallel port driver
[   40.328674] [drm] Changing LVDS panel from (-hsync, -vsync) to (-hsync, +vsync)
[   42.498673] powernow: This module only works with AMD K7 CPUs
[   43.371904] cpufreq-nforce2: No nForce2 chipset.
[   44.369920] vboxdrv: Found 4 processor cores.
[   44.370059] vboxdrv: fAsync=0 offMin=0x1f6 offMax=0x1029
[   44.370237] vboxdrv: TSC mode is 'synchronous', kernel timer mode is 'normal'.
[   44.370239] vboxdrv: Successfully loaded version 4.1.8 (interface 0x00190000).
[   45.011015] vboxpci: IOMMU not found (not registered)
[   46.949616] eth0: no IPv6 routers present
[   57.078666] apt-check[2411]: segfault at 0 ip b75e4b16 sp bfc878e8 error 6 in libc-2.11.2.so[b7570000+140000]
[   85.224563] exe (2670): /proc/2670/oom_adj is deprecated, please use /proc/2670/oom_score_adj instead.
Comment 3 Mikko Rapeli 2012-01-20 09:25:03 UTC
(In reply to comment #1)
> Can you please try "dd if=/dev/sda of=/dev/zero iflag=direct bs=1M count=100"
> when the system is in the slow state and post the output? Please also attach
> the output of dmesg. Thanks.

Right now it seems like the situation is on again. At least trying to grep or git grep something in a kernel tree seems to take ages and whole system seems to slow down.

top - 10:21:06 up 3 days, 29 min, 21 users,  load average: 1.07, 3.86, 5.12
Tasks: 200 total,   1 running, 199 sleeping,   0 stopped,   0 zombie
Cpu(s):  3.1%us,  1.9%sy,  0.0%ni, 77.5%id, 17.5%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   8191852k total,  7881324k used,   310528k free,   298740k buffers
Swap:  6922232k total,     5804k used,  6916428k free,  6885356k cached

# dd if=/dev/sda of=/dev/zero iflag=direct bs=1M count=100
100+0 records in
100+0 records out
104857600 bytes (105 MB) copied, 37.8645 s, 2.8 MB/s
Comment 4 Mikko Rapeli 2012-01-23 15:03:48 UTC
(In reply to comment #3)
> (In reply to comment #1)
> > Can you please try "dd if=/dev/sda of=/dev/zero iflag=direct bs=1M
> count=100"
> > when the system is in the slow state and post the output? Please also
> attach
> > the output of dmesg. Thanks.
> 
> Right now it seems like the situation is on again. At least trying to grep or
> git grep something in a kernel tree seems to take ages and whole system seems
> to slow down.
> 
> top - 10:21:06 up 3 days, 29 min, 21 users,  load average: 1.07, 3.86, 5.12
> Tasks: 200 total,   1 running, 199 sleeping,   0 stopped,   0 zombie
> Cpu(s):  3.1%us,  1.9%sy,  0.0%ni, 77.5%id, 17.5%wa,  0.0%hi,  0.0%si, 
> 0.0%st
> Mem:   8191852k total,  7881324k used,   310528k free,   298740k buffers
> Swap:  6922232k total,     5804k used,  6916428k free,  6885356k cached
> 
> # dd if=/dev/sda of=/dev/zero iflag=direct bs=1M count=100
> 100+0 records in
> 100+0 records out
> 104857600 bytes (105 MB) copied, 37.8645 s, 2.8 MB/s

In addition to this, I noticed some weird file access patterns on my ext4 fs. Grepping for a string in a 160 Mb vmlinux.o took over half an hour. I had played around with ext4 parameters relatime,data=writeback,barrier=0 on this file system but gone back to plain noatime, so maybe there's something I've screwed up. After "git clean -d -x -f"ing (which took ages to complete) the kernel tree I can now grep around with enough speed.

iotop shows almost no disk access when things go to halt.

I've used e2fsprogs 1.41.12-4stable1 from Debian squeeze/stable. Maybe a full fsck on the ext4 fs would help?
Comment 5 Mikko Rapeli 2012-01-24 09:12:09 UTC
Current ext4 parameters on the rootfs:

# tune2fs -l /dev/mapper/uldhcp1b029120-root
tune2fs 1.41.12 (17-May-2010)
Filesystem volume name:   <none>   
Last mounted on:          /
Filesystem UUID:          fb01bbfa-d11f-4c9f-9798-3744753d81f1
Filesystem magic number:  0xEF53   
Filesystem revision #:    1 (dynamic)
Filesystem features:      has_journal ext_attr resize_inode dir_index filetype n
eeds_recovery extent flex_bg sparse_super large_file huge_file uninit_bg dir_nli
nk extra_isize
Filesystem flags:         signed_directory_hash
Default mount options:    journal_data_writeback
Filesystem state:         clean
Errors behavior:          Continue 
Filesystem OS type:       Linux
Inode count:              19087360 
Block count:              76348416 
Reserved block count:     3817420  
Free blocks:              63188040 
Free inodes:              18129935 
First block:              0
Block size:               4096
Fragment size:            4096
Reserved GDT blocks:      1005
Blocks per group:         32768
Fragments per group:      32768
Inodes per group:         8192
Inode blocks per group:   512
RAID stride:              1
Flex block group size:    16
Filesystem created:       Tue Nov 15 18:01:33 2011
Last mount time:          Tue Jan 17 09:52:14 2012
Last write time:          Thu Nov 24 14:27:43 2011
Mount count:              18
Maximum mount count:      38
Last checked:             Tue Nov 15 18:01:33 2011
Check interval:           15552000 (6 months)
Next check after:         Sun May 13 19:01:33 2012
Lifetime writes:          38 GB
Reserved blocks uid:      0 (user root)
Reserved blocks gid:      0 (group root)
First inode:              11
Inode size:               256
Required extra isize:     28
Desired extra isize:      28
Journal inode:            8
First orphan inode:       788080  
Default directory hash:   half_md4 
Directory Hash Seed:      a8cc437c-f468-49e7-9700-40dc885e7d4e
Journal backup:           inode blocks
Comment 6 Mikko Rapeli 2012-02-22 07:43:03 UTC
Just in case I had messed up the ext4 options, I re-installed the root fs but the problems are still there. Very sluggish IO performance after few days of uptime.

# time ( dd if=/dev/sda of=/dev/zero iflag=direct bs=1M count=100 )
100+0 records in
100+0 records out
104857600 bytes (105 MB) copied, 30.2621 s, 3.5 MB/s

real    0m30.263s
user    0m0.000s
sys     0m0.020s

# hdparm -i /dev/sda

/dev/sda:

 Model=ST320LT007-9ZV142, FwRev=0004LVM1, SerialNo=W0Q1FL5R
 Config={ HardSect NotMFM HdSw>15uSec Fixed DTR>10Mbs RotSpdTol>.5% }
 RawCHS=16383/16/63, TrkSize=0, SectSize=0, ECCbytes=4
 BuffType=unknown, BuffSize=16384kB, MaxMultSect=16, MultSect=16
 CurCHS=65535/1/63, CurSects=4128705, LBA=yes, LBAsects=625142448
 IORDY=on/off, tPIO={min:120,w/IORDY:120}, tDMA={min:120,rec:120}
 PIO modes:  pio0 pio1 pio2 pio3 pio4
 DMA modes:  mdma0 mdma1 mdma2
 UDMA modes: udma0 udma1 udma2 udma3 udma4 udma5 *udma6
 AdvancedPM=yes: unknown setting WriteCache=enabled
 Drive conforms to: unknown:  ATA/ATAPI-3,4,5,6,7

 * signifies the current active mode

With 3.0.19 kernel I see something in logs though:

[638317.904285] INFO: task exim4:4343 blocked for more than 120 seconds.
[638317.904293] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
 message.
[638317.904300] exim4           D f2aaec08     0  4343   3783 0x00000000
[638317.904310]  e8286300 00000082 f2824600 f2aaec08 c10e124c 00000000 f2aaec08 
3202d000
[638317.904324]  f2a2a888 c1459900 e82864ac c1459900 e8286300 c1459900 c1459900 
00000000
[638317.904336]  00000001 f2824600 c10e1281 00001000 f0d8f8b8 f8ac18ac f8a17e94 
ef80b8c0
[638317.904349] Call Trace:
[638317.904366]  [<c10e124c>] ? __find_get_block+0x14d/0x157
[638317.904375]  [<c10e1281>] ? __getblk+0x2b/0x30d
[638317.904414]  [<f8a17e94>] ? jbd2_journal_grab_journal_head+0xf/0x25 [jbd2]
[638317.904428]  [<f8a1331f>] ? __jbd2_journal_file_buffer+0xb5/0x12c [jbd2]
[638317.904442]  [<f8a1458c>] ? do_get_write_access+0x196/0x30d [jbd2]
[638317.904452]  [<c104c983>] ? autoremove_wake_function+0x29/0x29
[638317.904467]  [<f8a1471b>] ? jbd2_journal_get_write_access+0x18/0x26 [jbd2]
[638317.904491]  [<f8ab58e2>] ? __ext4_journal_get_write_access+0x3f/0x47 [ext4]
[638317.904512]  [<f8a9f7a0>] ? ext4_orphan_add+0x64/0x180 [ext4]
[638317.904530]  [<f8aa1a9a>] ? ext4_unlink+0x175/0x1e3 [ext4]
[638317.904538]  [<c10cc372>] ? vfs_unlink+0x55/0xa5
[638317.904544]  [<c10ce277>] ? do_unlinkat+0xa9/0x11a
[638317.904552]  [<c10c57de>] ? fput+0x185/0x19d
[638317.904562]  [<c10c2e4b>] ? filp_close+0x54/0x5a
[638317.904570]  [<c12a9d5f>] ? sysenter_do_call+0x12/0x28
[638317.904578] INFO: task exim4:4488 blocked for more than 120 seconds.
[638317.904592] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[638317.904597] exim4           D 0002446f     0  4488   1904 0x00000000
[638317.904606]  e6cfa100 00000082 7953e45a 0002446f 00000006 d7e932c0 0002446f 0000d93d
[638317.904618]  00000000 c1459900 e6cfa2ac c1459900 e6cfa100 c1459900 c1459900 c109598b
[638317.904630]  0000000e 00000001 00000001 00000000 f39862e0 00000000 d647ff48 d7b9e070
[638317.904642] Call Trace:
[638317.904652]  [<c109598b>] ? find_get_pages_tag+0x37/0xc5
[638317.904662]  [<c102ac54>] ? __wake_up+0x2c/0x3b
[638317.904668]  [<c104cacc>] ? prepare_to_wait+0x14/0x52
[638317.904683]  [<f8a18c82>] ? jbd2_log_wait_commit+0xaa/0xf3 [jbd2]
[638317.904689]  [<c104c95a>] ? wake_up_bit+0x56/0x56
[638317.904706]  [<f8a94d07>] ? ext4_sync_file+0x1aa/0x207 [ext4]
[638317.904716]  [<c1096292>] ? filemap_write_and_wait_range+0x3e/0x4c
[638317.904724]  [<c10df986>] ? vfs_fsync_range+0x3f/0x5d
[638317.904730]  [<c10dfa0f>] ? vfs_fsync+0x11/0x15
[638317.904736]  [<c10dfa33>] ? do_fsync+0x20/0x2f
[638317.904743]  [<c12a9d5f>] ? sysenter_do_call+0x12/0x28
[638317.904752] INFO: task rm:4609 blocked for more than 120 seconds.
[638317.904757] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[638317.904757] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[638317.904762] rm              D 0002446f     0  4609   4587 0x00000000
[638317.904769]  e6da18c0 00200086 e26183aa 0002446f f28e98b8 00000000 0002446f 0000828f
[638317.904781]  00000000 c1459900 e6da1a6c c1459900 e6da18c0 c1459900 c1459900 f8a13674
[638317.904793]  008996d9 d7b9e000 f28e98b8 e6e33d80 00000000 f8a13674 f28e98b8 00042a13
[638317.904805] Call Trace:
[638317.904818]  [<f8a13674>] ? jbd2_journal_stop+0x20e/0x21a [jbd2]
[638317.904830]  [<f8a13674>] ? jbd2_journal_stop+0x20e/0x21a [jbd2]
[638317.904847]  [<f8aa1ab6>] ? ext4_unlink+0x191/0x1e3 [ext4]
[638317.904855]  [<c104cacc>] ? prepare_to_wait+0x14/0x52
[638317.904875]  [<f8a9dff7>] ? ext4_ioend_wait+0x6d/0x7f [ext4]
[638317.904881]  [<c104c95a>] ? wake_up_bit+0x56/0x56
[638317.904904]  [<f8a9d5b1>] ? ext4_evict_inode+0x2e/0x251 [ext4]
[638317.904915]  [<c10d48d7>] ? evict+0x56/0xe7
[638317.904921]  [<c10ce2a2>] ? do_unlinkat+0xd4/0x11a
[638317.904929]  [<c12a9d5f>] ? sysenter_do_call+0x12/0x28
[638858.988184] ata1.00: exception Emask 0x0 SAct 0x0 SErr 0x0 action 0x6 frozen
[638858.988208] ata1.00: failed command: SMART
[638858.988222] ata1.00: cmd b0/da:00:00:4f:c2/00:00:00:00:00/00 tag 0
638858.988225]          res 40/00:01:00:4f:c2/00:00:00:00:00/00 Emask 0x4 (timeout)
[638858.988232] ata1.00: status: { DRDY }
[638858.988246] ata1: hard resetting link
[638859.308065] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[638861.060106] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[638861.060118] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[638861.060127] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[638861.066437] ata1.00: ACPI cmd ef/02:00:00:00:00:a0 (SET FEATURES) succeeded
[638861.066448] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[638861.066457] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[638861.069252] ata1.00: configured for UDMA/133
[638861.069284] ata1: EH complete
[639517.522746] INFO: task jbd2/dm-1-8:338 blocked for more than 120 seconds.
[639517.522756] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[639517.522762] jbd2/dm-1-8     D 00024574     0   338      2 0x00000000
[639517.522773]  d7c1e300 00000046 addf9eb8 00024574 f88fb040 00000000 00024574 31fad000
[639517.522787]  00000000 c1459900 d7c1e4ac c1459900 d7c1e300 c1459900 c1459900 f2c30ce0
[639517.522799]  c1054421 3b9b9b82 00000000 f2c30cd8 ffffffff 00000202 00000202 c107ba97
[639517.522819] Call Trace:
[639517.522841]  [<c1054421>] ? ktime_get_ts+0x76/0x7d
[639517.522846]  [<c107ba97>] ? delayacct_end+0x8f/0x97
[639517.522848]  [<c10531ec>] ? timekeeping_get_ns+0x10/0x48
[639517.522853]  [<c12a380a>] ? io_schedule+0x6c/0xa4
[639517.522857]  [<c1095ce7>] ? sleep_on_page+0x5/0x8
[639517.522859]  [<c12a3b6d>] ? __wait_on_bit+0x31/0x56
[639517.522861]  [<c1095ce2>] ? __lock_page+0x72/0x72
[639517.522864]  [<c1095f0c>] ? wait_on_page_bit+0x7c/0x84
[639517.522866]  [<c104c983>] ? autoremove_wake_function+0x29/0x29
[639517.522869]  [<c1096113>] ? filemap_fdatawait_range+0x6d/0x109
[639517.522873]  [<c113af1a>] ? submit_bio+0xb4/0xce
[639517.522877]  [<c10e437b>] ? bio_alloc_bioset+0x35/0x94
[639517.522879]  [<c10961f2>] ? filemap_fdatawait+0x43/0x4c
[639517.522886]  [<f8a15107>] ? jbd2_journal_commit_transaction+0x68a/0xdeb [jbd2]
[639517.522890]  [<c1040f8f>] ? lock_timer_base+0x19/0x34
[639517.522894]  [<f8a18f0b>] ? kjournald2+0x9e/0x1c7 [jbd2]
[639517.522896]  [<c104c95a>] ? wake_up_bit+0x56/0x56
[639517.522900]  [<f8a18e6d>] ? commit_timeout+0x5/0x5 [jbd2]
[639517.522902]  [<c104c610>] ? kthread+0x63/0x68
[639517.522904]  [<c104c5ad>] ? kthread_worker_fn+0x114/0x114
[639517.522907]  [<c12aa2fe>] ? kernel_thread_helper+0x6/0x10
[639517.522921] INFO: task gconfd-2:2162 blocked for more than 120 seconds.
[639517.522923] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[639517.522925] gconfd-2        D d75233b8     0  2162      1 0x00000000
[639517.522927]  d7c19ce0 00200082 f2b26ac8 d75233b8 c10e124c 00000000 f2824600 31fed000
[639517.522931]  00001000 c1459900 d7c19e8c c1459900 d7c19ce0 c1459900 c1459900 00000000
[639517.522935]  00000001 f2824600 c10e1281 00001000 d75b1338 f8ac18ac 00000338 d75b1348
[639517.522938] Call Trace:
[639517.522941]  [<c10e124c>] ? __find_get_block+0x14d/0x157
[639517.522943]  [<c10e1281>] ? __getblk+0x2b/0x30d
[639517.522948]  [<f8a1458c>] ? do_get_write_access+0x196/0x30d [jbd2]
[639517.522951]  [<c104c983>] ? autoremove_wake_function+0x29/0x29
[639517.522955]  [<f8a1471b>] ? jbd2_journal_get_write_access+0x18/0x26 [jbd2]
[639517.522963]  [<f8ab58e2>] ? __ext4_journal_get_write_access+0x3f/0x47 [ext4]
[639517.522969]  [<f8a9f7a0>] ? ext4_orphan_add+0x64/0x180 [ext4]
[639517.522976]  [<f8aa1a9a>] ? ext4_unlink+0x175/0x1e3 [ext4]
[639517.522978]  [<c10cc372>] ? vfs_unlink+0x55/0xa5
[639517.522980]  [<c10ce277>] ? do_unlinkat+0xa9/0x11a
[639517.522984]  [<c10c36be>] ? sys_faccessat+0x146/0x153
[639517.522986]  [<c12a9d5f>] ? sysenter_do_call+0x12/0x28
[639517.522989]  [<c12a0000>] ? native_cpu_up+0x422/0x5db
[639517.523000] INFO: task firefox-bin:2408 blocked for more than 120 seconds.
[639517.523002] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[639517.523003] firefox-bin     D 02f02067     0  2408      1 0x00000000
[639517.523006]  d80914a0 00200086 00000000 02f02067 00000000 00000000 f282474c 31fad000
[639517.523010]  f2824680 c1459900 d809164c c1459900 d80914a0 c1459900 c1459900 c1057db5
[639517.523013]  f0c47bd0 d7523578 d7523738 e9b38e00 ee513850 c4c6de38 efb4a498 eb01a0e0
[639517.523017] Call Trace:
[639517.523020]  [<c1057db5>] ? clockevents_program_event+0xd2/0xe4
[639517.523022]  [<c10531ec>] ? timekeeping_get_ns+0x10/0x48
[639517.523025]  [<c1054421>] ? ktime_get_ts+0x76/0x7d
[639517.523027]  [<c12a380a>] ? io_schedule+0x6c/0xa4
[639517.523029]  [<c10e1c0f>] ? sleep_on_buffer+0x5/0x8
[639517.523032]  [<c12a3b6d>] ? __wait_on_bit+0x31/0x56
[639517.523034]  [<c10e1c0a>] ? unmap_underlying_metadata+0x41/0x41
[639517.523037]  [<c10e1c0a>] ? unmap_underlying_metadata+0x41/0x41
[639517.523039]  [<c12a3c2d>] ? out_of_line_wait_on_bit+0x9b/0xa3
[639517.523041]  [<c104c983>] ? autoremove_wake_function+0x29/0x29
[639517.523044]  [<c10e1baf>] ? __wait_on_buffer+0x18/0x1a
[639517.523049]  [<f8a9fe14>] ? ext4_find_entry+0x278/0x354 [ext4]
[639517.523052]  [<c10c0ad2>] ? kmem_cache_alloc+0x21/0xd9
[639517.523055]  [<c10d20c0>] ? d_alloc+0x1b/0x136
[639517.523060]  [<f8a9ff14>] ? ext4_lookup+0x24/0xac [ext4]
[639517.523063]  [<c10cb7f6>] ? d_alloc_and_lookup+0x35/0x4b
[639517.523065]  [<c10cd034>] ? do_last+0x180/0x520
[639517.523069]  [<c11168d3>] ? security_file_alloc+0xc/0xd
[639517.523071]  [<c10cd855>] ? path_openat+0x97/0x27d
[639517.523073]  [<c10cdadf>] ? do_filp_open+0x21/0x5d
[639517.523076]  [<c10c0ad2>] ? kmem_cache_alloc+0x21/0xd9
[639517.523078]  [<c10cbd43>] ? getname_flags+0x24/0xd5
[639517.523081]  [<c10c2f57>] ? do_sys_open+0x58/0xd1
[639517.523083]  [<c10c3014>] ? sys_open+0x1e/0x23
[639517.523085]  [<c12a9d5f>] ? sysenter_do_call+0x12/0x28
[639517.523088]  [<c12a0000>] ? native_cpu_up+0x422/0x5db
[639517.523099] INFO: task flush-254:1:7092 blocked for more than 120 seconds.
[639517.523101] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[639517.523102] flush-254:1     D 0002457a     0  7092      2 0x00000000
[639517.523105]  e82856a0 00000046 0d6efe63 0002457a 03580004 00000000 0002457a 0001c7c8
[639517.523108]  00000000 c1459900 e828584c c1459900 e82856a0 c1459900 c1459900 c10e124c
[639517.523112]  0000000d e2567ea8 ee513818 e3128188 ee513850 c4c6de38 efb4a498 eb01a0e0
[639517.523116] Call Trace:
[639517.523118]  [<c10e124c>] ? __find_get_block+0x14d/0x157
[639517.523121]  [<c10e1281>] ? __getblk+0x2b/0x30d
[639517.523123]  [<c104cacc>] ? prepare_to_wait+0x14/0x52
[639517.523127]  [<f8a1458c>] ? do_get_write_access+0x196/0x30d [jbd2]
[639517.523129]  [<c104c983>] ? autoremove_wake_function+0x29/0x29
[639517.523133]  [<f8a1471b>] ? jbd2_journal_get_write_access+0x18/0x26 [jbd2]
[639517.523139]  [<f8ab58e2>] ? __ext4_journal_get_write_access+0x3f/0x47 [ext4]
[639517.523146]  [<f8ab72ae>] ? ext4_mb_mark_diskspace_used+0x5c/0x2ed [ext4]
[639517.523153]  [<f8abbee4>] ? ext4_mb_new_blocks+0x202/0x3d6 [ext4]
[639517.523159]  [<f8ab1e21>] ? ext4_ext_find_extent+0x35/0x295 [ext4]
[639517.523166]  [<f8ab4bd9>] ? ext4_ext_map_blocks+0xef9/0x124b [ext4]
[639517.523169]  [<c10977d2>] ? mempool_alloc+0x44/0xe8
[639517.523172]  [<c1149ece>] ? radix_tree_gang_lookup_tag_slot+0x6e/0x8e
[639517.523179]  [<f8a9a8a3>] ? ext4_map_blocks+0xdd/0x15a [ext4]
[639517.523184]  [<f8a9b09a>] ? mpage_da_map_and_submit+0x8c/0x375 [ext4]
[639517.523190]  [<f8a9baed>] ? ext4_da_writepages+0x262/0x3aa [ext4]
[639517.523193]  [<c109be36>] ? do_writepages+0x14/0x20
[639517.523197]  [<c10dc4ab>] ? writeback_single_inode+0xa0/0x192
[639517.523200]  [<c10dc752>] ? writeback_sb_inodes+0x9e/0xfb
[639517.523202]  [<c10dca5f>] ? writeback_inodes_wb+0xc8/0xd8
[639517.523204]  [<c10dd02d>] ? wb_writeback+0x1c7/0x28c
[639517.523207]  [<c10dd221>] ? wb_do_writeback+0x12f/0x19c
[639517.523209]  [<c10dd32b>] ? bdi_writeback_thread+0x9d/0x1aa
[639517.523211]  [<c10dd28e>] ? wb_do_writeback+0x19c/0x19c
[639517.523212]  [<c104c610>] ? kthread+0x63/0x68
[639517.523214]  [<c104c5ad>] ? kthread_worker_fn+0x114/0x114
[639517.523216]  [<c12aa2fe>] ? kernel_thread_helper+0x6/0x10
[639517.523228] INFO: task exim4:13389 blocked for more than 120 seconds.
...

Does the SMART error mean the disk is just crap?
Comment 7 Mikko Rapeli 2012-02-22 07:54:18 UTC
Right after poweroff and reboot the disk is back to normal again, for a few hours I hope:

# time ( dd if=/dev/sda of=/dev/zero iflag=dire
ct bs=1M count=100 )
100+0 records in
100+0 records out
104857600 bytes (105 MB) copied, 1.00901 s, 104 MB/s

real    0m1.012s
user    0m0.004s
sys     0m0.016s

# hdparm -i /dev/sda

/dev/sda:

 Model=ST320LT007-9ZV142, FwRev=0004LVM1, SerialNo=W0Q1FL5R
 Config={ HardSect NotMFM HdSw>15uSec Fixed DTR>10Mbs RotSpdTol>.5% }
 RawCHS=16383/16/63, TrkSize=0, SectSize=0, ECCbytes=4
 BuffType=unknown, BuffSize=16384kB, MaxMultSect=16, MultSect=16
 CurCHS=65535/1/63, CurSects=4128705, LBA=yes, LBAsects=625142448
 IORDY=on/off, tPIO={min:120,w/IORDY:120}, tDMA={min:120,rec:120}
 PIO modes:  pio0 pio1 pio2 pio3 pio4
 DMA modes:  mdma0 mdma1 mdma2
 UDMA modes: udma0 udma1 udma2 udma3 udma4 udma5 *udma6
 AdvancedPM=yes: unknown setting WriteCache=enabled
 Drive conforms to: unknown:  ATA/ATAPI-3,4,5,6,7

 * signifies the current active mode
Comment 8 Alan 2012-05-12 02:38:27 UTC
It could be

The kernel doesn't itself send SMART commands - try disabling palimpset, smartutils or whatever you distro uses. If that makes the difference then let the mantainers of the apps know that you've got another drive they may need to blacklist