[rsyslog] Rsyslog 4.4.2: server out-of-memory with gnutls
Rainer Gerhards
rgerhards at hq.adiscon.com
Thu Nov 5 17:37:44 CET 2009
Can you send me your rsyslog.conf, so that I can run it under the memory
debugger in my lab. I'll also take this as a motivation to finally add
multi-daemon tests to the testbench (what may take me a little while...).
Rainer
> -----Original Message-----
> From: rsyslog-bounces at lists.adiscon.com [mailto:rsyslog-
> bounces at lists.adiscon.com] On Behalf Of Mr. Demeanour
> Sent: Thursday, November 05, 2009 5:14 PM
> To: rsyslog at lists.adiscon.com >> rsyslog-users
> Subject: [rsyslog] Rsyslog 4.4.2: server out-of-memory with gnutls
>
> 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
>
> _______________________________________________
> rsyslog mailing list
> http://lists.adiscon.net/mailman/listinfo/rsyslog
> http://www.rsyslog.com
More information about the rsyslog
mailing list