I'm currently building a new example server for The Server Framework. This is a variation on one of our proxy server examples for a client that's doing some WebSockets work. The idea is that the server takes an inbound WebSockets connection, creates an outbound TCP connection to the target server and routes data to and from the remote server and the WebSockets client. It's fairly simple stuff to put together once you're up to speed on The Server Framework but my client needed a helping hand and it's another nice example of what you can do with the framework.
As I've mentioned before, all of these example servers run a set of black box integration tests during the build process. Once the code has compiled the tests kick off automatically, start the server, run a client against it, check the results are as expected, etc. If the test fails then the build fails.
As I mentioned a while back, I've now got memory leak analysis and lock inversion detection built into the integration test runners. The lock inversion detection can find and report on potential deadlocks without the code under test needing to actually deadlock. It detects that the code COULD deadlock and reports why. You can download the lock inversion detector that I use from here on my www.lockexplorer.com site.
Anyway, I set up the integration tests for my new server example this morning and ran it. The tests ran fine but LID reported lock inversions. Every lock inversion is a deadlock waiting to happen and although the tests had run through fine and the server hadn't deadlocked the report from LID was showing me that, given the right set of threading circumstances, it could...
By default I run LID during the integration tests as this runs slightly faster than LIA the full featured lock inversion analyser. A simple adjustment to the configuration of the integration test lets me run LIA instead and the report was quite clear as to where the lock inversions were.
****************New Log***************** Target process has terminated Process "E:\OutboundGatewayServer\Output\VS2010\URelease\OutboundGatewayServer.exe" exit code: 0 Checking 3151 lock acquisition sequences for inversions Lock inversions detected! Lock inversion in acquisition of locks 164 and 41 Primary lock acquisition sequence: 164 @ 171, 41 @ 173 Executed on thread: 8 [6164] "IOPool" Secondary lock acquisition sequence: 41 @ 154, 164 @ 178 Executed on threads: 5 [1064] "IOPool", 17 [1236] "IOPool", 16 [1288] "IOPool", 3 [2028] "IOPool", 13 [3652] "IOPool", 9 [4056] "IOPool", 12 [4676] "IOPool", 10 [4948] "IOPool", 7 [5444] "IOPool", 8 [6164] "IOPool", 4 [6232] "IOPool", 15 [6412] "IOPool", 11 [6704] "IOPool", 6 [6836] "IOPool", 14 [6876] "IOPool", 18 [7080] "IOPool" Secondary lock acquisition sequence: 41 @ 154, 164 @ 187 Executed on threads: 5 [1064] "IOPool", 17 [1236] "IOPool", 16 [1288] "IOPool", 3 [2028] "IOPool", 13 [3652] "IOPool", 9 [4056] "IOPool", 12 [4676] "IOPool", 10 [4948] "IOPool", 7 [5444] "IOPool", 8 [6164] "IOPool", 4 [6232] "IOPool", 15 [6412] "IOPool", 11 [6704] "IOPool", 6 [6836] "IOPool", 14 [6876] "IOPool", 18 [7080] "IOPool" Secondary lock acquisition sequence: 41 @ 154, 164 @ 194 Executed on thread: 12 [4676] "IOPool" Location: 154 e:\jetbytetools\win32tools\criticalsection.cpp(80) : CCriticalSection::Enter e:\jetbytetools\win32tools\icriticalsection.cpp(44) : ICriticalSection::Owner::Owner e:\jetbytetools\websockettools\hybi08\protocolhandler.cpp(260) : CProtocolHandler::OnDataReceived e:\outboundgatewayserver\socketserver.cpp(206) : CSocketServer::OnReadCompleted e:\jetbytetools\sockettools\streamsocketconnectionmanagerbase.cpp(128) : CStreamSocketConnectionManagerBase::OnReadCompleted e:\jetbytetools\sockettools\streamsocketconnectionmanager.h(933) : TStreamSocketConnectionManager<cstreamsocketconnectionmanagerbase>::HandleOperation e:\jetbytetools\sockettools\tasyncsocket.h(565) : TAsyncSocket<ipoolablestreamsocket,istreamsocketconnectionmanager,istreamsocketcallback>::HandleOperation e:\jetbytetools\iotools\iopool.cpp(319) : CIOPool::WorkerThread::Run e:\jetbytetools\win32tools\thread.cpp(241) : CThread::ThreadFunction --- Location: 171 e:\jetbytetools\win32tools\criticalsection.cpp(80) : CCriticalSection::Enter e:\jetbytetools\win32tools\icriticalsection.cpp(44) : ICriticalSection::Owner::Owner e:\outboundgatewayserver\connection.cpp(128) : CConnection::OnConnectionEstablished e:\outboundgatewayserver\socketserver.cpp(157) : CSocketServer::OnConnectionEstablished e:\jetbytetools\sockettools\streamsocketconnectionmanagerbase.cpp(86) : CStreamSocketConnectionManagerBase::OnConnectionEstablished e:\jetbytetools\sockettools\streamsocketconnectionmanager.h(1422) : TStreamSocketConnectionManager<cstreamsocketconnectionmanagerbase>::ConnectCompleted e:\jetbytetools\sockettools\streamsocketconnectionmanager.h(981) : TStreamSocketConnectionManager<cstreamsocketconnectionmanagerbase>::HandleOperation e:\jetbytetools\sockettools\tasyncsocket.h(565) : TAsyncSocket<ipoolablestreamsocket,istreamsocketconnectionmanager,istreamsocketcallback>::HandleOperation e:\jetbytetools\iotools\iopool.cpp(319) : CIOPool::WorkerThread::Run e:\jetbytetools\win32tools\thread.cpp(241) : CThread::ThreadFunction --- Location: 173 e:\jetbytetools\win32tools\criticalsection.cpp(80) : CCriticalSection::Enter e:\jetbytetools\win32tools\icriticalsection.cpp(44) : ICriticalSection::Owner::Owner e:\jetbytetools\websockettools\hybi08\protocolhandler.cpp(996) : CProtocolHandler::TryRead e:\jetbytetools\websockettools\hybi08\websocket.cpp(166) : CWebSocket::TryRead e:\jetbytetools\websockettools\hybi08\websocket.cpp(145) : CWebSocket::TryRead e:\outboundgatewayserver\connection.cpp(143) : CConnection::OnConnectionEstablished e:\outboundgatewayserver\socketserver.cpp(157) : CSocketServer::OnConnectionEstablished e:\jetbytetools\sockettools\streamsocketconnectionmanagerbase.cpp(86) : CStreamSocketConnectionManagerBase::OnConnectionEstablished e:\jetbytetools\sockettools\streamsocketconnectionmanager.h(1422) : TStreamSocketConnectionManager<cstreamsocketconnectionmanagerbase>::ConnectCompleted e:\jetbytetools\sockettools\streamsocketconnectionmanager.h(981) : TStreamSocketConnectionManager<cstreamsocketconnectionmanagerbase>::HandleOperation e:\jetbytetools\sockettools\tasyncsocket.h(565) : TAsyncSocket<ipoolablestreamsocket,istreamsocketconnectionmanager,istreamsocketcallback>::HandleOperation e:\jetbytetools\iotools\iopool.cpp(319) : CIOPool::WorkerThread::Run e:\jetbytetools\win32tools\thread.cpp(241) : CThread::ThreadFunction --- Location: 178 e:\jetbytetools\win32tools\criticalsection.cpp(80) : CCriticalSection::Enter e:\jetbytetools\win32tools\icriticalsection.cpp(44) : ICriticalSection::Owner::Owner e:\outboundgatewayserver\connection.cpp(165) : CConnection::OnReadCompleted e:\outboundgatewayserver\socketserver.cpp(322) : CSocketServer::OnDataFrame e:\jetbytetools\websockettools\hybi08\protocolhandler.cpp(917) : CProtocolHandler::HandleData e:\jetbytetools\websockettools\hybi08\protocolhandler.cpp(692) : CProtocolHandler::DispatchFrame e:\jetbytetools\websockettools\hybi08\protocolhandler.cpp(536) : CProtocolHandler::ProcessDataReceived e:\jetbytetools\websockettools\hybi08\protocolhandler.cpp(341) : CProtocolHandler::HandleDataReceived e:\jetbytetools\websockettools\hybi08\protocolhandler.cpp(284) : CProtocolHandler::OnDataReceived e:\outboundgatewayserver\socketserver.cpp(206) : CSocketServer::OnReadCompleted e:\jetbytetools\sockettools\streamsocketconnectionmanagerbase.cpp(128) : CStreamSocketConnectionManagerBase::OnReadCompleted e:\jetbytetools\sockettools\streamsocketconnectionmanager.h(933) : TStreamSocketConnectionManager<cstreamsocketconnectionmanagerbase>::HandleOperation e:\jetbytetools\sockettools\tasyncsocket.h(565) : TAsyncSocket<ipoolablestreamsocket,istreamsocketconnectionmanager,istreamsocketcallback>::HandleOperation e:\jetbytetools\iotools\iopool.cpp(319) : CIOPool::WorkerThread::Run e:\jetbytetools\win32tools\thread.cpp(241) : CThread::ThreadFunction ---
Diving into the code for the lock acquisitions in question shows me that in one of the objects concerned I'm holding the lock for longer than I need to. Reducing the scope of the lock means that I don't hold it across the use of the other object which removes the lock inversion. 2 minutes and one recompile from discovery to confirmed fix. A nice start to the day.
Leave a comment