[syslog-ng] Re: syslog-ng 2.0rc1 memory usage
Martin, David M
David.Martin at anheuser-busch.com
Tue Aug 8 02:11:20 CEST 2006
I ran valgrind with these options for 10 minutes:
valgrind --tool=memcheck -v --leak-check=yes --show-reachable=yes
--log-file=/tmp/debug.txt ./syslog-ng -dv
Here's the output:
==15455== Memcheck, a memory error detector for x86-linux.
==15455== Copyright (C) 2002-2004, and GNU GPL'd, by Julian Seward et al.
==15455== Using valgrind-2.2.0, a program supervision framework for x86-linux.
==15455== Copyright (C) 2000-2004, and GNU GPL'd, by Julian Seward et al.
==15455==
==15455== My PID = 15455, parent PID = 5730. Prog and args are:
==15455== ./syslog-ng
==15455== -dv
==15455==
==15455== Valgrind library directory: /usr/lib/valgrind
==15455== Command line
==15455== ./syslog-ng
==15455== -dv
==15455== Startup, with flags:
==15455== --tool=memcheck
==15455== -v
==15455== --leak-check=yes
==15455== --show-reachable=yes
==15455== --log-file=/tmp/debug.txt
==15455== Contents of /proc/version:
==15455== Linux version 2.6.9-34.ELsmp (bhcompile at hs20-bc1-7.build.redhat.com)
(gcc version 3.4.5 20051201 (Red Hat 3.4.5-2)) #1 SMP Fri Feb 24 16:54:53 EST
2006
==15455== Reading syms from /opt/sfw/syslogng/2.0rc1/sbin/syslog-ng (0x8048000)
==15455== Reading syms from /lib/ld-2.3.4.so (0x1B8E4000)
==15455== object doesn't have any debug info
==15455== Reading syms from /usr/lib/valgrind/stage2 (0xB0000000)
==15455== Reading syms from /lib/ld-2.3.4.so (0xB1000000)
==15455== object doesn't have any debug info
==15455== Reading syms from /usr/lib/valgrind/vgskin_memcheck.so (0xB7BEB000)
==15455== Reading syms from /lib/tls/libc-2.3.4.so (0xB7E14000)
==15455== object doesn't have any debug info
==15455== Reading syms from /lib/libdl-2.3.4.so (0xB7F3F000)
==15455== object doesn't have any debug info
==15455== Reading suppressions file: /usr/lib/valgrind/default.supp
==15455== REDIRECT soname:libc.so.6(__GI___errno_location) to
soname:libpthread.so.0(__errno_location)
==15455== REDIRECT soname:libc.so.6(__errno_location) to
soname:libpthread.so.0(__errno_location)
==15455== REDIRECT soname:libc.so.6(__GI___h_errno_location) to
soname:libpthread.so.0(__h_errno_location)
==15455== REDIRECT soname:libc.so.6(__h_errno_location) to
soname:libpthread.so.0(__h_errno_location)
==15455== REDIRECT soname:libc.so.6(__GI___res_state) to
soname:libpthread.so.0(__res_state)
==15455== REDIRECT soname:libc.so.6(__res_state) to
soname:libpthread.so.0(__res_state)
==15455== REDIRECT soname:libc.so.6(stpcpy) to *vgpreload_memcheck.so*(stpcpy)
==15455== REDIRECT soname:libc.so.6(strnlen) to *vgpreload_memcheck.so*(strnlen)
==15455== REDIRECT soname:ld-linux.so.2(stpcpy) to
*vgpreload_memcheck.so*(stpcpy)
==15455== REDIRECT soname:ld-linux.so.2(strchr) to
*vgpreload_memcheck.so*(strchr)
==15455==
==15455== Reading syms from /usr/lib/valgrind/vg_inject.so (0x1B8FC000)
==15455== Reading syms from /usr/lib/valgrind/vgpreload_memcheck.so (0x1B901000)
==15455== TRANSLATE: 0x1B8F5F70 redirected to 0x1B904100
==15455== Reading syms from /lib/libnsl-2.3.4.so (0xC09000)
==15455== object doesn't have any debug info
==15455== Reading syms from /lib/tls/librt-2.3.4.so (0xDD5000)
==15455== object doesn't have any debug info
==15455== Reading syms from /usr/lib/libglib-2.0.so.0.400.7 (0x101000)
==15455== object doesn't have a symbol table
==15455== object doesn't have any debug info
==15455== Reading syms from /opt/sfw/eventlog/0.2.5/lib/libevtlog.so.0.0.0
(0x1B910000)
==15455== Reading syms from /lib/tls/libc-2.3.4.so (0xA60000)
==15455== object doesn't have any debug info
==15455== Reading syms from /usr/lib/valgrind/libpthread.so (0x1B917000)
==15455== Reading syms from /lib/libdl-2.3.4.so (0xB8C000)
==15455== object doesn't have any debug info
==15455== TRANSLATE: 0xAC4030 redirected to 0x1B9048F8
==15455== TRANSLATE: 0x1B8E47A0 redirected to 0x52BFF040
==15455== TRANSLATE: 0xAC1F60 redirected to 0x1B904E24
==15455== TRANSLATE: 0xAC3D50 redirected to 0x1B905274
==15455== TRANSLATE: 0xA752D0 redirected to 0x1B91EB87
==15455== TRANSLATE: 0xACA370 redirected to 0x1B9046F4
==15455== Reading syms from /lib/libnss_files-2.3.4.so (0x1BA51000)
==15455== object doesn't have any debug info
==15455== TRANSLATE: 0xAC4670 redirected to 0x1B905326
==15455== discard syms at 0x1BA51000-0x1BA5C000 in /lib/libnss_files-2.3.4.so
due to munmap()
==15455==
==15455== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 22 from 2)
--15455--
--15455-- supp: 2 _dl_relocate_object/dl_open_worker
--15455-- supp: 20 dl_relocate_object/dl_main
==15455== malloc/free: in use at exit: 47114 bytes in 370 blocks.
==15455== malloc/free: 535 allocs, 165 frees, 58731 bytes allocated.
==15455==
==15455== searching for pointers to 370 not-freed blocks.
==15459== TRANSLATE: 0xAC9000 redirected to 0x1B9042D0
==15455== checked 2396536 bytes.
==15455==
==15455== 8 bytes in 2 blocks are still reachable in loss record 1 of 19
==15455== at 0x1B904984: malloc (vg_replace_malloc.c:131)
==15455== by 0xAF72C8: register_state (in /lib/tls/libc-2.3.4.so)
==15455== by 0xAF765A: create_cd_newstate (in /lib/tls/libc-2.3.4.so)
==15455== by 0xB004C5: re_compile_internal (in /lib/tls/libc-2.3.4.so)
==15455==
==15455==
==15455== 8 bytes in 2 blocks are still reachable in loss record 2 of 19
==15455== at 0x1B904984: malloc (vg_replace_malloc.c:131)
==15455== by 0xAF7439: create_cd_newstate (in /lib/tls/libc-2.3.4.so)
==15455== by 0xB004C5: re_compile_internal (in /lib/tls/libc-2.3.4.so)
==15455== by 0xB012AB: regcomp (in /lib/tls/libc-2.3.4.so)
==15455==
==15455==
==15455== 12 bytes in 1 blocks are still reachable in loss record 3 of 19
==15455== at 0x1B904984: malloc (vg_replace_malloc.c:131)
==15455== by 0x1B9123A7: evt_ctx_tag_hook_add (evtctx.c:126)
==15455== by 0x1B91248B: evt_ctx_init (evtctx.c:151)
==15455== by 0x804C21F: msg_init (messages.c:123)
==15455==
==15455==
==15455== 16 bytes in 1 blocks are still reachable in loss record 4 of 19
==15455== at 0x1B905301: calloc (vg_replace_malloc.c:176)
==15455== by 0xB8D364: _dlerror_run (in /lib/libdl-2.3.4.so)
==15455== by 0xB8CE3B: dlsym (in /lib/libdl-2.3.4.so)
==15455== by 0x1B91ECA6: __errno_location (vg_libpthread.c:2127)
==15455==
==15455==
==15455== 56 bytes in 14 blocks are still reachable in loss record 5 of 19
==15455== at 0x1B904984: malloc (vg_replace_malloc.c:131)
==15455== by 0xAF9D1A: calc_eclosure_iter (in /lib/tls/libc-2.3.4.so)
==15455== by 0xAFF83F: re_compile_internal (in /lib/tls/libc-2.3.4.so)
==15455== by 0xB012AB: regcomp (in /lib/tls/libc-2.3.4.so)
==15455==
==15455==
==15455== 56 bytes in 2 blocks are still reachable in loss record 6 of 19
==15455== at 0x1B904984: malloc (vg_replace_malloc.c:131)
==15455== by 0xAFF59E: re_compile_internal (in /lib/tls/libc-2.3.4.so)
==15455== by 0xB012AB: regcomp (in /lib/tls/libc-2.3.4.so)
==15455== by 0x8051B1C: filter_re_compile (filter.c:266)
==15455==
==15455==
==15455== 92 bytes in 1 blocks are still reachable in loss record 7 of 19
==15455== at 0x1B905301: calloc (vg_replace_malloc.c:176)
==15455== by 0x1B912410: evt_ctx_init (evtctx.c:142)
==15455== by 0x804C21F: msg_init (messages.c:123)
==15455== by 0x804BA3E: main (main.c:389)
==15455==
==15455==
==15455== 104 bytes in 2 blocks are still reachable in loss record 8 of 19
==15455== at 0x1B905301: calloc (vg_replace_malloc.c:176)
==15455== by 0xAF73F8: create_cd_newstate (in /lib/tls/libc-2.3.4.so)
==15455== by 0xB004C5: re_compile_internal (in /lib/tls/libc-2.3.4.so)
==15455== by 0xB012AB: regcomp (in /lib/tls/libc-2.3.4.so)
==15455==
==15455==
==15455== 112 bytes in 2 blocks are still reachable in loss record 9 of 19
==15455== at 0x1B904984: malloc (vg_replace_malloc.c:131)
==15455== by 0xAFEF10: re_compile_internal (in /lib/tls/libc-2.3.4.so)
==15455== by 0xB012AB: regcomp (in /lib/tls/libc-2.3.4.so)
==15455== by 0x8051B1C: filter_re_compile (filter.c:266)
==15455==
==15455==
==15455== 168 bytes in 2 blocks are still reachable in loss record 10 of 19
==15455== at 0x1B904984: malloc (vg_replace_malloc.c:131)
==15455== by 0xAFF5F7: re_compile_internal (in /lib/tls/libc-2.3.4.so)
==15455== by 0xB012AB: regcomp (in /lib/tls/libc-2.3.4.so)
==15455== by 0x8051B1C: filter_re_compile (filter.c:266)
==15455==
==15455==
==15455== 168 bytes in 2 blocks are still reachable in loss record 11 of 19
==15455== at 0x1B904984: malloc (vg_replace_malloc.c:131)
==15455== by 0xAFF5E3: re_compile_internal (in /lib/tls/libc-2.3.4.so)
==15455== by 0xB012AB: regcomp (in /lib/tls/libc-2.3.4.so)
==15455== by 0x8051B1C: filter_re_compile (filter.c:266)
==15455==
==15455==
==15455== 168 bytes in 2 blocks are still reachable in loss record 12 of 19
==15455== at 0x1B904984: malloc (vg_replace_malloc.c:131)
==15455== by 0xAFF5CF: re_compile_internal (in /lib/tls/libc-2.3.4.so)
==15455== by 0xB012AB: regcomp (in /lib/tls/libc-2.3.4.so)
==15455== by 0x8051B1C: filter_re_compile (filter.c:266)
==15455==
==15455==
==15455== 288 bytes in 2 blocks are still reachable in loss record 14 of 19
==15455== at 0x1B905301: calloc (vg_replace_malloc.c:176)
==15455== by 0xAFEF3A: re_compile_internal (in /lib/tls/libc-2.3.4.so)
==15455== by 0xB012AB: regcomp (in /lib/tls/libc-2.3.4.so)
==15455== by 0x8051B1C: filter_re_compile (filter.c:266)
==15455==
==15455==
==15455== 512 bytes in 2 blocks are still reachable in loss record 15 of 19
==15455== at 0x1B904984: malloc (vg_replace_malloc.c:131)
==15455== by 0xB0123F: regcomp (in /lib/tls/libc-2.3.4.so)
==15455== by 0x8051B1C: filter_re_compile (filter.c:266)
==15455== by 0x8051D81: filter_host_new (filter.c:345)
==15455==
==15455==
==15455== 3608 bytes in 120 blocks are still reachable in loss record 16 of 19
==15455== at 0x1B904984: malloc (vg_replace_malloc.c:131)
==15455== by 0x1B905373: realloc (vg_replace_malloc.c:189)
==15455== by 0x12AC4B: g_realloc (in /usr/lib/libglib-2.0.so.0.400.7)
==15455== by 0x13C55B: (within /usr/lib/libglib-2.0.so.0.400.7)
==15455==
==15455==
==15455== 4780 bytes in 118 blocks are still reachable in loss record 17 of 19
==15455== at 0x1B905301: calloc (vg_replace_malloc.c:176)
==15455== by 0x12ABDF: g_malloc0 (in /usr/lib/libglib-2.0.so.0.400.7)
==15455== by 0x804C9F6: cfg_new (cfg.c:231)
==15455== by 0x804BA53: main (main.c:392)
==15455==
==15455==
==15455== 16438 bytes in 3 blocks are still reachable in loss record 18 of 19
==15455== at 0x1B904984: malloc (vg_replace_malloc.c:131)
==15455== by 0x804E8C6: yyalloc (cfg-lex.c:1958)
==15455== by 0x804E537: yyensure_buffer_stack (cfg-lex.c:1693)
==15455== by 0x804DFAC: yyrestart (cfg-lex.c:1467)
==15455==
==15455==
==15455== 20320 bytes in 91 blocks are still reachable in loss record 19 of 19
==15455== at 0x1B904984: malloc (vg_replace_malloc.c:131)
==15455== by 0x12AB72: g_malloc (in /usr/lib/libglib-2.0.so.0.400.7)
==15455== by 0x12B6D6: g_mem_chunk_new (in /usr/lib/libglib-2.0.so.0.400.7)
==15455== by 0x130DD7: g_queue_new (in /usr/lib/libglib-2.0.so.0.400.7)
==15455==
==15455== LEAK SUMMARY:
==15455== definitely lost: 0 bytes in 0 blocks.
==15455== possibly lost: 0 bytes in 0 blocks.
==15455== still reachable: 46914 bytes in 369 blocks.
==15455== suppressed: 200 bytes in 1 blocks.
--15455-- TT/TC: 0 tc sectors discarded.
--15455-- 6718 tt_fast misses.
--15455-- translate: new 6280 (108519 -> 1438685; ratio 132:10)
--15455-- discard 124 (1626 -> 21552; ratio 132:10).
--15455-- chainings: 4327 chainings, 3 unchainings.
--15455-- dispatch: 150000 jumps (bb entries); of them 33013 (22%) unchained.
--15455-- 186/7935 major/minor sched events.
--15455-- reg-alloc: 1249 t-req-spill, 266791+8325 orig+spill uis,
--15455-- 32960 total-reg-rank
--15455-- sanity: 98 cheap, 4 expensive checks.
--15455-- ccalls: 27165 C calls, 55% saves+restores avoided (89350 bytes)
--15455-- 36017 args, avg 0.87 setup instrs each (8714 bytes)
--15455-- 0% clear the stack (81126 bytes)
--15455-- 10761 retvals, 32% of reg-reg movs avoided (6756 bytes)
==15459== Reading syms from /lib/libnss_dns-2.3.4.so (0x1BA49000)
==15459== object doesn't have any debug info
==15459== Reading syms from /lib/libresolv-2.3.4.so (0xC21000)
==15459== object doesn't have any debug info
==15459== TRANSLATE: 0xB37F10 redirected to 0x1B91EE2A
==15459== TRANSLATE: 0xB3C050 redirected to 0x1B91ED13
==15459== discard syms at 0x1BA51000-0x1BA5C000 in /lib/libnss_files-2.3.4.so
due to munmap()
==15459== discard syms at 0x1BA49000-0x1BA4F000 in /lib/libnss_dns-2.3.4.so due
to munmap()
==15459== discard syms at 0xC21000-0xC34000 in /lib/libresolv-2.3.4.so due to
munmap()
==15459==
==15459== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 25 from 2)
--15459--
--15459-- supp: 5 _dl_relocate_object/dl_open_worker
--15459-- supp: 20 dl_relocate_object/dl_main
==15459== malloc/free: in use at exit: 780924 bytes in 20868 blocks.
==15459== malloc/free: 5144214 allocs, 5123346 frees, 119383338 bytes allocated.
==15459==
==15459== searching for pointers to 20868 not-freed blocks.
==15459== checked 3118956 bytes.
==15459==
==15459== 16 bytes in 1 blocks are still reachable in loss record 1 of 9
==15459== at 0x1B905301: calloc (vg_replace_malloc.c:176)
==15459== by 0xB8D364: _dlerror_run (in /lib/libdl-2.3.4.so)
==15459== by 0xB8CE3B: dlsym (in /lib/libdl-2.3.4.so)
==15459== by 0x1B91ECA6: __errno_location (vg_libpthread.c:2127)
==15459==
==15459==
==15459== 224 bytes in 7 blocks are possibly lost in loss record 3 of 9
==15459== at 0x1B905301: calloc (vg_replace_malloc.c:176)
==15459== by 0x12ABDF: g_malloc0 (in /usr/lib/libglib-2.0.so.0.400.7)
==15459== by 0x805A5E7: g_sockaddr_inet_new2 (gsockaddr.c:378)
==15459== by 0x805A3E2: g_sockaddr_new (gsockaddr.c:188)
==15459==
==15459==
==15459== 13956 bytes in 201 blocks are still reachable in loss record 4 of 9
==15459== at 0x1B905301: calloc (vg_replace_malloc.c:176)
==15459== by 0x12ABDF: g_malloc0 (in /usr/lib/libglib-2.0.so.0.400.7)
==15459== by 0x8056BDB: affile_dd_new (affile.c:584)
==15459== by 0x804FCAF: yyparse (cfg-grammar.y:478)
==15459==
==15459==
==15459== 14848 bytes in 70 blocks are still reachable in loss record 5 of 9
==15459== at 0x1B9053EE: realloc (vg_replace_malloc.c:197)
==15459== by 0x12AC4B: g_realloc (in /usr/lib/libglib-2.0.so.0.400.7)
==15459== by 0x13C55B: (within /usr/lib/libglib-2.0.so.0.400.7)
==15459== by 0x13CACD: g_string_insert_len (in
/usr/lib/libglib-2.0.so.0.400.7)
==15459==
==15459==
==15459== 16438 bytes in 3 blocks are still reachable in loss record 6 of 9
==15459== at 0x1B904984: malloc (vg_replace_malloc.c:131)
==15459== by 0x804E8C6: yyalloc (cfg-lex.c:1958)
==15459== by 0x804E537: yyensure_buffer_stack (cfg-lex.c:1693)
==15459== by 0x804DFAC: yyrestart (cfg-lex.c:1467)
==15459==
==15459==
==15459== 21876 bytes in 403 blocks are still reachable in loss record 7 of 9
==15459== at 0x1B904984: malloc (vg_replace_malloc.c:131)
==15459== by 0x1B905373: realloc (vg_replace_malloc.c:189)
==15459== by 0x12AC4B: g_realloc (in /usr/lib/libglib-2.0.so.0.400.7)
==15459== by 0x13C55B: (within /usr/lib/libglib-2.0.so.0.400.7)
==15459==
==15459==
==15459== 71654 bytes in 138 blocks are still reachable in loss record 8 of 9
==15459== at 0x1B904984: malloc (vg_replace_malloc.c:131)
==15459== by 0x12AB72: g_malloc (in /usr/lib/libglib-2.0.so.0.400.7)
==15459== by 0x12B6D6: g_mem_chunk_new (in /usr/lib/libglib-2.0.so.0.400.7)
==15459== by 0x130DD7: g_queue_new (in /usr/lib/libglib-2.0.so.0.400.7)
==15459==
==15459==
==15459== 641712 bytes in 20044 blocks are definitely lost in loss record 9 of 9
==15459== at 0x1B905301: calloc (vg_replace_malloc.c:176)
==15459== by 0x12ABDF: g_malloc0 (in /usr/lib/libglib-2.0.so.0.400.7)
==15459== by 0x805A5E7: g_sockaddr_inet_new2 (gsockaddr.c:378)
==15459== by 0x805A3E2: g_sockaddr_new (gsockaddr.c:188)
==15459==
==15459== LEAK SUMMARY:
==15459== definitely lost: 641712 bytes in 20044 blocks.
==15459== possibly lost: 224 bytes in 7 blocks.
==15459== still reachable: 138788 bytes in 816 blocks.
==15459== suppressed: 200 bytes in 1 blocks.
--15459-- TT/TC: 0 tc sectors discarded.
--15459-- 837986 tt_fast misses.
--15459-- translate: new 10227 (172436 -> 2329564; ratio 135:10)
--15459-- discard 686 (11202 -> 143164; ratio 127:10).
--15459-- chainings: 7861 chainings, 3 unchainings.
--15459-- dispatch: 600000 jumps (bb entries); of them 140194964 (23365%)
unchained.
--15459-- 498074/12754935 major/minor sched events.
--15459-- reg-alloc: 1928 t-req-spill, 431251+13266 orig+spill uis,
--15459-- 53090 total-reg-rank
--15459-- sanity: 265389 cheap, 10616 expensive checks.
--15459-- ccalls: 44952 C calls, 56% saves+restores avoided (149946 bytes)
--15459-- 59179 args, avg 0.88 setup instrs each (13872 bytes)
--15459-- 0% clear the stack (134349 bytes)
--15459-- 17732 retvals, 33% of reg-reg movs avoided (11472 bytes)
This is w/ eventlog-0.2.5 and syslog-ng-2.0rc1+20060807.
Let me know if you need additional info.
I could not reproduce the leak so far locally, although I fixed some
one-off allocation leaks but that should only affect reloads and not
simply running the process.
I suspect this is strict production environment, but I ask anyway, can
you run something like valgrind on the syslog-ng process?
Another idea is to use the built-in leak finder in syslog-ng, it is not
as intrusive but might still help.
If neither of these is possible, I could still use a core file dumped
when syslog-ng is large in size. (I'd need debugging symbols on the
syslog-ng executable as well)
There must be some kind of usage pattern that I miss here, but without
that I cannot fix the problem.
--
Bazsi
The information transmitted (including attachments) is
covered by the Electronic Communications Privacy Act,
18 U.S.C. 2510-2521, is intended only for the person(s) or
entity/entities to which it is addressed and may contain
confidential and/or privileged material. Any review,
retransmission, dissemination or other use of, or taking
of any action in reliance upon, this information by persons
or entities other than the intended recipient(s) is prohibited.
If you received this in error, please contact the sender and
delete the material from any computer.
More information about the syslog-ng
mailing list