test_abc hangs on TSan Parallel Test on Free Threading

[vstinner]

Bug report

Job: https://github.com/python/cpython/actions/runs/27618576478/job/81660859608?pr=151486

Python built with ./configure --config-cache --with-thread-sanitizer --with-pydebug --disable-gil.

Test logs:

Run ./python -m test --tsan-parallel --parallel-threads=4 -j4 -W
Using random seed: 2157163694
0:00:00 load avg: 2.93 mem: 274.0 MiB Run 2 tests in parallel using 2 worker processes
0:00:12 load avg: 3.10 mem: 591.6 MiB [1/2] test_hashlib passed
0:00:42 load avg: 1.88 mem: 591.6 MiB running (1): test_abc (42.3 sec)
0:01:13 load avg: 1.14 mem: 591.7 MiB running (1): test_abc (1 min 12 sec)
0:01:43 load avg: 0.69 mem: 591.7 MiB running (1): test_abc (1 min 42 sec)
0:02:13 load avg: 0.42 mem: 591.7 MiB running (1): test_abc (2 min 13 sec)
...
0:35:59 load avg: 0.03 mem: 533.8 MiB running (1): test_abc (35 min 59 sec)
0:36:29 load avg: 0.02 mem: 533.8 MiB running (1): test_abc (36 min 29 sec)
0:37:00 load avg: 0.01 mem: 533.8 MiB running (1): test_abc (36 min 59 sec)
Error: The operation was canceled.

Linked PRs

• gh-151593: Use timeout on GitHub Action TSan job #151594
• [3.15] gh-151593: Use timeout on GitHub Action TSan jobs (GH-151594) #151597
• [3.14] gh-151593: Use timeout on GitHub Action TSan jobs (GH-151594) #151598
• gh-151593: Avoid deadlock in insert_split_key(). #152133
• Temporarily allow the TSan (free-threading) job to fail #152173
• gh-151593: Fix dead lock in PyDict insert_split_key() #152200
• gh-152238: Revert gh-150490 and gh-152200. #152232

[vstinner]

When the test doesn't hang, the whole command takes 14.1 seconds: https://github.com/python/cpython/actions/runs/27677669151/job/81856939320

./python -m test --tsan-parallel --parallel-threads=4 -j4 -W

Using random seed: 3376840650
0:00:00 load avg: 2.57 mem: 273.5 MiB Run 2 tests in parallel using 2 worker processes
0:00:07 load avg: 2.53 mem: 659.9 MiB [1/2] test_abc passed
0:00:14 load avg: 2.91 mem: 293.7 MiB [2/2] test_hashlib passed

== Tests result: SUCCESS ==

All 2 tests OK.

Total duration: 14.1 sec
Total tests: run=160 skipped=56
Total test files: run=2/2
Result: SUCCESS

[vstinner]

Aha, using my PR adding timeouts, I managed to get traceback where test_abc hangs:

0:08:47 load avg: 0.02 mem: 486.4 MiB running (1): test_abc (8 min 47 sec)
0:09:17 load avg: 0.01 mem: 486.5 MiB running (1): test_abc (9 min 17 sec)
0:09:47 load avg: 0.01 mem: 486.5 MiB running (1): test_abc (9 min 47 sec)
0:10:03 load avg: 0.08 mem: 253.9 MiB [2/2/1] test_abc worker non-zero exit code (Exit code 1)
test_positional_only_and_kwonlyargs_with_init_subclass (test.test_abc.test_factory.<locals>.TestABCWithInitSubclass.test_positional_only_and_kwonlyargs_with_init_subclass) [threads=4] ... ok
test_works_with_init_subclass (test.test_abc.test_factory.<locals>.TestABCWithInitSubclass.test_works_with_init_subclass) [threads=4] ... ok
test_positional_only_and_kwonlyargs_with_init_subclass (test.test_abc.test_factory.<locals>.TestABCWithInitSubclass.test_positional_only_and_kwonlyargs_with_init_subclass) ... ok
test_works_with_init_subclass (test.test_abc.test_factory.<locals>.TestABCWithInitSubclass.test_works_with_init_subclass) ... ok
test_ABC_has___slots__ (test.test_abc.test_factory.<locals>.TestABC.test_ABC_has___slots__) [threads=4] ... ok
test_ABC_helper (test.test_abc.test_factory.<locals>.TestABC.test_ABC_helper) [threads=4] ... ok
test_abstractclassmethod_basics (test.test_abc.test_factory.<locals>.TestABC.test_abstractclassmethod_basics) [threads=4] ... ok
test_abstractmethod_basics (test.test_abc.test_factory.<locals>.TestABC.test_abstractmethod_basics) [threads=4] ... ok
test_abstractmethod_integration (test.test_abc.test_factory.<locals>.TestABC.test_abstractmethod_integration) [threads=4] ...

Timeout (0:10:00)!
Thread 0x00007fb4767ff6c0 [test_abstractme] (most recent call first):
  File "/home/runner/work/cpython/cpython/Lib/abc.py", line 102 in __init__
  File "/home/runner/work/cpython/cpython/Lib/test/test_abc.py", line 207 in C
  File "/home/runner/work/cpython/cpython/Lib/test/test_abc.py", line 206 in test_abstractmethod_integration
  File "/home/runner/work/cpython/cpython/Lib/contextlib.py", line 116 in inner
  File "/home/runner/work/cpython/cpython/Lib/unittest/case.py", line 637 in _callTestMethod
  File "/home/runner/work/cpython/cpython/Lib/unittest/case.py", line 691 in run
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/parallel_case.py", line 23 in run_worker
  File "/home/runner/work/cpython/cpython/Lib/threading.py", line 1160 in run
  File "/home/runner/work/cpython/cpython/Lib/threading.py", line 1218 in _bootstrap_inner
  File "/home/runner/work/cpython/cpython/Lib/threading.py", line 1180 in _bootstrap

Thread 0x00007fb4789ff6c0 [test_abstractme] (most recent call first):
  File "/home/runner/work/cpython/cpython/Lib/abc.py", line 102 in __init__
  File "/home/runner/work/cpython/cpython/Lib/test/test_abc.py", line 207 in C
  File "/home/runner/work/cpython/cpython/Lib/test/test_abc.py", line 206 in test_abstractmethod_integration
  File "/home/runner/work/cpython/cpython/Lib/contextlib.py", line 116 in inner
  File "/home/runner/work/cpython/cpython/Lib/unittest/case.py", line 637 in _callTestMethod
  File "/home/runner/work/cpython/cpython/Lib/unittest/case.py", line 691 in run
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/parallel_case.py", line 23 in run_worker
  File "/home/runner/work/cpython/cpython/Lib/threading.py", line 1160 in run
  File "/home/runner/work/cpython/cpython/Lib/threading.py", line 1218 in _bootstrap_inner
  File "/home/runner/work/cpython/cpython/Lib/threading.py", line 1180 in _bootstrap

Thread 0x00007fb47adff6c0 [test_abstractme] (most recent call first):
  File "/home/runner/work/cpython/cpython/Lib/abc.py", line 128 in __new__
  File "/home/runner/work/cpython/cpython/Lib/test/test_abc.py", line 223 in test_abstractmethod_integration
  File "/home/runner/work/cpython/cpython/Lib/contextlib.py", line 116 in inner
  File "/home/runner/work/cpython/cpython/Lib/unittest/case.py", line 637 in _callTestMethod
  File "/home/runner/work/cpython/cpython/Lib/unittest/case.py", line 691 in run
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/parallel_case.py", line 23 in run_worker
  File "/home/runner/work/cpython/cpython/Lib/threading.py", line 1160 in run
  File "/home/runner/work/cpython/cpython/Lib/threading.py", line 1218 in _bootstrap_inner
  File "/home/runner/work/cpython/cpython/Lib/threading.py", line 1180 in _bootstrap

