Maintained by: NLnet Labs

[Unbound-users] unbound should probably manage other RLIMITs as well...

Greg A. Woods
Tue Oct 27 23:35:48 CET 2009


I have unbound-1.3.0 running on a pair of local hosts as my main
recursive resolvers on my local IPv4-only network, and sometimes one or
the other instance dies, this time I've got enough records to show that
it was claiming that it ran out of memory.

Syslog messages from just prior to, and during, the crash are appended
for completeness.

I have the following non-default memory-usage related settings:

	num_threads: 1
	rrset-cache-size: 256m
	rrset-cache-slabs: 8

However note the soft datasize RLIMIT is just exactly 256m, through some
accident in how my system and kernel are configured, and this is of
course slightly too small for Unbound's current configuration:

	# sysctl proc.25953
	proc.25953.corename = %n.core
	proc.25953.rlimit.cputime.soft = unlimited
	proc.25953.rlimit.cputime.hard = unlimited
	proc.25953.rlimit.filesize.soft = unlimited
	proc.25953.rlimit.filesize.hard = unlimited
	proc.25953.rlimit.datasize.soft = 268435456
	proc.25953.rlimit.datasize.hard = 3221225472
	proc.25953.rlimit.stacksize.soft = 67108864
	proc.25953.rlimit.stacksize.hard = 67108864
	proc.25953.rlimit.coredumpsize.soft = unlimited
	proc.25953.rlimit.coredumpsize.hard = unlimited
	proc.25953.rlimit.memoryuse.soft = 3920551936
	proc.25953.rlimit.memoryuse.hard = 3920551936
	proc.25953.rlimit.memorylocked.soft = 1306850645
	proc.25953.rlimit.memorylocked.hard = 3920551936
	proc.25953.rlimit.maxproc.soft = 2068
	proc.25953.rlimit.maxproc.hard = 2068
	proc.25953.rlimit.descriptors.soft = 6668
	proc.25953.rlimit.descriptors.hard = 6668
	proc.25953.rlimit.sbsize.soft = unlimited
	proc.25953.rlimit.sbsize.hard = unlimited
	proc.25953.stopfork = 0
	proc.25953.stopexec = 0
	proc.25953.stopexit = 0


So, this crash seems to have happening because the cache does finally
fill close to the specified limit, but since the process can't grow that
big, malloc() reports being out of memory and eventually Unbound gives
up and dies.

I think Unbound should probably try to manage other of its RLIMIT values
besides just the number of open files.

