在《.NET 5.0 背鍋案》第7集-大結局之後,園子和 .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.GetAllAsyncT
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的資料庫連線監控圖