一:背景
1. 讲故事
这个月初,有位朋友wx上找到我,说他的api过一段时间后,就会出现只有请求,没有响应的情况,截图如下:
文章图片
从朋友的描述中看样子程序是被什么东西卡住了,这种卡死的问题解决起来相对简单,接下来我就用 windbg 给大家分析一下。
二:Windbg 分析
1. Request 请求正在干嘛?
既然朋友说 api 有 request 无 response,那怎么去验证朋友的话对不对呢? 我们都知道 .NET 用 HttpContext
来表示一个请求,言外之意就是可以去抓 HttpContext 下的时长属性,Netext 中有一个 !whttp
命令可以帮助我们。
0:000> !whttp
HttpContextThread Time Out RunningStatus VerbUrl
000000563bf803b042 00:01:50 00:01:24200 POSThttp://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=x-HN
000000563bf84660-- 00:01:50 Finished200 GEThttp://xxx.com:30003/
000000563c4a047051 00:01:50 00:00:12200 POSThttp://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=xxx2C
00000056bbf6359030 00:01:50 00:02:41200 POSThttp://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=xxx-B2C
00000056bc82a038-- 00:01:50 Finished200 GEThttp://localhost:30003/
00000056bc84a3e844 00:01:50 00:00:51200 POSThttp://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=x
00000056bc8671c846 00:01:50 00:00:45200 POSThttp://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=xxx-B2C
000000573bf4469835 00:01:50 00:02:39200 POSThttp://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=x
000000573bf483c033 00:01:50 00:02:41200 POSThttp://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=x-HN
000000573bf97e8040 00:01:50 00:02:32200 POSThttp://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=ZJB2C
000000573c583b08-- 00:01:50 Finished200 GEThttp://localhost:30003/
000000573c589ec8-- 00:01:50 Finished200 GEThttp://xxx.com:30003/Wms/xxx/xxx/xxx
000000573c760e28-- 00:01:50 Finished200 POSThttp://xxx.com:30003/Wms/xxx/xxx/xxx
000000573c95f99048 00:01:50 00:00:31200 POSThttp://xxx.com:30003/Wms/Common/xxx?xxx=xxx&xxx=x-HN
00000057bbf4f8e831 00:01:50 00:02:12200 POSThttp://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=x
00000057bc08034050 00:01:50 00:00:19200 POSThttp://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=x
000000583c4aee8043 00:01:50 00:01:11200 POSThttp://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=xxx2B
000000583c4d0c5053 00:01:50 00:00:01200 POSThttp://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=xxx2B
00000058bbf8f1a034 00:01:50 00:02:22200 POSThttp://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=xxx2B
000000593bfe175841 00:01:50 00:01:22200 POSThttp://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=xxx2C
000000593c892160-- 00:01:50 Finished200 GEThttp://xxx.com:30003/Wms/xxx/xxx/xxxJob
000000593ca813b045 00:01:50 00:00:30200 POSThttp://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=xxx-HN
000000593caa45d8-- 00:01:50 Finished200 GEThttp://xxx.com:30003/
00000059bc1ad80832 00:01:50 00:01:45200 POSThttp://xxx.com:30003/Wms/xxx/xxx?xxx=xxx&xxx=xxx-B2C
00000059bc1c3d7036 00:01:50 00:01:29200 POSThttp://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 c3ret
0:030> !clrstack
OS Thread Id: 0x29d0 (30)
Child SPIP 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 c3ret
0:033> !clrstack
OS Thread Id: 0x3ad4 (33)
Child SPIP 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)
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(config);
}
catch (Exception ex)
{
return default(T);
}
}
}private string GetConfig(ConfigListener listener, Func action)
{
var text2 = action(new GetConfigRequest
{
DataId = listener.DataId,
Group = listener.Group,
Tenant = text
}).Result;
return text2;
}internal async Task 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 就死锁, 这代码还怎么写?,解决办法大概有四种。- 使用 .ConfigureAwait(false)
- 改成全异步
- 用 Task 再包一层。
- 改成全同步
同步代码
中做了 异步代码.Result
导致的死锁问题,有非常多的文章都在抨击这种现象,在 asp.net core 中已经移除了这种同步上下文
的大坑,给到朋友的建议是改成全同步,死锁问题也随之消失。文章图片
【记一次 .NET 某药品仓储管理系统 卡死分析】哈哈,真替朋友开心!
推荐阅读
- IIS发布.net连接不上数据库解决办法
- 浅谈.NET 6 中 gRPC 的最新功能
- 利用Visual Studio 2017的扩展开发(VSIX、ItemTemplate) 快速实现项目的半自动化搭建
- C#进度条实现
- .net|利用MSXML2.XMLHTTP的无刷新技术
- 配置VS2008中文版调试.netframework源代码
- .net|解决Win8.1下VS2005编辑报错的问题
- Java与C#间json时间格式互转完美解决方案
- 在VS.NET内使用“从源代码管理打开”时出现无法读取项目文件的错误