StackExchange.Redis ConnectionMultiplexer takes up to 2 seconds to connect when run from within AWS lambda

We recently moved from running on physical machines to using AWS Lambda. I have determined that initial connection times are super slow when we run from Lambda. At first I thought this was an AWS issue so I reached out to their engineers and I had them reproduce the issue. However when they switch to a different runtime(python), the issue is not present and so they said it isn't related to the lambda itself but something in our client that we connect with.

Otherwise this SDK functions perfectly correctly, its just the initial connection times.

Is there any community where people use stack exchange redis on lambda? Somebody else must have noticed this as its quite impacting request performance.

We are connecting to a redis cluster with many shards incase that is relevant.

Feb 28 '22 00:02 greyhoundgames

When you call connect, it takes a TextWriter to log to - can you please use that overload and post the log here? That'll help us advise :)

Feb 28 '22 13:02 NickCraver

Thanks for replying! Here is what you asked for.

zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Connecting... zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: BeginConnectAsync 1 unique nodes specified zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting) Allowing 1 endpoint(s) 00:00:03 to respond... Awaiting 1 available task completion(s) for 3000ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767) zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Connected zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Server handshake zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Setting client name: 169 zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configuring... zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Sending critical tracer (handshake): ECHO zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Writing: ECHO zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Flushing outbound buffer zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnEstablishingAsync complete zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Starting read zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) version: 6.0.5 zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) server-type: cluster zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) role: replica Response from zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive / ECHO: BulkString: 16 bytes zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnConnectedAsync completed (From command: ECHO) All 1 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=3,Free=32764,Min=2,Max=32767) zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished Election: Gathering tie-breakers... zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")... zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Writing: GET __Booksleeve_TieBreak zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Returned with success as Cluster replica (Source: From command: ECHO) Response from zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive / GET __Booksleeve_TieBreak: (null) 10.2.191.128:6379: OnConnectedAsync already connected start 10.2.191.128:6379/Interactive: Writing: PING 10.2.170.226:6379: OnConnectedAsync already connected start 10.2.170.226:6379/Interactive: Writing: PING 10.2.179.50:6379: OnConnectedAsync already connected start 10.2.179.50:6379/Interactive: Writing: PING Response from 10.2.191.128:6379/Interactive / PING: SimpleString: PONG 10.2.164.21:6379: OnConnectedAsync already connected start 10.2.164.21:6379/Interactive: Writing: PING Allowing 4 endpoint(s) 00:00:02.3600000 to respond... Awaiting 4 available task completion(s) for 2360ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=3,Free=32764,Min=2,Max=32767) 10.2.191.128:6379: OnConnectedAsync already connected end Response from 10.2.179.50:6379/Interactive / PING: SimpleString: PONG 10.2.179.50:6379: OnConnectedAsync already connected end Response from 10.2.170.226:6379/Interactive / PING: SimpleString: PONG 10.2.170.226:6379: OnConnectedAsync already connected end Response from 10.2.164.21:6379/Interactive / PING: SimpleString: PONG 10.2.164.21:6379: OnConnectedAsync already connected end All 4 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=1,Free=32766,Min=2,Max=32767) 10.2.191.128:6379: Endpoint is ConnectedEstablished 10.2.170.226:6379: Endpoint is ConnectedEstablished 10.2.179.50:6379: Endpoint is ConnectedEstablished 10.2.164.21:6379: Endpoint is ConnectedEstablished Election: Gathering tie-breakers... 10.2.191.128:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")... 10.2.191.128:6379/Interactive: Writing: GET __Booksleeve_TieBreak 10.2.170.226:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")... 10.2.170.226:6379/Interactive: Writing: GET __Booksleeve_TieBreak 10.2.179.50:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")... 10.2.179.50:6379/Interactive: Writing: GET __Booksleeve_TieBreak 10.2.164.21:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")... 10.2.164.21:6379/Interactive: Writing: GET __Booksleeve_TieBreak 10.2.191.128:6379: Returned with success as Cluster primary (Source: Already connected) 10.2.170.226:6379: Returned with success as Cluster replica (Source: Already connected) 10.2.179.50:6379: Returned with success as Cluster replica (Source: Already connected) 10.2.164.21:6379: Returned with success as Cluster primary (Source: Already connected) Cluster: 16384 of 16384 slots covered zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Cluster v6.0.5, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active Response from 10.2.191.128:6379/Interactive / GET __Booksleeve_TieBreak: (null) Response from 10.2.179.50:6379/Interactive / GET __Booksleeve_TieBreak: Error: MOVED 6202 10.2.191.128:6379 Response from 10.2.164.21:6379/Interactive / GET __Booksleeve_TieBreak: Error: MOVED 6202 10.2.191.128:6379 Response from 10.2.170.226:6379/Interactive / GET __Booksleeve_TieBreak: (null) zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1, non-pref=1; sub ops=3, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1 zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 0+3=3 (0.30 ops/s; spans 10s) 10.2.191.128:6379: Cluster v6.0.5, master; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 10.2.191.128:6379: int ops=11, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 10.2.191.128:6379: Circular op-count snapshot; int: 0+11=11 (1.10 ops/s; spans 10s); sub: 10.2.164.21:6379: Cluster v6.0.5, master; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 10.2.164.21:6379: int ops=11, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 10.2.164.21:6379: Circular op-count snapshot; int: 0+11=11 (1.10 ops/s; spans 10s); sub: 10.2.179.50:6379: Cluster v6.0.5, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 10.2.179.50:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 10.2.179.50:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 10.2.170.226:6379: Cluster v6.0.5, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 10.2.170.226:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 10.2.170.226:6379: Circular op-cou Connect log:zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379,asyncTimeout=3000,connectTimeout=3000,abortConnect=False,connectRetry=1 zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Connecting... zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: BeginConnectAsync 1 unique nodes specified zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting) Allowing 1 endpoint(s) 00:00:03 to respond... Awaiting 1 available task completion(s) for 3000ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767) zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Connected zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Server handshake zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Setting client name: 169 zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configuring... zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Sending critical tracer (handshake): ECHO zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Writing: ECHO zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Flushing outbound buffer zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnEstablishingAsync complete zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Starting read zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) version: 6.0.5 zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) server-type: cluster zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) role: replica Response from zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive / ECHO: BulkString: 16 bytes zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnConnectedAsync completed (From command: ECHO) All 1 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=3,Free=32764,Min=2,Max=32767) zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished Election: Gathering tie-breakers... zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")... zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Writing: GET __Booksleeve_TieBreak zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Returned with success as Cluster replica (Source: From command: ECHO) Response from zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive / GET __Booksleeve_TieBreak: (null) 10.2.191.128:6379: OnConnectedAsync already connected start 10.2.191.128:6379/Interactive: Writing: PING 10.2.170.226:6379: OnConnectedAsync already connected start 10.2.170.226:6379/Interactive: Writing: PING 10.2.179.50:6379: OnConnectedAsync already connected start 10.2.179.50:6379/Interactive: Writing: PING Response from 10.2.191.128:6379/Interactive / PING: SimpleString: PONG 10.2.164.21:6379: OnConnectedAsync already connected start 10.2.164.21:6379/Interactive: Writing: PING Allowing 4 endpoint(s) 00:00:02.3600000 to respond... Awaiting 4 available task completion(s) for 2360ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=3,Free=32764,Min=2,Max=32767) 10.2.191.128:6379: OnConnectedAsync already connected end Response from 10.2.179.50:6379/Interactive / PING: SimpleString: PONG 10.2.179.50:6379: OnConnectedAsync already connected end Response from 10.2.170.226:6379/Interactive / PING: SimpleString: PONG 10.2.170.226:6379: OnConnectedAsync already connected end Response from 10.2.164.21:6379/Interactive / PING: SimpleString: PONG 10.2.164.21:6379: OnConnectedAsync already connected end All 4 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=1,Free=32766,Min=2,Max=32767) 10.2.191.128:6379: Endpoint is ConnectedEstablished 10.2.170.226:6379: Endpoint is ConnectedEstablished 10.2.179.50:6379: Endpoint is ConnectedEstablished 10.2.164.21:6379: Endpoint is ConnectedEstablished Election: Gathering tie-breakers... 10.2.191.128:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")... 10.2.191.128:6379/Interactive: Writing: GET __Booksleeve_TieBreak 10.2.170.226:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")... 10.2.170.226:6379/Interactive: Writing: GET __Booksleeve_TieBreak 10.2.179.50:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")... 10.2.179.50:6379/Interactive: Writing: GET __Booksleeve_TieBreak 10.2.164.21:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")... 10.2.164.21:6379/Interactive: Writing: GET __Booksleeve_TieBreak 10.2.191.128:6379: Returned with success as Cluster primary (Source: Already connected) 10.2.170.226:6379: Returned with success as Cluster replica (Source: Already connected) 10.2.179.50:6379: Returned with success as Cluster replica (Source: Already connected) 10.2.164.21:6379: Returned with success as Cluster primary (Source: Already connected) Cluster: 16384 of 16384 slots covered zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Cluster v6.0.5, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active Response from 10.2.191.128:6379/Interactive / GET __Booksleeve_TieBreak: (null) Response from 10.2.179.50:6379/Interactive / GET __Booksleeve_TieBreak: Error: MOVED 6202 10.2.191.128:6379 Response from 10.2.164.21:6379/Interactive / GET __Booksleeve_TieBreak: Error: MOVED 6202 10.2.191.128:6379 Response from 10.2.170.226:6379/Interactive / GET __Booksleeve_TieBreak: (null) zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1, non-pref=1; sub ops=3, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1 zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 0+3=3 (0.30 ops/s; spans 10s) 10.2.191.128:6379: Cluster v6.0.5, master; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 10.2.191.128:6379: int ops=11, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 10.2.191.128:6379: Circular op-count snapshot; int: 0+11=11 (1.10 ops/s; spans 10s); sub: 10.2.164.21:6379: Cluster v6.0.5, master; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 10.2.164.21:6379: int ops=11, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 10.2.164.21:6379: Circular op-count snapshot; int: 0+11=11 (1.10 ops/s; spans 10s); sub: 10.2.179.50:6379: Cluster v6.0.5, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 10.2.179.50:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 10.2.179.50:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 10.2.170.226:6379: Cluster v6.0.5, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 10.2.170.226:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 10.2.170.226:6379: Circular op-cou

Feb 28 '22 23:02 greyhoundgames

Which version of the library is in use here? I'm mobile at the moment but swear I put version into logging in the more recent releases (high also have connection improvements). If not on latest (2.2.88+), I highly recommend upgrading and re-running logs.

Mar 01 '22 04:03 NickCraver

Ok I Have upgraded from 2.2.62 to the latest nuget 2.2.88. The connection time unfortunately is still long, about 1.4 seconds. Here is the new log

