Time taken to create server connection is sometimes far greater than it should be

[kfreezen]

I think this is related to #486 and #466 but opening a new issue because I've pinpointed a problem.

I decided to log the times in TimeLine to the console and I noticed that the difference between Request Received and Server Connection Created can run from 3-20 seconds.

Excerpt from the log:

Session Created=00:00:00
Request Received=00:00:00.0000349
After invokeBeforeRequest=00:00:01.2515124
After prefetchTask if=00:00:01.2515139
After GetConnectionCacheKey=00:00:01.2515147
After generator creation=00:00:01.2515151
Server Connection Created=00:00:43.6580544


Session Created=00:00:00
Request Received=00:00:00.0000410
After invokeBeforeRequest=00:00:00.0004671
After prefetchTask if=00:00:00.0004679
After GetConnectionCacheKey=00:00:00.0004690
After generator creation=00:00:00.0004690
Server Connection Created=00:00:21.2557844


Session Created=00:00:00
Request Received=00:00:00.0000345
After invokeBeforeRequest=00:00:00.0004029
After prefetchTask if=00:00:00.0004033
After GetConnectionCacheKey=00:00:00.0004040
After generator creation=00:00:00.0004040
Server Connection Created=00:00:21.3582822


Session Created=00:00:00
Request Received=00:00:00.0000345
After invokeBeforeRequest=00:00:00.0004360
After prefetchTask if=00:00:00.0004363
After GetConnectionCacheKey=00:00:00.0004371
After generator creation=00:00:00.0004371
Server Connection Created=00:00:21.1989975


Session Created=00:00:00
Request Received=00:00:00.0000349
After invokeBeforeRequest=00:00:00.0004177
After prefetchTask if=00:00:00.0004185
After GetConnectionCacheKey=00:00:00.0004189
After generator creation=00:00:00.0004192
Server Connection Created=00:00:21.3541475


Session Created=00:00:00
Request Received=00:00:00.0000345
After invokeBeforeRequest=00:00:00.0004436
After prefetchTask if=00:00:00.0004443
After GetConnectionCacheKey=00:00:00.0004447
After generator creation=00:00:00.0004451
Server Connection Created=00:00:42.4095211


Session Created=00:00:00
Request Received=00:00:00.0000406
After invokeBeforeRequest=00:00:00.0004135
After prefetchTask if=00:00:00.0004139
After GetConnectionCacheKey=00:00:00.0004147
After generator creation=00:00:00.0004151
Server Connection Created=00:00:42.1948350


Session Created=00:00:00
Request Received=00:00:00.0000342
After invokeBeforeRequest=00:00:00.0004200
After prefetchTask if=00:00:00.0004204
After GetConnectionCacheKey=00:00:00.0004208
After generator creation=00:00:00.0004211
Server Connection Created=00:00:42.1896435


Session Created=00:00:00
Request Received=00:00:00.0000357
After invokeBeforeRequest=00:00:00.0004299
After prefetchTask if=00:00:00.0004303
After GetConnectionCacheKey=00:00:00.0004306
After generator creation=00:00:00.0004310
Server Connection Created=00:01:03.3936918

Those four After --- I have added in my dev version.

I haven't dug into whether it's the TcpClient() constructor or the ConnectAsync() function yet.

Do you have any ideas on what could be causing this?

[kfreezen]

Drilling down into GetServerConnection() it looks like we have two bottlenecks: ConnectAsync()

see

before-tcp-ctor 0
after-tcp-ctor 0
after-connect 21182
after-custom-buffered-stream-ctor 21182
before-ssl 21182
after-custom-stream-ctor 21182
after-authenticate-as-client-async 21420

and AuthenticateAsClientAsync()

before-tcp-ctor 0
after-tcp-ctor 2
after-connect 185
after-custom-buffered-stream-ctor 185
before-ssl 185
after-custom-stream-ctor 185
after-authenticate-as-client-async 5554

Not every request has such long delays as what is seen here. It seems to be somewhat intermittent.

