YAG'B /yag-bee/ noun: Yet Another Geek Blog       Dev       Hard       Misc       About

Diving into Python Memory to track leak and ballooning

Memory leaks in python can’t really happen due to the work done by the garbage collector. However, ballooning is still possible, and cyclic references sometimes are hard to track. Let’s see with a real example how these tools can be useful to track and fix these memory issues.

Why this post ?

As a pet project I’m contributing to Archipel a virtual machine orchestrator based on libvirt and using XMPP as an underlying communication system (which is really cool !).

This software is based on xmpppy a XMPP python library no longer maintained nor developed but pretty easy to use and flexible enough to make everything we wanted to.

I notice that the main daemons (archipel-agent and archipel-central-agent ) were really eating more and more memory accros the time and sometime took all the available memory (32Gb for a python daemon is pretty huge regarding what was really done).

So I needed some tools to see what was really stored in the memory and why it was endlessly growing.

What's in my Toolbox

A small compilation of tools I found:

  • objgraph: A super useful module to visually explore Python object graphs
  • guppy: A Heap Analysis Toolset
  • ipdb/ipython: A Powerful interactive python shell

Bring it on !

This issue is quite hard to reproduce as we have to wait long enough to see what is eating the memory.

So first thing was to add an ipdb trace handler (so I can fire up ipdb console whenever I wanted to) by adding the following code to the main program loop:

    sig.signal(sig.SIGTERM, exit_handler)
    import signal,resource
        import ipdb as pdb
        import pdb

    def handle_signal(signal_number, frame_stack):
        import objgraph, resource
        print 'Memory : %s (kb)' % (resource.getrusage(resource.RUSAGE_SELF).ru_maxrss))

    signal.signal(signal.SIGINT, handle_signal)

This way, each time I hit ctrl+c, it raises an ipdb console (and also showing the actual state of memory).

From this prompt, I can use whatever python thing to track and understand where the issue is hiding.

TIP: to be able to write multilines function I can run the following inside my ipdb prompt type:

!import code; code.interact(local=vars())

From there I can start to inspect the memory using guppy and create some useful graph using objgraph.

Clean the dust

First of all, I should clean everything that I can using the garbage collector and only after that I can have some information about the memory taken by my process.

>>> import gc
>>> gc.collect()
>>> resource.getrusage(resource.RUSAGE_SELF).ru_maxrss

Now let’s dig on memory.

These are not the droids you are looking for...

With guppy I can print the current heap:

In : import guppy
In : hp=guppy.hpy()
In : h= hp.heap()
In : h
Partition of a set of 343006 objects. Total size = 59627592 bytes.
 Index  Count   %     Size   % Cumulative  % Kind (class / dict of class)
     0 115457  34 12238120  21  12238120  21 str
     1  36156  11 11455008  19  23693128  40 dict (no owner)
     2   7591   2  7955368  13  31648496  53 dict of xmpp.simplexml.Node
     3  55817  16  4811344   8  36459840  61 tuple
     4  23899   7  3405328   6  39865168  67 unicode
     5   2439   1  2556072   4  42421240  71 dict of xmpp.protocol.Iq
     6  23194   7  2505488   4  44926728  75 list
     7    588   0  1931808   3  46858536  79 dict of module
     8  14401   4  1728120   3  48586656  81 types.CodeType
     9  14104   4  1692480   3  50279136  84 function
<830 more rows. Type e.g. '_.more' to view.>

As you can see, there is a lot of strings/dicts... but hold on, what am I really looking for ?

My daemons are quite simple: they manipulate XML objects, receive and send XMPP stanzas (which are also XML objects) and that's all, so I will dig on these items.

A Stanza can be a Message or an IQ and composed from Nodes, Nodes contains dicts and dicts contains strings.

As we can see I have Node and IQ taking a big part of memory. Let’s dig on it.

In : h[5].domisize

It seems we have 25MB of IQ stored in memory, this is huge ! (We do not keep any sort of history)

