FAQ Search Today's Posts Mark Forums Read
» Video Reviews

» Linux Archive

Linux-archive is a website aiming to archive linux email lists and to make them easily accessible for linux users/developers.


» Sponsor

» Partners

» Sponsor

Go Back   Linux Archive > Debian > Debian Kernel

 
 
LinkBack Thread Tools
 
Old 06-07-2010, 09:53 AM
Ian Jackson
 
Default Bug#584881: Lockups under heavy disk IO; md (RAID) resync/check implicated

Package: linux-image-2.6.26-2-686-bigmem
Version: 2.6.26-21lenny4

I keep getting soft lockups; the symptoms appear to be that user
processes become deadlocked when they try to access the disk, but the
kernel doesn't notice that anything is wrong.

It appears that the lockups happen when:
(a) my software (mdadm) RAID mirror is resyncing or checking
(b) some other program does heavy disk IO

I'm currently trying to work around the problem by disabling the
system's backups (which are a prime trigger in category (b)) until the
post-crash mirror resync is complete, combined with setting the sysctl
dev.raid.speed_limit_max to 1000. Just disabling the backups wasn't
sufficient because, it seems, various recovery tasks in the most
recent crash are sufficient to trigger the bug.

I observe that the message from the md driver, and the presence of the
sysctls dev.raid.speed_limit_{min,max}, suggest that the md driver is
using a fundamentally incorrect algorithm which depends on guessing
the available IO bandwidth.


Actual hard data:

* chiark locked up at 0355 on the 2nd of May. It did so shortly after
the backups start. chiark's backups are done with LVM snapshots and
rsync. I don't any more have information about exactly at what
stage the backups were at.

* chiark locked up again at 0355 on Sunday morning the 6th of June.
In this case I was able to see that the system had successfully
created and mounted the LVM snapshot as the rsync process on the
backup master system was still present.

* Note that both these two crashes happened on the 1st Sunday of the
month. Investigating the kernel logs for the 2nd crash show this:
Jun 6 00:57:01 chiark kernel: [3250794.079478] md: data-check of RAID array md127
Jun 6 00:57:01 chiark kernel: [3250794.079479] md: minimum _guaranteed_ speed: 1000 KB/sec/disk.
Jun 6 00:57:01 chiark kernel: [3250794.079479] md: using maximum available idle IO bandwidth (but not more than 200000 KB/sec) for data-check.
Jun 6 00:57:01 chiark kernel: [3250794.079479] md: using 128k window, over a total of 222297980 blocks.
However there is no sign of it completing.

* Shortly after I power cycled the system to get it back up, it locked
up again. At that point, the RAID was doing a post-crash resync,
and the crash happened at the point where the backup master
attempted to start on the next partition.

* Some research dug up some reports of first-Sunday-of-the-month
crashes associated with RAID integrity checks.[1] So I tried setting
the max IO bandwidth sysctl to the lowest reasonable value (by hand)
and left the system running. However, it locked up again as the
backups started.

* I power cycled the machine again and disabled the backups and made
sure they were truly stopped. However chiark locked up again mere
minutes after coming back up.

* I have now power cycled chiark once more and this time I set the
max IO bandwidth sysctl. So far it seems to have stayed up for
about half an hour.

If nothing more goes wrong I intend to leave the backups disabled
until the RAID finishes its resync, which we can expect to be some
time on Wednesday night.


chiark is running LVM-on-MD-on-LVM. So the two "disks" which form the
mirror which is resyncing are actually LVM LVs, and that mirror is
itself an LVM PV. The underlying hardware is a Dell R210 with two
WD SATA disks (WD7500AYPS-0).


[1] https://bugs.launchpad.net/ubuntu/+source/linux/+bug/212684
seems relevant for example.


Ian.


lvs:

LV VG Attr LSize Origin Snap% Move Log Copy% Convert
mirror-base chiark-early-a -wi-ao 400.00G
stripe-base chiark-early-a -wi-ao 52.00G
swap chiark-early-a -wi-ao 4.00G
mirror-base chiark-early-b -wi-ao 400.00G
stripe-base chiark-early-b -wi-ao 52.00G
swap chiark-early-b -wi-ao 4.00G
lv-quicksand vg-chiark-stripe -wi-ao 40.00G
twomack-relations vg-chiark-stripe -wi-ao 60.00G
lv-log vg-main -wi-ao 3.00G
lv-mail vg-main -wi-ao 3.00G
lv-news vg-main -wi-ao 15.94G
lv-root vg-main -wi-ao 1.00G
lv-u vg-main -wi-ao 9.75G
lv-u2 vg-main -wi-ao 12.25G
lv-u3 vg-main -wi-ao 7.06G
lv-usr vg-main -wi-ao 4.12G
lv-var vg-main -wi-ao 5.94G
lv-volt vg-main -wi-ao 77.44G


pvs:

PV VG Fmt Attr PSize PFree
/dev/md_chiark-mirror vg-main lvm2 a- 211.94G 72.44G
/dev/md_chiark-stripe vg-chiark-stripe lvm2 a- 103.94G 3.94G
/dev/sdb2 chiark-early-a lvm2 a- 464.00G 8.00G
/dev/sdc2 chiark-early-b lvm2 a- 464.00G 8.00G


/proc/mdstat:

Personalities : [raid0] [raid1]
md126 : active raid0 dm-2[0] dm-5[1]
109051776 blocks super 1.1 64k chunks

md127 : active raid1 dm-0[3] dm-3[2]
222297980 blocks super 1.1 [2/2] [UU]
[>....................] resync = 0.9% (2014848/222297980) finish=3659.9min speed=1000K/sec


mdadm -D -vv --scan:

/dev/md127:
Version : 01.01
Creation Time : Sat Mar 6 20:06:57 2010
Raid Level : raid1
Array Size : 222297980 (212.00 GiB 227.63 GB)
Used Dev Size : 444595960 (424.00 GiB 455.27 GB)
Raid Devices : 2
Total Devices : 2
Preferred Minor : 127
Persistence : Superblock is persistent

Update Time : Mon Jun 7 10:13:05 2010
State : active, resyncing
Active Devices : 2
Working Devices : 2
Failed Devices : 0
Spare Devices : 0

Rebuild Status : 0% complete

Name : chiark:chiark-mirror (local to host chiark)
UUID : [***]
Events : 9033

Number Major Minor RaidDevice State
3 254 0 0 active sync /dev/dm-0
2 254 3 1 active sync /dev/dm-3
/dev/md126:
Version : 01.01
Creation Time : Thu Mar 11 13:52:05 2010
Raid Level : raid0
Array Size : 109051776 (104.00 GiB 111.67 GB)
Raid Devices : 2
Total Devices : 2
Preferred Minor : 126
Persistence : Superblock is persistent

Update Time : Mon Jun 7 10:47:15 2010
State : active
Active Devices : 2
Working Devices : 2
Failed Devices : 0
Spare Devices : 0

Chunk Size : 64K

Name : chiark:chiark-stripe (local to host chiark)
UUID : [***]
Events : 5

Number Major Minor RaidDevice State
0 254 2 0 active sync /dev/dm-2
1 254 5 1 active sync /dev/dm-5

brw-r----- 1 root disk 254, 0 Jun 7 10:13 /dev/dm-0
brw-r----- 1 root disk 254, 1 Jun 7 10:13 /dev/dm-1
brw-r----- 1 root disk 254, 2 Jun 7 10:13 /dev/dm-2
brw-r----- 1 root disk 254, 3 Jun 7 10:13 /dev/dm-3
brw-r----- 1 root disk 254, 4 Jun 7 10:13 /dev/dm-4
brw-r----- 1 root disk 254, 5 Jun 7 10:13 /dev/dm-5
brw-r----- 1 root disk 254, 6 Jun 7 10:13 /dev/dm-6
brw-r----- 1 root disk 254, 7 Jun 7 10:13 /dev/dm-7
brw-r----- 1 root disk 254, 8 Jun 7 10:13 /dev/dm-8

/dev/mapper/:
total 0
drwxr-xr-x 2 root root 420 Jun 7 10:43 ./
drwxr-xr-x 19 root root 3840 Jun 7 10:43 ../
brw-rw---- 1 root disk 254, 0 Jun 7 10:13 chiark--early--a-mirror--base
brw-rw---- 1 root disk 254, 2 Jun 7 10:13 chiark--early--a-stripe--base
brw-rw---- 1 root disk 254, 1 Jun 7 10:13 chiark--early--a-swap
brw-rw---- 1 root disk 254, 3 Jun 7 10:13 chiark--early--b-mirror--base
brw-rw---- 1 root disk 254, 5 Jun 7 10:13 chiark--early--b-stripe--base
brw-rw---- 1 root disk 254, 4 Jun 7 10:13 chiark--early--b-swap
crw-rw---- 1 root root 10, 60 Jun 7 10:13 control
brw-rw---- 1 root disk 254, 20 Jun 7 10:13 vg--chiark--stripe-lv--quicksand
brw-rw---- 1 root disk 254, 19 Jun 7 10:13 vg--chiark--stripe-twomack--relations
brw-rw---- 1 root disk 254, 6 Jun 7 10:13 vg--main-lv--log
brw-rw---- 1 root disk 254, 7 Jun 7 10:13 vg--main-lv--mail
brw-rw---- 1 root disk 254, 8 Jun 7 10:13 vg--main-lv--news
brw-rw---- 1 root disk 254, 18 Jun 7 10:13 vg--main-lv--root
brw-rw---- 1 root disk 254, 10 Jun 7 10:13 vg--main-lv--u
brw-rw---- 1 root disk 254, 13 Jun 7 10:13 vg--main-lv--u2
brw-rw---- 1 root disk 254, 14 Jun 7 10:13 vg--main-lv--u3
brw-rw---- 1 root disk 254, 15 Jun 7 10:13 vg--main-lv--usr
brw-rw---- 1 root disk 254, 16 Jun 7 10:13 vg--main-lv--var
brw-rw---- 1 root disk 254, 17 Jun 7 10:13 vg--main-lv--volt

