Add a new marker to check for memory leaks

[pablogsal]

Users have indicated that it will be very useful if the plugin exposes a way to detect memory leaks in tests. This is possible, but is a bit tricky as the interpreter can allocate memory for internal caches, as well as user functions.

To make this more reliable, the new marker will take two parameters:

• The watermark of memory to ignore. If the memory leaked by the test is higher than this value, the test will fail and it will pass otherwise.

• The number of warmup runs. This allows to run the test multiple times (assuming it passes) before actually checking for leaks. This allows to warmup user and interpreter caches.

Closes: #45

[pablogsal]

I have added docs

[tonybaloney]

Just tried https://github.com/bloomberg/pytest-memray/pull/52/commits/466743b4853261a35c3ff84d4d4654d6586918a1 and I'm getting the warning:

PytestUnknownMarkWarning: Unknown pytest.mark.check_leaks - is this a typo?  You can register custom marks to avoid this warning - for details, see https://docs.pytest.org/en/stable/how-to/mark.html
    @pytest.mark.check_leaks()

$ pip freeze
....
pytest-memray @ git+https://github.com/pablogsal/pytest-memray@466743b4853261a35c3ff84d4d4654d6586918a1
...

Update:

$ pytest --markers

Doesn't show the markers, but

$ pytest --memray --markers

Does. Compared with hypothesis, or other extensions which show it regardless. This is separate (or by design) to this PR.

[godlygeek]

This is separate (or by design) to this PR

@tonybaloney Yep, and we have #49 for that already.

[godlygeek]

Other than needing to provide --memray, did things work nicely for you when you tried it?

[tonybaloney]

Other than needing to provide --memray, did things work nicely for you when you tried it?