Connect log:zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379,asyncTimeout=3000,connectTimeout=3000,abortConnect=False,connectRetry=1zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Connecting...zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: BeginConnectAsync1 unique nodes specifiedzir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)Allowing 1 endpoint(s) 00:00:03 to respond...Awaiting 1 available task completion(s) for 3000ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767)zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Connected zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Server handshakezir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Setting client name: 169zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configuring...zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Sending critical tracer (handshake): ECHOzir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Writing: ECHOzir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Flushing outbound bufferzir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnEstablishingAsync completezir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Starting readzir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) version: 6.0.5zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) server-type: clusterzir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) role: replicaResponse from zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive / ECHO: BulkString: 16 bytesAll 1 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=3,Free=32764,Min=2,Max=32767)zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Endpoint is ConnectedEstablishedElection: Gathering tie-breakers...zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")...zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Writing: GET __Booksleeve_TieBreakzir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Returned with success as Cluster replica (Source: From command: ECHO)zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnConnectedAsync completed (From command: ECHO)Response from zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive / GET __Booksleeve_TieBreak: (null)10.2.191.128:6379: OnConnectedAsync already connected start10.2.191.128:6379/Interactive: Writing: PINGResponse from 10.2.191.128:6379/Interactive / PING: SimpleString: PONG10.2.170.226:6379: OnConnectedAsync already connected start10.2.170.226:6379/Interactive: Writing: PING10.2.179.50:6379: OnConnectedAsync already connected start10.2.179.50:6379/Interactive: Writing: PING10.2.164.21:6379: OnConnectedAsync already connected start10.2.164.21:6379/Interactive: Writing: PINGAllowing 4 endpoint(s) 00:00:02.3400000 to respond...Awaiting 4 available task completion(s) for 2340ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=3,Free=32764,Min=2,Max=32767)Response from 10.2.179.50:6379/Interactive / PING: SimpleString: PONG10.2.191.128:6379: OnConnectedAsync already connected end10.2.179.50:6379: OnConnectedAsync already connected endResponse from 10.2.164.21:6379/Interactive / PING: SimpleString: PONGResponse from 10.2.170.226:6379/Interactive / PING: SimpleString: PONG10.2.170.226:6379: OnConnectedAsync already connected end10.2.164.21:6379: OnConnectedAsync already connected endAll 4 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767)10.2.191.128:6379: Endpoint is ConnectedEstablished10.2.170.226:6379: Endpoint is ConnectedEstablished10.2.179.50:6379: Endpoint is ConnectedEstablished10.2.164.21:6379: Endpoint is ConnectedEstablishedElection: Gathering tie-breakers...10.2.191.128:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")...10.2.191.128:6379/Interactive: Writing: GET __Booksleeve_TieBreak10.2.170.226:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")...10.2.170.226:6379/Interactive: Writing: GET __Booksleeve_TieBreak10.2.179.50:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")...10.2.179.50:6379/Interactive: Writing: GET __Booksleeve_TieBreak10.2.164.21:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")...10.2.164.21:6379/Interactive: Writing: GET __Booksleeve_TieBreak10.2.191.128:6379: Returned with success as Cluster primary (Source: Already connected)10.2.170.226:6379: Returned with success as Cluster replica (Source: Already connected)10.2.179.50:6379: Returned with success as Cluster replica (Source: Already connected)10.2.164.21:6379: Returned with success as Cluster primary (Source: Already connected)Cluster: 16384 of 16384 slots coveredResponse from 10.2.191.128:6379/Interactive / GET __Booksleeve_TieBreak: (null)Response from 10.2.179.50:6379/Interactive / GET __Booksleeve_TieBreak: Error: MOVED 6202 10.2.191.128:6379zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Cluster v6.0.5, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 activezir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1, non-pref=1; sub ops=3, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1Response from 10.2.170.226:6379/Interactive / GET __Booksleeve_TieBreak: (null)Response from 10.2.164.21:6379/Interactive / GET __Booksleeve_TieBreak: Error: MOVED 6202 10.2.191.128:6379zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 0+3=3 (0.30 ops/s; spans 10s)10.2.191.128:6379: Cluster v6.0.5, master; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a10.2.191.128:6379: int ops=11, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=010.2.191.128:6379: Circular op-count snapshot; int: 0+11=11 (1.10 ops/s; spans 10s); sub:10.2.164.21:6379: Cluster v6.0.5, master; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a10.2.164.21:6379: int ops=11, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=010.2.164.21:6379: Circular op-count snapshot; int: 0+11=11 (1.10 ops/s; spans 10s); sub:10.2.170.226:6379: Cluster v6.0.5, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a10.2.170.226:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=010.2.170.226:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub:10.2.179.50:6379: Cluster v6.0.5, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a10.2.179.50:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=010.2.179.50:6379: Circular op-cou | Connect log:zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379,asyncTimeout=3000,connectTimeout=3000,abortConnect=False,connectRetry=1 zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Connecting... zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: BeginConnectAsync 1 unique nodes specified zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting) Allowing 1 endpoint(s) 00:00:03 to respond... Awaiting 1 available task completion(s) for 3000ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767) zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Connected zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Server handshake zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Setting client name: 169 zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configuring... zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Sending critical tracer (handshake): ECHO zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Writing: ECHO zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Flushing outbound buffer zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnEstablishingAsync complete zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Starting read zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) version: 6.0.5 zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) server-type: cluster zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) role: replica Response from zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive / ECHO: BulkString: 16 bytes All 1 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=3,Free=32764,Min=2,Max=32767) zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished Election: Gathering tie-breakers... zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")... zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Writing: GET __Booksleeve_TieBreak zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Returned with success as Cluster replica (Source: From command: ECHO) zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnConnectedAsync completed (From command: ECHO) Response from zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive / GET __Booksleeve_TieBreak: (null) 10.2.191.128:6379: OnConnectedAsync already connected start 10.2.191.128:6379/Interactive: Writing: PING Response from 10.2.191.128:6379/Interactive / PING: SimpleString: PONG 10.2.170.226:6379: OnConnectedAsync already connected start 10.2.170.226:6379/Interactive: Writing: PING 10.2.179.50:6379: OnConnectedAsync already connected start 10.2.179.50:6379/Interactive: Writing: PING 10.2.164.21:6379: OnConnectedAsync already connected start 10.2.164.21:6379/Interactive: Writing: PING Allowing 4 endpoint(s) 00:00:02.3400000 to respond... Awaiting 4 available task completion(s) for 2340ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=3,Free=32764,Min=2,Max=32767) Response from 10.2.179.50:6379/Interactive / PING: SimpleString: PONG 10.2.191.128:6379: OnConnectedAsync already connected end 10.2.179.50:6379: OnConnectedAsync already connected end Response from 10.2.164.21:6379/Interactive / PING: SimpleString: PONG Response from 10.2.170.226:6379/Interactive / PING: SimpleString: PONG 10.2.170.226:6379: OnConnectedAsync already connected end 10.2.164.21:6379: OnConnectedAsync already connected end All 4 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767) 10.2.191.128:6379: Endpoint is ConnectedEstablished 10.2.170.226:6379: Endpoint is ConnectedEstablished 10.2.179.50:6379: Endpoint is ConnectedEstablished 10.2.164.21:6379: Endpoint is ConnectedEstablished Election: Gathering tie-breakers... 10.2.191.128:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")... 10.2.191.128:6379/Interactive: Writing: GET __Booksleeve_TieBreak 10.2.170.226:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")... 10.2.170.226:6379/Interactive: Writing: GET __Booksleeve_TieBreak 10.2.179.50:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")... 10.2.179.50:6379/Interactive: Writing: GET __Booksleeve_TieBreak 10.2.164.21:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")... 10.2.164.21:6379/Interactive: Writing: GET __Booksleeve_TieBreak 10.2.191.128:6379: Returned with success as Cluster primary (Source: Already connected) 10.2.170.226:6379: Returned with success as Cluster replica (Source: Already connected) 10.2.179.50:6379: Returned with success as Cluster replica (Source: Already connected) 10.2.164.21:6379: Returned with success as Cluster primary (Source: Already connected) Cluster: 16384 of 16384 slots covered Response from 10.2.191.128:6379/Interactive / GET __Booksleeve_TieBreak: (null) Response from 10.2.179.50:6379/Interactive / GET __Booksleeve_TieBreak: Error: MOVED 6202 10.2.191.128:6379 zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Cluster v6.0.5, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1, non-pref=1; sub ops=3, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1 Response from 10.2.170.226:6379/Interactive / GET __Booksleeve_TieBreak: (null) Response from 10.2.164.21:6379/Interactive / GET __Booksleeve_TieBreak: Error: MOVED 6202 10.2.191.128:6379 zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 0+3=3 (0.30 ops/s; spans 10s) 10.2.191.128:6379: Cluster v6.0.5, master; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 10.2.191.128:6379: int ops=11, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 10.2.191.128:6379: Circular op-count snapshot; int: 0+11=11 (1.10 ops/s; spans 10s); sub: 10.2.164.21:6379: Cluster v6.0.5, master; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 10.2.164.21:6379: int ops=11, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 10.2.164.21:6379: Circular op-count snapshot; int: 0+11=11 (1.10 ops/s; spans 10s); sub: 10.2.170.226:6379: Cluster v6.0.5, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 10.2.170.226:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 10.2.170.226:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 10.2.179.50:6379: Cluster v6.0.5, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 10.2.179.50:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 10.2.179.50:6379: Circular op-cou

Mar 01 '22 14:03 greyhoundgames

@greyhoundgames My fault! The latest prerelease has the tie breaker and connection changes - either the latest on MyGet or the unlisted on NuGet will have the tiebreaker changes in there. Can you give this release a try and see if it speeds up your connection? https://www.nuget.org/packages/StackExchange.Redis/2.5.34-prerelease

I was trying to figure out why the logs didn't jive with memory and it's because 2.2.88 doesn't have the new hotness either, sorry!

Mar 02 '22 01:03 NickCraver

I'm still not seeing a version in the log. My packages in visual studio shows that I'm on that pre-release... not sure. I really appreciate your help!

Connect log:Connecting (sync) on .NET Core 3.1.22 03:27:21.2935: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379,asyncTimeout=3000,connectTimeout=3000,abortConnect=False,connectRetry=1

