Bug 15783

Summary:	slow dd and multiple "page allocation failure" messages
Product:	Memory Management	Reporter:	Walter Haidinger (walter.haidinger)
Component:	Other	Assignee:	Andrew Morton (akpm)
Status:	RESOLVED OBSOLETE
Severity:	normal	CC:	alan, rtguille
Priority:	P1
Hardware:	All
OS:	Linux
Kernel Version:	2.6.38	Subsystem:
Regression:	No	Bisected commit-id:

Description Walter Haidinger 2010-04-14 08:35:42 UTC

There are some other bugzilla entries regarding "page allocation failure" messages, but for me the problem is reproducible:
I've tried to zero-out a sata disk with 'dd if=/dev/zero of=/dev/sde1' over night and within about 5 hours over 100 "page allocation failure" messages" were logged.

Please note that 'dd if=/dev/zero of=/dev/sde1' IO throughput is reproducible _slow_, only about 10 (ten) MiB/s. In contrast, 'badblocks -w /dev/sde1' has 10 times (>100 MiB/s). Odd. Btw, the harddisk (Seagate ST31500341AS) has no problems. sata_nv is the driver module used.

The system itself has 6 GiB RAM and idle most of the time. Especially no virtual machines or other memory hogs were/are currently running. Active memory is usually about 2 GiB (see /proc/meminfo below), leaving 4 for buffers/cache.
Still a single dd can cause memory pressure?

One more to note: Swap-space is a dmcrypt LVM logical volume.

I'm adding the dmesg kernel message and some system info (lspci,lsmod) below.
Please tell me if you need any additional info (kernel config, etc).

OS: openSUSE 11.2 x86_64 with custom 2.6.33.2 kernel compiled from mainline.
    dd is version 7.1 from coreutils-7.1-3.2.x86_64 rpm.
Hardware: Athlon X2 BE-2350 on a MSI MS-7250 motherboard

# dmesg 
...
[800144.472687] swapper: page allocation failure. order:2, mode:0x4020
[800144.472701] Pid: 0, comm: swapper Not tainted 2.6.33.2-vmhost64 #13
[800144.472706] Call Trace:
[800144.472710]  <IRQ>  [<ffffffff810a94dd>] __alloc_pages_nodemask+0x55d/0x650
[800144.472726]  [<ffffffff81257348>] ? dev_alloc_skb+0x18/0x30
[800144.472732]  [<ffffffff810a95e2>] __get_free_pages+0x12/0x50
[800144.472739]  [<ffffffff810d6dbc>] __kmalloc_track_caller+0xdc/0xe0
[800144.472745]  [<ffffffff8125660f>] __alloc_skb+0x6f/0x170
[800144.472750]  [<ffffffff81257348>] dev_alloc_skb+0x18/0x30
[800144.472782]  [<ffffffffa0232298>] nv_alloc_rx_optimized+0x198/0x260 [forcedeth]
[800144.472792]  [<ffffffffa0234033>] ? nv_rx_process_optimized+0xa3/0x2a0 [forcedeth]
[800144.472802]  [<ffffffffa0235956>] nv_napi_poll+0x86/0x600 [forcedeth]
[800144.472809]  [<ffffffff812a3b7e>] ? tcp_send_probe0+0x7e/0x110
[800144.472816]  [<ffffffff8125ecdb>] net_rx_action+0xdb/0x190
[800144.472822]  [<ffffffff810491b6>] __do_softirq+0xa6/0x130
[800144.472831]  [<ffffffffa02344bd>] ? nv_nic_irq_optimized+0x6d/0xa0 [forcedeth]
[800144.472840]  [<ffffffff81003c0c>] call_softirq+0x1c/0x30
[800144.472845]  [<ffffffff81005ccd>] do_softirq+0x4d/0x80
[800144.472850]  [<ffffffff81048ecd>] irq_exit+0x7d/0x90
[800144.472855]  [<ffffffff810052c0>] do_IRQ+0x70/0xf0
[800144.472861]  [<ffffffff812f6713>] ret_from_intr+0x0/0xa
[800144.472865]  <EOI>  [<ffffffff8100b584>] ? default_idle+0x24/0x40
[800144.472873]  [<ffffffff8100b6c3>] c1e_idle+0x83/0x100
[800144.472879]  [<ffffffff8105eff5>] ? atomic_notifier_call_chain+0x15/0x20
[800144.472886]  [<ffffffff81001e85>] cpu_idle+0xa5/0x100
[800144.472893]  [<ffffffff812e40d4>] rest_init+0x74/0x80
[800144.472899]  [<ffffffff81661b22>] start_kernel+0x3b3/0x3bf
[800144.472905]  [<ffffffff81661123>] x86_64_start_reservations+0x120/0x124
[800144.472910]  [<ffffffff81661208>] x86_64_start_kernel+0xe1/0xe8
[800144.472915] Mem-Info:
[800144.472918] DMA per-cpu:
[800144.472922] CPU    0: hi:    0, btch:   1 usd:   0
[800144.472926] CPU    1: hi:    0, btch:   1 usd:   0
[800144.472930] DMA32 per-cpu:
[800144.472934] CPU    0: hi:  186, btch:  31 usd:  45
[800144.472938] CPU    1: hi:  186, btch:  31 usd:  41
[800144.472942] Normal per-cpu:
[800144.472945] CPU    0: hi:  186, btch:  31 usd: 174
[800144.472949] CPU    1: hi:  186, btch:  31 usd: 161
[800144.472956] active_anon:140610 inactive_anon:62465 isolated_anon:0
[800144.472957]  active_file:389749 inactive_file:423491 isolated_file:0
[800144.472959]  unevictable:0 dirty:46557 writeback:0 unstable:0
[800144.472960]  free:61093 slab_reclaimable:113077 slab_unreclaimable:43152
[800144.472961]  mapped:7423 shmem:2438 pagetables:5126 bounce:0
[800144.472980] DMA free:15832kB min:160kB low:200kB high:240kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15272kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:8kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
[800144.472998] lowmem_reserve[]: 0 2872 6028 6028
[800144.473008] DMA32 free:185784kB min:31144kB low:38928kB high:46716kB active_anon:76516kB inactive_anon:86588kB active_file:746584kB inactive_file:815404kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:2940960kB mlocked:0kB dirty:128756kB writeback:0kB mapped:3100kB shmem:48kB slab_reclaimable:367280kB slab_unreclaimable:114280kB kernel_stack:248kB pagetables:1220kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[800144.473028] lowmem_reserve[]: 0 0 3156 3156
[800144.473037] Normal free:42756kB min:34224kB low:42780kB high:51336kB active_anon:485924kB inactive_anon:163272kB active_file:812412kB inactive_file:878560kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:3232000kB mlocked:0kB dirty:57472kB writeback:0kB mapped:26592kB shmem:9704kB slab_reclaimable:85028kB slab_unreclaimable:58320kB kernel_stack:4128kB pagetables:19284kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[800144.473057] lowmem_reserve[]: 0 0 0 0
[800144.473062] DMA: 4*4kB 3*8kB 3*16kB 2*32kB 3*64kB 3*128kB 1*256kB 1*512kB 2*1024kB 2*2048kB 2*4096kB = 15832kB
[800144.473075] DMA32: 45342*4kB 0*8kB 1*16kB 0*32kB 1*64kB 0*128kB 1*256kB 0*512kB 0*1024kB 0*2048kB 1*4096kB = 185800kB
[800144.473087] Normal: 9685*4kB 0*8kB 1*16kB 1*32kB 0*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 1*2048kB 0*4096kB = 42756kB
[800144.473100] 820255 total pagecache pages
[800144.473103] 4556 pages in swap cache
[800144.473108] Swap cache stats: add 27731, delete 23175, find 4074847/4075448
[800144.473112] Free swap  = 10257060kB
[800144.473116] Total swap = 10348392kB
[800144.513770] 1572864 pages RAM
[800144.513786] 43214 pages reserved
[800144.513789] 933611 pages shared
[800144.513792] 587054 pages non-shared

