/* Rambling comments... */

Viewing lock lifetimes

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...

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...