it could even try using getrusage(2) where available to discover initial
memory requirements at startup (though on many systems getrusage(2)
doesn't really provide enough useful information).


Oct 27 01:54:42 once unbound: [12262:0] info: server stats for thread 0: 450 queries, 56 answers from cache, 394 recursions
Oct 27 01:54:42 once unbound: [12262:0] info: server stats for thread 0: requestlist max 9 avg 4.35787 exceeded 0
Oct 27 01:54:42 once unbound: [12262:0] info: average recursion processing time 8.471841 sec
Oct 27 01:54:42 once unbound: [12262:0] info: histogram of recursion processing times
Oct 27 01:54:42 once unbound: [12262:0] info: [25%]=0.016384 median[50%]=0.00119156 [75%]=0.118561
Oct 27 01:54:42 once unbound: [12262:0] info: lower(secs) upper(secs) recursions
Oct 27 01:54:42 once unbound: [12262:0] info:    0.000000    0.000001 4
Oct 27 01:54:42 once unbound: [12262:0] info:    0.001024    0.002048 47
Oct 27 01:54:42 once unbound: [12262:0] info:    0.002048    0.004096 10
Oct 27 01:54:42 once unbound: [12262:0] info:    0.004096    0.008192 3
Oct 27 01:54:42 once unbound: [12262:0] info:    0.032768    0.065536 2
Oct 27 01:54:42 once unbound: [12262:0] info:    0.065536    0.131072 130
Oct 27 01:54:42 once unbound: [12262:0] info:    0.131072    0.262144 110
Oct 27 01:54:42 once unbound: [12262:0] info:    0.262144    0.524288 22
Oct 27 01:54:42 once unbound: [12262:0] info:    0.524288    1.000000 3
Oct 27 01:54:42 once unbound: [12262:0] info:    1.000000    2.000000 3
Oct 27 01:54:42 once unbound: [12262:0] info:    2.000000    4.000000 3
Oct 27 01:54:42 once unbound: [12262:0] info:    4.000000    8.000000 2
Oct 27 01:54:42 once unbound: [12262:0] info:    8.000000   16.000000 4
Oct 27 01:54:42 once unbound: [12262:0] info:   16.000000   32.000000 8
Oct 27 01:54:42 once unbound: [12262:0] info:   32.000000   64.000000 19
Oct 27 01:54:42 once unbound: [12262:0] info:   64.000000  128.000000 24
Oct 27 01:58:41 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 01:59:42 once unbound: [12262:0] info: server stats for thread 0: 552 queries, 126 answers from cache, 426 recursions
Oct 27 01:59:42 once unbound: [12262:0] info: server stats for thread 0: requestlist max 8 avg 3.6385 exceeded 0
Oct 27 01:59:42 once unbound: [12262:0] info: average recursion processing time 9.901999 sec
Oct 27 01:59:42 once unbound: [12262:0] info: histogram of recursion processing times
Oct 27 01:59:42 once unbound: [12262:0] info: [25%]=0.0156245 median[50%]=0.0624979 [75%]=0.114123
Oct 27 01:59:42 once unbound: [12262:0] info: lower(secs) upper(secs) recursions
Oct 27 01:59:42 once unbound: [12262:0] info:    0.000000    0.000001 2
Oct 27 01:59:42 once unbound: [12262:0] info:    0.001024    0.002048 56
Oct 27 01:59:42 once unbound: [12262:0] info:    0.002048    0.004096 4
Oct 27 01:59:42 once unbound: [12262:0] info:    0.004096    0.008192 1
Oct 27 01:59:42 once unbound: [12262:0] info:    0.016384    0.032768 2
Oct 27 01:59:42 once unbound: [12262:0] info:    0.032768    0.065536 7
Oct 27 01:59:42 once unbound: [12262:0] info:    0.065536    0.131072 151
Oct 27 01:59:42 once unbound: [12262:0] info:    0.131072    0.262144 116
Oct 27 01:59:42 once unbound: [12262:0] info:    0.262144    0.524288 28
Oct 27 01:59:42 once unbound: [12262:0] info:    0.524288    1.000000 11
Oct 27 01:59:42 once unbound: [12262:0] info:    1.000000    2.000000 5
Oct 27 01:59:42 once unbound: [12262:0] info:    2.000000    4.000000 1
Oct 27 01:59:42 once unbound: [12262:0] info:    4.000000    8.000000 2
Oct 27 01:59:42 once unbound: [12262:0] info:    8.000000   16.000000 5
Oct 27 01:59:42 once unbound: [12262:0] info:   16.000000   32.000000 11
Oct 27 01:59:42 once unbound: [12262:0] info:   32.000000   64.000000 11
Oct 27 01:59:42 once unbound: [12262:0] info:   64.000000  128.000000 12
Oct 27 01:59:42 once unbound: [12262:0] info:  128.000000  256.000000 3
Oct 27 01:59:42 once unbound: [12262:0] info:  256.000000  512.000000 4
Oct 27 02:01:24 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:01:24 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:01:24 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:01:24 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:01:25 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:01:26 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:01:35 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:01:36 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:01:56 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:01:57 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:03 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:02:03 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:03 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:02:03 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:13 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:02:13 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:14 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:02:15 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:16 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:02:17 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:35 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:02:35 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:35 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:02:35 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:35 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:02:35 once last message repeated 2 times
Oct 27 02:02:35 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:35 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:35 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:02:35 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:35 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:35 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:02:35 once last message repeated 2 times
Oct 27 02:02:35 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:36 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:36 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:02:36 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:36 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:36 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:02:36 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:36 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:02:36 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:38 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:02:38 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:38 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:02:38 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:39 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:02:39 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:40 once unbound: [12262:0] error: find_delegation: addrs out of memory
Oct 27 02:02:40 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:44 once last message repeated 3 times
Oct 27 02:02:44 once unbound: [12262:0] error: mesh_state_attachment: out of memory
Oct 27 02:02:44 once last message repeated 275 times
Oct 27 02:02:44 once unbound: [12262:0] error: malloc failure: allocating incoming dns_msg
Oct 27 02:02:45 once last message repeated 18 times
Oct 27 02:02:48 once unbound: [12262:0] fatal error: prealloc: out of memory


-- 
						Greg A. Woods
						Planix, Inc.

<woods at planix.com>       +1 416 218 0099        http://www.planix.com/
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 186 bytes
Desc: not available
URL: <http://unbound.nlnetlabs.nl/pipermail/unbound-users/attachments/20091027/402c5da1/attachment.pgp>