解决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连接到了远程的机房去访问数据库,所以延迟比较高,如果在本地的话,基本都是几十毫秒的事情。

posted @ 2018-07-02 10:33 guogangj 阅读(...) 评论(...) 编辑 收藏