kernel 2.6.22: what IS the VM doing?
From: Sami Farin
Date: Thu Aug 30 2007 - 07:54:43 EST
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 majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/