《.NET 5.0 背锅案》第3集-剧情反转:EnyimMemcachedCore 无罪,.NET 5.0 继续背锅

今天晚上基于第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

posted @ 2020-11-16 22:04  博客园团队  阅读(7216)  评论(61编辑  收藏  举报