`test_free_threading.test_pickle` takes more than 4 minutes and consumes up to 22 GiB of memory

[vstinner]

Sometimes, test_free_threading.test_pickle takes more than 4 minutes and consumes up to 22 GiB of memory. I had to interrupt the job to avoid an OOM error.

Output of a modified Python on my Fedora 44:

$ ./python -m test -j0 test_free_threading
(...)
0:04:14 load avg: 2.46 mem: 22.0 GiB running (1): test_free_threading.test_pickle (4 min 10 sec)
  pid 1267609: test_free_threading.test_pickle: 22660.4 MiB
0:04:15 load avg: 2.46 mem: 22.1 GiB running (1): test_free_threading.test_pickle (4 min 12 sec)
  pid 1267609: test_free_threading.test_pickle: 22761.5 MiB
0:04:17 load avg: 2.46 mem: 22.2 GiB running (1): test_free_threading.test_pickle (4 min 13 sec)
  pid 1267609: test_free_threading.test_pickle: 23027.4 MiB
0:04:18 load avg: 2.43 mem: 22.5 GiB running (1): test_free_threading.test_pickle (4 min 15 sec)
^C

Linked PRs

• gh-150257: Skip test_free_threading.test_pickle #150260

[colesbury]

Disable the test for now?

[vstinner]

When the bug occurs, a (at least one?) Python dumper() thread is calling pickle.dumps(shared):

• _pickle_dumps() -> _pickle_dumps_impl() -> dump() -> save() -> save_dict() -> batch_dict_exact()

The problem is that batch_dict_exact() is stuck in a loop, it keeps writing into memory and grows its buffer in an unlimited loop.

The loop in gdb:

(gdb) next
3489	        if (dict_size - total == 1) {
(gdb) next
3518	        if (_Pickler_Write(self, &mark_op, 1) < 0)
(gdb) next
3522	            Py_BEGIN_CRITICAL_SECTION(obj);
(gdb) next
3523	            next = PyDict_Next(obj, &ppos, &key, &value);
(gdb) next
3524	            if (next) {
(gdb) next
3528	            Py_END_CRITICAL_SECTION();
(gdb) next
3529	            if (!next) {
(gdb) next
3545	        if (_Pickler_Write(self, &setitems_op, 1) < 0)
(gdb) next
3547	        if (PyDict_GET_SIZE(obj) != dict_size) {
(gdb) next
3554	    } while (total < dict_size);
(gdb) next
(...)

At each iteration, next is false: PyDict_Next() exhausted the dictionary iterator, but the loop continue since the (total < dict_size) condition is false.

Variables:

• ppos = 114
• total = 47
• dict_size = 50

The code makes the assumption that PyDict_Next() iterates exactly 50 times if a dictionary has 50 entries.

Problem: Py_BEGIN_CRITICAL_SECTION(obj); and Py_END_CRITICAL_SECTION(); is put around a single PyDict_Next() call, whereas the PyDict_Next() documentation recommends putting the whole loop in the critical section.

[vstinner]

Disable the test for now?

I wanted to analyze the root cause first: it's now done, it's a race condition in pickle.dumps(dict) (see my previous comment).

I created PR gh-150260 to skip the test.

[colesbury]

Oh, well if you've already found the bug we can just fix it. I thought it would take longer to figure out the root cause!

[vstinner]

The root cause is a regression introduced by PR gh-150025. I proposed to revert the change: #150025 (comment).