classification
Title: Enhance tracemalloc to trace properly free lists
Type: Stage: resolved
Components: Library (Lib) Versions: Python 3.8
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: inada.naoki, serhiy.storchaka, vstinner
Priority: normal Keywords: patch

Created on 2018-10-23 16:42 by vstinner, last changed 2018-10-25 22:03 by vstinner. This issue is now closed.

Files
File name Uploaded Description Edit
dict_wrong_traceback.py vstinner, 2018-10-24 12:09
Pull Requests
URL Status Linked Edit
PR 10063 merged vstinner, 2018-10-23 17:01
PR 10091 merged vstinner, 2018-10-25 13:05
PR 10107 merged vstinner, 2018-10-25 21:42
Messages (12)
msg328326 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-10-23 16:42
CPython uses many "free lists": list of "deallocated" objects which are kept alive to optimize allocation of new objects. For example, the builtin list type has a free list.

Problem: tracemalloc only traces the memory allocation when the object is created, but it doesn't update the traceback when the "free object" is reused to create "a new object".

Attached PR modifies _Py_NewReference() to update the Python traceback in the tracemalloc trace.
msg328351 - (view) Author: Inada Naoki (inada.naoki) * (Python committer) Date: 2018-10-24 02:05
Is performance overhead negligible?
msg328361 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-10-24 11:16
> Is performance overhead negligible?

Thank you for asking the most important question :-)

I ran this microbenchmark:

make distclean
./configure --enable-lto
make
./python -m venv env
env/bin/python -m pip install perf
sudo env/bin/python -m perf system tune
env/bin/python -m perf timeit -o FILE.json -v '[]'


My first attempt:

$ env/bin/python -m perf compare_to ref.json patch.json 
Mean +- std dev: [ref] 20.6 ns +- 0.1 ns -> [patch] 22.4 ns +- 0.1 ns: 1.09x slower (+9%)

The addition of the _PyTraceMalloc_NewReference() call which does nothing (check tracing flag, return) adds 1.7 ns: it's not negligible on such micro-benchmark, and I would prefer to avoid it whenever possible since _Py_NewReference() is the root of the free list optimization.


New attempt: expose tracemalloc_config and add _Py_unlikely() macro (instruct the compiler that tracing is false most of the time):

Mean +- std dev: [ref] 20.6 ns +- 0.1 ns -> [unlikely] 20.4 ns +- 0.3 ns: 1.01x faster (-1%)

Good! The overhead is now negligible!


But... is the hardcore low-level _Py_unlikely() optimization really needed?...

$ env/bin/python -m perf compare_to ref.json if_tracing.json 
Benchmark hidden because not significant (1): timeit

=> no, the macro is useless, so I removed it!



New benchmark to double-check on my laptop.

git checkout master
make clean; make
rm -rf env; ./python -m venv env; env/bin/python -m pip install perf
sudo env/bin/python -m perf system tune
env/bin/python -m perf timeit -o ref.json -v '[]' --rigorous

git checkout tracemalloc_newref
make clean; make
rm -rf env; ./python -m venv env; env/bin/python -m pip install perf
env/bin/python -m perf timeit -o patch.json -v '[]' --rigorous

$ env/bin/python -m perf compare_to ref.json patch.json 
Mean +- std dev: [ref] 20.8 ns +- 0.7 ns -> [patch] 20.5 ns +- 0.3 ns: 1.01x faster (-1%)


The std dev is a little bit high. I didn't use CPU isolation and Hexchat + Firefox was running in the background, *but* it seems like the mean is very close, and so that my PR has no significant overhead.
msg328363 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-10-24 12:09
Python 3.8 uses many free lists:
https://pythondev.readthedocs.io/cpython_impl_optim.html#free-lists

Attached dict_wrong_traceback.py shows the bug on the dictionary of an object:

$ ./python ~/dict_wrong_traceback.py 
  File "/home/vstinner/dict_wrong_traceback.py", line 13
    p = Point() # first object (dead!)
  File "/home/vstinner/dict_wrong_traceback.py", line 8
    self.x = 1

tracemalloc shows the traceback of the first object... which has been destroyed!

With the fix:

$ ./python ~/dict_wrong_traceback.py 
  File "/home/vstinner/dict_wrong_traceback.py", line 16
    p = Point() # second object (alive)
  File "/home/vstinner/dict_wrong_traceback.py", line 8
    self.x = 1

It's much better: it doesn't show dead objects anymore :-)
msg328364 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-10-24 12:19
A little bit of history.

I opened a bug 2 years ago but I closed it (lack of interest):
https://github.com/vstinner/pytracemalloc/issues/2

I rewrote tracemalloc between version 0.9 and 1.0. In tracemalloc 0.9, there was an API to track free lists. Here is the code to handle "alloc" and "free" of an object inside a freelist:

https://github.com/vstinner/pytracemalloc/blob/a2b2616fc73cd5ce0ea45d1b68a490e0fc52ccc8/_tracemalloc.c#L291-L337

My PR 10063 has a more correct and efficient implementation:

* It keeps the trace alive when the object moves into the free list to report the real memory usage of Python: the free lists consumes memory
* It writes directly into the hash table entry rather than remove/add frequently the trace, it should be more efficient
msg328374 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-10-24 16:11
Even if Python 3.6 and 3.7 are impacted by the bug, I propose to only fix Python 3.8 since the change modifies a _Py_NewReference() function which is critical for performance.
msg328375 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-10-24 16:11
While writing PR 10063, I was unhappy with _Py_NewReference() macro, and so I wrote bpo-35059 to convert it to a static inline function.
msg328428 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-10-25 11:31
New changeset 9e00e80e213ebc37eff89ce72102c1f928ebc133 by Victor Stinner in branch 'master':
bpo-35053: Enhance tracemalloc to trace free lists (GH-10063)
https://github.com/python/cpython/commit/9e00e80e213ebc37eff89ce72102c1f928ebc133
msg328436 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-10-25 13:54
New changeset 6279c1c5003cd94b5e04e568ce3df7c4e8f1eaa3 by Victor Stinner in branch 'master':
bpo-35053: Add Include/tracemalloc.h (GH-10091)
https://github.com/python/cpython/commit/6279c1c5003cd94b5e04e568ce3df7c4e8f1eaa3
msg328441 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-10-25 14:16
This change modifies _Py_NewReference() which is a very important function and it impacts Python performance. I prefer to keep the bug in Python 3.6 and 3.7 to not risk to introduce a regression.

The bug exists since Python 3.4 and I'm the first one to spot it. It's not like there is huge pressure to backport the fix.

Thanks again INADA-san for the review!
msg328500 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-10-25 22:02
New changeset c89a93271447ec65e83a1dc7605e62dbf272cafd by Victor Stinner in branch 'master':
bpo-35053: Define _PyTraceMalloc_NewReference in object.h (GH-10107)
https://github.com/python/cpython/commit/c89a93271447ec65e83a1dc7605e62dbf272cafd
msg328501 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-10-25 22:03
Oh :-( I didn't expect that I would have to declare PyTraceMalloc_NewReference() in object.h even if Py_LIMITED_API is defined...

Python currently leaks too much things even if Py_LIMITED_API is defined. It's time to break the C API! :-) https://pythoncapi.readthedocs.io/ (just kidding, or not)
History
Date User Action Args
2018-10-25 22:03:41vstinnersetmessages: + msg328501
2018-10-25 22:02:02vstinnersetmessages: + msg328500
2018-10-25 21:42:59vstinnersetpull_requests: + pull_request9439
2018-10-25 14:16:18vstinnersetstatus: open -> closed
resolution: fixed
messages: + msg328441

stage: patch review -> resolved
2018-10-25 13:54:25vstinnersetmessages: + msg328436
2018-10-25 13:05:58vstinnersetpull_requests: + pull_request9422
2018-10-25 11:31:20vstinnersetmessages: + msg328428
2018-10-24 16:11:56vstinnersetmessages: + msg328375
2018-10-24 16:11:05vstinnersetmessages: + msg328374
2018-10-24 12:19:05vstinnersetmessages: + msg328364
2018-10-24 12:09:09vstinnersetfiles: + dict_wrong_traceback.py

messages: + msg328363
2018-10-24 11:16:35vstinnersetmessages: + msg328361
2018-10-24 02:05:32inada.naokisetnosy: + inada.naoki
messages: + msg328351
2018-10-23 17:47:35serhiy.storchakasetnosy: + serhiy.storchaka
2018-10-23 17:01:12vstinnersetkeywords: + patch
stage: patch review
pull_requests: + pull_request9399
2018-10-23 16:42:14vstinnercreate