# grep "page allocation failure" /var/log/allmessages | tail -n 30
Apr 14 06:41:32 vmhost kernel: [795264.472696] swapper: page allocation failure. order:2, mode:0x4020
Apr 14 06:41:32 vmhost kernel: [795264.514764] swapper: page allocation failure. order:2, mode:0x4020
Apr 14 06:48:57 vmhost kernel: [795709.282767] ksoftirqd/0: page allocation failure. order:2, mode:0x4020
Apr 14 06:49:40 vmhost kernel: [795752.472794] ksoftirqd/0: page allocation failure. order:2, mode:0x4020
Apr 14 07:00:51 vmhost kernel: [796423.473152] ksoftirqd/0: page allocation failure. order:2, mode:0x4020
Apr 14 07:06:57 vmhost kernel: [796789.472681] ksoftirqd/0: page allocation failure. order:2, mode:0x4020
Apr 14 07:09:45 vmhost kernel: [796956.780137] dd: page allocation failure. order:2, mode:0x4020
Apr 14 07:12:02 vmhost kernel: [797094.472832] ksoftirqd/0: page allocation failure. order:2, mode:0x4020
Apr 14 07:16:15 vmhost kernel: [797347.399274] swapper: page allocation failure. order:2, mode:0x4020
Apr 14 07:16:15 vmhost kernel: [797347.439814] swapper: page allocation failure. order:2, mode:0x4020
Apr 14 07:18:08 vmhost kernel: [797460.475082] ksoftirqd/0: page allocation failure. order:2, mode:0x4020
Apr 14 07:23:13 vmhost kernel: [797765.475010] ksoftirqd/0: page allocation failure. order:2, mode:0x4020
Apr 14 07:24:06 vmhost kernel: [797818.282571] swapper: page allocation failure. order:2, mode:0x4020
Apr 14 07:24:14 vmhost kernel: [797826.474998] ksoftirqd/0: page allocation failure. order:2, mode:0x4020
Apr 14 07:25:15 vmhost kernel: [797887.472741] swapper: page allocation failure. order:2, mode:0x4020
Apr 14 07:26:16 vmhost kernel: [797948.472813] swapper: page allocation failure. order:2, mode:0x4020
Apr 14 07:29:05 vmhost kernel: [798117.492686] swapper: page allocation failure. order:2, mode:0x4020
Apr 14 07:29:06 vmhost kernel: [798117.538250] swapper: page allocation failure. order:2, mode:0x4020
Apr 14 07:29:06 vmhost kernel: [798117.584141] swapper: page allocation failure. order:2, mode:0x4020
Apr 14 07:29:19 vmhost kernel: [798131.472943] swapper: page allocation failure. order:2, mode:0x4020
Apr 14 07:34:06 vmhost kernel: [798418.066793] swapper: page allocation failure. order:2, mode:0x4020
Apr 14 07:37:27 vmhost kernel: [798619.472779] swapper: page allocation failure. order:2, mode:0x4020
Apr 14 07:39:09 vmhost kernel: [798720.620177] nmbd: page allocation failure. order:2, mode:0x4020
Apr 14 07:43:33 vmhost kernel: [798985.472759] ksoftirqd/0: page allocation failure. order:2, mode:0x4020
Apr 14 07:44:09 vmhost kernel: [799021.350169] nmbd: page allocation failure. order:2, mode:0x4020
Apr 14 07:56:46 vmhost kernel: [799778.472862] swapper: page allocation failure. order:2, mode:0x4020
Apr 14 08:00:50 vmhost kernel: [800022.472689] swapper: page allocation failure. order:2, mode:0x4020
Apr 14 08:00:50 vmhost kernel: [800022.512410] swapper: page allocation failure. order:2, mode:0x4020
Apr 14 08:02:52 vmhost kernel: [800144.472687] swapper: page allocation failure. order:2, mode:0x4020
Apr 14 08:11:00 vmhost kernel: [800632.472900] ksoftirqd/0: page allocation failure. order:2, mode:0x4020

#uname -a
Linux vmhost.private 2.6.33.2-vmhost64 #13 SMP Sat Apr 3 13:59:32 CEST 2010 x86_64 x86_64 x86_64 GNU/Linux

#cat /proc/meminfo 
MemTotal:        6118600 kB
MemFree:          229480 kB
Buffers:         3073148 kB
Cached:           262476 kB
SwapCached:        18124 kB
Active:          1900516 kB
Inactive:        2243036 kB
Active(anon):     569736 kB
Inactive(anon):   248008 kB
Active(file):    1330780 kB
Inactive(file):  1995028 kB
Unevictable:           0 kB
Mlocked:               0 kB
SwapTotal:      10348392 kB
SwapFree:       10255720 kB
Dirty:            190724 kB
Writeback:             0 kB
AnonPages:        790712 kB
Mapped:            33872 kB
Shmem:              9752 kB
Slab:             552152 kB
SReclaimable:     378800 kB
SUnreclaim:       173352 kB
KernelStack:        4400 kB
PageTables:        20760 kB
NFS_Unstable:          0 kB
Bounce:                0 kB
WritebackTmp:          0 kB
CommitLimit:    13407692 kB
Committed_AS:    1495296 kB
VmallocTotal:   34359738367 kB
VmallocUsed:      288944 kB
VmallocChunk:   34359412148 kB
HardwareCorrupted:     0 kB
HugePages_Total:       0
HugePages_Free:        0
HugePages_Rsvd:        0
HugePages_Surp:        0
Hugepagesize:       2048 kB
DirectMap4k:       10048 kB
DirectMap2M:     6281216 kB

