最近在做的一个项目中，发现网页端同时发起了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:work2Njt.Crm2Njt.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:work2Njt.Crm2Njt.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= :innerExceptionSeparator= ---Inner--- :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连接到了远程的机房去访问数据库，所以延迟比较高，如果在本地的话，基本都是几十毫秒的事情。