我有一个托管在 Windows 7 / IIS 7.5 上的 .Net Framework 4.0、ASP.NET、ASP.NET MVC 3 Web 应用程序。此计算机上已启用 IIS 日志记录并设置为以 W3C 模式登录。
该应用程序使用 Release 配置进行编译，并已通过显式设置的 属性部署到 IIS。 Web.config 指定使用基于 SQL Server 的会话状态。
我分别在 Global.asax 的 BeginRequest 和 EndRequest 事件中添加了以下语句。结果（即“sw.Elapsed.TotalMilliseconds”）存储在应用程序级别的值列表中。我通过调试页面转储这些值并获得相同的平均值。
// in BeginRequest
HttpContext.Current.Items.Add("RequestStartEnd", System.Diagnostics.Stopwatch.StartNew());
// in EndRequest
var sw = (System.Diagnostics.Stopwatch)HttpContext.Current.Items["RequestStartEnd"];
sw.Stop();
我创建了一个负载测试，该测试针对该应用程序运行单个请求，并发用户负载为 20 个用户。测试在 Visual Studio 2010 Ultimate 版本中运行。
运行负载测试后，秒表记录的平均时间为 681 毫秒。根据 IIS，这些请求的平均时间（我在运行负载测试之前清除了所有日志）为 2121 毫秒。 IIS 所花费的平均时间与 Visual Studio 负载测试报告中显示的值相符。
根据 IIS 日志/Visual Studio 报告，秒表所用时间仅占所用时间的 32%。剩下的68%时间都去哪儿了？
更新1：
我将会话状态设置为 InProc 并重新运行负载测试。在这种情况下，秒表报告的平均时间与 IIS 日志报告的平均时间之间的差异增长到 70% 以上！那些时间都去哪儿了？
更新2：
@Peter - 我通过设置跟踪规则来登录状态代码 200 来尝试失败的请求跟踪。接下来，我对 20 个并发用户运行了大约 1.5 分钟的负载测试。查看最后 50 个跟踪文件，发现该报告中的“Time Taken”字段的范围为 750 毫秒到 1300 毫秒。 Visual Studio 报告显示平均。所用时间为 2300ms。在报告中，使用紧凑视图，我看到以下转换之间所花费的时间发生变化
(1)AspNetStart-> AspNetAppDomainEnter
(2) ManagedPipelineHandler-启动 ManagedPipelineHandler-结束。
(2) 项可能是我的应用程序的代码。根据失败请求日志的最大耗时（即 1300 毫秒）和平均耗时之间仍然存在很大差异。 Visual Studio 显示的耗时为 2300 毫秒。如何找到对此的会计处理？不过还是谢谢你的这个好建议！
I have an .Net Framework 4.0, ASP.NET, ASP.NET MVC 3 web application hosted on a Windows 7 / IIS 7.5. IIS logging is enabled on this machine and set to log in W3C mode.
The application is compiled by using the Release configuration and has been deployed to IIS with <compilation debug='false' attribute set explicitly. The Web.config specifies the use of SQL Server based session state.
I have added the following statements in Global.asax in BeginRequest and EndRequest events respectively. The results i.e. "sw.Elapsed.TotalMilliseconds" are getting stored in an Application level list of values. I dump these values out via a debug page and get an average of the same.
// in BeginRequest
HttpContext.Current.Items.Add("RequestStartEnd", System.Diagnostics.Stopwatch.StartNew());
// in EndRequest
var sw = (System.Diagnostics.Stopwatch)HttpContext.Current.Items["RequestStartEnd"];
sw.Stop();
I have created a load test which runs a single request against this application with a concurrent user load of 20 users. The test is run in Visual Studio 2010 Ultimate edition.
After running the load test, I am getting an average time-taken as recorded by the stopwatch as 681 milliseconds.The average time-taken as per IIS for these requests (I cleaned out all logs before running the load test) is 2121 milliseconds. The average time-taken as per IIS tallys with the value shown in Visual Studio load test report.
The stopwatch time-taken only accounts for 32% of time-taken as reported by IIS logs / Visual Studio. Where does the other 68% time go?
Update 1:
I set the session state to InProc and re-ran the load test. In this scenario the difference between the average time reported by stopwatch and average time-taken reported by IIS logs grew to more than 70%!!! Where is all that time going?
Update 2:
@Peter - I tried out the failed request tracing by putting a trace rule to log on status code of 200. Next, I ran the load test with 20 concurrent users for approx 1.5 minutes. Went through last 50 trace files and found that the "Time Taken" field in that report had range of 750ms to 1300ms. The Visual Studio report showed avg. time taken as 2300ms. In the report, using the compact view, I see that the time taken changes between the following transitions
(1) AspNetStart -> AspNetAppDomainEnter
(2) ManagedPipelineHandler-start ManagedPipelineHandler-end.
The (2) item is probably my application's code. Still there is a big difference between max of time-taken as per failed request logs i.e. 1300ms and the avg. time-taken as shown by Visual Studio 2300ms. How to find accounting for that? Thanks for this great tip though!
发布评论
评论（5）
您运行负载测试多长时间？如果您在 Windows 7 下运行它，您可能会得到与 Windows 服务器下不同的结果。在突发负载下将线程分配给线程池时可能会遇到问题。 .Net会立即分配线程到线程池min，然后慢慢分配到线程池max。我相信客户端操作系统的默认设置与服务器操作系统的默认设置不同。在客户端操作系统上，默认的最小线程设置可能等于您计算机上的核心数量，这意味着 .net 将慢慢分配更多线程来满足您的突发负载。
一个简单的检查是让负载测试运行更长时间，看看两次测量之间的差距是否缩小。
How long are you running your load test for? If you're running it under windows 7 you may get different results than under a windows server as well. You could be having issues with getting threads allocated to the thread pool under burst loads. .Net will immediately allocate threads up to the thread pool min and then slowly allocate up to the thread pool max. I believe the default settings for client OS's are different than for server OS's. It may be on a client OS the default min thread setting is equal to the number of cores on your machine, meaning that .net will then slowly allocate more threads to meet your burst load.
A simple check would be to let your load test run longer and see if the gap between your 2 measurements narrows.
有一种更好的方法来查看应用程序的内部结构，即使用“失败请求跟踪规则”
http://learn.iis.net/page.aspx/266/troubleshooting-failed-requests-using-tracing-in-iis-7/
有了它，您就可以准确地遵循您的操作应用程序正在 IIS 中执行操作
There is a better way to look into the internals of your app, by using "Failed Request Tracing Rules"
http://learn.iis.net/page.aspx/266/troubleshooting-failed-requests-using-tracing-in-iis-7/
With that you can follow exactly what you app is doing in IIS
我建议研究 MvcMiniProfiler。它是一个 NuGet 包，您可以添加并连接（几乎毫不费力），它确实可以缩短 MVC 应用程序中各个点的执行时间。您可以看到每个请求的实时视图以及瓶颈所在的位置。
详细信息：
I would suggest looking into MvcMiniProfiler. It's a NuGet package you could add and wire in (almost effortlessly) that really breaks down the execution times of various points in your MVC app. You could see a live view of each request and where any bottlenecks reside.
More info:
它很可能是托管管道开销和您的网络（甚至本地主机或127.0.0.1）的组合也许可以解释“损失”的时间。
测试数字 - 两者都涉及网络堆栈和托管管道。
在 ASP.NET 执行开始之前和结束之前），并且不考虑
处理 TCP 网络请求、解析的 IIS 开销
请求和响应以及传输时间的 HTTP 标头
通过托管管道和 TCP 堆栈。
Its most likely a combination of the Managed Pipeline overhead and your network (even localhost or 127.0.0.1) is probably where the "lost" time can be accounted for.
test figures - both of those involve the network stack and the managed pipleline.
before ASP.NET execution begins and just before it ends), and does not take into account
the IIS overhead of processing a TCP network request, parsing
HTTP-headers for both the request and response and transmission time
through the managed pipeline and TCP stack.
如果您遇到加载时间较长的问题，则可能与多种因素有关，如果您有大量 IO 操作，则可能会影响此问题
如果您正在使用 orm 进行数据库查询，请尝试在 sql 分析器中或在内置分析器的 sql 服务器中分析您的 sql 语句，如果您收到大量单独的查询，您可能需要考虑使用 linq 查询中的一些包含来捆绑将一些数据放入单个查询中，
您可能还需要考虑如果您有大量 IO 操作，则需要考虑使用异步控制器来缩短响应时间，这样您的应用程序就不会连续等待每个 io 操作完成
请参阅 wintellect.com/CS/blogs/jprosise/archive/2010/03/29/…
还有比 iis 日志记录更好的解决方案，因为它是一个相当古老的组件，您可能需要查看 log4net 来进行更一般的日志记录，或者查看 elmah 来记录错误和异常，因为这些解决方案可以捆绑一堆日志条目并在单个操作中写入多个日志条目，同时还可以提高 IO 性能
if you are having issues with long load times it may be related to several things if you have a high number of IO operations it can affect this
if you are doing database queries with an orm try profiling your sql statements either in vs with a sql profiler or in sql servers built in profiler if you are getting alot of individual querys you may want to consider using some includes in you linq queries to bundle up some of your data into single queries
you may also want to consider want to consider using async controllers to improve response times if you have alot of IO operations so your application isnt continuously waiting for each io operation to complete
see wintellect.com/CS/blogs/jprosise/archive/2010/03/29/…
there also better solutions out there for logging than the iis logging as it is a fairly old component you may want to take a look at log4net for more general logging or elmah for logging errors and exceptions as these solutions can bundle up a bunch of log entries and write several in a single operation also improving IO performance