[ 0.000000] Initializing cgroup subsys cpuset
[ 0.000000] Initializing cgroup subsys cpu
[ 0.000000] Linux version 2.6.26-2-686-bigmem (Debian 2.6.26-21lenny4) (dannf@debian.org) (gcc version 4.1.3 20080704 (prerelease) (Debian 4.1.2-25)) #1 SMP Tue Mar 9 18:01:52 UTC 2010
[ 0.000000] BIOS-provided physical RAM map:
[ 0.000000] BIOS-e820: 0000000000000000 - 000000000009d000 (usable)
[ 0.000000] BIOS-e820: 0000000000100000 - 00000000bf699000 (usable)
[ 0.000000] BIOS-e820: 00000000bf699000 - 00000000bf6af000 (reserved)
[ 0.000000] BIOS-e820: 00000000bf6af000 - 00000000bf6ce000 (ACPI data)
[ 0.000000] BIOS-e820: 00000000bf6ce000 - 00000000c0000000 (reserved)
[ 0.000000] BIOS-e820: 00000000e0000000 - 00000000f0000000 (reserved)
[ 0.000000] BIOS-e820: 00000000fe000000 - 0000000100000000 (reserved)
[ 0.000000] BIOS-e820: 0000000100000000 - 0000000140000000 (usable)
[ 0.000000] 4224MB HIGHMEM available.
[ 0.000000] 896MB LOWMEM available.
[ 0.000000] found SMP MP-table at [c00fe710] 000fe710
[ 0.000000] NX (Execute Disable) protection: active
[ 0.000000] Entering add_active_range(0, 0, 1310720) 0 entries of 256 used
[ 0.000000] Zone PFN ranges:
[ 0.000000] DMA 0 -> 4096
[ 0.000000] Normal 4096 -> 229376
[ 0.000000] HighMem 229376 -> 1310720
[ 0.000000] Movable zone start PFN for each node
[ 0.000000] early_node_map[1] active PFN ranges
[ 0.000000] 0: 0 -> 1310720
[ 0.000000] On node 0 totalpages: 1310720
[ 0.000000] DMA zone: 32 pages used for memmap
[ 0.000000] DMA zone: 0 pages reserved
[ 0.000000] DMA zone: 4064 pages, LIFO batch:0
[ 0.000000] Normal zone: 1760 pages used for memmap
[ 0.000000] Normal zone: 223520 pages, LIFO batch:31
[ 0.000000] HighMem zone: 8448 pages used for memmap
[ 0.000000] HighMem zone: 1072896 pages, LIFO batch:31
[ 0.000000] Movable zone: 0 pages used for memmap
[ 0.000000] DMI 2.6 present.
[ 0.000000] Using APIC driver default
[ 0.000000] ACPI: RSDP 000F0B40, 0024 (r2 DELL )
[ 0.000000] ACPI: XSDT 000F0C40, 0094 (r1 DELL PE_SC3 1 DELL 1)
[ 0.000000] ACPI: FACP BF6C3BB4, 00F4 (r3 DELL PE_SC3 1 DELL 1)
[ 0.000000] ACPI: DSDT BF6AF000, 398C (r1 DELL PE_SC3 1 INTL 20050624)
[ 0.000000] ACPI: FACS BF6C6000, 0040
[ 0.000000] ACPI: APIC BF6C3478, 0152 (r1 DELL PE_SC3 1 DELL 1)
[ 0.000000] ACPI: SPCR BF6C35CC, 0050 (r1 DELL PE_SC3 1 DELL 1)
[ 0.000000] ACPI: HPET BF6C3620, 0038 (r1 DELL PE_SC3 1 DELL 1)
[ 0.000000] ACPI: DM__ BF6C365C, 00A8 (r1 DELL PE_SC3 1 DELL 1)
[ 0.000000] ACPI: MCFG BF6C3850, 003C (r1 DELL PE_SC3 1 DELL 1)
[ 0.000000] ACPI: WD__ BF6C3890, 0134 (r1 DELL PE_SC3 1 DELL 1)
[ 0.000000] ACPI: SLIC BF6C39C8, 0024 (r1 DELL PE_SC3 1 DELL 1)
[ 0.000000] ACPI: ERST BF6B2B0C, 0270 (r1 DELL PE_SC3 1 DELL 1)
[ 0.000000] ACPI: HEST BF6B2D7C, 03A8 (r1 DELL PE_SC3 1 DELL 1)
[ 0.000000] ACPI: BERT BF6B298C, 0030 (r1 DELL PE_SC3 1 DELL 1)
[ 0.000000] ACPI: EINJ BF6B29BC, 0150 (r1 DELL PE_SC3 1 DELL 1)
[ 0.000000] ACPI: TCPA BF6C3B4C, 0064 (r2 DELL PE_SC3 1 DELL 1)
[ 0.000000] ACPI: SSDT BF6C7000, 2164 (r1 INTEL PPM RCM 80000001 INTL 20061109)
[ 0.000000] ACPI: PM-Timer IO Port: 0x808
[ 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[0x02] enabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x03] lapic_id[0x04] enabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x04] lapic_id[0x06] enabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x05] lapic_id[0x01] enabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x06] lapic_id[0x03] enabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x07] lapic_id[0x05] enabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x08] lapic_id[0x07] enabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x09] lapic_id[0x28] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x0a] lapic_id[0x29] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x0b] lapic_id[0x2a] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x0c] lapic_id[0x2b] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x0d] lapic_id[0x2c] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x0e] lapic_id[0x2d] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x0f] lapic_id[0x2e] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x10] lapic_id[0x2f] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x11] lapic_id[0x30] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x12] lapic_id[0x31] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x13] lapic_id[0x32] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x14] lapic_id[0x33] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x15] lapic_id[0x34] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x16] lapic_id[0x35] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x17] lapic_id[0x36] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x18] lapic_id[0x37] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x19] lapic_id[0x38] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x1a] lapic_id[0x39] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x1b] lapic_id[0x3a] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x1c] lapic_id[0x3b] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x1d] lapic_id[0x3c] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x1e] lapic_id[0x3d] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x1f] lapic_id[0x3e] disabled)
[ 0.000000] ACPI: LAPIC (acpi_id[0x20] lapic_id[0x3f] disabled)
[ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] high edge lint[0x1])
[ 0.000000] ACPI: IOAPIC (id[0x00] address[0xfec00000] gsi_base[0])
[ 0.000000] IOAPIC[0]: apic_id 0, 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] Enabling APIC mode: Flat. Using 1 I/O APICs
[ 0.000000] ACPI: HPET id: 0x8086a701 base: 0xfed00000
[ 0.000000] Using ACPI (MADT) for SMP configuration information
[ 0.000000] Allocating PCI resources starting at c2000000 (gap: c0000000:20000000)
[ 0.000000] PM: Registered nosave memory: 000000000009d000 - 0000000000100000
[ 0.000000] SMP: Allowing 32 CPUs, 24 hotplug CPUs
[ 0.000000] PERCPU: Allocating 42184 bytes of per cpu data
[ 0.000000] NR_CPUS: 32, nr_cpu_ids: 32
[ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 1300480
[ 0.000000] Kernel command line: ro root=/dev/vg-main/lv-root console=tty0 console=ttyS0,9600n8 TERM=dumb reboot=bios,smp,warm
[ 0.000000] mapped APIC to ffffb000 (fee00000)
[ 0.000000] mapped IOAPIC to ffffa000 (fec00000)
[ 0.000000] Enabling fast FPU save and restore... done.
[ 0.000000] Enabling unmasked SIMD FPU exception support... done.
[ 0.000000] Initializing CPU#0
[ 0.000000] PID hash table entries: 4096 (order: 12, 16384 bytes)
[ 0.000000] Extended CMOS year: 2000
[ 0.000000] Detected 1862.111 MHz processor.
[ 0.004000] Console: colour VGA+ 80x25
[ 0.004000] console [tty0] enabled
[ 0.004000] console [ttyS0] enabled
[ 0.004000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[ 0.004000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[ 0.004000] Memory: 4130168k/5242880k available (1836k kernel code, 53248k reserved, 790k data, 256k init, 3267172k highmem)
[ 0.004000] virtual kernel memory layout:
[ 0.004000] fixmap : 0xffe13000 - 0xfffff000 (1968 kB)
[ 0.004000] pkmap : 0xffa00000 - 0xffc00000 (2048 kB)
[ 0.004000] vmalloc : 0xf8800000 - 0xff9fe000 ( 113 MB)
[ 0.004000] lowmem : 0xc0000000 - 0xf8000000 ( 896 MB)
[ 0.004000] .init : 0xc0399000 - 0xc03d9000 ( 256 kB)
[ 0.004000] .data : 0xc02cb06d - 0xc0390ac0 ( 790 kB)
[ 0.004000] .text : 0xc0100000 - 0xc02cb06d (1836 kB)
[ 0.004000] Checking if this processor honours the WP bit even in supervisor mode...Ok.
[ 0.004000] CPA: page pool initialized 1 of 1 pages preallocated
[ 0.004000] hpet clockevent registered
[ 0.083864] Calibrating delay using timer specific routine.. 3727.45 BogoMIPS (lpj=7454918)
[ 0.092005] Security Framework initialized
[ 0.096006] SELinux: Disabled at boot.
[ 0.100006] Capability LSM initialized
[ 0.104006] Mount-cache hash table entries: 512
[ 0.108006] Initializing cgroup subsys ns
[ 0.112007] Initializing cgroup subsys cpuacct
[ 0.116007] Initializing cgroup subsys devices
[ 0.120007] CPU: L1 I cache: 32K, L1 D cache: 32K
[ 0.128008] CPU: L2 cache: 256K
[ 0.132008] CPU: L3 cache: 8192K
[ 0.136008] CPU: Physical Processor ID: 0
[ 0.140008] CPU: Processor Core ID: 0
[ 0.144009] Intel machine check architecture supported.
[ 0.148009] Intel machine check reporting enabled on CPU#0.
[ 0.152009] using mwait in idle threads.
[ 0.156009] Checking 'hlt' instruction... OK.
[ 0.180011] ACPI: Core revision 20080321
[ 0.188011] ENABLING IO-APIC IRQs
[ 0.192012] ..TIMER: vector=0x31 apic1=0 pin1=2 apic2=-1 pin2=-1
[ 0.235662] CPU0: Intel(R) Xeon(R) CPU L3426 @ 1.87GHz stepping 05
[ 0.248015] Booting processor 1/2 ip 6000
[ 0.260016] Initializing CPU#1
[ 0.260016] Calibrating delay using timer specific routine.. 3723.81 BogoMIPS (lpj=7447620)
[ 0.260016] CPU: L1 I cache: 32K, L1 D cache: 32K
[ 0.260016] CPU: L2 cache: 256K
[ 0.260016] CPU: L3 cache: 8192K
[ 0.260016] CPU: Physical Processor ID: 0
[ 0.260016] CPU: Processor Core ID: 1
[ 0.260016] Intel machine check architecture supported.
[ 0.260016] Intel machine check reporting enabled on CPU#1.
[ 0.340021] CPU1: Intel(R) Xeon(R) CPU L3426 @ 1.87GHz stepping 05
[ 0.352022] checking TSC synchronization [CPU#0 -> CPU#1]: passed.
[ 0.356022] Booting processor 2/4 ip 6000
[ 0.372023] Initializing CPU#2
[ 0.372023] Calibrating delay using timer specific routine.. 3723.81 BogoMIPS (lpj=7447631)
[ 0.372023] CPU: L1 I cache: 32K, L1 D cache: 32K
[ 0.372023] CPU: L2 cache: 256K
[ 0.372023] CPU: L3 cache: 8192K
[ 0.372023] CPU: Physical Processor ID: 0
[ 0.372023] CPU: Processor Core ID: 2
[ 0.372023] Intel machine check architecture supported.
[ 0.372023] Intel machine check reporting enabled on CPU#2.
[ 0.448857] CPU2: Intel(R) Xeon(R) CPU L3426 @ 1.87GHz stepping 05
[ 0.464029] checking TSC synchronization [CPU#0 -> CPU#2]: passed.
[ 0.468029] Booting processor 3/6 ip 6000
[ 0.484030] Initializing CPU#3
[ 0.484030] Calibrating delay using timer specific routine.. 3723.81 BogoMIPS (lpj=7447636)
[ 0.484030] CPU: L1 I cache: 32K, L1 D cache: 32K
[ 0.484030] CPU: L2 cache: 256K
[ 0.484030] CPU: L3 cache: 8192K
[ 0.484030] CPU: Physical Processor ID: 0
[ 0.484030] CPU: Processor Core ID: 3
[ 0.484030] Intel machine check architecture supported.
[ 0.484030] Intel machine check reporting enabled on CPU#3.
[ 0.560779] CPU3: Intel(R) Xeon(R) CPU L3426 @ 1.87GHz stepping 05
[ 0.576031] checking TSC synchronization [CPU#0 -> CPU#3]: passed.
[ 0.580031] Booting processor 4/1 ip 6000
[ 0.596037] Initializing CPU#4
[ 0.596037] Calibrating delay using timer specific routine.. 3723.80 BogoMIPS (lpj=7447615)
[ 0.596037] CPU: L1 I cache: 32K, L1 D cache: 32K
[ 0.596037] CPU: L2 cache: 256K
[ 0.596037] CPU: L3 cache: 8192K
[ 0.596037] CPU: Physical Processor ID: 0
[ 0.596037] CPU: Processor Core ID: 0
[ 0.596037] Intel machine check architecture supported.
[ 0.596037] Intel machine check reporting enabled on CPU#4.
[ 0.672947] CPU4: Intel(R) Xeon(R) CPU L3426 @ 1.87GHz stepping 05
[ 0.688031] checking TSC synchronization [CPU#0 -> CPU#4]: passed.
[ 0.692031] Booting processor 5/3 ip 6000
[ 0.708044] Initializing CPU#5
[ 0.708044] Calibrating delay using timer specific routine.. 3723.81 BogoMIPS (lpj=7447627)
[ 0.708044] CPU: L1 I cache: 32K, L1 D cache: 32K
[ 0.708044] CPU: L2 cache: 256K
[ 0.708044] CPU: L3 cache: 8192K
[ 0.708044] CPU: Physical Processor ID: 0
[ 0.708044] CPU: Processor Core ID: 1
[ 0.708044] Intel machine check architecture supported.
[ 0.708044] Intel machine check reporting enabled on CPU#5.
[ 0.784980] CPU5: Intel(R) Xeon(R) CPU L3426 @ 1.87GHz stepping 05
[ 0.800038] checking TSC synchronization [CPU#0 -> CPU#5]: passed.
[ 0.804038] Booting processor 6/5 ip 6000
[ 0.820051] Initializing CPU#6
[ 0.820051] Calibrating delay using timer specific routine.. 3723.81 BogoMIPS (lpj=7447636)
[ 0.820051] CPU: L1 I cache: 32K, L1 D cache: 32K
[ 0.820051] CPU: L2 cache: 256K
[ 0.820051] CPU: L3 cache: 8192K
[ 0.820051] CPU: Physical Processor ID: 0
[ 0.820051] CPU: Processor Core ID: 2
[ 0.820051] Intel machine check architecture supported.
[ 0.820051] Intel machine check reporting enabled on CPU#6.
[ 0.896887] CPU6: Intel(R) Xeon(R) CPU L3426 @ 1.87GHz stepping 05
[ 0.912044] checking TSC synchronization [CPU#0 -> CPU#6]: passed.
[ 0.916044] Booting processor 7/7 ip 6000
[ 0.932058] Initializing CPU#7
[ 0.932058] Calibrating delay using timer specific routine.. 3723.81 BogoMIPS (lpj=7447631)
[ 0.932058] CPU: L1 I cache: 32K, L1 D cache: 32K
[ 0.932058] CPU: L2 cache: 256K
[ 0.932058] CPU: L3 cache: 8192K
[ 0.932058] CPU: Physical Processor ID: 0
[ 0.932058] CPU: Processor Core ID: 3
[ 0.932058] Intel machine check architecture supported.
[ 0.932058] Intel machine check reporting enabled on CPU#7.
[ 1.008795] CPU7: Intel(R) Xeon(R) CPU L3426 @ 1.87GHz stepping 05
[ 1.024052] checking TSC synchronization [CPU#0 -> CPU#7]: passed.
[ 1.028052] Brought up 8 CPUs
[ 1.032052] Total of 8 processors activated (29794.15 BogoMIPS).
[ 1.036052] CPU0 attaching sched-domain:
[ 1.036052] domain 0: span 0,4
[ 1.036052] groups: 0 4
[ 1.036052] domain 1: span 0-7
[ 1.036052] groups: 0,4 1,5 2,6 3,7
[ 1.036052] CPU1 attaching sched-domain:
[ 1.036052] domain 0: span 1,5
[ 1.036052] groups: 1 5
[ 1.036052] domain 1: span 0-7
[ 1.036052] groups: 1,5 2,6 3,7 0,4
[ 1.036052] CPU2 attaching sched-domain:
[ 1.036052] domain 0: span 2,6
[ 1.036052] groups: 2 6
[ 1.036052] domain 1: span 0-7
[ 1.036052] groups: 2,6 3,7 0,4 1,5
[ 1.036052] CPU3 attaching sched-domain:
[ 1.036052] domain 0: span 3,7
[ 1.036052] groups: 3 7
[ 1.036052] domain 1: span 0-7
[ 1.036052] groups: 3,7 0,4 1,5 2,6
[ 1.036052] CPU4 attaching sched-domain:
[ 1.036052] domain 0: span 0,4
[ 1.036052] groups: 4 0
[ 1.036052] domain 1: span 0-7
[ 1.036052] groups: 0,4 1,5 2,6 3,7
[ 1.036052] CPU5 attaching sched-domain:
[ 1.036052] domain 0: span 1,5
[ 1.036052] groups: 5 1
[ 1.036052] domain 1: span 0-7
[ 1.036052] groups: 1,5 2,6 3,7 0,4
[ 1.036052] CPU6 attaching sched-domain:
[ 1.036052] domain 0: span 2,6
[ 1.036052] groups: 6 2
[ 1.036052] domain 1: span 0-7
[ 1.036052] groups: 2,6 3,7 0,4 1,5
[ 1.036052] CPU7 attaching sched-domain:
[ 1.036052] domain 0: span 3,7
[ 1.036052] groups: 7 3
[ 1.036052] domain 1: span 0-7
[ 1.036052] groups: 3,7 0,4 1,5 2,6
[ 1.036052] net_namespace: 660 bytes
[ 1.040060] Booting paravirtualized kernel on bare hardware
[ 1.044060] NET: Registered protocol family 16
[ 1.048060] ACPI FADT declares the system doesn't support PCIe ASPM, so disable it
[ 1.055393] ACPI: bus type pci registered
[ 1.059393] PCI: MCFG configuration 0: base e0000000 segment 0 buses 0 - 255
[ 1.063393] PCI: MCFG area at e0000000 reserved in E820
[ 1.067393] PCI: Using MMCONFIG for extended config space
[ 1.071393] PCI: Using configuration type 1 for base access
[ 1.075393] Setting up standard PCI resources
[ 1.079393] ACPI: EC: Look up EC in DSDT
[ 1.084794] ACPI: BIOS _OSI(Linux) query ignored
[ 1.091030] ACPI: DMI System Vendor: Dell Inc.
[ 1.095030] ACPI: DMI Product Name: PowerEdge R210
[ 1.099030] ACPI: DMI Product Version:
[ 1.103030] ACPI: DMI Board Name: 0M877N
[ 1.107030] ACPI: DMI BIOS Vendor: Dell Inc.
[ 1.111032] ACPI: DMI BIOS Date: 10/30/2009
[ 1.115032] ACPI: Please send DMI info above to linux-acpi@vger.kernel.org
[ 1.119032] ACPI: If "acpi_osi=Linux" works better, please notify linux-acpi@vger.kernel.org
[ 1.123033] ACPI: Interpreter enabled
[ 1.127033] ACPI: (supports S0 S4 S5)
[ 1.139034] ACPI: Using IOAPIC for interrupt routing
[ 1.150844] ACPI: PCI Root Bridge [PCI0] (0000:00)
[ 1.158836] PCI: Transparent bridge - 0000:00:1e.0
[ 1.166131] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
[ 1.166131] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.LYD0._PRT]
[ 1.166131] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PEX0._PRT]
[ 1.166131] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.COMP._PRT]
[ 1.170131] ACPI: PCI Interrupt Link [LK00] (IRQs 3 4 5 6 7 10 11 14 *15)
[ 1.200049] ACPI: PCI Interrupt Link [LK01] (IRQs 3 4 5 6 7 10 11 14 15) *0, disabled.
[ 1.239241] ACPI: PCI Interrupt Link [LK02] (IRQs 3 4 5 6 7 10 11 14 15) *0, disabled.
[ 1.281507] ACPI: PCI Interrupt Link [LK03] (IRQs 3 4 5 6 7 *10 11 14 15)
[ 1.313679] ACPI: PCI Interrupt Link [LK04] (IRQs 3 4 5 6 7 10 *11 14 15)
[ 1.345937] ACPI: PCI Interrupt Link [LK05] (IRQs 3 4 5 6 7 10 11 14 15) *0, disabled.
[ 1.384679] ACPI: PCI Interrupt Link [LK06] (IRQs 3 4 5 6 7 10 11 *14 15)
[ 1.420582] ACPI: PCI Interrupt Link [LK07] (IRQs 3 4 5 6 7 10 11 14 15) *0, disabled.
[ 1.463236] Linux Plug and Play Support v0.97 (c) Adam Belay
[ 1.467236] pnp: PnP ACPI init
[ 1.471236] ACPI: bus type pnp registered
[ 1.481343] pnp: PnP ACPI: found 13 devices
[ 1.485344] ACPI: ACPI bus type pnp unregistered
[ 1.489344] PnPBIOS: Disabled by ACPI PNP
[ 1.493344] PCI: Using ACPI for IRQ routing
[ 1.505352] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0, 0, 0, 0, 0, 0
[ 1.581606] hpet0: 8 64-bit timers, 14318180 Hz
[ 1.636850] ACPI: RTC can wake from S4
[ 1.637508] Switched to high resolution mode on CPU 0
[ 1.639335] Switched to high resolution mode on CPU 7
[ 1.641058] Switched to high resolution mode on CPU 3
[ 1.641096] Switched to high resolution mode on CPU 1
[ 1.641096] Switched to high resolution mode on CPU 2
[ 1.644899] Switched to high resolution mode on CPU 5
[ 1.646400] Switched to high resolution mode on CPU 6
[ 1.686592] Switched to high resolution mode on CPU 4
[ 1.690619] system 00:07: ioport range 0x800-0x87f has been reserved
[ 1.766671] system 00:07: ioport range 0x880-0x8ff has been reserved
[ 1.842794] system 00:07: ioport range 0x900-0x91f has been reserved
[ 1.918917] system 00:07: ioport range 0x920-0x923 has been reserved
[ 1.995040] system 00:07: ioport range 0x924-0x924 has been reserved
[ 2.071165] system 00:07: ioport range 0xca0-0xca7 has been reserved
[ 2.147289] system 00:07: ioport range 0xca9-0xcab has been reserved
[ 2.223411] system 00:07: ioport range 0xcad-0xcaf has been reserved
[ 2.299538] system 00:08: ioport range 0xca8-0xca8 has been reserved
[ 2.375656] system 00:08: ioport range 0xcac-0xcac has been reserved
[ 2.451787] system 00:0a: iomem range 0xe0000000-0xefffffff could not be reserved
[ 2.541442] system 00:0c: iomem range 0xfed50000-0xfed53fff could not be reserved
[ 2.749565] PCI: Bridge: 0000:00:03.0
[ 2.793561] IO window: f000-ffff
[ 2.837572] MEM window: 0xdf900000-0xdf9fffff
[ 2.892592] PREFETCH window: disabled.
[ 2.945573] PCI: Bridge: 0000:00:1c.0
[ 2.989382] IO window: disabled.
[ 3.030080] MEM window: disabled.
[ 3.071815] PREFETCH window: disabled.
[ 3.118746] PCI: Bridge: 0000:00:1e.0
[ 3.162554] IO window: disabled.
[ 3.203254] MEM window: 0xde800000-0xdf7fffff
[ 3.258049] PREFETCH window: 0x00000000de000000-0x00000000de7fffff
[ 3.334064] ACPI: PCI Interrupt 0000:00:03.0[A] -> GSI 16 (level, low) -> IRQ 16
[ 3.437572] PCI: Setting latency timer of device 0000:00:03.0 to 64
[ 3.437590] PCI: Setting latency timer of device 0000:00:1c.0 to 64
[ 3.437600] PCI: Setting latency timer of device 0000:00:1e.0 to 64
[ 3.437653] NET: Registered protocol family 2
[ 3.529659] IP route cache hash table entries: 32768 (order: 5, 131072 bytes)
[ 3.615173] TCP established hash table entries: 131072 (order: 8, 1048576 bytes)
[ 3.704445] TCP bind hash table entries: 65536 (order: 7, 524288 bytes)
[ 3.783971] TCP: Hash tables configured (established 131072 bind 65536)
[ 3.863107] TCP reno registered
[ 3.918800] NET: Registered protocol family 1
[ 3.970943] checking if image is initramfs... it is
[ 4.596694] Freeing initrd memory: 6602k freed
[ 5.358462] audit: initializing netlink socket (disabled)
[ 5.658791] type=2000 audit(1275901948.528:1): initialized
[ 5.728510] highmem bounce pool size: 64 pages
[ 5.780517] Total HugeTLB memory allocated, 0
[ 5.834268] VFS: Disk quotas dquot_6.5.1
[ 5.905506] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[ 5.999711] msgmni has been set to 1700
[ 6.045670] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 253)
[ 6.237671] io scheduler noop registered
[ 6.285670] io scheduler anticipatory registered
[ 6.341670] io scheduler deadline registered
[ 7.306212] io scheduler cfq registered (default)
[ 7.377656] pci 0000:03:03.0: Boot video device
[ 7.378704] PCI: Setting latency timer of device 0000:00:03.0 to 64
[ 7.378704] assign_interrupt_mode Found MSI capability
[ 7.438735] Allocate Port Service[0000:00:03.0cie00]
[ 7.440386] Allocate Port Service[0000:00:03.0cie01]
[ 7.440386] PCI: Setting latency timer of device 0000:00:1c.0 to 64
[ 7.440386] assign_interrupt_mode Found MSI capability
[ 7.926210] Allocate Port Service[0000:00:1c.0cie00]
[ 7.930302] Load service driver aer on pcie device 0000:00:03.0cie01
[ 7.930302] isapnp: Scanning for PnP cards...
[ 9.103921] isapnp: No Plug & Play device found
[ 9.913339] hpet_resources: 0xfed00000 is busy
[ 9.913339] Serial: 8250/16550 driver $Revision: 1.90 $ 4 ports, IRQ sharing enabled
[ 11.529239] serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[ 11.601288] serial8250: ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A
[ 11.702619] 00:05: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[ 11.776850] 00:06: ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A
[ 11.843718] brd: module loaded
[ 11.881567] PNP: No PS/2 controller found. Probing ports directly.
[ 12.138037] i8042.c: No controller found.
[ 12.186909] mice: PS/2 mouse device common for all mice
[ 12.251095] rtc_cmos 00:04: rtc core: registered rtc_cmos as rtc0
[ 12.324317] rtc0: alarms up to one day, y3k
[ 12.377396] cpuidle: using governor ladder
[ 12.425401] cpuidle: using governor menu
[ 12.473063] No iBFT detected.
[ 12.509084] TCP cubic registered
[ 12.546220] NET: Registered protocol family 17
[ 12.600954] Using IPI No-Shortcut mode
[ 12.647114] registered taskstats version 1
[ 12.695376] rtc_cmos 00:04: setting system clock to 2010-06-07 09:12:48 UTC (1275901968)
[ 12.788310] Freeing unused kernel memory: 256k freed
[ 14.538145] Monitor-Mwait will be used to enter C-1 state
[ 14.538145] Monitor-Mwait will be used to enter C-2 state
[ 14.538145] Monitor-Mwait will be used to enter C-3 state
[ 14.538145] ACPI: CPU0 (power states: C1[C1] C2[C2] C3[C3])
[ 15.286040] ACPI: ACPI0007:00 is registered as cooling_device0
[ 15.356073] ------------[ cut here ]------------
[ 15.356073] ACPI: CPU1 (power states: C1[C1] C2[C2] C3[C3])
[ 15.356073] ACPI: ACPI0007:01 is registered as cooling_device1
[ 15.356073] WARNING: at arch/x86/kernel/hpet.c:299 hpet_legacy_next_event+0x38/0x5a()
[ 15.881774] Modules linked in: processor(+) fan thermal_sys
[ 15.881774] Pid: 0, comm: swapper Not tainted 2.6.26-2-686-bigmem #1
[ 15.881774] [<c0129147>] warn_on_slowpath+0x40/0x66
[ 15.881774] [<c01e7782>] __next_cpu+0x12/0x21
[ 16.081772] [<c01201f9>] find_busiest_group+0x21e/0x623
[ 16.081772] [<c01192bb>] hpet_legacy_next_event+0x38/0x5a
[ 16.081772] [<c013f68c>] clockevents_program_event+0xc4/0xd2
[ 16.081772] [<c014038e>] tick_dev_program_event+0x1e/0x82
[ 16.081772] [<c013fe14>] tick_broadcast_set_event+0xf/0x11
[ 16.081772] [<c014009e>] tick_broadcast_oneshot_control+0x8a/0xda
[ 16.081772] [<c013fae8>] tick_notify+0x1cd/0x2e3
[ 16.081772] [<c013acaa>] enqueue_hrtimer+0xc9/0xd4
[ 16.081772] [<c013bdd0>] notifier_call_chain+0x2a/0x47
[ 16.081772] [<c013be14>] raw_notifier_call_chain+0x9/0xc
[ 16.081772] [<c013f58c>] clockevents_notify+0x19/0x55
[ 16.081772] [<f8848f1b>] acpi_idle_enter_bm+0x12f/0x315 [processor]
[ 16.081772] [<c025b435>] cpuidle_idle_call+0x5b/0x86
[ 16.081772] [<c025b3da>] cpuidle_idle_call+0x0/0x86
[ 16.081772] [<c01075d3>] cpu_idle+0xb0/0xd0
[ 16.081772] =======================
[ 18.026131] ---[ end trace 180ccccd85916810 ]---
[ 18.026131] Marking TSC unstable due to: TSC halts in idle.
[ 18.026131] ACPI: CPU2 (power states: C1[C1] C2[C2] C3[C3])
[ 18.026131] ACPI: ACPI0007:02 is registered as cooling_device2
[ 18.033904] ACPI: CPU3 (power states: C1[C1] C2[C2] C3[C3])
[ 18.033904] ACPI: ACPI0007:03 is registered as cooling_device3
[ 18.033904] ACPI: CPU4 (power states: C1[C1] C2[C2] C3[C3])
[ 18.033904] ACPI: ACPI0007:04 is registered as cooling_device4
[ 18.033904] ACPI: CPU5 (power states: C1[C1] C2[C2] C3[C3])
[ 18.033904] ACPI: ACPI0007:05 is registered as cooling_device5
[ 18.033904] ACPI: CPU6 (power states: C1[C1] C2[C2] C3[C3])
[ 18.033904] ACPI: ACPI0007:06 is registered as cooling_device6
[ 18.035674] ACPI: CPU7 (power states: C1[C1] C2[C2] C3[C3])
[ 18.035674] ACPI: ACPI0007:07 is registered as cooling_device7
[ 19.910306] e1000e: Intel(R) PRO/1000 Network Driver - 0.3.3.3-k2
[ 19.984585] e1000e: Copyright (c) 1999-2008 Intel Corporation.
[ 20.056632] ACPI: PCI Interrupt 0000:01:00.0[A] -> GSI 16 (level, low) -> IRQ 16
[ 20.145363] PCI: Setting latency timer of device 0000:01:00.0 to 64
[ 20.148015] usbcore: registered new interface driver usbfs
[ 20.218805] usbcore: registered new interface driver hub
[ 20.282794] usbcore: registered new device driver usb
[ 20.348926] No dock devices found.
[ 20.434205] SCSI subsystem initialized
[ 20.491095] libata version 3.00 loaded.
[ 20.515513] eth0: (PCI Express:2.5GB/s:Width x1) 00:1b:21:51:a5:06
[ 20.634158] eth0: Intel(R) PRO/1000 Network Connection
[ 20.717939] eth0: MAC: 3, PHY: 8, PBA No: e46981-003
[ 20.772268] ACPI: PCI Interrupt 0000:00:1a.0[A] -> GSI 22 (level, low) -> IRQ 22
[ 20.876293] PCI: Setting latency timer of device 0000:00:1a.0 to 64
[ 20.876297] ehci_hcd 0000:00:1a.0: EHCI Host Controller
[ 20.940363] ehci_hcd 0000:00:1a.0: new USB bus registered, assigned bus number 1
[ 21.096163] ehci_hcd 0000:00:1a.0: debug port 2
[ 21.182164] PCI: cache line size of 32 is not supported by device 0000:00:1a.0
[ 21.182174] ehci_hcd 0000:00:1a.0: irq 22, io mem 0xdf8fa000
[ 21.297066] ehci_hcd 0000:00:1a.0: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004
[ 21.385254] usb usb1: configuration #1 chosen from 1 choice
[ 21.475578] hub 1-0:1.0: USB hub found
[ 21.520485] hub 1-0:1.0: 2 ports detected
[ 21.674646] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[ 21.996465] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 22.084470] usb usb1: Product: EHCI Host Controller
[ 22.142842] usb usb1: Manufacturer: Linux 2.6.26-2-686-bigmem ehci_hcd
[ 22.154728] usb 1-1: new high speed USB device using ehci_hcd and address 2
[ 22.287166] usb 1-1: configuration #1 chosen from 1 choice
[ 22.287166] hub 1-1:1.0: USB hub found
[ 22.287229] hub 1-1:1.0: 6 ports detected
[ 22.390367] usb 1-1: New USB device found, idVendor=8087, idProduct=0020
[ 22.390370] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 22.630390] usb usb1: SerialNumber: 0000:00:1a.0
[ 22.682406] ACPI: PCI Interrupt 0000:00:1d.0[A] -> GSI 22 (level, low) -> IRQ 22
[ 23.127469] PCI: Setting latency timer of device 0000:00:1d.0 to 64
[ 23.127472] ehci_hcd 0000:00:1d.0: EHCI Host Controller
[ 23.187971] ehci_hcd 0000:00:1d.0: new USB bus registered, assigned bus number 2
[ 23.287989] ehci_hcd 0000:00:1d.0: debug port 2
[ 23.340171] PCI: cache line size of 32 is not supported by device 0000:00:1d.0
[ 23.340176] ehci_hcd 0000:00:1d.0: irq 22, io mem 0xdf8fc000
[ 23.424255] ehci_hcd 0000:00:1d.0: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004
[ 23.513222] usb usb2: configuration #1 chosen from 1 choice
[ 23.583141] hub 2-0:1.0: USB hub found
[ 23.628706] hub 2-0:1.0: 2 ports detected
[ 24.272184] usb usb2: New USB device found, idVendor=1d6b, idProduct=0002
[ 24.354065] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 24.442070] usb usb2: Product: EHCI Host Controller
[ 24.500409] usb usb2: Manufacturer: Linux 2.6.26-2-686-bigmem ehci_hcd
[ 24.514102] usb 2-1: new high speed USB device using ehci_hcd and address 2
[ 24.646523] usb 2-1: configuration #1 chosen from 1 choice
[ 24.646523] hub 2-1:1.0: USB hub found
[ 24.646589] hub 2-1:1.0: 6 ports detected
[ 24.750137] usb 2-1: New USB device found, idVendor=8087, idProduct=0020
[ 24.750140] usb 2-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 24.950222] usb 2-1.5: new high speed USB device using ehci_hcd and address 3
[ 25.042490] usb 2-1.5: configuration #1 chosen from 1 choice
[ 25.042490] hub 2-1.5:1.0: USB hub found
[ 25.042559] hub 2-1.5:1.0: 4 ports detected
[ 25.446601] usb 2-1.5: New USB device found, idVendor=0424, idProduct=2514
[ 25.446603] usb 2-1.5: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 25.646809] usb 2-1.5.3: new high speed USB device using ehci_hcd and address 4
[ 25.742051] usb 2-1.5.3: configuration #1 chosen from 1 choice
[ 25.745999] usb 2-1.5.3: New USB device found, idVendor=0951, idProduct=1624
[ 25.745999] usb 2-1.5.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 25.745999] usb 2-1.5.3: Product: DataTraveler G2
[ 25.745999] usb 2-1.5.3: Manufacturer: Kingston
[ 25.745999] usb 2-1.5.3: SerialNumber: 0014780F9955A9A085EC00BE
[ 26.238512] usb usb2: SerialNumber: 0000:00:1d.0
[ 26.295652] ahci 0000:00:1f.2: version 3.0
[ 26.295652] ACPI: PCI Interrupt 0000:00:1f.2[A] -> GSI 20 (level, low) -> IRQ 20
[ 26.685567] Initializing USB Mass Storage driver...
[ 26.759632] scsi0 : SCSI emulation for USB Mass Storage devices
[ 26.830422] usbcore: registered new interface driver usb-storage
[ 26.830422] usb-storage: device found at 4
[ 26.830424] usb-storage: waiting for device to settle before scanning
[ 26.910949] USB Mass Storage support registered.
[ 27.711754] ahci 0000:00:1f.2: AHCI 0001.0300 32 slots 6 ports 3 Gbps 0x3f impl SATA mode
[ 27.882626] ahci 0000:00:1f.2: flags: 64bit ncq sntf pm led clo pmp pio slum part
[ 28.059553] PCI: Setting latency timer of device 0000:00:1f.2 to 64
[ 28.061471] scsi1 : ahci
[ 28.094211] scsi2 : ahci
[ 28.125334] scsi3 : ahci
[ 28.157198] scsi4 : ahci
[ 28.188218] scsi5 : ahci
[ 28.236327] scsi6 : ahci
[ 28.267975] ata1: SATA max UDMA/133 abar m2048@0xdf8fe000 port 0xdf8fe100 irq 218
[ 28.361466] ata2: SATA max UDMA/133 abar m2048@0xdf8fe000 port 0xdf8fe180 irq 218
[ 28.451112] ata3: SATA max UDMA/133 abar m2048@0xdf8fe000 port 0xdf8fe200 irq 218
[ 28.543119] ata4: SATA max UDMA/133 abar m2048@0xdf8fe000 port 0xdf8fe280 irq 218
[ 28.632613] ata5: SATA max UDMA/133 abar m2048@0xdf8fe000 port 0xdf8fe300 irq 218
[ 28.722415] ata6: SATA max UDMA/133 abar m2048@0xdf8fe000 port 0xdf8fe380 irq 218
[ 29.399603] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 29.484570] ata1.00: ATA-8: WDC WD7500AYPS-01ZKB1, 02.01B02, max UDMA/133
[ 29.565992] ata1.00: 1465149168 sectors, multi 0: LBA48 NCQ (depth 31/32)
[ 29.652465] ata1.00: configured for UDMA/133
[ 30.201114] ata2: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 30.313461] ata2.00: ATA-8: WDC WD7500AYPS-01ZKB1, 02.01B02, max UDMA/133
[ 30.405207] ata2.00: 1465149168 sectors, multi 0: LBA48 NCQ (depth 31/32)
[ 30.495436] ata2.00: configured for UDMA/133
[ 30.874691] ata3: SATA link down (SStatus 0 SControl 300)
[ 31.274925] ata4: SATA link down (SStatus 0 SControl 300)
[ 31.675161] ata5: SATA link down (SStatus 0 SControl 300)
[ 32.285148] ata6: SATA link down (SStatus 0 SControl 300)
[ 32.364921] scsi 1:0:0:0: Direct-Access ATA WDC WD7500AYPS-0 02.0 PQ: 0 ANSI: 5
[ 32.390095] usb-storage: device scan complete
[ 32.390095] scsi 0:0:0:0: Direct-Access Kingston DataTraveler G2 1.00 PQ: 0 ANSI: 2
[ 32.901856] Driver 'sd' needs updating - please use bus_type methods
[ 32.901856] scsi 2:0:0:0: Direct-Access ATA WDC WD7500AYPS-0 02.0 PQ: 0 ANSI: 5
[ 33.077904] sd 0:0:0:0: [sda] 7831552 512-byte hardware sectors (4010 MB)
[ 33.161033] sd 0:0:0:0: [sda] Write Protect is off
[ 33.261524] sd 0:0:0:0: [sda] Mode Sense: 23 00 00 00
[ 33.261526] sd 0:0:0:0: [sda] Assuming drive cache: write through
[ 33.337817] sd 0:0:0:0: [sda] 7831552 512-byte hardware sectors (4010 MB)
[ 33.422891] sd 0:0:0:0: [sda] Write Protect is off
[ 33.506633] sd 0:0:0:0: [sda] Mode Sense: 23 00 00 00
[ 33.506635] sd 0:0:0:0: [sda] Assuming drive cache: write through
[ 33.578786] sda: sda1
[ 33.608932] sd 0:0:0:0: [sda] Attached SCSI removable disk
[ 33.677442] sd 1:0:0:0: [sdb] 1465149168 512-byte hardware sectors (750156 MB)
[ 33.768455] sd 1:0:0:0: [sdb] Write Protect is off
[ 33.825721] sd 1:0:0:0: [sdb] Mode Sense: 00 3a 00 00
[ 33.828492] sd 1:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 34.037780] sd 1:0:0:0: [sdb] 1465149168 512-byte hardware sectors (750156 MB)
[ 34.121780] sd 1:0:0:0: [sdb] Write Protect is off
[ 34.121780] sd 1:0:0:0: [sdb] Mode Sense: 00 3a 00 00
[ 34.177781] sd 1:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 34.285778] sdb: sdb1 sdb2
[ 34.331956] sd 1:0:0:0: [sdb] Attached SCSI disk
[ 34.391358] sd 2:0:0:0: [sdc] 1465149168 512-byte hardware sectors (750156 MB)
[ 34.486374] sd 2:0:0:0: [sdc] Write Protect is off
[ 34.543212] sd 2:0:0:0: [sdc] Mode Sense: 00 3a 00 00
[ 34.545753] sd 2:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 34.654258] sd 2:0:0:0: [sdc] 1465149168 512-byte hardware sectors (750156 MB)
[ 34.837987] sd 2:0:0:0: [sdc] Write Protect is off
[ 34.894175] sd 2:0:0:0: [sdc] Mode Sense: 00 3a 00 00
[ 34.895577] sd 2:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 35.003896] sdc: sdc1 sdc2
[ 35.050156] sd 2:0:0:0: [sdc] Attached SCSI disk
[ 35.307708] device-mapper: uevent: version 1.0.3
[ 35.383401] device-mapper: ioctl: 4.13.0-ioctl (2007-10-18) initialised: dm-devel@redhat.com
[ 35.530895] md: raid0 personality registered for level 0
[ 35.609576] md: raid1 personality registered for level 1
[ 35.873259] md: md127 stopped.
[ 35.991805] md: bind<dm-3>
[ 36.030565] md: bind<dm-0>
[ 36.079520] md: md127: raid array is not clean -- starting background reconstruction
[ 36.204275] raid1: raid set md127 active with 2 out of 2 mirrors
[ 36.742716] EXT3-fs: INFO: recovery required on readonly filesystem.
[ 36.834254] EXT3-fs: write access will be enabled during recovery.
[ 37.375441] md: resync of RAID array md127
[ 37.393581] kjournald starting. Commit interval 5 seconds
[ 37.393581] EXT3-fs: recovery complete.
[ 37.393778] EXT3-fs: mounted filesystem with ordered data mode.
[ 37.763446] md: minimum _guaranteed_ speed: 1000 KB/sec/disk.
[ 37.901838] md: using maximum available idle IO bandwidth (but not more than 200000 KB/sec) for resync.
[ 37.901843] md: using 128k window, over a total of 222297980 blocks.
[ 39.318926] udevd version 125 started
[ 39.526894] dcdbas dcdbas: Dell Systems Management Base Driver (version 5.6.0-3.2)
[ 39.768006] input: PC Speaker as /class/input/input0
[ 39.850320] input: Power Button (FF) as /class/input/input1
[ 39.984597] ACPI: Power Button (FF) [PWRF]
[ 41.212396] EXT3 FS on dm-18, internal journal
[ 41.831114] md: md126 stopped.
[ 42.046012] md: bind<dm-5>
[ 42.089787] md: bind<dm-2>
[ 42.215263] md126: setting max_sectors to 128, segment boundary to 32767
[ 42.295225] raid0: looking at dm-2
[ 42.335916] raid0: comparing dm-2(54525888) with dm-2(54525888)
[ 42.407836] raid0: END
[ 42.438153] raid0: ==> UNIQUE
[ 42.475739] raid0: 1 zones
[ 42.528213] raid0: looking at dm-5
[ 42.581001] raid0: comparing dm-5(54525888) with dm-2(54525888)
[ 42.678343] raid0: EQUAL
[ 42.711182] raid0: FINAL 1 zones
[ 42.751186] raid0: done.
[ 42.781448] raid0 : md_size is 109051776 blocks.
[ 42.836906] raid0 : conf->hash_spacing is 109051776 blocks.
[ 42.904911] raid0 : nb_zone is 1.
[ 42.961486] raid0 : Allocating 4 bytes for hash.
[ 73.273813] kjournald starting. Commit interval 5 seconds
[ 73.275108] EXT3 FS on dm-15, internal journal
[ 73.275108] EXT3-fs: mounted filesystem with ordered data mode.
[ 73.315332] kjournald starting. Commit interval 5 seconds
[ 73.315332] EXT3 FS on dm-16, internal journal
[ 73.315332] EXT3-fs: mounted filesystem with ordered data mode.
[ 73.379532] kjournald starting. Commit interval 5 seconds
[ 73.380685] EXT3 FS on dm-6, internal journal
[ 73.380685] EXT3-fs: mounted filesystem with ordered data mode.
[ 73.449358] kjournald starting. Commit interval 5 seconds
[ 73.449358] EXT3 FS on dm-7, internal journal
[ 73.449358] EXT3-fs: mounted filesystem with ordered data mode.
[ 73.479249] kjournald starting. Commit interval 5 seconds
[ 73.480447] EXT3 FS on dm-8, internal journal
[ 73.480447] EXT3-fs: mounted filesystem with ordered data mode.
[ 73.525190] kjournald starting. Commit interval 5 seconds
[ 73.525190] EXT3 FS on dm-17, internal journal
[ 73.525190] EXT3-fs: mounted filesystem with ordered data mode.
[ 73.566757] kjournald starting. Commit interval 5 seconds
[ 73.568562] EXT3 FS on dm-10, internal journal
[ 73.568562] EXT3-fs: mounted filesystem with ordered data mode.
[ 73.574051] kjournald starting. Commit interval 5 seconds
[ 73.574051] EXT3 FS on dm-13, internal journal
[ 73.574051] EXT3-fs: mounted filesystem with ordered data mode.
[ 73.611615] kjournald starting. Commit interval 5 seconds
[ 73.611684] EXT3 FS on dm-14, internal journal
[ 73.611684] EXT3-fs: mounted filesystem with ordered data mode.
[ 73.690197] kjournald starting. Commit interval 5 seconds
[ 73.690197] EXT3 FS on dm-19, internal journal
[ 73.690197] EXT3-fs: mounted filesystem with ordered data mode.
[ 73.738732] kjournald starting. Commit interval 5 seconds
[ 73.739828] EXT3 FS on dm-20, internal journal
[ 73.739828] EXT3-fs: mounted filesystem with ordered data mode.
[ 73.786859] Adding 4194296k swap on /dev/mapper/chiark--early--a-swap. Priority:10 extents:1 across:4194296k
[ 73.847214] Adding 4194296k swap on /dev/mapper/chiark--early--b-swap. Priority:10 extents:1 across:4194296k
[ 75.677263] ip_tables: (C) 2000-2006 Netfilter Core Team
[ 75.744291] NET: Registered protocol family 10
[ 75.744291] lo: Disabled Privacy Extensions
[ 75.765697] ip6_tables: (C) 2000-2006 Netfilter Core Team
[ 78.125485] ADDRCONF(NETDEV_UP): eth0: link is not ready
 