Thread 0x00007fb479dfe6c0 [test_abstractme] (most recent call first):
  File "/home/runner/work/cpython/cpython/Lib/traceback.py", line 316 in clear_frames
  File "/home/runner/work/cpython/cpython/Lib/unittest/case.py", line 272 in __exit__
  File "/home/runner/work/cpython/cpython/Lib/unittest/case.py", line 244 in handle
  File "/home/runner/work/cpython/cpython/Lib/unittest/case.py", line 835 in assertRaises
  File "/home/runner/work/cpython/cpython/Lib/test/test_abc.py", line 227 in test_abstractmethod_integration
  File "/home/runner/work/cpython/cpython/Lib/contextlib.py", line 116 in inner
  File "/home/runner/work/cpython/cpython/Lib/unittest/case.py", line 637 in _callTestMethod
  File "/home/runner/work/cpython/cpython/Lib/unittest/case.py", line 691 in run
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/parallel_case.py", line 23 in run_worker
  File "/home/runner/work/cpython/cpython/Lib/threading.py", line 1160 in run
  File "/home/runner/work/cpython/cpython/Lib/threading.py", line 1218 in _bootstrap_inner
  File "/home/runner/work/cpython/cpython/Lib/threading.py", line 1180 in _bootstrap

Thread 0x00007fb4d3b58f40 [python] (most recent call first):
  File "/home/runner/work/cpython/cpython/Lib/threading.py", line 1269 in join
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/parallel_case.py", line 54 in run
  File "/home/runner/work/cpython/cpython/Lib/unittest/case.py", line 747 in __call__
  File "/home/runner/work/cpython/cpython/Lib/unittest/suite.py", line 122 in run
  File "/home/runner/work/cpython/cpython/Lib/unittest/suite.py", line 84 in __call__
  File "/home/runner/work/cpython/cpython/Lib/unittest/suite.py", line 122 in run
  File "/home/runner/work/cpython/cpython/Lib/unittest/suite.py", line 84 in __call__
  File "/home/runner/work/cpython/cpython/Lib/unittest/runner.py", line 256 in run
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/single.py", line 84 in _run_suite
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/single.py", line 42 in run_unittest
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/single.py", line 162 in test_func
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/single.py", line 118 in regrtest_runner
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/single.py", line 165 in _load_run_test
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/single.py", line 210 in _runtest_env_changed_exc
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/single.py", line 319 in _runtest
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/single.py", line 348 in run_single_test
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/worker.py", line 99 in worker_process
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/worker.py", line 137 in main
  File "/home/runner/work/cpython/cpython/Lib/test/libregrtest/worker.py", line 141 in <module>
  File "/home/runner/work/cpython/cpython/Lib/runpy.py", line 87 in _run_code
  File "/home/runner/work/cpython/cpython/Lib/runpy.py", line 201 in _run_module_as_main
== Tests result: FAILURE ==

[vstinner]

I'm able to reproduce the issue on my Fedora 44 laptop.

• Python built with ./configure --cache-file=../python-config.cache --with-pydebug --with-system-expat --with-thread-sanitizer --disable-gil

For example, test_ABC_helper() of test_abc hangs.

• Thread 40 waits for _PyEval_StopTheWorld().
• Thread 38 waits for _PyThreadState_Attach().
• Thread 1 waits for threads.join() (wait until tests complete)
• Thread 2 is TSan background thread.
• Other threads wait for a lock hold by another thread. For example, LOCK_KEYS(keys) calls PyMutex_LockFlags() with _Py_LOCK_DONT_DETACH.

Summary of the 12 threads:

Thread 40 (Thread 0x7fff8d7fc6c0 (LWP 897520) "test_ABC_helper"):
  Wait for _PyEval_StopTheWorld()
  Hold mutex 0xc3e1d8 -- BEGIN_TYPE_LOCK()

Thread 36 (Thread 0x7fff8c1f96c0 (LWP 897490) "test_ABC_helper"):
  Wait for BEGIN_TYPE_LOCK(), mutex 0xc3e1d8 -- hold by thread 40
  Hold mutex 0x7fffb52c1fa3
Thread 41 (Thread 0x7fff8cffb6c0 (LWP 897521) "test_ABC_helper"):
  Wait for BEGIN_TYPE_LOCK(), mutex 0xc3e1d8 -- hold by thread 40
Thread 33 (Thread 0x7fff899fe6c0 (LWP 897448) "test_ABC_helper"):
  Wait for BEGIN_TYPE_LOCK(), mutex 0xc3e1d8 -- hold by thread 40
Thread 39 (Thread 0x7fff8dffd6c0 (LWP 897519) "test_ABC_helper"):
  Wait for BEGIN_TYPE_DICT_LOCK(dict), mutex 0xc3e1d8 -- hold by thread 40
      Wait for BEGIN_TYPE_LOCK(), mutex 0xc3e1d8 -- hold by thread 40

Thread 42 (Thread 0x7fff8a1ff6c0 (LWP 897522) "test_ABC_helper"):
Thread 37 (Thread 0x7fff8efff6c0 (LWP 897492) "test_ABC_helper"):
Thread 35 (Thread 0x7fff8b5ff6c0 (LWP 897476) "test_ABC_helper"):
Thread 34 (Thread 0x7fff8adfe6c0 (LWP 897449) "test_ABC_helper"):
  Wait for LOCK_KEYS(keys), mutex 0x7fffb52c1fa3 -- hold by thread 36

Thread 38 (Thread 0x7fff8e7fe6c0 (LWP 897506) "test_ABC_helper"):
  Wait for _PyThreadState_Attach()

Thread 2 (Thread 0x7fff905ff6c0 (LWP 896899) "python"):
  TSan background thread
Thread 1 (Thread 0x7ffff7f68f40 (LWP 896428) "python"):
  Wait for threads.join()

[vstinner]

Full traceback of the 12 threads: traceback.txt.

[vstinner]

Thread 40 calls type_set_abstractmethods(), extract:

    BEGIN_TYPE_LOCK();
    type_modified_unlocked(type);
    types_stop_world();  // <========== HERE
    if (abstract)
        type_add_flags(type, Py_TPFLAGS_IS_ABSTRACT);
    else
        type_clear_flags(type, Py_TPFLAGS_IS_ABSTRACT);
    types_start_world();
    ASSERT_TYPE_LOCK_HELD();
    END_TYPE_LOCK();

First, it acquires the type lock. Then, it calls _PyEval_StopTheWorld().

BEGIN_TYPE_LOCK() was added by commit baae9cb.

commit baae9cb159e240ee9474ce7c02f88c233390777a
Author: Neil Schemenauer <nas-github@arctrix.com>
Date:   Tue Feb 25 21:24:20 2025 -0800

    gh-117657: Use an atomic store to set type flags. (gh-127588)
    
    The `PyType_HasFeature()` function reads the flags with a relaxed atomic
    load and without holding the type lock.  To avoid data races, use atomic
    stores if `PyType_Ready()` has already been called.

types_stop_world() was added by commit fbbbc10:

commit fbbbc10055e0ee0011cf683132be706815480839
Author: Neil Schemenauer <nas-github@arctrix.com>
Date:   Tue May 27 18:27:41 2025 -0700

    gh-127266: avoid data races when updating type slots (gh-133177)
    
    In the free-threaded build, avoid data races caused by updating type
    slots or type flags after the type was initially created.  For those
    (typically rare) cases, use the stop-the-world mechanism.  Remove the
    use of atomics when reading or writing type flags.