03:27:21.3382: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Connecting... 03:27:21.3960: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: BeginConnectAsync 03:27:21.5349: 1 unique nodes specified (with tiebreaker) 03:27:21.5356: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting) 03:27:21.5360: Allowing 1 endpoint(s) 00:00:03 to respond... 03:27:21.5528: Awaiting 1 available task completion(s) for 3000ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=0,CompletedItems=6) 03:27:21.6335: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Connected 03:27:21.6527: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Server handshake 03:27:21.7325: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Setting client name: 169(v2.5.34.40405) 03:27:21.7735: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configuring... 03:27:21.7751: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")... 03:27:21.7758: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Writing: GET __Booksleeve_TieBreak 03:27:21.7974: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Sending critical tracer (handshake): ECHO 03:27:21.7975: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Writing: ECHO 03:27:21.7975: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Flushing outbound buffer 03:27:21.7977: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnEstablishingAsync complete 03:27:21.7981: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Starting read 03:27:21.9367: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) role: replica 03:27:21.9380: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) version: 6.0.5 03:27:21.9381: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) server-type: cluster 03:27:22.0124: Response from zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive / GET __Booksleeve_TieBreak: Error: MOVED 6202 10.2.191.128:6379 03:27:22.0130: Response from zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive / ECHO: BulkString: 16 bytes 03:27:22.0326: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnConnectedAsync completed (From command: ECHO) 03:27:22.0337: All 1 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=1,Free=32766,Min=2,Max=32767), POOL: (Threads=3,QueuedItems=0,CompletedItems=30) 03:27:22.0541: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished 03:27:22.0542: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Returned with success as Cluster replica (Source: From command: ECHO) 03:27:22.0782: 10.2.164.21:6379: OnConnectedAsync already connected start 03:27:22.0787: 10.2.164.21:6379/Interactive: Writing: PING 03:27:22.0795: 10.2.170.226:6379: OnConnectedAsync already connected start 03:27:22.0795: 10.2.170.226:6379/Interactive: Writing: PING 03:27:22.0796: 10.2.179.50:6379: OnConnectedAsync already connected start 03:27:22.0796: 10.2.179.50:6379/Interactive: Writing: PING 03:27:22.0796: 10.2.191.128:6379: OnConnectedAsync already connected start 03:27:22.0796: 10.2.191.128:6379/Interactive: Writing: PING 03:27:22.0797: Allowing 4 endpoint(s) 00:00:02.4570000 to respond... 03:27:22.0797: Awaiting 4 available task completion(s) for 2457ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=3,Free=32764,Min=2,Max=32767), POOL: (Threads=3,QueuedItems=0,CompletedItems=44) 03:27:22.0936: Response from 10.2.170.226:6379/Interactive / PING: SimpleString: PONG 03:27:22.0937: Response from 10.2.164.21:6379/Interactive / PING: SimpleString: PONG 03:27:22.0938: Response from 10.2.179.50:6379/Interactive / PING: SimpleString: PONG 03:27:22.0940: Response from 10.2.191.128:6379/Interactive / PING: SimpleString: PONG 03:27:22.0947: 10.2.179.50:6379: OnConnectedAsync already connected end 03:27:22.0947: 10.2.164.21:6379: OnConnectedAsync already connected end 03:27:22.0948: 10.2.191.128:6379: OnConnectedAsync already connected end 03:27:22.0948: 10.2.170.226:6379: OnConnectedAsync already connected end 03:27:22.0948: All 4 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767), POOL: (Threads=3,QueuedItems=0,CompletedItems=53) 03:27:22.0949: 10.2.164.21:6379: Endpoint is ConnectedEstablished 03:27:22.0949: 10.2.170.226:6379: Endpoint is ConnectedEstablished 03:27:22.0949: 10.2.179.50:6379: Endpoint is ConnectedEstablished 03:27:22.0949: 10.2.191.128:6379: Endpoint is ConnectedEstablished 03:27:22.0949: 10.2.164.21:6379: Returned with success as Cluster primary (Source: Already connected) 03:27:22.0949: 10.2.170.226:6379: Returned with success as Cluster replica (Source: Already connected) 03:27:22.0949: 10.2.179.50:6379: Returned with success as Cluster replica (Source: Already connected) 03:27:22.0949: 10.2.191.128:6379: Returned with success as Cluster primary (Source: Already connected) 03:27:22.0952: Cluster: 16384 of 16384 slots covered 03:27:22.1129: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Cluster v6.0.5, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active 03:27:22.1140: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: int ops=13, qu=0, qs=0, qc=0, wr=0, socks=1, non-pref=1; sub ops=3, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1 03:27:22.1156: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+13=13 (1.30 ops/s; spans 10s); sub: 0+3=3 (0.30 ops/s; spans 10s) 03:27:22.1156: 10.2.164.21:6379: Cluster v6.0.5, master; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 03:27:22.1156: 10.2.164.21:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 03:27:22.1156: 10.2.164.21:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 03:27:22.1156: 10.2.191.128:6379: Cluster v6.0.5, master; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 03:27:22.1156: 10.2.191.128:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 03:27:22.1156: 10.2.191.128:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 03:27:22.1156: 10.2.179.50:6379: Cluster v6.0.5, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 03:27:22.1156: 10.2.179.50:6379: int ops=13, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 03:27:22.1156: 10.2.179.50:637

Mar 02 '22 03:03 greyhoundgames

Alrighty, awesome - I'll add an explicit version to the log as a follow-up :)

In the latest, I see an overall of 03:27:21.2935 to 03:27:22.1156, which means about 820ms and judging by the gaps in certain places like:

03:27:22.0797: Awaiting 4 available task completion(s) for 2457ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=3,Free=32764,Min=2,Max=32767), POOL: (Threads=3,QueuedItems=0,CompletedItems=44)
03:27:22.0936: Response from 10.2.170.226:6379/Interactive / PING: SimpleString: PONG
03:27:22.0937: Response from 10.2.164.21:6379/Interactive / PING: SimpleString: PONG
03:27:22.0938: Response from 10.2.179.50:6379/Interactive / PING: SimpleString: PONG
03:27:22.0940: Response from 10.2.191.128:6379/Interactive / PING: SimpleString: PONG

...I see about a ~140ms latency to the Redis server. It looks like in other places though, this may be JIT time spinning up code for the first time (which I'd expect on Lambda often).

Overall (and check me here), it looks like:

Latest release drops from ~2 seconds to ~820ms
There's JIT (first time startup of .NET code) time involved

The latter is a guess, but the way I'd recommend testing this is to release with precompiled code, e.g. AOT or "ReadyToRun" it's sometimes called. In situations where startup matters, you'll generally have a good performance boost there. The other way to test this easily is to connect, throw away that multiplexer, and connect again in the same process and post that log here - happy to help verify!

Mar 02 '22 13:03 NickCraver

I am going to try those things and also I noticed that Lambda just came out with .net 6 support(im using .net core) which claims improvements in JIT as well so I will run it on that first as well and give you some times.

Also I was inaccurate in the title of this post, it should have said as much as 2 seconds. I have seen slower connections in the past but looking at yesterdays time stamps of the older version and the new, I'm seeing around 1.4 seconds on the older stack exchange redis and on the one you provided I see 1.1-1.2. My timings are coming via just a Log directly before and after the connect call(I use the lazy code style as shown in the stack exchange samples incase that is relevant).

Mar 02 '22 17:03 greyhoundgames

Some really interesting results when using a JIT setting in the project file!

core CS#1 1328 CS#2 1339 Normal Start 2.5ms

.net 6 CS#1 1328 CS#2 1270 Normal start 2.14

.net turning on PublishReadyToRun true in project file (Pre jit) CS#1 580 CS#2 3000 <-long delay in multiplexer but hoping its just an annomoly CS#3 614 CS#4 698

Log attached for that 3 second delay one (They changed the way logging works so your log is being auto spread into separate log entries hence the format change below)

2022-03-02T18:02:05.632Z 29827c27-c128-4cd3-b8f8-c577d26e2199 Connect log:Connecting (sync) on .NET 6.0.1

18:02:02.5455: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379,asyncTimeout=3000,connectTimeout=3000,abortConnect=False,connectRetry=1 18:02:02.5827: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Connecting... 18:02:02.6041: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: BeginConnectAsync 18:02:02.6239: 1 unique nodes specified (with tiebreaker) 18:02:02.6241: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting) 18:02:02.6243: Allowing 1 endpoint(s) 00:00:03 to respond... 18:02:02.6248: Awaiting 1 available task completion(s) for 3000ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=0,CompletedItems=7) 18:02:02.6445: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Connected 18:02:02.6454: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Server handshake 18:02:02.7045: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Setting client name: 169(v2.5.34.40405) 18:02:02.7250: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configuring... 18:02:02.7251: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")... 18:02:02.7252: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Writing: GET __Booksleeve_TieBreak 18:02:02.7252: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Sending critical tracer (handshake): ECHO 18:02:02.7253: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Writing: ECHO 18:02:02.7425: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Flushing outbound buffer 18:02:02.7426: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnEstablishingAsync complete 18:02:02.7426: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Starting read 18:02:02.7651: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) role: replica 18:02:02.7654: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) version: 6.0.5 18:02:02.7657: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) server-type: cluster 18:02:02.7858: Response from zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive / GET __Booksleeve_TieBreak: Error: MOVED 6202 10.2.191.128:6379 18:02:02.7859: Response from zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive / ECHO: BulkString: 16 bytes 18:02:02.7860: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnConnectedAsync completed (From command: ECHO) 18:02:02.8031: All 1 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=3,Free=32764,Min=2,Max=32767), POOL: (Threads=3,QueuedItems=1,CompletedItems=21) 18:02:02.8034: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished 18:02:02.8034: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Returned with success as Cluster replica (Source: From command: ECHO) 18:02:02.8257: 10.2.191.128:6379: OnConnectedAsync already connected start 18:02:02.8259: 10.2.191.128:6379/Interactive: Writing: PING 18:02:02.8434: 10.2.170.226:6379: OnConnectedAsync init (State=ConnectedEstablishing) 18:02:02.8435: 10.2.179.50:6379: OnConnectedAsync init (State=Connecting) 18:02:02.8435: 10.2.164.21:6379: OnConnectedAsync already connected start 18:02:02.8435: 10.2.164.21:6379/Interactive: Writing: PING 18:02:02.8437: Allowing 4 endpoint(s) 00:00:02.7810000 to respond... 18:02:02.8437: Awaiting 4 available task completion(s) for 2781ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=4,Free=32763,Min=2,Max=32767), POOL: (Threads=4,QueuedItems=1,CompletedItems=27) 18:02:02.8446: Response from 10.2.191.128:6379/Interactive / PING: SimpleString: PONG 18:02:02.8452: 10.2.191.128:6379: OnConnectedAsync already connected end 18:02:02.8623: Response from 10.2.164.21:6379/Interactive / PING: SimpleString: PONG 18:02:02.8627: 10.2.164.21:6379: OnConnectedAsync already connected end 18:02:05.6268: Not all available tasks completed cleanly (from ReconfigureAsync#1760, timeout 2781ms), IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=3,Free=32764,Min=2,Max=32767), POOL: (Threads=4,QueuedItems=0,CompletedItems=40) 18:02:05.6278: Server[0] (10.2.191.128:6379) Status: RanToCompletion (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: 0, out-pipe: 0, bw: Inactive, rs: ReadAsync. ws: Idle) 18:02:05.6278: Server[1] (10.2.170.226:6379) Status: WaitingForActivation (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: 0, out-pipe: 0, bw: Inactive, rs: ReadAsync. ws: Idle) 18:02:05.6278: Server[2] (10.2.179.50:6379) Status: WaitingForActivation (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: 0, out-pipe: 0, bw: Inactive, rs: ReadAsync. ws: Idle) 18:02:05.6278: Server[3] (10.2.164.21:6379) Status: RanToCompletion (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: 0, out-pipe: 0, bw: Inactive, rs: ReadAsync. ws: Idle) 18:02:05.6278: 10.2.191.128:6379: Endpoint is ConnectedEstablished 18:02:05.6278: 10.2.170.226:6379: Endpoint is ConnectedEstablished 18:02:05.6279: 10.2.179.50:6379: Endpoint is ConnectedEstablished 18:02:05.6279: 10.2.164.21:6379: Endpoint is ConnectedEstablished 18:02:05.6279: 10.2.191.128:6379: Returned with success as Cluster primary (Source: Already connected) 18:02:05.6279: 10.2.170.226:6379: Did not respond 18:02:05.6279: 10.2.179.50:6379: Did not respond 18:02:05.6279: 10.2.164.21:6379: Returned with success as Cluster primary (Source: Already connected) 18:02:05.6279: Cluster: 16384 of 16384 slots covered 18:02:05.6280: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Cluster v6.0.5, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active 18:02:05.6281: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: int ops=13, qu=0, qs=0, qc=0, wr=0, socks=1, non-pref=1; sub ops=3, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1 18:02:05.6320: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+13=13 (1.30 ops/s; spans 10s); sub: 0+3=3 (0.30 ops/s; spans 10s) 18:02:05.6320: 10.2.191.128:6379: Cluster v6.0.5, master; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 18:02:05.6320: 10.2.191.128:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 18:02:05.6320: 10.2.191.128:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 18:02:05.6320: 10.2.164.21:6379: Cluster v6.0.5, master; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 18:02:05.6320: 10.2.164.21:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 18:02:05.6320: 10.2.164.21:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 18:02:05.6321: 10.2.170

Mar 02 '22 18:03 greyhoundgames

Also as an aside, I went back to the latest stable stack exchange redis and the performance was similar for the cold starts FYI

Mar 02 '22 18:03 greyhoundgames

Can you post connection logs from one of the fast ones? What's most curious is the "Threads=2" which implies a very low thread pool and I wonder if we have contention there even in this small scenario.

Mar 02 '22 18:03 NickCraver

2022-03-02T18:17:16.282Z d0f13617-781d-4229-8b5b-dffeb6a2c3a7 Connect log:Connecting (sync) on .NET 6.0.1

18:17:15.9634: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379,asyncTimeout=3000,connectTimeout=3000,abortConnect=False,connectRetry=1 18:17:15.9820: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Connecting... 18:17:16.0029: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: BeginConnectAsync 18:17:16.0227: 1 unique nodes specified (with tiebreaker) 18:17:16.0229: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting) 18:17:16.0231: Allowing 1 endpoint(s) 00:00:03 to respond... 18:17:16.0236: Awaiting 1 available task completion(s) for 3000ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=0,CompletedItems=11) 18:17:16.0620: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Connected 18:17:16.0628: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Server handshake 18:17:16.1032: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Setting client name: 169(v2.5.34.40405) 18:17:16.1238: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configuring... 18:17:16.1239: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")... 18:17:16.1239: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Writing: GET __Booksleeve_TieBreak 18:17:16.1241: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Sending critical tracer (handshake): ECHO 18:17:16.1241: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Writing: ECHO 18:17:16.1241: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Flushing outbound buffer 18:17:16.1241: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnEstablishingAsync complete 18:17:16.1242: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Starting read 18:17:16.1636: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) role: master 18:17:16.1639: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) version: 6.0.5 18:17:16.1642: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) server-type: cluster 18:17:16.2013: Response from zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive / GET __Booksleeve_TieBreak: (null) 18:17:16.2015: Response from zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive / ECHO: BulkString: 16 bytes 18:17:16.2019: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnConnectedAsync completed (From command: ECHO) 18:17:16.2031: All 1 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767), POOL: (Threads=3,QueuedItems=0,CompletedItems=30) 18:17:16.2035: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished 18:17:16.2035: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Returned with success as Cluster primary (Source: From command: ECHO) 18:17:16.2237: 10.2.191.128:6379: OnConnectedAsync already connected start 18:17:16.2240: 10.2.191.128:6379/Interactive: Writing: PING 18:17:16.2424: 10.2.170.226:6379: OnConnectedAsync already connected start 18:17:16.2424: 10.2.170.226:6379/Interactive: Writing: PING 18:17:16.2425: 10.2.164.21:6379: OnConnectedAsync already connected start 18:17:16.2425: 10.2.164.21:6379/Interactive: Writing: PING 18:17:16.2426: 10.2.179.50:6379: OnConnectedAsync already connected start 18:17:16.2426: 10.2.179.50:6379/Interactive: Writing: PING 18:17:16.2427: Allowing 4 endpoint(s) 00:00:02.7810000 to respond... 18:17:16.2427: Awaiting 4 available task completion(s) for 2781ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=4,Free=32763,Min=2,Max=32767), POOL: (Threads=4,QueuedItems=1,CompletedItems=45) 18:17:16.2430: Response from 10.2.191.128:6379/Interactive / PING: SimpleString: PONG 18:17:16.2433: Response from 10.2.179.50:6379/Interactive / PING: SimpleString: PONG 18:17:16.2615: 10.2.191.128:6379: OnConnectedAsync already connected end 18:17:16.2617: 10.2.179.50:6379: OnConnectedAsync already connected end 18:17:16.2618: Response from 10.2.170.226:6379/Interactive / PING: SimpleString: PONG 18:17:16.2619: Response from 10.2.164.21:6379/Interactive / PING: SimpleString: PONG 18:17:16.2619: 10.2.170.226:6379: OnConnectedAsync already connected end 18:17:16.2619: 10.2.164.21:6379: OnConnectedAsync already connected end 18:17:16.2620: All 4 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=4,Free=32763,Min=2,Max=32767), POOL: (Threads=4,QueuedItems=0,CompletedItems=53) 18:17:16.2620: 10.2.191.128:6379: Endpoint is ConnectedEstablished 18:17:16.2620: 10.2.170.226:6379: Endpoint is ConnectedEstablished 18:17:16.2620: 10.2.164.21:6379: Endpoint is ConnectedEstablished 18:17:16.2620: 10.2.179.50:6379: Endpoint is ConnectedEstablished 18:17:16.2620: 10.2.191.128:6379: Returned with success as Cluster primary (Source: Already connected) 18:17:16.2620: 10.2.170.226:6379: Returned with success as Cluster replica (Source: Already connected) 18:17:16.2620: 10.2.164.21:6379: Returned with success as Cluster primary (Source: Already connected) 18:17:16.2620: 10.2.179.50:6379: Returned with success as Cluster replica (Source: Already connected) 18:17:16.2620: Cluster: 16384 of 16384 slots covered 18:17:16.2621: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Cluster v6.0.5, master; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active 18:17:16.2623: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=3, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1 18:17:16.2817: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 0+3=3 (0.30 ops/s; spans 10s) 18:17:16.2817: 10.2.191.128:6379: Cluster v6.0.5, master; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 18:17:16.2817: 10.2.191.128:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 18:17:16.2818: 10.2.191.128:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 18:17:16.2818: 10.2.164.21:6379: Cluster v6.0.5, master; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 18:17:16.2818: 10.2.164.21:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 18:17:16.2818: 10.2.164.21:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 18:17:16.2818: 10.2.170.226:6379: Cluster v6.0.5, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 18:17:16.2818: 10.2.170.226:6379: int ops=13, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 18:17:16.2818: 10.2.170.226:6379: Circular op-count snapshot; int: 0+13=13 (

Mar 02 '22 18:03 greyhoundgames

Note that in lambda each lambda sandbox has its own multiplexer handling one user at a time.

Mar 02 '22 18:03 greyhoundgames

Really appreciate your help Nick. This line of investigation has lead to dramatic improvements for our app across the board. Thanks for the work you do here and your help with this issue. Our app is a mobile game called Evertale that uses your SDK extensively and we have really liked working with it.

Mar 02 '22 19:03 greyhoundgames

@greyhoundgames Awesome, I appreciate the kind words, and happy when I can help!

For kicks, let's try calling this before you connect and see if bumping those 2 threads helps...

ThreadPool.SetMinThreads(5, 5);

Mar 02 '22 20:03 NickCraver

Adding that line made the lambda act very strangely. Duration shot up to 3 seconds. Log section that shows the delay:

20:47:25.6846: Response from 10.2.191.128:6379/Interactive / PING: SimpleString: PONG

20:47:25.6846: 10.2.191.128:6379: OnConnectedAsync already connected end 20:47:28.4095: Not all available tasks completed cleanly (from ReconfigureAsync#1760, timeout 2723ms), IOCP: (Busy=0,Free=1000,Min=5,Max=1000), WORKER: (Busy=2,Free=32765,Min=5,Max=32767), POOL: (Threads=7,QueuedItems=0,CompletedItems=58) 20:47:28.4104: Server[0] (10.2.179.50:6379) Status: WaitingForActivation (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: 0, out-pipe: 0, bw: Inactive, rs: ReadAsync. ws: Idle)

Crazy enough this also caused my other lambdas that use redis to spike really hard. I removed it and let it calm down, and then when i put it back the exact same thing happened... Very strange. I know lambda has limits on multithreading because of how it works so maybe that code is just no bueno for lambda.

Mar 02 '22 20:03 greyhoundgames

@greyhoundgames I added a bit more stuff (like total timing) in the 2.5.43 release so it's worth a shot here but I don't expect appreciable gains over current. I'll be keeping this scenario in mind, but don't have more suggestions at the moment unless we could get detailed profiling (like an .etl trace) from it happening. I'm not exactly sure how hardware is presented and constrained here, but it looks like more than a few threads hoses the thing so whatever bounds exist, they're fairly sharp.

Mar 10 '22 01:03 NickCraver

Ok. I will try it out sometime next week and post.

Mar 10 '22 17:03 greyhoundgames

I don't know whats up, but after doing this its gone to 3 seconds. Here is the log. I tried running it many times but I got the same thing each time.

2022-03-11T14:54:21.382Z 9f470186-adc1-4fa0-84cd-f3119a85a3f1 Connect log:Connecting (sync) on .NET 6.0.1

14:54:18.3622: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379,asyncTimeout=3000,connectTimeout=3000,abortConnect=False,connectRetry=1 14:54:18.3668: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Connecting... 14:54:18.3752: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: BeginConnectAsync 14:54:18.3787: 1 unique nodes specified (with tiebreaker) 14:54:18.3789: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting) 14:54:18.3791: Allowing 1 endpoint(s) 00:00:03 to respond... 14:54:18.3795: Awaiting 1 available task completion(s) for 3000ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=0,CompletedItems=11) 14:54:18.3886: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Connected 14:54:18.3886: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Server handshake 14:54:18.4020: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Setting client name: 169(v2.5.34.40405) 14:54:18.4064: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configuring... 14:54:18.4065: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")... 14:54:18.4067: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Writing: GET __Booksleeve_TieBreak 14:54:18.4070: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Sending critical tracer (handshake): ECHO 14:54:18.4070: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Writing: ECHO 14:54:18.4071: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Flushing outbound buffer 14:54:18.4071: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnEstablishingAsync complete 14:54:18.4071: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Starting read 14:54:18.4136: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) role: replica 14:54:18.4138: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) version: 6.0.5 14:54:18.4141: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Auto-configured (INFO) server-type: cluster 14:54:18.4175: Response from zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive / GET __Booksleeve_TieBreak: Error: MOVED 6202 10.2.191.128:6379 14:54:18.4176: Response from zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive / ECHO: BulkString: 16 bytes 14:54:18.4191: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: OnConnectedAsync completed (From command: ECHO) 14:54:18.4191: All 1 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=4,Free=32763,Min=2,Max=32767), POOL: (Threads=4,QueuedItems=1,CompletedItems=20) 14:54:18.4194: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished 14:54:18.4194: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Returned with success as Cluster replica (Source: From command: ECHO) 14:54:18.4229: 10.2.191.128:6379: OnConnectedAsync already connected start 14:54:18.4232: 10.2.191.128:6379/Interactive: Writing: PING 14:54:18.4240: 10.2.170.226:6379: OnConnectedAsync init (State=Connecting) 14:54:18.4241: 10.2.179.50:6379: OnConnectedAsync init (State=Connecting) 14:54:18.4241: 10.2.164.21:6379: OnConnectedAsync init (State=ConnectedEstablishing) 14:54:18.4241: Allowing 4 endpoint(s) 00:00:02.9550000 to respond... 14:54:18.4241: Awaiting 4 available task completion(s) for 2955ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=3,Free=32764,Min=2,Max=32767), POOL: (Threads=4,QueuedItems=1,CompletedItems=30) 14:54:18.4257: Response from 10.2.191.128:6379/Interactive / PING: SimpleString: PONG 14:54:18.4264: 10.2.191.128:6379: OnConnectedAsync already connected end 14:54:21.3770: Not all available tasks completed cleanly (from ReconfigureAsync#1760, timeout 2955ms), IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767), POOL: (Threads=4,QueuedItems=0,CompletedItems=49) 14:54:21.3779: Server[0] (10.2.191.128:6379) Status: RanToCompletion (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: 0, out-pipe: 0, bw: Inactive, rs: ReadAsync. ws: Idle) 14:54:21.3779: Server[1] (10.2.170.226:6379) Status: WaitingForActivation (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: 0, out-pipe: 0, bw: Inactive, rs: ReadAsync. ws: Idle) 14:54:21.3780: Server[2] (10.2.179.50:6379) Status: WaitingForActivation (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: 0, out-pipe: 0, bw: Inactive, rs: ReadAsync. ws: Idle) 14:54:21.3780: Server[3] (10.2.164.21:6379) Status: WaitingForActivation (inst: 11, qs: 0, in: 0, qu: 11, aw: False, in-pipe: 0, out-pipe: 0, bw: Inactive, rs: ReadAsync. ws: Idle) 14:54:21.3780: 10.2.191.128:6379: Endpoint is ConnectedEstablished 14:54:21.3780: 10.2.170.226:6379: Endpoint is ConnectedEstablished 14:54:21.3780: 10.2.179.50:6379: Endpoint is ConnectedEstablished 14:54:21.3780: 10.2.164.21:6379: Endpoint is ConnectedEstablished 14:54:21.3780: 10.2.191.128:6379: Returned with success as Cluster primary (Source: Already connected) 14:54:21.3780: 10.2.170.226:6379: Did not respond 14:54:21.3780: 10.2.179.50:6379: Did not respond 14:54:21.3780: 10.2.164.21:6379: Did not respond 14:54:21.3781: Cluster: 16384 of 16384 slots covered 14:54:21.3782: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Cluster v6.0.5, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active 14:54:21.3783: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: int ops=13, qu=0, qs=0, qc=0, wr=0, socks=1, non-pref=1; sub ops=3, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1 14:54:21.3814: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+13=13 (1.30 ops/s; spans 10s); sub: 0+3=3 (0.30 ops/s; spans 10s) 14:54:21.3814: 10.2.191.128:6379: Cluster v6.0.5, master; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 14:54:21.3814: 10.2.191.128:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 14:54:21.3815: 10.2.191.128:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 14:54:21.3815: 10.2.164.21:6379: Cluster v6.0.5, master; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a; not in use: DidNotRespond 14:54:21.3815: 10.2.164.21:6379: int ops=11, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 14:54:21.3815: 10.2.164.21:6379: Circular op-count snapshot; int: 0+11=11 (1.10 ops/s; spans 10s); sub: 14:54:21.3815: 10.2.170.226:6379: Cluster v6.0.5, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a; not in use: DidNotRespond 14:54:21.3815: 10.2.170.226:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 14 END RequestId: 9f470186-adc1-4fa0-84cd-f3119a85a3f1

Mar 11 '22 14:03 greyhoundgames

I'm not sure its worth your time to look at this more. It has to be something lambda specific at this point that is wonky.

Mar 11 '22 14:03 greyhoundgames

@greyhoundgames which client version is this on? With 2.5.43 I'd expect a few more things in the output - something is amiss with the connection task completion sources for sure.

Mar 11 '22 15:03 NickCraver

I updated from the preview release to the official release of 2.5.43. If I go to my dependencies and right click it and say show in folder, there is a sha file: pB345YnLpm38oc4ueqY6N2U7qh/O1F7Pw5Ex+jf5Q7whgR4q+q9AOH4M0xDkSneJQEuNWNtCe3BWcQ88zSzTFA==

Also on a whim I decided to try using another redis client to see, ServiceStack.redis. When I used that it connected very fast. But then stack exchange redis started connecting very fast. Its so strange, but whatever it is, I don't know that its in your code base.

Mar 11 '22 15:03 greyhoundgames

Also since using visual studio 2022 I have noticed really weird stuff with nuget package manager. For example in this test I mention above. I installed that new redis client. I used the code. Compiled all good. Went to upload and the dependency was gone and it could not compile(and it was not present on the Packages list in vstudio). The nuget installer claimed it was still installed, so I uninstalled, reinstalled and it was ok. I have seen this sort of flakey package manager things about 4 times since I upgraded to Vs2022 and never before this so there is a possibility that it's not managing its libraries correctly. Do you have the version number included in the initial connection log? That might help.

Mar 11 '22 15:03 greyhoundgames

In the 2.5.43 release you should see the version in the commit log, but unfortunately it wasn't present before then. I added some logging bits just for your issue here :)

Mar 11 '22 15:03 NickCraver

Hi @NickCraver,

We also got a similar issue after we upgraded the Redis library from 2.2.79 to 2.5.61. It takes a time that is similar to the ConnectTimeout we set in the ConfigurationOptions. In @greyhoundgames' case, he set 3 seconds. But in my environment, I use 10 seconds as the following. Finally, I should wait up to 10 seconds to connect when running within AWS Lambda. That is wired.

configOptions = new ConfigurationOptions();
configOptions.EndPoints.Add(ip, port);
configOptions.Password = password;
configOptions.Ssl = true;
configOptions.ClientName = "MyRedis";
configOptions.ConnectTimeout = 10000;
configOptions.SyncTimeout = 30000;
configOptions.KeepAlive = 10;
configOptions.AbortOnConnectFail = false;

I also collected logs. Please help to check it, thanks.

2022-04-13 07:04:39.706,"07:04:39.7067: Total connect time: 10,261 ms
2022-04-13 07:04:39.705,"07:04:39.7057:   clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 0+4=4 (0.40 ops/s; spans 10s)
2022-04-13 07:04:39.705,"07:04:39.7058:   my-redis-cluster-0001-001.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Cluster v5.0.6, primary; keep-alive: 00:00:10; int: ConnectedEstablished; sub: n/a
2022-04-13 07:04:39.705,"07:04:39.7058:   my-redis-cluster-0001-001.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0
2022-04-13 07:04:39.705,"07:04:39.7058:   my-redis-cluster-0001-001.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub:
2022-04-13 07:04:39.705,"07:04:39.7058:   my-redis-cluster-0001-003.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Cluster v5.0.6, replica; keep-alive: 00:00:10; int: ConnectedEstablished; sub: n/a; not in use: DidNotRespond
2022-04-13 07:04:39.705,"07:04:39.7058:   my-redis-cluster-0001-003.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0
2022-04-13 07:04:39.705,"07:04:39.7059:   my-redis-cluster-0001-003.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub:
2022-04-13 07:04:39.705,"07:04:39.7059:   my-redis-cluster-0001-002.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Cluster v5.0.6, replica; keep-alive: 00:00:10; int: ConnectedEstablished; sub: n/a; not in use: DidNotRespond
2022-04-13 07:04:39.705,"07:04:39.7059:   my-redis-cluster-0001-002.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0
2022-04-13 07:04:39.705,"07:04:39.7059:   my-redis-cluster-0001-002.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub:
2022-04-13 07:04:39.705,"07:04:39.7059:   my-redis-cluster-0001-004.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Cluster v5.0.6, replica; keep-alive: 00:00:10; int: ConnectedEstablished; sub: n/a; not in use: DidNotRespond
2022-04-13 07:04:39.705,"07:04:39.7059:   my-redis-cluster-0001-004.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0
2022-04-13 07:04:39.705,"07:04:39.7059:   my-redis-cluster-0001-004.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub:
2022-04-13 07:04:39.704,"07:04:39.7044:   clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=4, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1
2022-04-13 07:04:39.703,"07:04:39.7033:   clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Cluster v5.0.6, primary; keep-alive: 00:00:10; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
2022-04-13 07:04:39.702,"07:04:39.7027: Endpoint Summary:
2022-04-13 07:04:39.701,"07:04:39.7015:   Server[0] (my-redis-cluster-0001-001.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379) Status: RanToCompletion (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: -1, out-pipe: -1, bw: Inactive, rs: ReadAsync. ws: Idle)
2022-04-13 07:04:39.701,"07:04:39.7016:   Server[1] (my-redis-cluster-0001-003.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379) Status: WaitingForActivation (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: -1, out-pipe: -1, bw: Inactive, rs: ReadAsync. ws: Idle)
2022-04-13 07:04:39.701,"07:04:39.7016:   Server[2] (my-redis-cluster-0001-002.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379) Status: WaitingForActivation (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: -1, out-pipe: -1, bw: Inactive, rs: ReadAsync. ws: Idle)
2022-04-13 07:04:39.701,"07:04:39.7016:   Server[3] (my-redis-cluster-0001-004.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379) Status: WaitingForActivation (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: -1, out-pipe: -1, bw: Inactive, rs: ReadAsync. ws: Idle)
2022-04-13 07:04:39.701,"07:04:39.7016: Endpoint summary:
2022-04-13 07:04:39.701,"07:04:39.7016:   my-redis-cluster-0001-001.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished
2022-04-13 07:04:39.701,"07:04:39.7016:   my-redis-cluster-0001-003.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished
2022-04-13 07:04:39.701,"07:04:39.7016:   my-redis-cluster-0001-002.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished
2022-04-13 07:04:39.701,"07:04:39.7016:   my-redis-cluster-0001-004.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished
2022-04-13 07:04:39.701,"07:04:39.7016:   my-redis-cluster-0001-001.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Returned with success as Cluster primary (Source: Already connected)
2022-04-13 07:04:39.701,"07:04:39.7016:   my-redis-cluster-0001-003.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Did not respond
2022-04-13 07:04:39.701,"07:04:39.7016:   my-redis-cluster-0001-002.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Did not respond
2022-04-13 07:04:39.701,"07:04:39.7016:   my-redis-cluster-0001-004.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Did not respond
2022-04-13 07:04:39.701,"07:04:39.7018: Cluster: 16384 of 16384 slots covered
2022-04-13 07:04:39.700,"07:04:39.6998: Not all available tasks completed cleanly (from ReconfigureAsync#1271, timeout 9421ms), IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=1,Free=32766,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=0,CompletedItems=68)
2022-04-13 07:04:30.321,"07:04:30.3214: my-redis-cluster-0001-001.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: OnConnectedAsync already connected end
2022-04-13 07:04:30.301,"07:04:30.3015: Response from my-redis-cluster-0001-001.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379/Interactive / PING: SimpleString: PONG
2022-04-13 07:04:30.280,"07:04:30.2804: my-redis-cluster-0001-003.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)
2022-04-13 07:04:30.280,"07:04:30.2805: my-redis-cluster-0001-002.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)
2022-04-13 07:04:30.280,"07:04:30.2805: my-redis-cluster-0001-004.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)
2022-04-13 07:04:30.280,"07:04:30.2805: Allowing 4 endpoint(s) 00:00:09.4210000 to respond...
2022-04-13 07:04:30.280,"07:04:30.2806: Awaiting 4 available task completion(s) for 9421ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=5,CompletedItems=49)
2022-04-13 07:04:30.279,"07:04:30.2790: my-redis-cluster-0001-001.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379/Interactive: Writing: PING
2022-04-13 07:04:30.262,"07:04:30.2621: my-redis-cluster-0001-001.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: OnConnectedAsync already connected start
2022-04-13 07:04:30.241,"07:04:30.2417: clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: OnConnectedAsync completed (From command: ECHO)
2022-04-13 07:04:30.202,"07:04:30.2021: Endpoint summary:
2022-04-13 07:04:30.202,"07:04:30.2021:   clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished
2022-04-13 07:04:30.202,"07:04:30.2022:   clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Returned with success as Cluster primary (Source: From command: ECHO)
2022-04-13 07:04:30.201,"07:04:30.2018: All 1 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=3,CompletedItems=38)
2022-04-13 07:04:30.199,"07:04:30.1990: Response from clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379/Interactive / ECHO: BulkString: 16 bytes
2022-04-13 07:04:30.198,"07:04:30.1986: Response from clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379/Interactive / GET __Booksleeve_TieBreak: (null)
2022-04-13 07:04:30.138,"07:04:30.1237: clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Auto-configured (INFO) role: primary
2022-04-13 07:04:30.138,"07:04:30.1242: clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Auto-configured (INFO) version: 5.0.6
2022-04-13 07:04:30.138,"07:04:30.1243: clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Auto-configured (INFO) server-type: cluster
2022-04-13 07:04:30.000,"07:04:30.0003: clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Sending critical tracer (handshake): ECHO
2022-04-13 07:04:30.000,"07:04:30.0003: clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379/Interactive: Writing: ECHO
2022-04-13 07:04:30.000,"07:04:30.0004: clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Flushing outbound buffer
2022-04-13 07:04:30.000,"07:04:30.0005: clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: OnEstablishingAsync complete
2022-04-13 07:04:30.000,"07:04:30.0005: clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Starting read
2022-04-13 07:04:29.999,"07:04:29.9990: clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Requesting tie-break (Key=""__Booksleeve_TieBreak"")...
2022-04-13 07:04:29.999,"07:04:29.9997: clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379/Interactive: Writing: GET __Booksleeve_TieBreak
2022-04-13 07:04:29.980,"07:04:29.9801: clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Auto-configuring...
2022-04-13 07:04:29.946,"07:04:29.9462: clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Setting client name: MyRedis
2022-04-13 07:04:29.818,"07:04:29.8187: clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Server handshake
2022-04-13 07:04:29.818,"07:04:29.8189: clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: Authenticating (password)
2022-04-13 07:04:29.766,"07:04:29.7662: clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379/Interactive: Connected 
2022-04-13 07:04:29.764,"07:04:29.7648: TLS connection established successfully using protocol: Tls12
2022-04-13 07:04:29.738,"07:04:29.7389: Awaiting 1 available task completion(s) for 10000ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=3,Free=32764,Min=2,Max=32767), POOL: (Threads=3,QueuedItems=2,CompletedItems=21)
2022-04-13 07:04:29.720,"07:04:29.7202: Configuring TLS
2022-04-13 07:04:29.701,"07:04:29.7012: Allowing 1 endpoint(s) 00:00:10 to respond...
2022-04-13 07:04:29.700,"07:04:29.7007: clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)
2022-04-13 07:04:29.699,"07:04:29.6998: 1 unique nodes specified (with tiebreaker)
2022-04-13 07:04:29.665,"07:04:29.6652: clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379: BeginConnectAsync
2022-04-13 07:04:29.623,"07:04:29.6234: clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379/Interactive: Connecting...
2022-04-13 07:04:29.599,"07:04:29.5996: clustercfg.my-redis-cluster.puhtgv.use1.cache.amazonaws.com:6379,name=MyRedis,keepAlive=10,syncTimeout=30000,connectTimeout=10000,password=*****,ssl=True,abortConnect=False
2022-04-13 07:04:29.445,"07:04:29.4454: Connecting (sync) on .NET Core 3.1.23 (StackExchange.Redis: v2.5.61.22961)

Apr 13 '22 07:04 jlee58tw

Hi @jlee58tw , @NickCraver Just deployed my Lambda and I am also observing a high cold start delay as well - I think what's the interesting part here is that it basically waits until the ConnectTimeout is reached, and afterwards continues normally:

Log with the default timeout of 5s:

13:24:17.6509: Connecting (sync) on .NET Core 3.1.25 (StackExchange.Redis: v2.6.48.48654)
13:24:17.6620: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379,password=*****,ssl=True
13:24:17.6656: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379/Interactive: Connecting...
13:24:17.6750: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: BeginConnectAsync
13:24:17.6770: 1 unique nodes specified (with tiebreaker)
13:24:17.6772: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)
13:24:17.6775: Allowing 1 endpoint(s) 00:00:05 to respond...
13:24:17.6781: Awaiting 1 available task completion(s) for 5000ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767), POOL: (Threads=3,QueuedItems=0,CompletedItems=28)
13:24:17.6813: Configuring TLS
13:24:17.6931: TLS connection established successfully using protocol: Tls12
13:24:17.6956: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379/Interactive: Connected
13:24:17.6970: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Server handshake
13:24:17.6970: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Authenticating (password)
13:24:17.7076: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Setting client name: 169(SE.Redis-v2.6.48.48654)
13:24:17.7084: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Auto-configuring...
13:24:17.7088: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")...
13:24:17.7089: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379/Interactive: Writing: GET __Booksleeve_TieBreak
13:24:17.7090: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Sending critical tracer (handshake): ECHO
13:24:17.7090: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379/Interactive: Writing: ECHO
13:24:17.7090: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Flushing outbound buffer
13:24:17.7090: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: OnEstablishingAsync complete
13:24:17.7090: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Starting read
13:24:17.7133: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Auto-configured (INFO) role: replica
13:24:17.7143: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Auto-configured (INFO) version: 6.2.6
13:24:17.7147: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Auto-configured (INFO) server-type: cluster
13:24:17.7183: Response from clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379/Interactive / GET __Booksleeve_TieBreak: Error: MOVED 6202 emr1poj4j996g37b-0001-001.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379
13:24:17.7184: Response from clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379/Interactive / ECHO: BulkString: 16 bytes
13:24:17.7194: All 1 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=1,CompletedItems=42)
13:24:17.7198: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync completed (From command: ECHO)
13:24:17.7201: Endpoint summary:
13:24:17.7201:   clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished
13:24:17.7202:   clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Returned with success as Cluster replica (Source: From command: ECHO)
13:24:17.7241: emr1poj4j996g37b-0001-001.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)
13:24:17.7241: emr1poj4j996g37b-0001-002.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)
13:24:17.7242: Allowing 2 endpoint(s) 00:00:04.9540000 to respond...
13:24:17.7242: Awaiting 2 available task completion(s) for 4954ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=1,CompletedItems=48)
13:24:22.6751: Not all available tasks completed cleanly (from ReconfigureAsync#1271, timeout 4954ms), IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=1,Free=32766,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=0,CompletedItems=61)
13:24:22.6761:   Server[0] (emr1poj4j996g37b-0001-001.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379) Status: WaitingForActivation (inst: 11, qs: 0, in: 0, qu: 11, aw: False, in-pipe: -1, out-pipe: -1, bw: Inactive, rs: ReadAsync. ws: Idle)
13:24:22.6761:   Server[1] (emr1poj4j996g37b-0001-002.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379) Status: WaitingForActivation (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: -1, out-pipe: -1, bw: Inactive, rs: ReadAsync. ws: Idle)
13:24:22.6761: Endpoint summary:
13:24:22.6761:   emr1poj4j996g37b-0001-001.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished
13:24:22.6761:   emr1poj4j996g37b-0001-002.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished
13:24:22.6761:   emr1poj4j996g37b-0001-001.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Did not respond
13:24:22.6761:   emr1poj4j996g37b-0001-002.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Did not respond
13:24:22.6762: Cluster: 16384 of 16384 slots covered
13:24:22.6762: Endpoint Summary:
13:24:22.6763:   clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Cluster v6.2.6, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
13:24:22.6764:   clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: int ops=13, qu=0, qs=0, qc=0, wr=0, socks=1, non-pref=1; sub ops=4, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1
13:24:22.6768:   clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+13=13 (1.30 ops/s; spans 10s); sub: 0+4=4 (0.40 ops/s; spans 10s)
13:24:22.6769:   emr1poj4j996g37b-0001-001.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Cluster v6.2.6, primary; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a; not in use: DidNotRespond
13:24:22.6769:   emr1poj4j996g37b-0001-001.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: int ops=11, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0
13:24:22.6769:   emr1poj4j996g37b-0001-001.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+11=11 (1.10 ops/s; spans 10s); sub:
13:24:22.6769:   emr1poj4j996g37b-0001-002.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Cluster v6.2.6, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a; not in use: DidNotRespond
13:24:22.6769:   emr1poj4j996g37b-0001-002.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0
13:24:22.6769:   emr1poj4j996g37b-0001-002.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub:
13:24:22.6769: Sync timeouts: 0; async timeouts: 0; fire and forget: 0; last heartbeat: -1s ago
13:24:22.6769: Starting heartbeat...
13:24:22.6772: Total connect time: 5,026 ms

Log with timeout set to 200ms:

15:57:17.5531: Connecting (sync) on .NET Core 3.1.25 (StackExchange.Redis: v2.6.48.48654)
15:57:17.5642: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379,connectTimeout=200,password=*****,ssl=True
15:57:17.5679: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379/Interactive: Connecting...
15:57:17.5774: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: BeginConnectAsync
15:57:17.5794: 1 unique nodes specified (with tiebreaker)
15:57:17.5798: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)
15:57:17.5801: Allowing 1 endpoint(s) 00:00:00.2000000 to respond...
15:57:17.5806: Awaiting 1 available task completion(s) for 200ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=1,Free=32766,Min=2,Max=32767), POOL: (Threads=3,QueuedItems=0,CompletedItems=26)
15:57:17.5825: Configuring TLS
15:57:17.5931: TLS connection established successfully using protocol: Tls12
15:57:17.5953: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379/Interactive: Connected
15:57:17.5968: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Server handshake
15:57:17.5968: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Authenticating (password)
15:57:17.6029: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Setting client name: 169(SE.Redis-v2.6.48.48654)
15:57:17.6042: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Auto-configuring...
15:57:17.6043: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")...
15:57:17.6044: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379/Interactive: Writing: GET __Booksleeve_TieBreak
15:57:17.6046: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Sending critical tracer (handshake): ECHO
15:57:17.6046: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379/Interactive: Writing: ECHO
15:57:17.6047: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Flushing outbound buffer
15:57:17.6047: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: OnEstablishingAsync complete
15:57:17.6047: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Starting read
15:57:17.6081: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Auto-configured (INFO) role: replica
15:57:17.6089: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Auto-configured (INFO) version: 6.2.6
15:57:17.6093: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Auto-configured (INFO) server-type: cluster
15:57:17.6281: Response from clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379/Interactive / GET __Booksleeve_TieBreak: Error: MOVED 6202 emr1cd6qvn7xsw7u-0001-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379
15:57:17.6282: Response from clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379/Interactive / ECHO: BulkString: 16 bytes
15:57:17.6294: All 1 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=4,CompletedItems=45)
15:57:17.6297: Endpoint summary:
15:57:17.6297:   clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished
15:57:17.6297:   clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Returned with success as Cluster replica (Source: From command: ECHO)
15:57:17.6338: emr1cd6qvn7xsw7u-0002-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync already connected start
15:57:17.6344: emr1cd6qvn7xsw7u-0002-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379/Interactive: Writing: PING
15:57:17.6352: emr1cd6qvn7xsw7u-0002-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)
15:57:17.6353: emr1cd6qvn7xsw7u-0001-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)
15:57:17.6353: emr1cd6qvn7xsw7u-0001-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)
15:57:17.6353: Allowing 4 endpoint(s) 00:00:00.1450000 to respond...
15:57:17.6353: Awaiting 4 available task completion(s) for 145ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=4,CompletedItems=51)
15:57:17.6376: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync completed (From command: ECHO)
15:57:17.6411: Response from emr1cd6qvn7xsw7u-0002-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379/Interactive / PING: SimpleString: PONG
15:57:17.6464: emr1cd6qvn7xsw7u-0002-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync already connected end
15:57:17.7809: Not all available tasks completed cleanly (from ReconfigureAsync#1271, timeout 145ms), IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=1,Free=32766,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=0,CompletedItems=72)
15:57:17.7817:   Server[0] (emr1cd6qvn7xsw7u-0002-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379) Status: RanToCompletion (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: -1, out-pipe: -1, bw: Inactive, rs: ReadAsync. ws: Idle)
15:57:17.7817:   Server[1] (emr1cd6qvn7xsw7u-0002-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379) Status: WaitingForActivation (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: -1, out-pipe: -1, bw: Inactive, rs: ReadAsync. ws: Idle)
15:57:17.7817:   Server[2] (emr1cd6qvn7xsw7u-0001-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379) Status: WaitingForActivation (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: -1, out-pipe: -1, bw: Inactive, rs: ReadAsync. ws: Idle)
15:57:17.7817:   Server[3] (emr1cd6qvn7xsw7u-0001-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379) Status: WaitingForActivation (inst: 11, qs: 0, in: 0, qu: 11, aw: False, in-pipe: -1, out-pipe: -1, bw: Inactive, rs: ReadAsync. ws: Idle)
15:57:17.7817: Endpoint summary:
15:57:17.7818:   emr1cd6qvn7xsw7u-0002-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished
15:57:17.7818:   emr1cd6qvn7xsw7u-0002-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished
15:57:17.7818:   emr1cd6qvn7xsw7u-0001-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished
15:57:17.7818:   emr1cd6qvn7xsw7u-0001-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished
15:57:17.7818:   emr1cd6qvn7xsw7u-0002-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Returned with success as Cluster primary (Source: Already connected)
15:57:17.7818:   emr1cd6qvn7xsw7u-0002-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Did not respond
15:57:17.7818:   emr1cd6qvn7xsw7u-0001-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Did not respond
15:57:17.7818:   emr1cd6qvn7xsw7u-0001-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Did not respond
15:57:17.7818: Cluster: 16384 of 16384 slots covered
15:57:17.7818: Endpoint Summary:
15:57:17.7820:   clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Cluster v6.2.6, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
15:57:17.7821:   clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: int ops=13, qu=0, qs=0, qc=0, wr=0, socks=1, non-pref=1; sub ops=4, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1
15:57:17.7825:   clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+13=13 (1.30 ops/s; spans 10s); sub: 0+4=4 (0.40 ops/s; spans 10s)
15:57:17.7825:   emr1cd6qvn7xsw7u-0002-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Cluster v6.2.6, primary; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a
15:57:17.7825:   emr1cd6qvn7xsw7u-0002-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0
15:57:17.7825:   emr1cd6qvn7xsw7u-0002-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub:
15:57:17.7826:   emr1cd6qvn7xsw7u-0001-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Cluster v6.2.6, primary; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a; not in use: DidNotRespond
15:57:17.7826:   emr1cd6qvn7xsw7u-0001-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: int ops=11, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0
15:57:17.7826:   emr1cd6qvn7xsw7u-0001-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+11=11 (1.10 ops/s; spans 10s); sub:
15:57:17.7826:   emr1cd6qvn7xsw7u-0002-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Cluster v6.2.6, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a; not in use: DidNotRespond
15:57:17.7826:   emr1cd6qvn7xsw7u-0002-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0
15:57:17.7826:   emr1cd6qvn7xsw7u-0002-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub:
15:57:17.7826:   emr1cd6qvn7xsw7u-0001-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Cluster v6.2.6, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a; not in use: DidNotRespond
15:57:17.7826:   emr1cd6qvn7xsw7u-0001-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0
15:57:17.7826:   emr1cd6qvn7xsw7u-0001-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub:
15:57:17.7826: Sync timeouts: 0; async timeouts: 0; fire and forget: 0; last heartbeat: -1s ago
15:57:17.7826: Starting heartbeat...
15:57:17.7829: Total connect time: 230 ms

Any ideas what we can do here to improve? I think it's also worth noting that it always says "Endpoint is ConnectedEstablished" followed by "Did not respond", but the endpoints seem to work.

Aug 31 '22 16:08 Compufreak345

Do you have ready to run set on your project to pre compile for the right platform (net6+ feature). That didn't solve it but it helped it.

On Wed, Aug 31, 2022 at 9:01 AM Christoph Sonntag @.***> wrote:

Hi @jlee58tw https://github.com/jlee58tw , @NickCraver https://github.com/NickCraver Just deployed my Lambda and I am also observing a high cold start delay as well - I think what's the interesting part here is that it basically waits until the ConnectTimeout is reached, and afterwards continues normally:

Log with the default timeout of 5s:

13:24:17.6509: Connecting (sync) on .NET Core 3.1.25 (StackExchange.Redis: v2.6.48.48654) 13:24:17.6620: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379,password=*****,ssl=True 13:24:17.6656: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379/Interactive: Connecting... 13:24:17.6750: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: BeginConnectAsync 13:24:17.6770: 1 unique nodes specified (with tiebreaker) 13:24:17.6772: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting) 13:24:17.6775: Allowing 1 endpoint(s) 00:00:05 to respond... 13:24:17.6781: Awaiting 1 available task completion(s) for 5000ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767), POOL: (Threads=3,QueuedItems=0,CompletedItems=28) 13:24:17.6813: Configuring TLS 13:24:17.6931: TLS connection established successfully using protocol: Tls12 13:24:17.6956: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379/Interactive: Connected 13:24:17.6970: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Server handshake 13:24:17.6970: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Authenticating (password) 13:24:17.7076: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Setting client name: 169(SE.Redis-v2.6.48.48654) 13:24:17.7084: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Auto-configuring... 13:24:17.7088: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")... 13:24:17.7089: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379/Interactive: Writing: GET __Booksleeve_TieBreak 13:24:17.7090: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Sending critical tracer (handshake): ECHO 13:24:17.7090: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379/Interactive: Writing: ECHO 13:24:17.7090: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Flushing outbound buffer 13:24:17.7090: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: OnEstablishingAsync complete 13:24:17.7090: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Starting read 13:24:17.7133: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Auto-configured (INFO) role: replica 13:24:17.7143: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Auto-configured (INFO) version: 6.2.6 13:24:17.7147: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Auto-configured (INFO) server-type: cluster 13:24:17.7183: Response from clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379/Interactive / GET __Booksleeve_TieBreak: Error: MOVED 6202 emr1poj4j996g37b-0001-001.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379 13:24:17.7184: Response from clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379/Interactive / ECHO: BulkString: 16 bytes 13:24:17.7194: All 1 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=1,CompletedItems=42) 13:24:17.7198: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync completed (From command: ECHO) 13:24:17.7201: Endpoint summary: 13:24:17.7201: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished 13:24:17.7202: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Returned with success as Cluster replica (Source: From command: ECHO) 13:24:17.7241: emr1poj4j996g37b-0001-001.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting) 13:24:17.7241: emr1poj4j996g37b-0001-002.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting) 13:24:17.7242: Allowing 2 endpoint(s) 00:00:04.9540000 to respond... 13:24:17.7242: Awaiting 2 available task completion(s) for 4954ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=1,CompletedItems=48) 13:24:22.6751: Not all available tasks completed cleanly (from ReconfigureAsync#1271, timeout 4954ms), IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=1,Free=32766,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=0,CompletedItems=61) 13:24:22.6761: Server[0] (emr1poj4j996g37b-0001-001.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379) Status: WaitingForActivation (inst: 11, qs: 0, in: 0, qu: 11, aw: False, in-pipe: -1, out-pipe: -1, bw: Inactive, rs: ReadAsync. ws: Idle) 13:24:22.6761: Server[1] (emr1poj4j996g37b-0001-002.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379) Status: WaitingForActivation (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: -1, out-pipe: -1, bw: Inactive, rs: ReadAsync. ws: Idle) 13:24:22.6761: Endpoint summary: 13:24:22.6761: emr1poj4j996g37b-0001-001.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished 13:24:22.6761: emr1poj4j996g37b-0001-002.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished 13:24:22.6761: emr1poj4j996g37b-0001-001.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Did not respond 13:24:22.6761: emr1poj4j996g37b-0001-002.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Did not respond 13:24:22.6762: Cluster: 16384 of 16384 slots covered 13:24:22.6762: Endpoint Summary: 13:24:22.6763: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Cluster v6.2.6, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active 13:24:22.6764: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: int ops=13, qu=0, qs=0, qc=0, wr=0, socks=1, non-pref=1; sub ops=4, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1 13:24:22.6768: clustercfg.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+13=13 (1.30 ops/s; spans 10s); sub: 0+4=4 (0.40 ops/s; spans 10s) 13:24:22.6769: emr1poj4j996g37b-0001-001.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Cluster v6.2.6, primary; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a; not in use: DidNotRespond 13:24:22.6769: emr1poj4j996g37b-0001-001.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: int ops=11, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 13:24:22.6769: emr1poj4j996g37b-0001-001.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+11=11 (1.10 ops/s; spans 10s); sub: 13:24:22.6769: emr1poj4j996g37b-0001-002.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Cluster v6.2.6, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a; not in use: DidNotRespond 13:24:22.6769: emr1poj4j996g37b-0001-002.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 13:24:22.6769: emr1poj4j996g37b-0001-002.emr1poj4j996g37b.wvkctd.euw1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 13:24:22.6769: Sync timeouts: 0; async timeouts: 0; fire and forget: 0; last heartbeat: -1s ago 13:24:22.6769: Starting heartbeat... 13:24:22.6772: Total connect time: 5,026 ms

Log with timeout set to 200ms:

15:57:17.5531: Connecting (sync) on .NET Core 3.1.25 (StackExchange.Redis: v2.6.48.48654) 15:57:17.5642: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379,connectTimeout=200,password=*****,ssl=True 15:57:17.5679: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379/Interactive: Connecting... 15:57:17.5774: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: BeginConnectAsync 15:57:17.5794: 1 unique nodes specified (with tiebreaker) 15:57:17.5798: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting) 15:57:17.5801: Allowing 1 endpoint(s) 00:00:00.2000000 to respond... 15:57:17.5806: Awaiting 1 available task completion(s) for 200ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=1,Free=32766,Min=2,Max=32767), POOL: (Threads=3,QueuedItems=0,CompletedItems=26) 15:57:17.5825: Configuring TLS 15:57:17.5931: TLS connection established successfully using protocol: Tls12 15:57:17.5953: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379/Interactive: Connected 15:57:17.5968: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Server handshake 15:57:17.5968: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Authenticating (password) 15:57:17.6029: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Setting client name: 169(SE.Redis-v2.6.48.48654) 15:57:17.6042: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Auto-configuring... 15:57:17.6043: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Requesting tie-break (Key="__Booksleeve_TieBreak")... 15:57:17.6044: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379/Interactive: Writing: GET __Booksleeve_TieBreak 15:57:17.6046: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Sending critical tracer (handshake): ECHO 15:57:17.6046: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379/Interactive: Writing: ECHO 15:57:17.6047: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Flushing outbound buffer 15:57:17.6047: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: OnEstablishingAsync complete 15:57:17.6047: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Starting read 15:57:17.6081: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Auto-configured (INFO) role: replica 15:57:17.6089: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Auto-configured (INFO) version: 6.2.6 15:57:17.6093: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Auto-configured (INFO) server-type: cluster 15:57:17.6281: Response from clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379/Interactive / GET __Booksleeve_TieBreak: Error: MOVED 6202 emr1cd6qvn7xsw7u-0001-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379 15:57:17.6282: Response from clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379/Interactive / ECHO: BulkString: 16 bytes 15:57:17.6294: All 1 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=4,CompletedItems=45) 15:57:17.6297: Endpoint summary: 15:57:17.6297: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished 15:57:17.6297: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Returned with success as Cluster replica (Source: From command: ECHO) 15:57:17.6338: emr1cd6qvn7xsw7u-0002-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync already connected start 15:57:17.6344: emr1cd6qvn7xsw7u-0002-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379/Interactive: Writing: PING 15:57:17.6352: emr1cd6qvn7xsw7u-0002-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting) 15:57:17.6353: emr1cd6qvn7xsw7u-0001-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting) 15:57:17.6353: emr1cd6qvn7xsw7u-0001-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting) 15:57:17.6353: Allowing 4 endpoint(s) 00:00:00.1450000 to respond... 15:57:17.6353: Awaiting 4 available task completion(s) for 145ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=4,CompletedItems=51) 15:57:17.6376: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync completed (From command: ECHO) 15:57:17.6411: Response from emr1cd6qvn7xsw7u-0002-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379/Interactive / PING: SimpleString: PONG 15:57:17.6464: emr1cd6qvn7xsw7u-0002-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: OnConnectedAsync already connected end 15:57:17.7809: Not all available tasks completed cleanly (from ReconfigureAsync#1271, timeout 145ms), IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=1,Free=32766,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=0,CompletedItems=72) 15:57:17.7817: Server[0] (emr1cd6qvn7xsw7u-0002-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379) Status: RanToCompletion (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: -1, out-pipe: -1, bw: Inactive, rs: ReadAsync. ws: Idle) 15:57:17.7817: Server[1] (emr1cd6qvn7xsw7u-0002-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379) Status: WaitingForActivation (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: -1, out-pipe: -1, bw: Inactive, rs: ReadAsync. ws: Idle) 15:57:17.7817: Server[2] (emr1cd6qvn7xsw7u-0001-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379) Status: WaitingForActivation (inst: 12, qs: 0, in: 0, qu: 12, aw: False, in-pipe: -1, out-pipe: -1, bw: Inactive, rs: ReadAsync. ws: Idle) 15:57:17.7817: Server[3] (emr1cd6qvn7xsw7u-0001-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379) Status: WaitingForActivation (inst: 11, qs: 0, in: 0, qu: 11, aw: False, in-pipe: -1, out-pipe: -1, bw: Inactive, rs: ReadAsync. ws: Idle) 15:57:17.7817: Endpoint summary: 15:57:17.7818: emr1cd6qvn7xsw7u-0002-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished 15:57:17.7818: emr1cd6qvn7xsw7u-0002-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished 15:57:17.7818: emr1cd6qvn7xsw7u-0001-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished 15:57:17.7818: emr1cd6qvn7xsw7u-0001-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Endpoint is ConnectedEstablished 15:57:17.7818: emr1cd6qvn7xsw7u-0002-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Returned with success as Cluster primary (Source: Already connected) 15:57:17.7818: emr1cd6qvn7xsw7u-0002-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Did not respond 15:57:17.7818: emr1cd6qvn7xsw7u-0001-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Did not respond 15:57:17.7818: emr1cd6qvn7xsw7u-0001-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Did not respond 15:57:17.7818: Cluster: 16384 of 16384 slots covered 15:57:17.7818: Endpoint Summary: 15:57:17.7820: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Cluster v6.2.6, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active 15:57:17.7821: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: int ops=13, qu=0, qs=0, qc=0, wr=0, socks=1, non-pref=1; sub ops=4, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1 15:57:17.7825: clustercfg.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+13=13 (1.30 ops/s; spans 10s); sub: 0+4=4 (0.40 ops/s; spans 10s) 15:57:17.7825: emr1cd6qvn7xsw7u-0002-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Cluster v6.2.6, primary; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a 15:57:17.7825: emr1cd6qvn7xsw7u-0002-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 15:57:17.7825: emr1cd6qvn7xsw7u-0002-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 15:57:17.7826: emr1cd6qvn7xsw7u-0001-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Cluster v6.2.6, primary; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a; not in use: DidNotRespond 15:57:17.7826: emr1cd6qvn7xsw7u-0001-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: int ops=11, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 15:57:17.7826: emr1cd6qvn7xsw7u-0001-001.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+11=11 (1.10 ops/s; spans 10s); sub: 15:57:17.7826: emr1cd6qvn7xsw7u-0002-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Cluster v6.2.6, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a; not in use: DidNotRespond 15:57:17.7826: emr1cd6qvn7xsw7u-0002-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 15:57:17.7826: emr1cd6qvn7xsw7u-0002-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 15:57:17.7826: emr1cd6qvn7xsw7u-0001-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Cluster v6.2.6, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: n/a; not in use: DidNotRespond 15:57:17.7826: emr1cd6qvn7xsw7u-0001-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0 15:57:17.7826: emr1cd6qvn7xsw7u-0001-002.emr1cd6qvn7xsw7u.wvkctd.euw1.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 15:57:17.7826: Sync timeouts: 0; async timeouts: 0; fire and forget: 0; last heartbeat: -1s ago 15:57:17.7826: Starting heartbeat... 15:57:17.7829: Total connect time: 230 ms

Any ideas what we can do here to improve? I think it's also worth noting that it always says "Endpoint is ConnectedEstablished" followed by "Did not respond", but the endpoints seem to work.

— Reply to this email directly, view it on GitHub https://github.com/StackExchange/StackExchange.Redis/issues/2017#issuecomment-1233130624, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAB7A75A6HIAZ5QJFKNK2FDV356XDANCNFSM5PPWFFHA . You are receiving this because you were mentioned.Message ID: @.***>

Sep 01 '22 07:09 greyhoundgames

Do you have ready to run set on your project to pre compile for the right platform (net6+ feature). That didn't solve it but it helped it.

Yes I do.

Whereas this does improve cold start times, the time to connect to the Redis Cluster still is almost exactly as long as the configured timeout.

Sep 02 '22 06:09 Compufreak345

I have just updated from netcore3.1 to net6.0 running on AWS Lambda and have also started seeing a lot of timeouts.

syncTimeout and connectTimeout are both set to 1000ms.
PublishReadyToRun is true.
I also tried increasing the min worker threads but it caused lambda to perform very poorly so had to revert.
I've enabled Slow Logs and Engine Logs on Elastic Cache but so far nothing has been logged.

13:40:38.60: Connecting (async) on .NET 6.0.4 (StackExchange.Redis: v2.5.43.42402)
13:40:38.62: prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379,syncTimeout=1000,connectTimeout=1000,ssl=False,abortConnect=False
13:40:38.62: prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379/Interactive: Connecting...
13:40:38.63: prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: BeginConnectAsync
13:40:38.64: 1 unique nodes specified (with tiebreaker)
13:40:38.64: prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)
13:40:38.64: Allowing 1 endpoint(s) 00:00:01 to respond...
13:40:38.64: Awaiting 1 available task completion(s) for 1000ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=1,Free=32766,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=0,CompletedItems=4)
13:40:39.64: Not all available tasks completed cleanly (from ReconfigureAsync#1731, timeout 1000ms), IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=2,CompletedItems=4)
13:40:39.64:   Server[0] (prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379) Status: WaitingForActivation (inst: 0, qs: 0, in: 0, qu: 0, aw: False, in-pipe: -1, out-pipe: -1, bw: Inactive, rs: NotStarted. ws: Initializing)
13:40:39.64: Endpoint summary:
13:40:39.64:   prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: Endpoint is Connecting
13:40:39.64:   prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: Did not respond
13:40:39.64: Election summary:
13:40:39.64:   Election: prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379 had no tiebreaker set
13:40:39.64:   Election: No masters detected
13:40:39.64: Endpoint Summary:
13:40:39.64:   prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: Standalone v3.0.0, master; keep-alive: 00:01:00; int: Connecting; sub: Connecting; not in use: DidNotRespond
13:40:39.64:   prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: int ops=0, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0, socks=1
13:40:39.64:   prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0 (0.00 ops/s; spans 10s); sub: 0 (0.00 ops/s; spans 10s)
13:40:39.64: Sync timeouts: 0; async timeouts: 0; fire and forget: 0; last heartbeat: -1s ago
13:40:39.64: Resetting failing connections to retry...
13:40:39.65:   Retrying - attempts left: 2...
13:40:39.65: 1 unique nodes specified (with tiebreaker)
13:40:39.65: prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)
13:40:39.65: Allowing 1 endpoint(s) 00:00:01 to respond...
13:40:39.65: Awaiting 1 available task completion(s) for 1000ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=2,Free=32765,Min=2,Max=32767), POOL: (Threads=2,QueuedItems=2,CompletedItems=4)
13:40:40.64: All 1 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=3,Free=32764,Min=2,Max=32767), POOL: (Threads=3,QueuedItems=5,CompletedItems=9)
13:40:40.64: Endpoint summary:
13:40:40.64:   prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: Endpoint is Connecting
13:40:40.64:   prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: Returned, but incorrectly
13:40:40.64: Election summary:
13:40:40.64:   Election: prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379 had no tiebreaker set
13:40:40.64:   Election: No masters detected
13:40:40.64: Endpoint Summary:
13:40:40.64:   prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: Standalone v3.0.0, master; keep-alive: 00:01:00; int: Connecting; sub: Connecting; not in use: DidNotRespond
13:40:40.64:   prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: int ops=0, qu=0, qs=0, qc=0, wr=0, socks=2; sub ops=0, qu=0, qs=0, qc=0, wr=0, socks=2
13:40:40.64:   prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0 (0.00 ops/s; spans 10s); sub: 0 (0.00 ops/s; spans 10s)
13:40:40.64: Sync timeouts: 0; async timeouts: 0; fire and forget: 0; last heartbeat: -1s ago
13:40:40.64: Resetting failing connections to retry...
13:40:40.64:   Retrying - attempts left: 1...
13:40:40.64: 1 unique nodes specified (with tiebreaker)
13:40:40.64: prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: OnConnectedAsync init (State=Connecting)
13:40:40.64: Allowing 1 endpoint(s) 00:00:01 to respond...
13:40:40.64: Awaiting 1 available task completion(s) for 1000ms, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=3,Free=32764,Min=2,Max=32767), POOL: (Threads=3,QueuedItems=5,CompletedItems=9)
13:40:40.64: prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: OnConnectedAsync completed (Disconnected)
13:40:40.64: prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: OnConnectedAsync completed (Disconnected)
13:40:40.64: Connection failed: prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379 (Subscription, UnableToConnect): UnableToConnect on prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379/Subscription, Initializing/NotStarted, last: NONE, origin: BeginConnectAsync, outstanding: 0, last-read: 1s ago, last-write: 1s ago, keep-alive: 60s, state: Connecting, mgr: 10 of 10 available, last-heartbeat: never, global: 1s ago, v: 2.5.43.42402
13:40:40.64: Connection failed: prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379 (Interactive, UnableToConnect): UnableToConnect on prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379/Interactive, Initializing/NotStarted, last: NONE, origin: BeginConnectAsync, outstanding: 0, last-read: 2s ago, last-write: 2s ago, keep-alive: 60s, state: Connecting, mgr: 10 of 10 available, last-heartbeat: never, global: 2s ago, v: 2.5.43.42402
13:40:41.64: Not all available tasks completed cleanly (from ReconfigureAsync#1731, timeout 1000ms), IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=4,Free=32763,Min=2,Max=32767), POOL: (Threads=4,QueuedItems=0,CompletedItems=20)
13:40:41.64:   Server[0] (prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379) Status: WaitingForActivation (inst: 0, qs: 0, in: -1, qu: 0, aw: False, in-pipe: -1, out-pipe: -1, bw: Inactive, rs: NotStarted. ws: Initializing)
13:40:41.64: Endpoint summary:
13:40:41.64:   prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: Endpoint is Disconnected
13:40:41.64:   prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: Returned, but incorrectly
13:40:41.64: Election summary:
13:40:41.64: prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: OnConnectedAsync completed (Disconnected)
13:40:41.64:   Election: prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379 had no tiebreaker set
13:40:41.64:   Election: No masters detected
13:40:41.64: Endpoint Summary:
13:40:41.64:   prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: Standalone v3.0.0, master; keep-alive: 00:01:00; int: Disconnected; sub: Disconnected; not in use: DidNotRespond
13:40:41.64:   prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: int ops=0, qu=0, qs=0, qc=0, wr=0, socks=2; sub ops=0, qu=0, qs=0, qc=0, wr=0, socks=2
13:40:41.64:   prod-multiaz.wo3f6z.ng.0001.apse2.cache.amazonaws.com:6379: Circular op-count snapshot; int: 0 (0.00 ops/s; spans 10s); sub: 0 (0.00 ops/s; spans 10s)
13:40:41.64: Sync timeouts: 0; async timeouts: 0; fire and forget: 0; last heartbeat: -1s ago
13:40:41.64: Starting heartbeat...
13:40:41.64: Total connect time: 3,040 ms

Sep 09 '22 14:09 pariesz

@pariesz Can you verify this is happening on 2.6.66? Some tweaks in there and I want to make sure we're talking 1:1 here.

Sep 09 '22 22:09 NickCraver