Old 06-20-2010, 11:08 PM
Ben Hutchings
 
Default Bug#584881: Lockups under heavy disk IO; md (RAID) resync/check implicated

On Mon, 2010-06-07 at 10:53 +0100, Ian Jackson wrote:
> Package: linux-image-2.6.26-2-686-bigmem
> Version: 2.6.26-21lenny4
>
> I keep getting soft lockups; the symptoms appear to be that user
> processes become deadlocked when they try to access the disk, but the
> kernel doesn't notice that anything is wrong.
[...]

We really need to see the kernel messages reporting soft-lockup.

Note that your disk configuration is unusual and probably not
well-tested by others. It is unlikely that anyone in the kernel team
will be able to debug this as I don't think any of us have particular
expertise in this area. If you have the opportunity, it would be
helpful if you could test a newer kernel version. This would give us a
clue as to whether the bug has subsequently been fixed upstream, and if
not then it would be the basis for an upstream bug report.

Ben.

--
Ben Hutchings
Once a job is fouled up, anything done to improve it makes it worse.
 
Old 06-21-2010, 10:11 AM
Ian Jackson
 
Default Bug#584881: Lockups under heavy disk IO; md (RAID) resync/check implicated

Ben Hutchings writes ("Re: Bug#584881: Lockups under heavy disk IO; md (RAID) resync/check implicated"):
> We really need to see the kernel messages reporting soft-lockup.

