4

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

 2 years ago
source link: https://developer.51cto.com/art/202201/699319.htm
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.
neoserver,ios ssh client

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

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

作者： 一线码农聊技术 来源： 一线码农聊技术|2022-01-17 21:28

1. 讲故事

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

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

二：Windbg 分析

1. Request 请求正在干嘛?

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

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

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

2. 探究 Running 最长线程

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

  1. 0:000> ~30s 
  2. ntdll!NtWaitForSingleObject+0xa: 
  3. 00007ffd`b81f024a c3              ret 
  4. 0:030> !clrstack  
  5. OS Thread Id: 0x29d0 (30) 
  6.         Child SP               IP Call Site 
  7. 0000005acc3ac590 00007ffdb81f024a [PrestubMethodFrame: 0000005acc3ac590] xxx.xxx.RedisConnectionHelp.get_Instance() 
  8. 0000005acc3ac850 00007ffd4dd78911 xxx.xxx.RedisCache..ctor(Int32, System.String) 
  9. 0000005acc3ac8c0 00007ffd4dd78038 xxx.xxx.CacheByRedis.HashGet[[System.__Canon, mscorlib]](System.String, System.String, Int32) 
  10. 0000005acc3ac968 00007ffdabef1f7c [StubHelperFrame: 0000005acc3ac968]  
  11. 0000005acc3ac9c0 00007ffd4dd77f18 xxx.xxx.Cache.xxx.GetCacheNotAreaDataEntity[[System.__Canon, mscorlib]](System.String, System.String, System.String) 
  12. 0:030> ~33s 
  13. ntdll!NtWaitForMultipleObjects+0xa: 
  14. 00007ffd`b81f07ba c3              ret 
  15. 0:033> !clrstack  
  16. OS Thread Id: 0x3ad4 (33) 
  17.         Child SP               IP Call Site 
  18. 0000005accabae90 00007ffdb81f07ba [GCFrame: 0000005accabae90]  
  19. 0000005accabafb8 00007ffdb81f07ba [HelperMethodFrame_1OBJ: 0000005accabafb8] System.Threading.Monitor.ObjWait(Boolean, Int32, System.Object) 
  20. 0000005accabb0d0 00007ffdaac60d64 System.Threading.ManualResetEventSlim.Wait(Int32, System.Threading.CancellationToken) 
  21. 0000005accabb160 00007ffdaac5b4bb System.Threading.Tasks.Task.SpinThenBlockingWait(Int32, System.Threading.CancellationToken) 
  22. 0000005accabb1d0 00007ffdab5a01d1 System.Threading.Tasks.Task.InternalWait(Int32, System.Threading.CancellationToken) 
  23. 0000005accabb2a0 00007ffdab59cfa7 System.Threading.Tasks.Task`1[[System.__Canon, mscorlib]].GetResultxxx(Boolean) 
  24. 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>>) 
  25. 0000005accabb340 00007ffd4d8d2f40 xxx.Config.xxx.Config`1[[System.__Canon, mscorlib]].get_Item(System.String, System.String) 
  26. 0000005accabb3c0 00007ffd4dd78f7f xxx.Util.BaseConfig.get_GetRedisConn() 
  27. 0000005accabb440 00007ffd4dd78e9c xxx.xxx.RedisConnectionHelp.GetConnectionString() 
  28. 0000005accabb4a0 00007ffd4dd789cb xxx.xxx.RedisConnectionHelp..cctor() 
  29. 0000005accabb940 00007ffdabef6953 [GCFrame: 0000005accabb940]  
  30. 0000005accabc5b0 00007ffdabef6953 [PrestubMethodFrame: 0000005accabc5b0] xxx.xxx.RedisConnectionHelp.get_Instance() 
  31. 0000005accabc870 00007ffd4dd78911 xxx.xxx.RedisCache..ctor(Int32, System.String) 
  32. 0000005accabc8e0 00007ffd4dd78038 xxx.xxx.CacheByRedis.HashGet[[System.__Canon, mscorlib]](System.String, System.String, Int32) 
  33. 0000005accabc988 00007ffdabef1f7c [StubHelperFrame: 0000005accabc988]  
  34. 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 找到问题代码。

  1. public static class RedisConnectionHelp 
  2.  public static ConnectionMultiplexer Instance 
  3.    if (_instance == null) 
  4.     lock (Locker) 
  5.      if (_instance == null || !_instance.IsConnected) 
  6.       _instance = GetManager(); 
  7.    return _instance; 

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

  1. public T this[string dataId, string key = ""] 
  2.    string config = GetConfig(configListener, new NacosConfigClient(Base.NacosConfiguration).DoGetConfigAsync); 
  3.    return JsonConvert.DeserializeObject<T>(config); 
  4.   catch (Exception ex) 
  5.    return default(T); 
  6. private string GetConfig(ConfigListener listener, Func<GetConfigRequest, Task<string>> action) 
  7.  var text2 = action(new GetConfigRequest 
  8.   DataId = listener.DataId, 
  9.   Group = listener.Group, 
  10.   Tenant = text 
  11.  }).Result; 
  12.  return text2; 
  13. internal async Task<string> DoGetConfigAsync(GetConfigRequest request) 
  14.  IRestResponse restResponse = await HttpUtil.Request(currentServerAddr, Method.GET, request.ParamValues(), xxx); 
  15.  return restResponse.Content; 

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

  • 使用 .ConfigureAwait(false)
  • 改成全异步
  • 用 Task 再包一层。
  • 改成全同步

其实本次事故主要还是因为在 同步代码 中做了 异步代码.Result 导致的死锁问题，有非常多的文章都在抨击这种现象，在 asp.net core 中已经移除了这种同步上下文的大坑，给到朋友的建议是改成全同步，死锁问题也随之消失。

哈哈，真替朋友开心!

本文转载自微信公众号「 一线码农聊技术」，可以通过以下二维码关注。转载本文请联系一线码农聊技术公众号。

【编辑推荐】

【责任编辑：武晓燕 TEL：（010）68476606】
点赞 0

report

Recommend

About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK