Re: 2.6.10-rc3: kswapd eats CPU on start of memory-eating task

[Voluspa]

Sorry about the delay.

On 2004-12-17 0:41:30 Andrew Morton wrote:

> Can you identify the kernel release which caused the problem to start?

My next mail did just that. Sort of. Somewhere between, and including, 2.6.9-
rc1 and 2.6.9-rc1-bk4. The latter being the first functional kernel I can 
test due to oopses and loss of keyboard in X starting from -rc1.

>> with a default of nice 19 and sucks up every free CPU cycle.
>
> What sucks up all the CPU?  The application?  kswapd?

The folding client uses all unused CPU, as it should. What kswapd does is 
beyond my knowledge.

> How much RAM, how much swap?

256 megabyte ram, about 1 gigabyte swap. You'll find more info in the next 
section.

On 2004-12-16 8:14:44 Nick Piggin wrote:

> So please, do the sysrq+m traces with a 2.6.10-rc3 kernel. Thanks.

Ok, done. I can do the same with last uneffected 2.6.8.1-bk2 upon request (didn't 
want to spam unless told to). Log from dmesg attached. Don't want to "inline" 
it since my ISP has changed the webmail program to some POS java where I 
have no control over the linebreaks.

Testing explanation: Cold boot. Started the folding client and waited 15 
minutes for it to write the first checkpoint (wanted full stability). Started 
X. Started Blender. Loaded a scene where I only use the "Sequence Editor" 
mode.

In this mode there's a 'preview' window where you can Alt-a, for animate, and 
watch your work in an almost real time. Overhead prevents a real, real time. 
Here I let the animation loop until the testing is over.

What happens during animation is that my 500 1.2 meg pictures (ie 20 seconds) is 
read from /dev/hdb - a slightly better and modern disk, fills up memory 
and then starts using the swap partition on /dev/hda. The read from /dev/hdb 
seems to be done only once since neither memory nor swap is released until 
I close the scene.

The machine CPU usage, as monitored by Gkrellm, is highest during the initial 
phase of swapping, about 50 percent (not counting the niced folding client 
usage) and then falls to about 15 percent when all swapping is done. How 
high it reaches during the screen freezes I don't know.

The sysrq+m snapshots were taken thusly: 1) Some seconds after the beginning of 
swap usage. 2) When the first screen freeze began. 3) In another screen 
freeze. 4) In the last minute of swapping, also during a screen freeze.

Total wall clock was about 3 minutes from beginning of animation to when all 
swapping had been done and the animation was "stable".

Mvh
Mats Johannesson
Linux version 2.6.10-rc3-sysrq (root@loke) (gcc version 3.4.3) #1 Thu Dec 16 10:38:55 CET 2004
BIOS-provided physical RAM map:
 BIOS-e820: 0000000000000000 - 00000000000a0000 (usable)
 BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
 BIOS-e820: 0000000000100000 - 000000000fff0000 (usable)
 BIOS-e820: 000000000fff0000 - 000000000fff3000 (ACPI NVS)
 BIOS-e820: 000000000fff3000 - 0000000010000000 (ACPI data)
 BIOS-e820: 00000000ffb00000 - 0000000100000000 (reserved)
255MB LOWMEM available.
On node 0 totalpages: 65520
  DMA zone: 4096 pages, LIFO batch:1
  Normal zone: 61424 pages, LIFO batch:14
  HighMem zone: 0 pages, LIFO batch:1