My tests fail because memray writes to stderr on macOS with a warning (see https://github.com/bloomberg/memray/issues/254) but other than that, it seems to work when I tried it. I'm going to purposefully write a leaky test and verify that it catches it next

[pablogsal]

Just tried 466743b and I'm getting the warning:

PytestUnknownMarkWarning: Unknown pytest.mark.check_leaks - is this a typo?  You can register custom marks to avoid this warning - for details, see https://docs.pytest.org/en/stable/how-to/mark.html
    @pytest.mark.check_leaks()

$ pip freeze
....
pytest-memray @ git+https://github.com/pablogsal/pytest-memray@466743b4853261a35c3ff84d4d4654d6586918a1
...

Update:

$ pytest --markers

Doesn't show the markers, but

$ pytest --memray --markers

Does. Compared with hypothesis, or other extensions which show it regardless. This is separate (or by design) to this PR.

Apart from that, does it work for your use case? Can you simulate a leak in your extension and try the marker?

[tonybaloney]

I tried adding a leaking String object to the __repr__ function for an extension type:

PyObject* Logger_repr(Logger *self) {
    std::string level = _getLevelName(self->effective_level);
    PyObject* leaky_object = PyUnicode_FromString("Hello"); /* TEST */
    return PyUnicode_FromFormat("<Logger '%U' (%s)>", self->name, level.c_str());
}

Running memray by hand using a script that instantiates an instance of the extension type (100,000 times), I can see the leak in the graph:

This is what I'm currently doing. But using this marker doesn't seem to catch the same thing?

@pytest.mark.parametrize("level", levels)
@pytest.mark.check_leaks("0B", warmups=3)
def test_logger_repr(level):
    logger = picologging.Logger("test", level)
    assert repr(logger) == f"<Logger 'test' ({level_names[levels.index(level)]})>"

Doesn't give me any information about leaks, every test seems to leak at least something, even ones not testing my extension module:

--------------------------------------------------------------------------------- memray-leaked-memory ----------------------------------------------------------------------------------
Test leaked 108.0B out of limit of 0.0B
List of leaked allocations: 
        - test_logger_repr:/Users/anthonyshaw/projects/picologging/tests/unit/test_logger.py:279 -> 54.0B
        - test_logger_repr:/Users/anthonyshaw/projects/picologging/tests/unit/test_logger.py:280 -> 54.0B

I guess I could run each test and work out how much memory it should consume and then set the limit manually?

[pablogsal]

I tried adding a leaking String object to the __repr__ function for an extension type:

PyObject* Logger_repr(Logger *self) {
    std::string level = _getLevelName(self->effective_level);
    PyObject* leaky_object = PyUnicode_FromString("Hello"); /* TEST */
    return PyUnicode_FromFormat("<Logger '%U' (%s)>", self->name, level.c_str());
}

Running memray by hand using a script that instantiates an instance of the extension type (100,000 times), I can see the leak in the graph:

This is what I'm currently doing. But using this marker doesn't seem to catch the same thing?

@pytest.mark.parametrize("level", levels)
@pytest.mark.check_leaks("0B", warmups=3)
def test_logger_repr(level):
    logger = picologging.Logger("test", level)
    assert repr(logger) == f"<Logger 'test' ({level_names[levels.index(level)]})>"

Doesn't give me any information about leaks, every test seems to leak at least something, even ones not testing my extension module:

--------------------------------------------------------------------------------- memray-leaked-memory ----------------------------------------------------------------------------------
Test leaked 108.0B out of limit of 0.0B
List of leaked allocations: 
        - test_logger_repr:/Users/anthonyshaw/projects/picologging/tests/unit/test_logger.py:279 -> 54.0B
        - test_logger_repr:/Users/anthonyshaw/projects/picologging/tests/unit/test_logger.py:280 -> 54.0B

I guess I could run each test and work out how much memory it should consume and then set the limit manually?

Well that’s because something is being leaked indeed, but is not what you are hunting for. The marker will complain about anything created in the test that survives the test. In your flamegraph for leaks you can see many more objects. So it would not be surprising that there is a lot more stuff being kept alive other than the string. That’s precisely why we take the minimum memory allowed to leak, so you can filter out that stuff.

[pablogsal]

Doesn't give me any information about leaks

what information are you expecting?

[tonybaloney]

I was expecting it to report that the PyUnicode object allocated in the Logger_repr function is leaked, like:

Test leaked XXB out of limit of 0.0B
List of leaked allocations: 
        - _Logger_repr:/Users/anthonyshaw/projects/picologging/src/logger.cxx:Logger_repr : 142 -> XXB

[pablogsal]

test_logger_repr:/Users/anthonyshaw/projects/picologging/tests/unit/test_logger.py:279 -> 54.0 test_logger_repr:/Users/anthonyshaw/projects/picologging/tests/unit/test_logger.py:280 -> 54.0B

Humm, to me this looks right. Is telling you that your C extension type is leaking memory. I don’t see why you say that is not giving you any information about the leak.

by default the marker doesn’t run in native mode so that’s why it doesn’t show anything below that. It tells you the lower Python frame that called something that leak. As it cannot see below, it cannot split that into the different calls that you see in the flamegraph but is telling you that is leaking which is the main pour pose of the marker.

to debug the leak you can use the profiler directly which allows you to use more powerful visualisations

[pablogsal]

was expecting it to report that the PyUnicode object allocated in the Logger_repr function is leaked, like:

The marker doesn’t run in native mode (for performance reasons as that’s quite heavy for a test suite) so it won’t show you any C code. Does that explain what’s going on?

[tonybaloney]

was expecting it to report that the PyUnicode object allocated in the Logger_repr function is leaked, like:

The marker doesn’t run in native mode so it won’t show you any C code. Does that explain what’s going on?

Ok, that makes sense then. Is there a way to run it in native mode? The settings I use on the CLI are:

$ PYTHONMALLOC=malloc memray run --trace-python-allocators -o .profiles/memray_logger.py.bin -f --native memray_logger.py
$ memray flamegraph --leaks -f .profiles/memray_logger.py.bin

[pablogsal]

The idea of the marker is that it will complain that there are leaks and then will show you the Python call that leaked. If you need to investigate with native code you can do it later with the profiler. Or at least that’s the idea.

the marker is not a substitute for the profiler, is a way to ensure that you are not leaking and it will tell you sonemething about the Python call that leaked but then you should investigate with better reporters.

[tonybaloney]

Ok, then yes, this will serve the requested use case in #45 I'll test it with more scenarios.

[pablogsal]

Ok, then yes, this will serve the requested use case in #45 I'll test it with more scenarios.

we could add a way to run in native mode, but that would make the happy path (the test passing) extra slow for no reason. As failures are the rare case, we are prioritising detection over exhaustive reports and leaving the manual execution of the profiler for the later.

[godlygeek]

Is there a way to run it in native mode?

@pablogsal and I were going back and forth about this on Slack for quite a while today, so I'm feeling a bit vindicated 😛

[tonybaloney]

Is there a way to run it in native mode?

@pablogsal and I were going back and forth about this on Slack for quite a while today, so I'm feeling a bit vindicated 😛

I understand it would be really slow, but handy as an optional flag

[pablogsal]

I understand it would be really slow, but handy as an optional flag

@tonybaloney

I have cheated a bit and have executed a bunch of tests in picologging under memray with native traces without modifying anything. For instance, tests/unit/test_formatter.py::test_format_time seems to leak 116.0B. This is the report;

―――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――― test_format_time ―――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――
Test was allowed to leak 0.0B but leaked 116.0B
------------------------------------------------------------------------------------------------------ memray-leaked-memory -------------------------------------------------------------------------------------------------------
Test leaked 116.0B out of limit of 0.0B
List of leaked allocations:
        - PyObject_Malloc:Objects/obmalloc.c:685 -> 59.0B
        - PyUnicode_New:Objects/unicodeobject.c:1447 -> 59.0B
        - unicode_decode_utf8:Objects/unicodeobject.c:5186 -> 59.0B
        - FormatStyle_usesTime(FormatStyle*):<unknown>:0 -> 59.0B
        - Formatter_init(Formatter*, _object*, _object*):<unknown>:0 -> 59.0B
        - type_call:Objects/typeobject.c:1128 -> 59.0B
        - _PyObject_MakeTpCall:Objects/call.c:215 -> 59.0B
        - call_function:Python/ceval.c:5893 -> 59.0B
        - test_format_time:/home/pablogsal/github/picologging/tests/unit/test_formatter.py:123 -> 59.0B
        - _PyEval_EvalFrame:./Include/internal/pycore_ceval.h:46 -> 59.0B
        - _PyEval_Vector:Python/ceval.c:5081 -> 59.0B
        - _PyFunction_Vectorcall:Objects/call.c:342 -> 59.0B
        - _PyObject_VectorcallTstate:./Include/cpython/abstract.h:114 -> 59.0B
        - _PyObject_VectorcallTstate:./Include/cpython/abstract.h:114 -> 59.0B
        - call_function:Python/ceval.c:5893 -> 59.0B
-------------
        - PyObject_Malloc:Objects/obmalloc.c:685 -> 57.0B
        - PyUnicode_New:Objects/unicodeobject.c:1447 -> 57.0B
        - unicode_decode_utf8:Objects/unicodeobject.c:5186 -> 57.0B
        - PyObject_GetAttrString:Objects/object.c:812 -> 57.0B
        - PyObject_CallMethod:Objects/call.c:570 -> 57.0B
        - Formatter_init(Formatter*, _object*, _object*):<unknown>:0 -> 57.0B
        - type_call:Objects/typeobject.c:1128 -> 57.0B
        - _PyObject_MakeTpCall:Objects/call.c:215 -> 57.0B
        - call_function:Python/ceval.c:5893 -> 57.0B
        - test_format_time:/home/pablogsal/github/picologging/tests/unit/test_formatter.py:123 -> 57.0B
        - _PyEval_EvalFrame:./Include/internal/pycore_ceval.h:46 -> 57.0B
        - _PyEval_Vector:Python/ceval.c:5081 -> 57.0B
        - _PyFunction_Vectorcall:Objects/call.c:342 -> 57.0B
        - _PyObject_VectorcallTstate:./Include/cpython/abstract.h:114 -> 57.0B
        - _PyObject_VectorcallTstate:./Include/cpython/abstract.h:114 -> 57.0B
        - call_function:Python/ceval.c:5893 -> 57.0B
-------------

One is leaked because is hitting this:

https://github.com/python/cpython/blob/2cd268a3a9340346dd86b66db2e9b428b3f878fc/Objects/typeobject.c#L3832

which forces the interpreter to cache. This is why in the docs for this PR we say:

The Python interpreter has some internal caches that will not be cleared when the test ends. You may need to allow some small amount of leaked memory or use the warmups argument to avoid false positive leak reports caused by objects that the interpreter plans to reuse later. These caches are implementation details of the interpreter, so the amount of memory allocated, the location of the allocation, and the allocator that was used can all change from one Python version to another.

As you can see, even if you activate native without extensive knowledge of the interpreter is not easy to understand what's going on there.

:exclamation: :exclamation: But on the other hand, the first one is a genuine leak. You are leaking this:

https://github.com/microsoft/picologging/blob/783acf1eba13fd587028a8dcd0d97544d33149a2/src/picologging/formatstyle.cxx#L156

            ret = PyUnicode_Find(self->fmt, PyUnicode_FromString("%(asctime)"), 0, PyUnicode_GET_LENGTH(self->fmt), 1);

in particular, you are leaking the call to PyUnicode_FromString("%(asctime)"). You need to decrement that reference after you are done with the call.

So, I guess the plugin was useful after all :wink:

[miguelcoolchips]

Hello! I was wondering if there are plans to merge this functionality in the near future. Thanks

[pablogsal]

Hello! I was wondering if there are plans to merge this functionality in the near future. Thanks

Yep, unfortunately, a bunch of things came out and we had to deprioritize finishing this. We will get to this soon. Thanks for the patience

[pablogsal]

@godlygeek This is ready for another round

[godlygeek]

I've pushed another fixup. It adds another dataclass to represent a stack frame, so that the users get named fields instead of needing to work with a tuple[str, str, int] (especially because it's not easy to remember which str is which). I've also renamed the stack frame type from StackElement to StackFrame, since I think that'll be more intuitive for users. I've also updated Stack to say that frames is a Sequence rather than a Collection, since it makes no sense to say that they're ordered but not allow users to reverse them or subscript them.