There aren't any. Or, if there are, it isn't printing them to the
serial console. Perhaps it is trying to send them only to syslogd
which obviously can't write to the disk either.

I know that the serial console is working after the crash as it echoes
my first carriage return (although then login or the shell wedges
before being able to print a prompt). I could have asked for a magic
sysrq process dump but given that the process table is probably full I
expect this would take many hours at 9600bps.

> Note that your disk configuration is unusual and probably not
> well-tested by others. It is unlikely that anyone in the kernel team
> will be able to debug this as I don't think any of us have particular
> expertise in this area.

Search the web suggests that symptoms very similar to mine are not
uncommon, including instances without soft lockup messages, and none
of the other users seem to have a similar disk layout.

I can't easily test this theory but I think the unusual disk layout is
probably simply making a race easier to trigger.

> If you have the opportunity, it would be
> helpful if you could test a newer kernel version. This would give us a
> clue as to whether the bug has subsequently been fixed upstream, and if
> not then it would be the basis for an upstream bug report.

Unfortunately testing this bug on the live system involves (a) risking
a crash and then if the test fails (b) an extremely vulnerable system
without backups for the following four days.

I'll see if I can borrow a spare R210 from Jump, in which case I may
be able to reproduce the problem in controlled conditions on my coffee
table at home (and with access to the VGA console). Which kernel
should I test in that case ?

Ian.



--
To UNSUBSCRIBE, email to debian-kernel-REQUEST@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listmaster@lists.debian.org
Archive: 19487.15030.702626.287407@chiark.greenend.org.uk"> http://lists.debian.org/19487.15030.702626.287407@chiark.greenend.org.uk
 
Old 06-24-2010, 02:15 AM
Ben Hutchings
 
Default Bug#584881: Lockups under heavy disk IO; md (RAID) resync/check implicated

On Mon, 2010-06-21 at 11:11 +0100, Ian Jackson wrote:
> Ben Hutchings writes ("Re: Bug#584881: Lockups under heavy disk IO; md (RAID) resync/check implicated"):
> > We really need to see the kernel messages reporting soft-lockup.
>
> There aren't any. Or, if there are, it isn't printing them to the
> serial console. Perhaps it is trying to send them only to syslogd
> which obviously can't write to the disk either.
>
> I know that the serial console is working after the crash as it echoes
> my first carriage return (although then login or the shell wedges
> before being able to print a prompt). I could have asked for a magic
> sysrq process dump but given that the process table is probably full I
> expect this would take many hours at 9600bps.

Even if you can't get a process dump, you can get some useful
information with:
'd' - show locks held
'l' - show backtrace for active CPUs
'w' - show uninterruptible tasks

> > Note that your disk configuration is unusual and probably not
> > well-tested by others. It is unlikely that anyone in the kernel team
> > will be able to debug this as I don't think any of us have particular
> > expertise in this area.
>
> Search the web suggests that symptoms very similar to mine are not
> uncommon, including instances without soft lockup messages, and none
> of the other users seem to have a similar disk layout.
>
> I can't easily test this theory but I think the unusual disk layout is
> probably simply making a race easier to trigger.

Thinking of some kind of lock-dependency bug? Blocking on a mutex for a
long period should still trigger a soft-lockup message. Since there are
no messages from the kernel it's something of a mystery what's going on.

> > If you have the opportunity, it would be
> > helpful if you could test a newer kernel version. This would give us a
> > clue as to whether the bug has subsequently been fixed upstream, and if
> > not then it would be the basis for an upstream bug report.
>
> Unfortunately testing this bug on the live system involves (a) risking
> a crash and then if the test fails (b) an extremely vulnerable system
> without backups for the following four days.

That's what I suspected.

> I'll see if I can borrow a spare R210 from Jump, in which case I may
> be able to reproduce the problem in controlled conditions on my coffee
> table at home (and with access to the VGA console). Which kernel
> should I test in that case ?

Please try 2.6.34 from experimental.

Ben.

--
Ben Hutchings
Once a job is fouled up, anything done to improve it makes it worse.
 
Old 06-24-2010, 10:17 AM
Ian Jackson
 
