Previous .NET Exceptions Report (Exceptions in all .NET Heaps)
|
| [[GCFrame]] |
| [[GCFrame]] |
| [[HelperMethodFrame] (System.Threading.Monitor.Enter)] System.Threading.Monitor.Enter(System.Object) |
| MongoDB.Driver.Internal.DiscoveringMongoServerProxy.EnsureInstanceManager(System.TimeSpan)+34 |
| MongoDB.Driver.Internal.DiscoveringMongoServerProxy.ChooseServerInstance(MongoDB.Driver.ReadPreference)+1f |
| MongoDB.Driver.MongoServer.AcquireConnection(MongoDB.Driver.ReadPreference)+12b |
| MongoDB.Driver.MongoCollection.InsertBatch(System.Type, System.Collections.IEnumerable, MongoDB.Driver.MongoInsertOptions)+95 |
| MongoDB.Driver.MongoCollection.Insert(System.Type, System.Object, MongoDB.Driver.MongoInsertOptions)+56 |
| mscorlib_ni!System.Threading.Tasks.Task`1[[System.__Canon, mscorlib]].InnerInvoke()+4f |
| mscorlib_ni!System.Threading.Tasks.Task.Execute()+6e |
| mscorlib_ni!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+285 |
| mscorlib_ni!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+9 |
| mscorlib_ni!System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef)+250 |
| mscorlib_ni!System.Threading.Tasks.Task.ExecuteEntry(Boolean)+85 |
| mscorlib_ni!System.Threading.ThreadPoolWorkQueue.Dispatch()+1ea |
| [[DebuggerU2MCatchHandlerFrame]] |
| [[ContextTransitionFrame]] |
| [[DebuggerU2MCatchHandlerFrame]] And all these threads are basically locked and alive, in effect clogging our server (over 97.5% thread lock for over 30 minutes). Basically it looks as if some static lock inside the C#'s connection handler doesn't get released, and just locks up any other access to the DB. |
// private methodsprivate void EnsureInstanceManager(TimeSpan timeout){if (_serverProxy == null){lock (_lock){if (_serverProxy == null){_connectionAttempt++;_state = MongoServerState.Connecting;Discover(timeout);}}}}
I checked the dumps and see exactly what we expected after looking at WCF traces. I see that many threads (handling new requests) are waiting to own a lock which is owned by another thread. The owning thread is stuck and not releasing the lock and causing the contention/hang and eventually service hits the MaxConcurrentCalls limit.
Both the responsible callstacks are related to Mongo DB here i.e. Thread which are waiting to own a lock and thread callstack owning the lock is from Mongo DB module. Please see the callstack here,
Sample Thread callstack waiting to own a .Net Lock
878 Id: 60c.16c4 Suspend: 0 Teb: 000007f6`9f312000 Unfrozen
Child-SP RetAddr Call Site
000000a9`a36acff8 000007f8`9522129e ntdll!ZwWaitForMultipleObjects+0xa
000000a9`a36ad000 000007f8`8f4614f2 KERNELBASE!WaitForMultipleObjectsEx+0xe5
000000a9`a36ad2e0 000007f8`8f4613a7 clr!WaitForMultipleObjectsEx_SO_TOLERANT+0x62
000000a9`a36ad340 000007f8`8f461236 clr!Thread::DoAppropriateAptStateWait+0x53
000000a9`a36ad380 000007f8`8f46108d clr!Thread::DoAppropriateWaitWorker+0x186
000000a9`a36ad470 000007f8`8f461327 clr!Thread::DoAppropriateWait+0x7d
000000a9`a36ad4f0 000007f8`8f3c584e clr!CLREventBase::WaitEx+0xc0
000000a9`a36ad580 000007f8`8f3c5762 clr!AwareLock::EnterEpilogHelper+0xc6
000000a9`a36ad640 000007f8`8f387abb clr!AwareLock::EnterEpilog+0x62
000000a9`a36ad6a0 000007f8`8f3c5bdb clr!AwareLock::Contention+0x1e3
000000a9`a36ad760 000007f8`2fd1c5d4 clr!JITutil_MonContention+0xaf
000000a9`a36ad8f0 000007f8`2fd1c55f MongoDB_Driver!MongoDB.Driver.Internal.DiscoveringMongoServerProxy.EnsureInstanceManager(System.TimeSpan)+0x34
000000a9`a36ad940 000007f8`2fd1c4cb MongoDB_Driver!MongoDB.Driver.Internal.DiscoveringMongoServerProxy.ChooseServerInstance(MongoDB.Driver.ReadPreference)+0x1f
000000a9`a36ad980 000007f8`3002d815 MongoDB_Driver!MongoDB.Driver.MongoServer.AcquireConnection(MongoDB.Driver.ReadPreference)+0x12b
000000a9`a36ad9e0 000007f8`3002d6e6 MongoDB_Driver!MongoDB.Driver.MongoCollection.InsertBatch(System.Type, System.Collections.IEnumerable, MongoDB.Driver.MongoInsertOptions)+0x95
000000a9`a36ada90 000007f8`8e0410df MongoDB_Driver!MongoDB.Driver.MongoCollection.Insert(System.Type, System.Object, MongoDB.Driver.MongoInsertOptions)+0x56
000000a9`a36adae0 000007f8`8e03c1de mscorlib_ni!System.Threading.Tasks.Task`1[[System.__Canon, mscorlib]].InnerInvoke()+0x4f
000000a9`a36adb30 000007f8`8e0ed0b5 mscorlib_ni!System.Threading.Tasks.Task.Execute()+0x6e
Sample Thread callstack owning a .Net Lock (and taking time to release it)L
0:117> kL
Child-SP RetAddr Call Site
000000a9`86d2d008 000007f8`9522129e ntdll!ZwWaitForMultipleObjects+0xa
000000a9`86d2d010 000007f8`8f4614f2 KERNELBASE!WaitForMultipleObjectsEx+0xe5
000000a9`86d2d2f0 000007f8`8f4613a7 clr!WaitForMultipleObjectsEx_SO_TOLERANT+0x62
000000a9`86d2d350 000007f8`8f461236 clr!Thread::DoAppropriateAptStateWait+0x53
000000a9`86d2d390 000007f8`8f46108d clr!Thread::DoAppropriateWaitWorker+0x186
000000a9`86d2d480 000007f8`8f461327 clr!Thread::DoAppropriateWait+0x7d
000000a9`86d2d500 000007f8`8f3d1b5e clr!CLREventBase::WaitEx+0xc0
000000a9`86d2d590 000007f8`8f3d1b38 clr!Thread::Block+0x1e
000000a9`86d2d5c0 000007f8`8f3d1983 clr!SyncBlock::Wait+0x150
(Inline Function) --------`-------- clr!Object::Wait+0xb
000000a9`86d2d700 000007f8`2fd1cad5 clr!ObjectNative::WaitTimeout+0xc7
000000a9`86d2d880 000007f8`2fd1c73d MongoDB_Driver!MongoDB.Driver.Internal.BlockingQueue`1[[System.__Canon, mscorlib]].Dequeue(System.TimeSpan)+0xd5
000000a9`86d2d910 000007f8`2fd1c5f8 MongoDB_Driver!MongoDB.Driver.Internal.DiscoveringMongoServerProxy.Discover(System.TimeSpan)+0xdd
000000a9`86d2d980 000007f8`2fd1c55f MongoDB_Driver!MongoDB.Driver.Internal.DiscoveringMongoServerProxy.EnsureInstanceManager(System.TimeSpan)+0x58
000000a9`86d2d9d0 000007f8`2fd1c4cb MongoDB_Driver!MongoDB.Driver.Internal.DiscoveringMongoServerProxy.ChooseServerInstance(MongoDB.Driver.ReadPreference)+0x1f
000000a9`86d2da10 000007f8`3002d815 MongoDB_Driver!MongoDB.Driver.MongoServer.AcquireConnection(MongoDB.Driver.ReadPreference)+0x12b
000000a9`86d2da70 000007f8`3002d6e6 MongoDB_Driver!MongoDB.Driver.MongoCollection.InsertBatch(System.Type, System.Collections.IEnumerable, MongoDB.Driver.MongoInsertOptions)+0x95
000000a9`86d2db20 000007f8`8e0410df MongoDB_Driver!MongoDB.Driver.MongoCollection.Insert(System.Type, System.Object, MongoDB.Driver.MongoInsertOptions)+0x56
000000a9`86d2db70 000007f8`8e03c1de mscorlib_ni!System.Threading.Tasks.Task`1[[System.__Canon, mscorlib]].InnerInvoke()+0x4f
000000a9`86d2dbc0 000007f8`8e0ed0b5 mscorlib_ni!System.Threading.Tasks.Task.Execute()+0x6e
// MongoDB.Driver.Internal.BlockingQueue<T>
public T Dequeue(TimeSpan timeout)
{
object syncRoot;
Monitor.Enter(syncRoot = this._syncRoot);
T result;
try
{
DateTime d = DateTime.UtcNow + timeout;
while (this._queue.Count == 0)
{
TimeSpan timeSpan = d - DateTime.UtcNow;
if (!(timeSpan > TimeSpan.Zero))
{
result = default(T);
return result;
}
Monitor.Wait(this._syncRoot, timeSpan); <<<< All the dumps shows that here Dequeue method seems to be waiting for long and causing contention
}
I also see following exceptions in the memory which seems to be related as thrown from same method causing contention.
MongoDB.Driver.MongoConnectionException: Unable to connect in the specified timeframe of '00:00:30'. <<<< There’re around 23 instance of this exception in memory
MongoDB.Driver.Internal.DiscoveringMongoServerProxy.Discover(System.TimeSpan)
MongoDB.Driver.Internal.DiscoveringMongoServerProxy.EnsureInstanceManager(System.TimeSpan)
MongoDB.Driver.Internal.DiscoveringMongoServerProxy.ChooseServerInstance(MongoDB.Driver.ReadPreference)
MongoDB.Driver.MongoServer.AcquireConnection(MongoDB.Driver.ReadPreference)
MongoDB.Driver.MongoCollection.InsertBatch(System.Type, System.Collections.IEnumerable, MongoDB.Driver.MongoInsertOptions)
MongoDB.Driver.MongoCollection.Insert(System.Type, System.Object, MongoDB.Driver.MongoInsertOptions)
System.Threading.Tasks.Task`1[[System.__Canon, mscorlib]].InnerInvoke()
System.Threading.Tasks.Task.Execute()
System.ObjectDisposedException | : | Cannot access a disposed object. |
MongoDB.Driver.Internal.DiscoveringMongoServerProxy.Discover(System.TimeSpan)
MongoDB.Driver.Internal.DiscoveringMongoServerProxy.EnsureInstanceManager(System.TimeSpan)
MongoDB.Driver.Internal.DiscoveringMongoServerProxy.ChooseServerInstance(MongoDB.Driver.ReadPreference)
MongoDB.Driver.MongoServer.AcquireConnection(MongoDB.Driver.ReadPreference)
MongoDB.Driver.MongoCollection.InsertBatch(System.Type, System.Collections.IEnumerable, MongoDB.Driver.MongoInsertOptions)
MongoDB.Driver.MongoCollection.Insert(System.Type, System.Object, MongoDB.Driver.MongoInsertOptions)
System.Threading.Tasks.Task`1[[System.__Canon, mscorlib]].InnerInvoke()
System.Threading.Tasks.Task.Execute()
I think the former exception in above list MongoDB.Driver.MongoConnectionException is thrown by DiscoveringMongoServerProxy.Discover because BlockingQueue`1[[System.__Canon, mscorlib]].Dequeue didn’t finish in specified Timeout (30 sec) and eventually Discover threw the exception. So, it’s confirmed that BlockingQueue`1[[System.__Canon, mscorlib]].Dequeue looks to be taking time to finish.
Summary
=========
The cause of the hang is confirmed as we expected that Mongo DB module is causing the contention and slow processing of request. In the meantime, requests keep piling up and eventually hitting the MaxConcurrentCalls limit and client application receives SocketExceptions.
What can be done
=================
Please connect with Mongo DB support team and check with them why above code could be creating contention. Do they’ve any better suggestions to avoid the contention.
...
I'm afraid while the 'replicaSet' did stop the thread lock, the problem has migrated elsewhere.
Every 1-2 days we will suddenly get hundreds to thousands of timeouts to the DB, a thing which a simple restart will solve.
Looking in the socket logs I see nothing out of the ordinary, only a simple socket connecion timeout.
Do you have any other suggestion on how to proceed?