解决ASP.NET Core MVC调试慢的问题

最近在做的一个项目中，发现网页端同时发起了4个AJAX请求需要数秒才获取到响应，太慢了，当我把请求数降低为1个的时候，速度看起来就比较正常，增加到2个同时的请求后，速度就有些慢了，3个的话就明显慢了，4个更慢，如下图：

而这几个请求获取的数据量都是非常少的，且服务器端也没什么重量级的操作，这太奇怪了。

我到处寻找解决方案，未果，仔细查看output窗口中日志，也没发现警告或者错误之类的提示。但后来我仔细看了output日志之后，发现了一个问题，那就是output窗口日志输出太多，且输出速度较慢，下面就是日志片段：

Njt.Crm> 10:05:50.415 [Debug][Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets]  Connection id "0HLEVO0B2MOF4" received FIN. 
Njt.Crm> 10:05:50.415 [Debug][Microsoft.AspNetCore.Server.Kestrel]  Connection id "0HLEVO0B2MOF8" started. 
Njt.Crm> 10:05:50.415 [Debug][Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets]  Connection id "0HLEVO0B2MOF6" received FIN. 
Njt.Crm> 10:05:50.415 [Debug][Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets]  Connection id "0HLEVO0B2MOF5" received FIN. 
Njt.Crm> 10:05:50.455 [Debug][Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets]  Connection id "0HLEVO0B2MOF7" received FIN. 
Njt.Crm> 10:05:50.468 [Info][Microsoft.AspNetCore.Hosting.Internal.WebHost]  Request starting HTTP/1.1 GET http://localhost:5004/Mf/MfOrgs/3?MfId=3&PageNo=1&PageSize=40   
Njt.Crm> 10:05:50.492 [Trace][Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware]  All hosts are allowed. 
Njt.Crm> 10:05:50.513 [Debug][Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware]  The request path /Mf/MfOrgs/3 does not match a supported file type 
Njt.Crm> 10:05:50.513 [Debug][Microsoft.AspNetCore.Server.Kestrel]  Connection id "0HLEVO0B2MOF9" started. 
Njt.Crm> 10:05:50.555 [Trace][Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector]  Performing protect operation to key {d729c8cb-a753-4343-ac75-2dddd71308a6} with purposes ('D:\work2\Njt.Crm2\Njt.Crm', 'SessionMiddleware'). 
Njt.Crm> 10:05:50.525 [Debug][Microsoft.AspNetCore.Server.Kestrel]  Connection id "0HLEVO0B2MOF5" disconnecting. 
Njt.Crm> 10:05:50.525 [Debug][Microsoft.AspNetCore.Server.Kestrel]  Connection id "0HLEVO0B2MOF7" disconnecting. 
Njt.Crm> 10:05:50.525 [Debug][Microsoft.AspNetCore.Server.Kestrel]  Connection id "0HLEVO0B2MOF6" disconnecting. 
Njt.Crm> 10:05:50.569 [Debug][Microsoft.AspNetCore.Routing.RouteBase]  Request successfully matched the route with name 'default' and template '{controller=Home}/{action=Index}/{id?}'. 
Njt.Crm> 10:05:50.540 [Debug][Microsoft.AspNetCore.Server.Kestrel]  Connection id "0HLEVO0B2MOF4" disconnecting. 
Njt.Crm> 10:05:50.569 [Info][Microsoft.AspNetCore.Hosting.Internal.WebHost]  Request starting HTTP/1.1 GET http://localhost:5004/Mf/Contact/3?MfId=3&PageNo=1&PageSize=5   
Njt.Crm> 10:05:50.569 [Debug][Microsoft.AspNetCore.Server.Kestrel]  Connection id "0HLEVO0B2MOFA" started. 
Njt.Crm> 10:05:50.569 [Info][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Route matched with {action = "MfOrgs", controller = "Mf"}. Executing action Njt.Crm.Controllers.MfController.MfOrgs (Njt.Crm) 
Njt.Crm> 10:05:50.569 [Debug][Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets]  Connection id "0HLEVO0B2MOF5" sending FIN. 
Njt.Crm> 10:05:50.582 [Trace][Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware]  All hosts are allowed. 
Njt.Crm> 10:05:50.569 [Debug][Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets]  Connection id "0HLEVO0B2MOF7" sending FIN. 
Njt.Crm> 10:05:50.569 [Debug][Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets]  Connection id "0HLEVO0B2MOF6" sending FIN. 
Njt.Crm> 10:05:50.582 [Debug][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Execution plan of authorization filters (in the following order): Njt.MvcBaseLib.Filters.UnifiedAuthFilter (Order: 0), Njt.MvcBaseLib.Filters.MaintainFilter (Order: 0), Njt.MvcBaseLib.Filters.AppNotOpenedDenyFilter (Order: 0) 
Njt.Crm> 10:05:50.582 [Debug][Microsoft.AspNetCore.Server.Kestrel]  Connection id "0HLEVO0B2MOFB" started. 
Njt.Crm> 10:05:50.582 [Debug][Microsoft.AspNetCore.StaticFiles.StaticFileMiddleware]  The request path /Mf/Contact/3 does not match a supported file type 
Njt.Crm> 10:05:50.615 [Info][Microsoft.AspNetCore.Hosting.Internal.WebHost]  Request starting HTTP/1.1 GET http://localhost:5004/Mf/Contract/3?MfId=3&PageNo=1&PageSize=40   
Njt.Crm> 10:05:50.615 [Debug][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Execution plan of resource filters (in the following order): Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter 
Njt.Crm> 10:05:50.615 [Info][Microsoft.AspNetCore.Hosting.Internal.WebHost]  Request starting HTTP/1.1 GET http://localhost:5004/Mf/Milestone/3?MfId=3&PageNo=1&PageSize=40   
Njt.Crm> 10:05:50.615 [Trace][Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector]  Performing protect operation to key {d729c8cb-a753-4343-ac75-2dddd71308a6} with purposes ('D:\work2\Njt.Crm2\Njt.Crm', 'SessionMiddleware'). 
Njt.Crm> 10:05:50.615 [Trace][Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware]  All hosts are allowed. 

//……

Njt.Crm> 10:05:53.160 [Trace][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Result Filter: Before executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter. 
Njt.Crm> 10:05:53.184 [Trace][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Result Filter: After executing OnResultExecutionAsync on filter Njt.MvcBaseLib.Filters.AppNotOpenedDenyFilter. 
Njt.Crm> 10:05:53.205 [Info][Microsoft.AspNetCore.Mvc.Formatters.Json.Internal.JsonResultExecutor]  Executing JsonResult, writing value of type 'Njt.Crm.SvcModels.Mf.MilestoneListOfMfIdResp'. 
Njt.Crm> 10:05:53.228 [Trace][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Result Filter: After executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter. 
Njt.Crm> 10:05:53.249 [Trace][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Result Filter: After executing OnResultExecutionAsync on filter Njt.MvcBaseLib.Filters.MaintainFilter. 
Njt.Crm> 10:05:53.249 [Trace][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  After executing action result Microsoft.AspNetCore.Mvc.JsonResult. 
Njt.Crm> 10:05:53.273 [Trace][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Resource Filter: Before executing OnResourceExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter. 
Njt.Crm> 10:05:53.273 [Trace][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Result Filter: After executing OnResultExecutionAsync on filter Njt.MvcBaseLib.Filters.UnifiedAuthFilter. 
Njt.Crm> 10:05:53.273 [Trace][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Result Filter: After executing OnResultExecutionAsync on filter Njt.MvcBaseLib.Filters.AppNotOpenedDenyFilter. 
Njt.Crm> 10:05:53.301 [Trace][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Resource Filter: After executing OnResourceExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter. 
Njt.Crm> 10:05:53.304 [Trace][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Result Filter: After executing OnResultExecutionAsync on filter Njt.Crm.Filters.RightFilterAttribute+RightFilterImplAttribute. 
Njt.Crm> 10:05:53.304 [Trace][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Result Filter: After executing OnResultExecutionAsync on filter Njt.MvcBaseLib.Filters.MaintainFilter. 
Njt.Crm> 10:05:53.304 [Info][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Executed action Njt.Crm.Controllers.MfController.Contract (Njt.Crm) in 2468.5499ms 
Njt.Crm> 10:05:53.333 [Trace][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Result Filter: After executing OnResultExecutionAsync on filter Njt.MvcBaseLib.Filters.UnifiedAuthFilter. 
Njt.Crm> 10:05:53.304 [Trace][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Result Filter: Before executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter. 
Njt.Crm> 10:05:53.333 [Debug][Microsoft.AspNetCore.Server.Kestrel]  Connection id "0HLEVO0B2MOFA" completed keep alive response. 
Njt.Crm> 10:05:53.333 [Trace][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Result Filter: After executing OnResultExecutionAsync on filter Njt.Crm.Filters.RightFilterAttribute+RightFilterImplAttribute. 
Njt.Crm> 10:05:53.333 [Info][Microsoft.AspNetCore.Hosting.Internal.WebHost]  Request finished in 2726.3829ms 200 application/json; charset=utf-8 
Njt.Crm> 10:05:53.333 [Trace][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Result Filter: After executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter. 
Njt.Crm> 10:05:53.333 [Trace][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Result Filter: Before executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter. 
Njt.Crm> 10:05:53.368 [Trace][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Resource Filter: Before executing OnResourceExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter. 
Njt.Crm> 10:05:53.368 [Trace][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Result Filter: After executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter. 
Njt.Crm> 10:05:53.368 [Trace][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Resource Filter: After executing OnResourceExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter. 
Njt.Crm> 10:05:53.368 [Trace][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Resource Filter: Before executing OnResourceExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter. 
Njt.Crm> 10:05:53.379 [Info][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Executed action Njt.Crm.Controllers.MfController.Contact (Njt.Crm) in 2616.9911ms 
Njt.Crm> 10:05:53.402 [Trace][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Resource Filter: After executing OnResourceExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Internal.SaveTempDataFilter. 
Njt.Crm> 10:05:53.402 [Debug][Microsoft.AspNetCore.Server.Kestrel]  Connection id "0HLEVO0B2MOF9" completed keep alive response. 
Njt.Crm> 10:05:53.402 [Info][Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker]  Executed action Njt.Crm.Controllers.MfController.Milestone (Njt.Crm) in 2507.7129ms 
Njt.Crm> 10:05:53.402 [Info][Microsoft.AspNetCore.Hosting.Internal.WebHost]  Request finished in 2836.4425ms 200 application/json; charset=utf-8 
Njt.Crm> 10:05:53.411 [Debug][Microsoft.AspNetCore.Server.Kestrel]  Connection id "0HLEVO0B2MOFB" completed keep alive response. 
Njt.Crm> 10:05:53.436 [Info][Microsoft.AspNetCore.Hosting.Internal.WebHost]  Request finished in 2810.8861ms 200 application/json; charset=utf-8 

这4个请求一共导致了300多行log，我只截取了前后30行，看吧，全都是Trace/Debug/Info，这些信息对我们来说基本没什么用，考虑到我用的是NLog日志输出，那只需要修改一下配置，让NLog不输出这些多余的东西不就好了吗？于是我修改了NLog配置：

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      autoReload="true"
      throwExceptions="false"
      internalLogLevel="Off">
  <variable name="theLayout" value="${date:format=HH\:mm\:ss.fff} [${level}][${logger}] ${callsite:className=False:fileName=True:methodName=False} ${message} ${onexception:${newline}}${exception:format=Message,ShortType,StackTrace:innerFormat=Message,ShortType,StackTrace:separator=\r\n:innerExceptionSeparator=\r\n---Inner---\r\n:maxInnerExceptionLevel=5}"/>
  <targets>
    <target name="asyncFile" xsi:type="AsyncWrapper">
      <target name="logfile" xsi:type="File" fileName="${basedir}/log/${shortdate}.log" layout="${theLayout}" encoding="UTF-8" />
    </target>
    <target name="debugger" xsi:type="Debugger" layout="${theLayout}" />
    <target name="console" xsi:type="Console" layout="${theLayout}" />
    <target name="void" xsi:type="Null" formatMessage="false" />
  </targets>
  <rules>
    <logger name="Microsoft.AspNetCore.*" minlevel="Trace" maxlevel="Info" writeTo="void" final="true" />
    <logger name="*" minlevel="Debug" writeTo="asyncFile" />
    <logger name="*" minlevel="Trace" writeTo="debugger"/>
    <logger name="*" minlevel="Trace" writeTo="console"/>
  </rules>
</nlog>

注意看这行：

<logger name="Microsoft.AspNetCore.*" minlevel="Trace" maxlevel="Info" writeTo="void" final="true" />

意思就是把Microsoft.AspNetCore的日志都写到void去，并且就此结束，不再写到别的日志处理器去(final="true")，void的定义见上面，其实就是什么都不写。

这么一来，居然有了令人惊喜的效果：

速度有了质的飞跃，且其它页面打开似乎也快了一点。而我做的只是把多余的日志拿掉了。

回到开始，为什么4个同时发生的AJAX请求会显著让响应变慢呢？我猜是这样，4个请求同时到达服务器，每个请求都产生很多log，4个请求就产生了4倍的log，且我们的程序在这些Log输出完毕之前，不会进入下一步操作，所以就相当于同时阻挡了这4个请求。

我还发现这么一来我们整个ASP.NET Core程序的调试都略快于以前了，别人没碰到这个问题的原因是他们可能没像我这样使用NLog，他们也许使用了别的日志框架之类的。

另外，你也许觉得100多毫秒的响应速度还是太慢了，确实，这跟我的工作环境有关系，我们的数据库服务器并不是放在本地的，我们是通过VPN连接到了远程的机房去访问数据库，所以延迟比较高，如果在本地的话，基本都是几十毫秒的事情。