Stuck WCF IIS hosted webservice and DevArt dotConnect for MySQL

Question

We have a problem with the webservice being stuck: it's not even accepting new requests and only application pool recycling helps (It's not crashing, just stucks as if threads are in infinite timeout loop). Here is how the Entity Framework ConnectionString looks:

<add name="XXXEntities" connectionString="metadata=res://*/DBModel.csdl|res://*/DBModel.ssdl|res://*/DBModel.msl;provider=Devart.Data.MySql;provider connection string=&quot;User Id=XX;Password=XXX;Host=XXX;port=XXX;Database=XXX;CharSet=utf8;Connection Timeout=20;Default Command Timeout=60;Pooling=True;Connection Lifetime=45;Validate Connection=True;Min Pool Size=15;Max Pool Size=750;Persist Security Info=True;default fetchall=True;Transaction Scope Local=true;&quot;" providerName="System.Data.EntityClient" />

Changing Max Pool Size does not affect the situation in our case.

Example with fullstack (~40% threads are waiting with almost the same stacks like the one provided below). And all of them contain the following block:

[[HelperMethodFrame] (System.Threading.Monitor.Enter)] System.Threading.Monitor.Enter(System.Object)
Devart.Common.DbConnectionPool.RemoveObject(System.Object)+2b
Devart.Common.DbConnectionPool.PutObject(System.Object)+a1
Devart.Common.DbConnectionInternal.CloseInternalConnection()+1e1
Devart.Common.DbConnectionInternal.Close()+7c
Devart.Common.DbConnectionBase.Close()+55
Devart.Common.DbConnectionBase.Close()+26
Devart.Data.MySql.MySqlConnection.Close()+18

Stack from memory dump:

Thread 60 - System ID 7648

Entry point clr!Thread::intermediateThreadProc
Create time 12/26/2017 01:35:29
Time spent in user mode 0 Days 00:00:00.000
Time spent in kernel mode 0 Days 00:00:00.000


This thread is waiting to enter a .NET Lock

.NET Call Stack

