Observing lock contention

Debugging Tools, Geek Speak, Lock Explorer

The deadlock detection tool that I was working on last week is coming on nicely. I managed to locate two potential deadlocks that had never caused any problems in code that is running live on a client’s site. Once I had a report from my tool it was relatively easy to fix the problems. Both of these were real bugs that just hadn’t bitten yet.

Today I added some rudimentary lock contention monitoring to the tool and the results seem to be quite useful…

Note: the deadlock detector mentioned in this blog post is now available for download from www.lockexplorer.com.

The lock contention output is similar to the deadlock detection output. A series of reports for each lock that suffered from contention during the program run. Each report displays the thread that blocked, the location that it blocked at and the thread that owned the lock at the time and where it acquired it.

Thread: 692 blocked @ 705 by thread: 4404 @ 772 12 times
Location: 705
MTSCSS - I:\Win32Tools\CriticalSection.cpp: 99 - JetByteTools::Win32::CCriticalSection::Owner::Owner
MTSCSS - I:\IOTools\BufferAllocator.cpp: 119 - JetByteTools::IO::CBufferAllocator::Release
MTSCSS - I:\IOTools\Buffer.cpp: 266 - JetByteTools::IO::CBuffer::Release
MTSCSS - I:\SocketTools\AsyncSocketConnectionManager.cpp: 411 - JetByteTools::Socket::CAsyncSocketConnectionManager::HandleOperation
MTSCSS - I:\SocketTools\AsyncSocket.cpp: 583 - JetByteTools::Socket::CAsyncSocket::HandleOperation
MTSCSS - I:\IOTools\IOPool.cpp: 224 - JetByteTools::IO::CIOPool::WorkerThread::Run
MTSCSS - I:\Win32Tools\Thread.cpp: 149 - JetByteTools::Win32::CThread::ThreadFunction
MTSCSS - : 0 - __beginthreadex
---
Location: 772
MTSCSS - I:\Win32Tools\CriticalSection.cpp: 99 - JetByteTools::Win32::CCriticalSection::Owner::Owner
MTSCSS - I:\IOTools\BufferAllocator.cpp: 80 - JetByteTools::IO::CBufferAllocator::Allocate
MTSCSS - I:\SocketTools\AsyncSocketConnectionManager.cpp: 199 - JetByteTools::Socket::CAsyncSocketConnectionManager::AllocateBuffer
MTSCSS - I:\SocketTools\AsyncSocketConnectionManager.cpp: 244 - JetByteTools::Socket::CAsyncSocketConnectionManager::PostFilteredReadRequest
MTSCSS - I:\OpenSSLTools\AsyncSocketConnectionManager.cpp: 248 - JetByteTools::OpenSSL::CAsyncSocketConnectionManager::FilterReadCompleted
MTSCSS - I:\SocketTools\AsyncSocket.cpp: 583 - JetByteTools::Socket::CAsyncSocket::HandleOperation
MTSCSS - I:\IOTools\IOPool.cpp: 224 - JetByteTools::IO::CIOPool::WorkerThread::Run
MTSCSS - I:\Win32Tools\Thread.cpp: 149 - JetByteTools::Win32::CThread::ThreadFunction
MTSCSS - : 0 - __beginthreadex
---

The value of this report is less immediate; I can’t just leap into the code and fix the problem, but I still think it’s useful. Well, it is as long as the act of monitoring isn’t perturbing the results too much…