Web Service 请求 60s 问题调查【未解决】

🏷️ ASP.NET

根据听云的统计，很多慢事务的时间都在 60 秒左右。
而且返回的 HttpCode 为 500（服务器内部错误）。但是所有的接口的调用都是有 TryCatch 的，如果业务处理发生了异常，也是可以正常返回的。

对比了正常和异常的请求，发现异常请求中 ScriptModule.OnPostAcquireRequestState 方法执行了很长时间，之后直接调用 SessionStateModule.OnEndRequest 结束了请求。
而正常流程下还会有执行很多接口中的处理，之后才会调用 SessionStateModule.OnReleaseState 结束请求。

异常请求的流程

1. Global.Application_BeginRequest
2. WindowsAuthenticationModule.OnEnter
3. ScriptModule.AuthenticateRequestHandler
4. Global.Application_AuthenticateRequest
5. DefaultAuthenticationModule.OnEnter
6. ServiceHttpModule.BeginProcessRequest
7. UrlAuthorizationModule.OnEnter
8. FileAuthorizationModule.OnEnter
9. OutputCacheModule.OnEnter
10. UrlRoutingModule.OnApplicationPostResolveRequestCache
11. SessionStateModule.BeginAcquireState
12. ProfileModule.OnEnter
13. ScriptModule.OnPostAcquireRequestState
14. SessionStateModule.OnEndRequest
15. ProfileModule.OnLeave
16. ScriptModule.EndRequestHandler

正常请求的流程

1. Global.Application_BeginRequest
2. WindowsAuthenticationModule.OnEnter
3. ScriptModule.AuthenticateRequestHandler
4. Global.Application_AuthenticateRequest
5. DefaultAuthenticationModule.OnEnter
6. ServiceHttpModule.BeginProcessRequest
7. UrlAuthorizationModule.OnEnter
8. FileAuthorizationModule.OnEnter
9. OutputCacheModule.OnEnter
10. UrlRoutingModule.OnApplicationPostResolveRequestCache
11. SessionStateModule.BeginAcquireState
12. ProfileModule.OnEnter
13. ScriptModule.OnPostAcquireRequestState
14. ImplicitAsyncPreloadModule.OnEnter
15. RedisNativeClient.GetBytes
16. ...
17. ...
18. SessionStateModule.OnReleaseState
19. OutputCacheModule.OnLeave
20. ProfileModule.OnLeave
21. ScriptModule.EndRequestHandler

下面的描述摘自 ASP.Net 请求处理机制初步探索之旅 - Part 3 管道 :

从上面的介绍中可以看到，第九到第十个事件是： AcquireRequestState ， PostAcquireRequestState 。这期间首先会接收到浏览器发过来的 SessionId ，然后先会将 IHttpHandler 接口尝试转换为 IRequiresSessionState 接口，如果转换成功，ASP.NET 会根据这个 SessionId 到服务器的 Session 池 中去查找所对应的 Session 对象，并将这个 Session 对象 赋值到 HttpContext 对象 的 Session 属性。如果尝试转换为 IRequiresSessionState 接口不成功，则不加载 Session。

所以准备禁用 Session，改为通过自定义的处理来创建这个 SessionId，实际的 Session 数据则保存在 Redis 中。

实际发布到生产后发现并没有解决任何问题。下面是修改后的异常请求流程。

禁用 Session 后异常请求的流程

1. Global.Application_BeginRequest
2. WindowsAuthenticationModule.OnEnter
3. ScriptModule.AuthenticateRequestHandler
4. Global.Application_AuthenticateRequest
5. DefaultAuthenticationModule.OnEnter
6. ServiceHttpModule.BeginProcessRequest
7. UrlAuthorizationModule.OnEnter
8. FileAuthorizationModule.OnEnter
9. OutputCacheModule.OnEnter
10. UrlRoutingModule.OnApplicationPostResolveRequestCache
11. ProfileModule.OnEnter
12. ScriptModule.OnPostAcquireRequestState
13. ProfileModule.OnLeave
14. ScriptModule.EndRequestHandler

怀疑可能出现问题的地方

1. IIS 出现堵塞
   • 请求并没有多少，也没有排队的请求
2. Redis 缓存查询超时
   • 如果 Redis 查询超时了，应该有会异常的日志，而且 HttpCode 也不可能为 500
3. 听云记录出错
   • 有可能吗？不知道。
4. 请求超时
   • 请求超时的话，HTTP Code 应该为 408 才对
5. IIS 获取/创建 Session 数据超时？
   • 禁用 Session 后仍然还是没有任何改善

参考

1. CHttpModule::OnPostAcquireRequestState Method
2. REQUEST_NOTIFICATION_STATUS Enumeration
3. ASP.Net 请求处理机制初步探索之旅 - Part 3 管道
4. SessionStateStoreProviderAsyncBase.cs
5. ASP.NET 运行时详解 揭开请求过程神秘面纱
6. ASP.NET 运行时详解 集成模式和经典模式