In : h[5].byid
Set of 2439 <dict of xmpp.protocol.Iq> objects. Total size = 2556072 bytes.
 Index     Size   %   Cumulative  %   Owner Address
     0     1048   0.0      1048   0.0 0x19446d0
     1     1048   0.0      2096   0.1 0x1f9f790
     2     1048   0.0      3144   0.1 0x23e5750
     3     1048   0.0      4192   0.2 0x25517d0
     4     1048   0.0      5240   0.2 0x2551ad0
     5     1048   0.0      6288   0.2 0x2551b90
     6     1048   0.0      7336   0.3 0x2a75dd0
     7     1048   0.0      8384   0.3 0x2a75f10
     8     1048   0.0      9432   0.4 0x2a961d0
     9     1048   0.0     10480   0.4 0x2a96790
<2429 more rows. Type e.g. '_.more' to view.>

2500 object of size 1048, interesting… Let’s use objgraph now to get more information about relationships.

With objgraph I can walk through object types like this:

import objgraph
In : objgraph.show_most_common_types()
dict                       59731
tuple                      56281
list                       24216
function                   14161
Node                       7857
instance                   5824
instancemethod             3791
weakref                    2704
Iq                         2512
builtin_function_or_method 1759

So here we can see that I have a lot of Iq objects as we saw previously. Let’s see what they are:

In: for iq in objgraph.by_type('Iq'): print iq


<iq to="admin@central-server.archipel.priv/ArchipelController" from="agent-1.archipel.priv@central-server.archipel.priv/agent-1.archipel.priv" id="9394860" type="result"><query xmlns="archipel:xmppserver"><users xmpp="True" xmlrpc="False" /><groups xmpp="False" xmlrpc="True" /></query></iq>
<iq to="admin@central-server.archipel.priv/ArchipelController" from="agent-1.archipel.priv@central-server.archipel.priv/agent-1.archipel.priv" id="9396011" type="result"><query xmlns="archipel:xmppserver"><users xmpp="True" xmlrpc="False" /><groups xmpp="False" xmlrpc="True" /></query></iq>


It's Iq responses… there are a lot of them almost identical (except the id) they should be cleaned by the GC, but it's not the case, they must have some pending references, let's see which are the holders.

Objgraph can generate pretty useful graphes regarding references:

In : objgraph.show_backrefs(objgraph.by_type('Iq')[0], filename="/vagrant/g.png",refcounts=True, max_depth=5)
Graph written to /tmp/objgraph-a08L96.dot (10 nodes)
Image generated as /vagrant/g.png

Here is the result:

Oh a Cyclic reference (in red) ! Normally the garbage collector should take care of that, but it is strongly recommended to deal with them at the source. There are plenty of ways to fix this, I choose to use the Weakref.

Parent object are now weakref.proxy and the garbage collector can clean everything easily as you can see here

Straight to the root

I thought fixing the cyclic reference issue would fix all the memory eating but it does not. Something is still eating my memory ! And using the same tools as before I just figured out that I still have tons of IQ hanging in memory. Using objgraph again helps a lot to find the real source:

In : objgraph.show_backrefs(objgraph.by_type('Iq')[:3], filename="/vagrant/g.png",refcounts=True, max_depth=5)
Graph written to /tmp/objgraph-NZsvZL.dot (24 nodes)
Image generated as /vagrant/g.png

This is interesting… but wait, I also have a bunch of Messages hanging (Message is a type of IQ). Let’s see what’s behind and if it’s related to the previous one:

In : objgraph.show_backrefs(objgraph.by_type('Message')[:5],max_depth=8, filename="/vagrant/g.png")
Graph written to /tmp/objgraph-Dhqhdu.dot (58 nodes)
Image generated as /vagrant/g.png

What a mess !

As we can see, the Dispatcher instance keeps a list of every stanza dispatched (and actually most of them are related to callbacks).

For the record, a closure contains a cell which contains details of the variables defined in the enclosing scope.

