Viewing lock lifetimes

Debugging Tools, Geek Speak, Lock Explorer

I added some more monitoring to the deadlock tool. You can now view the entire life cycle of the locks, from initialisation, through usage to destruction. The lock usage figures put the contention figures in context as you can see how often the lock was acquired by each thread and compare that to how often there was contention…

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

Lock usage for: 0x0012fbe8
Initialised
 by thread: 4500 @ 601
Location: 601
MTSCSS - I:\JetByteTools\Win32Tools\ThreadedCallbackTimerQueue.cpp: 56 - Win32::CThreadedCallbackTimerQueue::CThreadedCallbackTimerQueue
MTSCSS - I:\MTSCSS\ServerMain.cpp: 302 - ServerMain
MTSCSS - I:\MTSCSS\ServerMain.cpp: 651 - wWinMain
MTSCSS - _wWinMainCRTStartup

Locked
 by thread: 2740 @ 603 41 times
 by thread: 4960 @ 691 17 times
 by thread: 5880 @ 772 13 times
 by thread: 6020 @ 932 13 times

Location: 603
MTSCSS - I:\JetByteTools\Win32Tools\CriticalSection.cpp: 99 - Win32::CCriticalSection::Owner::Owner
MTSCSS - I:\JetByteTools\Win32Tools\ThreadedCallbackTimerQueue.cpp: 152 - Win32::CThreadedCallbackTimerQueue::GetNextTimeout
MTSCSS - I:\JetByteTools\Win32Tools\ThreadedCallbackTimerQueue.cpp: 133 - Win32::CThreadedCallbackTimerQueue::Run
MTSCSS - I:\JetByteTools\Win32Tools\Thread.cpp: 149 - Win32::CThread::ThreadFunction
MTSCSS - __beginthreadex

Location: 691
MTSCSS - I:\JetByteTools\Win32Tools\CriticalSection.cpp: 99 - Win32::CCriticalSection::Owner::Owner
MTSCSS - I:\JetByteTools\Win32Tools\ThreadedCallbackTimerQueue.cpp: 77 - Win32::CThreadedCallbackTimerQueue::CreateTimer
MTSCSS - I:\MTSCSS\ProtocolHandler.cpp: 102 - CProtocolHandler::CProtocolHandler
MTSCSS - Socket::CAsyncSocket::`vftable'
MTSCSS - I:\JetByteTools\SocketTools\AsyncSocket.cpp: 410 - Socket::CAsyncSocket::Read

Location: 772
MTSCSS - I:\JetByteTools\Win32Tools\CriticalSection.cpp: 99 - Win32::CCriticalSection::Owner::Owner
MTSCSS - I:\JetByteTools\Win32Tools\ThreadedCallbackTimerQueue.cpp: 100 - Win32::CThreadedCallbackTimerQueue::CancelTimer
MTSCSS - I:\MTSCSS\ProtocolHandler.cpp: 109 - CProtocolHandler::~CProtocolHandler
MTSCSS - CProtocolHandler::`vftable'
MTSCSS - I:\MTSCSS\ProtocolHandler.cpp: 515 - CProtocolHandler::OnConnectionFailed

Location: 932
MTSCSS - I:\JetByteTools\Win32Tools\CriticalSection.cpp: 99 - Win32::CCriticalSection::Owner::Owner
MTSCSS - I:\JetByteTools\Win32Tools\ThreadedCallbackTimerQueue.cpp: 100 - Win32::CThreadedCallbackTimerQueue::CancelTimer
MTSCSS - I:\MTSCSS\ProtocolHandler.cpp: 179 - CProtocolHandler::OnDataReceived
MTSCSS - I:\MTSCSS\OutgoingSocketServer.cpp: 238 - COutgoingSocketServer::OnDataAvailable

Unlocked
 by thread: 2740 @ 604 41 times
 by thread: 4960 @ 692 17 times
 by thread: 5880 @ 773 13 times
 by thread: 6020 @ 933 13 times

Location: 604
MTSCSS - I:\JetByteTools\Win32Tools\CriticalSection.cpp: 104 - Win32::CCriticalSection::Owner::~Owner
MTSCSS - I:\JetByteTools\Win32Tools\ThreadedCallbackTimerQueue.cpp: 154 - Win32::CThreadedCallbackTimerQueue::GetNextTimeout
MTSCSS - I:\JetByteTools\Win32Tools\ThreadedCallbackTimerQueue.cpp: 133 - Win32::CThreadedCallbackTimerQueue::Run
MTSCSS - I:\JetByteTools\Win32Tools\Thread.cpp: 149 - Win32::CThread::ThreadFunction
MTSCSS - __beginthreadex

Location: 692
MTSCSS - I:\JetByteTools\Win32Tools\CriticalSection.cpp: 104 - Win32::CCriticalSection::Owner::~Owner
MTSCSS - I:\JetByteTools\Win32Tools\ThreadedCallbackTimerQueue.cpp: 79 - Win32::CThreadedCallbackTimerQueue::CreateTimer
MTSCSS - I:\MTSCSS\ProtocolHandler.cpp: 102 - CProtocolHandler::CProtocolHandler
MTSCSS - Socket::CAsyncSocket::`vftable'
MTSCSS - I:\JetByteTools\SocketTools\AsyncSocket.cpp: 410 - Socket::CAsyncSocket::Read

Location: 773
MTSCSS - I:\JetByteTools\Win32Tools\CriticalSection.cpp: 104 - Win32::CCriticalSection::Owner::~Owner
MTSCSS - I:\JetByteTools\Win32Tools\ThreadedCallbackTimerQueue.cpp: 106 - Win32::CThreadedCallbackTimerQueue::CancelTimer
MTSCSS - I:\MTSCSS\ProtocolHandler.cpp: 109 - CProtocolHandler::~CProtocolHandler
MTSCSS - CProtocolHandler::`vftable'
MTSCSS - I:\MTSCSS\ProtocolHandler.cpp: 515 - CProtocolHandler::OnConnectionFailed

Location: 933
MTSCSS - I:\JetByteTools\Win32Tools\CriticalSection.cpp: 104 - Win32::CCriticalSection::Owner::~Owner
MTSCSS - I:\JetByteTools\Win32Tools\ThreadedCallbackTimerQueue.cpp: 106 - Win32::CThreadedCallbackTimerQueue::CancelTimer
MTSCSS - I:\MTSCSS\ProtocolHandler.cpp: 179 - CProtocolHandler::OnDataReceived
MTSCSS - I:\MTSCSS\OutgoingSocketServer.cpp: 238 - COutgoingSocketServer::OnDataAvailable

Deleted
 by thread: 4500 @ 1026

Location: 1026
MTSCSS - I:\JetByteTools\Win32Tools\ThreadedCallbackTimerQueue.cpp: 73 - Win32::CThreadedCallbackTimerQueue::~CThreadedCallbackTimerQueue
MTSCSS - I:\MTSCSS\ServerMain.cpp: 403 - ServerMain
MTSCSS - I:\MTSCSS\ServerMain.cpp: 651 - wWinMain
MTSCSS - _wWinMainCRTStartup

Lock contention for: 0x0012fbe8
Thread: 5880 blocked @ 774 by thread: 2740 @ 603 1 times

Location: 603
MTSCSS - I:\JetByteTools\Win32Tools\CriticalSection.cpp: 99 - Win32::CCriticalSection::Owner::Owner
MTSCSS - I:\JetByteTools\Win32Tools\ThreadedCallbackTimerQueue.cpp: 152 - Win32::CThreadedCallbackTimerQueue::GetNextTimeout
MTSCSS - I:\JetByteTools\Win32Tools\ThreadedCallbackTimerQueue.cpp: 133 - Win32::CThreadedCallbackTimerQueue::Run
MTSCSS - I:\JetByteTools\Win32Tools\Thread.cpp: 149 - Win32::CThread::ThreadFunction
MTSCSS - __beginthreadex

Location: 774
MTSCSS - I:\JetByteTools\Win32Tools\CriticalSection.cpp: 99 - Win32::CCriticalSection::Owner::Owner
MTSCSS - I:\JetByteTools\Win32Tools\ThreadedCallbackTimerQueue.cpp: 112 - Win32::CThreadedCallbackTimerQueue::DestroyTimer
MTSCSS - I:\MTSCSS\ProtocolHandler.cpp: 111 - CProtocolHandler::~CProtocolHandler
MTSCSS - CProtocolHandler::`vftable'
MTSCSS - I:\MTSCSS\ProtocolHandler.cpp: 515 - CProtocolHandler::OnConnectionFailed

I also added per thread lock operation tracking, which allows you to see what each thread does to which locks, in which order. I’m starting to drown in data now and I think I’m reaching the point where a GUI is required…

One of the interesting things about the lock operation tracking is that I display the tick count when the operation took place. The idea was to display contention time for locks, ie how long a lock operation was blocked for, but unfortunately all this does is clearly illustrates that GetTickCount() isn’t anywhere near accurate enough for this kind of thing; but I expected as much. As Raymond Chen points out GetTickCount() has high precision but low accuracy. A link from Raymond’s comments led me to the Nvidia developer site which has some timer testing code available here, I think I’ll take a look at the alternatives and see if I can get some results that are more useful…