#lspci
00:00.0 RAM memory: nVidia Corporation MCP55 Memory Controller (rev a1)
00:01.0 ISA bridge: nVidia Corporation MCP55 LPC Bridge (rev a2)
00:01.1 SMBus: nVidia Corporation MCP55 SMBus (rev a2)
00:02.0 USB Controller: nVidia Corporation MCP55 USB Controller (rev a1)
00:02.1 USB Controller: nVidia Corporation MCP55 USB Controller (rev a2)
00:04.0 IDE interface: nVidia Corporation MCP55 IDE (rev a1)
00:05.0 RAID bus controller: nVidia Corporation MCP55 SATA Controller (rev a2)
00:05.1 RAID bus controller: nVidia Corporation MCP55 SATA Controller (rev a2)
00:05.2 RAID bus controller: nVidia Corporation MCP55 SATA Controller (rev a2)
00:06.0 PCI bridge: nVidia Corporation MCP55 PCI bridge (rev a2)
00:06.1 Audio device: nVidia Corporation MCP55 High Definition Audio (rev a2)
00:08.0 Bridge: nVidia Corporation MCP55 Ethernet (rev a2)
00:09.0 Bridge: nVidia Corporation MCP55 Ethernet (rev a2)
00:0a.0 PCI bridge: nVidia Corporation MCP55 PCI Express bridge (rev a2)
00:0b.0 PCI bridge: nVidia Corporation MCP55 PCI Express bridge (rev a2)
00:0c.0 PCI bridge: nVidia Corporation MCP55 PCI Express bridge (rev a2)
00:0d.0 PCI bridge: nVidia Corporation MCP55 PCI Express bridge (rev a2)
00:0e.0 PCI bridge: nVidia Corporation MCP55 PCI Express bridge (rev a2)
00:0f.0 PCI bridge: nVidia Corporation MCP55 PCI Express bridge (rev a2)
00:18.0 Host bridge: Advanced Micro Devices [AMD] K8 [Athlon64/Opteron] HyperTransport Technology Configuration
00:18.1 Host bridge: Advanced Micro Devices [AMD] K8 [Athlon64/Opteron] Address Map
00:18.2 Host bridge: Advanced Micro Devices [AMD] K8 [Athlon64/Opteron] DRAM Controller
00:18.3 Host bridge: Advanced Micro Devices [AMD] K8 [Athlon64/Opteron] Miscellaneous Control
01:00.0 Multimedia video controller: Internext Compression Inc iTVC16 (CX23416) MPEG-2 Encoder (rev 01)
01:01.0 Multimedia video controller: Internext Compression Inc iTVC16 (CX23416) MPEG-2 Encoder (rev 01)
01:02.0 Multimedia controller: Philips Semiconductors SAA7146 (rev 01)
05:00.0 Mass storage controller: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller (rev 01)
07:00.0 VGA compatible controller: nVidia Corporation NV44 [GeForce 6200 LE] (rev a1)

Comment 1 Walter Haidinger 2010-04-14 08:55:59 UTC

Just noticed the following: All "page allocation failures" call traces today (well, 119 in total and I did not find any that did not) reference the forcedeth driver. So maybe a bug there caused by disk IO???

Also forgot modified vm sysctl settings.
vm.swappiness = 90
vm.vfs_cache_pressure = 1000
vm.min_free_kbytes = 65535

With the default vm.vfs_cache_pressure value I used get "page allocation failures" during "normal" use. When raised to 1000, none were logged except with this issue.

