Runtime: SQL Reader Async 10 times slower than sync

[nils2612]

Hi,

we got a problem with the async sql reader. We can reproduce that in ef core and with the sql data reader. Its so slow, that it's not usable. I also tried 4.5.0-preview2-26225-02, but the speed tests give the same result.
Example:
Async Sql Client

using (var conn = new System.Data.SqlClient.SqlConnection(getConnectionstring(_config)))
                    {
                        using (var cmd = new System.Data.SqlClient.SqlCommand("SELECT TOP 350 * FROM users.Users;", conn))
                        {
                            cmd.CommandType = System.Data.CommandType.Text;

                            conn.Open();
                            var reader = await cmd.ExecuteReaderAsync();

                            while (await reader.ReadAsync())
                            {
                                Guid id = reader.GetGuid(0);
                                stringBuilder2.AppendLine(id.ToString());
                            }
                        }
                    }

Result: 218ms

Sync Sql Client

    using (var conn = new System.Data.SqlClient.SqlConnection(getConnectionstring(_config)))
                    {
                        using (var cmd = new System.Data.SqlClient.SqlCommand("SELECT TOP 350 * FROM users.Users;", conn))
                        {
                            cmd.CommandType = System.Data.CommandType.Text;
                            conn.Open();
                            var reader = cmd.ExecuteReader();

                            while (reader.Read())
                            {
                                Guid id = reader.GetGuid(0);
                                stringBuilder.AppendLine(id.ToString());
                            }
                        }
                    }

Result: 28 ms

I always tried 10 or more times to exclude warmup.

The same happens using ef:

