在《.NET 5.0 背鍋案》第7集-大結局之后,園子和 .NET 繼續過上了幸福生活。。。劇情很美好,現實很殘酷。。。現實是舊案剛結,新案立至,而且新案與舊案有關聯,被迫繼續拍劇,並對該劇重新進行命名,劇名叫《高並發下的.NET》(后來改名為《博客園.NET歷險記》),第1季的劇情是《.NET 5.0 背鍋案》,第2季的劇情是《memcached連接暴增案》。
就在我們發布修復 StackExchange.Redis.Extensions 並發問題的更新后的第2天就出現了 memcached tcp 連接暴增的情況(通常連接數在3k以下,暴增時竟然超過15k),而這周一至周四每天都會出現。
下圖是其中1台 memcached 服務器(一共有3台)的 tcp 連接數監控圖(來自阿里雲雲監控)

阿里雲雲監控的報警郵件:
華東1(杭州) 雲服務器ECS實例:memcached1,雲服務器實例ID=i-bp1f2iqt161cleifjsfl,狀態=ESTABLISHED,instanceName=memcached1 ,Host.tcpconnection於18:41發生告警,平均值為15265.55Count,持續時間0分鍾。
而昨天下午(11月26日)16:17 的訪問高峰出現了一個相反情況,memcached 服務器 tcp 連接數突然暴跌

接着,16:45:07.025 開始出現 EnyimMemcachedCore 重置 socket 連接超時的錯誤日志
Enyim.Caching.MemcachedClient
2020-11-26 16:45:07.025 [Error] Timeout to reset an acquired socket.
16:45:07.774 開始出現 EnyimMemcachedCore 重置 socket 連接失敗的錯誤日志
Enyim.Caching.Configuration.MemcachedClientConfiguration
2020-11-26 16:45:07.774 [Error] Failed to reset an acquired socket.
16:45:56.582 開始出現 SqlClient 連接數據庫超時的錯誤日志,遇到這個錯誤的請求會出現500錯誤
Microsoft.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
---> System.ComponentModel.Win32Exception (258): Unknown error 258
16:45:56.658 開始出現 StackExchange.Redis 的超時錯誤
StackExchange.Redis.RedisTimeoutException: Timeout awaiting response (outbound=0KiB, inbound=0KiB, 1444ms elapsed, timeout is 1000ms), command=MGET, next: GET blog_v2_BlogPosts-389476, inst: 0, qu: 0, qs: 3, aw: False, rs: ReadAsync, ws: Idle, in: 14559, in-pipe: 0, out-pipe: 0, serverEndpoint: redis-blog:6379, mc: 1/1/0, mgr: 8 of 10 available, clientName: blog-web-5cf67c9795-6wmvz, IOCP: (Busy=0,Free=1000,Min=20,Max=1000), WORKER: (Busy=50,Free=32717,Min=50,Max=32767), v: 2.1.58.34321 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)
at StackExchange.Redis.Extensions.Core.Implementations.RedisDatabase.GetAllAsync(...)
16:45:57.305 開始出現 pod 重啟的日志,說明開始有 pod 因為健康檢查失敗而被強制重啟
2020-11-26 16:45:57.305 [Error] Request Execution Time: 7740 ms
ThreadPool.ThreadCount: 50, Pending work item count: 216, Completed work item count: 226710523
pod 啟動后接入負載時由於並發請求大,EnyimMemcachedCore 出現下面的錯誤日志
[Error] Pool is full, timeouting. 10.0.78.156:11211
隨后出現更多 SqlClient 連接數據庫超時的錯誤日志。
Execution Timeout Expired. The timeout period elapsed prior to completion of the operation or the server is not responding
16:52:00.028 EnyimMemcachedCore 開始出現告警日志
[Warning] Socket bound to "10.0.78.156:11211" has 44 unread data! This is probably a bug in the code. InstanceID was a247c5cd-575f-4f04-8573-fb03f199cb9c.
16:55 開始,從日志記錄可以看出更多 pod 在重啟
16:56:00.032 開始出現連接數據庫服務器失敗的錯誤
An error occurred using the connection to database '"xxx"' on server '"yyyy.sqlserver.rds.aliyuncs.com,3433"'.
Microsoft.EntityFrameworkCore.Database.Connection
日志中繼續出現大量連接數據庫服務器失敗或者超時的錯誤
17:03 開始,從日志看系統恢復了正常。
目前我們還沒有找到問題的線索,正在進一步排查。
最后,附上阿里雲RDS的數據庫連接監控圖
