记一次 .NET 某药品仓储管理系统卡死分析

提示：扫一扫查出行
【扫一扫了解最新限行尾号】
复制提示

一：背景

1. 讲故事

这个月初，有位朋友wx上找到我，说他的api过一段时间后，就会出现只有请求，没有响应的情况，截图如下：

从朋友的描述中看样子程序是被什么东西卡住了，这种卡死的问题解决起来相对简单，接下来我就用 windbg 给大家分析一下。

二：Windbg 分析

1. Request 请求正在干嘛？

既然朋友说 api 有 request 无 response，那怎么去验证朋友的话对不对呢？我们都知道 .NET 用 HttpContext 来表示一个请求，言外之意就是可以去抓 HttpContext 下的时长属性，Netext 中有一个 !whttp 命令可以帮助我们。

0:000> !whttp HttpContext Thread Time Out Running Status Verb Url 000000563bf803b0 42 00:01:50 00:01:24 200 POST http://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=x-HN 000000563bf84660 -- 00:01:50 Finished 200 GET http://xxx.com:30003/ 000000563c4a0470 51 00:01:50 00:00:12 200 POST http://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=xxx2C 00000056bbf63590 30 00:01:50 00:02:41 200 POST http://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=xxx-B2C 00000056bc82a038 -- 00:01:50 Finished 200 GET http://localhost:30003/ 00000056bc84a3e8 44 00:01:50 00:00:51 200 POST http://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=x 00000056bc8671c8 46 00:01:50 00:00:45 200 POST http://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=xxx-B2C 000000573bf44698 35 00:01:50 00:02:39 200 POST http://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=x 000000573bf483c0 33 00:01:50 00:02:41 200 POST http://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=x-HN 000000573bf97e80 40 00:01:50 00:02:32 200 POST http://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=ZJB2C 000000573c583b08 -- 00:01:50 Finished 200 GET http://localhost:30003/ 000000573c589ec8 -- 00:01:50 Finished 200 GET http://xxx.com:30003/Wms/xxx/xxx/xxx 000000573c760e28 -- 00:01:50 Finished 200 POST http://xxx.com:30003/Wms/xxx/xxx/xxx 000000573c95f990 48 00:01:50 00:00:31 200 POST http://xxx.com:30003/Wms/Common/xxx?xxx=xxx&xxx=x-HN 00000057bbf4f8e8 31 00:01:50 00:02:12 200 POST http://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=x 00000057bc080340 50 00:01:50 00:00:19 200 POST http://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=x 000000583c4aee80 43 00:01:50 00:01:11 200 POST http://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=xxx2B 000000583c4d0c50 53 00:01:50 00:00:01 200 POST http://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=xxx2B 00000058bbf8f1a0 34 00:01:50 00:02:22 200 POST http://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=xxx2B 000000593bfe1758 41 00:01:50 00:01:22 200 POST http://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=xxx2C 000000593c892160 -- 00:01:50 Finished 200 GET http://xxx.com:30003/Wms/xxx/xxx/xxxJob 000000593ca813b0 45 00:01:50 00:00:30 200 POST http://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=xxx-HN 000000593caa45d8 -- 00:01:50 Finished 200 GET http://xxx.com:30003/ 00000059bc1ad808 32 00:01:50 00:01:45 200 POST http://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=xxx-B2C 00000059bc1c3d70 36 00:01:50 00:01:29 200 POST http://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=x25 HttpContext object(s) found matching criteria

从 Running 列可以看到大多请求都已经达到1分钟以上，这也验证了朋友所说的卡死问题，按照经验，可以取 Running 列中最大的 httpContext 所在的线程，也就是上面的 30 和 33 号线程，看看它们都在干什么？

2. 探究 Running 最长线程

接下来切到 30 和 33 号线程，看看它们的线程栈。

