Improper creating of logger instances or a Memory Leak?

[foobar]

I've run across a memory leak in a long running process which I can't
determine if its my issue or if its the logger.

The long and short is I'm doing load testing on an application server
which spawns handlers threads which in turn each spawn a single
application thread. A graphic representation would be One Server ->
(to many pairs of) [ Handler <-> Application ].

Each application thread gets a logger instance in it's init() method
via:

self.logger = logging.getLogger('ivr-'+str(self.rand))

where self.rand is a suitably large random number to avoid collisions
of the log file's name. Until the log file gets created I attach am
memory handler

self.memhandler =
logging.handlers.MemoryHandler(1000)
self.memhandler.setLevel(10)
formatter = logging.Formatter('%
(levelname)s %(message)s')
self.memhandler.setFormatter(formatter)
self.logger.addHandler(self.memhandler)

when the application thread formally starts with the run() method I
create the log file and terminate the memory handler

filehandler = logging.FileHandler(logfilename)
filehandler.setLevel(10)
formatter = logging.Formatter('%(levelname)s %(message)s')
filehandler.setFormatter(formatter)

self.memhandler.setTarget(filehandler)
self.memhandler.close()
self.logger.removeHandler(self.memhandler)
self.logger.addHandler(filehandler)


finally the last statements in the run() method are:

filehandler.close()
self.logger.removeHandler(filehandler)
del self.logger #this was added to try and force a clean up of
the logger instances.

Using the objgraph to look at the objects in memory I find the number
of logger instances equal to the total number of threads to have lived
despite the fact that either a) there are only the standard load
testing number of threads alive, 35 or b) that there no threads
running nor are there any stale waiting for the GC.

From objgraph a selection of the most prevalent objects in memory are
(this is with the system idle post-run):

list 256730
dict 128933
Logger 128164 # total
application threads executed running load testing.
function 2356
wrapper_descriptor 1028
builtin_function_or_method 702
method_descriptor 648
tuple 643
weakref 629
getset_descriptor 304
type 252
set 224
member_descriptor 209
module 128
WeakSet 102


The only references to self.logger other than those listed are wrapper
methods defined in the application thread to wrap up the log / debug
methods. Any help or direction would be much appreciated.

 

[Chris Torek]

I've run across a memory leak in a long running process which I can't
determine if its my issue or if its the logger.

You do not say what version of python you are using, but on the
other hand I do not know how much the logger code has evolved
over time anyway.

Each application thread gets a logger instance in it's init() method
via:

self.logger = logging.getLogger('ivr-'+str(self.rand))

where self.rand is a suitably large random number to avoid collisions
of the log file's name.

This instance will "live forever" (since the thread shares the
main logging manager with all other threads).
---------
class Manager:
"""
There is [under normal circumstances] just one Manager instance, which
holds the hierarchy of loggers.
"""
def __init__(self, rootnode):
"""
Initialize the manager with the root node of the logger hierarchy.
"""
[snip]
self.loggerDict = {}

def getLogger(self, name):
"""
Get a logger with the specified name (channel name), creating it
if it doesn't yet exist. This name is a dot-separated hierarchical
name, such as "a", "a.b", "a.b.c" or similar.

If a PlaceHolder existed for the specified name [i.e. the logger
didn't exist but a child of it did], replace it with the created
logger and fix up the parent/child references which pointed to the
placeholder to now point to the logger.
"""
[snip]
self.loggerDict[name] = rv
[snip]
[snip]
Logger.manager = Manager(Logger.root)
---------

So you will find all the various ivr-* loggers in
logging.Logger.manager.loggerDict[].

finally the last statements in the run() method are:

filehandler.close()
self.logger.removeHandler(filehandler)
del self.logger #this was added to try and force a clean up of
the logger instances.

There appears to be no __del__ handler and nothing that allows
removing a logger instance from the manager's loggerDict. Of
course you could do this "manually", e.g.:

...
self.logger.removeHandler(filehandler)
del logging.Logger.manager.loggerDict[self.logger.name]
del self.logger # optional

I am curious as to why you create a new logger for each thread.
The logging module has thread synchronization in it, so that you
can share one log (or several logs) amongst all threads, which is
more typically what one wants.

 

[Vinay Sajip]

I've run across a memory leak in a long running process which I can't
determine if its my issue or if its the logger.

As Chris Torek said, it's not a good idea to create a logger for each thread. A
logger name represents a place in your application; typically, a module, or
perhaps some part of a module. If you want to include information in the log to
see what different threads are doing, do that using the information provided
here:

http://docs.python.org/howto/loggin...contextual-information-to-your-logging-output

Regards,

Vinay Sajip

 

[Vinay Sajip]

I've run across a memory leak in a long running process which I can't
determine if its my issue or if its the logger.

BTW did you also ask this question on Stack Overflow? I've answered there, too.

http://stackoverflow.com/questions/6388514/

Regards,

Vinay Sajip

 

[foobar]

Yes, I asked it on stack overflow first and didn't see an quick
reply. I'm trying to tighten up this code as much as possible in a
final pre-production push; I apologize for being overly antsy about
this. This is my pet project to upgrade our core systems from an
ancient IBM language that Moses might have used.

Currently I'm using python 3.1.2 (sorry for the obvious omission).

Regarding adding a new logger for each thread - each thread represents
a telephone call in a data collection system. I need to be able to
cleanly provided call-logging for debugging to my programmers as well
as data logging and verification; having a single log file is somewhat
impractical. To use the logging filtering then I would have to be
dynamically adding to the filtering hierarchy continuously, no?

Thanks!
Bill

 

[Vinay Sajip]

Regarding adding a new logger for each thread - each thread represents
a telephone call in a data collection system. I need to be able to
cleanly provided call-loggingfor debugging to my programmers as well
as dataloggingand verification; having a single log file is somewhat
impractical.  To use theloggingfiltering then I would have to be
dynamically adding to the filtering hierarchy continuously, no?

You could, for example, have a different *handler* for each thread.
There are a number of possibilities according to exactly what you want
to do, but there's certainly no need to create one *logger* per
thread.

Regards,

Vinay Sajip