Honestly, I think we should probably change that to list instead. Once we release this, we're never going to change it to be anything other than a list, thanks to Hyrum's Law, and just telling people that it's a list makes for more readable documentation than telling them that it's a Sequence and making them jump to the CPython docs to double check which operations a Sequence supports.

[godlygeek]

OK. I've added another fixup commit getting this into a state where I'm happy to land it. I changed a fair amount of stuff, but most of it is pretty minor. The biggest changes were to the documentation.

• [x] I rearranged the order of the items on the API docs page
• [x] I set up intersphinx, to let us link to Python stdlib docs
• [x] I set the default role for Sphinx to py:obj so we can reference things with just backticks - without specifying a role (which keeps our doc strings more human-readable)
• [x] I dropped the hack I put in place in my earlier fixup to better handle type aliases. Instead, I switched LeaksFilteringFunction to be a typing.Protocol, which we can add a proper docstring to, improving the generated documentation.
• [x] I rearranged the docs pages on the sidebar so that the API docs are above the changelog instead of below
• [x] I documented the markers as pytest.mark.foo instead of just foo, making it easier to see how they're meant to be used, and also linked to the pytest docs page on custom markers.
• [x] I dropped an outdated statement from the docs: "These markers do nothing when the plugin is not enabled" - that hasn't been true since #49
• [x] I removed the section heading for each marker, and indented all of the text for each one to be part of the body of that function description (rewrapping long lines)
• [x] I fleshed out the prose for the leaks marker to explain it in a way that I think is more thorough
• [x] I also expanded upon the warning to give some examples of caches, to make it clear the sorts of things someone would be wrestling with if they ignored our warning.
• [x] I renamed LeaksFilteringFunction to LeaksFilterFunction so the signature wouldn't line wrap in the rendered docs.
• [x] Sorted imports and __all__
• [x] Switched Stack.frames from Sequence to Tuple as we discussed
• [x] Removed the base class for the two different types of MemoryInfo, in favor of making _generate_section_text a free function and creating a SectionMetadata protocol for plugin.py - this change was a bit opinionated, feel free to revert if you disagree. The use of inheritance felt awkward to me, and I think this separation does a better job of making the required contracts clear.
• [x] Removed "$bytes out of limit of $bytes" from the leaks section header, as it was being duplicated (both the long_repr and section body showed it)
• [x] Renamed passes_filter to _passes_filter for consistency with the other private members of marks.py
• [x] Made passes_filter pass the stack to the filter as a tuple instead of a list
• [x] Removed an unnecessary func variable from the implementations of the two marker functions. I think that was a hold over from a previous state when both were implemented by a common function.
• [x] Passed fields to the dataclass constructors by keyword: passing 5 integers positionally seemed tough to read to me. That's opinionated, revert if you disagree.
• [x] Fixed some indenting in the tests (some lines were indented 9 spaces instead of 8)

Sorry that this turned out to be a lot of changes, but I hope most of them will be pretty uncontroversial.

[godlygeek]

https://godlygeek.github.io/pytest-memray/usage.html and https://godlygeek.github.io/pytest-memray/api.html show the rendered documentation after my changes.