[[GCFrame]]
[[GCFrame]]
[[HelperMethodFrame] (System.Threading.Monitor.Enter)] System.Threading.Monitor.Enter(System.Object)
Devart.Common.DbConnectionPool.RemoveObject(System.Object)+2b
Devart.Common.DbConnectionPool.PutObject(System.Object)+a1
Devart.Common.DbConnectionInternal.CloseInternalConnection()+1e1
Devart.Common.DbConnectionInternal.Close()+7c
Devart.Common.DbConnectionBase.Close()+55
Devart.Common.DbConnectionBase.Close()+26
Devart.Data.MySql.MySqlConnection.Close()+18
System.Data.Entity.Infrastructure.Interception.InternalDispatcher`1[[System.__Canon, mscorlib]].Dispatch[[System.__Canon, mscorlib],[System.__Canon, mscorlib]](System.__Canon, System.Action`2, System.__Canon, System.Action`3, System.Action`3)+10a
System.Data.Entity.Infrastructure.Interception.DbConnectionDispatcher.Close(System.Data.Common.DbConnection, System.Data.Entity.Infrastructure.Interception.DbInterceptionContext)+1fd
System.Data.Entity.Core.EntityClient.EntityConnection.StoreCloseHelper()+a8
System.Data.Entity.Core.Objects.ObjectContext.ReleaseConnection()+53
System.Data.Entity.Core.Common.Internal.Materialization.Shaper`1[[System.Nullable`1[[System.Int32, mscorlib]], mscorlib]].Finally()+4e
System.Data.Entity.Core.Common.Internal.Materialization.Shaper`1+SimpleEnumerator[[System.Nullable`1[[System.Int32, mscorlib]], mscorlib]].MoveNext()+78
System.Linq.Enumerable.Single[[System.Nullable`1[[System.Int32, mscorlib]], mscorlib]](System.Collections.Generic.IEnumerable`1>)+d8
XXXService.Extensions.ServiceUtils.CheckApplicationGetAppid(System.String, System.String)+6e
XXXService.NavigationHelper.RecheckApplication()+2a1
XXXService.SessionAttribute.OnInvoke(PostSharp.Aspects.MethodInterceptionArgs)+455
XXXService.Service.UserGetAccounts()+a0
DynamicClass.SyncInvokeUserGetAccounts(System.Object, System.Object[], System.Object[])+62
System.ServiceModel.Dispatcher.SyncMethodInvoker.Invoke(System.Object, System.Object[], System.Object[] ByRef)+6f0
System.ServiceModel.Dispatcher.DispatchOperationRuntime.InvokeBegin(System.ServiceModel.Dispatcher.MessageRpc ByRef)+29d
System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage5(System.ServiceModel.Dispatcher.MessageRpc ByRef)+21f
System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage11(System.ServiceModel.Dispatcher.MessageRpc ByRef)+296
System.ServiceModel.Dispatcher.MessageRpc.Process(Boolean)+da
System.ServiceModel.Dispatcher.ChannelHandler.DispatchAndReleasePump(System.ServiceModel.Channels.RequestContext, Boolean, System.ServiceModel.OperationContext)+456
System.ServiceModel.Dispatcher.ChannelHandler.HandleRequest(System.ServiceModel.Channels.RequestContext, System.ServiceModel.OperationContext)+19b
System.ServiceModel.Dispatcher.ChannelHandler.AsyncMessagePump(System.IAsyncResult)+f8
System.ServiceModel.Dispatcher.ChannelHandler.OnAsyncReceiveComplete(System.IAsyncResult)+5f
System.Runtime.Fx+AsyncThunk.UnhandledExceptionFrame(System.IAsyncResult)+2a
System.Runtime.AsyncResult.Complete(Boolean)+10a
System.Runtime.InputQueue`1+AsyncQueueReader[[System.__Canon, mscorlib]].Set(Item)+65
System.Runtime.InputQueue`1[[System.__Canon, mscorlib]].EnqueueAndDispatch(Item, Boolean)+2c2
System.Runtime.InputQueue`1[[System.__Canon, mscorlib]].EnqueueAndDispatch(System.__Canon, System.Action, Boolean)+a0
System.ServiceModel.Channels.SingletonChannelAcceptor`3[[System.__Canon, mscorlib],[System.__Canon, mscorlib],[System.__Canon, mscorlib]].Enqueue(System.__Canon, System.Action, Boolean)+7a
System.ServiceModel.Channels.HttpPipeline+EnqueueMessageAsyncResult.CompleteParseAndEnqueue(System.IAsyncResult)+a2
System.ServiceModel.Channels.HttpPipeline+EnqueueMessageAsyncResult.HandleParseIncomingMessage(System.IAsyncResult)+49
System.Runtime.AsyncResult.SyncContinue(System.IAsyncResult)+2f
System.ServiceModel.Channels.HttpPipeline+EmptyHttpPipeline.BeginProcessInboundRequest(System.ServiceModel.Channels.ReplyChannelAcceptor, System.Action, System.AsyncCallback, System.Object)+53
System.ServiceModel.Channels.HttpChannelListener`1+HttpContextReceivedAsyncResult`1[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].ProcessHttpContextAsync()+1c7
System.ServiceModel.Channels.HttpChannelListener`1[[System.__Canon, mscorlib]].BeginHttpContextReceived(System.ServiceModel.Channels.HttpRequestContext, System.Action, System.AsyncCallback, System.Object)+87
System.ServiceModel.Activation.HostedHttpTransportManager.HttpContextReceived(System.ServiceModel.Activation.HostedHttpRequestAsyncResult)+192
System.ServiceModel.Activation.HostedHttpRequestAsyncResult.HandleRequest()+286
System.ServiceModel.Activation.HostedHttpRequestAsyncResult.BeginRequest()+1e
System.ServiceModel.Activation.HostedHttpRequestAsyncResult.OnBeginRequest(System.Object)+4e
System.Runtime.IOThreadScheduler+ScheduledOverlapped.IOCallback(UInt32, UInt32, System.Threading.NativeOverlapped*)+53
System.Runtime.Fx+IOCompletionThunk.UnhandledExceptionFrame(UInt32, UInt32, System.Threading.NativeOverlapped*)+37
System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32, UInt32, System.Threading.NativeOverlapped*)+94
[[GCFrame]]
[[DebuggerU2MCatchHandlerFrame]]
[[ContextTransitionFrame]]
[[DebuggerU2MCatchHandlerFrame]]

Full Call Stack




Source

ntdll!NtWaitForMultipleObjects+a
KERNELBASE!WaitForMultipleObjectsEx+e1
clr!WaitForMultipleObjectsEx_SO_TOLERANT+62
clr!Thread::DoAppropriateWaitWorker+1e4
clr!Thread::DoAppropriateWait+7d
clr!CLREventBase::WaitEx+c4
clr!AwareLock::EnterEpilogHelper+ca
[[GCFrame]]
clr!AwareLock::EnterEpilog+62
clr! ?? ::FNODOBFM::`string'+cc8a0
clr!JITutil_MonContention+af
[[GCFrame]]
[[HelperMethodFrame] (System.Threading.Monitor.Enter)] System.Threading.Monitor.Enter(System.Object)
Devart.Common.DbConnectionPool.RemoveObject(System.Object)+2b
Devart.Common.DbConnectionPool.PutObject(System.Object)+a1
Devart.Common.DbConnectionInternal.CloseInternalConnection()+1e1
Devart.Common.DbConnectionInternal.Close()+7c
Devart.Common.DbConnectionBase.Close()+55
Devart.Common.DbConnectionBase.Close()+26
Devart.Data.MySql.MySqlConnection.Close()+18
System.Data.Entity.Infrastructure.Interception.InternalDispatcher`1[[System.__Canon, mscorlib]].Dispatch[[System.__Canon, mscorlib],[System.__Canon, mscorlib]](System.__Canon, System.Action`2<System.__Canon,System.__Canon>, System.__Canon, System.Action`3<System.__Canon,System.__Canon,System.__Canon>, System.Action`3<System.__Canon,System.__Canon,System.__Canon>)+10a
System.Data.Entity.Infrastructure.Interception.DbConnectionDispatcher.Close(System.Data.Common.DbConnection, System.Data.Entity.Infrastructure.Interception.DbInterceptionContext)+1fd
System.Data.Entity.Core.EntityClient.EntityConnection.StoreCloseHelper()+a8
System.Data.Entity.Core.Objects.ObjectContext.ReleaseConnection()+53
System.Data.Entity.Core.Common.Internal.Materialization.Shaper`1[[System.Nullable`1[[System.Int32, mscorlib]], mscorlib]].Finally()+4e
System.Data.Entity.Core.Common.Internal.Materialization.Shaper`1+SimpleEnumerator[[System.Nullable`1[[System.Int32, mscorlib]], mscorlib]].MoveNext()+78
System.Linq.Enumerable.Single[[System.Nullable`1[[System.Int32, mscorlib]], mscorlib]](System.Collections.Generic.IEnumerable`1<System.Nullable`1<Int32>>)+d8
XXXService.Extensions.ServiceUtils.CheckApplicationGetAppid(System.String, System.String)+6e
XXXService.NavigationHelper.RecheckApplication()+2a1
XXXService.SessionAttribute.OnInvoke(PostSharp.Aspects.MethodInterceptionArgs)+455
XXXService.Service.UserGetAccounts()+a0
DynamicClass.SyncInvokeUserGetAccounts(System.Object, System.Object[], System.Object[])+62
System.ServiceModel.Dispatcher.SyncMethodInvoker.Invoke(System.Object, System.Object[], System.Object[] ByRef)+6f0
System.ServiceModel.Dispatcher.DispatchOperationRuntime.InvokeBegin(System.ServiceModel.Dispatcher.MessageRpc ByRef)+29d
System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage5(System.ServiceModel.Dispatcher.MessageRpc ByRef)+21f
System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage11(System.ServiceModel.Dispatcher.MessageRpc ByRef)+296
System.ServiceModel.Dispatcher.MessageRpc.Process(Boolean)+da
System.ServiceModel.Dispatcher.ChannelHandler.DispatchAndReleasePump(System.ServiceModel.Channels.RequestContext, Boolean, System.ServiceModel.OperationContext)+456
System.ServiceModel.Dispatcher.ChannelHandler.HandleRequest(System.ServiceModel.Channels.RequestContext, System.ServiceModel.OperationContext)+19b
System.ServiceModel.Dispatcher.ChannelHandler.AsyncMessagePump(System.IAsyncResult)+f8
System.ServiceModel.Dispatcher.ChannelHandler.OnAsyncReceiveComplete(System.IAsyncResult)+5f
System.Runtime.Fx+AsyncThunk.UnhandledExceptionFrame(System.IAsyncResult)+2a
System.Runtime.AsyncResult.Complete(Boolean)+10a
System.Runtime.InputQueue`1+AsyncQueueReader[[System.__Canon, mscorlib]].Set(Item<System.__Canon>)+65
System.Runtime.InputQueue`1[[System.__Canon, mscorlib]].EnqueueAndDispatch(Item<System.__Canon>, Boolean)+2c2
System.Runtime.InputQueue`1[[System.__Canon, mscorlib]].EnqueueAndDispatch(System.__Canon, System.Action, Boolean)+a0
System.ServiceModel.Channels.SingletonChannelAcceptor`3[[System.__Canon, mscorlib],[System.__Canon, mscorlib],[System.__Canon, mscorlib]].Enqueue(System.__Canon, System.Action, Boolean)+7a
System.ServiceModel.Channels.HttpPipeline+EnqueueMessageAsyncResult.CompleteParseAndEnqueue(System.IAsyncResult)+a2
System.ServiceModel.Channels.HttpPipeline+EnqueueMessageAsyncResult.HandleParseIncomingMessage(System.IAsyncResult)+49
System.Runtime.AsyncResult.SyncContinue(System.IAsyncResult)+2f
System.ServiceModel.Channels.HttpPipeline+EmptyHttpPipeline.BeginProcessInboundRequest(System.ServiceModel.Channels.ReplyChannelAcceptor, System.Action, System.AsyncCallback, System.Object)+53
System.ServiceModel.Channels.HttpChannelListener`1+HttpContextReceivedAsyncResult`1[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].ProcessHttpContextAsync()+1c7
System.ServiceModel.Channels.HttpChannelListener`1[[System.__Canon, mscorlib]].BeginHttpContextReceived(System.ServiceModel.Channels.HttpRequestContext, System.Action, System.AsyncCallback, System.Object)+87
System.ServiceModel.Activation.HostedHttpTransportManager.HttpContextReceived(System.ServiceModel.Activation.HostedHttpRequestAsyncResult)+192
System.ServiceModel.Activation.HostedHttpRequestAsyncResult.HandleRequest()+286
System.ServiceModel.Activation.HostedHttpRequestAsyncResult.BeginRequest()+1e
System.ServiceModel.Activation.HostedHttpRequestAsyncResult.OnBeginRequest(System.Object)+4e
System.Runtime.IOThreadScheduler+ScheduledOverlapped.IOCallback(UInt32, UInt32, System.Threading.NativeOverlapped*)+53
System.Runtime.Fx+IOCompletionThunk.UnhandledExceptionFrame(UInt32, UInt32, System.Threading.NativeOverlapped*)+37
System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32, UInt32, System.Threading.NativeOverlapped*)+94
clr!CallDescrWorkerInternal+83
clr!CallDescrWorkerWithHandler+4e
clr!DispatchCallSimple+67
clr!BindIoCompletionCallBack_Worker+c7
[[GCFrame]]
clr!Frame::Push+59
clr!FillInRegTypeMap+198
clr!FillInRegTypeMap+c1
[[DebuggerU2MCatchHandlerFrame]]
clr!GCToOSInterface::GetRestrictedPhysicalMemoryLimit+9d
clr!Thread::DoADCallBack+278
[[ContextTransitionFrame]]
clr! ?? ::FNODOBFM::`string'+4a299
clr!FillInRegTypeMap+198
clr!FillInRegTypeMap+c1
[[DebuggerU2MCatchHandlerFrame]]
clr!FillInRegTypeMap+47
clr!BindIoCompletionCallbackStubEx+b9
clr!BindIoCompletionCallbackStub+9
clr!ThreadpoolMgr::CompletionPortThreadStart+5fc
clr!Thread::intermediateThreadProc+86
kernel32!BaseThreadInitThunk+22
ntdll!RtlUserThreadStart+34

OS: Windows Server 2012 R2 Standard 64bit
RAM: 4GB
IIS: 8.5.9600.16384
DevArt for MySql: 8.10.1031.0
.NET: 4.6

Same question on official forums
What can cause the problem?
In case Devart representative sees this: will you patch it or we should granularily set some parameters?

UPDATE
There is a notification in dump report:

Look at the callstack of thread 29 to see why that thread id waiting on and why it is not releasing the lock.

So here is additional part of the dump of the thread 29:

Thread 29 - System ID 5420   

Entry point   clr!Thread::intermediateThreadProc 
Create time   12/26/2017 00:14:58 
Time spent in user mode   0 Days 00:00:13.937 
Time spent in kernel mode   0 Days 00:00:01.953    

This thread is waiting to enter a .NET Lock   

.NET Call Stack

[[GCFrame]] 
[[GCFrame]] 
[[HelperMethodFrame_1OBJ] (System.Threading.Monitor.Enter)] System.Threading.Monitor.Enter(System.Object) 
Devart.Common.DbConnectionPoolGroup.a(Devart.Common.DbConnectionPool)+b3 
Devart.Common.DbConnectionPoolGroup.a(System.Object)+cd 
System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+16b 
System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+14 
System.Threading.TimerQueueTimer.CallCallback()+138 
System.Threading.TimerQueueTimer.Fire()+72 
System.Threading.TimerQueue.FireNextTimers()+6a 
[[DebuggerU2MCatchHandlerFrame]] 
[[ContextTransitionFrame]] 
[[DebuggerU2MCatchHandlerFrame]] 

Full Call Stack


  Source

ntdll!NtWaitForMultipleObjects+a    
KERNELBASE!WaitForMultipleObjectsEx+e1    
clr!WaitForMultipleObjectsEx_SO_TOLERANT+62    
clr!Thread::DoAppropriateWaitWorker+1e4    
clr!Thread::DoAppropriateWait+7d    
clr!CLREventBase::WaitEx+c4    
clr!AwareLock::EnterEpilogHelper+ca    
[[GCFrame]]    
clr!AwareLock::EnterEpilog+62    
clr!JITutil_MonEnterWorker+e2    
[[GCFrame]]    
[[HelperMethodFrame_1OBJ] (System.Threading.Monitor.Enter)] System.Threading.Monitor.Enter(System.Object)    
Devart.Common.DbConnectionPoolGroup.a(Devart.Common.DbConnectionPool)+b3    
Devart.Common.DbConnectionPoolGroup.a(System.Object)+cd    
System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+16b    
System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+14    
System.Threading.TimerQueueTimer.CallCallback()+138    
System.Threading.TimerQueueTimer.Fire()+72    
System.Threading.TimerQueue.FireNextTimers()+6a    
clr!CallDescrWorkerInternal+83    
clr!CallDescrWorkerWithHandler+4e    
clr!MethodDescCallSite::CallTargetWorker+f8    
clr!AppDomainTimerCallback_Worker+23    
clr!Frame::Push+59    
clr!FillInRegTypeMap+198    
clr!FillInRegTypeMap+c1    
[[DebuggerU2MCatchHandlerFrame]]    
clr!GCToOSInterface::GetRestrictedPhysicalMemoryLimit+9d    
clr!Thread::DoADCallBack+278    
[[ContextTransitionFrame]]    
clr! ?? ::FNODOBFM::`string'+4a299    
clr!FillInRegTypeMap+198    
clr!FillInRegTypeMap+c1    
[[DebuggerU2MCatchHandlerFrame]]    
clr!FillInRegTypeMap+47    
clr!AppDomainTimerCallback+7f    
clr!ThreadpoolMgr::AsyncTimerCallbackCompletion+7e    
clr!UnManagedPerAppDomainTPCount::DispatchWorkItem+1bc    
clr!ThreadpoolMgr::ExecuteWorkRequest+64    
clr!ThreadpoolMgr::WorkerThreadStart+f5    
clr!Thread::intermediateThreadProc+86    
kernel32!BaseThreadInitThunk+22    
ntdll!RtlUserThreadStart+34

At a first glance, not digging into code I would first investigate some kind of DB blocking i.e. some sql query that is locking stuff up on an update or some such thing and not clearing. That is not a huge amount of memory for a server that has sql on it and IIS — Mark Schultheiss, Dec 26 '17 at 15:08
hmmm `GetRestrictedPhysicalMemoryLimit` in there, do not know this code but that in a superficial dig seems interesting — Mark Schultheiss, Dec 26 '17 at 15:14
@MarkSchultheiss there is only IIS on that server, the database is sure on another one.. 4GB is not enough for it, but OK for webserver (for now it users around 700-800mb). About "not clearing": we use "using" blocks all the time when we initiate any DB procedure call, I've specially rechecked that. — 0x49D1, Dec 26 '17 at 19:08
Is the DB server seeing blocking queries? Is there a specific table locked up? `SHOW FULL PROCESSLIST;` look for stuff not "locked" as the offender perhaps? — Mark Schultheiss, Dec 26 '17 at 19:33
Will check during the next "hang".. But the number of connections to the database and CPU usage increases almost 3 times normal. Recycling webservice's application pool helps -> my guess is that it's some MySQL connector implementation issue. I've tried to change Connection Pooling settings and it kinda changes the behavior, but still "hungs" in unpredictable (for now) times. — 0x49D1, Dec 26 '17 at 19:37
We have answered you at http://forums.devart.com/viewtopic.php?f=2&t=36401#p126946. — Devart, Dec 27 '17 at 19:14
@Devart 1. max_connections is 500. Changed the setting to 250 for our case. 750 was set after several tries. 2. We have "using" blocks everywhere, when using entity data context with dotconnect. Rechecked that and there is NO code without using. 3. Hang occurs when number of connections is ~150. Normally its ~70. Can't really give you any samples, just dumps. We've made second one and the picture seems the same. The most frustrating thing is that the whole service just stops and is not responding until you start recycling process. Once the service was stopped whole night. — 0x49D1, Dec 27 '17 at 19:41
Please check your IIS settings: https://forums.iis.net/t/1216179.aspx and https://weblogs.asp.net/owscott/windows-8-iis-8-concurrent-requests-limit — Devart, Jan 05 '18 at 12:32

Stuck WCF IIS hosted webservice and DevArt dotConnect for MySQL

0 Answers0