lists.openwall.net   lists  /  announce  owl-users  owl-dev  john-users  john-dev  passwdqc-users  yescrypt  popa3d-users  /  oss-security  kernel-hardening  musl  sabotage  tlsify  passwords  /  crypt-dev  xvendor  /  Bugtraq  Full-Disclosure  linux-kernel  linux-netdev  linux-ext4  linux-hardening  linux-cve-announce  PHC 
Open Source and information security mailing list archives
 
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [thread-next>] [day] [month] [year] [list]
Date:	Sun, 15 Jul 2007 15:03:21 +0300
From:	Sami Farin <safari-kernel@...ari.iki.fi>
To:	linux-kernel Mailing List <linux-kernel@...r.kernel.org>
Subject: Linux 2.6.22: had to reboot after OOM

After I got this error [1], system got real slow, like 386 having 32 MB of RAM
and swapping constantly.
My system is P4 SMP with 1GB of RAM.

I got this same behavior with 2.6.19, too, but then I used GNU cp v6.9
which had micro-optimization which did not bother doing read() for regular
files, like /proc/vmstat , instead, it generated 0-byte destination file
(I noticed that only after rebooting).
So I do not have useful debug info for 2.6.19.

And now my version of cp does not have that micro-optimization.

I also attached vmstat and slabinfo , in case somebody can figure out
something out of them.
I also now use --probes=5 for ipset nethash... uses less mem but is slower.

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
 r  b   swpd   free   buff  cache   si   so    bi    bo   in    cs us sy id wa st
 0  2 762376 748392      0  17104   11    8    52    65   64    53 10  3 85  3  0
 0  3 762376 748664      0  17144  456   12   908    24  237  3044  2  3 26 70  0
 0  2 762376 749544      0  16492  464  284  1440   288  248  3633  2  5 14 79  0
 0  3 762376 749916      0  16392  432    0  1368    16  239  3360  1  2  5 93  0
 0  3 762376 751108      0  15740  512  432  1656   460  214  3751  1  3 28 69  0
 0  7 762376 751740      0  15512  532  104  1920   131  237  4014  2  4  5 90  0
 0 10 762436 755064      0  15652  200 3172   992  3264  274  5086  1  3  1 96  0
 0 11 762504 757208      0  15156  144  836   624   926  204  2602  1  2  0 98  0
 0 13 762680 766384      0  12740   36 7284    96  7308  252  8643  0  5  0 95  0
 0 14 762772 771312      0  11696   12 3908   132  3912  253  5153  0  3  0 97  0
 0 13 763044 778536      0  10356  184 8088   572  8088  249  6889  1  3  0 97  0
 0 15 763092 781380      0  10284    0 2136   532  2160  176  2387  1  2  0 98  0
 0 16 763360 785428      0  10008   60 4884  1312  4985  281  4798  0  5  0 96  0
 0 19 763636 791192      0   8548   24 6264   476  6268  219  6732  0  3  0 97  0
 0 18 763824 799184      0   6240    0 7500    52  7504  217  7080  1  6  0 94  0
 0 18 763872 802196      0   5816    0 2628   552  2640  194  3851  0  4  0 96  0
 0 28 764048 805072      0   5168   92 1760  1180  1772  185  2703  0  5  0 94  0
 0 30 764048 806032      0   5256   36  164   364   234  126  1448  0  1  0 99  0
 0 31 764048 807728      0   4732   32   40    92    84  152  1824  0  3  0 97  0
 0 35 764056 809372      0   4332 1100  532  9084   804  194  1986  0  7  0 94  0
 0 74 764012 839544      0   8100 1604    0  5660    12 4216 46853  0  8  0 92  0

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
 r  b   swpd   free  inact active   si   so    bi    bo   in    cs us sy id wa st
 0 14 762504 757108   4004  90724   11    8    52    65   64    53 10  3 85  3  0
 0 13 762676 764608   8768  78084   44 6324   288  6370  251  7697  0  4  0 95  0
 0 14 762772 770832  12404  68328   12 4868   128  4880  243  6161  0  4  0 96  0
 0 13 763044 778536  24248  48736  180 7908   548  7912  296  7208  0  3  0 97  0
 0 16 763092 781380  21196  49004    4 2312   560  2336  185  2524  1  1  0 98  0
 0 16 763360 784584  40040  27048   60 4088  1312  4189  267  3964  0  4  0 96  0
 0 19 763636 791192  36552  23804   24 7064   392  7068  227  7600  0  4  0 96  0
 0 18 763824 798896  36928  15568    0 7352   136  7356  219  6902  0  5  0 94  0
 0 19 763872 802088  41372   7876    0 2776   548  2788  195  3917  0  4  0 96  0
 0 25 764048 804636  39896   6932   56 1760   920  1772  170  2602  0  4  0 95  0
 0 30 764048 806032  39308   6272   72  164   628   234  131  1579  0  2  0 98  0
 0 30 764048 807500  38316   5768   32   40    84    68  149  1630  0  2  0 98  0
 1 34 764056 808476  37900   5444   20  192   660   242  184  1883  0  6  0 94  0
 1 37 764056 811148  38772   1740   20  100   388   104  168  2409  0  5  0 95  0
 0 38 764056 813056  34164   4536    0    0   124    47  227  2590  0  6  0 94  0
 0 38 764056 815500  32924   3308   40    0   608     5  228  2448  0  4  0 96  0