So as we can read in this diagram, xmpp.dispatcher.Dispatcher instance, has an dict attribute named _expected and this attribute contain every IQ/Message (identified with ID as key) sent and pending for a response.

I took a look to the xmpppy library and I found that in specific case of the Dispatcher.Dispatch, the session._expected[ID] was never cleaned. I smartly add a del session._expected[ID] here just after all have been processed and tada, no more memory leak !

Are we done ?

After stressing a bit the new code, I notice that some objects are still in memory:

In : print 'Memory : %s (kb) with %s Node %s iq %s message %s dict' % (resource.getrusage(resource.RUSAGE_SELF).ru_maxrss,objgraph.count('Node'),objgraph.count('Iq'),objgraph.count('Message'),objgraph.count('dict') )
Memory : 115188 (kb) with 377 Node 0 iq 0 message 11235 dict

We can see that our previous fix works since we don't have any IQ/Messages hanging.

But I still have Nodes, I know that we are using the simplexml object to deal with XML files (libvirt domain definition for example) so let’s see what these nodes are.

First I try to filter the parent nodes (as nodes can have leaf nodes and parent nodes):

In : topNodes=[]
In : for node in objgraph.by_type('Node'):
...:     if not node.parent:
...:         topNodes.append(node)
In : len(topNodes)

So we have 70 Nodes left (out of 377) without parents, let’s sort them and count them by .name attribute

In:  topNodesByName=sorted(topNodes, key=lambda node: node.name)
In : for item in topNodesByName:
...:     if str(item.name) not in NodeCount.keys():
...:             NodeCount[str(item.name)] = 1
...:     NodeCount[str(item.name)] += 1
In : NodeCount
{'domain': 5, 'features': 6, 'success': 6, 'iq': 11, 'capabilities': 2, 'item': 34, 'groups': 2, 'stream:stream': 11, 'users': 2}

We see that Node with item as name represent almost 50% of the Nodes, let’s see how they are referenced:

Gather the item together:

In : items=[]
In : for item in topNodesByName:
...:    if item.name == 'item':
...:            items.append(item)

Let’s pick one and find its index:

In: objgraph.by_type('Node').index(items[0])
In: del topNodes
In: del topNodeByName
In: del items

Note: before generating graph I must delete every intermediate values (topNodes….) as they could appear in the graph also...

Now generate the chain of back references:

In : objgraph.show_chain(
...:     objgraph.find_backref_chain(
...:         objgraph.by_type('Node')[93],
...:         objgraph.is_proper_module),
...:     filename='/vagrant/chain.png')

Graph written to /tmp/objgraph-cujzXy.dot (13 nodes)
Image generated as /vagrant/chain.png

We can see that the TNPubSubNode instance is holding these Nodes. By having at the code we figure out that theses Nodes are the PubSub Events retrieved. Theses are stored to avoid fetch everything each time (and by the way the limit set is 1000 so it will never grow endlessly).

To be sure that we tracked all wanted too, I check with guppy to see what remains in memory:

In : import guppy
In : hp = guppy.hpy()
In : h = hp.heap()
In : h
Partition of a set of 241435 objects. Total size = 34193088 bytes.
 Index  Count   %     Size   % Cumulative  % Kind (class / dict of class)
     0 119302  49 12690504  37  12690504  37 str
     1  53350  22  4633584  14  17324088  51 tuple
     2   4954   2  2573296   8  19897384  58 dict (no owner)
     3    588   0  1931808   6  21829192  64 dict of module
     4  14400   6  1728000   5  23557192  69 types.CodeType
     5  14109   6  1693080   5  25250272  74 function
     6   1318   1  1187584   3  26437856  77 type
     7   1318   1  1138192   3  27576048  81 dict of type
     8   2079   1   944200   3  28520248  83 unicode
     9   3902   2   717680   2  29237928  86 list
<832 more rows. Type e.g. '_.more' to view.>

All seems fine, we have a lot of str and dict but nothing relevant.

Final word

It could sound like an easy fix, but these issues gave me a hard time...

comments powered by Disqus