Here's another dmesg output:
[783282.341609] dd: page allocation failure. order:2, mode:0x4020
[783282.341622] Pid: 6997, comm: dd Not tainted 2.6.33.2-vmhost64 #13
[783282.341628] Call Trace:
[783282.341632]  <IRQ>  [<ffffffff810a94dd>] __alloc_pages_nodemask+0x55d/0x650
[783282.341648]  [<ffffffff81257348>] ? dev_alloc_skb+0x18/0x30
[783282.341654]  [<ffffffff810a95e2>] __get_free_pages+0x12/0x50
[783282.341660]  [<ffffffff810d6dbc>] __kmalloc_track_caller+0xdc/0xe0
[783282.341666]  [<ffffffff8125660f>] __alloc_skb+0x6f/0x170
[783282.341671]  [<ffffffff81257348>] dev_alloc_skb+0x18/0x30
[783282.341704]  [<ffffffffa0232298>] nv_alloc_rx_optimized+0x198/0x260 [forcedeth]
[783282.341714]  [<ffffffffa0234033>] ? nv_rx_process_optimized+0xa3/0x2a0 [forcedeth]
[783282.341724]  [<ffffffffa0235956>] nv_napi_poll+0x86/0x600 [forcedeth]
[783282.341733]  [<ffffffff81005d1d>] ? handle_irq+0x1d/0x30
[783282.341738]  [<ffffffff81048e93>] ? irq_exit+0x43/0x90
[783282.341745]  [<ffffffff8125ecdb>] net_rx_action+0xdb/0x190
[783282.341750]  [<ffffffff810491b6>] __do_softirq+0xa6/0x130
[783282.341759]  [<ffffffffa02344bd>] ? nv_nic_irq_optimized+0x6d/0xa0 [forcedeth]
[783282.341767]  [<ffffffff81003c0c>] call_softirq+0x1c/0x30
[783282.341772]  [<ffffffff81005ccd>] do_softirq+0x4d/0x80
[783282.341776]  [<ffffffff81048ecd>] irq_exit+0x7d/0x90
[783282.341781]  [<ffffffff810052c0>] do_IRQ+0x70/0xf0
[783282.341787]  [<ffffffff812f6713>] ret_from_intr+0x0/0xa
[783282.341791]  <EOI>  [<ffffffff81020731>] ? read_hpet+0x11/0x20
[783282.341802]  [<ffffffff81223be9>] ? scsi_request_fn+0xc9/0x4b0
[783282.341809]  [<ffffffff81062eca>] ktime_get_ts+0x6a/0xe0
[783282.341815]  [<ffffffff8109802c>] delayacct_end+0x2c/0xa0
[783282.341822]  [<ffffffff81105f40>] ? sync_buffer+0x0/0x50
[783282.341827]  [<ffffffff810980ff>] __delayacct_blkio_end+0x2f/0x50
[783282.341833]  [<ffffffff812f452d>] io_schedule+0x8d/0xb0
[783282.341838]  [<ffffffff81105f7b>] sync_buffer+0x3b/0x50
[783282.341843]  [<ffffffff812f4aa7>] __wait_on_bit+0x57/0x80
[783282.341850]  [<ffffffff8116b047>] ? submit_bio+0x77/0x100
[783282.341855]  [<ffffffff812f4b41>] out_of_line_wait_on_bit+0x71/0x80
[783282.341861]  [<ffffffff81105f40>] ? sync_buffer+0x0/0x50
[783282.341867]  [<ffffffff8105a080>] ? wake_bit_function+0x0/0x40
[783282.341873]  [<ffffffff81105ee6>] __wait_on_buffer+0x26/0x30
[783282.341879]  [<ffffffff81106ec2>] __block_prepare_write+0x392/0x530
[783282.341885]  [<ffffffff8110a5a0>] ? blkdev_get_block+0x0/0x70
[783282.341891]  [<ffffffff810a332f>] ? grab_cache_page_write_begin+0x9f/0xd0
[783282.341897]  [<ffffffff811071ef>] block_write_begin+0x5f/0x100
[783282.341903]  [<ffffffff8110b635>] blkdev_write_begin+0x25/0x30
[783282.341908]  [<ffffffff8110a5a0>] ? blkdev_get_block+0x0/0x70
[783282.341913]  [<ffffffff810a241e>] generic_file_buffered_write+0xfe/0x250
[783282.341920]  [<ffffffff810482b2>] ? current_fs_time+0x22/0x30
[783282.341926]  [<ffffffff810a4138>] __generic_file_aio_write+0x238/0x450
[783282.341933]  [<ffffffff810036ce>] ? apic_timer_interrupt+0xe/0x20
[783282.341938]  [<ffffffff8110ab11>] blkdev_aio_write+0x31/0x90
[783282.341945]  [<ffffffff810df29a>] do_sync_write+0xca/0x110
[783282.341950]  [<ffffffff810038ae>] ? reschedule_interrupt+0xe/0x20
[783282.341957]  [<ffffffff81157a41>] ? security_file_permission+0x11/0x20
[783282.341962]  [<ffffffff810dfdc0>] vfs_write+0xb0/0x190
[783282.341967]  [<ffffffff810dff7c>] sys_write+0x4c/0x80
[783282.341973]  [<ffffffff81002d6b>] system_call_fastpath+0x16/0x1b
[783282.341977] Mem-Info:
[783282.341981] DMA per-cpu:
[783282.341984] CPU    0: hi:    0, btch:   1 usd:   0
[783282.341988] CPU    1: hi:    0, btch:   1 usd:   0
[783282.341992] DMA32 per-cpu:
[783282.341996] CPU    0: hi:  186, btch:  31 usd:  67
[783282.342000] CPU    1: hi:  186, btch:  31 usd: 169
[783282.342003] Normal per-cpu:
[783282.342007] CPU    0: hi:  186, btch:  31 usd: 170
[783282.342011] CPU    1: hi:  186, btch:  31 usd: 166
[783282.342017] active_anon:136758 inactive_anon:62541 isolated_anon:0
[783282.342019]  active_file:361379 inactive_file:457391 isolated_file:33
[783282.342020]  unevictable:0 dirty:17232 writeback:0 unstable:0
[783282.342021]  free:63339 slab_reclaimable:113790 slab_unreclaimable:42739
[783282.342022]  mapped:7743 shmem:2438 pagetables:5129 bounce:0
[783282.342041] DMA free:15832kB min:160kB low:200kB high:240kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15272kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:8kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
[783282.342059] lowmem_reserve[]: 0 2872 6028 6028
[783282.342069] DMA32 free:194928kB min:31144kB low:38928kB high:46716kB active_anon:78640kB inactive_anon:87052kB active_file:678280kB inactive_file:878656kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:2940960kB mlocked:0kB dirty:50176kB writeback:0kB mapped:3252kB shmem:32kB slab_reclaimable:369420kB slab_unreclaimable:112808kB kernel_stack:232kB pagetables:1344kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[783282.342088] lowmem_reserve[]: 0 0 3156 3156
[783282.342098] Normal free:42720kB min:34224kB low:42780kB high:51336kB active_anon:468392kB inactive_anon:163112kB active_file:767236kB inactive_file:950776kB unevictable:0kB isolated(anon):0kB isolated(file):132kB present:3232000kB mlocked:0kB dirty:18752kB writeback:0kB mapped:27720kB shmem:9720kB slab_reclaimable:85740kB slab_unreclaimable:58140kB kernel_stack:4144kB pagetables:19172kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:33 all_unreclaimable? no
[783282.342117] lowmem_reserve[]: 0 0 0 0
[783282.342122] DMA: 4*4kB 3*8kB 3*16kB 2*32kB 3*64kB 3*128kB 1*256kB 1*512kB 2*1024kB 2*2048kB 2*4096kB = 15832kB
[783282.342134] DMA32: 47600*4kB 14*8kB 3*16kB 1*32kB 0*64kB 0*128kB 1*256kB 0*512kB 0*1024kB 0*2048kB 1*4096kB = 194944kB
[783282.342146] Normal: 9689*4kB 3*8kB 2*16kB 0*32kB 1*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 1*2048kB 0*4096kB = 42844kB
[783282.342158] 825681 total pagecache pages
[783282.342162] 4516 pages in swap cache
[783282.342166] Swap cache stats: add 27691, delete 23175, find 3838421/3839017
[783282.342171] Free swap  = 10257060kB
[783282.342174] Total swap = 10348392kB
[783282.384525] 1572864 pages RAM
[783282.384535] 43214 pages reserved
[783282.384539] 944434 pages shared
[783282.384544] 568386 pages non-shared
[783308.474703] ksoftirqd/0: page allocation failure. order:2, mode:0x4020
...

Comment 2 Andrew Morton 2010-04-19 21:10:33 UTC

(switched to email.  Please respond via emailed reply-to-all, not via the
bugzilla web interface).

Sigh.  This shouldn't happen.

