search

DataAction / AdoNetCore.AseClient

AdoNetCore.AseClient - a .NET Core DB Provider for SAP ASE
Apache License 2.0
108 stars 45 forks source link

High CPU usage when waiting for pooling connection #142

Closed alfhv closed 5 years ago

alfhv commented 5 years ago

I have a webapi, dotnet 2.2, deploying on Linux OS. (RedHat 7). AdoNetCore.AseClient 0.14.0 I'm connecting to a SyBase database using Linq2Db, which will use AseClient underlying.

I have a simple code as:

public List<Customer> GetCustomers()
{
   using (var connection = new DataConnection(ProviderName.SyBase, connectionString))
   {
       return connection.Query<Customer>(sqlQuery, paramList).ToList();
   }
}

Note: the query takes some time to respond, about 2 or 3 minutes, too many data to retrieve.

and I have a stress test doing a lot of queries, multiple clients, multiples threads, agains my webapi service. (stress test client is in a different machine, not in same webapi server)

We have found that during stress tests database connections get exhausted, which is normal, in some moment maximum pool size is reach and no more queries are executed, we get server errors but thats is expected.

The problem is, when stress test is finished, we have no more queries executing, logs are quiet, but CPU is at 100%, actually 400% because 4 cores, and it stays like that for hours, we need to restart the service.

doing "htop" command we can see our service at top consuming all CPU. checking stack trace we find all the time this piece of code stock running:

