[rsyslog] Rsyslog 4.4.2: server out-of-memory with gnutls
Mr. Demeanour
mrdemeanour at jackpot.uk.net
Thu Nov 5 17:14:05 CET 2009
Hi,
I'm running a central rsyslog server with a couple of remote WAN
(internet) clients and several remote LAN clients. Traffic is low - of
the order of 10,000 messages per day. Internet clients communicate with
the server using gnutls. LAN clients are currently using UDP. The server
writes client logs to mysql, and also writes messages of local origin to
disk.
After some interval x::x <= 24h, the server consumes all memory (and
swap) in the system. It looks as if the OS then tries to evict rsyslogd,
and hangs - there's what looks like a stacktrace displayed on the (dead)
console.
I've stopped using gnutls for now, because the server machine is also a
NFS file-server, and other systems depend on it not shutting down like
this. It seems the problem doesn't occur with plain tcp.
# uname -a
Linux prajna 2.6.30-2-686 #1 SMP Sat Sep 26 01:16:22 UTC 2009 i686 GNU/Linux
# rsyslogd -v
rsyslogd 4.4.2, compiled with:
FEATURE_REGEXP: Yes
FEATURE_LARGEFILE: Yes
FEATURE_NETZIP (message compression): Yes
GSSAPI Kerberos 5 support: Yes
FEATURE_DEBUG (debug build, slow code): No
Atomic operations supported: Yes
Runtime Instrumentation (slow code): No
Here's some log output from around the time of one of these incidents; I
don't know if it helps, but the data on the console after the incident
looks a lot like the end of this set of entries.
Nov 4 08:10:05 prajna rsyslogd: [origin software="rsyslogd"
swVersion="4.4.2" x-pid="15425" x-info="http://www.rsyslog.com"] (re)start
Nov 4 08:10:05 prajna kernel: [47633.000709] Killed process 13665
(rsyslogd)
Nov 4 08:10:05 prajna kernel: [47633.000612] 191505 pages non-shared
Nov 4 08:10:05 prajna kernel: [47633.000636] Out of memory: kill
process 13665 (rsyslogd) score 14137 or a child
Nov 4 08:10:05 prajna kernel: [47633.000575] 2870 pages reserved
Nov 4 08:10:05 prajna kernel: [47633.000594] 221 pages shared
Nov 4 08:10:05 prajna kernel: [47633.000529] 196608 pages RAM
Nov 4 08:10:05 prajna kernel: [47633.000557] 0 pages HighMem
Nov 4 08:10:05 prajna kernel: [47632.970129] Free swap = 0kB
Nov 4 08:10:05 prajna kernel: [47632.970148] Total swap = 1951856kB
Nov 4 08:10:05 prajna kernel: [47632.970081] 0 pages in swap cache
Nov 4 08:10:05 prajna kernel: [47632.970103] Swap cache stats: add
497948, delete 497948, find 68248/68574
Nov 4 08:10:05 prajna kernel: [47632.970061] 209 total pagecache pages
Nov 4 08:10:05 prajna kernel: [47632.969982] Normal: 6*4kB 1*8kB 1*16kB
0*32kB 1*64kB 2*128kB 0*256kB 0*512kB 1*1024kB 1*2048kB 0*4096kB = 3440kB
Nov 4 08:10:05 prajna kernel: [47632.969873] lowmem_reserve[]: 0 0 0 0
Nov 4 08:10:05 prajna kernel: [47632.969905] DMA: 1*4kB 1*8kB 0*16kB
1*32kB 1*64kB 1*128kB 1*256kB 1*512kB 0*1024kB 1*2048kB 0*4096kB = 3052kB
Nov 4 08:10:05 prajna kernel: [47632.969763] lowmem_reserve[]: 0 746
746 746
Nov 4 08:10:05 prajna kernel: [47632.969804] Normal free:3456kB
min:3460kB low:4324kB high:5188kB active_anon:366232kB
inactive_anon:366324kB active_file:608kB inactive_file:156kB
unevictable:64kB present:764032kB pages_scanned:1512018
all_unreclaimable? yes
Nov 4 08:10:05 prajna kernel: [47632.968951] free:1627 slab:1995
mapped:1 pagetables:944 bounce:0
Nov 4 08:10:05 prajna kernel: [47632.969024] DMA free:3052kB min:68kB
low:84kB high:100kB active_anon:4352kB inactive_anon:4440kB
active_file:0kB inactive_file:16kB unevictable:0kB present:15868kB
pages_scanned:15745 all_unreclaimable? yes
Nov 4 08:10:05 prajna kernel: [47632.968946] inactive_file:43
unevictable:16 dirty:0 writeback:0 unstable:0
Nov 4 08:10:05 prajna kernel: [47632.968909] CPU 0: hi: 186, btch:
31 usd: 171
Nov 4 08:10:05 prajna kernel: [47632.968941] Active_anon:92646
active_file:152 inactive_anon:92691
Nov 4 08:10:05 prajna kernel: [47632.968889] Normal per-cpu:
Nov 4 08:10:05 prajna kernel: [47632.968827] Mem-Info:
Nov 4 08:10:05 prajna kernel: [47632.968846] DMA per-cpu:
Nov 4 08:10:05 prajna kernel: [47632.968866] CPU 0: hi: 0, btch:
1 usd: 0
Nov 4 08:10:05 prajna kernel: [47632.968803] [<c0117589>] ?
do_page_fault+0x0/0x1e7
Nov 4 08:10:05 prajna kernel: [47632.968731] [<c0117589>] ?
do_page_fault+0x0/0x1e7
Nov 4 08:10:05 prajna kernel: [47632.968774] [<c031ebad>] ?
error_code+0x6d/0x74
Nov 4 08:10:05 prajna kernel: [47632.968702] [<c0117761>] ?
do_page_fault+0x1d8/0x1e7
Nov 4 08:10:05 prajna kernel: [47632.968623] [<c017baa7>] ?
handle_mm_fault+0x2bb/0x652
Nov 4 08:10:05 prajna kernel: [47632.968658] [<c018bc51>] ?
fd_install+0x1e/0x3c
Nov 4 08:10:05 prajna kernel: [47632.968592] [<c012b412>] ?
irq_exit+0x31/0x53
Nov 4 08:10:05 prajna kernel: [47632.968549] [<c0179e63>] ?
__do_fault+0x47/0x355
Nov 4 08:10:05 prajna kernel: [47632.968508] [<c011abb7>] ?
kunmap_atomic+0x63/0x72
Nov 4 08:10:05 prajna kernel: [47632.968442] [<c0171404>] ?
do_page_cache_readahead+0x3d/0x47
Nov 4 08:10:05 prajna kernel: [47632.968474] [<c016b6f3>] ?
filemap_fault+0x154/0x315
Nov 4 08:10:05 prajna kernel: [47632.968410] [<c01712f4>] ?
__do_page_cache_readahead+0x98/0x16b
Nov 4 08:10:05 prajna kernel: [47632.968376] [<c016fac8>] ?
__alloc_pages_internal+0x2ee/0x39d
Nov 4 08:10:05 prajna kernel: [47632.968342] [<c016d7b4>] ?
out_of_memory+0x5a/0x7c
Nov 4 08:10:05 prajna kernel: [47632.968311] [<c016d682>] ?
__out_of_memory+0x33/0x10b
Nov 4 08:10:05 prajna kernel: [47632.968231] Call Trace:
Nov 4 08:10:05 prajna kernel: [47632.968279] [<c016d13e>] ?
oom_kill_process+0x79/0x1f7
Nov 4 08:10:05 prajna kernel: [47632.968173] hald-addon-stor cpuset=/
mems_allowed=0
Nov 4 08:10:05 prajna kernel: [47632.968204] Pid: 1965, comm:
hald-addon-stor Not tainted 2.6.30-2-686 #1
Nov 4 08:10:05 prajna kernel: [47632.968114] hald-addon-stor invoked
oom-killer: gfp_mask=0x1201d2, order=0, oomkilladj=0
Nov 4 08:10:05 prajna kernel: [47631.204598] Out of memory: kill
process 6420 (rsyslogd) score 21205 or a child
Nov 4 08:10:05 prajna kernel: [47631.204667] Killed process 6420 (rsyslogd)
Nov 4 08:10:05 prajna kernel: [47631.204555] 207 pages shared
Nov 4 08:10:05 prajna kernel: [47631.204573] 191533 pages non-shared
Nov 4 08:10:05 prajna kernel: [47631.204518] 0 pages HighMem
Nov 4 08:10:05 prajna kernel: [47631.204536] 2870 pages reserved
Nov 4 08:10:05 prajna kernel: [47631.174161] Total swap = 1951856kB
Nov 4 08:10:05 prajna kernel: [47631.204489] 196608 pages RAM
Nov 4 08:10:05 prajna kernel: [47631.174142] Free swap = 0kB
Nov 4 08:10:05 prajna kernel: [47631.174093] 14 pages in swap cache
Nov 4 08:10:05 prajna kernel: [47631.174116] Swap cache stats: add
497939, delete 497925, find 68248/68574
Nov 4 08:10:05 prajna kernel: [47631.173995] Normal: 4*4kB 1*8kB 1*16kB
0*32kB 1*64kB 2*128kB 0*256kB 0*512kB 1*1024kB 1*2048kB 0*4096kB = 3432kB
Nov 4 08:10:05 prajna kernel: [47631.174073] 230 total pagecache pages
Nov 4 08:10:05 prajna kernel: [47631.173917] DMA: 1*4kB 1*8kB 0*16kB
1*32kB 1*64kB 1*128kB 1*256kB 1*512kB 0*1024kB 1*2048kB 0*4096kB = 3052kB
Nov 4 08:10:05 prajna kernel: [47631.173817] Normal free:3448kB
min:3460kB low:4324kB high:5188kB active_anon:366252kB
inactive_anon:366360kB active_file:280kB inactive_file:584kB
unevictable:64kB present:764032kB pages_scanned:1830820
all_unreclaimable? yes
Nov 4 08:10:05 prajna kernel: [47631.173885] lowmem_reserve[]: 0 0 0 0
Nov 4 08:10:05 prajna kernel: [47631.173775] lowmem_reserve[]: 0 746
746 746
Nov 4 08:10:05 prajna kernel: [47631.173710] DMA free:3052kB min:68kB
low:84kB high:100kB active_anon:4352kB inactive_anon:4440kB
active_file:0kB inactive_file:0kB unevictable:0kB present:15868kB
pages_scanned:15745 all_unreclaimable? yes
Nov 4 08:10:05 prajna kernel: [47631.173637] free:1625 slab:2000
mapped:1 pagetables:944 bounce:0
Nov 4 08:10:05 prajna kernel: [47631.173627] Active_anon:92651
active_file:70 inactive_anon:92700
Nov 4 08:10:05 prajna kernel: [47631.173632] inactive_file:146
unevictable:16 dirty:0 writeback:0 unstable:0
Nov 4 08:10:05 prajna kernel: [47631.173575] Normal per-cpu:
Nov 4 08:10:05 prajna kernel: [47631.173596] CPU 0: hi: 186, btch:
31 usd: 154
Nov 4 08:10:05 prajna kernel: [47631.173532] DMA per-cpu:
Nov 4 08:10:05 prajna kernel: [47631.173552] CPU 0: hi: 0, btch:
1 usd: 0
Nov 4 08:10:05 prajna kernel: [47631.173514] Mem-Info:
Nov 4 08:10:05 prajna kernel: [47631.173461] [<c031ebad>] ?
error_code+0x6d/0x74
Nov 4 08:10:05 prajna kernel: [47631.173490] [<c0117589>] ?
do_page_fault+0x0/0x1e7
Nov 4 08:10:05 prajna kernel: [47631.173420] [<c0117589>] ?
do_page_fault+0x0/0x1e7
Nov 4 08:10:05 prajna kernel: [47631.173348] [<c02863d4>] ?
sys_socketcall+0x103/0x19f
Nov 4 08:10:05 prajna kernel: [47631.173390] [<c0117761>] ?
do_page_fault+0x1d8/0x1e7
Nov 4 08:10:05 prajna kernel: [47631.173319] [<c0285fb8>] ?
sys_recv+0x19/0x1d
Nov 4 08:10:05 prajna kernel: [47631.173280] [<c017baa7>] ?
handle_mm_fault+0x2bb/0x652
Nov 4 08:10:05 prajna kernel: [47631.173208] [<c011abb7>] ?
kunmap_atomic+0x63/0x72
Nov 4 08:10:05 prajna kernel: [47631.173248] [<c0179e63>] ?
__do_fault+0x47/0x355
Nov 4 08:10:05 prajna kernel: [47631.173173] [<c016b6f3>] ?
filemap_fault+0x154/0x315
Nov 4 08:10:05 prajna kernel: [47631.173110] [<c01712f4>] ?
__do_page_cache_readahead+0x98/0x16b
Nov 4 08:10:05 prajna kernel: [47631.173142] [<c0171404>] ?
do_page_cache_readahead+0x3d/0x47
Nov 4 08:10:05 prajna kernel: [47631.173011] [<c016d682>] ?
__out_of_memory+0x33/0x10b
Nov 4 08:10:05 prajna kernel: [47631.173042] [<c016d7b4>] ?
out_of_memory+0x5a/0x7c
Nov 4 08:10:05 prajna kernel: [47631.173076] [<c016fac8>] ?
__alloc_pages_internal+0x2ee/0x39d
Nov 4 08:10:05 prajna kernel: [47631.172979] [<c016d13e>] ?
oom_kill_process+0x79/0x1f7
Nov 4 08:10:05 prajna kernel: [47631.172935] Call Trace:
Nov 4 08:10:05 prajna kernel: [47631.172909] Pid: 13665, comm: rsyslogd
Not tainted 2.6.30-2-686 #1
Nov 4 08:10:05 prajna kernel: [47631.172829] rsyslogd invoked
oom-killer: gfp_mask=0x1201d2, order=0, oomkilladj=0
Nov 4 08:10:05 prajna kernel: [47631.172881] rsyslogd cpuset=/
mems_allowed=0
Nov 4 08:10:05 prajna kernel: [47631.136403] Killed process 13664
(rsyslogd)
Nov 4 08:10:05 prajna kernel: [47631.136310] 191499 pages non-shared
Nov 4 08:10:05 prajna kernel: [47631.136334] Out of memory: kill
process 13664 (rsyslogd) score 42411 or a child
Nov 4 08:10:05 prajna kernel: [47631.136272] 2870 pages reserved
Nov 4 08:10:05 prajna kernel: [47631.136291] 203 pages shared
Nov 4 08:10:05 prajna kernel: [47631.136226] 196608 pages RAM
Nov 4 08:10:05 prajna kernel: [47631.136254] 0 pages HighMem
Nov 4 08:10:05 prajna kernel: [47631.105740] Total swap = 1951856kB
Nov 4 08:10:05 prajna kernel: [47631.105722] Free swap = 0kB
Nov 4 08:10:05 prajna kernel: [47631.105696] Swap cache stats: add
497920, delete 497920, find 68247/68572
Nov 4 08:10:05 prajna kernel: [47631.105674] 0 pages in swap cache
Nov 4 08:10:05 prajna kernel: [47631.105653] 152 total pagecache pages
Nov 4 08:10:05 prajna kernel: [47631.105574] Normal: 33*4kB 2*8kB
1*16kB 0*32kB 1*64kB 2*128kB 0*256kB 0*512kB 1*1024kB 1*2048kB 0*4096kB
= 3556kB
Nov 4 08:10:05 prajna kernel: [47631.105496] DMA: 1*4kB 1*8kB 0*16kB
1*32kB 1*64kB 1*128kB 1*256kB 1*512kB 0*1024kB 1*2048kB 0*4096kB = 3052kB
Nov 4 08:10:05 prajna kernel: [47631.105465] lowmem_reserve[]: 0 0 0 0
Nov 4 08:10:05 prajna kernel: [47631.105396] Normal free:3556kB
min:3460kB low:4324kB high:5188kB active_anon:366288kB
inactive_anon:366268kB active_file:280kB inactive_file:324kB
unevictable:64kB present:764032kB pages_scanned:1830304
all_unreclaimable? yes
Nov 4 08:10:05 prajna kernel: [47631.105355] lowmem_reserve[]: 0 746
746 746
Nov 4 08:10:05 prajna kernel: [47631.105289] DMA free:3052kB min:68kB
low:84kB high:100kB active_anon:4352kB inactive_anon:4440kB
active_file:0kB inactive_file:0kB unevictable:0kB present:15868kB
pages_scanned:15745 all_unreclaimable? yes
Nov 4 08:10:05 prajna kernel: [47631.105217] free:1652 slab:2000
mapped:1 pagetables:944 bounce:0
Nov 4 08:10:05 prajna kernel: [47631.105207] Active_anon:92660
active_file:70 inactive_anon:92677
Nov 4 08:10:05 prajna kernel: [47631.105212] inactive_file:81
unevictable:16 dirty:0 writeback:0 unstable:0
Nov 4 08:10:05 prajna kernel: [47631.105155] Normal per-cpu:
Nov 4 08:10:05 prajna kernel: [47631.105175] CPU 0: hi: 186, btch:
31 usd: 161
Nov 4 08:10:05 prajna kernel: [47631.105132] CPU 0: hi: 0, btch:
1 usd: 0
Nov 4 08:10:05 prajna kernel: [47631.105093] Mem-Info:
Nov 4 08:10:05 prajna kernel: [47631.105112] DMA per-cpu:
Nov 4 08:10:05 prajna kernel: [47631.105069] [<c0117589>] ?
do_page_fault+0x0/0x1e7
Nov 4 08:10:05 prajna kernel: imklog 4.4.2, log source = /proc/kmsg
started.
Nov 4 08:10:05 prajna kernel: [<c031ebad>] ? error_code+0x6d/0x74
More information about the rsyslog
mailing list