test__xxsubinterpreters is Occasionally Crashing

[ericsnowcurrently]

This appears to have started once gh-104210 was merged.

"Fatal Python error: drop_gil: PyMUTEX_LOCK(gil->switch_mutex) failed"

It may be specific to test.test__xxsubinterpreters.RunStringTests.test_create_thread.

See:

• https://buildbot.python.org/all/#builders/484/builds/3261
• GH-104308: socket.getnameinfo should release the GIL #104307 (comment)

Linked PRs

• gh-104341: Ensure tstate Holding GIL is Always Current #104436
• gh-104341: Adjust tstate_must_exit() to Respect Interpreter Finalization #104437
• gh-104341: Clean Up threading Module #104552
• gh-104341: Fix threading Module Shutdown #104560
• gh-104341: Minor Fixes in the _thread Module #104595
• gh-104341: Wait Completely at threading._shutdown() #104672
• [reverted] gh-104341: Add a Separate "Running" Lock for Each Thread #104754
• [3.12] gh-104341: Add a Separate "Running" Lock for Each Thread (gh-104754) #104817
• gh-104341: Call _PyEval_ReleaseLock() with NULL When Finalizing the Current Thread #105109
• [3.12] gh-104341: Call _PyEval_ReleaseLock() with NULL When Finalizing the Current Thread (gh-105109) #105209

[ericsnowcurrently]

CC @brandtbucher

[ericsnowcurrently]

I've been able to reproduce the crash locally with ./python -m test -j8 test__xxsubinterpreters --forever

[brandtbucher]

