You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4cxx-dev@logging.apache.org by "Balik, Martin" <Ma...@siemens.com> on 2006/06/12 13:59:17 UTC
Log4cxx memory leaks in reconfiguration.
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_xm
l_elemNS_7helpers10ObjectPtrTINS_6LoggerEEEbP11apr_xml_docRSt3mapISsNS5_
INS_8AppenderEEESt4lessISsESaISt4pairIKSsSC_EEE
(domconfigurator.cpp:453)
==8287== by 0x804FB5F:
_ZN7log4cxx3xml15DOMConfigurator9parseRootEP12apr_xml_elemP11apr_xml_doc
RSt3mapISsNS_7helpers10ObjectPtrTINS_8AppenderEEESt4lessISsESaISt4pairIK
SsSA_EEE (domconfigurator.cpp:399)
==8287== by 0x8053B3F:
_ZN7log4cxx3xml15DOMConfigurator5parseEP12apr_xml_elemP11apr_xml_docRSt3
mapISsNS_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
RE: Log4cxx memory leaks in reconfiguration.
Posted by "Balik, Martin" <Ma...@siemens.com>.
Hi,
I tested the out-of-the-box version of latest log4cxx CVS, without
modification, built by ant with all dependencies, I still observed the
growth of memory usage when using DOMConfigurator::configure. So I
added the bug report into jira
(http://issues.apache.org/jira/browse/LOGCXX-145?page=all). I didn't add
the valgrind reports, because as you said the pool usage should be OK
and another bug can cause the memory usage growth.
Best regards
Martin Balik
-----Original Message-----
From: Curt Arnold [mailto:carnold@apache.org]
Sent: Monday, June 12, 2006 4:52 PM
To: Log4CXX Dev
Subject: Re: Log4cxx memory leaks in reconfiguration.
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.
RE: Log4cxx memory leaks in reconfiguration.
Posted by "Balik, Martin" <Ma...@siemens.com>.
I tried to run the program with fixed number of iterations (1000), let
it terminate normally and it looks that, the leak is reported anyway
(I'm just sending a part of the report, I can store full
reports in jira assigned to bug). But it's possible that the reason of
the leak can be other than I think.
To complete the picture, I must say, that I built log4cxx using APR
1.2.2 and APR-UTIL 1.2.2 built separately (standard configure options,
patches supplied with log4cxx were applied, no other modifications).
Is it necessary to use another options, maybe affecting this leak?
==10197== 6112 bytes in 1 blocks are still reachable in loss record 12
of 12
==10197== at 0x1B905CF8: operator new(unsigned) (in
/usr/lib/valgrind/vgpreload_memcheck.so)
==10197== by 0x1B9DC008: std::__default_alloc_template<true,
0>::_S_chunk_alloc(unsigned, int&) (in /usr/lib/libstdc++.so.5.0.7)
==10197== by 0x1B9DC0FC: std::__default_alloc_template<true,
0>::_S_refill(unsigned) (in /usr/lib/libstdc++.so.5.0.7)
==10197== by 0x1B9DC416: std::__default_alloc_template<true,
0>::allocate(unsigned) (in /usr/lib/libstdc++.so.5.0.7)
==10197== by 0x1B9DEC6D: std::string::_Rep::_S_create(unsigned,
std::allocator<char> const&) (in /usr/lib/libstdc++.so.5.0.7)
==10197== by 0x1B9DF2B4:
std::string::_Rep::_M_clone(std::allocator<char> const&, unsigned) (in
/usr/lib/libstdc++.so.5.0.7)
==10197== by 0x1B9DF395: std::string::reserve(unsigned) (in
/usr/lib/libstdc++.so.5.0.7)
==10197== by 0x1B9E0B52: std::string::append(char const*, unsigned)
(in /usr/lib/libstdc++.so.5.0.7)
==10197== by 0x1B9E0B94: std::string::append(char const*) (in
/usr/lib/libstdc++.so.5.0.7)
==10197== by 0x805434D: std::basic_string<char,
std::char_traits<char>, std::allocator<char> > std::operator+<char,
std::char_traits<char>, std::allocator<char> >(std::basic_string<char,
std::char_traits<char>, std::allocator<char> > const&, char const*)
(basic_string.h:884)
==10197== by 0x8050548:
log4cxx::xml::DOMConfigurator::parseLayout(apr_xml_elem*)
(domconfigurator.cpp:463)
==10197== by 0x804D2BC:
_ZN7log4cxx3xml15DOMConfigurator13parseAppenderEP12apr_xml_elemP11apr_xm
l_docRSt3mapISsNS_7helpers10ObjectPtrTINS_8AppenderEEESt4lessISsESaISt4p
airIKSsSA_EEE (domconfigurator.cpp:188)
==10197== by 0x804C887:
_ZN7log4cxx3xml15DOMConfigurator18findAppenderByNameEP12apr_xml_elemRKSs
RSt3mapISsNS_7helpers10ObjectPtrTINS_8AppenderEEESt4lessISsESaISt4pairIS
4_SA_EEE (domconfigurator.cpp:119)
==10197== by 0x804C900:
_ZN7log4cxx3xml15DOMConfigurator18findAppenderByNameEP12apr_xml_elemRKSs
RSt3mapISsNS_7helpers10ObjectPtrTINS_8AppenderEEESt4lessISsESaISt4pairIS
4_SA_EEE (domconfigurator.cpp:123)
==10197== by 0x804CB9F:
_ZN7log4cxx3xml15DOMConfigurator23findAppenderByReferenceEP12apr_xml_ele
mP11apr_xml_docRSt3mapISsNS_7helpers10ObjectPtrTINS_8AppenderEEESt4lessI
SsESaISt4pairIKSsSA_EEE (domconfigurator.cpp:144)
==10197== by 0x804FD48:
_ZN7log4cxx3xml15DOMConfigurator28parseChildrenOfLoggerElementEP12apr_xm
l_elemNS_7helpers10ObjectPtrTINS_6LoggerEEEbP11apr_xml_docRSt3mapISsNS5_
INS_8AppenderEEESt4lessISsESaISt4pairIKSsSC_EEE
(domconfigurator.cpp:424)
==10197== by 0x804FB83:
_ZN7log4cxx3xml15DOMConfigurator9parseRootEP12apr_xml_elemP11apr_xml_doc
RSt3mapISsNS_7helpers10ObjectPtrTINS_8AppenderEEESt4lessISsESaISt4pairIK
SsSA_EEE (domconfigurator.cpp:399)
==10197== by 0x8053B63:
_ZN7log4cxx3xml15DOMConfigurator5parseEP12apr_xml_elemP11apr_xml_docRSt3
mapISsNS_7helpers10ObjectPtrTINS_8AppenderEEESt4lessISsESaISt4pairIKSsSA
_EEE (domconfigurator.cpp:824)
==10197== by 0x8052C2C:
log4cxx::xml::DOMConfigurator::doConfigure(log4cxx::File const&,
log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggerRepository>&)
(domconfigurator.cpp:692)
==10197== by 0x8052D43:
log4cxx::xml::DOMConfigurator::configure(std::string const&)
(domconfigurator.cpp:700)
==10197== by 0x804C3B0: main (main.cpp:8)
==10197== by 0x1BA5BE7F: __libc_start_main (in /lib/tls/libc.so.6)
==10197== by 0x804C2B0: ??? (start.S:119)
-----Original Message-----
From: Curt Arnold [mailto:carnold@apache.org]
Sent: Monday, June 12, 2006 4:52 PM
To: Log4CXX Dev
Subject: Re: Log4cxx memory leaks in reconfiguration.
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.
Re: Log4cxx memory leaks in reconfiguration.
Posted by Curt Arnold <ca...@apache.org>.
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.