oom-killer invoked when plenty of memory...

[blankmind]

Hello,

Hopefully this is a simple question for someone for knows something about Linux memory management.

I am running Squid 2.7STABLE9 on a server with a 2.6.35.7 kernel, 4GB of RAM (3.5GB addressable) and a Core 2 Duo 2.13Ghz processor. It is doing no more than 30Mbit/sec throughput.

The issue I am having is that occasionally, maybe every three days or so, Squid is being killed by the oom-killer. I am puzzled because it looks as though there is plenty of memory available and I cannot imagine that a huge amount of memory is being requested by socket_alloc calls. I may of course be intrepreting the oom-killer log incorrectly.

My question is: are there any reasons why the oom-killer might be invoked when it looks as though there is plenty of memory available.

The output from the oom-killer event is as follows:

Nov  1 13:34:53 locus kernel: [248183.969960] squid invoked oom-killer: gfp_mask=0x44d0, order=2, oom_adj=0
Nov  1 13:34:53 locus kernel: [248183.969964] Pid: 8115, comm: squid Not tainted 2.6.35.7 #2
Nov  1 13:34:53 locus kernel: [248183.969965] Call Trace:
Nov  1 13:34:53 locus kernel: [248183.969971]  [<c016da2f>] ? T.408+0x5f/0x170
Nov  1 13:34:53 locus kernel: [248183.969975]  [<c024f5bc>] ? ___ratelimit+0x8c/0x100
Nov  1 13:34:53 locus kernel: [248183.969977]  [<c016db93>] ? T.407+0x53/0x130
Nov  1 13:34:53 locus kernel: [248183.969979]  [<c016dd4c>] ? __out_of_memory+0xdc/0x140
Nov  1 13:34:53 locus kernel: [248183.969981]  [<c016de04>] ? out_of_memory+0x54/0xc0
Nov  1 13:34:53 locus kernel: [248183.969983]  [<c0170f98>] ? __alloc_pages_nodemask+0x5b8/0x5d0
Nov  1 13:34:53 locus kernel: [248183.969986]  [<c0170fc4>] ? __get_free_pages+0x14/0x30
Nov  1 13:34:53 locus kernel: [248183.969989]  [<c0368208>] ? __alloc_skb+0x58/0x100
Nov  1 13:34:53 locus kernel: [248183.969991]  [<c0363847>] ? sock_alloc_send_pskb+0x167/0x290
Nov  1 13:34:53 locus kernel: [248183.969993]  [<c0363986>] ? sock_alloc_send_skb+0x16/0x20
Nov  1 13:34:53 locus kernel: [248183.969996]  [<c03f0019>] ? unix_stream_sendmsg+0x239/0x350
Nov  1 13:34:53 locus kernel: [248183.969999]  [<c035f524>] ? sock_aio_write+0xf4/0x140
Nov  1 13:34:53 locus kernel: [248183.970001]  [<c0363043>] ? release_sock+0x13/0xd0
Nov  1 13:34:53 locus kernel: [248183.970003]  [<c0196f45>] ? do_sync_write+0xb5/0xf0
Nov  1 13:34:53 locus kernel: [248183.970006]  [<c014397a>] ? add_wait_queue+0x1a/0x50
Nov  1 13:34:53 locus kernel: [248183.970009]  [<c022c71c>] ? security_file_permission+0xc/0x10
Nov  1 13:34:53 locus kernel: [248183.970011]  [<c01970d6>] ? rw_verify_area+0x66/0xe0
Nov  1 13:34:53 locus kernel: [248183.970013]  [<c0197b29>] ? vfs_write+0x149/0x160
Nov  1 13:34:53 locus kernel: [248183.970015]  [<c0197c01>] ? sys_write+0x41/0x70
Nov  1 13:34:53 locus kernel: [248183.970018]  [<c0435f2d>] ? syscall_call+0x7/0xb
Nov  1 13:34:53 locus kernel: [248183.970024]  [<c0430000>] ? mce_create_device+0xe5/0x187
Nov  1 13:34:53 locus kernel: [248183.970025] Mem-Info:
Nov  1 13:34:53 locus kernel: [248183.970026] DMA per-cpu:
Nov  1 13:34:53 locus kernel: [248183.970028] CPU    0: hi:    0, btch:   1 usd:   0
Nov  1 13:34:53 locus kernel: [248183.970029] CPU    1: hi:    0, btch:   1 usd:   0
Nov  1 13:34:53 locus kernel: [248183.970030] Normal per-cpu:
Nov  1 13:34:53 locus kernel: [248183.970031] CPU    0: hi:  186, btch:  31 usd: 113
Nov  1 13:34:53 locus kernel: [248183.970032] CPU    1: hi:  186, btch:  31 usd: 124
Nov  1 13:34:53 locus kernel: [248183.970033] HighMem per-cpu:
Nov  1 13:34:53 locus kernel: [248183.970034] CPU    0: hi:  186, btch:  31 usd: 144
Nov  1 13:34:53 locus kernel: [248183.970036] CPU    1: hi:  186, btch:  31 usd:   0
Nov  1 13:34:53 locus kernel: [248183.970039] active_anon:66580 inactive_anon:74423 isolated_anon:0
Nov  1 13:34:53 locus kernel: [248183.970039]  active_file:159351 inactive_file:383343 isolated_file:224
Nov  1 13:34:53 locus kernel: [248183.970040]  unevictable:0 dirty:296 writeback:0 unstable:0
Nov  1 13:34:53 locus kernel: [248183.970041]  free:122590 slab_reclaimable:11066 slab_unreclaimable:82191
Nov  1 13:34:53 locus kernel: [248183.970041]  mapped:1076 shmem:13 pagetables:233 bounce:0
Nov  1 13:34:53 locus kernel: [248183.970045] DMA free:3492kB min:64kB low:80kB high:96kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15804kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:976kB slab_unreclaimable:6512kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
Nov  1 13:34:53 locus kernel: [248183.970048] lowmem_reserve[]: 0 865 3539 3539
Nov  1 13:34:53 locus kernel: [248183.970054] Normal free:460148kB min:3728kB low:4660kB high:5592kB active_anon:0kB inactive_anon:0kB active_file:3484kB inactive_file:3416kB unevictable:0kB isolated(anon):0kB isolated(file):896kB present:885944kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:43288kB slab_unreclaimable:322252kB kernel_stack:800kB pagetables:112kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:10459 all_unreclaimable? yes
Nov  1 13:34:53 locus kernel: [248183.970057] lowmem_reserve[]: 0 0 21395 21395
Nov  1 13:34:53 locus kernel: [248183.970062] HighMem free:26720kB min:512kB low:3392kB high:6276kB active_anon:266320kB inactive_anon:297692kB active_file:633920kB inactive_file:1529956kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:2738632kB mlocked:0kB dirty:1184kB writeback:0kB mapped:4304kB shmem:52kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:820kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
Nov  1 13:34:53 locus kernel: [248183.970065] lowmem_reserve[]: 0 0 0 0
Nov  1 13:34:53 locus kernel: [248183.970067] DMA: 3*4kB 37*8kB 29*16kB 15*32kB 1*64kB 1*128kB 0*256kB 0*512kB 0*1024kB 1*2048kB 0*4096kB = 3492kB
Nov  1 13:34:53 locus kernel: [248183.970073] Normal: 52109*4kB 31452*8kB 2*16kB 0*32kB 1*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 460148kB
Nov  1 13:34:53 locus kernel: [248183.970079] HighMem: 528*4kB 1760*8kB 482*16kB 4*32kB 2*64kB 0*128kB 4*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 26720kB
Nov  1 13:34:53 locus kernel: [248183.970085] 544829 total pagecache pages
Nov  1 13:34:53 locus kernel: [248183.970087] 1900 pages in swap cache
Nov  1 13:34:53 locus kernel: [248183.970088] Swap cache stats: add 175591, delete 173691, find 155567/167065
Nov  1 13:34:53 locus kernel: [248183.970089] Free swap  = 502916kB
Nov  1 13:34:53 locus kernel: [248183.970090] Total swap = 514072kB
Nov  1 13:34:53 locus kernel: [248183.979439] 917360 pages RAM
Nov  1 13:34:53 locus kernel: [248183.979440] 690050 pages HighMem
Nov  1 13:34:53 locus kernel: [248183.979441] 8772 pages reserved
Nov  1 13:34:53 locus kernel: [248183.979442] 227370 pages shared
Nov  1 13:34:53 locus kernel: [248183.979443] 561563 pages non-shared
Nov  1 13:34:53 locus kernel: [248183.979444] [ pid ]   uid  tgid total_vm      rss cpu oom_adj name
Nov  1 13:34:53 locus kernel: [248183.979447] [    1]     0     1      297       88   0       0 init
Nov  1 13:34:53 locus kernel: [248183.979457] [ 1503]     0  1503      370      139   0       0 syslogd
Nov  1 13:34:53 locus squid[8113]: Squid Parent: child process 8115 exited due to signal 9
Nov  1 13:34:53 locus kernel: [248183.979460] [ 1507]     0  1507      295       68   0       0 klogd
Nov  1 13:34:53 locus kernel: [248183.979462] [ 2908]     0  2908      947      437   1       0 snmpd
Nov  1 13:34:53 locus kernel: [248183.979464] [ 2947]     0  2947      295       79   0       0 agetty
Nov  1 13:34:53 locus kernel: [248183.979467] [ 2948]     0  2948      295       79   0       0 agetty
Nov  1 13:34:53 locus kernel: [248183.979469] [ 2949]     0  2949      295       79   0       0 agetty
Nov  1 13:34:53 locus kernel: [248183.979471] [ 2950]     0  2950      346      149   1       0 quick_proc
Nov  1 13:34:53 locus kernel: [248183.979473] [ 2951]     0  2951      467      204   0       0 fan_trap
Nov  1 13:34:53 locus kernel: [248183.979476] [ 2952]     0  2952      446      132   1       0 acpid
Nov  1 13:34:53 locus kernel: [248183.979478] [ 2957]     0  2957      292       35   0       0 cat
Nov  1 13:34:53 locus kernel: [248183.979480] [ 2958]     0  2958      446      116   1       0 acpid
Nov  1 13:34:53 locus kernel: [248183.979482] [ 2978]     0  2978      289       76   0       0 eth0_activity
Nov  1 13:34:53 locus kernel: [248183.979484] [ 3000]     0  3000      324      123   0       0 crond
Nov  1 13:34:53 locus kernel: [248183.979487] [ 3020]     0  3020      299       34   1       0 rooter
Nov  1 13:34:53 locus kernel: [248183.979489] [ 3029]     0  3029      365       92   0       0 inetd
Nov  1 13:34:53 locus kernel: [248183.979491] [ 3064]     0  3064      980      585   1       0 httpd
Nov  1 13:34:53 locus kernel: [248183.979494] [ 8113]     0  8113     1310       74   0       0 squid
Nov  1 13:34:53 locus kernel: [248183.979496] [ 8115] 60001  8115   147622   139001   1       0 squid
Nov  1 13:34:53 locus kernel: [248183.979501] [ 8116] 60001  8116      915      380   1       0 voc
Nov  1 13:34:53 locus kernel: [248183.979503] [ 8117] 60001  8117      770      278   0       0 squidlogdaemon
Nov  1 13:34:53 locus kernel: [248183.979506] [ 8118] 60001  8118      198        0   1       0 unlinkd
Nov  1 13:34:53 locus kernel: [248183.979508] [ 9368]     0  9368     1281      208   1       0 sshd
Nov  1 13:34:53 locus kernel: [248183.979510] [ 9370]     0  9370      462      193   1       0 bash
Nov  1 13:34:53 locus kernel: [248183.979513] [23451] 60000 23451      980      493   1       0 httpd
Nov  1 13:34:53 locus kernel: [248183.979515] [23452] 60000 23452      980      497   1       0 httpd
Nov  1 13:34:53 locus kernel: [248183.979518] [26102]     0 26102      335       57   1       0 sleep
Nov  1 13:34:53 locus kernel: [248183.979520] Out of memory: kill process 8113 (squid) score 1565 or a child
Nov  1 13:34:53 locus kernel: [248183.979522] Killed process 8115 (squid) vsz:590488kB, anon-rss:554680kB, file-rss:1324kB

Thanks is advance for any ideas on what might be causing this!

Matthew

[Rubberman]

It could be that it is out of stack, heap, or some other resource and that the "out of memory" message is somewhat misleading. What are your ulimit settings when you start squid?

[blankmind]

Before starting Squid I increase the number of available file descriptors using:

ulimit -c unlimited -HSn 65535

The other values are inherited from the environment:

core file size (blocks)     0
data seg size (kbytes)      unlimited
file size (blocks)          unlimited
max locked memory (kbytes)  64
max memory size (kbytes)    unlimited
pipe size (512 bytes)       8
stack size (kbytes)         8192
cpu time (seconds)          unlimited
max user processes          1982
virtual memory (kbytes)     unlimited

[Rubberman]

From your last posting, I'd have to say that you are running out of stack space. Increase that to some larger value and see what happens.