0:000> ~30s ntdll!NtWaitForSingleObject+0xa: 00007ffd`b81f024a c3 ret 0:030> !clrstack OS Thread Id: 0x29d0 (30) Child SP IP Call Site 0000005acc3ac590 00007ffdb81f024a [PrestubMethodFrame: 0000005acc3ac590] xxx.xxx.RedisConnectionHelp.get_Instance() 0000005acc3ac850 00007ffd4dd78911 xxx.xxx.RedisCache..ctor(Int32, System.String) 0000005acc3ac8c0 00007ffd4dd78038 xxx.xxx.CacheByRedis.HashGet[[System.__Canon, mscorlib]](System.String, System.String, Int32) 0000005acc3ac968 00007ffdabef1f7c [StubHelperFrame: 0000005acc3ac968] 0000005acc3ac9c0 00007ffd4dd77f18 xxx.xxx.Cache.xxx.GetCacheNotAreaDataEntity[[System.__Canon, mscorlib]](System.String, System.String, System.String)...0:030> ~33s ntdll!NtWaitForMultipleObjects+0xa: 00007ffd`b81f07ba c3 ret 0:033> !clrstack OS Thread Id: 0x3ad4 (33) Child SP IP Call Site 0000005accabae90 00007ffdb81f07ba [GCFrame: 0000005accabae90] 0000005accabafb8 00007ffdb81f07ba [HelperMethodFrame_1OBJ: 0000005accabafb8] System.Threading.Monitor.ObjWait(Boolean, Int32, System.Object) 0000005accabb0d0 00007ffdaac60d64 System.Threading.ManualResetEventSlim.Wait(Int32, System.Threading.CancellationToken) 0000005accabb160 00007ffdaac5b4bb System.Threading.Tasks.Task.SpinThenBlockingWait(Int32, System.Threading.CancellationToken) 0000005accabb1d0 00007ffdab5a01d1 System.Threading.Tasks.Task.InternalWait(Int32, System.Threading.CancellationToken) 0000005accabb2a0 00007ffdab59cfa7 System.Threading.Tasks.Task`1[[System.__Canon, mscorlib]].GetResultxxx(Boolean) 0000005accabb2e0 00007ffd4d8d338f xxx.Config.xxx.Config`1[[System.__Canon, mscorlib]].GetConfig(xxx.Config.Model.ConfigListener, System.Func`2<xxx.Config.Request.GetConfigRequest,System.Threading.Tasks.Task`1<System.String>>) 0000005accabb340 00007ffd4d8d2f40 xxx.Config.xxx.Config`1[[System.__Canon, mscorlib]].get_Item(System.String, System.String) 0000005accabb3c0 00007ffd4dd78f7f xxx.Util.BaseConfig.get_GetRedisConn() 0000005accabb440 00007ffd4dd78e9c xxx.xxx.RedisConnectionHelp.GetConnectionString() 0000005accabb4a0 00007ffd4dd789cb xxx.xxx.RedisConnectionHelp..cctor() 0000005accabb940 00007ffdabef6953 [GCFrame: 0000005accabb940] 0000005accabc5b0 00007ffdabef6953 [PrestubMethodFrame: 0000005accabc5b0] xxx.xxx.RedisConnectionHelp.get_Instance() 0000005accabc870 00007ffd4dd78911 xxx.xxx.RedisCache..ctor(Int32, System.String) 0000005accabc8e0 00007ffd4dd78038 xxx.xxx.CacheByRedis.HashGet[[System.__Canon, mscorlib]](System.String, System.String, Int32) 0000005accabc988 00007ffdabef1f7c [StubHelperFrame: 0000005accabc988] 0000005accabc9e0 00007ffd4dd77f18 xxx.Core.Cache.xxx.GetCacheNotAreaDataEntity[[System.__Canon, mscorlib]](System.String, System.String, System.String) ...

上面的信息不难发现 30 号线程正卡在 RedisConnectionHelp.get_Instance() 处，33 号线已经进入了 RedisConnectionHelp.get_Instance() 方法中，最后在 GetConfig() 处等待 Result 的结果，按经验来说，30 号线程看样子正在锁等待， 33 号正在等待异步结果，接下来的突破点就是探究下 RedisConnectionHelp.Instance 处代码。

3. 寻找问题代码

接下来用反编译工具 ILSpy 找到问题代码。

public static class RedisConnectionHelp { public static ConnectionMultiplexer Instance { get { if (_instance == null) { lock (Locker) { if (_instance == null || !_instance.IsConnected) { _instance = GetManager(); } } } return _instance; } } }

30 号线程果然是卡在 Locker 处，接下来深挖下 33 号线程所执行的 GetManager() 方法，简化后代码如下：

public T this[string dataId, string key = ""] { get { try { string config = GetConfig(configListener, new NacosConfigClient(Base.NacosConfiguration).DoGetConfigAsync);return JsonConvert.DeserializeObject<T>(config); } catch (Exception ex) { return default(T); } } }private string GetConfig(ConfigListener listener, Func<GetConfigRequest, Task<string>> action) { var text2 = action(new GetConfigRequest { DataId = listener.DataId, Group = listener.Group, Tenant = text }).Result;return text2; }internal async Task<string> DoGetConfigAsync(GetConfigRequest request) { IRestResponse restResponse = await HttpUtil.Request(currentServerAddr, Method.GET, request.ParamValues(), xxx);return restResponse.Content; }

可以看到代码卡在了 Result 上无限期等待，到这里我就想到了 同步上下文 ，我看他这个程序是 .NET 4.8 下的 ASP.NET MVC，记得不错上下文应该是 AspNetSynchronizationContext，具体死锁原因可参见我的这篇文章：一句 Task.Result 就死锁, 这代码还怎么写？，解决办法大概有四种。