Getting different results for @pytest.mark.limit_memory on macOS

[ecerulm]

Bug Report

The urllib3 test suite uses @pytest.mark.limit_memory,

When using pytest 7.4.4 + pytest-memray 1.5.0 we get the expected behaviour (that is the test passes).

Then using pytest 8.0.0 + pytest-memray 1.5.0 we got some test failures. This happens on macOS (python 3.10, 3.11 and 3.12 ) and Ubuntu 22.04 (python 3.12, not with python 3.11 or python 3.10).

The test checks for a limit of 10.01MB but it fails due to increased memory usage (10.1MB), since the test code has not changed (the only change is bumping the pytest version to 8.0.0) we wonder if there is problem on the way pytest-memray is calculating the memory usage.

I'm aware that the pytest-memray usage states:

As the Python interpreter has its own object allocator it’s possible that memory is not immediately released to the system when objects are deleted, so tests using this marker may need to give some room to account for this.

But we wonder why the memory usage reported is bigger now if the tested code is the same.

Also we know that if we run the urllib3 test_get_all_memory_usage_single_chunk alone it will pass (only consumes 10.01M) but if we run the test_socket_close_socket_then_file before it fails on test_get_all_memory_usage_single_chunk (reporting that it consumes 10.1M). That suggest that some allocation that happens on test_socket_close_socket_then_file is counted as if happened on test_get_all_memory_usage_single_chunk.

See more details on https://github.com/urllib3/urllib3/pull/3335

Input Code

Expected behavior/code A clear and concise description of what you expected to happen (or code).

Environment python 3.10 on macOS python 3.11 on macOS python 3.12 on macOS python 3.12 on Ubuntu 22.04

Possible Solution

Additional context/Screenshots Add any other context about the problem here. If applicable, add screenshots to help explain.

[pablogsal]

Hummm I tried to reproduce locally but I cannot get it to reproduce. This is what you get in the test:

_________ TestBytesQueueBuffer.test_get_all_memory_usage_single_chunk __________
Test was limited to 10.0MiB but allocated 10.1MiB
------------------------------ memray-max-memory -------------------------------
List of allocations:
    - 628.0B allocated here:
        wrapper:/home/runner/work/urllib3/urllib3/.nox/test-3-11/lib/python3.11/site-packages/pytest_memray/plugin.py:191
    - 10.0MiB allocated here:
        test_get_all_memory_usage_single_chunk:/home/runner/work/urllib3/urllib3/test/test_response.py:114
        ...
    - 528.0B allocated here:
        __init__:/home/runner/work/urllib3/urllib3/.nox/test-3-11/lib/python3.11/site-packages/urllib3/response.py:247
        ...
    - 64.0KiB allocated here:
        read:/opt/hostedtoolcache/Python/3.11.8/x64/lib/python3.11/ssl.py:1168
        ...
    - 64.0KiB allocated here:
        read:/opt/hostedtoolcache/Python/3.11.8/x64/lib/python3.11/ssl.py:1168
        ...

and this is what I get (with pytest 8.0.2):

------------------------------------------------------------------------------------------ memray-max-memory ------------------------------------------------------------------------------------------List of allocations:
    - 628.0B allocated here:
        wrapper:/home/pablogsal/urllib3/venv/lib/python3.11/site-packages/pytest_memray/plugin.py:191
    - 528.0B allocated here:
        __init__:/home/pablogsal/urllib3/src/urllib3/response.py:247
        ...
    - 10.0MiB allocated here:
        test_get_all_memory_usage_single_chunk:/home/pablogsal/urllib3/test/test_response.py:114
        ...

Looks like somehow you got these extra SSL allocations:

    - 64.0KiB allocated here:
        read:/opt/hostedtoolcache/Python/3.11.8/x64/lib/python3.11/ssl.py:1168
        ...
    - 64.0KiB allocated here:
        read:/opt/hostedtoolcache/Python/3.11.8/x64/lib/python3.11/ssl.py:1168
        ...

those are certainly real but I don't know where they are coming from

[pablogsal]

Ok, following https://github.com/urllib3/urllib3/pull/3335#issuecomment-1967557700 I did some investigation by adding --native --stacks=100 to check native stacks and got this:

    - 64.0KiB allocated here:
        _PyObject_Malloc:Objects/obmalloc.c:2003
        _PyObject_Malloc:Objects/obmalloc.c:1996
        _PyBytes_FromSize:Objects/bytesobject.c:103
        _PyBytes_FromSize:Objects/bytesobject.c:84
        PyBytes_FromStringAndSize:Objects/bytesobject.c:136
        _ssl__SSLSocket_read_impl:/tmp/python-build.20240227211037.2773/Python-3.11.8/Modules/_ssl.c:2505
        _ssl__SSLSocket_read:/tmp/python-build.20240227211037.2773/Python-3.11.8/Modules/clinic/_ssl.c.h:301
        cfunction_call:Objects/methodobject.c:553
        _PyObject_MakeTpCall:Objects/call.c:214
        trace_call_function:Python/ceval.c:7301
        read:/home/pablogsal/.pyenv/versions/3.11.8/lib/python3.11/ssl.py:1168
        recv:/home/pablogsal/.pyenv/versions/3.11.8/lib/python3.11/ssl.py:1295
        consume_socket:/home/pablogsal/urllib3/dummyserver/testcase.py:26
        consume_ssl_socket:/home/pablogsal/urllib3/test/with_dummyserver/test_socketlevel.py:967
        _start_server:/home/pablogsal/urllib3/dummyserver/socketserver.py:138
        run:/home/pablogsal/urllib3/dummyserver/socketserver.py:141
        _bootstrap_inner:/home/pablogsal/.pyenv/versions/3.11.8/lib/python3.11/threading.py:1045
        _bootstrap:/home/pablogsal/.pyenv/versions/3.11.8/lib/python3.11/threading.py:1002
        _PyEval_EvalFrame:./Include/internal/pycore_ceval.h:73
        _PyEval_Vector:Python/ceval.c:6434
        _PyObject_VectorcallTstate:./Include/internal/pycore_call.h:92
        method_vectorcall:Objects/classobject.c:67
        _PyVectorcall_Call:Objects/call.c:245
        _PyObject_Call:Objects/call.c:328
        thread_run:./Modules/_threadmodule.c:1124
        pythread_wrapper:Python/thread_pthread.h:241
        start_thread:/build/glibc-BHL3KM/glibc-2.31/nptl/pthread_create.c:477
        __clone:<unknown>:0

So looks like it's a python thread that is doing the allocation. It's possible that this thread is alive when the test starts some times and that is where the allocation comes from.

[pablogsal]

I added print(threading.enumerate()) and got:

 [<_MainThread(MainThread, started 139919148259136)>, <SocketServerThread(Thread-1, started daemon 139919049676544)>]

So that SocketServerThread is surviving the other test.

[pablogsal]

Seems it's because https://github.com/urllib3/urllib3/blob/a7b81f554863f6dfafe2102e38d16688fdd9869a/dummyserver/testcase.py#L106 it's just returning after 0.1 but the thread is not being killed and leaks to other tests

[pablogsal]

I'm closing this as this seems to be explained by what I found, but feel free to reopen if we are missing anything.