edit to add: Perhaps this is normal behavior? How could we determine whether that is or isn't the case?

[justcoding121]

I've added Dns resolution time to TimeLine in latest beta release, which perhaps would give more details on server connection process. But I am not sure what exactly is causing this.

[kfreezen]

I did some more logging with the DNS resolution time. It looks completely random to me, which makes me wonder if there's something odd going on in the threadings/tasks/async.

I did check ThreadPool usage and concluded that the problem isn't because of ThreadPool exhaustion, but I can't say that with 100% certainty.

I also noticed that Microsoft's https://github.com/dotnet/corefx uses ConfigureAwait(false); in its SocketsHttpHandler, but I am not convinced that using that is going to solve any problem in this situation. Is your proxy code 100% async or are there some spots where synchronous code waits for asynchronous code to complete?

edit: After reading about thread pool injection rate, I think there's a possibility that that is the problem.

[justcoding121]

I cant recall any place we are waiting for sync to complete from async. Its async end to end.

[justcoding121]

Also note that you may not have Dns Resolved/Connection Established/Http Established events in timeline when session picks up the connection from cache. In that case the session will only have Connection Ready.

[justcoding121]

Also I noted that when I run in .Net desktop version for example 4.5 the proxy behaves more sanely even when I open 50+ tabs in Chrome. But on .Net core the process sometimes abruptly terminates and connections increase at a much higher rate and hits 500+ server connections. (as opposed to 100+ when using .Net framework). Tested on a 8 GB ram windows 10 running on a hypervisor powered by Xeon CPU with 4 CPU cores allocated.

[justcoding121]

You can probably try different parameters to see if it would make any difference. For example by disabling connection pool and/or prefetch.

Relevant flags are MaxCachedConnections, EnableConnectionPool, EnableTcpServerConnectionPrefetch, ConnectionTimeOutSeconds, MaxCachedConnections, TcpTimeWaitSeconds, ReuseSocket, BufferSize.

[kfreezen]

Posting this here, because it's timing related again. I can create a new issue for this comment if you'd rather.

I commented about this issue in #471

The problem I'm seeing is related to websockets. They work but send/receives from the https://websocket.org/echo.html are delayed by 10-20 seconds.

It looks like what's happening is that the server stream's write call is waiting on the read call to the server stream (in StreamExtensions.CopyToAsync) and this is yielding a delay.

Is this something you can reproduce on your machine @justcoding121? I'm beginning to wonder if there's something different about my environment that's making these timing issues crop up. If it is, I'd like to figure out the difference.

Are you using a VPS or a physical machine for your testing environment?

By the way, I really appreciate all the time you've put into helping me with this stuff!

[justcoding121]

@kfreezen I debugged and found that this Websocket issue appears to be a problem on Windows with .net 4.5 or even the latest .net 4.7.2. Its a bug with WriteAsync method of inner Stream used by CustomBufferedStream. It hangs for couple of seconds. The bug is with the inner Stream.WriteAsync call (may be only when Stream is an SslStream) which hangs for couple of seconds arbitrarily. I believe it has an internal buffer so it flushes only when buffer is full or when some arbitrary seconds have elapsed.

But when you run the project in .Net Core 2.0 I don't see the problem.

[justcoding121]

Particular call that causes the delay is in StreamExtended library.
https://github.com/justcoding121/Stream-Extended/blob/master/src/StreamExtended/Network/CustomBufferedStream.cs#L288

[justcoding121]

A solution is the make that call synchronous, and I see it disappears. This means all Write calls will be synchronous. I will have to push that change in future for .Net windows framework versions.

[justcoding121]

Websocket issue should be fixed in latest beta

[kfreezen]

Thanks!

…

On Wed, Oct 10, 2018 at 11:02 AM Jehonathan Thomas ***@***.***> wrote: Websocket issue should be fixed in latest beta — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#495 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAVLLIBegLlYrZWXrCW7Xa6cMEu7UsSPks5ujgwOgaJpZM4W7XWM> .