Another day, another deadlock avoided with no harm done

By Len on July 7, 2011 9:43 AM | 0 Comments
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.

This works great at flushing out any latent issues that the unit tests of all the framework code don't happen to catch. It's good for race condition problems and deadlocks and the like. The fact that the integration tests run on all of my build servers (which are a nice mix of power, memory and processors) means that race conditions and whatever get shaken out of the framework pretty quickly.
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.

Categories:

    

Leave a comment