Log4cxx memory leaks in reconfiguration.

[Balik, Martin]

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==
==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_docRSt3mapISsNS5_INS_8AppenderEEESt4lessISsESaISt4pairIKSsSC_EEE (domconfigurator.cpp:453)
==8287==    by 0x804FB5F: _ZN7log4cxx3xml15DOMConfigurator9parseRootEP12apr_xml_elemP11apr_xml_docRSt3mapISsNS_7helpers10ObjectPtrTINS_8AppenderEEESt4lessISsESaISt4pairIKSsSA_EEE (domconfigurator.cpp:399)
==8287==    by 0x8053B3F: _ZN7log4cxx3xml15DOMConfigurator5parseEP12apr_xml_elemP11apr_xml_docRSt3mapISsNS_7helpers10ObjectPtrTINS_8AppenderEEESt4lessISsESaISt4pairIKSsSA_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 ? I agree that no sensible user will be changing the logging configuration several thousand times a second in endless loop, but it's a slow memory eater. And the problem can resurface in other log4cxx functions. Maybe you know about this problem, but I  wasn't able to find something about it in jira.

 

Thank you.

 

Regards

Martin Balik