Debugging race condition that was actually a lifetime bug
I had some random crashes recently, shortly after some memory usage rework that fixed an apparent memory leak.
QThread: Destroyed while thread is still running
I wasn't sure exactly what caused these. It looked like a race condition at first.
Maybe I was clearing something too soon?
The crash seemed random. Sometimes Koi would run for days with mixed use before crashing.
So I made garbage collection much more aggressive.
import gc
gc.set_threshold(50, 5, 5)
I also added forced garbage collection at seemingly critical places:
gc.collect()
This eventually made the crash reproducible:
- Start Koi
- Open another window with an empty buffer
- Open a large file in the second window, then close it relatively quickly, before indexing finishes.
- Close the first window
QThread: Destroyed while thread is still running
Great. Now I just needed to know which thread.
I gave every indexer thread a unique name:
self._thread.setObjectName(f"IndexerController-{id(self):x}")
print(
"INDEXER CREATE",
f"controller={id(self):x}",
f"thread={id(self._thread):x}",
f"parent={id(parent):x}" if parent else None,
)
And logged when each one was stopped:
print(
"INDEXER STOP",
thread.objectName(),
"running=", thread.isRunning(),
)
...
print(
"INDEXER STOPPED",
thread.objectName(),
"running=", thread.isRunning(),
)
This gives a nice chronological list of created and stopped threads.
Following the reproduction steps, closing the second window showed:
EditorContainer 488 EditorContainer : _shutdown_threads
INDEXER STOP IndexerController-13695ddb0 running=True
INDEXER STOPPED IndexerController-13695ddb0 running=False
Closing the first window and the app showed:
EditorContainer 600 EditorContainer : _shutdown_threads
INDEXER STOP IndexerController-117162670 running=True
INDEXER STOPPED IndexerController-117162670 running=False
...
EditorWindow 168 EditorWindow : _shutdown_window_threads
QThread: Destroyed while thread 'IndexerController-13411aa30' is still running
What the +f+ is thread 13411aa30?
I can see 13695ddb0 and 117162670 being stopped correctly, but not 13411aa30.
Then it hit me.
The indexer shutdown code wasn't the problem.
Some time ago I changed Koi so opening or dropping a file into a new empty window replaces the empty placeholder buffer. Mostly a convenience feature, and probably implemented late at night.
Looking at that code again:
self.open_buffers.remove(buffer_to_remove)
...
target_container.setParent(None)
What is this slop-code? I should fire myself.
I'm removing the placeholder EditorContainer from the list of open buffers and then explicitly unparenting it.
But I'm not actually closing it.
That container has its own IndexerController, and the indexer has a running QThread.
This will be garbage collected at some point, and then attempt to close the still running indexer thread attached to this removed buffer.
So the crash wasn't really a race condition. It was a lifetime bug with delayed destruction.
How is this related to the recent memory leak fix?
The previous unparented indexer had likely hidden this bug. The removed buffer could be garbage collected without taking the still-running indexer with it.
After fixing the memory leak, I changed the indexer back to being parented by the EditorContainer.
Parenting the indexer exposed the actual problem: the buffer was being removed, but never properly closed.
All blog posts