Stuck WCF IIS hosted webservice and DevArt dotConnect for MySQL

Discussion of open issues, suggestions and bugs regarding ADO.NET provider for MySQL
Post Reply
dpursanov
Posts: 10
Joined: Wed 16 Nov 2016 12:44

Stuck WCF IIS hosted webservice and DevArt dotConnect for MySQL

Post by dpursanov » Tue 26 Dec 2017 07:53

Hello, we have a problem with the webservice being stuck: it's not even accepting new requests and only application pool recycling helps.
Here is how the connectionstring looks:
<add name="XXXEntities" connectionString="metadata=res://*/DBModel.csdl|res://*/DBModel.ssdl|res://*/DBModel.msl;provider=Devart.Data.MySql;provider connection string="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;"" 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):
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

https://stackoverflow.com/questions/479 ... -for-mysql
Last edited by dpursanov on Wed 27 Dec 2017 07:02, edited 1 time in total.

dpursanov
Posts: 10
Joined: Wed 16 Nov 2016 12:44

Re: Problem with stuck webservice

Post by dpursanov » Wed 27 Dec 2017 07:00

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

Shalex
Site Admin
Posts: 9543
Joined: Thu 14 Aug 2008 12:44

Re: Stuck WCF IIS hosted webservice and DevArt dotConnect for MySQL

Post by Shalex » Wed 27 Dec 2017 19:09

1. Your connection string includes "Max Pool Size=750;". Check the max_connections value on your MySQL Server. If it is less 750, please increase its value.

JIC: https://dev.mysql.com/doc/refman/5.5/en ... tions.html
"The number of connections permitted is controlled by the max_connections system variable. The default value is 151 to improve performance when MySQL is used with the Apache Web server. (Previously, the default was 100.) If you need to support more connections, you should set a larger value for this variable."

2. Confirm that the code of your application closes connections after their usage so that the "Max Pool Size" should not be exceeded.

3. Specify your value of max_connections (a) and the number of opened sessions on the database side (b) when the hang occurs.

If this doesn't help, please upload a small test project with the corresponding DDL/DML sсript to ftp://ftp.devart.com (credentials: anonymous / yourEmail).

dpursanov
Posts: 10
Joined: Wed 16 Nov 2016 12:44

Re: Stuck WCF IIS hosted webservice and DevArt dotConnect for MySQL

Post by dpursanov » Wed 27 Dec 2017 19:39

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. For example once the service was stopped for nearly whole night.


Post Reply