Sync ef example

                    using (var db = new TestContext(_config))
                    {

                        db.ConfigureLogging(s => stringLogger.AppendLine(stopwatch.ElapsedMilliseconds.ToString() + " " + s));
                        var blogs = db.Users.Take(350)
                            .ToList();


                    }

                    break;`

Result:
ef-client took 22ms
0 Opening connection to database 'users-service' on server 'xx.database.cloudapi.de'.
0 Opened connection to database 'users-service' on server 'xx.database.cloudapi.de'.
0 Executing DbCommand [Parameters=[@__p_0='?'], CommandType='Text', CommandTimeout='30']
SELECT TOP(@__p_0) [u].[Id], [u].[FirstName], [u].[LastName]
FROM [users].[Users] AS [u]
21 Executed DbCommand (21ms) [Parameters=[@__p_0='?'], CommandType='Text', CommandTimeout='30']
SELECT TOP(@__p_0) [u].[Id], [u].[FirstName], [u].[LastName]
FROM [users].[Users] AS [u]
22 A data reader was disposed.
22 Closing connection to database 'users-service' on server 'xx.database.cloudapi.de'.
22 Closed connection to database 'users-service' on server 'xx.database.cloudapi.de'.

Async ef example:

using (var db = new TestContext(_config))
                    {
                      db.ConfigureLogging(s => stringLogger.AppendLine(stopwatch.ElapsedMilliseconds.ToString() + " " + s));
                        var blogs = await db.Users.Take(350)
                            .ToListAsync();


                    }

Result:
ef-client-async took 197ms
0 Opening connection to database 'users-service' on server 'xx.cloudapi.de'.
0 Opened connection to database 'users-service' on server 'xx.database.cloudapi.de'.
0 Executing DbCommand [Parameters=[@__p_0='?'], CommandType='Text', CommandTimeout='30']
SELECT TOP(@__p_0) [u].[Id], [u].[FirstName], [u].[LastName]
FROM [users].[Users] AS [u]
125 Executed DbCommand (125ms) [Parameters=[@__p_0='?'], CommandType='Text', CommandTimeout='30']
SELECT TOP(@__p_0) [u].[Id], [u].[FirstName], [u].[LastName]
FROM [users].[Users] AS [u]
197 A data reader was disposed.
197 Closing connection to database 'users-service' on server 'xx.database.cloudapi.de'.
197 Closed connection to database 'users-service' on server 'xx.database.cloudapi.de'.

I would expect the async code to be slower but not 5 to 10 times.

I tried all available versions (preview 1, 2 and normal version).

My tests are generated with vs code on mac and in our docker images, e.g dotnet-nightly:2.1.0-preview1-runtime-stretch

Any ideas?

[saurabh500]

What OS is this on?

[saurabh500]

Looks like you are using macOS and connecting to Azure Sql. I know about this problem and there is a PR in progress to help alleviate asynchronous execution with asynchronous API in encrypted connections

Please confirm that I got your environment right.

[nils2612]

We can reproduce that problem on macosx, debian and ubuntu (docker and w/o docker).

Can you send me the pr?

[saurabh500]

https://github.com/dotnet/corefx/pull/27743

[saurabh500]

Basically non-Windows systems. Also you are seeing this with Encrypted connections, is that right?

[nils2612]

I tried to set encrypt to false, but i am not sure if that is working..

[nils2612]

If that's the right approach it didn't help..

[saurabh500]

With Azure Sql db, setting Encrypt=False doesn't help.
For Sql server and client protocol, the server has the last say in encryption. Even if the client says it doesn't want to encrypt, and the server says that it wants encryption, encryption will be used.
In case of Azure SQL DB, encryption is always forced by the server.

[nils2612]

Okay, understood. Just for clarification, does this pull request also effect the not async function, when encrypted? Because we just made other test load tests in none windows environments (w/o async) and we got other ssl related connection errors under high load. With windows its all working like a charm.

[saurabh500]

No the PR doesn't affect non-async scenarios on non-Windows. Can you post the errors?

[saurabh500]

Also what is the magnitude of the load that you are generating?

[nils2612]

A connection was successfully established with the server, but then an error occurred during the pre-login handshake. (provider: SSL Provider, error: 31 - Encryption(ssl/tls) handshake failed)

Feels weird, because 100% same code and same VM Size.

On Windows we were possible to do 350 req/sec of the "Sync ef example" from above. On linux on 20-40 req/sec the errors starts occurring frequently.

[saurabh500]

Is this error during the Connection.Open() phase?

[nils2612]

at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(System.Data.Common.DbConnection owningObject, System.UInt32 waitForMultipleObjectsTimeout, System.Boolean allowCreate, System.Boolean onlyOneCheckConnection, System.Data.Common.DbConnectionOptions userOptions, System.Data.ProviderBase.DbConnectionInternal& connection) in "System.Data.ProviderBase.DbConnectionPool" line 96
2
at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(System.Data.Common.DbConnection owningObject, System.Threading.Tasks.TaskCompletionSource1[System.Data.ProviderBase.DbConnectionInternal] retry, System.Data.Common.DbConnectionOptions userOptions, System.Data.ProviderBase.DbConnectionInternal& connection) in "System.Data.ProviderBase.DbConnectionPool" line 36 3 at System.Data.ProviderBase.DbConnectionFactory.TryGetConnection(System.Data.Common.DbConnection owningConnection, System.Threading.Tasks.TaskCompletionSource1[System.Data.ProviderBase.DbConnectionInternal] retry, System.Data.Common.DbConnectionOptions userOptions, System.Data.ProviderBase.DbConnectionInternal oldConnection, System.Data.ProviderBase.DbConnectionInternal& connection) in "System.Data.ProviderBase.DbConnectionFactory" line 541
4
at System.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(System.Data.Common.DbConnection outerConnection, System.Data.ProviderBase.DbConnectionFactory connectionFactory, System.Threading.Tasks.TaskCompletionSource1[System.Data.ProviderBase.DbConnectionInternal] retry, System.Data.Common.DbConnectionOptions userOptions) in "System.Data.ProviderBase.DbConnectionInternal" line 54 5 at System.Data.SqlClient.SqlConnection.TryOpen(System.Threading.Tasks.TaskCompletionSource1[System.Data.ProviderBase.DbConnectionInternal] retry) in "System.Data.SqlClient.SqlConnection" line 249
6
at System.Data.SqlClient.SqlConnection.Open() in "System.Data.SqlClient.SqlConnection" line 61
7
at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.Open(System.Boolean errorsExpected) in "Microsoft.EntityFrameworkCore.Storage.RelationalConnection" line 170
8
at Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable1+Enumerator.BufferlessMoveNext(System.Boolean buffer) in "Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable1+Enumerator" line 248
9
at Microsoft.EntityFrameworkCore.Storage.ExecutionStrategy.ExecuteImplementation(System.Func3[Microsoft.EntityFrameworkCore.DbContext,TState,TResult] operation, System.Func3[Microsoft.EntityFrameworkCore.DbContext,TState,Microsoft.EntityFrameworkCore.Storage.ExecutionResult1[TResult]] verifySucceeded, TState state) in "Microsoft.EntityFrameworkCore.Storage.ExecutionStrategy" line 126 10 at Microsoft.EntityFrameworkCore.Query.Internal.LinqOperatorProvider+<_TrackEntities>d__172.MoveNext() in "Microsoft.EntityFrameworkCore.Query.Internal.LinqOperatorProvider+<_TrackEntities>d__172" line 314 11 at Microsoft.EntityFrameworkCore.Query.Internal.LinqOperatorProvider+ExceptionInterceptor1+EnumeratorExceptionInterceptor.MoveNext() in "Microsoft.EntityFrameworkCore.Query.Internal.LinqOperatorProvider+ExceptionInterceptor1+EnumeratorExceptionInterceptor" line 65 12 at System.Collections.Generic.List1.AddEnumerable(System.Collections.Generic.IEnumerable1[T] enumerable) in "System.Collections.Generic.List1" line 89
13
at System.Linq.Enumerable.ToList(System.Collections.Generic.IEnumerable`1[TSource] source) in "System.Linq.Enumerable" line 30