00007F7B41AB9FA8 00007f80173e4bad [InlinedCallFrame: 00007f7b41ab9fa8] Interop+Sys.ReceiveMessage(IntPtr, MessageHeader, System.Net.Sockets.SocketFlags, Int64) 00007F7B41AB9FA8 00007f7f9fa84fbc [InlinedCallFrame: 00007f7b41ab9fa8] Interop+Sys.ReceiveMessage(IntPtr, MessageHeader, System.Net.Sockets.SocketFlags, Int64) 00007F7B41AB9FA0 00007F7F9FA84FBC DomainBoundILStubClass.IL_STUB_PInvoke(IntPtr, MessageHeader, System.Net.Sockets.SocketFlags, Int64) 00007F7B41ABA020 00007F7FA02C71C2 System.Net.Sockets.SocketPal.Receive(System.Net.Sockets.SafeCloseSocket, System.Net.Sockets.SocketFlags, System.Span1<Byte>, Byte[], Int32 ByRef, System.Net.Sockets.SocketFlags ByRef, Error ByRef) 00007F7B41ABA100 00007F7FA02C8CB3 System.Net.Sockets.SocketPal.TryCompleteReceiveFrom(System.Net.Sockets.SafeCloseSocket, System.Span1, System.Collections.Generic.IList1<System.ArraySegment1>, System.Net.Sockets.SocketFlags, Byte[], Int32 ByRef, Int32 ByRef, System.Net.Sockets.SocketFlags ByRef, System.Net.Sockets.SocketError ByRef) 00007F7B41ABA1A0 00007F7FA02C2E00 System.Net.Sockets.SocketAsyncContext.ReceiveFrom(System.Memory1<Byte>, System.Net.Sockets.SocketFlags ByRef, Byte[], Int32 ByRef, Int32, Int32 ByRef) 00007F7B41ABA250 00007F7FA02C9E36 System.Net.Sockets.SocketPal.Receive(System.Net.Sockets.SafeCloseSocket, Byte[], Int32, Int32, System.Net.Sockets.SocketFlags, Int32 ByRef) 00007F7B41ABA310 00007F7FA02A6165 System.Net.Sockets.Socket.Receive(Byte[], Int32, Int32, System.Net.Sockets.SocketFlags, System.Net.Sockets.SocketError ByRef) 00007F7B41ABA370 00007F7FA32F986C AdoNetCore.AseClient.Internal.RegularSocket.ReceiveTokens(AdoNetCore.AseClient.Internal.DbEnvironment) 00007F7B41ABA3F0 00007F7FA32F92EE AdoNetCore.AseClient.Internal.InternalConnection.ReceiveTokens(AdoNetCore.AseClient.Interface.ITokenHandler[]) 00007F7B41ABA440 00007F7FA37B3132 AdoNetCore.AseClient.Internal.InternalConnection.Ping() 00007F7B41ABA480 00007F7FA32F572A AdoNetCore.AseClient.Internal.ConnectionPool.FetchIdlePooledConnection(AdoNetCore.AseClient.Interface.IInfoMessageEventNotifier) 00007F7B41ABA4E0 00007F7FA32F5257 AdoNetCore.AseClient.Internal.ConnectionPool+<ReservePooledConnection>d__13.MoveNext() 00007F7B41ABA530 00007F7FA32F4CFB System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[[AdoNetCore.AseClient.Internal.ConnectionPool+<ReservePooledConnection>d__13, AdoNetCore.AseClient]](<ReservePooledConnection>d__13 ByRef) 00007F7B41ABA580 00007F7FA32F4C74 AdoNetCore.AseClient.Internal.ConnectionPool.ReservePooledConnection(System.Threading.CancellationToken, AdoNetCore.AseClient.Interface.IInfoMessageEventNotifier) 00007F7B41ABA5D0 00007F7FA32F493B AdoNetCore.AseClient.Internal.ConnectionPool.Reserve(AdoNetCore.AseClient.Interface.IInfoMessageEventNotifier) 00007F7B41ABA630 00007F7FA32F061B AdoNetCore.AseClient.AseConnection.Open() 00007F7B41ABA650 00007F7FA32E7C82 LinqToDB.Data.DataConnection.EnsureConnection() 00007F7B41ABA690 00007F7FA32E7414 LinqToDB.Data.DataConnection.CreateCommand() 00007F7B41ABA6B0 00007F7FA32E73CB LinqToDB.Data.DataConnection.get_Command() 00007F7B41ABA6D0 00007F7FA32E72BF LinqToDB.DataProvider.DataProviderBase.InitCommand(LinqToDB.Data.DataConnection, System.Data.CommandType, System.String, LinqToDB.Data.DataParameter[], Boolean) 00007F7B41ABA700 00007F7FA32E71A2 LinqToDB.Data.DataConnection.InitCommand(System.Data.CommandType, System.String, LinqToDB.Data.DataParameter[], System.Collections.Generic.List1, Boolean) 00007F7B41ABA740 00007F7FA32E6DDE LinqToDB.Data.CommandInfo.Query[[System.Canon, System.Private.CoreLib]]() 00007F7B41ABA770 00007F7FA32E6762MyDAO.MyServiceDAO+<>cDisplayClass8_1.<MyMethodDoingQueryHere()>b__0() [/da

Seems that when no more connections available in the pool, the code that waits for an available one never get ends, just wait indefinitely.

I want to precise that this happens in a very stressed situation, but I would like to avoid this kind of deadlock. Specially because server becomes very slow for other services.

senseibaka commented 5 years ago

Reformat of the above for readability:

System.Net.Sockets.SocketPal.Receive(System.Net.Sockets.SafeCloseSocket, System.Net.Sockets.SocketFlags, System.Span`1<Byte>, Byte[], Int32 ByRef, System.Net.Sockets.SocketFlags ByRef, Error ByRef)
System.Net.Sockets.SocketPal.TryCompleteReceiveFrom(System.Net.Sockets.SafeCloseSocket, System.Span`1<Byte>, System.Collections.Generic.IList`1<System.ArraySegment`1<Byte>>, System.Net.Sockets.SocketFlags, Byte[], Int32 ByRef, Int32 ByRef, System.Net.Sockets.SocketFlags ByRef, System.Net.Sockets.SocketError ByRef)
System.Net.Sockets.SocketAsyncContext.ReceiveFrom(System.Memory`1<Byte>, System.Net.Sockets.SocketFlags ByRef, Byte[], Int32 ByRef, Int32, Int32 ByRef)
System.Net.Sockets.SocketPal.Receive(System.Net.Sockets.SafeCloseSocket, Byte[], Int32, Int32, System.Net.Sockets.SocketFlags, Int32 ByRef)
System.Net.Sockets.Socket.Receive(Byte[], Int32, Int32, System.Net.Sockets.SocketFlags, System.Net.Sockets.SocketError ByRef)
===========
AdoNetCore.AseClient.Internal.RegularSocket.ReceiveTokens(AdoNetCore.AseClient.Internal.DbEnvironment)
AdoNetCore.AseClient.Internal.InternalConnection.ReceiveTokens(AdoNetCore.AseClient.Interface.ITokenHandler[])
AdoNetCore.AseClient.Internal.InternalConnection.Ping()
AdoNetCore.AseClient.Internal.ConnectionPool.FetchIdlePooledConnection(AdoNetCore.AseClient.Interface.IInfoMessageEventNotifier)
AdoNetCore.AseClient.Internal.ConnectionPool+<ReservePooledConnection>d__13.MoveNext()
    System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[[AdoNetCore.AseClient.Internal.ConnectionPool+<ReservePooledConnection>d__13, AdoNetCore.AseClient]](<ReservePooledConnection>d__13 ByRef)
AdoNetCore.AseClient.Internal.ConnectionPool.ReservePooledConnection(System.Threading.CancellationToken, AdoNetCore.AseClient.Interface.IInfoMessageEventNotifier)
AdoNetCore.AseClient.Internal.ConnectionPool.Reserve(AdoNetCore.AseClient.Interface.IInfoMessageEventNotifier)
AdoNetCore.AseClient.AseConnection.Open()
===========
LinqToDB.Data.DataConnection.EnsureConnection()
LinqToDB.Data.DataConnection.CreateCommand()
LinqToDB.Data.DataConnection.get_Command()
LinqToDB.DataProvider.DataProviderBase.InitCommand(LinqToDB.Data.DataConnection, System.Data.CommandType, System.String, LinqToDB.Data.DataParameter[], Boolean)
LinqToDB.Data.DataConnection.InitCommand(System.Data.CommandType, System.String, LinqToDB.Data.DataParameter[], System.Collections.Generic.List`1<System.String>, Boolean)
LinqToDB.Data.CommandInfo.Query[[System.__Canon, System.Private.CoreLib]]()
senseibaka commented 5 years ago

Hi @alfhv,

Short answer: I think the new version 0.15.0 of the driver should fix this for you, can you give it a shot?

Longer answer: To try and confirm the connection is healthy, by default the connection pool does a Ping (asks the server for some time statistics) and then expects a response, which is where the driver hangs (based on the trace). Having done a bit of digging through the code, I've identified a potential problem where the driver will repeatedly try to read n bytes from the network socket if the connection is dead (the socket would repeatedly return 0 bytes).

0.15.0 introduced some big changes to how data is read back from the server, and it looks like there's a specific check for this case.

alfhv commented 5 years ago

thanks a lot, v0.16 definitly fix the issue.

senseibaka commented 5 years ago

Nice!