On Jun 12, 2006, at 6:59 AM, Balik, Martin wrote:
Hi,
I tried to investigate possible memleaks in log4cxx, and I found
one using many reconfigurations in endless loop. I made small
program like this:
#include <log4cxx/logger.h>
#include <log4cxx/xml/domconfigurator.h>
using namespace log4cxx;
int main()
{
do {
log4cxx::xml::DOMConfigurator::configure("../config/
log_stdconf.xml");
} while (1==1);
return 0;
}
compiled it using CVS head, run it, and watched memory usage by
qps. The memory usage grew (1 MB/ sec). After some investigation
with valgrind:
valgrind --log-file=leaks.txt --num-callers=26 --tool=memcheck --
leak-check=yes --show-reachable=yes --leak-resolution=high --show-
below-main=yes ./BasicTest
I found these interesting places of log4cxx which caused the leaks:
==8287== 8192 bytes in 1 blocks are still reachable in loss record
86 of 88
==8287== at 0x1B905B7C: malloc (in /usr/lib/valgrind/
vgpreload_memcheck.so)
==8287== by 0x1B932ABB: allocator_alloc (apr_pools.c:300)
==8287== by 0x1B932F19: apr_pool_create_ex (apr_pools.c:800)
==8287== by 0x1B933B70: apr_pool_initialize (apr_pools.c:524)
==8287== by 0x1B933EBE: apr_initialize (start.c:55)
==8287== by 0x80BF70F:
log4cxx::helpers::APRInitializer::APRInitializer()
(aprinitializer.cpp:30)
==8287== by 0x80BF7C3:
log4cxx::helpers::APRInitializer::getInstance() (aprinitializer.cpp:
53)
==8287== by 0x80BF7F6:
log4cxx::helpers::APRInitializer::initialize() (aprinitializer.cpp:59)
==8287== by 0x809AB6A: log4cxx::helpers::ObjectImpl::ObjectImpl
() (objectimpl.cpp:25)
==8287== by 0x808D582: log4cxx::Level::Level(int, char const*,
int) (level.cpp:67)
==8287== by 0x808CFDC: log4cxx::Level::getOff() (level.cpp:28)
==8287== by 0x808DAFC: __static_initialization_and_destruction_0
(int, int) (level.cpp:206)
==8287== by 0x808DE30: _GLOBAL__I__ZNK7log4cxx5Level8getClassEv
(level.cpp:75)
==8287== by 0x80E9A68: (within /home/bal/leak-workspace/
BasicTest/Debug/BasicTest)
==8287== by 0x804B580: (within /home/bal/leak-workspace/
BasicTest/Debug/BasicTest)
==8287== by 0x80E9A10: __libc_csu_init (in /home/bal/leak-
workspace/BasicTest/Debug/BasicTest)
==8287== by 0x1BA5BE2D: __libc_start_main (in /lib/tls/libc.so.6)
==8287== by 0x804C2B0: ??? (start.S:119)
==8287==
This one isn't surprising. This call stack represents the
initialization of APR. Since the application is apparently forcibly
terminated there is not the corresponding call to apr_terminate.
==8287==
==8287== 319488 bytes in 39 blocks are still reachable in loss
record 87 of 88
==8287== at 0x1B905B7C: malloc (in /usr/lib/valgrind/
vgpreload_memcheck.so)
==8287== by 0x1B932ABB: allocator_alloc (apr_pools.c:300)
==8287== by 0x1B932F19: apr_pool_create_ex (apr_pools.c:800)
==8287== by 0x805CCE1: log4cxx::helpers::Pool::Pool() (pool.cpp:29)
==8287== by 0x805033B:
_ZN7log4cxx3xml15DOMConfigurator28parseChildrenOfLoggerElementEP12apr_
xml_elemNS_7helpers10ObjectPtrTINS_6LoggerEEEbP11apr_xml_docRSt3mapISs
NS5_INS_8AppenderEEESt4lessISsESaISt4pairIKSsSC_EEE
(domconfigurator.cpp:453)
==8287== by 0x804FB5F:
_ZN7log4cxx3xml15DOMConfigurator9parseRootEP12apr_xml_elemP11apr_xml_d
ocRSt3mapISsNS_7helpers10ObjectPtrTINS_8AppenderEEESt4lessISsESaISt4pa
irIKSsSA_EEE (domconfigurator.cpp:399)
==8287== by 0x8053B3F:
_ZN7log4cxx3xml15DOMConfigurator5parseEP12apr_xml_elemP11apr_xml_docRS
t3mapISsNS_7helpers10ObjectPtrTINS_8AppenderEEESt4lessISsESaISt4pairIK
SsSA_EEE (domconfigurator.cpp:824)
==8287== by 0x8052C08: log4cxx::xml::DOMConfigurator::doConfigure
(log4cxx::File const&,
log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggerRepository>&)
(domconfigurator.cpp:692)
==8287== by 0x8052D1F: log4cxx::xml::DOMConfigurator::configure
(std::string const&) (domconfigurator.cpp:700)
==8287== by 0x804C39B: main (main.cpp:8)
==8287== by 0x1BA5BE7F: __libc_start_main (in /lib/tls/libc.so.6)
==8287== by 0x804C2B0: ??? (start.S:119)
It appears that the cause of leaks is some error in memory pool
deallocation (temprary data reside in pools longer than they
should). When I changed the pool to be attribute of
DOMConfigurator class, and put this newly created pool instead of
the temporary one declared in the function, valgrind showed me
another places in DOMConfigurator where the leak occurs. When I
changed these, I found another leaks in other classes. I realized
that the problem is widespread.
Is it possible to review the pool usage, or create some pool
cleaning function ?
The Pool destructor which should be called when exiting
DOMConfigurator::parseChildrenOfLoggerElement should cause
apr_pool_destroy to be called. At that point, any memory allocated
from should be released. It may be that the overhead memory for the
pool might not be recovered until the global memory pool (the implied
parent pool) is recovered
Do you still get reported leaks if you set a fixed number of
iterations and let the test application finish normally? If so, then
it isn't really a leakage problem as memory would be (eventually)
reclaimed on normal termination. The application may growing its
working set during execution which is undesirable, but a different
type of problem.
