最近在做的一個項目中，發現網頁端同時發起了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連接到了遠程的機房去訪問數據庫，所以延遲比較高，如果在本地的話，基本都是幾十毫秒的事情。