06-03-2018, 06:03 PM
Troubleshooting ASP.NET Core Performance Problems
<div style="margin: 5px 5% 10px 5%;"><img src="http://www.sickgaming.net/blog/wp-content/uploads/2018/06/troubleshooting-asp-net-core-performance-problems.png" width="778" height="183" title="" alt="" /></div><div><h6><em>This is a guest post by Mike Rousos</em></h6>
<p class="code-line">I recently had an opportunity to help a developer with an <a href="http://asp.net/" title="http://asp.net/">ASP.NET</a> Core app that was functionally correct but slow when under a heavy user load. We found a few different factors contributing to the app’s slowdown while investigating, but the majority of the issues were some variation of blocking threads that could have run in a non-blocking way. It was a good reminder for me just how crucial it is to use non-blocking patterns in multi-threaded scenarios like a web app.<span id="more-13975"/></p>
<h2 class="code-line" id="beware-of-locks">Beware of Locks</h2>
<p class="code-line">One of the first problems we noticed (through CPU analysis with <a href="https://github.com/Microsoft/perfview" title="https://github.com/Microsoft/perfview">PerfView</a>) was that a lot of time was spent in logging code paths. This was confirmed with ad hoc exploration of call stacks in the debugger which showed many threads blocked waiting to acquire a lock. It turns out some common logging code paths in the application were incorrectly flushing Application Insights telemetry. Flushing App Insights requires a global lock and should generally not be done manually during the course of an app’s execution. In this case, though, Application Insights was being flushed at least once per HTTP request and, under load, this became a large bottleneck!</p>
<p class="code-line">You can see this sort of pattern in the images below from a small repro I made. In this sample, I have an <a href="http://asp.net/" title="http://asp.net/">ASP.NET</a> Core 2.0 web API that enables common CRUD operations against an Azure SQL database with Entity Framework Core. Load testing the service running on my laptop (not the best test environment), requests were processed in an average of about 0.27 seconds. After adding a custom <code>ILoggerProvider</code> calling <code>Console.WriteLine</code> inside of a lock, though, the average response time rose to 1.85 seconds – a very noticeable difference for end users. Using PerfView and a debugger, we can see that a lot of time (66% of PerfView’s samples) is spent in the custom logging method and that a lot of worker threads are stuck there (delaying responses) while waiting for their turn with the lock.</p>
<div id="attachment_13985" class="wp-caption aligncenter"><img src="http://www.sickgaming.net/blog/wp-content/uploads/2018/06/troubleshooting-asp-net-core-performance-problems.png" alt="Something's up with this logging call" class="wp-image-13985 size-full" width="778" height="183"/></p>
<p class="wp-caption-text">Something’s up with this logging call</p>
</div>
<div id="attachment_13995" class="wp-caption aligncenter"><img src="http://www.sickgaming.net/blog/wp-content/uploads/2018/06/troubleshooting-asp-net-core-performance-problems-1.png" alt="Threads waiting on lock acquisition" class="wp-image-13995 size-large" width="879" height="397"/></p>
<p class="wp-caption-text">Threads waiting on lock acquisition</p>
</div>
<p class="code-line"><a href="http://asp.net/" title="http://asp.net/">ASP.NET</a> Core’s Console logger used to have some locking like this in versions 1.0 and 1.1, causing it to be slow in high-traffic scenarios, but these issues have been addressed in <a href="http://asp.net/" title="http://asp.net/">ASP.NET</a> Core 2.0. It is still a best practice to be mindful of logging in production, though.</p>
<p class="code-line">For very performance-sensitive scenarios, you can use <code>LoggerMessage</code> to optimize logging even further. <code>LoggerMessage</code> allows defining log messages ahead-of-time so that message templates don’t need to be parsed every time a particular message is logged. More details are available in our<a href="https://docs.microsoft.com/aspnet/core/fundamentals/logging/loggermessage" title="https://docs.microsoft.com/aspnet/core/fundamentals/logging/loggermessage">documentation</a>, but the basic pattern is that log messages are defined as strongly-typed delegates:</p>
<pre>
<span class="hljs-comment">// This delegate logs a particular predefined message</span>
<span class="hljs-keyword">private</span> <span class="hljs-keyword">static</span> <span class="hljs-keyword">readonly</span> Action<ILogger, <span class="hljs-keyword">int</span>, Exception> _retrievedWidgets = LoggerMessage.Define<<span class="hljs-keyword">int</span>>( LogLevel.Information, <span class="hljs-keyword">new</span> EventId(<span class="hljs-number">1</span>, <span class="hljs-keyword">nameof</span>(RetrievedWidgets)), <span class="hljs-string">"Retrieved {Count} widgets"</span>); <span class="hljs-comment">// A helper extension method to make it easy to call the </span>
<span class="hljs-comment">// LoggerMessage-produced delegate from an ILogger</span>
<span class="hljs-function"><span class="hljs-keyword">public</span> <span class="hljs-keyword">static</span> <span class="hljs-keyword">void</span> <span class="hljs-title">RetrievedWidgets</span>(<span class="hljs-params"><span class="hljs-keyword">this</span> ILogger logger, <span class="hljs-keyword">int</span> count</span>) </span>=> _retrievedWidgets(logger, count, <span class="hljs-literal">null</span>);
</pre>
<p class="code-line">Then, that delegate is invoked as needed for high-performance logging:</p>
<pre>
<span class="hljs-keyword">var</span> widgets = <span class="hljs-keyword">await</span> _dbContext.Widgets.AsNoTracking().ToListAsync();
_logger.RetrievedWidgets(widgets.Length);
</pre>
<h2 class="code-line" id="keep-asynchronous-calls-asynchronous">Keep Asynchronous Calls Asynchronous</h2>
<p class="code-line">Another issue our investigation uncovered in the slow <a href="http://asp.net/" title="http://asp.net/">ASP.NET</a> Core app was similar: calling <code>Task.Wait()</code> or <code>Task.Result</code> on asynchronous calls made from the app’s controllers instead of using <code>await</code>. By making controller actions async and awaiting these sorts of calls, the executing thread is freed to go serve other requests while waiting for the invoked task to complete.</p>
<p class="code-line">I reproduced this issue in my sample application by replacing async calls in the action methods with synchronous alternatives. At first, this only caused a small slowdown (0.32 second average response instead of 0.27 seconds) because the async methods I was calling in the sample were all pretty quick. To simulate longer async tasks, I updated both the async and synchronous versions of my sample to have a <code>Task.Delay(200)</code> in each controller action (which, of course, I used <code>await</code> with when async and <code>.Wait()</code> with when synchronous). In the async case, average response time went from 0.27s to 0.46s which is more or less what we would expect if each request has an extra pause or 200ms. In the synchronous case, though, the average time went from 0.32 seconds to 1.47 seconds!</p>
<p class="code-line">The charts below demonstrate where a lot of this slowdown comes from. The green lines in the charts represent requests served per second and the red lines represent user load. In the first chart (which was taken while running the async version of my sample), you can see that as users increase, more requests are being served. In the second chart (corresponding to the<code>Task.Wait()</code> case), on the other hand, there’s a strange pattern of requests per second remaining flat for several minutes after user load increases and only then increasing to keep up. This is because the existing pool of threads serving requests couldn’t keep up with more users (since they were all blocked on <code>Task.Wait()</code> calls) and throughput didn’t improve until more threads were created.</p>
<div id="attachment_14005" class="wp-caption aligncenter"><img src="http://www.sickgaming.net/blog/wp-content/uploads/2018/06/troubleshooting-asp-net-core-performance-problems-2.png" alt="Threads Keeping Up" class="wp-image-14005 size-full" width="585" height="243"/></p>
<p class="wp-caption-text">Asynchronous RPS compared to user load</p>
</div>
<p class="code-line"><em> </em></p>
<div id="attachment_14015" class="wp-caption aligncenter"><img src="http://www.sickgaming.net/blog/wp-content/uploads/2018/06/troubleshooting-asp-net-core-performance-problems-3.png" alt="Sync Thread Growth Lag" class="wp-image-14015 size-full" width="579" height="242"/></p>
<p class="wp-caption-text">Synchronous RPS compared to user load</p>
</div>
<p class="code-line"><em> </em></p>
<p class="code-line">Attaching a debugger to both scenarios, I found that 75 managed threads were being used in the async test but 232 were in use in the synchronous test. Even though the synchronous test did eventually add enough threads to handle the incoming requests, calling <code>Task.Result</code> and <code>Task.Wait</code> can cause slowdowns when user load changes. Analyzers (like <a href="https://marketplace.visualstudio.com/items?itemName=SemihOkur.AsyncFixer" title="https://marketplace.visualstudio.com/items?itemName=SemihOkur.AsyncFixer">AsyncFixer</a>) can help to find places where asynchronous alternatives can be used and there are <a href="https://github.com/dotnet/corefx/issues/8931#issuecomment-337354565" title="https://github.com/dotnet/corefx/issues/8931#issuecomment-337354565">EventSource events</a> that can be used to find blocking calls at runtime, if needed.</p>
<h2 class="code-line" id="wrap-up">Wrap-Up</h2>
<p class="code-line">There were some other perf issues in the application I helped investigate (server GC wasn’t enabled in <a href="http://asp.net/" title="http://asp.net/">ASP.NET</a> Core 1.1 templates, for example, something that has been corrected in <a href="http://asp.net/" title="http://asp.net/">ASP.NET</a> Core 2.0), but one common theme of the problems we found was around blocking threads unnecessarily. Whether it’s from lock contention or waiting on tasks to finish, it’s important to keep threads unblocked for good performance in <a href="http://asp.net/" title="http://asp.net/">ASP.NET</a> Core apps.</p>
<p class="code-line">If you’d like to dig into your own apps to look for perf trouble areas, check out the <a href="https://channel9.msdn.com/Series/PerfView-Tutorial" title="https://channel9.msdn.com/Series/PerfView-Tutorial">Channel9 PerfView tutorials</a> for an overview of how PerfView can help uncover CPU and memory-related perf issues in .NET applications.</p>
</div>
<div style="margin: 5px 5% 10px 5%;"><img src="http://www.sickgaming.net/blog/wp-content/uploads/2018/06/troubleshooting-asp-net-core-performance-problems.png" width="778" height="183" title="" alt="" /></div><div><h6><em>This is a guest post by Mike Rousos</em></h6>
<p class="code-line">I recently had an opportunity to help a developer with an <a href="http://asp.net/" title="http://asp.net/">ASP.NET</a> Core app that was functionally correct but slow when under a heavy user load. We found a few different factors contributing to the app’s slowdown while investigating, but the majority of the issues were some variation of blocking threads that could have run in a non-blocking way. It was a good reminder for me just how crucial it is to use non-blocking patterns in multi-threaded scenarios like a web app.<span id="more-13975"/></p>
<h2 class="code-line" id="beware-of-locks">Beware of Locks</h2>
<p class="code-line">One of the first problems we noticed (through CPU analysis with <a href="https://github.com/Microsoft/perfview" title="https://github.com/Microsoft/perfview">PerfView</a>) was that a lot of time was spent in logging code paths. This was confirmed with ad hoc exploration of call stacks in the debugger which showed many threads blocked waiting to acquire a lock. It turns out some common logging code paths in the application were incorrectly flushing Application Insights telemetry. Flushing App Insights requires a global lock and should generally not be done manually during the course of an app’s execution. In this case, though, Application Insights was being flushed at least once per HTTP request and, under load, this became a large bottleneck!</p>
<p class="code-line">You can see this sort of pattern in the images below from a small repro I made. In this sample, I have an <a href="http://asp.net/" title="http://asp.net/">ASP.NET</a> Core 2.0 web API that enables common CRUD operations against an Azure SQL database with Entity Framework Core. Load testing the service running on my laptop (not the best test environment), requests were processed in an average of about 0.27 seconds. After adding a custom <code>ILoggerProvider</code> calling <code>Console.WriteLine</code> inside of a lock, though, the average response time rose to 1.85 seconds – a very noticeable difference for end users. Using PerfView and a debugger, we can see that a lot of time (66% of PerfView’s samples) is spent in the custom logging method and that a lot of worker threads are stuck there (delaying responses) while waiting for their turn with the lock.</p>
<div id="attachment_13985" class="wp-caption aligncenter"><img src="http://www.sickgaming.net/blog/wp-content/uploads/2018/06/troubleshooting-asp-net-core-performance-problems.png" alt="Something's up with this logging call" class="wp-image-13985 size-full" width="778" height="183"/></p>
<p class="wp-caption-text">Something’s up with this logging call</p>
</div>
<div id="attachment_13995" class="wp-caption aligncenter"><img src="http://www.sickgaming.net/blog/wp-content/uploads/2018/06/troubleshooting-asp-net-core-performance-problems-1.png" alt="Threads waiting on lock acquisition" class="wp-image-13995 size-large" width="879" height="397"/></p>
<p class="wp-caption-text">Threads waiting on lock acquisition</p>
</div>
<p class="code-line"><a href="http://asp.net/" title="http://asp.net/">ASP.NET</a> Core’s Console logger used to have some locking like this in versions 1.0 and 1.1, causing it to be slow in high-traffic scenarios, but these issues have been addressed in <a href="http://asp.net/" title="http://asp.net/">ASP.NET</a> Core 2.0. It is still a best practice to be mindful of logging in production, though.</p>
<p class="code-line">For very performance-sensitive scenarios, you can use <code>LoggerMessage</code> to optimize logging even further. <code>LoggerMessage</code> allows defining log messages ahead-of-time so that message templates don’t need to be parsed every time a particular message is logged. More details are available in our<a href="https://docs.microsoft.com/aspnet/core/fundamentals/logging/loggermessage" title="https://docs.microsoft.com/aspnet/core/fundamentals/logging/loggermessage">documentation</a>, but the basic pattern is that log messages are defined as strongly-typed delegates:</p>
<pre>
<span class="hljs-comment">// This delegate logs a particular predefined message</span>
<span class="hljs-keyword">private</span> <span class="hljs-keyword">static</span> <span class="hljs-keyword">readonly</span> Action<ILogger, <span class="hljs-keyword">int</span>, Exception> _retrievedWidgets = LoggerMessage.Define<<span class="hljs-keyword">int</span>>( LogLevel.Information, <span class="hljs-keyword">new</span> EventId(<span class="hljs-number">1</span>, <span class="hljs-keyword">nameof</span>(RetrievedWidgets)), <span class="hljs-string">"Retrieved {Count} widgets"</span>); <span class="hljs-comment">// A helper extension method to make it easy to call the </span>
<span class="hljs-comment">// LoggerMessage-produced delegate from an ILogger</span>
<span class="hljs-function"><span class="hljs-keyword">public</span> <span class="hljs-keyword">static</span> <span class="hljs-keyword">void</span> <span class="hljs-title">RetrievedWidgets</span>(<span class="hljs-params"><span class="hljs-keyword">this</span> ILogger logger, <span class="hljs-keyword">int</span> count</span>) </span>=> _retrievedWidgets(logger, count, <span class="hljs-literal">null</span>);
</pre>
<p class="code-line">Then, that delegate is invoked as needed for high-performance logging:</p>
<pre>
<span class="hljs-keyword">var</span> widgets = <span class="hljs-keyword">await</span> _dbContext.Widgets.AsNoTracking().ToListAsync();
_logger.RetrievedWidgets(widgets.Length);
</pre>
<h2 class="code-line" id="keep-asynchronous-calls-asynchronous">Keep Asynchronous Calls Asynchronous</h2>
<p class="code-line">Another issue our investigation uncovered in the slow <a href="http://asp.net/" title="http://asp.net/">ASP.NET</a> Core app was similar: calling <code>Task.Wait()</code> or <code>Task.Result</code> on asynchronous calls made from the app’s controllers instead of using <code>await</code>. By making controller actions async and awaiting these sorts of calls, the executing thread is freed to go serve other requests while waiting for the invoked task to complete.</p>
<p class="code-line">I reproduced this issue in my sample application by replacing async calls in the action methods with synchronous alternatives. At first, this only caused a small slowdown (0.32 second average response instead of 0.27 seconds) because the async methods I was calling in the sample were all pretty quick. To simulate longer async tasks, I updated both the async and synchronous versions of my sample to have a <code>Task.Delay(200)</code> in each controller action (which, of course, I used <code>await</code> with when async and <code>.Wait()</code> with when synchronous). In the async case, average response time went from 0.27s to 0.46s which is more or less what we would expect if each request has an extra pause or 200ms. In the synchronous case, though, the average time went from 0.32 seconds to 1.47 seconds!</p>
<p class="code-line">The charts below demonstrate where a lot of this slowdown comes from. The green lines in the charts represent requests served per second and the red lines represent user load. In the first chart (which was taken while running the async version of my sample), you can see that as users increase, more requests are being served. In the second chart (corresponding to the<code>Task.Wait()</code> case), on the other hand, there’s a strange pattern of requests per second remaining flat for several minutes after user load increases and only then increasing to keep up. This is because the existing pool of threads serving requests couldn’t keep up with more users (since they were all blocked on <code>Task.Wait()</code> calls) and throughput didn’t improve until more threads were created.</p>
<div id="attachment_14005" class="wp-caption aligncenter"><img src="http://www.sickgaming.net/blog/wp-content/uploads/2018/06/troubleshooting-asp-net-core-performance-problems-2.png" alt="Threads Keeping Up" class="wp-image-14005 size-full" width="585" height="243"/></p>
<p class="wp-caption-text">Asynchronous RPS compared to user load</p>
</div>
<p class="code-line"><em> </em></p>
<div id="attachment_14015" class="wp-caption aligncenter"><img src="http://www.sickgaming.net/blog/wp-content/uploads/2018/06/troubleshooting-asp-net-core-performance-problems-3.png" alt="Sync Thread Growth Lag" class="wp-image-14015 size-full" width="579" height="242"/></p>
<p class="wp-caption-text">Synchronous RPS compared to user load</p>
</div>
<p class="code-line"><em> </em></p>
<p class="code-line">Attaching a debugger to both scenarios, I found that 75 managed threads were being used in the async test but 232 were in use in the synchronous test. Even though the synchronous test did eventually add enough threads to handle the incoming requests, calling <code>Task.Result</code> and <code>Task.Wait</code> can cause slowdowns when user load changes. Analyzers (like <a href="https://marketplace.visualstudio.com/items?itemName=SemihOkur.AsyncFixer" title="https://marketplace.visualstudio.com/items?itemName=SemihOkur.AsyncFixer">AsyncFixer</a>) can help to find places where asynchronous alternatives can be used and there are <a href="https://github.com/dotnet/corefx/issues/8931#issuecomment-337354565" title="https://github.com/dotnet/corefx/issues/8931#issuecomment-337354565">EventSource events</a> that can be used to find blocking calls at runtime, if needed.</p>
<h2 class="code-line" id="wrap-up">Wrap-Up</h2>
<p class="code-line">There were some other perf issues in the application I helped investigate (server GC wasn’t enabled in <a href="http://asp.net/" title="http://asp.net/">ASP.NET</a> Core 1.1 templates, for example, something that has been corrected in <a href="http://asp.net/" title="http://asp.net/">ASP.NET</a> Core 2.0), but one common theme of the problems we found was around blocking threads unnecessarily. Whether it’s from lock contention or waiting on tasks to finish, it’s important to keep threads unblocked for good performance in <a href="http://asp.net/" title="http://asp.net/">ASP.NET</a> Core apps.</p>
<p class="code-line">If you’d like to dig into your own apps to look for perf trouble areas, check out the <a href="https://channel9.msdn.com/Series/PerfView-Tutorial" title="https://channel9.msdn.com/Series/PerfView-Tutorial">Channel9 PerfView tutorials</a> for an overview of how PerfView can help uncover CPU and memory-related perf issues in .NET applications.</p>
</div>