ConnectionMultiplexer takes up to 2 seconds to connect when run from within AWS lambda #2017
Comments
|
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 :) |
|
Thanks for replying! Here is what you asked for. zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Connecting... |
|
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. |
|
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 |
|
@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! |
|
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. Connect log:Connecting (sync) on .NET Core 3.1.22 03:27:21.3382: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379/Interactive: Connecting... |
|
Alrighty, awesome - I'll add an explicit version to the log as a follow-up :) In the latest, I see an overall of ...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:
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! |
|
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). |
|
Some really interesting results when using a JIT setting in the project file! core .net 6 .net turning on PublishReadyToRun true in project file (Pre jit) 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.118:02:02.5455: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379,asyncTimeout=3000,connectTimeout=3000,abortConnect=False,connectRetry=1 |
|
Also as an aside, I went back to the latest stable stack exchange redis and the performance was similar for the cold starts FYI |
|
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. |
2022-03-02T18:17:16.282Z d0f13617-781d-4229-8b5b-dffeb6a2c3a7 Connect log:Connecting (sync) on .NET 6.0.118:17:15.9634: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379,asyncTimeout=3000,connectTimeout=3000,abortConnect=False,connectRetry=1 |
|
Note that in lambda each lambda sandbox has its own multiplexer handling one user at a time. |
|
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. |
|
@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); |
|
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: PONG20:47:25.6846: 10.2.191.128:6379: OnConnectedAsync already connected end 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. |
This tweaks logging a bit to make it easier to parse and switches timings to `ValueStopwatch` while I'm in here adding one. Helps investigate things like #2017.
|
@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. |
|
Ok. I will try it out sometime next week and post. |
|
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.114:54:18.3622: zir1ouzc69wq8b4x.qtlqwe.clustercfg.usw2.cache.amazonaws.com:6379,asyncTimeout=3000,connectTimeout=3000,abortConnect=False,connectRetry=1 |
|
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. |
|
@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. |
|
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: 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. |
|
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. |
|
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 :) |
|
Hi @NickCraver, We also got a similar issue after we upgraded the Redis library from 2.2.79 to 2.5.61. I also collected logs. Please help to check it, thanks. |
|
Hi @jlee58tw , @NickCraver Log with the default timeout of 5s: Log with timeout set to 200ms: 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. |
|
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
<#2017 (comment)>,
or unsubscribe
<https://github.com/notifications/unsubscribe-auth/AAB7A75A6HIAZ5QJFKNK2FDV356XDANCNFSM5PPWFFHA>
.
You are receiving this because you were mentioned.Message ID:
***@***.***>
|
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. |
|
I have just updated from netcore3.1 to net6.0 running on AWS Lambda and have also started seeing a lot of timeouts.
|
|
@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. |
|
Sure I also saw another log testing this version that was a little different: I also just installed the 6.2.6 engine patch |
|
@pariesz Is it possible you have subscriptions/subscription commands disabled on the server? Trying to reason about the logs here and wonder if it's a config/expectation mismatch in play. |
|
I doubt it. but I'm not sure how to check to be sure. It's a pretty standards multi-az AWS ElasticCache deployment with cluster mode disabled. I haven't made any tweaks to the configuration. We also have several other services sharing this instance for similar .Net EDIT: I'm also able to replicate this running the service locally with a local instance of redis. However I currently have 2 seperate net6.0 applications running locally with EDIT 2: It seems the Thanks for taking you time with this. |
|
Hey y'all - there was a change just now in 2.6.70 (now on NuGet) which may improve timings here again - it's worth a poke if anyone has time to assess if it moves the needle any :) |
|
Hi @NickCraver , we just tested with 2.6.86 and we don't have the issues described above anymore. Thanks! |
|
@Compufreak345 awesome, thank you for the update! |
|
We are experiencing a delay of 1.04 secs on the initial connection to Elastic Cache - Redis cluster from an AWS Dotnet 6 Lambda. The connection code is. We are using the StackExchange.Redis ( version 2.6.104) to connect to cluster. Any help is appreciated. |
|
@ssathasivanACR You'll want to pass a logger as the second arg to .Connect() there to see what's what - if you can post that here it'd be helpful. Lambda's still on few cores though, so no promises on any improvements there depending on what's happening. |
|
Closing out to tidy up, but offer above stands - with a log happy to reopen and add advice! |
In case anyone is facing that particular behavior I would recommend you attach the But then after reviewing the |
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.
The text was updated successfully, but these errors were encountered: