kernel 2.6.22: what IS the VM doing?

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



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.

-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[Index of Archives]     [Kernel Newbies]     [Netfilter]     [Bugtraq]     [Photo]     [Stuff]     [Gimp]     [Yosemite News]     [MIPS Linux]     [ARM Linux]     [Linux Security]     [Linux RAID]     [Video 4 Linux]     [Linux for the blind]     [Linux Resources]
  Powered by Linux