Finding Python Memory Leaks Using Meliae
When working on the Tribler project as part of my master thesis, I was asked to investigate a memory issue. Tribler allows people to share content in a fully decentralized way and implements a Tor-like protocol that can be used to download content anonymously. By proxying traffic through other nodes, the anonymity of Tor is obtained. You can start a Python script that allows your computer to become a proxy for other users in the network. However, when running this tool for a longer period (a few days), the memory becomes filled with objects, eventually crashing the program because it runs out of memory.
To get me started, I was provided with several memory dumps from Python programs that have been running for different amount of times (up to 13 hours). These dumps have been created using meliae. Meliae can be used to dump memory to a file and provides some tools tool investigate these dumped files. A meliae files looks like this:
As you can see, each line represents a Python object in memory, formatted as JSON. The address, type, size in memory, length, references to other objects and an optional value are visible. When dealing with large files ten thousand lines of code, it is unfeasible to manually look at the entries. Fortunately, meliae provides some great tools to parse and visualize the data!
Meliae makes it possible to print an overview of the distribution of objects, based on type. We can do this with the following Python code:
1 2 3 4 5 6 7 8 from meliae import loader om = loader.load("my_memory_file.out") om.collapse_instance_dicts() om.compute_referrers() om.remove_expensive_references() om.guess_intern_dict() s = om.summarize() print s
This will output something like the following:
The output above is a parsed memory dump from a tunnel script that has been running for two hours. As we see, there are 222 frozenset objects in memory, responsible for 20% of the memory usage. Dictionaries are taking 17% of the memory. To find out which kind of object is causing the memory leak, we run the loader tool again on the dump from a longer run (only the four type of objects are visible that contribute most to the memory usage):
The amount of dictionaries in this dump is significant larger than our previous dump! Somehow, there must be some dictionaries that are not removed by our garbage collector.
To get a bit more insight in the increase of memory, I plotted the amount of dict objects in memory against the run time of the program:
Apparently, the number of dictionaries in memory is increasing very linear over time.
To get more information about the specific dictionaries that are causing havoc, I decided to get all dictionaries in the dump with lower running time and the dictionaries in the dump with a longer running time. Next, I filtered out all dictionaries that are only present in the dump with longer running time. These dictionary objects have been created for sure during the time of the two memory dumps. I’ve written the following small Python script to do this:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 from meliae import loader def get_dicts(file_name): om = loader.load(file_name) om.collapse_instance_dicts() om.compute_referrers() om.remove_expensive_references() om.guess_intern_dict() return om.get_all('dict') dicts_600 = get_dicts("memory-600.00.out") dicts_6000 = get_dicts("memory-6000.00.out") set_addresses_600 = set() for item in dicts_600: set_addresses_600.add(item.address) # find dictionaries in set_addresses_600 but not in diff_list =  for item in dicts_6000: if item.address not in set_addresses_600: diff_list.append(item)
diff_list now contains all dictionaries that have been added between the time of dumps of the two files. Let’s get some more information about the specific dictionary objects:
Interesting, these dictionary objects are very similar. We can print all the references of a specific object:
So this is the actual content of the dictionary. It appears to be some kind of logging entry. We can see which object is referencing the dictionary object above:
Our log entries seems to appear in a list. Moreover, we see that there are 2337 items in this list. Let’s see which object is pointing to the list above:
Now things get interesting. The LimitedHistoryLogObserver is part of the Twisted framework we are using to implement asynchronous programming. Our log gets filled with log messages. These log messages are generated when an event happens in Twisted (for instance, when we start or stop listening on a specific port).
At this point, I started to search on the internet to find any issues with the LimitedHistoryLogObserver. I found this issue in which the same issue is addressed. A workaround for the LimitedHistoryLogObserver getting filled with log messages can be found here. Seems that our observer is not really that limited :)
Meliae contains many more tools to investigate objects and get more interesting information:
Meliae can also be combined with other tools such as objgraph. Objgraph can generate graphs that show references between objects. In my next blog post, I will write more about this tool. I hope you enjoyed this blog post and if you have any comments or questions, please let me know.