[saurabh500]

Yes this is connection.Open() scenario. Also connection pool blocking period seems to be at play here, where the connection pool throws the cached error for 5 seconds in case a connection failed to establish in the connection pool.

Would it be possible for you to post a repo on Github with your repro?

[saurabh500]

Re

Would it be possible for you to post a repo on Github with your repro?

Preferably without EF.

[nils2612]

I can do that tomorrow, it's also reproducible without EF.

[saurabh500]

Sounds good.

[nils2612]

Here we are: https://github.com/nils2612/sql-client-repro

[MarkTiedemann]

When running a benchmark with microsoft/mssql-server-linux:2017-CU3 and microsoft/dotnet:2.0.0-sdk, I found async usage to create problems, too.

This code performed well as expected:

var reader = cmd.ExecuteReader();
while (reader.Read()) { ... }

This code, however, threw a bunch of SqlExceptions:

var reader = await cmd.ExecuteReaderAsync();
while (await reader.ReadAsync()) { ... }

System.Data.SqlClient.SqlException (0x80131904):

  A network-related or instance-specific error occurred while establishing a
  connection to SQL Server. The server was not found or was not accessible.
  Verify that the instance name is correct and that SQL Server is configured
  to allow remote connections.

  (provider: TCP Provider, error: 40 - Could not open a connection to SQL Server)

See MarkTiedemann/dotnet-sql-client-benchmark for details.

[nils2612]

Hi, we could resolve our problems by enforcing the min worker threads with these environment variables:
ENV COMPlus_ThreadPool_ForceMinWorkerThreads 200
ENV COMPlus_ThreadPool_ForceMaxWorkerThreads 10000
and using the ip of the database server instead of the hostname.

In combination we get almost as good results as in a windows test environment.
We reproduced it 50-80 times.. Changing back to hostname or changing the minworker threads always brings the number of concurrent requests down.

Is that expected? Known? Can we expect negative effects by doing that?

[saurabh500]

This is interesting that using the IP address increases throughput in your case. You are basically skipping the step in SqlClient which translates hostname to IP address.

ENV COMPlus_ThreadPool_ForceMinWorkerThreads 200
ENV COMPlus_ThreadPool_ForceMaxWorkerThreads 10000

Whether this will have a side effect or not, is dependent on the app and the thread requirements of other CoreCLR applications.

Is that expected? Known?

I know that there are some issues in SqlClient which can cause multiple threads to be spun up. Also in some cases sqlclient switches from sync sockets to async sockets and back based on the usage of the APIs which can cause more thread to be used.

[nils2612]

Okay, thanks for the feedback, did you try my repro? Is it reproducible on your side?

[saurabh500]

@keeratsingh is looking into a few issues in this area, where the connection pool doesn't scale. He had tried a few scenarios and is looking further into this.
What we figured out is that if the app targets netcoreapp2.0 the connection pool scaled better. We are trying to understand what caused this scalability regression for us.

[keeratsingh]

@nils2612
Could you kindly try the following workaround and see if it resolves your issue ?

• Add "Min Pool Size=50" keyword to the connection string.
• Call SqlConnection.Open() once to warm up the connection, before executing your application.

Regards,
Keerat

[nils2612]

@keeratsingh we tried that already.. lowered the problem a bit but the errors still occur with more connections. Did you try my repro repo on linux?

[keeratsingh]

@nils2612 Thank you for responding back.
Yes, I was able to repro the issue on Linux with Azure Sql DB with netcoreapp2.1
The issue was not seen with netcoreapp2.0 as tested, this issue is related to dotnet/runtime#25263 and we are actively working to find what has caused the regression.

Regards,
Keerat

[keeratsingh]

Edit: Adding Label Post-ZBB, explanation below:

Tomas(SslStream) was fully booked by the time we asked for his help, so he didn’t have time to look at it until Friday. It is now his top priority.

[David-Engel]

