《.NET 5.0 背鍋案》第3集-劇情反轉:EnyimMemcachedCore 無罪,.NET 5.0 繼續背鍋

部落格園團隊發表於2020-11-16

今天晚上基於第2集中改進版的 EnyimMemcachedCore 進行了釋出,釋出過程中故障重現,最大的嫌犯 EnyimMemcachedCore 被證明無罪,暫時委屈 .NET 5.0 繼續背鍋。

釋出操作啟動後,Kubernetes 叢集在 20:05 左右開始更新 pod

在 20:09 之前一切正常,20:09 開始日誌開始出現 tcp 連線相關的異常。

最先報異常的是 redis 客戶端 StackExchange.Redis

StackExchange.Redis.RedisTimeoutException: Timeout awaiting response (outbound=0KiB, inbound=0KiB, 1120ms elapsed, timeout is 1000ms), command=SET, next: SET blog_v2_blogpost-stats-192308-8057845

接著是 EnyimMemcachedCore

2020-11-16 20:09:03.901 [Error] Pool is full, timeouting. 10.0.78.156:11211
Enyim.Caching.Configuration.MemcachedClientConfiguration

日誌中一堆上面的2個錯誤交替出現,大概是這個時候故障開始出現,訪問速度開始變慢。

接著 20:12~20:17 期間出現非常神奇的事情,日誌中只有不到10條的記錄,這根本不可能,而且這時處於故障期間,大量請求響應緩慢,只有一個原因可以解釋——整個系統 hang 住了,似乎在這段時間所有執行緒都卡住了,.NET 5.0 的世界似乎時間停止了。

20:18 開始日誌記錄又開始大量出現,這時正好所有 pod 更新完畢

雖然 pod 更新完成了,但從日誌中看還是有 pod 在重啟,可能是因為健康檢查失敗而重啟。

20:19 開始情況變得更糟

Redis客戶端連線超時的情況繼續

StackExchange.Redis.RedisTimeoutException: Timeout awaiting response"

EnyimMemcachedCore 無法從 socket pool 拿到連線的情況繼續

Pool is full, timeouting

EnyimMemcachedCore 出現新的異常情況

2020-11-16 20:19:29.373 [Warning] Socket bound to "10.0.78.156:11211" has 20 unread data! This is probably a bug in the code. InstanceID was 59b0c942-47d4-4977-bd27-668ed4972459.

HttpClient 也開始出現連線超時

System.Threading.Tasks.TaskCanceledException: The request was canceled due to the configured HttpClient.Timeout of 3 seconds elapsing.

EnyimMemcachedCore 各種錯誤

[Error] Timeout to reset an acquired socket.
[Error] Acquire failed. Maybe we're already disposed?
...

20:20 開始出現大量資料庫連線超時的情況,故障全面爆發。

System.InvalidOperationException: Timeout expired. The timeout period elapsed prior to obtaining a connection from the pool. This may have occurred because all pooled connections were in use and max pool size was reached

似乎從時間停止狀態恢復的 .NET 5.0 世界一切錯亂了,趕緊回退。

這時開始向 .NET Core 3.1 版回退,在 20:25 左後回退全部完成後,一切恢復了正常。

這次完整地經歷了整個故障發生的過程,真是驚心動魄,經歷之後讓人茫然不知所措,不管怎麼樣,這個鍋不能讓 EnyimMemcachedCore 背,我們部落格系統的程式碼也背不起(就是我們想寫也寫不出能讓 .NET 5.0 runtime 世界天翻地覆的程式碼),還是先委屈 .NET 5.0 繼續背鍋吧,雖然這會招來一片罵聲,但我們實在找不出可以委以重任的替代者。

【更新】11月16日 23:00 之後,我們通過環境變數 COMPlus_TC_QuickJit 禁用了 Quick JIT 後釋出了 .NET 5.0 版,故障依舊,回退 .NET Core 3.1 版恢復。
【更新】11月17日 13:08 左右在 github 上發現一個可能相關的 issue Garbage Collection Thread is blocked waiting for another thread for 10 seconds or more

相關文章