Repository navigation
glibc allocator doesn't release all free()ed memory #56058
Description
| BPO | 11849 |
|---|---|
| Nosy | @tim-one, @pitrou, @vstinner, @bkline, @methane, @florentx, @davidmalcolm |
| Files |
Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.
Show more details
GitHub fields:
assignee = None
closed_at = <Date 2011-05-03.16:20:57.022>
created_at = <Date 2011-04-15.09:08:38.178>
labels = ['expert-XML', 'performance']
title = "glibc allocator doesn't release all free()ed memory"
updated_at = <Date 2018-01-16.12:51:42.458>
user = 'https://bugs.python.org/kaifeng'bugs.python.org fields:
activity = <Date 2018-01-16.12:51:42.458>
actor = 'bkline'
assignee = 'none'
closed = True
closed_date = <Date 2011-05-03.16:20:57.022>
closer = 'pitrou'
components = ['XML']
creation = <Date 2011-04-15.09:08:38.178>
creator = 'kaifeng'
dependencies = []
files = ['21669', '21670', '21700', '21770', '21859', '21864', '23782']
hgrepos = []
issue_num = 11849
keywords = ['patch']
message_count = 44.0
messages = ['133797', '133799', '133800', '133808', '133809', '133813', '133929', '133940', '133946', '133956', '133980', '134008', '134083', '134358', '134359', '134360', '134375', '134380', '134388', '134392', '134992', '134995', '135010', '135023', '135049', '148293', '148297', '148308', '148313', '148314', '148363', '148364', '148366', '148374', '202458', '202459', '202478', '310052', '310053', '310055', '310058', '310065', '310068', '310086']
nosy_count = 11.0
nosy_names = ['tim.peters', 'pitrou', 'vstinner', 'bkline', 'eli.bendersky', 'methane', 'flox', 'dmalcolm', 'neologix', 'python-dev', 'kaifeng']
pr_nums = []
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'resource usage'
url = 'https://bugs.python.org/issue11849'
versions = ['Python 3.3']
Activity
kaifeng commentedon Apr 15, 2011
I'm using xml.etree.ElementTree to parse large XML file, while the memory keep increasing consistently.
You can run attached test script to reproduce it. From 'top' in Linux or 'Task Manager' in Windows, the memory usage of python is not decreased as expected when 'Done' is printed.
Tested with Python 2.5/3.1 in Windows 7, and Python 2.5 in CentOS 5.3.
florentx commentedon Apr 15, 2011
Do you experience same issue with current versions of Python? (3.2 or 2.7)
The package was upgraded in latest versions.
kaifeng commentedon Apr 15, 2011
Yes. Just tested with Python 2.7 and 3.2 in Windows 7, the memory usage is still unexpected high after 'Done' is printed.
florentx commentedon Apr 15, 2011
I've tested a small variant of your script, on OSX.
It seems to behave correctly (with 2.5, 2.6, 2.7 and 3.1).
You can force Python to release memory immediately by calling "gc.collect()".
florentx commentedon Apr 15, 2011
this is the output for 2.7.1:
kaifeng commentedon Apr 15, 2011
Python 3.2 On Linux (CentOS 5.3)
*** Python 3.2.0 final
--- PID TTY STAT TIME MAJFL TRS DRS RSS %MEM COMMAND
0 15116 pts/0 S+ 0:00 1 1316 11055 6452 0.6 python3.2 issue11849_test.py
1 15116 pts/0 S+ 0:02 1 1316 53155 47340 4.5 python3.2 issue11849_test.py
2 15116 pts/0 S+ 0:05 1 1316 91051 86364 8.3 python3.2 issue11849_test.py
3 15116 pts/0 S+ 0:08 1 1316 129067 124232 12.0 python3.2 issue11849_test.py
4 15116 pts/0 S+ 0:10 1 1316 166587 162096 15.6 python3.2 issue11849_test.py
5 15116 pts/0 S+ 0:13 1 1316 204483 198824 19.2 python3.2 issue11849_test.py
6 15116 pts/0 S+ 0:17 1 1316 242375 236692 22.8 python3.2 issue11849_test.py
7 15116 pts/0 S+ 0:19 1 1316 284383 277528 26.8 python3.2 issue11849_test.py
8 15116 pts/0 S+ 0:23 1 1316 318371 312452 30.1 python3.2 issue11849_test.py
9 15116 pts/0 S+ 0:25 1 1316 360235 353288 34.1 python3.2 issue11849_test.py
END 15116 pts/0 S+ 0:30 1 1316 393975 388176 37.4 python3.2 issue11849_test.py
GC 15116 pts/0 S+ 0:30 1 1316 352035 347656 33.5 python3.2 issue11849_test.py
*** 15116 pts/0 S+ 0:30 1 1316 352035 347656 33.5 python3.2 issue11849_test.py
neologix commentedon Apr 17, 2011
The "problem" is not with Python, but with your libc.
When a program - such as Python - returns memory, it uses the free(3) library call.
But the libc is free to either return the memory immediately to the kernel using the relevant syscall (brk, munmap), or keep it around just in case (to simplify).
It seems that RHEL5 and onwards tend to keep a lot of memory around, at least in this case (probably because of the allocation pattern).
To sum up, python is returning memory, but your libc is not.
You can force it using malloc_trim, see the attached patch (I'm not at all suggesting its inclusion, it's just an illustration).
Results with current code:
*** Python 3.3.0 alpha
--- PID TTY STAT TIME MAJFL TRS DRS RSS %MEM COMMAND
0 29823 pts/0 S+ 0:00 1 1607 168176 8596 0.2 ./python /tmp/issue11849_test.py
1 29823 pts/0 S+ 0:01 1 1607 249400 87088 2.2 ./python /tmp/issue11849_test.py
2 29823 pts/0 S+ 0:03 1 1607 324080 161704 4.1 ./python /tmp/issue11849_test.py
3 29823 pts/0 S+ 0:04 1 1607 398960 235036 5.9 ./python /tmp/issue11849_test.py
4 29823 pts/0 S+ 0:06 1 1607 473356 309464 7.8 ./python /tmp/issue11849_test.py
5 29823 pts/0 S+ 0:07 1 1607 548120 384624 9.8 ./python /tmp/issue11849_test.py
6 29823 pts/0 S+ 0:09 1 1607 622884 458332 11.6 ./python /tmp/issue11849_test.py
7 29823 pts/0 S+ 0:10 1 1607 701864 535736 13.6 ./python /tmp/issue11849_test.py
8 29823 pts/0 S+ 0:12 1 1607 772440 607988 15.5 ./python /tmp/issue11849_test.py
9 29823 pts/0 S+ 0:13 1 1607 851156 685384 17.4 ./python /tmp/issue11849_test.py
END 29823 pts/0 S+ 0:16 1 1607 761712 599400 15.2 ./python /tmp/issue11849_test.py
GC 29823 pts/0 S+ 0:16 1 1607 680900 519280 13.2 ./python /tmp/issue11849_test.py
*** 29823 pts/0 S+ 0:16 1 1607 680900 519288 13.2 ./python /tmp/issue11849_test.py
Results with the malloc_trim:
*** Python 3.3.0 alpha
--- PID TTY STAT TIME MAJFL TRS DRS RSS %MEM COMMAND
0 30020 pts/0 S+ 0:00 1 1607 168180 8596 0.2 ./python /tmp/issue11849_test.py
1 30020 pts/0 S+ 0:01 1 1607 249404 86160 2.1 ./python /tmp/issue11849_test.py
2 30020 pts/0 S+ 0:03 1 1607 324084 160596 4.0 ./python /tmp/issue11849_test.py
3 30020 pts/0 S+ 0:04 1 1607 398964 235036 5.9 ./python /tmp/issue11849_test.py
4 30020 pts/0 S+ 0:06 1 1607 473360 309808 7.9 ./python /tmp/issue11849_test.py
5 30020 pts/0 S+ 0:07 1 1607 548124 383896 9.7 ./python /tmp/issue11849_test.py
6 30020 pts/0 S+ 0:09 1 1607 622888 458716 11.7 ./python /tmp/issue11849_test.py
7 30020 pts/0 S+ 0:10 1 1607 701868 536124 13.6 ./python /tmp/issue11849_test.py
8 30020 pts/0 S+ 0:12 1 1607 772444 607212 15.4 ./python /tmp/issue11849_test.py
9 30020 pts/0 S+ 0:14 1 1607 851160 684608 17.4 ./python /tmp/issue11849_test.py
END 30020 pts/0 S+ 0:16 1 1607 761716 599524 15.3 ./python /tmp/issue11849_test.py
GC 30020 pts/0 S+ 0:16 1 1607 680776 10744 0.2 ./python /tmp/issue11849_test.py
*** 30020 pts/0 S+ 0:16 1 1607 680776 10752 0.2 ./python /tmp/issue11849_test.py
pitrou commentedon Apr 17, 2011
That's an interesting thing, perhaps you want to open a feature request as a separate issue?
kaifeng commentedon Apr 18, 2011
I added 'malloc_trim' to the test code and rerun the test with Python 2.5 / 3.2 on CentOS 5.3. The problem still exists.
*** Python 2.5.5 final
--- PID TTY STAT TIME MAJFL TRS DRS RSS %MEM COMMAND
0 2567 pts/0 S+ 0:00 0 1 8206 4864 0.4 /home/zkf/.programs/python/bin/python issue11849_test.py
1 2567 pts/0 S+ 0:03 0 1 44558 41140 3.9 /home/zkf/.programs/python/bin/python issue11849_test.py
2 2567 pts/0 S+ 0:07 0 1 81166 77728 7.5 /home/zkf/.programs/python/bin/python issue11849_test.py
3 2567 pts/0 S+ 0:12 0 1 117798 114316 11.0 /home/zkf/.programs/python/bin/python issue11849_test.py
4 2567 pts/0 S+ 0:17 0 1 154402 150912 14.5 /home/zkf/.programs/python/bin/python issue11849_test.py
5 2567 pts/0 S+ 0:23 0 1 191018 187500 18.1 /home/zkf/.programs/python/bin/python issue11849_test.py
6 2567 pts/0 S+ 0:29 0 1 227630 224084 21.6 /home/zkf/.programs/python/bin/python issue11849_test.py
7 2567 pts/0 S+ 0:36 0 1 264242 260668 25.1 /home/zkf/.programs/python/bin/python issue11849_test.py
8 2567 pts/0 S+ 0:44 0 1 300882 297288 28.7 /home/zkf/.programs/python/bin/python issue11849_test.py
9 2567 pts/0 S+ 0:53 0 1 337230 333860 32.2 /home/zkf/.programs/python/bin/python issue11849_test.py
END 2567 pts/0 S+ 1:02 0 1 373842 370444 35.7 /home/zkf/.programs/python/bin/python issue11849_test.py
GC 2567 pts/0 S+ 1:02 0 1 373842 370444 35.7 /home/zkf/.programs/python/bin/python issue11849_test.py
*** 2567 pts/0 S+ 1:02 0 1 373714 370436 35.7 /home/zkf/.programs/python/bin/python issue11849_test.py
*** Python 3.2.0 final
--- PID TTY STAT TIME MAJFL TRS DRS RSS %MEM COMMAND
0 2633 pts/0 S+ 0:00 1 1316 11051 6448 0.6 python3.2 issue11849_test.py
1 2633 pts/0 S+ 0:02 1 1316 53151 47340 4.5 python3.2 issue11849_test.py
2 2633 pts/0 S+ 0:05 1 1316 91051 85216 8.2 python3.2 issue11849_test.py
3 2633 pts/0 S+ 0:08 1 1316 128943 124228 12.0 python3.2 issue11849_test.py
4 2633 pts/0 S+ 0:11 1 1316 166803 162296 15.6 python3.2 issue11849_test.py
5 2633 pts/0 S+ 0:14 1 1316 204475 199972 19.3 python3.2 issue11849_test.py
6 2633 pts/0 S+ 0:17 1 1316 243831 238180 23.0 python3.2 issue11849_test.py
7 2633 pts/0 S+ 0:20 1 1316 284371 277532 26.8 python3.2 issue11849_test.py
8 2633 pts/0 S+ 0:23 1 1316 318187 312456 30.1 python3.2 issue11849_test.py
9 2633 pts/0 S+ 0:26 1 1316 360231 353296 34.1 python3.2 issue11849_test.py
END 2633 pts/0 S+ 0:30 1 1316 393971 388184 37.4 python3.2 issue11849_test.py
GC 2633 pts/0 S+ 0:30 1 1316 352031 347652 33.5 python3.2 issue11849_test.py
*** 2633 pts/0 S+ 0:31 1 1316 351903 347524 33.5 python3.2 issue11849_test.py
kaifeng commentedon Apr 18, 2011
Found a minor defect of Python 3.2 / 3.3: line 1676 of xml/etree/ElementTree.py
was:
del self.target, self._parser # get rid of circular references
should be:
del self.target, self._target, self.parser, self._parser # get rid of circular references
While it doesn't help this issue...
neologix commentedon Apr 18, 2011
Well, malloc_trim can fail, but how did you "add" it ? Did you use
patch to apply the diff ?
Also, could you post the output of a
ltrace -e malloc_trim python <test script>
For info, the sample outputs I posted above come from a RHEL6 box.
Anyway, I'm 99% sure this isn't a leak but a malloc issue (valgrind
--tool=memcheck could confirm this if you want to try, I could be
wrong, it wouldn't be the first time ;-) ).
By the way, look at what I just found:
http://mail.gnome.org/archives/xml/2008-February/msg00003.html
Dunno.
Memory management is a domain which belongs to the operating
system/libc, and I think applications should mess with it (apart from
specific cases) .
I don't have time to look at this precise problem in greater detail
right now, but AFAICT, this looks either like a glibc bug, or at least
a corner case with default malloc parameters (M_TRIM_THRESHOLD and
friends), affecting only RHEL and derived distributions.
malloc_trim should be called automatically by free if the amount of
memory that could be release is above M_TRIM_THRESHOLD.
Calling it systematically can have a non-negligible performance impact.
kaifeng commentedon Apr 19, 2011
I applied your patch to Python 3.2, also I added a function call to 'malloc_trim' via ctypes, as you can see in issue11849_test2.py.
In fact I have a daemon written in Python 2.5, parsing an XML of size 10+ MB every 5 minutes, after 16+ hours running, the program finally exhausted 4 GB memory and died. I simplified the logic of the daemon and found ElementTree eats too much memory. There comes the attached test script.
BTW, after utilize lxml instead of ElementTree, such phenomenon of increasing memory usage disappeared.
--- SIGCHLD (Child exited) ---
*** Python 3.2.0 final
--- SIGCHLD (Child exited) ---
--- PID TTY STAT TIME MAJFL TRS DRS RSS %MEM COMMAND
--- SIGCHLD (Child exited) ---
0 13708 pts/1 S+ 0:00 1 65 1742 636 0.0 ltrace -e malloc_trim python3.2 Issue11849_test2.py
13709 pts/1 S+ 0:00 1 1316 11055 6440 0.6 python3.2 Issue11849_test2.py
--- SIGCHLD (Child exited) ---
1 13708 pts/1 S+ 0:00 1 65 1742 636 0.0 ltrace -e malloc_trim python3.2 Issue11849_test2.py
13709 pts/1 S+ 0:03 1 1316 53155 47332 4.5 python3.2 Issue11849_test2.py
--- SIGCHLD (Child exited) ---
2 13708 pts/1 S+ 0:00 1 65 1742 636 0.0 ltrace -e malloc_trim python3.2 Issue11849_test2.py
13709 pts/1 S+ 0:06 1 1316 91055 85204 8.2 python3.2 Issue11849_test2.py
--- SIGCHLD (Child exited) ---
3 13708 pts/1 S+ 0:01 1 65 1742 636 0.0 ltrace -e malloc_trim python3.2 Issue11849_test2.py
13709 pts/1 S+ 0:10 1 1316 128947 124212 11.9 python3.2 Issue11849_test2.py
--- SIGCHLD (Child exited) ---
4 13708 pts/1 S+ 0:01 1 65 1742 636 0.0 ltrace -e malloc_trim python3.2 Issue11849_test2.py
13709 pts/1 S+ 0:13 1 1316 166807 162280 15.6 python3.2 Issue11849_test2.py
--- SIGCHLD (Child exited) ---
5 13708 pts/1 S+ 0:01 1 65 1742 636 0.0 ltrace -e malloc_trim python3.2 Issue11849_test2.py
13709 pts/1 S+ 0:16 1 1316 204483 198808 19.2 python3.2 Issue11849_test2.py
--- SIGCHLD (Child exited) ---
6 13708 pts/1 S+ 0:02 1 65 1742 636 0.0 ltrace -e malloc_trim python3.2 Issue11849_test2.py
13709 pts/1 S+ 0:20 1 1316 242379 236672 22.8 python3.2 Issue11849_test2.py
--- SIGCHLD (Child exited) ---
7 13708 pts/1 S+ 0:02 1 65 1742 636 0.0 ltrace -e malloc_trim python3.2 Issue11849_test2.py
13709 pts/1 S+ 0:23 1 1316 284383 277508 26.8 python3.2 Issue11849_test2.py
--- SIGCHLD (Child exited) ---
8 13708 pts/1 S+ 0:03 1 65 1742 636 0.0 ltrace -e malloc_trim python3.2 Issue11849_test2.py
13709 pts/1 S+ 0:27 1 1316 318191 312436 30.1 python3.2 Issue11849_test2.py
--- SIGCHLD (Child exited) ---
9 13708 pts/1 S+ 0:03 1 65 1742 636 0.0 ltrace -e malloc_trim python3.2 Issue11849_test2.py
13709 pts/1 S+ 0:29 1 1316 360199 353272 34.1 python3.2 Issue11849_test2.py
--- SIGCHLD (Child exited) ---
END 13708 pts/1 S+ 0:03 1 65 1742 636 0.0 ltrace -e malloc_trim python3.2 Issue11849_test2.py
13709 pts/1 S+ 0:34 1 1316 393975 388164 37.4 python3.2 Issue11849_test2.py
malloc_trim(0, 0, 0x818480a, 0x81a0114, 0xbfb6c940) = 1
--- SIGCHLD (Child exited) ---
GC 13708 pts/1 S+ 0:03 1 65 1742 648 0.0 ltrace -e malloc_trim python3.2 Issue11849_test2.py
13709 pts/1 S+ 0:35 1 1316 351871 347480 33.5 python3.2 Issue11849_test2.py
--- SIGCHLD (Child exited) ---
*** 13708 pts/1 S+ 0:03 1 65 1742 648 0.0 ltrace -e malloc_trim python3.2 Issue11849_test2.py
13709 pts/1 S+ 0:35 1 1316 351871 347480 33.5 python3.2 Issue11849_test2.py
+++ exited (status 0) +++
neologix commentedon Apr 19, 2011
If you looked at the link I posted, you'll see that lxml had some similar issues and solved it by calling malloc_trim systematically when freeing memory.
It could also be heap fragmentation, though.
To go further, it'd be nice if you could provide the output of
valgrind --tool=memcheck --leak-check=full --suppressions=Misc/valgrind-python.supp python <test script>
after uncommenting relevant lines in Misc/valgrind-python.supp (see http://svn.python.org/projects/python/trunk/Misc/README.valgrind ).
It will either confirm a memory leak or malloc issue (I still favour the later).
By the way, does
lead to a constant memory usage increase ?
19 remaining items
neologix commentedon Nov 25, 2011
On my box:
default:
$ ./python -m timeit -s "n=300000; f=open('/tmp/10MB.bin', 'rb');
b=bytearray(n)" "f.seek(0);f.readinto(b)"
1000 loops, best of 3: 640 usec per loop
default without patch ("$ hg revert -r 68258 Objects/obmalloc.c && make"):
$ ./python -m timeit -s "n=300000; f=open('/tmp/10MB.bin', 'rb');
b=bytearray(n)" "f.seek(0);f.readinto(b)"
1000 loops, best of 3: 663 usec per loop
I'm just observing a random variance (but my computer is maybe too
slow to notice).
However, I really don't see how the patch could play a role here.
Concerning the slight performance regression, if it's a problem, I see
two options:
arenas (but I'm not sure anonymous mappings are supported by every OS
out there, so this might lead to some ugly #ifdef's...)
pitrou commentedon Nov 25, 2011
Hmm, quite slow indeed, are you sure you're not running in debug mode?
If the performance regression is limited to read(), I don't think it's
really an issue, but using mmap/munmap explicitly would probably benicer
anyway (1° because it lets the glibc choose whatever heuristic is best,
2° because it would help release memory on more systems than just glibc
systems). I think limiting ourselves to systems which have
MMAP_ANONYMOUS is good enough.
Here is what the glibc malloc does btw:
/*
Nearly all versions of mmap support MAP_ANONYMOUS,
so the following is unlikely to be needed, but is
supplied just in case.
*/
static int dev_zero_fd = -1; /* Cached file descriptor for /dev/zero. */
#else
#endif
neologix commentedon Nov 25, 2011
Well, yes, but it's no faster with a non-debug build: my laptop is
really crawling :-)
Agreed.
Here's a patch.
python-dev commentedon Nov 26, 2011
New changeset e7aa72e6aad4 by Antoine Pitrou in branch 'default':
Better resolution for issue bpo-11849: Ensure that free()d memory arenas are really released
http://hg.python.org/cpython/rev/e7aa72e6aad4
vstinner commentedon Nov 9, 2013
I just found this issue from this article:
http://python.dzone.com/articles/diagnosing-memory-leaks-python
Great job! Using mmap() for arenas is the best solution for this issue. I did something similar on a completly different project (also using its own dedicated memory allocator) for workaround the fragmentation of the heap memory.
tim-one commentedon Nov 9, 2013
[@Haypo]
? I read the article, and they stopped when they found "there seemed to be a ton of tiny little objects around, like integers.". Ints aren't allocated from arenas to begin wtih - they have their own (immortal & unbounded) free list in Python2. No change to pymalloc could make any difference to that.
vstinner commentedon Nov 9, 2013
Extract of the "workaround" section:
"You could also run your Python jobs using Jython, which uses the Java JVM
and does not exhibit this behavior. Likewise, you could upgrade to Python
3.3 <http://bugs.python.org/issue11849\>,"
Which contains a link to this issue.
bkline commentedon Jan 16, 2018
Would it be inappropriate for this fix to be applied to 2.7?
pitrou commentedon Jan 16, 2018
It's not really a fix, it's an improvement, and as such doesn't belong in 2.7. Using malloc() and free() is not a bug in itself.
bkline commentedon Jan 16, 2018
Sorry, I should have used the language of the patch author ("the resolution"). Without the resolution, Python 2.7 eventually runs out of memory and crashes for some correctly written user code.
pitrou commentedon Jan 16, 2018
Well, memory fragmentation can happen with any allocation scheme, and it's possible even Python 3 isn't immune to this. Backporting performance improvements is a strain on our resources and also constitutes a maintenance threat (what if the bug hides in the new code?). And Python 2.7 is really nearing its end-of-life more and more everyday. So IMHO it's a no-no.
bkline commentedon Jan 16, 2018
Thanks for your responses to my comments. I'm working as hard as I can to get my customer's systems migrated into the Python 3 world, and I appreciate the efforts of the community to provide incentives (such as the resolution for this failure) for developers to upgrade. However, it's a delicate balancing act sometimes, given that we have critical places in our system for which the same code runs more than twice as slowly on Python 3.6 as on Python 2.7.
methane commentedon Jan 16, 2018
FYI, jemalloc can reduce memory usage, especially when application
is multithreaded.
https://www.speedshop.co/2017/12/04/malloc-doubles-ruby-memory.html
https://zapier.com/engineering/celery-python-jemalloc/
bkline commentedon Jan 16, 2018
Thanks for the tip. I downloaded the source and successfully built the DLL, then went looking for a way to get it loaded. Unfortunately, DLL injection, which is needed to use this allocator in Python, seems to be much better supported on Linux than on Windows. Basically, Microsoft's documentation [1] for AppInit_DLL, the shim for DLL injection on Windows, says (in effect) "here's how to use this technique, but we don't recommend using it, so here's a link [2] for what we recommend you do instead. That link takes you to "Try searching for what you need. This page doesn’t exist."
[1] https://support.microsoft.com/en-us/help/197571/working-with-the-appinit-dlls-registry-value
[2] https://support.microsoft.com/en-us/help/134655