Default Bug#584881: Lockups under heavy disk IO; md (RAID) resync/check implicated

Ben Hutchings writes ("Re: Bug#584881: Lockups under heavy disk IO; md (RAID) resync/check implicated"):
> Even if you can't get a process dump, you can get some useful
> information with:

Right, thanks.

> 'd' - show locks held
> 'l' - show backtrace for active CPUs
> 'w' - show uninterruptible tasks

I'll try these although I suspect thousands of uninterruptible tasks.

> > Search the web suggests that symptoms very similar to mine are not
> > uncommon, including instances without soft lockup messages, and none
> > of the other users seem to have a similar disk layout.
> >
> > I can't easily test this theory but I think the unusual disk layout is
> > probably simply making a race easier to trigger.
>
> Thinking of some kind of lock-dependency bug? Blocking on a mutex for a
> long period should still trigger a soft-lockup message. Since there are
> no messages from the kernel it's something of a mystery what's going on.

The RAID system (md driver) has a separate mechanism for blocking
writes, which it calls a "barrier". I think it is quite capable of
indefinitely blocking all writes to a device without necessarily
triggering the soft lockup detector.

> > I'll see if I can borrow a spare R210 from Jump, in which case I may
> > be able to reproduce the problem in controlled conditions on my coffee
> > table at home (and with access to the VGA console). Which kernel
> > should I test in that case ?
>
> Please try 2.6.34 from experimental.

Will do. I'll get back to you.

Thanks,
Ian.



--
To UNSUBSCRIBE, email to debian-kernel-REQUEST@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listmaster@lists.debian.org
Archive: 19491.12472.880707.704477@chiark.greenend.org.uk"> http://lists.debian.org/19491.12472.880707.704477@chiark.greenend.org.uk
 
Old 06-25-2010, 12:53 AM
Ben Hutchings
 
Default Bug#584881: Lockups under heavy disk IO; md (RAID) resync/check implicated

On Thu, 2010-06-24 at 11:17 +0100, Ian Jackson wrote:
> Ben Hutchings writes ("Re: Bug#584881: Lockups under heavy disk IO; md (RAID) resync/check implicated"):
[...]
> > > Search the web suggests that symptoms very similar to mine are not
> > > uncommon, including instances without soft lockup messages, and none
> > > of the other users seem to have a similar disk layout.
> > >
> > > I can't easily test this theory but I think the unusual disk layout is
> > > probably simply making a race easier to trigger.
> >
> > Thinking of some kind of lock-dependency bug? Blocking on a mutex for a
> > long period should still trigger a soft-lockup message. Since there are
> > no messages from the kernel it's something of a mystery what's going on.
>
> The RAID system (md driver) has a separate mechanism for blocking
> writes, which it calls a "barrier". I think it is quite capable of
> indefinitely blocking all writes to a device without necessarily
> triggering the soft lockup detector.
[...]

I/O barriers are block I/O operations (not specific to md) that inhibit
reordering of read and write operations. They certainly should not be
blocking operations. Also, device-mapper did not support barriers until
after 2.6.26 so md will not be using them in the configuration you are
using.

Ben.

--
Ben Hutchings
Once a job is fouled up, anything done to improve it makes it worse.
 
Old 06-25-2010, 10:50 AM
Ian Jackson
 
Default Bug#584881: Lockups under heavy disk IO; md (RAID) resync/check implicated

Ben Hutchings writes ("Re: Bug#584881: Lockups under heavy disk IO; md (RAID) resync/check implicated"):
> I/O barriers are block I/O operations (not specific to md) that inhibit
> reordering of read and write operations. They certainly should not be
> blocking operations. Also, device-mapper did not support barriers until
> after 2.6.26 so md will not be using them in the configuration you are
> using.

No, I think there are two meanings of the word "barrier". AFAICT md
has its own thing which it confusingly calls a "barrier"; it can be
"raised" and "lowered".

Ian.



--
To UNSUBSCRIBE, email to debian-kernel-REQUEST@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listmaster@lists.debian.org
Archive: 19492.35328.840651.181744@chiark.greenend.org.uk"> http://lists.debian.org/19492.35328.840651.181744@chiark.greenend.org.uk
 
Old 06-25-2010, 11:13 AM
Ben Hutchings
 
Default Bug#584881: Lockups under heavy disk IO; md (RAID) resync/check implicated

On Fri, 2010-06-25 at 11:50 +0100, Ian Jackson wrote:
> Ben Hutchings writes ("Re: Bug#584881: Lockups under heavy disk IO; md (RAID) resync/check implicated"):
> > I/O barriers are block I/O operations (not specific to md) that inhibit
> > reordering of read and write operations. They certainly should not be
> > blocking operations. Also, device-mapper did not support barriers until
> > after 2.6.26 so md will not be using them in the configuration you are
> > using.
>
> No, I think there are two meanings of the word "barrier". AFAICT md
> has its own thing which it confusingly calls a "barrier"; it can be
> "raised" and "lowered".

Oh, great! I wondered whether this was the case but I could only find
discussion of md vs I/O barriers. Do you have any reference for
documentation of md barriers?

Ben.

--
Ben Hutchings
Once a job is fouled up, anything done to improve it makes it worse.
 
Old 06-25-2010, 11:27 AM
Ian Jackson
 
Default Bug#584881: Lockups under heavy disk IO; md (RAID) resync/check implicated

Ben Hutchings writes ("Re: Bug#584881: Lockups under heavy disk IO; md (RAID) resync/check implicated"):
> On Fri, 2010-06-25 at 11:50 +0100, Ian Jackson wrote:
> > No, I think there are two meanings of the word "barrier". AFAICT md
> > has its own thing which it confusingly calls a "barrier"; it can be
> > "raised" and "lowered".
>
> Oh, great! I wondered whether this was the case but I could only find
> discussion of md vs I/O barriers. Do you have any reference for
> documentation of md barriers?

No. I just stumbled across them in the source. Particularly this in
drivers/md/raid1.c:

/* Barriers....
* Sometimes we need to suspend IO while we do something else,
* either some resync/recovery, or reconfigure the array.
* To do this we raise a 'barrier'.
* The 'barrier' is a counter that can be raised multiple times
* to count how many activities are happening which preclude
* normal IO.
* We can only raise the barrier if there is no pending IO.
* i.e. if nr_pending == 0.
* We choose only to raise the barrier if no-one is waiting for the
* barrier to go down. This means that as soon as an IO request
* is ready, no other operations which require a barrier will start
* until the IO request has had a chance.
*
* So: regular IO calls 'wait_barrier'. When that returns there
* is no backgroup IO happening, It must arrange to call
* allow_barrier when it has finished its IO.
* backgroup IO calls must call raise_barrier. Once that returns
* there is no normal IO happeing. It must arrange to call
* lower_barrier when the particular background IO completes.
*/

Ian.



--
To UNSUBSCRIBE, email to debian-kernel-REQUEST@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listmaster@lists.debian.org
Archive: 19492.37519.253066.945143@chiark.greenend.org.uk"> http://lists.debian.org/19492.37519.253066.945143@chiark.greenend.org.uk
 
Old 07-20-2010, 09:51 PM
Ian Jackson
 
Default Bug#584881: Lockups under heavy disk IO; md (RAID) resync/check implicated

Ben Hutchings writes ("Re: Bug#584881: Lockups under heavy disk IO; md (RAID) resync/check implicated"):
> Please try 2.6.34 from experimental.

I've now replicated the problem on my coffee table with a temporary
(intermittent) loan of an identical machine from Jump networks.
I can get 2.6.26-21lenny4 and 2.6.26-24 to crash on demand very
easily. In none of the crashes do I get any kind of kernel log
messages (eg, soft lockup warnings).

2.6.34 wasn't in experimental any more by the time I had all this set
up. Instead I tried linux-image-2.6.35-rc5-686-bigmem version
2.6.35~rc5-1~experimental.1. I wasn't able to reproduce the problem
with 2.6.35.

> Even if you can't get a process dump, you can get some useful
> information with:
> 'd' - show locks held
> 'l' - show backtrace for active CPUs
> 'w' - show uninterruptible tasks

2.6.24 doesn't seem to have the "d" debug key. It says:

[ 723.072717] SysRq : HELP : loglevel0-8 reBoot Crashdump tErm Full
kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw
Sync showTasks Unmount shoW-blocked-tasks

But I have the other information. It's in the attached logfile. On
my coffee table I was able to set the serial rate to something
sensible :-).

The first 200 lines or so are just me setting things up and checking
that debug keys are working and the output is being collected. The
message
[ 612.446061] EXT3-fs: mounted filesystem with ordered data mode.
is due to the backup process mounting (readonly) its LVM snapshot.

I'll probably have to give the machine back for a bit now, so if you'd
like to think about what set of tests you'd like me to do next that
would be great. Next time it will be quicker to set up as I can keep
the disks in between :-).

Thanks.
Ian.