DMI 2.2 present.
Built 1 zonelists
Kernel command line: root=/dev/hda2 pci=usepirqmask elevator=cfq apic=verbose lapic=lapic
Local APIC disabled by BIOS -- reenabling.
Found and enabled local APIC!
mapped APIC to ffffd000 (fee00000)
Initializing CPU#0
CPU 0 irqstacks, hard=c0348000 soft=c0347000
PID hash table entries: 1024 (order: 10, 16384 bytes)
Detected 1075.368 MHz processor.
Using tsc for high-res timesource
Console: colour VGA+ 80x25
Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
Memory: 256548k/262080k available (1564k kernel code, 4968k reserved, 405k data, 336k init, 0k highmem)
Checking if this processor honours the WP bit even in supervisor mode... Ok.
Calibrating delay loop... 2121.72 BogoMIPS (lpj=1060864)
Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
CPU: After generic identify, caps: 0383fbff 00000000 00000000 00000000
CPU: After vendor identify, caps:  0383fbff 00000000 00000000 00000000
CPU: L1 I cache: 16K, L1 D cache: 16K
CPU: L2 cache: 128K
CPU: After all inits, caps:        0383fbff 00000000 00000000 00000040
Intel machine check architecture supported.
Intel machine check reporting enabled on CPU#0.
CPU: Intel Celeron (Coppermine) stepping 06
Enabling fast FPU save and restore... done.
Enabling unmasked SIMD FPU exception support... done.
Checking 'hlt' instruction... OK.
enabled ExtINT on CPU#0
Using local APIC timer interrupts.
calibrating APIC timer ...
..... CPU clock speed is 1074.0766 MHz.
..... host bus clock speed is 134.0345 MHz.
NET: Registered protocol family 16
PCI: PCI BIOS revision 2.10 entry at 0xfb550, last bus=2
PCI: Using configuration type 1
mtrr: v2.0 (20020519)
Linux Plug and Play Support v0.97 (c) Adam Belay
PnPBIOS: Scanning system for PnP BIOS support...
PnPBIOS: Found PnP BIOS installation structure at 0xc00fbf10
PnPBIOS: PnP BIOS version 1.0, entry 0xf0000:0xbf40, dseg 0xf0000
PnPBIOS: 16 nodes reported by PnP BIOS; 16 recorded by driver
usbcore: registered new driver usbfs
usbcore: registered new driver hub
PCI: Probing PCI hardware
PCI: Probing PCI hardware (bus 00)
PCI: Transparent bridge - 0000:00:1e.0
PCI: Using IRQ router PIIX/ICH [8086/2440] at 0000:00:1f.0
PCI: Found IRQ 12 for device 0000:00:1f.3
PCI: Sharing IRQ 12 with 0000:02:01.0
pnp: 00:0c: ioport range 0x3f0-0x3f1 has been reserved
Installing knfsd (copyright (C) 1996 okir@xxxxxxxxxxxx).
isapnp: Scanning for PnP cards...
isapnp: No Plug & Play device found
Real Time Clock Driver v1.12
serio: i8042 AUX port at 0x60,0x64 irq 12
serio: i8042 KBD port at 0x60,0x64 irq 1
parport: PnPBIOS parport detected.
parport0: PC-style at 0x378, irq 7 [PCSPP,TRISTATE]
io scheduler noop registered
io scheduler anticipatory registered
io scheduler deadline registered
io scheduler cfq registered
Floppy drive(s): fd0 is 1.44M
FDC 0 is a post-1991 82077
loop: loaded (max 8 devices)
ub: sizeof ub_scsi_cmd 64 ub_dev 2472
usbcore: registered new driver ub
Uniform Multi-Platform E-IDE driver Revision: 7.00alpha2
ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx
ICH2: IDE controller at PCI slot 0000:00:1f.1
ICH2: chipset revision 1
ICH2: not 100% native mode: will probe irqs later
    ide0: BM-DMA at 0xf000-0xf007, BIOS settings: hda:DMA, hdb:DMA
    ide1: BM-DMA at 0xf008-0xf00f, BIOS settings: hdc:DMA, hdd:DMA
Probing IDE interface ide0...
hda: IBM-DTLA-307030, ATA DISK drive
hdb: IC35L080AVVA07-0, ATA DISK drive
ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
Probing IDE interface ide1...
hdc: Hewlett-Packard CD-Writer Plus 9100, ATAPI CD/DVD-ROM drive
hdd: DVD-ROM DDU220E, ATAPI CD/DVD-ROM drive
ide1 at 0x170-0x177,0x376 on irq 15
Probing IDE interface ide2...
ide2: Wait for ready failed before probe !
Probing IDE interface ide3...
ide3: Wait for ready failed before probe !
Probing IDE interface ide4...
ide4: Wait for ready failed before probe !
Probing IDE interface ide5...
ide5: Wait for ready failed before probe !
hda: max request size: 128KiB
hda: 59772900 sectors (30603 MB) w/1916KiB Cache, CHS=59298/16/63, UDMA(100)
hda: cache flushes not supported
 hda: hda1 hda2 hda3 hda4 < hda5 hda6 hda7 hda8 hda9 >
hdb: max request size: 128KiB
hdb: 160836480 sectors (82348 MB) w/1863KiB Cache, CHS=65535/16/63, UDMA(100)
hdb: cache flushes supported
 hdb: hdb1 hdb2 hdb3 hdb4
