How to Find a Missing _Release

For quite some time, thread pool in OmniThreadLibrary had a weird problem – if you scheduled more than 80 tasks in one go, FastMM would report memory leaks when application was terminated. It bothered me, of course, but I could never find the real reason behind the problem. And so I left the code “as is” and said to myself that nobody would encounter it in practice, anyway.

And then Žarko came and wrote about me on his blog :( In case you are living in a dark cave and didn’t hear of him – Žarko runs immensely popular Delphi site at About.com. His testing (and most of all his highly reproducible test case) gave me a new energy to pursue the problem.

The reason for the memory leak was a reference count leak in TOmniInterfaceDictionary, which is now fixed in the SVN. I also found some very tricky race conditions in TOmniTask.Execute and TOmniTask.Terminate and a cause for weird "A call to an OS function failed" error in DispatchEvent. All in all, I had two very productive bug-hunting nights. But that’s not why I started writing this article. I wanted to tell you a debugging story titled “How to find a missing Release.”

I started at the end. Žarko’s test case produced (at least on some computers) a leak report which clearly stated that the background task worker, TOmniWorker, did not always get released, so I started with that and checked the reference count of the TOmniWorker objects after the thread pool was finished with them. [Almost all internals in OmniThreadLibrary are interface-based. That simplified the development a lot but also complicated problem finding. Still, I  believe that it was a good choice to take.] And behold! – only last ten-and-something (this happened two weeks ago and I’m now recreating it from my faulty memory) had proper reference count at this point, first (let’s say) 60 had reference count that was too large. It was off just by one, but that was enough – task was not released when it should have been.

I then spent quite some time measuring reference count at different points in the task’s execution. All to no avail – reference count was fine as far as I could trace the progress into the OTL innards, but when the task should be released, it was not fine anymore.

Again, I was lost, but then I remembered a little used function in the Delphi debugger – namely that it can log call stack that led to the execution of the current line. [Oh how I wish that I could also access this call stack with a RTL call!]

Then I wrote my own reference counting methods (_AddRef and _Release) in the TOmniTask class and put a breakpoint in both methods. Breakpoint was set to not break, to log the current value of the Result pseudo-variable and to log the call stack.

Breakpoint was put on a code branch that would only be executed if I turned on a special flag variable. This way, most TOmniTask objects were not logged, but I could selectively log refcount changes for two tasks – the first one (which I knew will not be destroyed properly) and the last one (which I knew that will be destroyed).

When the program terminated, I was left with a very long Event Log, full of debugger entries:

Breakpoint Call Stack: Log 10 stack frames Process app_11_ThreadPool.exe (7828)
    OtlTaskControl.TOmniTask._AddRef
    System._IntfAddRef(???)
    OtlTaskControl.TOmniThread.Create(TOmniTask($1F4C490) as IOmniTask)
    OtlTaskControl.TOmniTaskControl.Run
    OtlThreadPool.TOmniThreadPool.Create('GlobalOmniThreadPool')
    OtlThreadPool.CreateThreadPool('GlobalOmniThreadPool')
    OtlThreadPool.GlobalOmniThreadPool
    test_11_ThreadPool.TfrmTestOtlThreadPool.FormCreate($1ED4320)
    Forms.TCustomForm.DoCreate
    Forms.TCustomForm.AfterConstruction
Breakpoint Expression Result: 2

Breakpoint Call Stack: Log 10 stack frames Process app_11_ThreadPool.exe (7828)
    OtlTaskControl.TOmniTask._AddRef
    System._IntfCopy(???,???)
    :00409d98 @IntfCopy + $C
    OtlTaskControl.TOmniTaskControl.Run
    OtlThreadPool.TOmniThreadPool.Create(???)
    OtlThreadPool.CreateThreadPool('GlobalOmniThreadPool')
    OtlThreadPool.GlobalOmniThreadPool
    test_11_ThreadPool.TfrmTestOtlThreadPool.FormCreate($1ED4320)
    Forms.TCustomForm.DoCreate
    Forms.TCustomForm.AfterConstruction
Breakpoint Expression Result: 3

Breakpoint Call Stack: Log 10 stack frames Process app_11_ThreadPool.exe (7828)
    OtlTaskControl.TOmniTask._Release
    System._IntfClear(???)
    :00409d87 @IntfClear + $13
    OtlTaskControl.TOmniTaskControl.Run
    OtlThreadPool.TOmniThreadPool.Create(???)
    OtlThreadPool.CreateThreadPool('GlobalOmniThreadPool')
    OtlThreadPool.GlobalOmniThreadPool
    test_11_ThreadPool.TfrmTestOtlThreadPool.FormCreate($1ED4320)
    Forms.TCustomForm.DoCreate
    Forms.TCustomForm.AfterConstruction
Breakpoint Expression Result: 2

Then I separated this output into two refcount logs – one for the first task and one for the last (during which I wished I had also logged a Self address which would make my work much simpler) and at the end I compared both logs in two Notepads, opened side by side.

And there it was – a call to TOmniInterfaceDictionary.Resize that was present only in one log and which incremented refcount by one. :(

The rest of my evening was simple – write some unit tests, fix the Resize (and two other places in TOmniInterfaceDictionary where I messed things up) and finally the thread pool was working fine!

The moral of the story? Unit tests are good (but I’m still not writing them on a regular basis – no way!). Reference counting produces hard to find bugs (but I’m still using it). Delphi offers powerful debugging capabilities (but I would like to have more). And the most important of all – open source code is great, because other people can find bugs and write reproducible tests! :)