Thanks for using picocom
liberator:~> really picocom -b 9600 /dev/ttyUSB0 [1@1[1@1[1@5[1@2[1@2[1@0[1@0[1@0[1@0
picocom v1.4

port is : /dev/ttyUSB0
flowcontrol : none
baudrate is : 115200
parity is : none
databits are : 8
escape is : C-a
noinit is : no
noreset is : no
nolock is : no
send_cmd is : ascii_xfr -s -v -l10
receive_cmd is : rz -vv

Terminal ready



Thanks for using picocom
liberator:~> really picocom -b 115200 /dev/ttyUSB0 [1@9[1@6[1@0[1@0
picocom v1.4

port is : /dev/ttyUSB0
flowcontrol : none
baudrate is : 9600
parity is : none
databits are : 8
escape is : C-a
noinit is : no
noreset is : no
nolock is : no
send_cmd is : ascii_xfr -s -v -l10
receive_cmd is : rz -vv

Terminal ready

-rescue:~>
-rescue:~>
-rescue:~> really stty </de    115200

Thanks for using picocom
liberator:~> really picocom -b 9600 /dev/ttyUSB0 [1@1[1@1[1@1[1@5[1@2[1@0[1@0
picocom v1.4

port is : /dev/ttyUSB0
flowcontrol : none
baudrate is : 115200
parity is : none
databits are : 8
escape is : C-a
noinit is : no
noreset is : no
nolock is : no
send_cmd is : ascii_xfr -s -v -l10
receive_cmd is : rz -vv

Terminal ready

-rescue:~>
-rescue:~>
-rescue:~>
-rescue:~> d h  00:37:01 up 3 min, 3 users, load average: 1.33, 0.78, 0.32


-rescue:~>
-rescue:~> cat /proc/syske  /kernel/sysrq
1
-rescue:~>
-rescue:~> #
-rescue:~>
-rescue:~>
-rescue:~>
-rescue:~>
*** break sent ***
[ 415.071786] SysRq : Show Memory

-rescue:~>
-rescue:~>
-rescue:~>
-rescue:~>
-rescue:~> cat /pcat /etc/sysc
sysconfig/ sysctl.conf.dpkg-dist sysctl.d/
sysctl.conf sysctl.conf~
-rescue:~> cat /etc/sysc
sysconfig/ sysctl.conf.dpkg-dist sysctl.d/
sysctl.conf sysctl.conf~
-rescue:~> cat /etc/sysctl.conf
#
# /etc/sysctl.conf - Configuration file for setting system variables
# See sysctl.conf (5) for information.
#
#kernel.domainname = example.com
#net/ipv4/icmp_echo_ignore_broadcasts=1
kernel/printk= 4 4 1 4
fs/file-max= 200000
#fs/inode-max= 32768
-rescue:~> sysctl kernel/printk= 4 4 1 4
error: Malformed setting "kernel/printk="
error: "4" is an unknown key
error: "4" is an unknown key
error: "1" is an unknown key
error: "4" is an unknown key
-rescue:~> sysctl kernel/printk= 4 4 1 4printk[1@ = [1@'4 4 1 4'
kernel.printk = 4 4 1 4
error: Malformed setting "="
error: "4 4 1 4" is an unknown key
-rescue:~> sysctl kernel/printk = '4 4 1 4' 
kernel.printk = 4 4 1 4
error: Malformed setting "="
error: "4" is an unknown key
error: "4" is an unknown key
error: "1" is an unknown key
error: "4" is an unknown key
-rescue:~> sysctl kernel/printk = 4 4 1 4kernel/printk
kernel.printk = 4 4 1 4
error: "4" is an unknown key
error: "4" is an unknown key
error: "1" is an unknown key
error: "4" is an unknown key
-rescue:~> man sysctl
[?1049h[?1h=SYSCTL(8) SYSCTL(8)



NAME
sysctl - configure kernel parameters at runtime

SYNOPSIS
sysctl [-n] [-e] variable ...
sysctl [-n] [-e] [-q] -w variable=value ...
sysctl [-n] [-e] [-q] -p [filename]
sysctl [-n] [-e] -a
sysctl [-n] [-e] -A

DESCRIPTION
sysctl is used to modify kernel parameters at runtime. The parameters
available are those listed under /proc/sys/. Procfs is required for
sysctl support in Linux. You can use sysctl to both read and write
sysctl data.

PARAMETERS
variable
The name of a key to read from. An example is kernel.ostype.
 Manual page sysctl(8) line 1
gzip: stdout: No space left on device

[?1l>[?1049l-rescue:~> man sysctlsysctl kernel/printk 4 4 1 4[1@=[1@'4 4 1 4'
error: permission denied on key 'kernel.printk'
-rescue:~> sysctl kernel/printk='4 4 1 4'eal   
-rescue:~> [1@r[1@e[1@a[1@l[1@l[1@y[1@
kernel.printk = 4 4 1 4
-rescue:~> really sysctl kernel/printk='4 4 1 4'[1@7
kernel.printk = 7 4 1 4
-rescue:~> really sysctl kernel/printk='7 4 1 4''[1@0
kernel.printk = 0 4 1 4
-rescue:~>
*** break sent ***
[ 551.797057] SysRq : Show Memory

-rescue:~>
-rescue:~> really sysctl kernel/printk='0 4 1 4'7 4 1 4'
kernel.printk = 7 4 1 4
-rescue:~> 00:42:01 up 8 min, 3 users, load average: 0.52, 0.81, 0.47


*** break sent ***
[ 560.972713] SysRq : Show Memory
[ 560.972713] Mem-info:
[ 560.972713] DMA per-cpu:
[ 560.972713] CPU 0: hi: 0, btch: 1 usd: 0
[ 560.972713] CPU 1: hi: 0, btch: 1 usd: 0
[ 560.972713] CPU 2: hi: 0, btch: 1 usd: 0
[ 560.972713] CPU 3: hi: 0, btch: 1 usd: 0
[ 560.972713] CPU 4: hi: 0, btch: 1 usd: 0
[ 560.972713] CPU 5: hi: 0, btch: 1 usd: 0
[ 560.972713] CPU 6: hi: 0, btch: 1 usd: 0
[ 560.972713] CPU 7: hi: 0, btch: 1 usd: 0
[ 560.972713] Normal per-cpu:
[ 560.972713] CPU 0: hi: 186, btch: 31 usd: 83
[ 560.972713] CPU 1: hi: 186, btch: 31 usd: 51
[ 560.972713] CPU 2: hi: 186, btch: 31 usd: 66
[ 560.972713] CPU 3: hi: 186, btch: 31 usd: 44
[ 560.972713] CPU 4: hi: 186, btch: 31 usd: 131
[ 560.972713] CPU 5: hi: 186, btch: 31 usd: 104
[ 560.972713] CPU 6: hi: 186, btch: 31 usd: 160
[ 560.972713] CPU 7: hi: 186, btch: 31 usd: 39
[ 560.972713] HighMem per-cpu:
[ 560.972713] CPU 0: hi: 186, btch: 31 usd: 166
[ 560.972713] CPU 1: hi: 186, btch: 31 usd: 34
[ 560.972713] CPU 2: hi: 186, btch: 31 usd: 147
[ 560.972713] CPU 3: hi: 186, btch: 31 usd: 175
[ 560.972713] CPU 4: hi: 186, btch: 31 usd: 48
[ 560.972713] CPU 5: hi: 186, btch: 31 usd: 157
[ 560.972713] CPU 6: hi: 186, btch: 31 usd: 86
[ 560.972713] CPU 7: hi: 186, btch: 31 usd: 10
[ 560.972713] Active:10403 inactive:29112 dirty:49 writeback:0 unstable:0
[ 560.972713] free:984661 slab:4007 mapped:1923 pagetables:184 bounce:0
[ 560.972713] DMA free:12820kB min:68kB low:84kB high:100kB active:0kB inactive:0kB present:16256kB pages_scanned:0 all_unreclaimable? no
[ 560.972713] lowmem_reserve[]: 0 873 5064 5064
[ 560.972713] Normal free:818384kB min:3744kB low:4680kB high:5616kB active:5128kB inactive:4820kB present:894080kB pages_scanned:0 all_unreclaimable? no
[ 560.972713] lowmem_reserve[]: 0 0 33528 33528
[ 560.972713] HighMem free:3107440kB min:512kB low:5008kB high:9504kB active:36484kB inactive:111628kB present:4291584kB pages_scanned:0 all_unreclaimable? no
[ 560.972713] lowmem_reserve[]: 0 0 0 0
[ 560.972713] DMA: 5*4kB 4*8kB 4*16kB 3*32kB 3*64kB 3*128kB 1*256kB 1*512kB 1*1024kB 1*2048kB 2*4096kB = 12820kB
[ 560.972713] Normal: 62*4kB 15*8kB 16*16kB 11*32kB 42*64kB 21*128kB 12*256kB 4*512kB 2*1024kB 5*2048kB 194*4096kB = 818384kB
[ 560.972713] HighMem: 120*4kB 28*8kB 13*16kB 9*32kB 3*64kB 4*128kB 1*256kB 1*512kB 2*1024kB 1*2048kB 757*4096kB = 3107440kB
[ 560.972713] 36625 total pagecache pages
[ 560.972713] Swap cache: add 0, delete 0, find 0/0
[ 560.972713] Free swap = 8388592kB
[ 560.972713] Total swap = 8388592kB
[ 560.972713] 1310720 pages of RAM
[ 560.972713] 1081344 pages of HIGHMEM
[ 560.972713] 276248 reserved pages
[ 560.972713] 11078 pages shared
[ 560.972713] 0 pages swap cached
[ 560.972713] 49 pages dirty
[ 560.972713] 0 pages writeback
[ 560.972713] 1923 pages mapped
[ 560.972713] 4007 pages slab
[ 560.972713] 184 pages pagetables

-rescue:~>
-rescue:~>
-rescue:~> [ 612.446061] kjournald starting. Commit interval 5 seconds
[ 612.446061] EXT3-fs: mounted filesystem with ordered data mode.

-rescue:~>
-rescue:~>
-rescue:~>
-rescue:~> echo hi
hi
-rescue:~>
-rescue:~>
-rescue:~>
-rescue:~> ls





*** break sent ***
[ 677.678494] SysRq : HELP : loglevel0-8 reBoot Crashdump tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks

*** break sent ***
[ 694.121182] SysRq : Show Blocked State
[ 694.121182] task PC stack pid father
[ 694.121182] pdflush D 00000000 0 263 2
[ 694.121182] f75a3760 00000046 c011f085 00000000 00000003 f75a38ec c3819020 00000000
[ 694.121182] 00000001 00011b31 c012126f 00000000 00000000 00000000 0000030c ffffffff
[ 694.121182] f6592ac0 f6592b14 f6592af4 08fd0900 f89cf352 00000000 f75a3760 c01222b0
[ 694.121182] Call Trace:
[ 694.121182] [<c011f085>] __wake_up_common+0x2e/0x58
[ 694.121182] [<c012126f>] __wake_up+0x29/0x39
[ 694.121182] [<f89cf352>] wait_barrier+0x7e/0xb7 [raid1]
[ 694.121182] [<c01222b0>] default_wake_function+0x0/0x8
[ 694.121182] [<f89d0b84>] make_request+0x70/0x5a0 [raid1]
[ 694.121182] [<c01dc690>] generic_make_request+0x34d/0x37b
[ 694.121182] [<c015fc05>] mempool_alloc+0x1c/0xba
[ 694.121182] [<c01dd76c>] submit_bio+0xc6/0xcd
[ 694.121182] [<c019d2bf>] bio_alloc_bioset+0x9b/0xf3
[ 694.121182] [<c0199e27>] submit_bh+0xcf/0xed
[ 694.121182] [<c019b7d2>] __block_write_full_page+0x1fa/0x2da
[ 694.121182] [<f8c8c3fa>] ext3_get_block+0x0/0xd3 [ext3]
[ 694.121182] [<c019b993>] block_write_full_page+0xe1/0xea
[ 694.121182] [<f8c8c3fa>] ext3_get_block+0x0/0xd3 [ext3]
[ 694.121182] [<f8c8d889>] ext3_ordered_writepage+0xab/0x13d [ext3]
[ 694.121182] [<f8c8b030>] bget_one+0x0/0x7 [ext3]
[ 694.121182] [<c01628ed>] __writepage+0x8/0x21
[ 694.121182] [<c0162d68>] write_cache_pages+0x16a/0x27b
[ 694.121182] [<c01628e5>] __writepage+0x0/0x21
[ 694.121182] [<c0162e93>] generic_writepages+0x1a/0x21
[ 694.121182] [<c0162ec3>] do_writepages+0x29/0x30
[ 694.121182] [<c0196949>] __writeback_single_inode+0x127/0x251
[ 694.121182] [<f89626fe>] dm_table_any_congested+0x32/0x4e [dm_mod]
[ 694.121182] [<c0196d40>] sync_sb_inodes+0x17c/0x233
[ 694.121182] [<c01970b7>] writeback_inodes+0x53/0x99
[ 694.121182] [<c0163ad9>] pdflush+0x0/0x1cc
[ 694.121182] [<c0163794>] wb_kupdate+0x7b/0xdb
[ 694.121182] [<c0163c08>] pdflush+0x12f/0x1cc
[ 694.121182] [<c0163719>] wb_kupdate+0x0/0xdb
[ 694.121182] [<c013876b>] kthread+0x38/0x5d
[ 694.121182] [<c0138733>] kthread+0x0/0x5d
[ 694.121182] [<c01094f7>] kernel_thread_helper+0x7/0x10
[ 694.121182] =======================
[ 694.121182] kjournald D 00000000 0 1550 2
[ 694.121182] f78984a0 00000046 c011f085 00000000 00000003 f789862c c3866020 00000007
[ 694.121182] 00000001 000122e8 c012126f 00000000 00000000 00000000 00000000 ffffffff
[ 694.121182] f6592ac0 f6592b14 f6592af4 08fd0900 f89cf352 00000000 f78984a0 c01222b0
[ 694.121182] Call Trace:
[ 694.121182] [<c011f085>] __wake_up_common+0x2e/0x58
[ 694.121182] [<c012126f>] __wake_up+0x29/0x39
[ 694.121182] [<f89cf352>] wait_barrier+0x7e/0xb7 [raid1]
[ 694.121182] [<c01222b0>] default_wake_function+0x0/0x8
[ 694.121182] [<f89d0b84>] make_request+0x70/0x5a0 [raid1]
[ 694.121182] [<c01dc690>] generic_make_request+0x34d/0x37b
[ 694.121182] [<c015fc05>] mempool_alloc+0x1c/0xba
[ 694.121182] [<c01dd76c>] submit_bio+0xc6/0xcd
[ 694.121182] [<c019d2bf>] bio_alloc_bioset+0x9b/0xf3
[ 694.121182] [<c0199e27>] submit_bh+0xcf/0xed
[ 694.121182] [<f8c59d3b>] journal_commit_transaction+0x690/0xb3d [jbd]
[ 694.121182] [<c01309b4>] lock_timer_base+0x19/0x35
[ 694.121182] [<f8c5c468>] kjournald+0xa5/0x1c6 [jbd]
[ 694.121182] [<c013882c>] autoremove_wake_function+0x0/0x2d
[ 694.121182] [<f8c5c3c3>] kjournald+0x0/0x1c6 [jbd]
[ 694.121182] [<c013876b>] kthread+0x38/0x5d
[ 694.121182] [<c0138733>] kthread+0x0/0x5d
[ 694.121182] [<c01094f7>] kernel_thread_helper+0x7/0x10
[ 694.121182] =======================
[ 694.121182] md127_resync D 3ce2eced 0 2324 2
[ 694.121182] f68f1b80 00000046 c011f085 3ce2eced 00000089 f68f1d0c c383a020 00000003
[ 694.121182] 00000001 00000282 00000001 00000000 00000000 00000003 f6592ac0 f6592b14
[ 694.121182] f6592ac0 f6592b14 f6592af4 f6592ac0 f89cf48b 00000000 f68f1b80 c01222b0
[ 694.121182] Call Trace:
[ 694.121182] [<c011f085>] __wake_up_common+0x2e/0x58
[ 694.121182] [<f89cf48b>] raise_barrier+0x100/0x133 [raid1]
[ 694.121182] [<c01222b0>] default_wake_function+0x0/0x8
[ 694.121182] [<f89d1291>] sync_request+0x1dd/0x59a [raid1]
[ 694.121182] [<f89e8b51>] md_wakeup_thread+0x1e/0x20 [md_mod]
[ 694.121182] [<f89ef9f3>] md_do_sync+0x616/0xa9f [md_mod]
[ 694.121182] [<c02c8f8d>] schedule+0x63b/0x66d
[ 694.121182] [<f89ef310>] md_thread+0x0/0xcd [md_mod]
[ 694.121182] [<f89ef3c7>] md_thread+0xb7/0xcd [md_mod]
[ 694.121182] [<f89ef310>] md_thread+0x0/0xcd [md_mod]
[ 694.121182] [<c013876b>] kthread+0x38/0x5d
[ 694.121182] [<c0138733>] kthread+0x0/0x5d
[ 694.121182] [<c01094f7>] kernel_thread_helper+0x7/0x10
[ 694.121182] =======================
[ 694.121182] kjournald D 00000000 0 2483 2
[ 694.121182] f7670e20 00000046 c011f085 00000000 00000003 f7670fac c3819020 00000000
[ 694.121182] 00000001 00014482 c012126f 00000000 00000000 00000000 00000000 ffffffff
[ 694.121182] f6592ac0 f6592b14 f6592af4 08fd0900 f89cf352 00000000 f7670e20 c01222b0
[ 694.121182] Call Trace:
[ 694.121182] [<c011f085>] __wake_up_common+0x2e/0x58
[ 694.121182] [<c012126f>] __wake_up+0x29/0x39
[ 694.121182] [<f89cf352>] wait_barrier+0x7e/0xb7 [raid1]
[ 694.121182] [<c01222b0>] default_wake_function+0x0/0x8
[ 694.121182] [<f89d0b84>] make_request+0x70/0x5a0 [raid1]
[ 694.121182] [<c01dc690>] generic_make_request+0x34d/0x37b
[ 694.121182] [<c015fc05>] mempool_alloc+0x1c/0xba
[ 694.121182] [<c01dd76c>] submit_bio+0xc6/0xcd
[ 694.121182] [<c019d2bf>] bio_alloc_bioset+0x9b/0xf3
[ 694.121182] [<c0199e27>] submit_bh+0xcf/0xed
[ 694.121182] [<f8c59d3b>] journal_commit_transaction+0x690/0xb3d [jbd]
[ 694.121182] [<c01309b4>] lock_timer_base+0x19/0x35
[ 694.121182] [<f8c5c468>] kjournald+0xa5/0x1c6 [jbd]
[ 694.121182] [<c013882c>] autoremove_wake_function+0x0/0x2d
[ 694.121182] [<f8c5c3c3>] kjournald+0x0/0x1c6 [jbd]
[ 694.121182] [<c013876b>] kthread+0x38/0x5d
[ 694.121182] [<c0138733>] kthread+0x0/0x5d
[ 694.121182] [<c01094f7>] kernel_thread_helper+0x7/0x10
[ 694.121182] =======================
[ 694.121182] kjournald D d3d0808b 0 2484 2
[ 694.121182] f61775a0 00000046 c38372f8 d3d0808b 00000089 f617772c c383a020 00000003
[ 694.121182] c383a454 c38372f8 000048f9 00000000 d632cf95 00000089 00000246 c013893b
[ 694.121182] f613ec14 f44a7cfc f613ec74 f613ec00 f8c5976b f44a7cc0 c383a020 f593d800
[ 694.121182] Call Trace:
[ 694.121182] [<c013893b>] prepare_to_wait+0x12/0x4d
[ 694.121182] [<f8c5976b>] journal_commit_transaction+0xc0/0xb3d [jbd]
[ 694.121182] [<c02c8f8d>] schedule+0x63b/0x66d
[ 694.121182] [<c013882c>] autoremove_wake_function+0x0/0x2d
[ 694.121182] [<c0130a14>] try_to_del_timer_sync+0x44/0x4a
[ 694.121182] [<f8c5c468>] kjournald+0xa5/0x1c6 [jbd]
[ 694.121182] [<c013882c>] autoremove_wake_function+0x0/0x2d
[ 694.121182] [<f8c5c3c3>] kjournald+0x0/0x1c6 [jbd]
[ 694.121182] [<c013876b>] kthread+0x38/0x5d
[ 694.121182] [<c0138733>] kthread+0x0/0x5d
[ 694.121182] [<c01094f7>] kernel_thread_helper+0x7/0x10
[ 694.121182] =======================
[ 694.121182] kjournald D 00000000 0 2485 2
[ 694.121182] f6a651c0 00000046 c011f085 00000000 00000003 f6a6534c c3845020 00000004
[ 694.121182] 00000001 00013f05 c012126f 00000000 00000000 00000000 0000030c ffffffff
[ 694.121182] f6592ac0 f6592b14 f6592af4 08fd0900 f89cf352 00000000 f6a651c0 c01222b0
[ 694.121182] Call Trace:
[ 694.121182] [<c011f085>] __wake_up_common+0x2e/0x58
[ 694.121182] [<c012126f>] __wake_up+0x29/0x39
[ 694.121182] [<f89cf352>] wait_barrier+0x7e/0xb7 [raid1]
[ 694.121182] [<c01222b0>] default_wake_function+0x0/0x8
[ 694.121182] [<f89d0b84>] make_request+0x70/0x5a0 [raid1]
[ 694.121182] [<c0161cc3>] get_page_from_freelist+0xc1/0x3e9
[ 694.121182] [<c01dc690>] generic_make_request+0x34d/0x37b
[ 694.121182] [<c015fc05>] mempool_alloc+0x1c/0xba
[ 694.121182] [<c01dd76c>] submit_bio+0xc6/0xcd
[ 694.121182] [<c019d2bf>] bio_alloc_bioset+0x9b/0xf3
[ 694.121182] [<c0199e27>] submit_bh+0xcf/0xed
[ 694.121182] [<c019ccab>] sync_dirty_buffer+0x4d/0x91
[ 694.121182] [<f8c59ed6>] journal_commit_transaction+0x82b/0xb3d [jbd]
[ 694.121182] [<c01309b4>] lock_timer_base+0x19/0x35
[ 694.121182] [<c0130a14>] try_to_del_timer_sync+0x44/0x4a
[ 694.121182] [<f8c5c468>] kjournald+0xa5/0x1c6 [jbd]
[ 694.121182] [<c013882c>] autoremove_wake_function+0x0/0x2d
[ 694.121182] [<f8c5c3c3>] kjournald+0x0/0x1c6 [jbd]
[ 694.121182] [<c013876b>] kthread+0x38/0x5d
[ 694.121182] [<c0138733>] kthread+0x0/0x5d
[ 694.121182] [<c01094f7>] kernel_thread_helper+0x7/0x10
[ 694.121182] =======================
[ 694.121182] summer D 00000000 0 3433 3430
[ 694.121182] f7806560 00000082 f6827a90 00000000 00000003 f78066ec c3866020 00000007
[ 694.121182] 00000001 00011aaa c012126f 00000000 00000000 00000000 00000000 ffffffff
[ 694.121182] f6592ac0 f6592b14 f6592af4 08fd0900 f89cf352 00000000 f7806560 c01222b0
[ 694.121182] Call Trace:
[ 694.121182] [<c012126f>] __wake_up+0x29/0x39
[ 694.121182] [<f89cf352>] wait_barrier+0x7e/0xb7 [raid1]
[ 694.121182] [<c01222b0>] default_wake_function+0x0/0x8
[ 694.121182] [<f89d0b84>] make_request+0x70/0x5a0 [raid1]
[ 694.121182] [<c01dc690>] generic_make_request+0x34d/0x37b
[ 694.121182] [<c01dd76c>] submit_bio+0xc6/0xcd
[ 694.121182] [<c015dbd9>] add_to_page_cache+0x64/0x7d
[ 694.121182] [<c01a126d>] mpage_end_io_read+0x0/0x53
[ 694.121182] [<c01a0546>] mpage_bio_submit+0x19/0x1d
[ 694.121182] [<c01a136e>] mpage_readpages+0xae/0xb8
[ 694.121182] [<f8c8ba5f>] ext3_readpages+0x0/0x15 [ext3]
[ 694.121182] [<c0163e40>] __do_page_cache_readahead+0xea/0x163
[ 694.121182] [<f8c8c3fa>] ext3_get_block+0x0/0xd3 [ext3]
[ 694.121182] [<c016418d>] page_cache_sync_readahead+0x15/0x19
[ 694.121182] [<c015f429>] generic_file_aio_read+0x200/0x4e1
[ 694.121182] [<c016e9a7>] vma_adjust+0x1c6/0x399
[ 694.121182] [<c017e4d2>] do_sync_read+0xbf/0xfe
[ 694.121182] [<c013882c>] autoremove_wake_function+0x0/0x2d
[ 694.121182] [<c01c4da9>] security_file_permission+0xc/0xd
[ 694.121182] [<c017e413>] do_sync_read+0x0/0xfe
[ 694.121182] [<c017ec62>] vfs_read+0x81/0x11e
[ 694.121182] [<c017f0b3>] sys_read+0x3c/0x63
[ 694.121182] [<c0108857>] sysenter_past_esp+0x78/0xb1
[ 694.121182] =======================
[ 694.121182] ls D f48dc588 0 3465 3453
[ 694.121182] f7670a00 00000082 f48dc4e0 f48dc588 f3b735c0 f7670b8c c3850020 00000005
[ 694.121182] f6390b40 00011d6d c019a2ea 00000400 00000000 00000000 00000000 ffffffff
[ 694.121182] f4c5be70 f60ff2c0 c3802624 f7c4047c f8c58617 00000000 f48fc70c 00000000
[ 694.121182] Call Trace:
[ 694.121182] [<c019a2ea>] __getblk+0x27/0x24e
[ 694.121182] [<f8c58617>] do_get_write_access+0x1a4/0x331 [jbd]
[ 694.121182] [<c0138859>] wake_bit_function+0x0/0x3c
[ 694.121182] [<f8c587bc>] journal_get_write_access+0x18/0x26 [jbd]
[ 694.121182] [<f8c964f7>] __ext3_journal_get_write_access+0x13/0x32 [ext3]
[ 694.121182] [<f8c8b716>] ext3_reserve_inode_write+0x2d/0x5d [ext3]
[ 694.121182] [<f8c8b757>] ext3_mark_inode_dirty+0x11/0x27 [ext3]
[ 694.121182] [<f8c8df08>] ext3_dirty_inode+0x50/0x63 [ext3]
[ 694.121182] [<c0196f5b>] __mark_inode_dirty+0x21/0x12a
[ 694.121182] [<c018f21e>] touch_atime+0xc7/0xd1
[ 694.121182] [<c015d5fa>] generic_file_mmap+0x2a/0x3e
[ 694.121182] [<c016f604>] mmap_region+0x1c7/0x392
[ 694.121182] [<c016fb07>] do_mmap_pgoff+0x25d/0x2b0
[ 694.121182] [<c0167004>] sys_mmap_pgoff+0x9b/0xc2
[ 694.121182] [<c01088d2>] syscall_call+0x7/0xb
[ 694.121182] [<c02c0000>] quirk_vt82c686_acpi+0x55/0x7b
[ 694.121182] =======================
[ 694.121182] bash D f3305be0 0 3466 3132
[ 694.121182] f597ca00 00000082 f1d7ac50 f3305be0 f41836a0 f597cb8c c385b020 00000006
[ 694.121182] f6390ae0 00012e32 c019a2ea 00000400 00000000 00000000 00000000 ffffffff
[ 694.121182] f5473d8c f60ff2c0 c380080c f7deeafc f8c58617 00000000 f48fcaa4 00000000
[ 694.121182] Call Trace:
[ 694.121182] [<c019a2ea>] __getblk+0x27/0x24e
[ 694.121182] [<f8c58617>] do_get_write_access+0x1a4/0x331 [jbd]
[ 694.121182] [<c0138859>] wake_bit_function+0x0/0x3c
[ 694.121182] [<f8c587bc>] journal_get_write_access+0x18/0x26 [jbd]
[ 694.121182] [<f8c964f7>] __ext3_journal_get_write_access+0x13/0x32 [ext3]
[ 694.121182] [<f8c8b716>] ext3_reserve_inode_write+0x2d/0x5d [ext3]
[ 694.121182] [<f8c8b757>] ext3_mark_inode_dirty+0x11/0x27 [ext3]
[ 694.121182] [<f8c8df08>] ext3_dirty_inode+0x50/0x63 [ext3]
[ 694.121182] [<c0196f5b>] __mark_inode_dirty+0x21/0x12a
[ 694.121182] [<c018f21e>] touch_atime+0xc7/0xd1
[ 694.121182] [<c015f6c3>] generic_file_aio_read+0x49a/0x4e1
[ 694.121182] [<c017e4d2>] do_sync_read+0xbf/0xfe
[ 694.121182] [<c013882c>] autoremove_wake_function+0x0/0x2d
[ 694.121182] [<f8c98905>] ext3_xattr_security_get+0x31/0x3b [ext3]
[ 694.121182] [<c01c4da9>] security_file_permission+0xc/0xd
[ 694.121182] [<c017e413>] do_sync_read+0x0/0xfe
[ 694.121182] [<c017ec62>] vfs_read+0x81/0x11e
[ 694.121182] [<c0181c56>] kernel_read+0x32/0x43
[ 694.121182] [<c0181d27>] prepare_binprm+0xc0/0xc4
[ 694.121182] [<c0182b07>] do_execve+0xd2/0x1c6
[ 694.121182] [<c010713b>] sys_execve+0x2a/0x4a
[ 694.121182] [<c0108857>] sysenter_past_esp+0x78/0xb1
[ 694.121182] [<c02c0000>] quirk_vt82c686_acpi+0x55/0x7b
[ 694.121182] =======================
[ 694.121182] cat D f3305ba8 0 3467 3311
[ 694.121182] f5824f20 00000086 f7031668 f3305ba8 f1d7ac88 f58250ac c385b020 00000006
[ 694.121182] f6390b40 000144cd c019a2ea 00000400 00000000 00000000 00000000 ffffffff
[ 694.121182] f4cdbe70 f60ff2c0 c3802624 f7c4047c f8c58617 00000000 f48fcbf8 00000000
[ 694.121182] Call Trace:
[ 694.121182] [<c019a2ea>] __getblk+0x27/0x24e
[ 694.121182] [<f8c58617>] do_get_write_access+0x1a4/0x331 [jbd]
[ 694.121182] [<c0138859>] wake_bit_function+0x0/0x3c
[ 694.121182] [<f8c587bc>] journal_get_write_access+0x18/0x26 [jbd]
[ 694.121182] [<f8c964f7>] __ext3_journal_get_write_access+0x13/0x32 [ext3]
[ 694.121182] [<f8c8b716>] ext3_reserve_inode_write+0x2d/0x5d [ext3]
[ 694.121182] [<f8c8b757>] ext3_mark_inode_dirty+0x11/0x27 [ext3]
[ 694.121182] [<f8c8df08>] ext3_dirty_inode+0x50/0x63 [ext3]
[ 694.121182] [<c0196f5b>] __mark_inode_dirty+0x21/0x12a
[ 694.121182] [<c018f21e>] touch_atime+0xc7/0xd1
[ 694.121182] [<c015d5fa>] generic_file_mmap+0x2a/0x3e
[ 694.121182] [<c016f604>] mmap_region+0x1c7/0x392
[ 694.121182] [<c016fb07>] do_mmap_pgoff+0x25d/0x2b0
[ 694.121182] [<c0167004>] sys_mmap_pgoff+0x9b/0xc2
[ 694.121182] [<c01088d2>] syscall_call+0x7/0xb
[ 694.121182] [<c02c0000>] quirk_vt82c686_acpi+0x55/0x7b
[ 694.121182] =======================
[ 694.121182] cron D f71b3908 0 3468 2969
[ 694.121182] f7b23200 00000082 f7057160 f71b3908 f71074a8 f7b2338c c385b020 00000006
[ 694.121182] f6390960 000144ea c019a2ea 00000400 00000000 00000000 00000000 ffffffff
[ 694.121182] f54cbd80 f60ff2c0 c3800c74 f7dec6ec f8c58617 00000000 f48fca04 00000000
[ 694.121182] Call Trace:
[ 694.121182] [<c019a2ea>] __getblk+0x27/0x24e
[ 694.121182] [<f8c58617>] do_get_write_access+0x1a4/0x331 [jbd]
[ 694.121182] [<c0138859>] wake_bit_function+0x0/0x3c
[ 694.121182] [<f8c587bc>] journal_get_write_access+0x18/0x26 [jbd]
[ 694.121182] [<f8c964f7>] __ext3_journal_get_write_access+0x13/0x32 [ext3]
[ 694.121182] [<f8c8b716>] ext3_reserve_inode_write+0x2d/0x5d [ext3]
[ 694.121182] [<f8c8b757>] ext3_mark_inode_dirty+0x11/0x27 [ext3]
[ 694.121182] [<f8c8df08>] ext3_dirty_inode+0x50/0x63 [ext3]
[ 694.121182] [<c0196f5b>] __mark_inode_dirty+0x21/0x12a
[ 694.121182] [<c018f21e>] touch_atime+0xc7/0xd1
[ 694.121182] [<c01864e2>] __link_path_walk+0x7d8/0xb24
[ 694.121182] [<c018d022>] __d_lookup+0x98/0xd7
[ 694.121182] [<c0186865>] path_walk+0x37/0x70
[ 694.121182] [<c0186b14>] do_path_lookup+0x122/0x184
[ 694.121182] [<c01874f6>] __path_lookup_intent_open+0x42/0x72
[ 694.121182] [<c0187575>] path_lookup_open+0xf/0x13
[ 694.121182] [<c0187600>] do_filp_open+0x87/0x684
[ 694.121182] [<c011b3e1>] do_page_fault+0x4b2/0x8f9
[ 694.121182] [<c011b448>] do_page_fault+0x519/0x8f9
[ 694.121182] [<c017ce8c>] do_sys_open+0x40/0xb0
[ 694.121182] [<c017cf40>] sys_open+0x1e/0x23
[ 694.121182] [<c01088d2>] syscall_call+0x7/0xb
[ 694.121182] [<c02c0000>] quirk_vt82c686_acpi+0x55/0x7b
[ 694.121182] =======================
[ 694.121182] cron D f1e4ce80 0 3469 2969
[ 694.121182] f7661620 00000082 f3b3b390 f1e4ce80 f1e4cef0 f76617ac c3866020 00000007
[ 694.121182] f6390960 000144ea c019a2ea 00000400 00000000 00000000 00000000 ffffffff
[ 694.121182] f442ddc8 f60ff2c0 c3802b10 f7c40684 f8c58617 00000000 f48fca18 00000000
[ 694.121182] Call Trace:
[ 694.121182] [<c019a2ea>] __getblk+0x27/0x24e
[ 694.121182] [<f8c58617>] do_get_write_access+0x1a4/0x331 [jbd]
[ 694.121182] [<c0138859>] wake_bit_function+0x0/0x3c
[ 694.121182] [<f8c587bc>] journal_get_write_access+0x18/0x26 [jbd]
[ 694.121182] [<f8c964f7>] __ext3_journal_get_write_access+0x13/0x32 [ext3]
[ 694.121182] [<f8c8b716>] ext3_reserve_inode_write+0x2d/0x5d [ext3]
[ 694.121182] [<f8c8b757>] ext3_mark_inode_dirty+0x11/0x27 [ext3]
[ 694.121182] [<f8c8df08>] ext3_dirty_inode+0x50/0x63 [ext3]
[ 694.121182] [<c0196f5b>] __mark_inode_dirty+0x21/0x12a
[ 694.121182] [<c018f21e>] touch_atime+0xc7/0xd1
[ 694.121182] [<c015f6c3>] generic_file_aio_read+0x49a/0x4e1
[ 694.121182] [<c017e4d2>] do_sync_read+0xbf/0xfe
[ 694.121182] [<c013882c>] autoremove_wake_function+0x0/0x2d
[ 694.121182] [<c01c4da9>] security_file_permission+0xc/0xd
[ 694.121182] [<c017e413>] do_sync_read+0x0/0xfe
[ 694.121182] [<c017ec62>] vfs_read+0x81/0x11e
[ 694.121182] [<c017f0b3>] sys_read+0x3c/0x63
[ 694.121182] [<c01088d2>] syscall_call+0x7/0xb
[ 694.121182] [<c02c0000>] quirk_vt82c686_acpi+0x55/0x7b
[ 694.121182] =======================
[ 694.121182] cron D 00000002 0 3470 2969
[ 694.121182] f76605a0 00000086 f799eaf8 00000002 00000000 f766072c c3845020 00000004
[ 694.121182] 00000000 000144ce 0003404e 00000000 00000000 00000000 00000000 ffffffff
[ 694.121182] f613ec38 f613ec00 f4433e00 f44a7cc0 f8c58a05 f48fc360 00000002 00000000
[ 694.121182] Call Trace:
[ 694.121182] [<f8c58a05>] start_this_handle+0x23b/0x2aa [jbd]
[ 694.121182] [<c013882c>] autoremove_wake_function+0x0/0x2d
[ 694.121182] [<f8c58af1>] journal_start+0x7d/0xa9 [jbd]
[ 694.121182] [<f8c8ded9>] ext3_dirty_inode+0x21/0x63 [ext3]
[ 694.121182] [<c0196f5b>] __mark_inode_dirty+0x21/0x12a
[ 694.121182] [<c018f21e>] touch_atime+0xc7/0xd1
[ 694.121182] [<c015f6c3>] generic_file_aio_read+0x49a/0x4e1
[ 694.121182] [<c017e4d2>] do_sync_read+0xbf/0xfe
[ 694.121182] [<c013882c>] autoremove_wake_function+0x0/0x2d
[ 694.121182] [<c018c410>] fcntl_setlk+0x202/0x22a
[ 694.121182] [<c01c4da9>] security_file_permission+0xc/0xd
[ 694.121182] [<c017e413>] do_sync_read+0x0/0xfe
[ 694.121182] [<c017ec62>] vfs_read+0x81/0x11e
[ 694.121182] [<c017f0b3>] sys_read+0x3c/0x63
[ 694.121182] [<c0108857>] sysenter_past_esp+0x78/0xb1
[ 694.121182] [<c02c0000>] quirk_vt82c686_acpi+0x55/0x7b
[ 694.121182] =======================
[ 694.121182] sh D f7c2cef0 0 3472 3471
[ 694.121182] f7b9ce20 00000086 f7c11e10 f7c2cef0 f7c2c2b0 f7b9cfac c3866020 00000007
[ 694.121182] f6390960 000144ea c019a2ea 00000400 00000000 00000000 00000000 ffffffff
[ 694.121182] f4547d80 f60ff2c0 c3800c74 f7dec6ec f8c58617 00000000 f48fc5f4 00000000
[ 694.121182] Call Trace:
[ 694.121182] [<c019a2ea>] __getblk+0x27/0x24e
[ 694.121182] [<f8c58617>] do_get_write_access+0x1a4/0x331 [jbd]
[ 694.121182] [<c0138859>] wake_bit_function+0x0/0x3c
[ 694.121182] [<f8c587bc>] journal_get_write_access+0x18/0x26 [jbd]
[ 694.121182] [<f8c964f7>] __ext3_journal_get_write_access+0x13/0x32 [ext3]
[ 694.121182] [<f8c8b716>] ext3_reserve_inode_write+0x2d/0x5d [ext3]
[ 694.121182] [<f8c8b757>] ext3_mark_inode_dirty+0x11/0x27 [ext3]
[ 694.121182] [<f8c8df08>] ext3_dirty_inode+0x50/0x63 [ext3]
[ 694.121182] [<c0196f5b>] __mark_inode_dirty+0x21/0x12a
[ 694.121182] [<c018f21e>] touch_atime+0xc7/0xd1
[ 694.121182] [<c01864e2>] __link_path_walk+0x7d8/0xb24
[ 694.121182] [<c018d022>] __d_lookup+0x98/0xd7
[ 694.121182] [<c0186865>] path_walk+0x37/0x70
[ 694.121182] [<c0186b14>] do_path_lookup+0x122/0x184
[ 694.121182] [<c01874f6>] __path_lookup_intent_open+0x42/0x72
[ 694.121182] [<c0187575>] path_lookup_open+0xf/0x13
[ 694.121182] [<c0187600>] do_filp_open+0x87/0x684
[ 694.121182] [<c011b3e1>] do_page_fault+0x4b2/0x8f9
[ 694.121182] [<c011b448>] do_page_fault+0x519/0x8f9
[ 694.121182] [<c017ce8c>] do_sys_open+0x40/0xb0
[ 694.121182] [<c017cf40>] sys_open+0x1e/0x23
[ 694.121182] [<c01088d2>] syscall_call+0x7/0xb
[ 694.121182] [<c02c0000>] quirk_vt82c686_acpi+0x55/0x7b
[ 694.121182] =======================
[ 694.121182] Sched Debug Version: v0.07, 2.6.26-2-686-bigmem #1
[ 694.121182] now at 639513.043198 msecs
[ 694.121182] .sysctl_sched_latency : 80.000000
[ 694.121182] .sysctl_sched_min_granularity : 16.000000
[ 694.121182] .sysctl_sched_wakeup_granularity : 40.000000
[ 694.121182] .sysctl_sched_child_runs_first : 0.000001
[ 694.121182] .sysctl_sched_features : 895
[ 694.121182]
[ 694.121182] cpu#0, 1862.045 MHz
[ 694.121182] .nr_running : 0
[ 694.121182] .load : 0
[ 694.121182] .nr_switches : 72329
[ 694.121182] .nr_load_updates : 18539
[ 694.121182] .nr_uninterruptible : 4294967243
[ 694.121182] .jiffies : 84895
[ 694.121182] .next_balance : 0.084896
[ 694.121182] .curr->pid : 0
[ 694.121182] .clock : 639560.113202
[ 694.121182] .cpu_load[0] : 0
[ 694.121182] .cpu_load[1] : 0
[ 694.121182] .cpu_load[2] : 0
[ 694.121182] .cpu_load[3] : 0
[ 694.121182] .cpu_load[4] : 26
[ 694.121182]
[ 694.121182] cfs_rq[0]:
[ 694.121182] .exec_clock : 0.000000
[ 694.121182] .MIN_vruntime : 0.000001
[ 694.121182] .min_vruntime : 16348.622085
[ 694.121182] .max_vruntime : 0.000001
[ 694.121182] .spread : 0.000000
[ 694.121182] .spread0 : 0.000000
[ 694.121182] .nr_running : 0
[ 694.121182] .load : 0
[ 694.121182] .nr_spread_over : 0
[ 694.121182]
[ 694.121182] runnable tasks:
[ 694.121182] task PID tree-key switches prio exec-runtime sum-exec sum-sleep
[ 694.121182] ----------------------------------------------------------------------------------------------------------
[ 694.121182]
[ 694.121182] cpu#1, 1862.045 MHz
[ 694.121182] .nr_running : 0
[ 694.121182] .load : 0
[ 694.121182] .nr_switches : 29556
[ 694.121182] .nr_load_updates : 5341
[ 694.121182] .nr_uninterruptible : 4294967270
[ 694.121182] .jiffies : 84932
[ 694.121182] .next_balance : 0.084934
[ 694.121182] .curr->pid : 0
[ 694.121182] .clock : 639080.236160
[ 694.121182] .cpu_load[0] : 0
[ 694.121182] .cpu_load[1] : 0
[ 694.121182] .cpu_load[2] : 0
[ 694.121182] .cpu_load[3] : 0
[ 694.121182] .cpu_load[4] : 0
[ 694.121182]
[ 694.121182] cfs_rq[1]:
[ 694.121182] .exec_clock : 0.000000
[ 694.121182] .MIN_vruntime : 0.000001
[ 694.121182] .min_vruntime : 7320.183309
[ 694.121182] .max_vruntime : 0.000001
[ 694.121182] .spread : 0.000000
[ 694.121182] .spread0 : -9028.438776
[ 694.121182] .nr_running : 0
[ 694.121182] .load : 0
[ 694.121182] .nr_spread_over : 0
[ 694.121182]
[ 694.121182] runnable tasks:
[ 694.121182] task PID tree-key switches prio exec-runtime sum-exec sum-sleep
[ 694.121182] ----------------------------------------------------------------------------------------------------------
[ 694.121182]
[ 694.121182] cpu#2, 1862.045 MHz
[ 694.121182] .nr_running : 0
[ 694.121182] .load : 0
[ 694.121182] .nr_switches : 66329
[ 694.121182] .nr_load_updates : 5613
[ 694.121182] .nr_uninterruptible : 4294967199
[ 694.121182] .jiffies : 84970
[ 694.121182] .next_balance : 0.084972
[ 694.121182] .curr->pid : 0
[ 694.121182] .clock : 639084.061939
[ 694.121182] .cpu_load[0] : 0
[ 694.121182] .cpu_load[1] : 0
[ 694.121182] .cpu_load[2] : 0
[ 694.121182] .cpu_load[3] : 0
[ 694.121182] .cpu_load[4] : 60
[ 694.121182]
[ 694.121182] cfs_rq[2]:
[ 694.121182] .exec_clock : 0.000000
[ 694.121182] .MIN_vruntime : 0.000001
[ 694.121182] .min_vruntime : 12327.667563
[ 694.121182] .max_vruntime : 0.000001
[ 694.121182] .spread : 0.000000
[ 694.121182] .spread0 : -4020.954522
[ 694.121182] .nr_running : 0
[ 694.121182] .load : 0
[ 694.121182] .nr_spread_over : 0
[ 694.121182]
[ 694.121182] runnable tasks:
[ 694.121182] task PID tree-key switches prio exec-runtime sum-exec sum-sleep
[ 694.121182] ----------------------------------------------------------------------------------------------------------
[ 694.121182]
[ 694.121182] cpu#3, 1862.045 MHz
[ 694.121182] .nr_running : 0
[ 694.121182] .load : 0
[ 694.121182] .nr_switches : 1898699
[ 694.121182] .nr_load_updates : 92084
[ 694.121182] .nr_uninterruptible : 4294966813
[ 694.121182] .jiffies : 85008
[ 694.121182] .next_balance : 0.085009
[ 694.121182] .curr->pid : 0
[ 694.121182] .clock : 640051.975065
[ 694.121182] .cpu_load[0] : 0
[ 694.121182] .cpu_load[1] : 0
[ 694.121182] .cpu_load[2] : 0
[ 694.121182] .cpu_load[3] : 0
[ 694.121182] .cpu_load[4] : 0
[ 694.121182]
[ 694.121182] cfs_rq[3]:
[ 694.121182] .exec_clock : 0.000000
[ 694.121182] .MIN_vruntime : 0.000001
[ 694.121182] .min_vruntime : 55749.380669
[ 694.121182] .max_vruntime : 0.000001
[ 694.121182] .spread : 0.000000
[ 694.121182] .spread0 : 39400.758584
[ 694.121182] .nr_running : 0
[ 694.121182] .load : 0
[ 694.121182] .nr_spread_over : 0
[ 694.121182]
[ 694.121182] runnable tasks:
[ 694.121182] task PID tree-key switches prio exec-runtime sum-exec sum-sleep
[ 694.121182] ----------------------------------------------------------------------------------------------------------
[ 694.121182]
[ 694.121182] cpu#4, 1862.045 MHz
[ 694.121182] .nr_running : 0
[ 694.121182] .load : 0
[ 694.121182] .nr_switches : 65011
[ 694.121182] .nr_load_updates : 7806
[ 694.121182] .nr_uninterruptible : 214
[ 694.121182] .jiffies : 85046
[ 694.121182] .next_balance : 0.085047
[ 694.121182] .curr->pid : 0
[ 694.121182] .clock : 637517.396452
[ 694.121182] .cpu_load[0] : 0
[ 694.121182] .cpu_load[1] : 511
[ 694.121182] .cpu_load[2] : 750
[ 694.121182] .cpu_load[3] : 853
[ 694.121182] .cpu_load[4] : 868
[ 694.121182]
[ 694.121182] cfs_rq[4]:
[ 694.121182] .exec_clock : 0.000000
[ 694.121182] .MIN_vruntime : 0.000001
[ 694.121182] .min_vruntime : 45024.900733
[ 694.121182] .max_vruntime : 0.000001
[ 694.121182] .spread : 0.000000
[ 694.121182] .spread0 : 28676.278648
[ 694.121182] .nr_running : 0
[ 694.121182] .load : 0
[ 694.121182] .nr_spread_over : 0
[ 694.121182]
[ 694.121182] runnable tasks:
[ 694.121182] task PID tree-key switches prio exec-runtime sum-exec sum-sleep
[ 694.121182] ----------------------------------------------------------------------------------------------------------
[ 694.121182]
[ 694.121182] cpu#5, 1862.045 MHz
[ 694.121182] .nr_running : 0
[ 694.121182] .load : 0
[ 694.121182] .nr_switches : 34811
[ 694.121182] .nr_load_updates : 5207
[ 694.121182] .nr_uninterruptible : 128
[ 694.121182] .jiffies : 85084
[ 694.121182] .next_balance : 0.085085
[ 694.121182] .curr->pid : 0
[ 694.121182] .clock : 640352.338449
[ 694.121182] .cpu_load[0] : 0
[ 694.121182] .cpu_load[1] : 0
[ 694.121182] .cpu_load[2] : 0
[ 694.121182] .cpu_load[3] : 0
[ 694.121182] .cpu_load[4] : 30
[ 694.121182]
[ 694.121182] cfs_rq[5]:
[ 694.121182] .exec_clock : 0.000000
[ 694.121182] .MIN_vruntime : 0.000001
[ 694.121182] .min_vruntime : 26072.394124
[ 694.121182] .max_vruntime : 0.000001
[ 694.121182] .spread : 0.000000
[ 694.121182] .spread0 : 9723.772039
[ 694.121182] .nr_running : 0
[ 694.121182] .load : 0
[ 694.121182] .nr_spread_over : 0
[ 694.121182]
[ 694.121182] runnable tasks:
[ 694.121182] task PID tree-key switches prio exec-runtime sum-exec sum-sleep
[ 694.121182] ----------------------------------------------------------------------------------------------------------
[ 694.121182]
[ 694.121182] cpu#6, 1862.045 MHz
[ 694.121182] .nr_running : 0
[ 694.121182] .load : 0
[ 694.121182] .nr_switches : 32304
[ 694.121182] .nr_load_updates : 11575
[ 694.121182] .nr_uninterruptible : 172
[ 694.121182] .jiffies : 85121
[ 694.121182] .next_balance : 0.085124
[ 694.121182] .curr->pid : 0
[ 694.121182] .clock : 640500.418721
[ 694.121182] .cpu_load[0] : 0
[ 694.121182] .cpu_load[1] : 0
[ 694.121182] .cpu_load[2] : 0
[ 694.121182] .cpu_load[3] : 0
[ 694.121182] .cpu_load[4] : 0
[ 694.121182]
[ 694.121182] cfs_rq[6]:
[ 694.121182] .exec_clock : 0.000000
[ 694.121182] .MIN_vruntime : 0.000001
[ 694.121182] .min_vruntime : 37684.668142
[ 694.121182] .max_vruntime : 0.000001
[ 694.121182] .spread : 0.000000
[ 694.121182] .spread0 : 21336.046057
[ 694.121182] .nr_running : 0
[ 694.121182] .load : 0
[ 694.121182] .nr_spread_over : 0
[ 694.121182]
[ 694.121182] runnable tasks:
[ 694.121182] task PID tree-key switches prio exec-runtime sum-exec sum-sleep
[ 694.121182] ----------------------------------------------------------------------------------------------------------
[ 694.121182]
[ 694.121182] cpu#7, 1862.045 MHz
[ 694.121182] .nr_running : 0
[ 694.121182] .load : 0
[ 694.121182] .nr_switches : 2325749
[ 694.121182] .nr_load_updates : 10926
[ 694.121182] .nr_uninterruptible : 159
[ 694.121182] .jiffies : 85159
[ 694.121182] .next_balance : 0.085162
[ 694.121182] .curr->pid : 0
[ 694.121182] .clock : 640653.165765
[ 694.121182] .cpu_load[0] : 0
[ 694.121182] .cpu_load[1] : 0
[ 694.121182] .cpu_load[2] : 0
[ 694.121182] .cpu_load[3] : 0
[ 694.121182] .cpu_load[4] : 0
[ 694.121182]
[ 694.121182] cfs_rq[7]:
[ 694.121182] .exec_clock : 0.000000
[ 694.121182] .MIN_vruntime : 0.000001
[ 694.121182] .min_vruntime : 31973.568990
[ 694.121182] .max_vruntime : 0.000001
[ 694.121182] .spread : 0.000000
[ 694.121182] .spread0 : 15624.946905
[ 694.121182] .nr_running : 0
[ 694.121182] .load : 0
[ 694.121182] .nr_spread_over : 0
[ 694.121182]
[ 694.121182] runnable tasks:
[ 694.121182] task PID tree-key switches prio exec-runtime sum-exec sum-sleep
[ 694.121182] ----------------------------------------------------------------------------------------------------------
[ 694.121182]






*** break sent ***
[ 708.530043] SysRq : Show backtrace of all active CPUs
[ 708.530043] CPU4:
[ 708.530043]
[ 708.530043] Pid: 0, comm: swapper Tainted: G W (2.6.26-2-686-bigmem #1)
[ 708.530043] EIP: 0060:[<f884908c>] EFLAGS: 00000202 CPU: 4
[ 708.530043] EIP is at acpi_idle_enter_bm+0x2a0/0x315 [processor]
[ 708.530043] EAX: c03d5430 EBX: 00001033 ECX: 00005050 EDX: 0346d000
[ 708.530043] ESI: 00000000 EDI: 002cad1d EBP: 002c9cea ESP: f74b3f84
[ 708.530043] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[ 708.530043] CR0: 8005003b CR2: b77861be CR3: 00382000 CR4: 000006f0
[ 708.530043] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 708.530043] DR6: ffff0ff0 DR7: 00000400
[ 708.530043] [<c025b4f9>] ? cpuidle_idle_call+0x5b/0x86
[ 708.530043] [<c025b49e>] ? cpuidle_idle_call+0x0/0x86
[ 708.530043] [<c01075d3>] ? cpu_idle+0xb0/0xd0
[ 708.530043] =======================






*** break sent ***
[ 723.072717] SysRq : HELP : loglevel0-8 reBoot Crashdump tErm Full kIll saK aLlcpus showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks
 

Thread Tools




All times are GMT. The time now is 10:36 PM.

VBulletin, Copyright ©2000 - 2014, Jelsoft Enterprises Ltd.
Content Relevant URLs by vBSEO ©2007, Crawlability, Inc.
Copyright 2007 - 2008, www.linux-archive.org