hdc: ATAPI 32X CD-ROM CD-R/RW drive, 4096kB Cache, UDMA(33)
Uniform CD-ROM driver Revision: 3.20
hdd: ATAPI DVD-ROM drive, 512kB Cache, DMA
USB Universal Host Controller Interface driver v2.2
PCI: Found IRQ 11 for device 0000:00:1f.2
PCI: Sharing IRQ 11 with 0000:02:03.0
uhci_hcd 0000:00:1f.2: Intel Corp. 82801BA/BAM USB (Hub #1)
PCI: Setting latency timer of device 0000:00:1f.2 to 64
uhci_hcd 0000:00:1f.2: irq 11, io base 0xd000
uhci_hcd 0000:00:1f.2: new USB bus registered, assigned bus number 1
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 2 ports detected
PCI: setting IRQ 5 as level-triggered
PCI: Assigned IRQ 5 for device 0000:00:1f.4
uhci_hcd 0000:00:1f.4: Intel Corp. 82801BA/BAM USB (Hub #2)
PCI: Setting latency timer of device 0000:00:1f.4 to 64
uhci_hcd 0000:00:1f.4: irq 5, io base 0xd400
uhci_hcd 0000:00:1f.4: new USB bus registered, assigned bus number 2
hub 2-0:1.0: USB hub found
hub 2-0:1.0: 2 ports detected
usb 1-2: new low speed USB device using uhci_hcd and address 2
input: USB HID v1.10 Mouse [Logitech USB Trackball] on usb-0000:00:1f.2-2
usbcore: registered new driver usbhid
drivers/usb/input/hid-core.c: v2.0:USB HID core driver
mice: PS/2 mouse device common for all mice
input: AT Translated Set 2 keyboard on isa0060/serio0
input: PC Speaker
i2c /dev entries driver
u32 classifier
    OLD policer on 
NET: Registered protocol family 2
IP: routing cache hash table of 2048 buckets, 16Kbytes
TCP: Hash tables configured (established 16384 bind 32768)
NET: Registered protocol family 1
NET: Registered protocol family 17
NET: Registered protocol family 15
VFS: Mounted root (ext2 filesystem) readonly.
Freeing unused kernel memory: 336k freed
Adding 979924k swap on /dev/hda7.  Priority:1 extents:1
PCI: Found IRQ 12 for device 0000:02:01.0
PCI: Sharing IRQ 12 with 0000:00:1f.3
nvidia: module license 'NVIDIA' taints kernel.
NVRM: loading NVIDIA Linux x86 NVIDIA Kernel Module  1.0-6629  Wed Nov  3 13:12:51 PST 2004
8139too Fast Ethernet driver 0.9.27
PCI: Found IRQ 11 for device 0000:02:03.0
PCI: Sharing IRQ 11 with 0000:00:1f.2
eth0: RealTek RTL8139 at 0xd097e000, 00:48:54:66:c8:84, IRQ 11
eth0:  Identified 8139 chip type 'RTL-8139B'
eth0: link up, 100Mbps, full-duplex, lpa 0x45E1
SysRq : Show Memory
Mem-info:
DMA per-cpu:
cpu 0 hot: low 2, high 6, batch 1
cpu 0 cold: low 0, high 2, batch 1
Normal per-cpu:
cpu 0 hot: low 28, high 84, batch 14
cpu 0 cold: low 0, high 28, batch 14
HighMem per-cpu: empty

Free pages:        2528kB (0kB HighMem)
Active:40862 inactive:16601 dirty:0 writeback:0 unstable:0 free:632 slab:1392 mapped:49585 pagetables:206
DMA free:152kB min:124kB low:152kB high:184kB active:8636kB inactive:4992kB present:16384kB pages_scanned:36 all_unreclaimable? no
protections[]: 0 0 0
Normal free:2376kB min:1916kB low:2392kB high:2872kB active:154812kB inactive:61412kB present:245696kB pages_scanned:99 all_unreclaimable? no
protections[]: 0 0 0
HighMem free:0kB min:128kB low:160kB high:192kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no
protections[]: 0 0 0
DMA: 0*4kB 1*8kB 1*16kB 2*32kB 1*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 152kB
Normal: 4*4kB 1*8kB 1*16kB 1*32kB 10*64kB 1*128kB 0*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 2376kB
HighMem: empty
Swap cache: add 12914, delete 12031, find 8/36, race 0+0
Free swap:       929164kB
65520 pages of RAM
0 pages of HIGHMEM
4391 reserved pages
7013 pages shared
883 pages swap cached
SysRq : Show Memory
Mem-info:
DMA per-cpu:
cpu 0 hot: low 2, high 6, batch 1
cpu 0 cold: low 0, high 2, batch 1
Normal per-cpu:
cpu 0 hot: low 28, high 84, batch 14
cpu 0 cold: low 0, high 28, batch 14
HighMem per-cpu: empty

Free pages:        2928kB (0kB HighMem)
Active:38048 inactive:19285 dirty:0 writeback:1403 unstable:0 free:732 slab:1373 mapped:53240 pagetables:255
DMA free:216kB min:124kB low:152kB high:184kB active:5868kB inactive:7620kB present:16384kB pages_scanned:0 all_unreclaimable? no
protections[]: 0 0 0
Normal free:2712kB min:1916kB low:2392kB high:2872kB active:146324kB inactive:69520kB present:245696kB pages_scanned:0 all_unreclaimable? no
protections[]: 0 0 0
HighMem free:0kB min:128kB low:160kB high:192kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no
protections[]: 0 0 0
DMA: 24*4kB 1*8kB 1*16kB 1*32kB 1*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 216kB
Normal: 0*4kB 9*8kB 15*16kB 15*32kB 2*64kB 2*128kB 0*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 2712kB
HighMem: empty
Swap cache: add 59988, delete 57469, find 384/488, race 0+0
Free swap:       743204kB
65520 pages of RAM
0 pages of HIGHMEM
4391 reserved pages
5303 pages shared
2519 pages swap cached
SysRq : Show Memory
Mem-info:
DMA per-cpu:
cpu 0 hot: low 2, high 6, batch 1
cpu 0 cold: low 0, high 2, batch 1
Normal per-cpu:
cpu 0 hot: low 28, high 84, batch 14
cpu 0 cold: low 0, high 28, batch 14
HighMem per-cpu: empty

Free pages:        2760kB (0kB HighMem)
Active:53024 inactive:4421 dirty:0 writeback:0 unstable:0 free:690 slab:1331 mapped:56992 pagetables:255
DMA free:272kB min:124kB low:152kB high:184kB active:11704kB inactive:1736kB present:16384kB pages_scanned:0 all_unreclaimable? no
protections[]: 0 0 0
Normal free:2488kB min:1916kB low:2392kB high:2872kB active:200392kB inactive:15948kB present:245696kB pages_scanned:0 all_unreclaimable? no
protections[]: 0 0 0
HighMem free:0kB min:128kB low:160kB high:192kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no
protections[]: 0 0 0
DMA: 28*4kB 2*8kB 3*16kB 1*32kB 1*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 272kB
Normal: 0*4kB 21*8kB 1*16kB 0*32kB 0*64kB 2*128kB 2*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 2488kB
HighMem: empty
Swap cache: add 102121, delete 82743, find 19904/23544, race 0+0
Free swap:       684360kB
65520 pages of RAM
0 pages of HIGHMEM
4391 reserved pages
4895 pages shared
19378 pages swap cached
SysRq : Show Memory
Mem-info:
DMA per-cpu:
cpu 0 hot: low 2, high 6, batch 1
cpu 0 cold: low 0, high 2, batch 1
Normal per-cpu:
cpu 0 hot: low 28, high 84, batch 14
cpu 0 cold: low 0, high 28, batch 14
HighMem per-cpu: empty

Free pages:        2768kB (0kB HighMem)
Active:37234 inactive:20167 dirty:0 writeback:0 unstable:0 free:692 slab:1340 mapped:55097 pagetables:255
DMA free:280kB min:124kB low:152kB high:184kB active:8132kB inactive:5268kB present:16384kB pages_scanned:0 all_unreclaimable? no
protections[]: 0 0 0
Normal free:2488kB min:1916kB low:2392kB high:2872kB active:140804kB inactive:75400kB present:245696kB pages_scanned:0 all_unreclaimable? no
protections[]: 0 0 0
HighMem free:0kB min:128kB low:160kB high:192kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no
protections[]: 0 0 0
DMA: 32*4kB 1*8kB 3*16kB 1*32kB 1*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 280kB
Normal: 0*4kB 1*8kB 7*16kB 0*32kB 3*64kB 1*128kB 2*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 2488kB
HighMem: empty
Swap cache: add 142576, delete 111546, find 38489/46005, race 0+0
Free swap:       635524kB
65520 pages of RAM
0 pages of HIGHMEM
4391 reserved pages
4945 pages shared
31030 pages swap cached