Using SMP kernel 2.6.22.6pre-CFS-v20.5 on Pentium D (IA-32).
I think this bug (or whatever you want to call it) got triggered
when you first allocate several megabytes of memory in a kernel module
and then free them, and then run e.g. X and when memory gets tight,
you end up with this situation...
Top 2 /proc/vmstat Biggest Winners:
pgrefill_normal:49900/second
pgrefill_high:20810/second
$ vmstat 1
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
r b swpd free buff cache si so bi bo in cs us sy id wa st
0 1 326020 861476 0 7384 236 0 392 0 68 1100 1 1 45 54 0
0 1 326020 861860 0 7216 64 140 64 148 68 1137 0 0 48 51 0
0 1 326020 862696 0 6772 96 0 108 4 55 1069 0 1 48 51 0
0 3 326024 861352 0 8080 752 300 2540 308 191 1202 1 3 37 59 0
0 2 326024 857464 0 9340 2768 0 5364 40 228 1589 0 2 20 77 0
0 3 326396 857772 0 8408 1280 656 2580 664 203 1589 1 3 20 78 0
0 3 326376 855768 0 9864 1448 0 3632 0 167 1488 1 2 11 87 0
0 3 326084 854000 0 10712 1848 0 3228 0 180 1515 1 3 1 95 0
0 1 326084 854204 0 10052 628 0 776 0 98 1324 1 1 38 61 0
0 1 326084 855476 0 8644 100 0 332 52 81 1065 1 1 48 51 0
0 2 326084 856444 0 8180 88 0 396 0 84 1195 1 2 38 60 0
0 2 319072 849068 0 9572 7008 0 8548 0 1820 8460 1 18 15 68 0
2 3 303888 835724 0 8864 14900 0 15100 8 3800 15863 1 27 29 44 0
around here I rand swapoff -a
0 2 289024 822352 0 7724 14688 0 14840 4 3706 17628 1 25 13 61 0
0 4 270728 805104 0 7644 17384 0 17656 8 4388 19984 0 25 19 55 0
0 3 255216 789884 0 7296 15732 0 15892 8 3932 19146 1 22 24 54 0
2 3 241188 776476 0 6748 14192 0 14732 4 3550 16584 1 21 0 78 0
2 4 224708 760320 0 7152 16552 0 17460 0 4142 18909 1 22 0 77 0
2 4 211624 748112 0 6996 12716 0 13496 8 3226 14975 0 19 9 71 0
0 4 196352 733304 0 7464 15268 0 16168 16 3816 18359 1 25 0 74 0
2 4 179580 716516 0 7112 17028 0 17776 9 4261 20913 1 26 6 67 0
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
r b swpd free buff cache si so bi bo in cs us sy id wa st
0 4 164692 701644 0 7168 14848 0 16276 8 3732 16751 0 19 0 80 0
2 5 151980 688480 0 8140 12792 0 13872 0 3196 15417 0 24 0 75 0
0 6 135712 672272 0 8036 16496 0 17484 0 4036 18392 1 22 0 78 0
0 4 122128 658556 0 8116 13616 0 14748 12 3374 16222 0 23 0 77 0
0 4 109360 646788 0 7632 12648 0 13164 4 3176 15188 0 24 3 72 0
2 5 92496 630396 0 7480 16860 0 17460 4 4215 19614 1 24 5 71 0
0 6 78620 617316 0 7944 12688 0 13940 0 3229 14086 1 21 0 79 0
3 3 64760 603536 0 7980 13692 0 14576 8 3455 16508 1 20 2 76 0
0 4 50728 589352 0 8868 13552 0 15396 20 3474 15373 0 20 2 77 0
1 4 36088 575916 0 7724 14676 0 15208 4 3726 17567 0 27 0 72 0
2 2 22896 562900 0 7748 12952 0 13732 0 3311 14979 1 20 0 80 0
2 4 6108 547560 0 8044 15164 0 16300 0 3865 16899 1 24 40 35 0
0 1 0 545740 192 7620 3832 0 5588 65 1108 6072 1 8 38 54 0
0 2 0 545652 148 7608 0 0 332 0 63 1006 0 1 50 50 0
0 1 0 545048 44 8344 0 0 1976 0 103 1542 1 2 42 57 0
0 2 0 544168 0 9492 0 0 2764 4 105 1523 0 3 45 52 0
0 1 0 543812 0 9644 0 0 1584 8 113 1397 1 2 47 51 0
0 1 0 543836 0 9508 0 0 396 0 66 955 1 1 50 49 0
0 1 0 544288 0 9132 0 0 8 1 53 813 0 1 50 49 0
0 1 0 545216 0 8168 0 0 392 0 72 1489 1 1 50 48 0
0 1 0 545684 0 7496 0 0 124 8 59 1275 1 2 47 51 0
0 1 0 545160 0 8020 0 0 856 8 60 951 0 2 46 51 0
0 1 0 543396 0 10056 0 0 3144 0 146 1545 1 2 24 74 0
well did not make much difference,
$ vmstat 1 -a
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
r b swpd free inact active si so bi bo in cs us sy id wa st
0 1 326084 854204 3176 18896 628 0 776 0 97 1324 1 1 38 61 0
0 1 326084 855476 2936 17696 100 0 332 52 82 1065 1 1 48 51 0
0 2 326084 856444 2536 17156 88 0 396 0 84 1195 1 2 38 60 0
1 1 319076 849068 2676 24404 7004 0 8544 0 1820 8459 1 18 15 68 0
2 3 303920 835744 1388 39100 14872 0 15072 8 3792 15831 1 27 29 44 0
1 2 289048 822372 1504 52176 14692 0 14844 4 3708 17628 1 25 13 61 0
0 4 270728 805104 1952 69092 17412 0 17680 8 4393 20015 0 25 19 55 0
2 2 254708 789384 1132 85760 16244 0 16408 8 4062 19669 0 22 23 54 0
1 2 240672 775956 1044 99200 14196 0 14736 4 3550 16599 1 21 0 78 0
2 4 224280 759980 1412 115616 16464 0 17372 0 4120 18814 1 22 0 77 0
1 3 211300 747772 488 128568 12608 0 13388 8 3202 14916 1 20 9 71 0
0 4 196320 733188 1744 141952 15000 0 15900 24 3744 18047 1 25 0 75 0
2 4 179124 716040 2420 158420 17432 0 18180 1 4365 21330 1 27 6 67 0
2 6 166016 702936 2392 171464 13048 0 14468 8 3281 14671 1 20 0 80 0
0 5 151984 688480 1900 186440 14132 0 15220 0 3530 17005 0 23 0 76 0
0 6 135712 672272 1540 203204 16500 0 17488 0 4038 18398 1 22 0 78 0
0 4 122128 658556 1604 216780 13616 0 14748 12 3374 16222 0 23 0 77 0
0 4 109360 646788 1776 228324 12648 0 13164 4 3176 15188 0 24 3 72 0
2 5 92496 630396 2112 244384 16860 0 17460 4 4215 19614 1 24 5 71 0
0 6 78620 617316 2508 257136 12688 0 13940 0 3229 14086 1 21 0 79 0
3 3 64764 603536 3144 270072 13692 0 14576 8 3454 16506 1 20 2 76 0
2 4 51660 590236 3168 283432 12624 0 14464 20 3240 14237 1 20 3 77 0
2 4 36852 576732 1692 298600 14832 0 15280 4 3765 17769 1 27 0 73 0
0 3 23800 563920 2532 310624 12820 0 13640 0 3274 14940 1 20 0 80 0
0 4 7488 548920 3072 325044 14708 0 15892 0 3753 16459 1 24 36 39 0
0 1 0 545672 1896 331240 5192 0 6948 65 1450 7353 0 9 38 53 0
0 1 0 545732 1432 331604 0 0 208 0 62 926 1 1 50 50 0
0 1 0 545048 2488 331096 0 0 2080 0 98 1699 0 1 42 56 0
0 2 0 544916 3512 330444 0 0 2032 4 96 1520 0 3 45 53 0
**********************************************************************
kernel still does not want to cache programs in memory:
[42706.496411] xterm(32737): READ block 49743048 on sda8
[42706.496428] xterm(32737): READ block 49743104 on sda8
[42706.496438] xterm(32737): READ block 49743136 on sda8
[42706.496449] xterm(32737): READ block 49743176 on sda8
[42706.496460] xterm(32737): READ block 49743224 on sda8
[42706.496475] xterm(32737): READ block 49743264 on sda8
sda8 = /usr
**********************************************************************
zoneinfo:
Node 0, zone DMA
pages free 2590
min 17
low 21
high 25
scanned 0 (a: 13 i: 5)
spanned 4096
present 4064
nr_free_pages 2590
nr_inactive 0
nr_active 0
nr_anon_pages 0
nr_mapped 1
nr_file_pages 0
nr_dirty 0
nr_writeback 0
nr_slab_reclaimable 0
nr_slab_unreclaimable 11
nr_page_table_pages 0
nr_unstable 0
nr_bounce 0
nr_vmscan_write 994
protection: (0, 873, 975)
pagesets
cpu: 0 pcp: 0
count: 0
high: 0
batch: 1
cpu: 0 pcp: 1
count: 0
high: 0
batch: 1
vm stats threshold: 4
cpu: 1 pcp: 0
count: 0
high: 0
batch: 1
cpu: 1 pcp: 1
count: 0
high: 0
batch: 1
vm stats threshold: 4
all_unreclaimable: 1
prev_priority: 12
start_pfn: 0
Node 0, zone Normal
pages free 190917
min 936
low 1170
high 1404
scanned 62 (a: 0 i: 8)
spanned 225280
present 223520
nr_free_pages 190917
nr_inactive 30
nr_active 695
nr_anon_pages 492
nr_mapped 210
nr_file_pages 704
nr_dirty 0
nr_writeback 0
nr_slab_reclaimable 1451
nr_slab_unreclaimable 5215
nr_page_table_pages 1900
nr_unstable 0
nr_bounce 0
nr_vmscan_write 245614
protection: (0, 0, 817)
pagesets
cpu: 0 pcp: 0
count: 35
high: 186
batch: 31
cpu: 0 pcp: 1
count: 53
high: 62
batch: 15
vm stats threshold: 16
cpu: 1 pcp: 0
count: 15
high: 186
batch: 31
cpu: 1 pcp: 1
count: 60
high: 62
batch: 15
vm stats threshold: 16
all_unreclaimable: 0
prev_priority: 5
start_pfn: 4096
Node 0, zone HighMem
pages free 18198
min 32
low 59
high 86
scanned 109 (a: 0 i: 0)
spanned 26368
present 26162
nr_free_pages 18198
nr_inactive 834
nr_active 5547
nr_anon_pages 3077
nr_mapped 1988
nr_file_pages 6340
nr_dirty 1
nr_writeback 2
nr_slab_reclaimable 0
nr_slab_unreclaimable 0
nr_page_table_pages 0
nr_unstable 0
nr_bounce 0
nr_vmscan_write 123743
protection: (0, 0, 0)
pagesets
cpu: 0 pcp: 0
count: 7
high: 42
batch: 7
cpu: 0 pcp: 1
count: 11
high: 14
batch: 3
vm stats threshold: 4
cpu: 1 pcp: 0
count: 5
high: 42
batch: 7
cpu: 1 pcp: 1
count: 0
high: 14
batch: 3
vm stats threshold: 4
all_unreclaimable: 0
prev_priority: 5
start_pfn: 229376
buddyinfo:
Node 0, zone DMA 12 12 13 11 9 7 4 4 3 1 0
Node 0, zone Normal 0 1 1 23 306 996 513 195 59 27 9
Node 0, zone HighMem 10 0 1 0 1 1 0 0 0 0 0
**********************************************************************
sysrq-m before turning off swap
2007-08-30 12:23:07.055746266 <6>[40356.028164] SysRq : Show Memory
2007-08-30 12:23:07.055751434 <6>[40356.028173] Mem-info:
2007-08-30 12:23:07.055753111 <4>[40356.028176] DMA per-cpu:
2007-08-30 12:23:07.055754787 <4>[40356.028179] CPU 0: Hot: hi: 0, btch: 1 usd: 0 Cold: hi: 0, btch: 1 usd: 0
2007-08-30 12:23:07.055756812 <4>[40356.028183] CPU 1: Hot: hi: 0, btch: 1 usd: 0 Cold: hi: 0, btch: 1 usd: 0
2007-08-30 12:23:07.055758837 <4>[40356.028190] Normal per-cpu:
2007-08-30 12:23:07.055760444 <4>[40356.028193] CPU 0: Hot: hi: 186, btch: 31 usd: 6 Cold: hi: 62, btch: 15 usd: 59
2007-08-30 12:23:07.213548190 <4>[40356.028197] CPU 1: Hot: hi: 186, btch: 31 usd: 14 Cold: hi: 62, btch: 15 usd: 58
2007-08-30 12:23:07.213550844 <4>[40356.028200] HighMem per-cpu:
2007-08-30 12:23:07.213552520 <4>[40356.028203] CPU 0: Hot: hi: 42, btch: 7 usd: 0 Cold: hi: 14, btch: 3 usd: 13
2007-08-30 12:23:07.213554755 <4>[40356.028207] CPU 1: Hot: hi: 42, btch: 7 usd: 5 Cold: hi: 14, btch: 3 usd: 2
2007-08-30 12:23:07.213565231 <4>[40356.028212] Active:4675 inactive:1289 dirty:3 writeback:0 unstable:0
2007-08-30 12:23:07.213567396 <4>[40356.028213] free:213161 slab:6460 mapped:1672 pagetables:1776 bounce:0
2007-08-30 12:23:07.213569282 <4>[40356.028218] DMA free:10368kB min:68kB low:84kB high:100kB active:0kB inactive:0kB present:16256kB pages_scanned:0 all_unreclaimable? yes
2007-08-30 12:23:07.213593027 <4>[40356.028222] lowmem_reserve[]: 0 873 975
2007-08-30 12:23:07.213594843 <4>[40356.028229] Normal free:765076kB min:3744kB low:4680kB high:5616kB active:2444kB inactive:240kB present:894080kB pages_scanned:482 all_unreclaimable? no
2007-08-30 12:23:07.213597218 <4>[40356.028232] lowmem_reserve[]: 0 0 817
2007-08-30 12:23:07.213598894 <4>[40356.028239] HighMem free:77200kB min:128kB low:236kB high:344kB active:16284kB inactive:4916kB present:104648kB pages_scanned:63 all_unreclaimable? no
2007-08-30 12:23:07.213606087 <4>[40356.028242] lowmem_reserve[]: 0 0 0
2007-08-30 12:23:07.213607903 <4>[40356.028246] DMA: 12*4kB 12*8kB 13*16kB 11*32kB 9*64kB 7*128kB 4*256kB 4*512kB 3*1024kB 1*2048kB 0*4096kB = 10368kB
2007-08-30 12:23:07.213610068 <4>[40356.028259] Normal: 3659*4kB 3939*8kB 3103*16kB 2323*32kB 1592*64kB 1014*128kB 511*256kB 188*512kB 59*1024kB 19*2048kB 9*4096kB = 765076kB
2007-08-30 12:23:07.213639960 <4>[40356.028272] HighMem: 1*4kB 1*8kB 0*16kB 100*32kB 192*64kB 156*128kB 73*256kB 31*512kB 5*1024kB 1*2048kB 0*4096kB = 77196kB
2007-08-30 12:23:07.213642404 <4>[40356.028286] Swap cache: add 642131, delete 638843, find 136452/188191, race 0+61
2007-08-30 12:23:07.213644429 <4>[40356.028289] Free swap = 3583204kB
2007-08-30 12:23:07.213646036 <4>[40356.028291] Total swap = 3911784kB
2007-08-30 12:23:07.213658816 <6>[40356.028293] Free swap: 3583204kB
2007-08-30 12:23:07.213660562 <6>[40356.031284] 255744 pages of RAM
2007-08-30 12:23:07.213662169 <6>[40356.031287] 26368 pages of HIGHMEM
2007-08-30 12:23:07.213663845 <6>[40356.031289] 4055 reserved pages
2007-08-30 12:23:07.213665521 <6>[40356.031291] 32829 pages shared
2007-08-30 12:23:07.213667197 <6>[40356.031292] 3291 pages swap cached
2007-08-30 12:23:07.213668803 <6>[40356.031294] 3 pages dirty
2007-08-30 12:23:07.213674390 <6>[40356.031296] 0 pages writeback
2007-08-30 12:23:07.213676067 <6>[40356.031298] 1672 pages mapped
2007-08-30 12:23:07.213677673 <6>[40356.031299] 6460 pages slab
2007-08-30 12:23:07.213679279 <6>[40356.031301] 1776 pages pagetables
**********************************************************************
sysrq-m after turning off swap
2007-08-30 12:43:08.616003640 <6>[41557.422867] SysRq : Show Memory
2007-08-30 12:43:08.616008599 <6>[41557.422874] Mem-info:
2007-08-30 12:43:08.616010275 <4>[41557.422876] DMA per-cpu:
2007-08-30 12:43:08.616011951 <4>[41557.422880] CPU 0: Hot: hi: 0, btch: 1 usd: 0 Cold: hi: 0, btch: 1 usd: 0
2007-08-30 12:43:08.616013907 <4>[41557.422884] CPU 1: Hot: hi: 0, btch: 1 usd: 0 Cold: hi: 0, btch: 1 usd: 0
2007-08-30 12:43:08.616015932 <4>[41557.422887] Normal per-cpu:
2007-08-30 12:43:08.616017608 <4>[41557.422890] CPU 0: Hot: hi: 186, btch: 31 usd: 165 Cold: hi: 62, btch: 15 usd: 7
2007-08-30 12:43:08.639776160 <4>[41557.422894] CPU 1: Hot: hi: 186, btch: 31 usd: 27 Cold: hi: 62, btch: 15 usd: 8
2007-08-30 12:43:08.639778744 <4>[41557.422897] HighMem per-cpu:
2007-08-30 12:43:08.639780420 <4>[41557.422900] CPU 0: Hot: hi: 42, btch: 7 usd: 41 Cold: hi: 14, btch: 3 usd: 12
2007-08-30 12:43:08.639782515 <4>[41557.422903] CPU 1: Hot: hi: 42, btch: 7 usd: 25 Cold: hi: 14, btch: 3 usd: 2
2007-08-30 12:43:08.639791943 <4>[41557.422909] Active:82842 inactive:975 dirty:5 writeback:0 unstable:0
2007-08-30 12:43:08.639794108 <4>[41557.422910] free:135962 slab:6166 mapped:1526 pagetables:1738 bounce:0
2007-08-30 12:43:08.639795994 <4>[41557.422915] DMA free:10368kB min:68kB low:84kB high:100kB active:0kB inactive:0kB present:16256kB pages_scanned:0 all_unreclaimable? yes
2007-08-30 12:43:08.639811010 <4>[41557.422918] lowmem_reserve[]: 0 873 975
2007-08-30 12:43:08.639812825 <4>[41557.422926] Normal free:533240kB min:3928kB low:4908kB high:5892kB active:233432kB inactive:2052kB present:894080kB pages_scanned:30272 all_unreclaimable? no
2007-08-30 12:43:08.639815270 <4>[41557.422930] lowmem_reserve[]: 0 0 817
2007-08-30 12:43:08.639816946 <4>[41557.422936] HighMem free:240kB min:128kB low:240kB high:356kB active:97936kB inactive:1848kB present:104648kB pages_scanned:1079 all_unreclaimable? no
2007-08-30 12:43:08.639823092 <4>[41557.422939] lowmem_reserve[]: 0 0 0
2007-08-30 12:43:08.639824978 <4>[41557.422944] DMA: 12*4kB 12*8kB 13*16kB 11*32kB 9*64kB 7*128kB 4*256kB 4*512kB 3*1024kB 1*2048kB 0*4096kB = 10368kB
2007-08-30 12:43:08.639827073 <4>[41557.422956] Normal: 0*4kB 1*8kB 63*16kB 40*32kB 307*64kB 996*128kB 513*256kB 195*512kB 59*1024kB 27*2048kB 9*4096kB = 533176kB
2007-08-30 12:43:08.639832660 <4>[41557.422969] HighMem: 4*4kB 1*8kB 0*16kB 1*32kB 1*64kB 1*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 248kB
2007-08-30 12:43:08.639834825 <4>[41557.422982] Swap cache: add 963483, delete 963486, find 208589/302937, race 0+73
2007-08-30 12:43:08.639836711 <4>[41557.422985] Free swap = 0kB
2007-08-30 12:43:08.639838317 <4>[41557.422987] Total swap = 0kB
2007-08-30 12:43:08.639860805 <6>[41557.422989] Free swap: 0kB
2007-08-30 12:43:08.639873237 <6>[41557.425955] 255744 pages of RAM
2007-08-30 12:43:08.639875053 <6>[41557.425958] 26368 pages of HIGHMEM
2007-08-30 12:43:08.639876729 <6>[41557.425960] 4055 reserved pages
2007-08-30 12:43:08.639878335 <6>[41557.425961] 33020 pages shared
2007-08-30 12:43:08.639879941 <6>[41557.425963] 0 pages swap cached
2007-08-30 12:43:08.639881548 <6>[41557.425965] 5 pages dirty
2007-08-30 12:43:08.639883154 <6>[41557.425967] 0 pages writeback
2007-08-30 12:43:08.639884830 <6>[41557.425969] 1526 pages mapped
2007-08-30 12:43:08.639890068 <6>[41557.425970] 6166 pages slab
2007-08-30 12:43:08.639891744 <6>[41557.425972] 1738 pages pagetables
**********************************************************************
BUG with sysrq-show-timers (I have linux-2.6-highres-timers.patch from
fedora kernel-2.6.22-0.21.rc7.git5.fc8)
2007-08-30 12:57:35.454948818 <6>[42424.026396] SysRq : Show Pending Timers
2007-08-30 12:57:35.454954685 <4>[42424.026408] Timer List Version: v0.3
2007-08-30 12:57:35.454956431 <4>[42424.026410] HRTIMER_MAX_CLOCK_BASES: 2
2007-08-30 12:57:35.454958177 <4>[42424.026413] now at 42408470405177 nsecs
2007-08-30 12:57:35.454959853 <4>[42424.026415]
2007-08-30 12:57:35.454961389 <4>[42424.026416] cpu: 0
2007-08-30 12:57:35.454962996 <4>[42424.026418] clock 0:
2007-08-30 12:57:35.454964602 <4>[42424.026420] .index: 0
2007-08-30 12:57:35.454966208 <4>[42424.026422] .resolution: 1 nsecs
2007-08-30 12:57:35.478895658 <4>[42424.026423] .get_time: ktime_get_real
2007-08-30 12:57:35.478897684 <4>[42424.026435] .offset: 1188425446876518834 nsecs
2007-08-30 12:57:35.478899499 <4>[42424.026437] active timers:
2007-08-30 12:57:35.478901106 <4>[42424.026439] clock 1:
2007-08-30 12:57:35.478902712 <4>[42424.026440] .index: 1
2007-08-30 12:57:35.478904318 <4>[42424.026442] .resolution: 1 nsecs
2007-08-30 12:57:35.478905995 <4>[42424.026444] .get_time: ktime_get
2007-08-30 12:57:35.478913398 <4>[42424.026448] .offset: 0 nsecs
2007-08-30 12:57:35.478915283 <4>[42424.026449] active timers:
2007-08-30 12:57:35.478916890 <4>[42424.026451] #0: <3>BUG: sleeping function called from invalid context at kernel/mutex.c:86
2007-08-30 12:57:35.478918915 <4>[42424.026456] in_atomic():1, irqs_disabled():1
2007-08-30 12:57:35.495332427 <4>[42424.026460] [<c010388b>] show_trace_log_lvl+0x1a/0x30
2007-08-30 12:57:35.495334732 <4>[42424.026466] [<c0104489>] show_trace+0x12/0x14
2007-08-30 12:57:35.495336408 <4>[42424.026470] [<c01044e5>] dump_stack+0x16/0x18
2007-08-30 12:57:35.495338154 <4>[42424.026474] [<c011aa3e>] __might_sleep+0xaa/0xba
2007-08-30 12:57:35.495339900 <4>[42424.026480] [<c04b689e>] mutex_lock+0x15/0x24
2007-08-30 12:57:35.495341576 <4>[42424.026485] [<c013f4b8>] lookup_module_symbol_name+0x17/0xc0
2007-08-30 12:57:35.495343392 <4>[42424.026490] [<c013fb69>] lookup_symbol_name+0x3f/0x43
2007-08-30 12:57:35.495350656 <4>[42424.026494] [<c0136a76>] print_name_offset+0x1f/0x96
2007-08-30 12:57:35.495352471 <4>[42424.026499] [<c0137454>] timer_list_show+0x6a4/0xa8e
2007-08-30 12:57:35.495354287 <4>[42424.026503] [<c013784a>] sysrq_timer_list_show+0xc/0x12
2007-08-30 12:57:35.495356033 <4>[42424.026508] [<c032a6a1>] sysrq_handle_show_timers+0x8/0xa
2007-08-30 12:57:35.495357849 <4>[42424.026513] [<c032a5ac>] __handle_sysrq+0x7b/0x115
2007-08-30 12:57:35.495363436 <4>[42424.026517] [<c032a666>] handle_sysrq+0x20/0x24
2007-08-30 12:57:35.495365252 <4>[42424.026521] [<c0324ffc>] kbd_event+0x3a3/0x5b7
2007-08-30 12:57:35.495366998 <4>[42424.026526] [<c03efdd0>] input_event+0xc5/0x474
2007-08-30 12:57:35.495368744 <4>[42424.026531] [<c0412b40>] hidinput_hid_event+0x19a/0x480
2007-08-30 12:57:35.495370490 <4>[42424.026537] [<c040ec23>] hid_process_event+0x5f/0x61
2007-08-30 12:57:35.495372236 <4>[42424.026542] [<c040eea9>] hid_input_field+0x284/0x2f1
2007-08-30 12:57:35.495383410 <4>[42424.026546] [<c040efc8>] hid_input_report+0xb2/0x102
2007-08-30 12:57:35.495385226 <4>[42424.026550] [<c0414955>] hid_irq_in+0x120/0x166
2007-08-30 12:57:35.495387042 <4>[42424.026554] [<c03dfa83>] usb_hcd_giveback_urb+0x15/0x49
2007-08-30 12:57:35.495388788 <4>[42424.026559] [<f886aa7e>] uhci_giveback_urb+0x64/0x182 [uhci_hcd]
2007-08-30 12:57:35.495390604 <4>[42424.026586] [<f886b175>] uhci_scan_schedule+0x4d1/0x8a6 [uhci_hcd]
2007-08-30 12:57:35.495414210 <4>[42424.026595] [<f886cedc>] uhci_irq+0x69/0x15b [uhci_hcd]
2007-08-30 12:57:35.495416235 <4>[42424.026604] [<c03dfd17>] usb_hcd_irq+0x25/0x54
2007-08-30 12:57:35.495417981 <4>[42424.026609] [<c0148692>] handle_IRQ_event+0x2c/0x55
2007-08-30 12:57:35.495419727 <4>[42424.026614] [<c0149b2d>] handle_fasteoi_irq+0x65/0xbe
2007-08-30 12:57:35.495421473 <4>[42424.026618] [<c0104f68>] do_IRQ+0x48/0xa0
2007-08-30 12:57:35.495427689 <4>[42424.026622] [<c01032bb>] common_interrupt+0x23/0x28
2007-08-30 12:57:35.495429505 <4>[42424.026626] [<c0100afa>] mwait_idle+0xd/0xf
2007-08-30 12:57:35.495431250 <4>[42424.026630] [<c0100c01>] cpu_idle+0x61/0x76
2007-08-30 12:57:35.495432927 <4>[42424.026633] [<c04b4efd>] rest_init+0x4d/0x60
2007-08-30 12:57:35.495434673 <4>[42424.026638] [<c0605cb5>] start_kernel+0x2d5/0x360
2007-08-30 12:57:35.495436419 <4>[42424.026642] [<00000000>] _stext+0x3fefff50/0x19
2007-08-30 12:57:35.495441866 <4>[42424.026646] =======================
2007-08-30 12:57:35.495443612 <3>[42424.026649] BUG: scheduling while atomic: swapper/0x10010000/0
2007-08-30 12:57:35.495454507 <4>[42424.026652] [<c010388b>] show_trace_log_lvl+0x1a/0x30
2007-08-30 12:57:35.495456393 <4>[42424.026656] [<c0104489>] show_trace+0x12/0x14
2007-08-30 12:57:35.495458139 <4>[42424.026660] [<c01044e5>] dump_stack+0x16/0x18
2007-08-30 12:57:35.495459885 <4>[42424.026664] [<c011c729>] __schedule_bug+0x3b/0x3d
2007-08-30 12:57:35.495461631 <4>[42424.026668] [<c04b5782>] __sched_text_start+0x5b2/0x6b4
2007-08-30 12:57:35.495463447 <4>[42424.026673] [<c011c750>] __cond_resched+0x25/0x3c
2007-08-30 12:57:35.495468754 <4>[42424.026677] [<c04b58ef>] cond_resched+0x2a/0x31
2007-08-30 12:57:35.495470500 <4>[42424.026681] [<c04b68a3>] mutex_lock+0x1a/0x24
2007-08-30 12:57:35.495472246 <4>[42424.026685] [<c013f4b8>] lookup_module_symbol_name+0x17/0xc0
2007-08-30 12:57:35.495474062 <4>[42424.026690] [<c013fb69>] lookup_symbol_name+0x3f/0x43
2007-08-30 12:57:35.495475808 <4>[42424.026694] [<c0136a76>] print_name_offset+0x1f/0x96
2007-08-30 12:57:35.495477624 <4>[42424.026699] [<c0137454>] timer_list_show+0x6a4/0xa8e
2007-08-30 12:57:35.495482722 <4>[42424.026703] [<c013784a>] sysrq_timer_list_show+0xc/0x12
2007-08-30 12:57:35.495484608 <4>[42424.026707] [<c032a6a1>] sysrq_handle_show_timers+0x8/0xa
2007-08-30 12:57:35.495486424 <4>[42424.026711] [<c032a5ac>] __handle_sysrq+0x7b/0x115
2007-08-30 12:57:35.495488170 <4>[42424.026715] [<c032a666>] handle_sysrq+0x20/0x24
2007-08-30 12:57:35.495489986 <4>[42424.026719] [<c0324ffc>] kbd_event+0x3a3/0x5b7
2007-08-30 12:57:35.495501090 <4>[42424.026723] [<c03efdd0>] input_event+0xc5/0x474
2007-08-30 12:57:35.495502976 <4>[42424.026727] [<c0412b40>] hidinput_hid_event+0x19a/0x480
2007-08-30 12:57:35.495504792 <4>[42424.026732] [<c040ec23>] hid_process_event+0x5f/0x61
2007-08-30 12:57:35.495506538 <4>[42424.026737] [<c040eea9>] hid_input_field+0x284/0x2f1
2007-08-30 12:57:35.495508284 <4>[42424.026741] [<c040efc8>] hid_input_report+0xb2/0x102
2007-08-30 12:57:35.495510099 <4>[42424.026746] [<c0414955>] hid_irq_in+0x120/0x166
2007-08-30 12:57:35.495515547 <4>[42424.026749] [<c03dfa83>] usb_hcd_giveback_urb+0x15/0x49
2007-08-30 12:57:35.495517363 <4>[42424.026754] [<f886aa7e>] uhci_giveback_urb+0x64/0x182 [uhci_hcd]
2007-08-30 12:57:35.495519179 <4>[42424.026763] [<f886b175>] uhci_scan_schedule+0x4d1/0x8a6 [uhci_hcd]
2007-08-30 12:57:35.495523299 <4>[42424.026772] [<f886cedc>] uhci_irq+0x69/0x15b [uhci_hcd]
2007-08-30 12:57:35.495525184 <4>[42424.026781] [<c03dfd17>] usb_hcd_irq+0x25/0x54
2007-08-30 12:57:35.495530702 <4>[42424.026786] [<c0148692>] handle_IRQ_event+0x2c/0x55
2007-08-30 12:57:35.495532517 <4>[42424.026790] [<c0149b2d>] handle_fasteoi_irq+0x65/0xbe
2007-08-30 12:57:35.495534333 <4>[42424.026795] [<c0104f68>] do_IRQ+0x48/0xa0
2007-08-30 12:57:35.495536009 <4>[42424.026798] [<c01032bb>] common_interrupt+0x23/0x28
2007-08-30 12:57:35.495537755 <4>[42424.026802] [<c0100afa>] mwait_idle+0xd/0xf
2007-08-30 12:57:35.495539501 <4>[42424.026806] [<c0100c01>] cpu_idle+0x61/0x76
2007-08-30 12:57:35.495560593 <4>[42424.026810] [<c04b4efd>] rest_init+0x4d/0x60
2007-08-30 12:57:35.495562479 <4>[42424.026814] [<c0605cb5>] start_kernel+0x2d5/0x360
2007-08-30 12:57:35.495564225 <4>[42424.026818] [<00000000>] _stext+0x3fefff50/0x19
2007-08-30 12:57:35.495565971 <4>[42424.026822] =======================
2007-08-30 12:57:35.495567647 <4>[42424.026914] WARNING: at kernel/mutex.c:132 __mutex_lock_common()
2007-08-30 12:57:35.495569463 <4>[42424.026918] [<c010388b>] show_trace_log_lvl+0x1a/0x30
2007-08-30 12:57:35.495575678 <4>[42424.026923] [<c0104489>] show_trace+0x12/0x14
2007-08-30 12:57:35.495577494 <4>[42424.026926] [<c01044e5>] dump_stack+0x16/0x18
2007-08-30 12:57:35.495579240 <4>[42424.026930] [<c04b6884>] __mutex_lock_slowpath+0x219/0x21e
2007-08-30 12:57:35.495581056 <4>[42424.026935] [<c04b68aa>] mutex_lock+0x21/0x24
2007-08-30 12:57:35.495588180 <4>[42424.026939] [<c013f4b8>] lookup_module_symbol_name+0x17/0xc0
2007-08-30 12:57:35.495589996 <4>[42424.026943] [<c013fb69>] lookup_symbol_name+0x3f/0x43
2007-08-30 12:57:35.495596072 <4>[42424.026947] [<c0136a76>] print_name_offset+0x1f/0x96
2007-08-30 12:57:35.495597887 <4>[42424.026952] [<c0137454>] timer_list_show+0x6a4/0xa8e
2007-08-30 12:57:35.495599633 <4>[42424.026956] [<c013784a>] sysrq_timer_list_show+0xc/0x12
2007-08-30 12:57:35.495601449 <4>[42424.026960] [<c032a6a1>] sysrq_handle_show_timers+0x8/0xa
2007-08-30 12:57:35.495603265 <4>[42424.026964] [<c032a5ac>] __handle_sysrq+0x7b/0x115
2007-08-30 12:57:35.495608643 <4>[42424.026968] [<c032a666>] handle_sysrq+0x20/0x24
2007-08-30 12:57:35.495619677 <4>[42424.026971] [<c0324ffc>] kbd_event+0x3a3/0x5b7
2007-08-30 12:57:35.495621493 <4>[42424.026975] [<c03efdd0>] input_event+0xc5/0x474
2007-08-30 12:57:35.495623239 <4>[42424.026980] [<c0412b40>] hidinput_hid_event+0x19a/0x480
2007-08-30 12:57:35.495625055 <4>[42424.026984] [<c040ec23>] hid_process_event+0x5f/0x61
2007-08-30 12:57:35.495626801 <4>[42424.026989] [<c040eea9>] hid_input_field+0x284/0x2f1
2007-08-30 12:57:35.495628547 <4>[42424.026993] [<c040efc8>] hid_input_report+0xb2/0x102
2007-08-30 12:57:35.495634204 <4>[42424.026997] [<c0414955>] hid_irq_in+0x120/0x166
2007-08-30 12:57:35.495636090 <4>[42424.027001] [<c03dfa83>] usb_hcd_giveback_urb+0x15/0x49
2007-08-30 12:57:35.495637836 <4>[42424.027012] [<f886aa7e>] uhci_giveback_urb+0x64/0x182 [uhci_hcd]
2007-08-30 12:57:35.495639721 <4>[42424.027022] [<f886b175>] uhci_scan_schedule+0x4d1/0x8a6 [uhci_hcd]
2007-08-30 12:57:35.495641537 <4>[42424.027031] [<f886cedc>] uhci_irq+0x69/0x15b [uhci_hcd]
2007-08-30 12:57:35.495646775 <4>[42424.027040] [<c03dfd17>] usb_hcd_irq+0x25/0x54
2007-08-30 12:57:35.495648591 <4>[42424.027044] [<c0148692>] handle_IRQ_event+0x2c/0x55
2007-08-30 12:57:35.495650337 <4>[42424.027049] [<c0149b2d>] handle_fasteoi_irq+0x65/0xbe
2007-08-30 12:57:35.495652153 <4>[42424.027052] [<c0104f68>] do_IRQ+0x48/0xa0
2007-08-30 12:57:35.495653899 <4>[42424.027056] [<c01032bb>] common_interrupt+0x23/0x28
2007-08-30 12:57:35.495655645 <4>[42424.027060] [<c0100afa>] mwait_idle+0xd/0xf
2007-08-30 12:57:35.495666260 <4>[42424.027063] [<c0100c01>] cpu_idle+0x61/0x76
2007-08-30 12:57:35.495668076 <4>[42424.027067] [<c04b4efd>] rest_init+0x4d/0x60
2007-08-30 12:57:35.495669822 <4>[42424.027071] [<c0605cb5>] start_kernel+0x2d5/0x360
2007-08-30 12:57:35.495671568 <4>[42424.027075] [<00000000>] _stext+0x3fefff50/0x19
2007-08-30 12:57:35.495673244 <4>[42424.027078] =======================
2007-08-30 12:57:35.495674921 <4>[42424.027085] <c05ffc64>, tick_sched_timer, S:01
2007-08-30 12:57:35.495680508 <4>[42424.027093] # expires at 42408471000000 nsecs [in 594823 nsecs]
2007-08-30 12:57:35.495682393 <4>[42424.027096] #1: <c05ffc64>, hrtimer_wakeup, S:01
2007-08-30 12:57:35.495684209 <4>[42424.027107] # expires at 42408513072773 nsecs [in 42667596 nsecs]
2007-08-30 12:57:35.495686025 <4>[42424.027110] #2: <c05ffc64>, hrtimer_wakeup, S:01
2007-08-30 12:57:35.495687771 <4>[42424.027121] # expires at 42408513083563 nsecs [in 42678386 nsecs]
2007-08-30 12:57:35.495702018 <4>[42424.027123] #3: <c05ffc64>, hrtimer_wakeup, S:01
2007-08-30 12:57:35.495703974 <4>[42424.027134] # expires at 42408536549064 nsecs [in 66143887 nsecs]
2007-08-30 12:57:35.495705790 <4>[42424.027136] #4: <c05ffc64>, hrtimer_wakeup, S:01
2007-08-30 12:57:35.495707536 <4>[42424.027147] # expires at 42674800484097 nsecs [in 266330078920 nsecs]
2007-08-30 12:57:35.495709421 <4>[42424.027150] #5: <c05ffc64>, hrtimer_wakeup, S:01
2007-08-30 12:57:35.495715358 <4>[42424.027161] # expires at 45147113726167 nsecs [in 2738643320990 nsecs]
2007-08-30 12:57:35.495727370 <4>[42424.027164] .expires_next : 42408472000000 nsecs
2007-08-30 12:57:35.495729256 <4>[42424.027166] .hres_active : 1
2007-08-30 12:57:35.495730932 <4>[42424.027168] .nr_events : 44414003
2007-08-30 12:57:35.495732608 <4>[42424.027170] .nohz_mode : 0
2007-08-30 12:57:35.495734214 <4>[42424.027172] .idle_tick : 0 nsecs
2007-08-30 12:57:35.495735960 <4>[42424.027174] .tick_stopped : 0
2007-08-30 12:57:35.495741478 <4>[42424.027176] .idle_jiffies : 0
2007-08-30 12:57:35.495743154 <4>[42424.027178] .idle_calls : 0
2007-08-30 12:57:35.495744830 <4>[42424.027179] .idle_sleeps : 0
2007-08-30 12:57:35.495746506 <4>[42424.027181] .idle_entrytime : 0 nsecs
2007-08-30 12:57:35.495748182 <4>[42424.027183] .idle_sleeptime : 0 nsecs
2007-08-30 12:57:35.495749859 <4>[42424.027185] .last_jiffies : 0
2007-08-30 12:57:35.495751535 <4>[42424.027186] .next_jiffies : 0
2007-08-30 12:57:35.495756633 <4>[42424.027188] .idle_expires : 0 nsecs
2007-08-30 12:57:35.495758379 <4>[42424.027190] jiffies: 42108471
2007-08-30 12:57:35.495759985 <4>[42424.027192]
**********************************************************************
/proc/vmstat
timestamp 2007-08-30 12:43:23.509528789
nr_free_pages 135862
nr_inactive 864
nr_active 82948
nr_anon_pages 81413
nr_mapped 1591
nr_file_pages 2417
nr_dirty 3
nr_writeback 0
nr_slab_reclaimable 1214
nr_slab_unreclaimable 4973
nr_page_table_pages 1732
nr_unstable 0
nr_bounce 0
nr_vmscan_write 476760
pgpgin 7936229
pgpgout 3377652
pswpin 618141
pswpout 474034
pgalloc_dma 62031
pgalloc_normal 13340024
pgalloc_high 2677476
pgfree 16215751
pgactivate 1915016
pgdeactivate 2712942
pgfault 16662815
pgmajfault 139749
pgrefill_dma 26720
pgrefill_normal 16836591
pgrefill_high 16097035
pgsteal_dma 7873
pgsteal_normal 905360
pgsteal_high 1365757
pgscan_kswapd_dma 11210
pgscan_kswapd_normal 1609198
pgscan_kswapd_high 2445938
pgscan_direct_dma 384
pgscan_direct_normal 773902
pgscan_direct_high 15608
pginodesteal 0
slabs_scanned 224256
kswapd_steal 2111707
kswapd_inodesteal 777
pageoutrun 35884
allocstall 5970
pgrotated 451880
**********************************************************************
/proc/vmstat
timestamp 2007-08-30 12:43:45.381753791
nr_free_pages 136205
nr_inactive 1070
nr_active 82535
nr_anon_pages 81344
nr_mapped 1502
nr_file_pages 2265
nr_dirty 2
nr_writeback 0
nr_slab_reclaimable 1214
nr_slab_unreclaimable 4960
nr_page_table_pages 1732
nr_unstable 0
nr_bounce 0
nr_vmscan_write 476776
pgpgin 7964897
pgpgout 3377954
pswpin 618141
pswpout 474034
pgalloc_dma 62031
pgalloc_normal 13343747
pgalloc_high 2682342
pgfree 16224587
pgactivate 1925519
pgdeactivate 2723791
pgfault 16666297
pgmajfault 140086
pgrefill_dma 26720
pgrefill_normal 17928408
pgrefill_high 16552359
pgsteal_dma 7873
pgsteal_normal 908085
pgsteal_high 1370369
pgscan_kswapd_dma 11210
pgscan_kswapd_normal 1616139
pgscan_kswapd_high 2456741
pgscan_direct_dma 384
pgscan_direct_normal 773902
pgscan_direct_high 15608
pginodesteal 0
slabs_scanned 224256
kswapd_steal 2119044
kswapd_inodesteal 777
pageoutrun 35981
allocstall 5970
pgrotated 451896
Did I forget to include some info???
Oh, and I need to reboot in order to get usable system
when this bug happens.
--
Do what you love because life is too short for anything else.
Sami Farin wrote:
> Using SMP kernel 2.6.22.6pre-CFS-v20.5 on Pentium D (IA-32).
> I think this bug (or whatever you want to call it) got triggered
> when you first allocate several megabytes of memory in a kernel module
> and then free them, and then run e.g. X and when memory gets tight,
> you end up with this situation...
>
> Top 2 /proc/vmstat Biggest Winners:
>
> pgrefill_normal:49900/second
> pgrefill_high:20810/second
That means the pageout code was scanning about 70000 pages
per second on your system during peak stress. You may have
run into a scalability problem in the Linux kernel, where it
wants to clear the referenced bit off all the anonymous pages
before swapping something out.
To make matters worse, that unlucky page gets chosen because
it was the page where kswapd started scanning. It has little
to do with being the least recently used page, because every
anonymous page tends to have its referenced bit set by the time
we start scanning.
On truly enormous systems, say with 256GB of memory, kswapd
sometimes needs to scan hundreds of thousands or even millions
of pages before finding something to swap out. Not fun.
> Did I forget to include some info???
> Oh, and I need to reboot in order to get usable system
> when this bug happens.
Is the system trying to evict pages like crazy when your
system becomes unusable?
If so, I wonder if kswapd is simply doing the wrong thing
and trying to evict data from all zones, simply because the
highmem zone is low on free pages...
--
Politics is the struggle between those who want to make their country
the best in the world, and those who believe it already is. Each group
calls the other unpatriotic.
On Tue, Sep 04, 2007 at 21:37:35 -0400, Rik van Riel wrote:
> Sami Farin wrote:
>> Using SMP kernel 2.6.22.6pre-CFS-v20.5 on Pentium D (IA-32).
>> I think this bug (or whatever you want to call it) got triggered
>> when you first allocate several megabytes of memory in a kernel module
>> and then free them, and then run e.g. X and when memory gets tight,
>> you end up with this situation...
>> Top 2 /proc/vmstat Biggest Winners:
>> pgrefill_normal:49900/second
>> pgrefill_high:20810/second
>
> That means the pageout code was scanning about 70000 pages
> per second on your system during peak stress. You may have
> run into a scalability problem in the Linux kernel, where it
> wants to clear the referenced bit off all the anonymous pages
> before swapping something out.
Thanks for analysis...
Why turning off swap did not make any difference?
Why does is not keep e.g. xterm in memory (which I had 700MB free)?
> To make matters worse, that unlucky page gets chosen because
> it was the page where kswapd started scanning. It has little
> to do with being the least recently used page, because every
> anonymous page tends to have its referenced bit set by the time
> we start scanning.
>
> On truly enormous systems, say with 256GB of memory, kswapd
> sometimes needs to scan hundreds of thousands or even millions
> of pages before finding something to swap out. Not fun.
>
>> Did I forget to include some info???
>> Oh, and I need to reboot in order to get usable system
>> when this bug happens.
>
> Is the system trying to evict pages like crazy when your
> system becomes unusable?
I think so..
> If so, I wonder if kswapd is simply doing the wrong thing
> and trying to evict data from all zones, simply because the
> highmem zone is low on free pages...
*shrug*
--
"If we put the Pentagon's personnel managers in charge of the Sahara
Desert, they would run out of sand in five years." -Sayen Report
Sami Farin wrote:
> On Tue, Sep 04, 2007 at 21:37:35 -0400, Rik van Riel wrote:
>> Is the system trying to evict pages like crazy when your
>> system becomes unusable?
>
> I think so..
>
>> If so, I wonder if kswapd is simply doing the wrong thing
>> and trying to evict data from all zones, simply because the
>> highmem zone is low on free pages...
>
> *shrug*
The attached patch should make sure kswapd does not free an
excessive number of pages in zone_normal just because the
pages in zone_highmem are difficult to free.
It does give kswapd a large margin to continue putting equal
pressure on all zones in normal situations.
Sami, could you try out this patch to see if it helps your
situation?
Signed-off-by: Rik van Riel <[email protected]>
On Wed, Sep 05, 2007 at 12:24:26 -0400, Rik van Riel wrote:
...
>> *shrug*
>
> The attached patch should make sure kswapd does not free an
> excessive number of pages in zone_normal just because the
> pages in zone_highmem are difficult to free.
>
> It does give kswapd a large margin to continue putting equal
> pressure on all zones in normal situations.
>
> Sami, could you try out this patch to see if it helps your
> situation?
Thanks, Rik. bzImage is ready, I probably reboot inside one
month for a reason or other 8-)
--
Do what you love because life is too short for anything else.
Sami Farin wrote:
> On Wed, Sep 05, 2007 at 12:24:26 -0400, Rik van Riel wrote:
> ...
>>> *shrug*
>> The attached patch should make sure kswapd does not free an
>> excessive number of pages in zone_normal just because the
>> pages in zone_highmem are difficult to free.
>>
>> It does give kswapd a large margin to continue putting equal
>> pressure on all zones in normal situations.
>>
>> Sami, could you try out this patch to see if it helps your
>> situation?
>
> Thanks, Rik. bzImage is ready, I probably reboot inside one
> month for a reason or other 8-)
The more I look at the bug, the more I see that it is probably
not very easy to reproduce on demand. I have, however, a full
explanation on why it happens and why the patch should fix it,
so I will submit it for inclusion in -mm.
Sami, thank you for the detailed bug report.
--
Politics is the struggle between those who want to make their country
the best in the world, and those who believe it already is. Each group
calls the other unpatriotic.
On Wed, Sep 05, 2007 at 18:48:51 -0400, Rik van Riel wrote:
> Sami Farin wrote:
>> On Wed, Sep 05, 2007 at 12:24:26 -0400, Rik van Riel wrote:
>> ...
>>>> *shrug*
>>> The attached patch should make sure kswapd does not free an
>>> excessive number of pages in zone_normal just because the
>>> pages in zone_highmem are difficult to free.
>>>
>>> It does give kswapd a large margin to continue putting equal
>>> pressure on all zones in normal situations.
>>>
>>> Sami, could you try out this patch to see if it helps your
>>> situation?
>>
>> Thanks, Rik. bzImage is ready, I probably reboot inside one
>> month for a reason or other 8-)
>
> The more I look at the bug, the more I see that it is probably
> not very easy to reproduce on demand. I have, however, a full
Well, I now booted to x86_64 kernel.
I can still reproduce this.
When I unload ipset modules, kernel resumes "normal" operation, i.e.,
not swapping like mad.
sysrq-m, normal operation:
[172074.989053] SysRq : Show Memory
[172074.989063] Mem-info:
[172074.989071] DMA per-cpu:
[172074.989078] CPU 0: Hot: hi: 0, btch: 1 usd: 0 Cold: hi: 0, btch: 1 usd: 0
[172074.989083] CPU 1: Hot: hi: 0, btch: 1 usd: 0 Cold: hi: 0, btch: 1 usd: 0
[172074.989089] DMA32 per-cpu:
[172074.989094] CPU 0: Hot: hi: 186, btch: 31 usd: 153 Cold: hi: 62, btch: 15 usd: 10
[172074.989101] CPU 1: Hot: hi: 186, btch: 31 usd: 34 Cold: hi: 62, btch: 15 usd: 14
[172074.989109] Active:123048 inactive:55194 dirty:5 writeback:0 unstable:0
[172074.989111] free:15001 slab:27961 mapped:15063 pagetables:2996 bounce:0
[172074.989118] DMA free:5560kB min:32kB low:40kB high:48kB active:404kB inactive:736kB present:8620kB pages_scanned:0 all_unreclaimable? no
[172074.989124] lowmem_reserve[]: 0 968 968
[172074.989143] DMA32 free:54444kB min:3964kB low:4952kB high:5944kB active:491788kB inactive:220040kB present:991996kB pages_scanned:0 all_unreclaimable? no
[172074.989150] lowmem_reserve[]: 0 0 0
[172074.989166] DMA: 276*4kB 121*8kB 30*16kB 6*32kB 0*64kB 0*128kB 1*256kB 1*512kB 2*1024kB 0*2048kB 0*4096kB = 5560kB
[172074.989205] DMA32: 9467*4kB 1222*8kB 121*16kB 22*32kB 3*64kB 1*128kB 1*256kB 3*512kB 0*1024kB 1*2048kB 0*4096kB = 54444kB
[172074.989249] Swap cache: add 613353, delete 556659, find 441592/473681, race 0+5
[172074.989255] Free swap = 2751640kB
[172074.989260] Total swap = 3911784kB
[172074.989265] Free swap: 2751640kB
[172074.993693] 255744 pages of RAM
[172074.993699] 6060 reserved pages
[172074.993702] 79933 pages shared
[172074.993706] 56719 pages swap cached
then it goes bad:
[172373.542933] net/ipv4/netfilter/ip_set_nethash.c: retry: rehashing of set blockedp2pnew triggered: hashsize grows from 262144 to 288358
[172373.554837] net/ipv4/netfilter/ip_set_nethash.c: retry: rehashing of set blockedp2pnew triggered: hashsize grows from 262144 to 317193
[172373.561167] net/ipv4/netfilter/ip_set_nethash.c: retry: rehashing of set blockedp2pnew triggered: hashsize grows from 262144 to 348912
[172373.569375] net/ipv4/netfilter/ip_set_nethash.c: retry: rehashing of set blockedp2pnew triggered: hashsize grows from 262144 to 383803
[172394.471570] SysRq : Show Memory
[172394.471580] Mem-info:
[172394.471583] DMA per-cpu:
[172394.471586] CPU 0: Hot: hi: 0, btch: 1 usd: 0 Cold: hi: 0, btch: 1 usd: 0
[172394.471590] CPU 1: Hot: hi: 0, btch: 1 usd: 0 Cold: hi: 0, btch: 1 usd: 0
[172394.471593] DMA32 per-cpu:
[172394.471597] CPU 0: Hot: hi: 186, btch: 31 usd: 152 Cold: hi: 62, btch: 15 usd: 58
[172394.471601] CPU 1: Hot: hi: 186, btch: 31 usd: 108 Cold: hi: 62, btch: 15 usd: 52
[172394.471606] Active:46934 inactive:23643 dirty:0 writeback:17112 unstable:0
[172394.471608] free:133942 slab:16510 mapped:7826 pagetables:3004 bounce:0
[172394.471613] DMA free:8460kB min:32kB low:40kB high:48kB active:0kB inactive:0kB present:8620kB pages_scanned:0 all_unreclaimable? yes
[172394.471616] lowmem_reserve[]: 0 968 968
[172394.471623] DMA32 free:527308kB min:3964kB low:4952kB high:5944kB active:187736kB inactive:94572kB present:991996kB pages_scanned:92 all_unreclaimable? no
[172394.471627] lowmem_reserve[]: 0 0 0
[172394.471631] DMA: 154*4kB 133*8kB 78*16kB 29*32kB 12*64kB 0*128kB 1*256kB 1*512kB 1*1024kB 1*2048kB 0*4096kB = 8464kB
[172394.471644] DMA32: 47127*4kB 24614*8kB 7110*16kB 751*32kB 29*64kB 2*128kB 0*256kB 2*512kB 1*1024kB 0*2048kB 0*4096kB = 527372kB
[172394.471658] Swap cache: add 659497, delete 623328, find 442788/475174, race 0+5
[172394.471661] Free swap = 2571424kB
[172394.471664] Total swap = 3911784kB
[172394.471666] Free swap: 2571424kB
[172394.476322] 255744 pages of RAM
[172394.476325] 6060 reserved pages
[172394.476327] 61683 pages shared
[172394.476329] 36197 pages swap cached
---------------------------------------
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
r b swpd free buff cache si so bi bo in cs us sy id wa st
0 5 1446388 735176 0 21892 3 7 44 55 89 77 5 1 93 1 0
1 4 1446388 738120 0 21260 1108 0 1416 372 293 2898 16 3 12 69 0
1 4 1446388 738296 0 21320 2592 0 3516 8 358 3073 3 3 13 82 0
0 3 1446336 737976 0 21208 2216 0 2644 0 294 3073 1 2 1 97 0
0 4 1446300 737060 0 22444 1424 0 3128 11 280 2727 2 2 4 91 0
1 2 1446284 740080 0 21344 1180 0 1804 105 313 3368 5 4 15 77 0
0 3 1446284 743456 0 21236 1384 0 1584 159 330 2996 2 2 18 77 0
1 2 1446284 747932 0 19672 1060 0 1388 199 285 3253 2 2 14 82 0
1 1 1446248 750276 0 18668 628 0 956 111 230 3216 3 2 25 72 0
0 4 1446184 750124 0 20096 444 0 2280 4 212 2715 2 2 34 64 0
0 1 1446136 751124 0 21112 1100 0 2068 4 199 3323 3 3 28 65 0
2 1 1446116 754224 0 20692 128 0 624 350 102 2993 3 5 47 46 0
3 4 1445976 755952 0 19280 252 0 1176 106 173 3151 1 2 25 73 0
---------------------------------------
-r-------- 1 safari xuser 873 2007-09-14 20:01:07.301793115 +0300 vmstat.1189789266.txt
nr_free_pages 194048
nr_inactive 858
nr_active 14503
nr_anon_pages 9742
nr_mapped 4105
nr_file_pages 15069
nr_dirty 5
nr_writeback 0
nr_slab_reclaimable 3281
nr_slab_unreclaimable 8611
nr_page_table_pages 3005
nr_unstable 0
nr_bounce 0
nr_vmscan_write 561320
pgpgin 14933975
pgpgout 18925891
pswpin 227033
pswpout 559824
pgalloc_dma 653664
pgalloc_dma32 143470730
pgalloc_normal 0
pgfree 144318549
pgactivate 3092540
pgdeactivate 3161637
pgfault 227004020
pgmajfault 119460
pgrefill_dma 162043
pgrefill_dma32 11314403
pgrefill_normal 0
pgsteal_dma 101604
pgsteal_dma32 5116048
pgsteal_normal 0
pgscan_kswapd_dma 123227
pgscan_kswapd_dma32 6984704
pgscan_kswapd_normal 0
pgscan_direct_dma 4405
pgscan_direct_dma32 289888
pgscan_direct_normal 0
pginodesteal 0
slabs_scanned 1495808
kswapd_steal 5098094
kswapd_inodesteal 718
pageoutrun 90325
allocstall 1530
pgrotated 516566
---------------------------------------
-r-------- 1 safari xuser 874 2007-09-14 20:01:55.598448897 +0300 vmstat.1189789312.txt
nr_free_pages 189817
nr_inactive 4660
nr_active 15124
nr_anon_pages 7097
nr_mapped 3407
nr_file_pages 19694
nr_dirty 7
nr_writeback 0
nr_slab_reclaimable 3234
nr_slab_unreclaimable 8428
nr_page_table_pages 3007
nr_unstable 0
nr_bounce 0
nr_vmscan_write 566922
pgpgin 15094259
pgpgout 18948479
pswpin 248898
pswpout 565316
pgalloc_dma 653664
pgalloc_dma32 143514840
pgalloc_normal 0
pgfree 144358437
pgactivate 3126391
pgdeactivate 3216750
pgfault 227019864
pgmajfault 123477
pgrefill_dma 162043
pgrefill_dma32 11689820
pgrefill_normal 0
pgsteal_dma 101604
pgsteal_dma32 5151730
pgsteal_normal 0
pgscan_kswapd_dma 123227
pgscan_kswapd_dma32 7150624
pgscan_kswapd_normal 0
pgscan_direct_dma 4405
pgscan_direct_dma32 289888
pgscan_direct_normal 0
pginodesteal 0
slabs_scanned 1495808
kswapd_steal 5133776
kswapd_inodesteal 718
pageoutrun 90979
allocstall 1530
pgrotated 522062
> explanation on why it happens and why the patch should fix it,
> so I will submit it for inclusion in -mm.
>
> Sami, thank you for the detailed bug report.
--
Do what you love because life is too short for anything else.
On Fri, Sep 14, 2007 at 20:17:46 +0300, Sami Farin wrote:
> On Wed, Sep 05, 2007 at 18:48:51 -0400, Rik van Riel wrote:
> > Sami Farin wrote:
> >> On Wed, Sep 05, 2007 at 12:24:26 -0400, Rik van Riel wrote:
> >> ...
> >>>> *shrug*
> >>> The attached patch should make sure kswapd does not free an
> >>> excessive number of pages in zone_normal just because the
> >>> pages in zone_highmem are difficult to free.
> >>>
> >>> It does give kswapd a large margin to continue putting equal
> >>> pressure on all zones in normal situations.
> >>>
> >>> Sami, could you try out this patch to see if it helps your
> >>> situation?
> >>
> >> Thanks, Rik. bzImage is ready, I probably reboot inside one
> >> month for a reason or other 8-)
> >
> > The more I look at the bug, the more I see that it is probably
> > not very easy to reproduce on demand. I have, however, a full
>
> Well, I now booted to x86_64 kernel.
>
> I can still reproduce this.
> When I unload ipset modules, kernel resumes "normal" operation, i.e.,
> not swapping like mad.
I now have 2GB of extra RAM, so 3GB in total, on x86_64 system.
If ipset tries to allocate 512 KB or more, kernel
goes into swapping frenzy, of which system does not recover
in over 30 minutes unless I press sysrq+k.
some kernel settings...:
vm.dirty_ratio = 4
vm.dirty_background_ratio = 2
vm.swappiness = 10
vm.vfs_cache_pressure = 10
vm.overcommit_memory = 2
SysRq : Show Blocked State
task PC stack pid father
kswapd0 D 0000000000000000 0 258 2
ffff8100be333ca0 0000000000000046 0000000000000000 0000000000000286
ffff8100be333c50 ffffffff00000000 ffff8100be560080 ffffffff807af3c0
0000000000000064 00000001285af6e6 00000000000000ff ffffffff802463f8
Call Trace:
[<ffffffff802463f8>] __mod_timer+0xb8/0xd0
[<ffffffff80657da3>] schedule_timeout+0x63/0xd0
[<ffffffff80246120>] process_timeout+0x0/0x10
[<ffffffff806576f8>] io_schedule_timeout+0x28/0x40
[<ffffffff8027f5fc>] congestion_wait+0x8c/0xb0
[<ffffffff802524e0>] autoremove_wake_function+0x0/0x40
[<ffffffff80279ad4>] throttle_vm_writeout+0x54/0xc0
[<ffffffff8027d6f3>] shrink_zone+0xe3/0x140
[<ffffffff8027dea0>] kswapd+0x510/0x5b0
[<ffffffff802524e0>] autoremove_wake_function+0x0/0x40
[<ffffffff8027d990>] kswapd+0x0/0x5b0
[<ffffffff802520dd>] kthread+0x4d/0x80
[<ffffffff8020cae8>] child_rip+0xa/0x12
[<ffffffff80252090>] kthread+0x0/0x80
[<ffffffff8020cade>] child_rip+0x0/0x12
irqbalance D 0000000000aa7f00 0 2110 1
ffff8100b8c4fcd8 0000000000000082 0000000000000000 0000000000000000
ffff8100a5e57f00 0000000800700006 ffff8100be5f91c0 ffff810060182140
ffff8100b8c4fc88 0000000000000282 ffff8100b8c4fcb8 ffffffff8040e1f6
Call Trace:
[<ffffffff8040e1f6>] __up_read+0x46/0xb0
[<ffffffff806579d8>] io_schedule+0x28/0x40
[<ffffffff802736e7>] sync_page+0x37/0x50
[<ffffffff80657e9e>] __wait_on_bit_lock+0x4e/0x80
[<ffffffff802736b0>] sync_page+0x0/0x50
[<ffffffff80273695>] __lock_page+0x65/0x70
[<ffffffff80252520>] wake_bit_function+0x0/0x30
[<ffffffff80282289>] handle_mm_fault+0x269/0x870
[<ffffffff802261b4>] do_page_fault+0x1a4/0x900
[<ffffffff8028cafe>] free_pages_and_swap_cache+0x9e/0xd0
[<ffffffff80285b86>] unmap_region+0x136/0x150
[<ffffffff80285bfe>] remove_vma+0x5e/0x70
[<ffffffff8040e330>] __up_write+0xd0/0x130
[<ffffffff80659d9d>] error_exit+0x0/0x84
svscan D 0000000000df7900 0 2438 1
ffff8100b6607cd8 0000000000000082 0000000000000000 0000000000000000
ffff81005f81fd80 0000000800700006 ffff8100bb516180 ffff810060182140
ffff8100b6607c88 0000000000000282 ffff8100b6607cb8 ffffffff8040e1f6
Call Trace:
[<ffffffff8040e1f6>] __up_read+0x46/0xb0
[<ffffffff806579d8>] io_schedule+0x28/0x40
[<ffffffff802736e7>] sync_page+0x37/0x50
[<ffffffff80657e9e>] __wait_on_bit_lock+0x4e/0x80
[<ffffffff802736b0>] sync_page+0x0/0x50
[<ffffffff80273695>] __lock_page+0x65/0x70
[<ffffffff80252520>] wake_bit_function+0x0/0x30
[<ffffffff80282289>] handle_mm_fault+0x269/0x870
[<ffffffff803acc2c>] xfs_vn_getattr+0x4c/0x140
[<ffffffff802261b4>] do_page_fault+0x1a4/0x900
[<ffffffff8029cf80>] vfs_getattr+0x60/0x90
[<ffffffff8029d515>] vfs_fstat+0x45/0x60
[<ffffffff8022b35e>] sys32_fstat64+0x2e/0x40
[<ffffffff80659d9d>] error_exit+0x0/0x84
...
ipset D 0000000000000000 0 3713 3574
ffff8100566237a8 0000000000000086 ffff810056623748 ffffffff802335e2
ffff810056623748 0000000000000010 ffff8100b085e0c0 ffff810060182140
ffff810056623758 0000000000000282 ffff810056623788 ffffffff8040e1f6
Call Trace:
[<ffffffff802335e2>] enqueue_entity+0x42/0x60
[<ffffffff8040e1f6>] __up_read+0x46/0xb0
[<ffffffff806579d8>] io_schedule+0x28/0x40
[<ffffffff802736e7>] sync_page+0x37/0x50
[<ffffffff80657fb5>] __wait_on_bit+0x55/0x80
[<ffffffff802736b0>] sync_page+0x0/0x50
[<ffffffff802738bf>] wait_on_page_bit+0x6f/0x80
[<ffffffff80252520>] wake_bit_function+0x0/0x30
[<ffffffff8027ccd4>] shrink_page_list+0x164/0x680
[<ffffffff8024632a>] del_timer_sync+0x1a/0x30
[<ffffffff80657dab>] schedule_timeout+0x6b/0xd0
[<ffffffff80246120>] process_timeout+0x0/0x10
[<ffffffff8027f60a>] congestion_wait+0x9a/0xb0
[<ffffffff8027d5fa>] shrink_inactive_list+0x40a/0x420
[<ffffffff8027d6df>] shrink_zone+0xcf/0x140
[<ffffffff8027e3f4>] try_to_free_pages+0x174/0x270
[<ffffffff802786c0>] __alloc_pages+0x160/0x350
[<ffffffff8023cc77>] printk+0x67/0x70
[<ffffffff80295d53>] cache_alloc_refill+0x2e3/0x570
[<ffffffff802960f3>] __kmalloc+0x113/0x120
[<ffffffff882f9283>] :ip_set_nethash:retry+0x183/0x500
[<ffffffff882ad7af>] :ip_set:__ip_set_addip+0x6f/0x90
[<ffffffff882aea2d>] :ip_set:ip_set_sockfn_get+0x93d/0xd50
[<ffffffff805cb1b2>] nf_sockopt+0x142/0x150
[<ffffffff805cb1cf>] nf_getsockopt+0xf/0x20
[<ffffffff805d9398>] ip_getsockopt+0x98/0xc0
[<ffffffff805f4391>] raw_getsockopt+0x11/0x30
[<ffffffff805a20af>] sock_common_getsockopt+0xf/0x20
[<ffffffff8059fe8c>] sys_getsockopt+0x9c/0xd0
[<ffffffff8020be4c>] tracesys+0xdc/0xe1
SysRq : Show Memory
Mem-info:
DMA per-cpu:
CPU 0: Hot: hi: 0, btch: 1 usd: 0 Cold: hi: 0, btch: 1 usd: 0
CPU 1: Hot: hi: 0, btch: 1 usd: 0 Cold: hi: 0, btch: 1 usd: 0
DMA32 per-cpu:
CPU 0: Hot: hi: 186, btch: 31 usd: 22 Cold: hi: 62, btch: 15 usd: 55
CPU 1: Hot: hi: 186, btch: 31 usd: 13 Cold: hi: 62, btch: 15 usd: 4
Active:10058 inactive:2274 dirty:1 writeback:106 unstable:0
free:691389 slab:15936 mapped:1584 pagetables:4579 bounce:0
DMA free:9108kB min:16kB low:20kB high:24kB active:0kB inactive:0kB present:8604kB pages_scanned:0 all_unreclaimable? yes
lowmem_reserve[]: 0 2988 2988 2988
DMA32 free:2756448kB min:6984kB low:8728kB high:10476kB active:40232kB inactive:9096kB present:3060476kB pages_scanned:166 all_unreclaimable? no
lowmem_reserve[]: 0 0 0 0
DMA: 5*4kB 4*8kB 2*16kB 4*32kB 3*64kB 2*128kB 1*256kB 0*512kB 2*1024kB 1*2048kB 1*4096kB = 9108kB
DMA32: 14501*4kB 15671*8kB 13250*16kB 10866*32kB 8172*64kB 4993*128kB 2039*256kB 501*512kB 51*1024kB 10*2048kB 0*4096kB = 2756396kB
Swap cache: add 320914, delete 319423, find 5260/12831, race 0+3
Free swap = 2853404kB
Total swap = 3911784kB
Free swap: 2853404kB
780032 pages of RAM
14430 reserved pages
52938 pages shared
1491 pages swap cached
SysRq : Show Memory
Mem-info:
DMA per-cpu:
CPU 0: Hot: hi: 0, btch: 1 usd: 0 Cold: hi: 0, btch: 1 usd: 0
CPU 1: Hot: hi: 0, btch: 1 usd: 0 Cold: hi: 0, btch: 1 usd: 0
DMA32 per-cpu:
CPU 0: Hot: hi: 186, btch: 31 usd: 27 Cold: hi: 62, btch: 15 usd: 54
CPU 1: Hot: hi: 186, btch: 31 usd: 6 Cold: hi: 62, btch: 15 usd: 1
Active:10223 inactive:2151 dirty:0 writeback:122 unstable:0
free:691292 slab:16134 mapped:1645 pagetables:4494 bounce:0
DMA free:9108kB min:16kB low:20kB high:24kB active:0kB inactive:0kB present:8604kB pages_scanned:0 all_unreclaimable? yes
lowmem_reserve[]: 0 2988 2988 2988
DMA32 free:2756060kB min:6984kB low:8728kB high:10476kB active:40892kB inactive:8604kB present:3060476kB pages_scanned:39 all_unreclaimable? no
lowmem_reserve[]: 0 0 0 0
DMA: 5*4kB 4*8kB 2*16kB 4*32kB 3*64kB 2*128kB 1*256kB 0*512kB 2*1024kB 1*2048kB 1*4096kB = 9108kB
DMA32: 13655*4kB 15211*8kB 12903*16kB 10596*32kB 8005*64kB 4982*128kB 2094*256kB 522*512kB 59*1024kB 10*2048kB 0*4096kB = 2756068kB
Swap cache: add 412691, delete 411114, find 12357/32547, race 0+4
Free swap = 2853920kB
Total swap = 3911784kB
Free swap: 2853920kB
780032 pages of RAM
14430 reserved pages
52619 pages shared
1577 pages swap cached
5 min later...
kswapd0 D 0000000000000000 0 258 2
ffff8100be333d30 0000000000000046 0000000000000000 0000000000000286
ffff8100be333ce0 ffffffff00000000 ffff8100be560080 ffffffff807af3c0
0000000000000064 00000001286155f2 00000000000000ff ffffffff802463f8
Call Trace:
[<ffffffff802463f8>] __mod_timer+0xb8/0xd0
[<ffffffff80657da3>] schedule_timeout+0x63/0xd0
[<ffffffff80246120>] process_timeout+0x0/0x10
[<ffffffff806576f8>] io_schedule_timeout+0x28/0x40
[<ffffffff8027f5fc>] congestion_wait+0x8c/0xb0
[<ffffffff802524e0>] autoremove_wake_function+0x0/0x40
[<ffffffff8027ded5>] kswapd+0x545/0x5b0
[<ffffffff802524e0>] autoremove_wake_function+0x0/0x40
[<ffffffff8027d990>] kswapd+0x0/0x5b0
[<ffffffff802520dd>] kthread+0x4d/0x80
[<ffffffff8020cae8>] child_rip+0xa/0x12
[<ffffffff80252090>] kthread+0x0/0x80
[<ffffffff8020cade>] child_rip+0x0/0x12
Before this ipset test, I had around 100 KB swap used,
after ipset finished and I restarted Xorg I had 500 MB.
vmstat after I restarted Xorg:
nr_free_pages 614862
nr_inactive 27488
nr_active 62666
nr_anon_pages 37065
nr_mapped 7015
nr_file_pages 66637
nr_dirty 3
nr_writeback 0
nr_slab_reclaimable 4257
nr_slab_unreclaimable 10737
nr_page_table_pages 2652
nr_unstable 0
nr_bounce 0
nr_vmscan_write 340956
pgpgin 78462562
pgpgout 67868956
pswpin 625227
pswpout 338578
pgalloc_dma 0
pgalloc_dma32 399577709
pgalloc_normal 0
pgalloc_movable 0
pgfree 400192776
pgactivate 19916454
pgdeactivate 18092870
pgfault 472557115
pgmajfault 291798
pgrefill_dma 0
pgrefill_dma32 97774325
pgrefill_normal 0
pgrefill_movable 0
pgsteal_dma 0
pgsteal_dma32 24633836
pgsteal_normal 0
pgsteal_movable 0
pgscan_kswapd_dma 0
pgscan_kswapd_dma32 28206694
pgscan_kswapd_normal 0
pgscan_kswapd_movable 0
pgscan_direct_dma 0
pgscan_direct_dma32 574376
pgscan_direct_normal 0
pgscan_direct_movable 0
pginodesteal 0
slabs_scanned 4761472
kswapd_steal 24497549
kswapd_inodesteal 232
pageoutrun 392180
allocstall 949
pgrotated 315045
--
Do what you love because life is too short for anything else.