Re: Leak in apr_pools when using RollingFileAppender

[Peter Steiner <pe...@hugwi.ch>]

Replying to my own mail in log4cxx-user (which should have gone to
log4cxx-dev):

My original mail didn't get all details right:

It's not a leak and it's not in apr_pools. But it happens when using a
RollingFileAppender.

It's not a leak because the memory is properly given back when the
application terminates (but only then).

It's the mutexes of some helper object used when the RollingFileAppender
does a rollover. These mutexes are allocated out of the "root pool" of
log4cxx instead out of a short lived pool. See
http://issues.apache.org/jira/browse/LOGCXX-161 for more details.

I propose a patch to fix this (see log4cxx-161-mutex.patch of LOGCXX-161).

There are two more patches attached to the JIRA issue. They are not
related to RollingFileAppender and optimise log4cxx (I hope). As for the
default threshold of 40960 in log4cxx-161-threshold.patch: this is an
arbitrary number that works fine for my application, I haven't done any
tests to back it up.

Regards, Peter

Peter Steiner wrote:
> I'm using the SVN version of log4cxx (with a patched 
> propertyconfigurator, see
> http://issues.apache.org/jira/browse/LOGCXX-102).
> 
> I have observed that our application increases its working set in 8k 
> steps. I have tracked it down to happen whenever the log file rolls
> over:
> 
> log4cxx::rolling::RollingFileAppender::rollover() (Line 153) calls 
> WriterAppender::closeWriter() which allocates a new APR pool.
> 
> I think the error ultimately is in allocator_free() in apr_pools.c
> and was already discussed by Brian Pane in dev@httpd.apache.org (see 
> http://mail-archives.apache.org/mod_mbox/httpd-dev/200512.mbox/%3CA99202F3-A131-4656-8A68-7574C9E9062F@apache.org%3E
>  for the message). I couldn't find any correction for this in the APR
>  trunk, however.
> 
> In my case I have observed when stepping through the code that after
> the allocation of the pool in WriterAppender::closeWriter(), the next
> call to allocator_free() comes from a FileOutputStream destructor and
> only after that the pool from closeWriter is freed.
> 
> The second call to allocator_free has a current_free_index of 
> (unsigned)-1 and then overwrites the node pointer in allocator->free,
> so that the first of these nodes will never be freed.
> 
> 
> That said I'm not sure if it makes sense that closeWriter allocates
> its own pool. Reading 
> http://svn.apache.org/viewvc/apr/apr/trunk/docs/pool-design.html?view=co
>  I ask myself if closeWriter should not take a pool parameter (like 
> rollover already does) instead of having its own.
> 
> Regards, Peter


-- 
    _   _        Peter Steiner <pe...@hugwi.ch>
  / /_/ /        Hug-Witschi AG <http://www.hugwi.ch/>
 /  _  /         Electronic Engineering
/_/ /_/  _   _   Auriedstrasse 10
   / / / / / /   CH-3178 Boesingen
  / /_/ /_/ /    Tel  +41 31 740 44 44
 /_ _ _ _ _/     Fax  +41 31 740 44 45