Duplicate of dotnet/runtime#25263 (which was addressed in 2.1.0)

Closing this to track a single issue for the underlying problem.

[stephentoub]

@David-Engel, are you sure it's the same issue? I'm just confused because it sounds like this issue is related to the performance of asynchronous operations, whereas dotnet/runtime#25263 is believed to be due to synchronous operations. Have I misunderstood?

[David-Engel]

@stephentoub We believe so. Both issues are hitting the underlying SSL library in a way that we believe is resulting in a large delay from that library. Reading through them, it sounds like the library is not properly handling a mix of sync and async operations. Even though this issue is about async, some underlying operations in SqlClient are necessarily sync in nature when calling the underlying stack.

[stephentoub]

t sounds like the library is not properly handling a mix of sync and async operations

Yes, there were two issues, and they a) made some synchronous operations more expensive by actually turning them into sync-over-async operations, and b) made sync-over-async operations require two threads instead of one, which can lead to significant scalability problems.

Even though this issue is about async, some underlying operations in SqlClient are necessarily sync in nature when calling the underlying stack.

Really? Meaning you might issue an async operation on SqlClient but internally it does synchronous ones? That's something we should fix.

[saurabh500]

@stephentoub The error we are tracking are during connection open, where a request to open a connection in connection pool is queued as a request to a single thread in the connection pool, and the running thread, opens all the requested connections synchronously.
All the connection opens in SqlClient are always sync.

[stephentoub]

Hmm. I'm not completely following. But if you believe this really is a dup and will be fixed by the other issue being fixed, ok, great :smile: Looking forward to confirmation of that for both this and the other.

[saurabh500]

This issue starts with slow data retrieval over async API calls on encrypted connections, which was fixed with https://github.com/dotnet/corefx/pull/27743
After further discussions on this issue, it seems like the opening of connection was turning out to be a bottle neck.

When a connection is opened async on SqlClient, SqlConnection.OpenAsync() is called.
In SqlClient, the connections are returned by a connection pool (unless the pool is turned off explicitly by the customer, which is not the case here)
When SqlConnection.OpenAsync() is called, it can do one of the following:

1. Return an idle connection from the pool if available.
2. Places a request for a new connection to be opened from the pool.

In either case, the OpenAsync() call returned immediately.
Every connection pool starts a thread in the thread pool. When dotnet/corefx#2 happens, where a new connection is requested, this thread gets a request. This thread can receive multiple requests for opening the connection.

The thread, then serially processes the connection requests, by establishing TCP connections and logging into the SQL Server. Once it gets a connection, it signals the task returned by SqlConnection.OpenAsync() and marking it Completed.

The connection pool opens the connections serially, so that it doesn't allow overloading the SqlServer with multiple requests at the same time.

So for all connection open calls, whether sync or async at the API level, the internal mechanism opens all the connections synchronously on a single thread.

Every connection pool creates one thread and each application typically has one connection pool.

[stephentoub]

After further discussions on this issue, it seems like the opening of connection was turning out to be a bottle neck.

This is helpful information, but with this statement, how is this a dup then of dotnet/runtime#25263? That's what I'm confused about. Are you saying that this issue is stemming from another connection pool getting created, which in turn requires another work item queued to the thread pool, but the thread pool was already saturated? Or something else?

[saurabh500]

This issue is not stemming from another connection pool being created, but underlying networking stack/SslStream opening the connection slower than before.

Assume that we have a connection timeout of 15 seconds on each connection and we request 15 connections from the connection pool at the same time. Connection pool will open all these connections serially or synchronously whether we call SqlConnection.Open or SqlConnection.OpenAsync

Connection 1 will take 1 second and complete at 1 seconds, Connection 2 will complete at 2 seconds, connection 3 will complete at 3 seconds and connection 15 will end up opening at 15 seconds and hence all the 15 connections open within the first 15 seconds if everything is working fine.

Now a bug causing SslStream to take longer is introduced and one of the connections takes 4 seconds to open, instead of 1. Lets assume that the 4th connection takes 4 seconds to open.

Now, connection 3 completes at 3 seconds mark, connection 4 completes at 7 seconds mark and after connection 12, the 15 seconds timeout of the connection pool would have expired, and that would cause the last 3 connections to timeout.

The connection pool can now only hand out 12 connections instead of 15 because of the slow down of SslStream.

The reason this is a dupe, is because both issues suffer from the same problems while handing out connections from the pool.

The pool doesn't start a timeout timer for each connection it is trying to open. The timer is started when the connection request gets to the pool to the time when the connection is returned from the pool.