I'm going to go ahead and assume that some earlier kernels didn't do
this :(

Is the writeout to /dev/sde1 slow right from the start, or does it
start out fast and later slow down?

`dd' isn't very efficient without the `bs' option - it reads and writes
in 512-byte chunks.   But that shouldn't be causing these problems.

On Wed, 14 Apr 2010 08:36:08 GMT
bugzilla-daemon@bugzilla.kernel.org wrote:

> https://bugzilla.kernel.org/show_bug.cgi?id=15783
> 
>            Summary: slow dd and multiple "page allocation failure"
>                     messages
>            Product: Memory Management
>            Version: 2.5
>     Kernel Version: 2.6.33.2
>           Platform: All
>         OS/Version: Linux
>               Tree: Mainline
>             Status: NEW
>           Severity: normal
>           Priority: P1
>          Component: Other
>         AssignedTo: akpm@linux-foundation.org
>         ReportedBy: walter.haidinger@gmx.at
>         Regression: No
> 
> 
> There are some other bugzilla entries regarding "page allocation failure"
> messages, but for me the problem is reproducible:
> I've tried to zero-out a sata disk with 'dd if=/dev/zero of=/dev/sde1' over
> night and within about 5 hours over 100 "page allocation failure" messages"
> were logged.
> 
> Please note that 'dd if=/dev/zero of=/dev/sde1' IO throughput is reproducible
> _slow_, only about 10 (ten) MiB/s. In contrast, 'badblocks -w /dev/sde1' has
> 10
> times (>100 MiB/s). Odd. Btw, the harddisk (Seagate ST31500341AS) has no
> problems. sata_nv is the driver module used.
> 
> The system itself has 6 GiB RAM and idle most of the time. Especially no
> virtual machines or other memory hogs were/are currently running. Active
> memory
> is usually about 2 GiB (see /proc/meminfo below), leaving 4 for
> buffers/cache.
> Still a single dd can cause memory pressure?
> 
> One more to note: Swap-space is a dmcrypt LVM logical volume.
> 
> I'm adding the dmesg kernel message and some system info (lspci,lsmod) below.
> Please tell me if you need any additional info (kernel config, etc).
> 
> OS: openSUSE 11.2 x86_64 with custom 2.6.33.2 kernel compiled from mainline.
>     dd is version 7.1 from coreutils-7.1-3.2.x86_64 rpm.
> Hardware: Athlon X2 BE-2350 on a MSI MS-7250 motherboard
> 
> # dmesg 
> ...
> [800144.472687] swapper: page allocation failure. order:2, mode:0x4020
> [800144.472701] Pid: 0, comm: swapper Not tainted 2.6.33.2-vmhost64 #13
> [800144.472706] Call Trace:
> [800144.472710]  <IRQ>  [<ffffffff810a94dd>]
> __alloc_pages_nodemask+0x55d/0x650
> [800144.472726]  [<ffffffff81257348>] ? dev_alloc_skb+0x18/0x30
> [800144.472732]  [<ffffffff810a95e2>] __get_free_pages+0x12/0x50
> [800144.472739]  [<ffffffff810d6dbc>] __kmalloc_track_caller+0xdc/0xe0
> [800144.472745]  [<ffffffff8125660f>] __alloc_skb+0x6f/0x170
> [800144.472750]  [<ffffffff81257348>] dev_alloc_skb+0x18/0x30
> [800144.472782]  [<ffffffffa0232298>] nv_alloc_rx_optimized+0x198/0x260
> [forcedeth]
> [800144.472792]  [<ffffffffa0234033>] ? nv_rx_process_optimized+0xa3/0x2a0
> [forcedeth]
> [800144.472802]  [<ffffffffa0235956>] nv_napi_poll+0x86/0x600 [forcedeth]
> [800144.472809]  [<ffffffff812a3b7e>] ? tcp_send_probe0+0x7e/0x110
> [800144.472816]  [<ffffffff8125ecdb>] net_rx_action+0xdb/0x190
> [800144.472822]  [<ffffffff810491b6>] __do_softirq+0xa6/0x130
> [800144.472831]  [<ffffffffa02344bd>] ? nv_nic_irq_optimized+0x6d/0xa0
> [forcedeth]
> [800144.472840]  [<ffffffff81003c0c>] call_softirq+0x1c/0x30
> [800144.472845]  [<ffffffff81005ccd>] do_softirq+0x4d/0x80
> [800144.472850]  [<ffffffff81048ecd>] irq_exit+0x7d/0x90
> [800144.472855]  [<ffffffff810052c0>] do_IRQ+0x70/0xf0
> [800144.472861]  [<ffffffff812f6713>] ret_from_intr+0x0/0xa
> [800144.472865]  <EOI>  [<ffffffff8100b584>] ? default_idle+0x24/0x40
> [800144.472873]  [<ffffffff8100b6c3>] c1e_idle+0x83/0x100
> [800144.472879]  [<ffffffff8105eff5>] ? atomic_notifier_call_chain+0x15/0x20
> [800144.472886]  [<ffffffff81001e85>] cpu_idle+0xa5/0x100
> [800144.472893]  [<ffffffff812e40d4>] rest_init+0x74/0x80
> [800144.472899]  [<ffffffff81661b22>] start_kernel+0x3b3/0x3bf
> [800144.472905]  [<ffffffff81661123>] x86_64_start_reservations+0x120/0x124
> [800144.472910]  [<ffffffff81661208>] x86_64_start_kernel+0xe1/0xe8
> [800144.472915] Mem-Info:
> [800144.472918] DMA per-cpu:
> [800144.472922] CPU    0: hi:    0, btch:   1 usd:   0
> [800144.472926] CPU    1: hi:    0, btch:   1 usd:   0
> [800144.472930] DMA32 per-cpu:
> [800144.472934] CPU    0: hi:  186, btch:  31 usd:  45
> [800144.472938] CPU    1: hi:  186, btch:  31 usd:  41
> [800144.472942] Normal per-cpu:
> [800144.472945] CPU    0: hi:  186, btch:  31 usd: 174
> [800144.472949] CPU    1: hi:  186, btch:  31 usd: 161
> [800144.472956] active_anon:140610 inactive_anon:62465 isolated_anon:0
> [800144.472957]  active_file:389749 inactive_file:423491 isolated_file:0
> [800144.472959]  unevictable:0 dirty:46557 writeback:0 unstable:0
> [800144.472960]  free:61093 slab_reclaimable:113077 slab_unreclaimable:43152
> [800144.472961]  mapped:7423 shmem:2438 pagetables:5126 bounce:0
> [800144.472980] DMA free:15832kB min:160kB low:200kB high:240kB
> active_anon:0kB
> inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB
> isolated(anon):0kB isolated(file):0kB present:15272kB mlocked:0kB dirty:0kB
> writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB
> slab_unreclaimable:8kB
> kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB
> pages_scanned:0 all_unreclaimable? yes
> [800144.472998] lowmem_reserve[]: 0 2872 6028 6028
> [800144.473008] DMA32 free:185784kB min:31144kB low:38928kB high:46716kB
> active_anon:76516kB inactive_anon:86588kB active_file:746584kB
> inactive_file:815404kB unevictable:0kB isolated(anon):0kB isolated(file):0kB
> present:2940960kB mlocked:0kB dirty:128756kB writeback:0kB mapped:3100kB
> shmem:48kB slab_reclaimable:367280kB slab_unreclaimable:114280kB
> kernel_stack:248kB pagetables:1220kB unstable:0kB bounce:0kB
> writeback_tmp:0kB
> pages_scanned:0 all_unreclaimable? no
> [800144.473028] lowmem_reserve[]: 0 0 3156 3156
> [800144.473037] Normal free:42756kB min:34224kB low:42780kB high:51336kB
> active_anon:485924kB inactive_anon:163272kB active_file:812412kB
> inactive_file:878560kB unevictable:0kB isolated(anon):0kB isolated(file):0kB
> present:3232000kB mlocked:0kB dirty:57472kB writeback:0kB mapped:26592kB
> shmem:9704kB slab_reclaimable:85028kB slab_unreclaimable:58320kB
> kernel_stack:4128kB pagetables:19284kB unstable:0kB bounce:0kB
> writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
> [800144.473057] lowmem_reserve[]: 0 0 0 0
> [800144.473062] DMA: 4*4kB 3*8kB 3*16kB 2*32kB 3*64kB 3*128kB 1*256kB 1*512kB
> 2*1024kB 2*2048kB 2*4096kB = 15832kB
> [800144.473075] DMA32: 45342*4kB 0*8kB 1*16kB 0*32kB 1*64kB 0*128kB 1*256kB
> 0*512kB 0*1024kB 0*2048kB 1*4096kB = 185800kB
> [800144.473087] Normal: 9685*4kB 0*8kB 1*16kB 1*32kB 0*64kB 1*128kB 1*256kB
> 1*512kB 1*1024kB 1*2048kB 0*4096kB = 42756kB
> [800144.473100] 820255 total pagecache pages
> [800144.473103] 4556 pages in swap cache
> [800144.473108] Swap cache stats: add 27731, delete 23175, find
> 4074847/4075448
> [800144.473112] Free swap  = 10257060kB
> [800144.473116] Total swap = 10348392kB
> [800144.513770] 1572864 pages RAM
> [800144.513786] 43214 pages reserved
> [800144.513789] 933611 pages shared
> [800144.513792] 587054 pages non-shared
> 
> # grep "page allocation failure" /var/log/allmessages | tail -n 30
> Apr 14 06:41:32 vmhost kernel: [795264.472696] swapper: page allocation
> failure. order:2, mode:0x4020
> Apr 14 06:41:32 vmhost kernel: [795264.514764] swapper: page allocation
> failure. order:2, mode:0x4020
> Apr 14 06:48:57 vmhost kernel: [795709.282767] ksoftirqd/0: page allocation
> failure. order:2, mode:0x4020
> Apr 14 06:49:40 vmhost kernel: [795752.472794] ksoftirqd/0: page allocation
> failure. order:2, mode:0x4020
> Apr 14 07:00:51 vmhost kernel: [796423.473152] ksoftirqd/0: page allocation
> failure. order:2, mode:0x4020
> Apr 14 07:06:57 vmhost kernel: [796789.472681] ksoftirqd/0: page allocation
> failure. order:2, mode:0x4020
> Apr 14 07:09:45 vmhost kernel: [796956.780137] dd: page allocation failure.
> order:2, mode:0x4020
> Apr 14 07:12:02 vmhost kernel: [797094.472832] ksoftirqd/0: page allocation
> failure. order:2, mode:0x4020
> Apr 14 07:16:15 vmhost kernel: [797347.399274] swapper: page allocation
> failure. order:2, mode:0x4020
> Apr 14 07:16:15 vmhost kernel: [797347.439814] swapper: page allocation
> failure. order:2, mode:0x4020
> Apr 14 07:18:08 vmhost kernel: [797460.475082] ksoftirqd/0: page allocation
> failure. order:2, mode:0x4020
> Apr 14 07:23:13 vmhost kernel: [797765.475010] ksoftirqd/0: page allocation
> failure. order:2, mode:0x4020
> Apr 14 07:24:06 vmhost kernel: [797818.282571] swapper: page allocation
> failure. order:2, mode:0x4020
> Apr 14 07:24:14 vmhost kernel: [797826.474998] ksoftirqd/0: page allocation
> failure. order:2, mode:0x4020
> Apr 14 07:25:15 vmhost kernel: [797887.472741] swapper: page allocation
> failure. order:2, mode:0x4020
> Apr 14 07:26:16 vmhost kernel: [797948.472813] swapper: page allocation
> failure. order:2, mode:0x4020
> Apr 14 07:29:05 vmhost kernel: [798117.492686] swapper: page allocation
> failure. order:2, mode:0x4020
> Apr 14 07:29:06 vmhost kernel: [798117.538250] swapper: page allocation
> failure. order:2, mode:0x4020
> Apr 14 07:29:06 vmhost kernel: [798117.584141] swapper: page allocation
> failure. order:2, mode:0x4020
> Apr 14 07:29:19 vmhost kernel: [798131.472943] swapper: page allocation
> failure. order:2, mode:0x4020
> Apr 14 07:34:06 vmhost kernel: [798418.066793] swapper: page allocation
> failure. order:2, mode:0x4020
> Apr 14 07:37:27 vmhost kernel: [798619.472779] swapper: page allocation
> failure. order:2, mode:0x4020
> Apr 14 07:39:09 vmhost kernel: [798720.620177] nmbd: page allocation failure.
> order:2, mode:0x4020
> Apr 14 07:43:33 vmhost kernel: [798985.472759] ksoftirqd/0: page allocation
> failure. order:2, mode:0x4020
> Apr 14 07:44:09 vmhost kernel: [799021.350169] nmbd: page allocation failure.
> order:2, mode:0x4020
> Apr 14 07:56:46 vmhost kernel: [799778.472862] swapper: page allocation
> failure. order:2, mode:0x4020
> Apr 14 08:00:50 vmhost kernel: [800022.472689] swapper: page allocation
> failure. order:2, mode:0x4020
> Apr 14 08:00:50 vmhost kernel: [800022.512410] swapper: page allocation
> failure. order:2, mode:0x4020
> Apr 14 08:02:52 vmhost kernel: [800144.472687] swapper: page allocation
> failure. order:2, mode:0x4020
> Apr 14 08:11:00 vmhost kernel: [800632.472900] ksoftirqd/0: page allocation
> failure. order:2, mode:0x4020
> 
> #uname -a
> Linux vmhost.private 2.6.33.2-vmhost64 #13 SMP Sat Apr 3 13:59:32 CEST 2010
> x86_64 x86_64 x86_64 GNU/Linux
> 
> #cat /proc/meminfo 
> MemTotal:        6118600 kB
> MemFree:          229480 kB
> Buffers:         3073148 kB
> Cached:           262476 kB
> SwapCached:        18124 kB
> Active:          1900516 kB
> Inactive:        2243036 kB
> Active(anon):     569736 kB
> Inactive(anon):   248008 kB
> Active(file):    1330780 kB
> Inactive(file):  1995028 kB
> Unevictable:           0 kB
> Mlocked:               0 kB
> SwapTotal:      10348392 kB
> SwapFree:       10255720 kB
> Dirty:            190724 kB
> Writeback:             0 kB
> AnonPages:        790712 kB
> Mapped:            33872 kB
> Shmem:              9752 kB
> Slab:             552152 kB
> SReclaimable:     378800 kB
> SUnreclaim:       173352 kB
> KernelStack:        4400 kB
> PageTables:        20760 kB
> NFS_Unstable:          0 kB
> Bounce:                0 kB
> WritebackTmp:          0 kB
> CommitLimit:    13407692 kB
> Committed_AS:    1495296 kB
> VmallocTotal:   34359738367 kB
> VmallocUsed:      288944 kB
> VmallocChunk:   34359412148 kB
> HardwareCorrupted:     0 kB
> HugePages_Total:       0
> HugePages_Free:        0
> HugePages_Rsvd:        0
> HugePages_Surp:        0
> Hugepagesize:       2048 kB
> DirectMap4k:       10048 kB
> DirectMap2M:     6281216 kB
> 
> #lspci
> 00:00.0 RAM memory: nVidia Corporation MCP55 Memory Controller (rev a1)
> 00:01.0 ISA bridge: nVidia Corporation MCP55 LPC Bridge (rev a2)
> 00:01.1 SMBus: nVidia Corporation MCP55 SMBus (rev a2)
> 00:02.0 USB Controller: nVidia Corporation MCP55 USB Controller (rev a1)
> 00:02.1 USB Controller: nVidia Corporation MCP55 USB Controller (rev a2)
> 00:04.0 IDE interface: nVidia Corporation MCP55 IDE (rev a1)
> 00:05.0 RAID bus controller: nVidia Corporation MCP55 SATA Controller (rev
> a2)
> 00:05.1 RAID bus controller: nVidia Corporation MCP55 SATA Controller (rev
> a2)
> 00:05.2 RAID bus controller: nVidia Corporation MCP55 SATA Controller (rev
> a2)
> 00:06.0 PCI bridge: nVidia Corporation MCP55 PCI bridge (rev a2)
> 00:06.1 Audio device: nVidia Corporation MCP55 High Definition Audio (rev a2)
> 00:08.0 Bridge: nVidia Corporation MCP55 Ethernet (rev a2)
> 00:09.0 Bridge: nVidia Corporation MCP55 Ethernet (rev a2)
> 00:0a.0 PCI bridge: nVidia Corporation MCP55 PCI Express bridge (rev a2)
> 00:0b.0 PCI bridge: nVidia Corporation MCP55 PCI Express bridge (rev a2)
> 00:0c.0 PCI bridge: nVidia Corporation MCP55 PCI Express bridge (rev a2)
> 00:0d.0 PCI bridge: nVidia Corporation MCP55 PCI Express bridge (rev a2)
> 00:0e.0 PCI bridge: nVidia Corporation MCP55 PCI Express bridge (rev a2)
> 00:0f.0 PCI bridge: nVidia Corporation MCP55 PCI Express bridge (rev a2)
> 00:18.0 Host bridge: Advanced Micro Devices [AMD] K8 [Athlon64/Opteron]
> HyperTransport Technology Configuration
> 00:18.1 Host bridge: Advanced Micro Devices [AMD] K8 [Athlon64/Opteron]
> Address
> Map
> 00:18.2 Host bridge: Advanced Micro Devices [AMD] K8 [Athlon64/Opteron] DRAM
> Controller
> 00:18.3 Host bridge: Advanced Micro Devices [AMD] K8 [Athlon64/Opteron]
> Miscellaneous Control
> 01:00.0 Multimedia video controller: Internext Compression Inc iTVC16
> (CX23416)
> MPEG-2 Encoder (rev 01)
> 01:01.0 Multimedia video controller: Internext Compression Inc iTVC16
> (CX23416)
> MPEG-2 Encoder (rev 01)
> 01:02.0 Multimedia controller: Philips Semiconductors SAA7146 (rev 01)
> 05:00.0 Mass storage controller: Silicon Image, Inc. SiI 3132 Serial ATA Raid
> II Controller (rev 01)
> 07:00.0 VGA compatible controller: nVidia Corporation NV44 [GeForce 6200 LE]
> (rev a1)
> 
> -- 
> Configure bugmail: https://bugzilla.kernel.org/userprefs.cgi?tab=email
> ------- You are receiving this mail because: -------
> You are on the CC list for the bug.

Comment 3 Walter Haidinger 2010-04-20 08:57:43 UTC

Am 19.04.2010 23:09, schrieb Andrew Morton:
> 
> (switched to email.  Please respond via emailed reply-to-all, not
> via the bugzilla web interface).

ok.

> Sigh.  This shouldn't happen.
> 
> I'm going to go ahead and assume that some earlier kernels didn't
> do this :(

No, I don't _think_ so. Problem is, I only noticed this when zeroing out
the device. Haven't done this recently with earlier kernels. Besides,
as reported, not all write operations are slow.

> Is the writeout to /dev/sde1 slow right from the start, or does it 
> start out fast and later slow down?

It seems to me that write speed does not change very much, but the
actual speed varies. One time it's just 10 MiB/s, another time about 30.
But for a couple of tests writes, speed is pretty stable.

Also, only writing directly to the device seems to be slow.
Perhaps that's why is hard to notice.

e.g.: when /dev/sde1 is mounted as ext3 fs:
Copying a 5 GiB file takes about 50s,
mbuffer </dev/zero >/mnt1/foo1 writes with >100 MiB/s,
dd if=/dev/zero of=/mnt1/foo2 manages >75 MiB/s.

After unmounting and writing directly from /dev/zero to /dev/sde1:
mbuffer writes about 40 MiB/s and dd less than 30.

But then badblocks -svw -t 0x00 /dev/sde1 writes about 120 MiB/s.
Btw, dd if=/dev/zero of=/dev/null runs with >500 MiB/s.

Needless to say, I'm confused by the numbers...

> `dd' isn't very efficient without the `bs' option - it reads and
> writes in 512-byte chunks.   But that shouldn't be causing these
> problems.

Tried mbuffer instead. Shows similar results, only a bit faster.
Still, even if dd is inefficient, it is way slower than expected.

If you want me to test anything, please let me know.

Walter

PS: The short tests above triggered no "page allocation failures"
    (vm.vfs_cache_pressure = 1000).

Comment 4 Walter Haidinger 2010-04-20 08:59:34 UTC

Am 19.04.2010 23:09, schrieb Andrew Morton:
> 
> (switched to email.  Please respond via emailed reply-to-all, not
> via the bugzilla web interface).

ok.

> Sigh.  This shouldn't happen.
> 
> I'm going to go ahead and assume that some earlier kernels didn't
> do this :(

No, I don't _think_ so. Problem is, I only noticed this when zeroing out
the device. Haven't done this recently with earlier kernels. Besides,
as reported, not all write operations are slow.

> Is the writeout to /dev/sde1 slow right from the start, or does it 
> start out fast and later slow down?

It seems to me that write speed does not change very much, but the
actual speed varies. One time it's just 10 MiB/s, another time about 30.
But for a couple of tests writes, speed is pretty stable.

Also, only writing directly to the device seems to be slow.
Perhaps that's why is hard to notice.

e.g.: when /dev/sde1 is mounted as ext3 fs:
Copying a 5 GiB file takes about 50s,
mbuffer </dev/zero >/mnt1/foo1 writes with >100 MiB/s,
dd if=/dev/zero of=/mnt1/foo2 manages >75 MiB/s.

After unmounting and writing directly from /dev/zero to /dev/sde1:
mbuffer writes about 40 MiB/s and dd less than 30.

But then badblocks -svw -t 0x00 /dev/sde1 writes about 120 MiB/s.
Btw, dd if=/dev/zero of=/dev/null runs with >500 MiB/s.

Needless to say, I'm confused by the numbers...

> `dd' isn't very efficient without the `bs' option - it reads and
> writes in 512-byte chunks.   But that shouldn't be causing these
> problems.

Tried mbuffer instead. Shows similar results, only a bit faster.
Still, even if dd is inefficient, it is way slower than expected.

If you want me to test anything, please let me know.

Walter

PS: The short tests above triggered no "page allocation failures"
    (vm.vfs_cache_pressure = 1000).

Comment 5 Reartes Guillermo 2011-06-12 00:25:34 UTC

I installed a new PCIe 1x, 2 eSATA port SATA controller:

03:00.0 Mass storage controller [0180]: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller [1095:3132] (rev 01)
        Subsystem: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller [1095:3132]
        Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR+ FastB2B- DisINTx-
        Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
        Latency: 0, Cache Line Size: 64 bytes
        Interrupt: pin A routed to IRQ 18
        Region 0: Memory at fbfffc00 (64-bit, non-prefetchable) [size=128]
        Region 2: Memory at fbff8000 (64-bit, non-prefetchable) [size=16K]
        Region 4: I/O ports at ec00 [size=128]
        Expansion ROM at fbf00000 [disabled] [size=512K]
        Capabilities: [54] Power Management version 2
                Flags: PMEClk- DSI+ D1+ D2+ AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
                Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=1 PME-
        Capabilities: [5c] MSI: Enable- Count=1/1 Maskable- 64bit+
                Address: 0000000000000000  Data: 0000
        Capabilities: [70] Express (v1) Legacy Endpoint, MSI 00
                DevCap: MaxPayload 1024 bytes, PhantFunc 0, Latency L0s <64ns, L1 <1us
                        ExtTag- AttnBtn- AttnInd- PwrInd- RBE- FLReset-
                DevCtl: Report errors: Correctable- Non-Fatal- Fatal- Unsupported-
                        RlxdOrd- ExtTag- PhantFunc- AuxPwr- NoSnoop-
                        MaxPayload 128 bytes, MaxReadReq 4096 bytes
                DevSta: CorrErr- UncorrErr+ FatalErr- UnsuppReq+ AuxPwr- TransPend-
                LnkCap: Port #0, Speed 2.5GT/s, Width x1, ASPM L0s, Latency L0 unlimited, L1 unlimited
                        ClockPM- Surprise- LLActRep- BwNot-
                LnkCtl: ASPM Disabled; RCB 64 bytes Disabled- Retrain- CommClk-
                        ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
                LnkSta: Speed 2.5GT/s, Width x1, TrErr- Train- SlotClk+ DLActive- BWMgmt- ABWMgmt-
        Capabilities: [100 v1] Advanced Error Reporting
                UESta:  DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq+ ACSViol-
                UEMsk:  DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq- ACSViol-
                UESvrt: DLP+ SDES- TLP- FCP+ CmpltTO- CmpltAbrt- UnxCmplt- RxOF+ MalfTLP+ ECRC- UnsupReq- ACSViol-
                CESta:  RxErr- BadTLP- BadDLLP- Rollover- Timeout- NonFatalErr-
                CEMsk:  RxErr- BadTLP- BadDLLP- Rollover- Timeout- NonFatalErr-
                AERCap: First Error Pointer: 14, GenCap+ CGenEn- ChkCap+ ChkEn-
        Kernel driver in use: sata_sil24
        Kernel modules: sata_sil24

And i get 10 MiB/s write speed (varies slightly).

Jun 11 20:06:08 ulquiorra kernel: [ 2551.349984] ata10: exception Emask 0x10 SAct 0x0 SErr 0x0 action 0xe frozen
Jun 11 20:06:08 ulquiorra kernel: [ 2551.349995] ata10: irq_stat 0x00b40090, PHY RDY changed
Jun 11 20:06:08 ulquiorra kernel: [ 2551.350048] ata10: hard resetting link
Jun 11 20:06:10 ulquiorra kernel: [ 2553.482092] ata10: SATA link up 3.0 Gbps (SStatus 123 SControl 0)
Jun 11 20:06:10 ulquiorra kernel: [ 2553.497754] ata10.00: ATA-8: WDC WD20EARS-00MVWB0, 50.0AB50, max UDMA/133
Jun 11 20:06:10 ulquiorra kernel: [ 2553.497765] ata10.00: 3907029168 sectors, multi 0: LBA48 
Jun 11 20:06:10 ulquiorra kernel: [ 2553.501584] ata10.00: configured for UDMA/100
Jun 11 20:06:10 ulquiorra kernel: [ 2553.501603] ata10: EH complete
Jun 11 20:06:10 ulquiorra kernel: [ 2553.501830] scsi 9:0:0:0: Direct-Access     ATA      WDC WD20EARS-00M 50.0 PQ: 0 ANSI: 5
Jun 11 20:06:10 ulquiorra kernel: [ 2553.502419] sd 9:0:0:0: [sdc] 3907029168 512-byte logical blocks: (2.00 TB/1.81 TiB)
Jun 11 20:06:10 ulquiorra kernel: [ 2553.502553] sd 9:0:0:0: [sdc] Write Protect is off
Jun 11 20:06:10 ulquiorra kernel: [ 2553.502619] sd 9:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Jun 11 20:06:10 ulquiorra kernel: [ 2553.503699] sd 9:0:0:0: Attached scsi generic sg3 type 0
Jun 11 20:06:10 ulquiorra kernel: [ 2553.515539]  sdc: sdc1
Jun 11 20:06:10 ulquiorra kernel: [ 2553.516172] sd 9:0:0:0: [sdc] Attached SCSI disk

Read speed is fast, not a problem, a single 17GB file copied from sdc to sdb took 3 minutes at 65Mb speed.

The same disks works at normal speeds when attached to the nvidia controller and performing hot-swap. (speaking of sustainted r/w speeds).

The card seems to share the interrupt with the sound card.... and it is not using msi.

When writing to the disk attached to the Silicon Image card, the activity led of the enclosures flashes and have loong pauses between flashes, indicating some time of performance problem in card/driver).

I do not experience "page allocation failures" or any king of message, but i installed it an hour ago and it is not used for permanent disks.

Distribution: F15 (x86_64)
Kernel: 2.6.38.7-30.fc15.x86_64


I do have several hard disks, so i will test them.