Core was generated by `./python -m test --forever test__xxsubinterpreters -m test_create_thread'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  raise (sig=sig@entry=11) at ../sysdeps/unix/sysv/linux/raise.c:50
50      ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
[Current thread is 1 (Thread 0x7f44daa8a700 (LWP 23889))]
(gdb) bt
#0  raise (sig=sig@entry=11) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x000055d7555a0d94 in faulthandler_fatal_error (signum=11) at ./Modules/faulthandler.c:330
#2  <signal handler called>
#3  drop_gil (ceval=0x7f44dae104d8, tstate=tstate@entry=0x55d756081200) at Python/ceval_gil.c:301
#4  0x000055d75552fad5 in _PyEval_ReleaseLock (tstate=tstate@entry=0x55d756081200) at Python/ceval_gil.c:629
#5  0x000055d75556a9bd in _PyThreadState_DeleteCurrent (tstate=tstate@entry=0x55d756081200) at Python/pystate.c:1568
#6  0x000055d755615cb8 in thread_run (boot_raw=boot_raw@entry=0x7f44dab23790) at ./Modules/_threadmodule.c:1097
#7  0x000055d755587672 in pythread_wrapper (arg=<optimized out>) at Python/thread_pthread.h:233
#8  0x00007f44dc5af609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#9  0x00007f44dc37c293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

[brandtbucher]

Also when running test_threads_join and test_threads_join_2 in test_threading with the same flags.

[ericsnowcurrently]

I think I've got this figured out. It looks like the interpreter is getting finalized before the thread is completely done in thread_run() (in _threadmodule.c). Apparently the thread isn't completely finalized at the point thread.join() returns. Thus there's a small race there where the runtime may think the thread is done running. It proceeds to clean up the thread state even though the thread is still cleaning itself up.

Based on the above, there are two points at which it should have waited:

• thread.join()
• wait_for_thread_shutdown() via Py_EndInterpreter() (in pylifecycle.c)

I'm going to figure out why things didn't wait properly. I suspect it looks something like this:

1. the sub-thread finishes
2. it "marks" itself as done
3. it releases the subinterpreter GIL
4. the subinterpreter's initial thread acquires the GIL
5. it finishes running
6. it releases its GIL
7. the sub-thread acquires the subinterpreter GIL
8. it finishes cleaning up its thread state
9. the main interpreter starts running again (with its own GIL)
10. it calls Py_EndInterpreter()
11. the thread is already off the "known threads" list so it doesn't wait there
12. it clears/frees the subinterpreter's remaining thread states and then the subinterpreter itself

The race lies between steps (8) and (12). If (8) doesn't finish before (12) happens then we'd see the crash we're seeing.

What I don't understand is:

• what do we need to do differently in step (2)?
• when is step (3) happening?

To be honest, I still haven't figured out what we are actually doing in (2) such that it affects thread.join() and wait_for_thread_shutdown(). However that may be irrelevant. I suspect we are missing a step before (9) where we acquire the subinterpreter's GIL while we're cleaning things up in Py_EndInterpreter().

FYI, this doesn't happen when the GIL is shared because (9) is blocked by the GIL being held still in the sub-thread.

[ericsnowcurrently]

This may also be related to (or a variant of) gh-96387.

[ericsnowcurrently]

Hmm, looks like I need to add _PyInterpreterState_GetFinalizing(), etc. and use it in tstate_must_exit() (in ceval_gil.c).

[ericsnowcurrently]

FYI, the two fixes I have up for review don't solve the crashes yet, but I'm getting closer.

[ericsnowcurrently]

Currently here's where things are at:

1. when the sub-thread in test_create_thread() finishes, thread_run() (in _threadmodule.c) starts cleaning up
2. the last thing it does is call _PyThreadState_DeleteCurrent() (pystate.c), which calls _PyEval_ReleaseLock() (ceval_gil.c)
3. that turns into drop_gil() (ceval_gil.c), where everything goes smoothly, until...
4. MUTEX_UNLOCK(gil->mutex); successfully releases the lock, but often gets stuck when there are many processes running the test
5. it finally unblocks at some point during the call in Py_EndInterpreter() (pylifecycle.c), where the main interpreter is destroying the subinterpreter, likely around the point the subinterpreter's GIL is destoyed
6. drop_gil() subsequently blows up because the thread state is no longer valid

Here's a detailed breakdown of execution:

(expand)

Fatal Python error: Segmentation fault

Thread 0x00007fec567fc700 (most recent call first):
  File "/home/esnow/projects/work/cpython-perf/cpython/Lib/subprocess.py", line 1971 in _try_wait
  File "/home/esnow/projects/work/cpython-perf/cpython/Lib/subprocess.py", line 2013 in _wait
  File "/home/esnow/projects/work/cpython-perf/cpython/Lib/subprocess.py", line 1262 in wait
  File "/home/esnow/projects/work/cpython-perf/cpython/Lib/test/libregrtest/runtest_mp.py", line 241 in _run_process
  File "/home/esnow/projects/work/cpython-perf/cpython/Lib/test/libregrtest/runtest_mp.py", line 293 in _runtest
  File "/home/esnow/projects/work/cpython-perf/cpython/Lib/test/libregrtest/runtest_mp.py", line 342 in run
  File "/home/esnow/projects/work/cpython-perf/cpython/Lib/threading.py", line 1056 in _bootstrap_inner
  File "/home/esnow/projects/work/cpython-perf/cpython/Lib/threading.py", line 1013 in _bootstrap

0:00:00 load avg: 0.29 [  1/1] test__xxsubinterpreters crashed (Exit code -11)
Thread 0x00007fec56ffd700 (most recent call first):
  File "/home/esnow/projects/work/cpython-perf/cpython/Lib/subprocess.py ", line 1971 in _try_wait
  File "/home/esnow/projects/work/cpython-perf/cpython/Lib/subprocess.py", line 2013 in _wait
  File "/home/esnow/projects/work/cpython-perf/cpython/Lib/subprocess.py", line 1262 in wait

   28237 drop_gil                       ts:0x561957657b40 (cur:0x561957657b40) - is:0x5619575f9660 gil:0x561957657a70 <entered>
   28237 drop_gil                       ts:0x561957657b40 (cur:0x561957657b40) - is:0x5619575f9660 gil:0x561957657a70 starting
   28237 drop_gil                       ts:0x561957657b40 (cur:0x561957657b40) - is:0x5619575f9660 gil:0x561957657a70 done
   28237 drop_gil                       ts:0x561957657b40 (cur:0x561957657b40) - is:0x5619575f9660 gil:0x561957657a70 returning
   28237 take_gil                       ts:0x561957657b40 (cur:0x561957657b40) - is:0x5619575f9660 gil:0x561957657a70 <entered>
   28237 take_gil                       ts:0x561957657b40 (cur:0x561957657b40) - is:0x5619575f9660 gil:0x561957657a70 acquired mutex
   28237 take_gil                       ts:0x561957657b40 (cur:0x561957657b40) - is:0x5619575f9660 gil:0x561957657a70 aquired (locked)
   28237 take_gil                       ts:0x561957657b40 (cur:0x561957657b40) - is:0x5619575f9660 gil:0x561957657a70 released mutex
   28237 drop_gil                       ts:0x561957657b40 (cur:0x561957657b40) - is:0x5619575f9660 gil:0x561957657a70 <entered>
   28237 drop_gil                       ts:0x561957657b40 (cur:0x561957657b40) - is:0x5619575f9660 gil:0x561957657a70 starting
   28237 drop_gil                       ts:0x561957657b40 (cur:0x561957657b40) - is:0x5619575f9660 gil:0x561957657a70 done
   28237 drop_gil                       ts:0x561957657b40 (cur:0x561957657b40) - is:0x5619575f9660 gil:0x561957657a70 returning

############################################

28247 starting test
1
2
28247 running script
28247 starting thread
   28247 thread_run               XXXXX ts:0x55d128cf2f00 (cur:(nil)) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 thread_run               XXXXX ts:0x55d128cf2f00 (cur:(nil)) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquiring GIL
   28247 take_gil                 XXXXX ts:0x55d128cf2f00 (cur:0x55d128cf2f00) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 take_gil                 XXXXX ts:0x55d128cf2f00 (cur:0x55d128cf2f00) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 take_gil                 XXXXX ts:0x55d128cf2f00 (cur:0x55d128cf2f00) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (locked)
   28247 take_gil                 XXXXX ts:0x55d128cf2f00 (cur:0x55d128cf2f00) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (last holder)
   28247 take_gil                 XXXXX ts:0x55d128cf2f00 (cur:0x55d128cf2f00) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released mutex
   28247 thread_run               XXXXX ts:0x55d128cf2f00 (cur:0x55d128cf2f00) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired GIL
   28247 thread_run               XXXXX ts:0x55d128cf2f00 (cur:0x55d128cf2f00) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 about to run
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 thread_run               XXXXX ts:0x55d128cf2f00 (cur:0x55d128cf2f00) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 finishing
   28247 thread_run               XXXXX ts:0x55d128cf2f00 (cur:0x55d128cf2f00) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 almost done
   28247 _PyThreadState_DeleteCurrent X ts:0x55d128cf2f00 (cur:0x55d128cf2f00) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 _PyThreadState_DeleteCurrent X ts:0x55d128cf2f00 (cur:0x55d128cf2f00) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 releasing GIL
   28247 drop_gil                 XXXXX ts:0x55d128cf2f00 (cur:0x55d128cf2f00) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 drop_gil                 XXXXX ts:0x55d128cf2f00 (cur:0x55d128cf2f00) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 starting
   28247 drop_gil                 XXXXX ts:0x55d128cf2f00 (cur:0x55d128cf2f00) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 drop_gil                 XXXXX ts:0x55d128cf2f00 (cur:0x55d128cf2f00) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 locked = 1
   28247 drop_gil                 XXXXX ts:0x55d128cf2f00 (cur:0x55d128cf2f00) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 signaled cond
          ================= should unlock mutex here ==================
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released/acquired mutex
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (locked)
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (last holder)
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released mutex
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 starting
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 done
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 returning
28247 joining
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (locked)
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released mutex
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 starting
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 done
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 returning
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (locked)
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released mutex
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 starting
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 done
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 returning
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (locked)
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released mutex
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 starting
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 done
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 returning
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (locked)
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released mutex
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 starting
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 done
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 returning
28247 joined
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (locked)
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released mutex
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 starting
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 done
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 returning
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (locked)
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released mutex
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 starting
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 done
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 returning
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (locked)
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released mutex
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 starting
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 done
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 returning
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (locked)
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released mutex
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 starting
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 done
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 returning
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (locked)
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released mutex
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 starting
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 done
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 returning
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (locked)
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released mutex
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 starting
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 done
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 returning
28247 script finished

############################################

(decref) interpid 2 (0)
finalizing 2
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (locked)
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released mutex
   28247 Py_EndInterpreter              ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 starting
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 done
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 returning
28247 shutting down threads
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (locked)
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released mutex
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 starting
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 done
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 returning
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (locked)
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released mutex
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 starting
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 done
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 returning
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (locked)
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released mutex
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 starting
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 done
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 returning
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (locked)
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released mutex
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 starting
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 done
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 returning
28247 stopping main thread
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (locked)
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released mutex
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 starting
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 done
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 returning
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (locked)
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released mutex
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 starting
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 done
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 returning
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (locked)
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released mutex
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 starting
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 done
   28247 drop_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 returning
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 <entered>
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 acquired mutex
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 aquired (locked)
   28247 take_gil                       ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released mutex
   28247 Py_EndInterpreter              ts:0x7f69e1a6a500 (cur:0x7f69e1a6a500) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 clearing subinterpreter
   28247 drop_gil                 XXXXX ts:0x55d128cf2f00 (cur:0x55d128cf2f00) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 done
   28247 drop_gil                 XXXXX ts:0x55d128cf2f00 (cur:0x55d128cf2f00) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 returning
   28247 _PyThreadState_DeleteCurrent X ts:0x55d128cf2f00 (cur:0x55d128cf2f00) - is:0x7f69e1a0c020 gil:0x7f69e1a6a430 released GIL
Fatal Python error: Segmentation fault