Application_BeginRequest 未在压力环境中触发

Question

在对我们的应用程序进行压力测试时，我们发现了一些奇怪的问题。我们使用 Application_BeginRequest 和 Application_EndRequest 来记录 Web 请求的开始和结束，以及线程 ID。

但是，从我们的日志中，我们看到 Application_Begin_REquest 没有被触发：

我们使用以下代码在 global.asax.cs 中进行日志记录：

protected void Application_BeginRequest(object sender, EventArgs e)
{
  string url = "";
  if (HttpContext.Current != null)  // this should alway be true
    url = HttpContext.Current.Request.Url.ToString();

  Dbg.WriteLine(String.Format("Request: {0} {1}", HttpContext.Current.Request.ServerVariables["REMOTE_ADDR"], url));

  // integration calls measurement
  HttpContext.Current.Items.Add("wcfElapsed", new TimeSpan());

}

protected void Application_EndRequest(Object sender, EventArgs e)
{
  string url = "";
  if (HttpContext.Current != null)  // this should alway be true
    url = HttpContext.Current.Request.Url.ToString();

  Dbg.WriteLine(String.Format("End request: {0} {1}", HttpContext.Current.Request.ServerVariables["REMOTE_ADDR"], url));
}

这是我们的日志文件。 url 省略 00013 列是线程id。

  14.12.10 21:41:25.042 00013 00000            Request: 172.23.26.41 
  14.12.10 21:41:25.068 00013 00000            End request: 172.23.26.41 
  14.12.10 21:41:25.212 00013 00000            Request: 172.23.26.41 
  14.12.10 21:41:25.223 00013 00000            End request: 172.23.26.41 
  14.12.10 21:41:30.974 00013 00000            End request: 172.23.26.88 

可以看到最后两行有两个“End request”，但是最后一个日志行没有(Begin) Request。

我们的 Dbg.WriteLine 使用 System.Diagnostics 跟踪侦听器将数据输出到文件。

环境：Windows Server 2008 R2，ASP.NET 3.5

这仅在执行压力测试时发生。 CPU 利用率约为 60%，最多执行 10 个并发请求。

任何想法，可能有什么问题？

更新：我发现其他一些也确实有类似的问题（尽管在不同的配置中：http://forums.iis.net/t/1154954.aspx） 马特杰

UPDATE#2：今晚与事实有关，用于打印日志文件中线程标识符的 Thread.GetHashCode() 可能会发生变化。见ASP.NET - Thread.GetHashCode() changes

Answer 1

我认为可能是调试到文件，无法处理所有这些事件。写入文件有其局限性。

我建议使用您可以在DebugView 中看到的默认调试跟踪。

Answer 2

可能不是 BeginRequest 没有触发太多，因为可能存在未处理的异常导致 System.Diagnostics 在不终止请求的情况下崩溃。

我建议找出问题的最佳方法是安装IIS Debug Diagnostics 并运行崩溃或挂起报告。你不会很喜欢它，因为它收集了大量的数据，但如果有某种线程崩溃/挂起，它肯定会捕获它。

编辑：
在将备份日志事件直接实施到系统事件日志中的自定义事件日志时，我们发现在重压下请求访问日志的权限会导致延迟（我们的猜测是在一定数量的请求之后，活动目录连接器无法及时响应）并最终出现例外情况。这似乎在一个单独的线程上运行，我们可以看到转储。 W3wp.exe 继续运行，页面完成了响应任务，但我们发现应该记录的 3 个事件中，记录的事件不一致。我们还发现事件日志本身会变得繁忙并抛出异常。我们找到了这个异常，因为这个异常有时会出现在用户界面上，而不是与其他异常一起消失。我们的最终解决方案是使用本地帐户向库提供权限，以减少对域策略的请求。这甚至清除了事件日志繁忙的症状。那时我们很高兴它消失了，我们没有进一步追求它。