10 37 764056 817764  30404   3800    0   16   260    20  323  3795  0 10  0 90  0
 1 37 764056 819548  28552   3744    0   20   148    56  207  2275  0  6  0 94  0
 1 38 764056 820828  27004   4028   20    8   496    21  216  1703  0  3  0 97  0
 0 71 764056 820064  28228   3508  600    0  1424     4  140   826  0  2  0 99  0
 0 73 764028 822568  25928   3404   68   36   332    48  205  2223  0  5  0 95  0



As a comparison, these are stats after booting, with similar workload:

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
 r  b   swpd   free   buff  cache   si   so    bi    bo   in    cs us sy id wa st
 2  0 290544  12728      0 444216    2   13   213   285  144   922  7  2 82  9  0
 0  0 290544  12672      0 444264    0    0    16  1616  270  1881  2  2 96  0  0
 0  0 290544  12752      0 444280    0    0    16    56  245  1687  2  2 96  1  0
 0  0 290544  12876      0 444280    0    0     0    31  243  1604  2  1 97  0  0
 0  0 290544  12520      0 444260   48    0    80    50  333  1708  2  2 94  2  0
 0  0 290544  12656      0 444424    0    0   136   114  269  1817  3  2 95  1  0
 0  0 290544  12672      0 444448    0    0    12  1687  330  1822  2  2 97  0  0

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------
 r  b   swpd   free  inact active   si   so    bi    bo   in    cs us sy id wa st
 2  0 290544  18756 316324 420928    2   13   212   284  144   922  7  2 82  9  0
 0  0 290544  18716 316360 421112    0    0    32    72  273  1979  2  2 96  0  0
 0  0 290544  18472 316504 421152    0    0   144    51  256  1644  3  1 97  0  0
 0  0 290544  18256 316520 421144    0    0    16    63  240  1768  2  3 96  1  0
 0  0 290544  18264 316520 421160    0    0     0   121  243  1770  2  1 97  0  0
 0  0 290544  18312 316520 421168    0    0     8    51  235  1789  2  1 97  0  0
 0  0 290544  18252 316544 421168    0    0    24   204  296  2017  2  1 96  1  0

...

and the rest are after the mem allocation failure.

2007-07-15 10:43:02.271042500 <6>[246964.992391] SysRq : Show Memory
2007-07-15 10:43:02.271082500 <6>[246964.992399] Mem-info:
2007-07-15 10:43:02.271103500 <4>[246964.992401] DMA per-cpu:
2007-07-15 10:43:02.271123500 <4>[246964.992405] CPU    0: Hot: hi:    0, btch:   1 usd:   0   Cold: hi:    0, btch:   1 usd:   0
2007-07-15 10:43:02.271144500 <4>[246964.992409] CPU    1: Hot: hi:    0, btch:   1 usd:   0   Cold: hi:    0, btch:   1 usd:   0
2007-07-15 10:43:02.271164500 <4>[246964.992412] Normal per-cpu:
2007-07-15 10:43:02.271185500 <4>[246964.992415] CPU    0: Hot: hi:  186, btch:  31 usd:  31   Cold: hi:   62, btch:  15 usd:  50
2007-07-15 10:43:02.271205500 <4>[246964.992419] CPU    1: Hot: hi:  186, btch:  31 usd:  21   Cold: hi:   62, btch:  15 usd:  59
2007-07-15 10:43:02.271225500 <4>[246964.992422] HighMem per-cpu:
2007-07-15 10:43:02.271245500 <4>[246964.992425] CPU    0: Hot: hi:   42, btch:   7 usd:   6   Cold: hi:   14, btch:   3 usd:   1
2007-07-15 10:43:02.271266500 <4>[246964.992429] CPU    1: Hot: hi:   42, btch:   7 usd:   4   Cold: hi:   14, btch:   3 usd:   1
2007-07-15 10:43:02.271287500 <4>[246964.992434] Active:23152 inactive:648 dirty:8 writeback:50 unstable:0
2007-07-15 10:43:02.271307500 <4>[246964.992436]  free:189843 slab:8987 mapped:3892 pagetables:1960 bounce:0
2007-07-15 10:43:02.271329500 <4>[246964.992440] DMA free:10384kB min:68kB low:84kB high:100kB active:0kB inactive:0kB present:16256kB pages_scanned:0 all_unreclaimable? yes
2007-07-15 10:43:02.271349500 <4>[246964.992444] lowmem_reserve[]: 0 873 975
2007-07-15 10:43:02.271371500 <4>[246964.992451] Normal free:742488kB min:3744kB low:4680kB high:5616kB active:2860kB inactive:212kB present:894080kB pages_scanned:0 all_unreclaimable? no
2007-07-15 10:43:02.271391500 <4>[246964.992454] lowmem_reserve[]: 0 0 817
2007-07-15 10:43:02.271413500 <4>[246964.992461] HighMem free:6500kB min:128kB low:236kB high:344kB active:89748kB inactive:2380kB present:104648kB pages_scanned:346 all_unreclaimable? no
2007-07-15 10:43:02.271433500 <4>[246964.992464] lowmem_reserve[]: 0 0 0
2007-07-15 10:43:02.271454500 <4>[246964.992468] DMA: 14*4kB 15*8kB 14*16kB 12*32kB 10*64kB 10*128kB 8*256kB 1*512kB 1*1024kB 0*2048kB 1*4096kB = 10384kB
2007-07-15 10:43:02.271476500 <4>[246964.992481] Normal: 23450*4kB 19190*8kB 12331*16kB 5473*32kB 1389*64kB 200*128kB 12*256kB 2*512kB 2*1024kB 1*2048kB 0*4096kB = 742440kB
2007-07-15 10:43:02.271498500 <4>[246964.992495] HighMem: 1*4kB 0*8kB 133*16kB 34*32kB 3*64kB 0*128kB 0*256kB 6*512kB 0*1024kB 0*2048kB 0*4096kB = 6484kB
2007-07-15 10:43:02.271519500 <4>[246964.992509] Swap cache: add 1800223, delete 1781495, find 1255162/1452648, race 0+116
2007-07-15 10:43:02.271539500 <4>[246964.992512] Free swap  = 3149924kB
2007-07-15 10:43:02.271558500 <4>[246964.992514] Total swap = 3911784kB
2007-07-15 10:43:02.271578500 <6>[246964.992516] Free swap:       3149924kB
2007-07-15 10:43:02.273952500 <6>[246964.995940] 255744 pages of RAM
2007-07-15 10:43:02.273972500 <6>[246964.995946] 26368 pages of HIGHMEM
2007-07-15 10:43:02.273992500 <6>[246964.995953] 4035 reserved pages
2007-07-15 10:43:02.274011500 <6>[246964.995960] 42603 pages shared
2007-07-15 10:43:02.274030500 <6>[246964.995967] 18736 pages swap cached
2007-07-15 10:43:02.274049500 <6>[246964.995972] 8 pages dirty
2007-07-15 10:43:02.274068500 <6>[246964.995977] 50 pages writeback
2007-07-15 10:43:02.274087500 <6>[246964.995985] 3892 pages mapped
2007-07-15 10:43:02.274106500 <6>[246964.995989] 8987 pages slab
2007-07-15 10:43:02.274184500 <6>[246964.995995] 1960 pages pagetables


-------------------------------------------------------------------------------------

[1]

2007-07-15 10:12:40.640668500 <4>[245143.816358] net/ipv4/netfilter/ip_set_nethash.c: retry: rehashing of set blockedp2pnew triggered: hashsize grows from 262144 to 348651
2007-07-15 10:12:40.640672500 <4>[245143.816379] ipset: page allocation failure. order:9, mode:0x20
2007-07-15 10:12:40.640674500 <4>[245143.816384]  [<c010385b>] show_trace_log_lvl+0x1a/0x30
2007-07-15 10:12:40.640675500 <4>[245143.816395]  [<c0104459>] show_trace+0x12/0x14
2007-07-15 10:12:40.640677500 <4>[245143.816399]  [<c01044b5>] dump_stack+0x16/0x18
2007-07-15 10:12:40.640678500 <4>[245143.816404]  [<c0150dd0>] __alloc_pages+0x2d7/0x2ed
2007-07-15 10:12:40.640700500 <4>[245143.816410]  [<c016803a>] cache_alloc_refill+0x2b4/0x4dc
2007-07-15 10:12:40.640701500 <4>[245143.816417]  [<c01682ec>] __kmalloc+0x8a/0x8c
2007-07-15 10:12:40.640703500 <4>[245143.816421]  [<f8e47ff0>] retry+0x51/0x455 [ip_set_nethash]
2007-07-15 10:12:40.640704500 <4>[245143.816431]  [<f8dc55e0>] __ip_set_addip+0x55/0x65 [ip_set]
2007-07-15 10:12:40.640705500 <4>[245143.816446]  [<f8dc679e>] ip_set_sockfn_get+0x8c9/0xc70 [ip_set]
2007-07-15 10:12:40.640711500 <4>[245143.816454]  [<c043b567>] nf_sockopt+0x77/0xf5
2007-07-15 10:12:40.640712500 <4>[245143.816461]  [<c043b606>] nf_getsockopt+0x21/0x27
2007-07-15 10:12:40.640714500 <4>[245143.816465]  [<c0446423>] ip_getsockopt+0x1b3/0x69c
2007-07-15 10:12:40.640715500 <4>[245143.816470]  [<c045f3b5>] raw_getsockopt+0x26/0x96
2007-07-15 10:12:40.640717500 <4>[245143.816475]  [<c041ce17>] sock_common_getsockopt+0x1e/0x25
2007-07-15 10:12:40.640728500 <4>[245143.816482]  [<c041b25e>] sys_getsockopt+0x6c/0x99
2007-07-15 10:12:40.640730500 <4>[245143.816486]  [<c041cb42>] sys_socketcall+0x23c/0x277
2007-07-15 10:12:40.640731500 <4>[245143.816490]  [<c01028e2>] syscall_call+0x7/0xb
2007-07-15 10:12:40.640732500 <4>[245143.816494]  =======================
2007-07-15 10:12:40.640734500 <6>[245143.816497] Mem-info:
2007-07-15 10:12:40.640735500 <4>[245143.816499] DMA per-cpu:
2007-07-15 10:12:40.640740500 <4>[245143.816503] CPU    0: Hot: hi:    0, btch:   1 usd:   0   Cold: hi:    0, btch:   1 usd:   0
2007-07-15 10:12:40.640742500 <4>[245143.816507] CPU    1: Hot: hi:    0, btch:   1 usd:   0   Cold: hi:    0, btch:   1 usd:   0
2007-07-15 10:12:40.640744500 <4>[245143.816510] Normal per-cpu:
2007-07-15 10:12:40.640745500 <4>[245143.816513] CPU    0: Hot: hi:  186, btch:  31 usd:  19   Cold: hi:   62, btch:  15 usd:   0
2007-07-15 10:12:40.640747500 <4>[245143.816517] CPU    1: Hot: hi:  186, btch:  31 usd: 141   Cold: hi:   62, btch:  15 usd:  10
2007-07-15 10:12:40.640752500 <4>[245143.816520] HighMem per-cpu:
2007-07-15 10:12:40.640753500 <4>[245143.816523] CPU    0: Hot: hi:   42, btch:   7 usd:  19   Cold: hi:   14, btch:   3 usd:   2
2007-07-15 10:12:40.640755500 <4>[245143.816527] CPU    1: Hot: hi:   42, btch:   7 usd:  41   Cold: hi:   14, btch:   3 usd:   1
2007-07-15 10:12:40.640801500 <4>[245143.816532] Active:135613 inactive:63608 dirty:155 writeback:0 unstable:0
2007-07-15 10:12:40.640803500 <4>[245143.816533]  free:3497 slab:20685 mapped:12285 pagetables:2011 bounce:0
2007-07-15 10:12:40.640804500 <4>[245143.816538] DMA free:3980kB min:68kB low:84kB high:100kB active:2960kB inactive:0kB present:16256kB pages_scanned:256 all_unreclaimable? no
2007-07-15 10:12:40.640806500 <4>[245143.816541] lowmem_reserve[]: 0 873 975
2007-07-15 10:12:40.640808500 <4>[245143.816548] Normal free:9772kB min:3744kB low:4680kB high:5616kB active:465640kB inactive:228696kB present:894080kB pages_scanned:32 all_unreclaimable? no
2007-07-15 10:12:40.640822500 <4>[245143.816552] lowmem_reserve[]: 0 0 817
2007-07-15 10:12:40.640870500 <4>[245143.816558] HighMem free:236kB min:128kB low:236kB high:344kB active:73852kB inactive:25736kB present:104648kB pages_scanned:0 all_unreclaimable? no
2007-07-15 10:12:40.640872500 <4>[245143.816561] lowmem_reserve[]: 0 0 0
2007-07-15 10:12:40.640874500 <4>[245143.816565] DMA: 251*4kB 140*8kB 20*16kB 0*32kB 2*64kB 1*128kB 1*256kB 0*512kB 1*1024kB 0*2048kB 0*4096kB = 3980kB
2007-07-15 10:12:40.640875500 <4>[245143.816578] Normal: 907*4kB 313*8kB 21*16kB 2*32kB 5*64kB 7*128kB 0*256kB 0*512kB 0*1024kB 1*2048kB 0*4096kB = 9796kB
2007-07-15 10:12:40.640886500 <4>[245143.816591] HighMem: 8*4kB 13*8kB 2*16kB 0*32kB 1*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 232kB
2007-07-15 10:12:40.640888500 <4>[245143.816605] Swap cache: add 1125622, delete 1090250, find 1139372/1240799, race 0+15
2007-07-15 10:12:40.640890500 <4>[245143.816608] Free swap  = 3397536kB
2007-07-15 10:12:40.640891500 <4>[245143.816610] Total swap = 3911784kB
2007-07-15 10:12:40.640918500 <6>[245143.816612] Free swap:       3397536kB
2007-07-15 10:12:40.640920500 <6>[245143.820364] 255744 pages of RAM
2007-07-15 10:12:40.640945500 <6>[245143.820366] 26368 pages of HIGHMEM
2007-07-15 10:12:40.640978500 <6>[245143.820368] 4035 reserved pages
2007-07-15 10:12:40.640980500 <6>[245143.820370] 74789 pages shared
2007-07-15 10:12:40.640981500 <6>[245143.820372] 35371 pages swap cached
2007-07-15 10:12:40.641014500 <6>[245143.820374] 155 pages dirty
2007-07-15 10:12:40.641016500 <6>[245143.820376] 0 pages writeback
2007-07-15 10:12:40.641017500 <6>[245143.820378] 12285 pages mapped
2007-07-15 10:12:40.641019500 <6>[245143.820380] 20685 pages slab
2007-07-15 10:12:40.641020500 <6>[245143.820381] 2011 pages pagetables


-- 
Do what you love because life is too short for anything else.


View attachment "vmstat-20070715T074733Z.txt" of type "text/plain" (908 bytes)

View attachment "vmstat-20070715T074806Z.txt" of type "text/plain" (909 bytes)

View attachment "slabinfo-20070715T073220Z.txt" of type "text/plain" (18210 bytes)

View attachment "slabinfo-20070715T075017Z.txt" of type "text/plain" (18211 bytes)

Powered by blists - more mailing lists