public inbox for linux-kernel@vger.kernel.org
 help / color / mirror / Atom feed
* kernel 2.6.22: what IS the VM doing?
@ 2007-08-30 11:54 Sami Farin
  2007-09-05  1:37 ` Rik van Riel
  0 siblings, 1 reply; 8+ messages in thread
From: Sami Farin @ 2007-08-30 11:54 UTC (permalink / raw)
  To: Linux kernel Mailing List

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.


^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: kernel 2.6.22: what IS the VM doing?
  2007-08-30 11:54 kernel 2.6.22: what IS the VM doing? Sami Farin
@ 2007-09-05  1:37 ` Rik van Riel
  2007-09-05 11:45   ` Sami Farin
  0 siblings, 1 reply; 8+ messages in thread
From: Rik van Riel @ 2007-09-05  1:37 UTC (permalink / raw)
  To: Linux kernel Mailing List

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.

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: kernel 2.6.22: what IS the VM doing?
  2007-09-05  1:37 ` Rik van Riel
@ 2007-09-05 11:45   ` Sami Farin
  2007-09-05 16:24     ` Rik van Riel
  0 siblings, 1 reply; 8+ messages in thread
From: Sami Farin @ 2007-09-05 11:45 UTC (permalink / raw)
  To: Linux kernel Mailing List

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


^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: kernel 2.6.22: what IS the VM doing?
  2007-09-05 11:45   ` Sami Farin
@ 2007-09-05 16:24     ` Rik van Riel
  2007-09-05 17:33       ` Sami Farin
  0 siblings, 1 reply; 8+ messages in thread
From: Rik van Riel @ 2007-09-05 16:24 UTC (permalink / raw)
  To: Linux kernel Mailing List

[-- Attachment #1: Type: text/plain, Size: 754 bytes --]

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 <riel@redhat.com>

[-- Attachment #2: linux-2.6-excessive-pageout.patch --]
[-- Type: text/x-patch, Size: 714 bytes --]

--- linux-2.6.22.noarch/mm/vmscan.c.excessive	2007-09-05 12:19:49.000000000 -0400
+++ linux-2.6.22.noarch/mm/vmscan.c	2007-09-05 12:21:40.000000000 -0400
@@ -1371,7 +1371,13 @@ loop_again:
 			temp_priority[i] = priority;
 			sc.nr_scanned = 0;
 			note_zone_scanning_priority(zone, priority);
-			nr_reclaimed += shrink_zone(priority, zone, &sc);
+			/*
+			 * We put equal pressure on every zone, unless one
+			 * zone has way too many pages free already.
+			 */
+			if (!zone_watermark_ok(zone, order, 8*zone->pages_high,
+						end_zone, 0))
+				nr_reclaimed += shrink_zone(priority, zone, &sc);
 			reclaim_state->reclaimed_slab = 0;
 			nr_slab = shrink_slab(sc.nr_scanned, GFP_KERNEL,
 						lru_pages);

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: kernel 2.6.22: what IS the VM doing?
  2007-09-05 16:24     ` Rik van Riel
@ 2007-09-05 17:33       ` Sami Farin
  2007-09-05 22:48         ` Rik van Riel
  0 siblings, 1 reply; 8+ messages in thread
From: Sami Farin @ 2007-09-05 17:33 UTC (permalink / raw)
  To: Linux kernel Mailing List

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.


^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: kernel 2.6.22: what IS the VM doing?
  2007-09-05 17:33       ` Sami Farin
@ 2007-09-05 22:48         ` Rik van Riel
  2007-09-14 17:17           ` Sami Farin
  0 siblings, 1 reply; 8+ messages in thread
From: Rik van Riel @ 2007-09-05 22:48 UTC (permalink / raw)
  To: Linux kernel Mailing List

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.

^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: kernel 2.6.22: what IS the VM doing?
  2007-09-05 22:48         ` Rik van Riel
@ 2007-09-14 17:17           ` Sami Farin
  2007-11-02 14:36             ` kernel 2.6.23: " Sami Farin
  0 siblings, 1 reply; 8+ messages in thread
From: Sami Farin @ 2007-09-14 17:17 UTC (permalink / raw)
  To: Linux kernel Mailing List; +Cc: Rik van Riel

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.


^ permalink raw reply	[flat|nested] 8+ messages in thread

* Re: kernel 2.6.23: what IS the VM doing?
  2007-09-14 17:17           ` Sami Farin
@ 2007-11-02 14:36             ` Sami Farin
  0 siblings, 0 replies; 8+ messages in thread
From: Sami Farin @ 2007-11-02 14:36 UTC (permalink / raw)
  To: Linux kernel Mailing List; +Cc: Rik van Riel

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.


^ permalink raw reply	[flat|nested] 8+ messages in thread

end of thread, other threads:[~2007-11-02 14:36 UTC | newest]

Thread overview: 8+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2007-08-30 11:54 kernel 2.6.22: what IS the VM doing? Sami Farin
2007-09-05  1:37 ` Rik van Riel
2007-09-05 11:45   ` Sami Farin
2007-09-05 16:24     ` Rik van Riel
2007-09-05 17:33       ` Sami Farin
2007-09-05 22:48         ` Rik van Riel
2007-09-14 17:17           ` Sami Farin
2007-11-02 14:36             ` kernel 2.6.23: " Sami Farin

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox