Last post Mar 06, 2018 06:16 AM by anders06
Mar 05, 2018 02:29 AM|anders06|LINK
We have a very simple async web api defined as public async <Task> GetOrderById(long id). Normally, it runs quickly and can be completed in 100ms. However sometimes, it takes more than 5 seconds on Production. The following figure is one of the slow
call we traced (The last column shows methods' offset time in ms when the server received the api call ).
The 'RedisDataBase.StringGetAsync' method is called in AuthenticationAttribute class (subclass of ActionFilterAttribute), using the 'OnActionExecutingAsync' async way, by 'var user = await redisCache.TryGetAsync(sessionId)'.
So we suspects the API has been temp blocked during switching back to Asp.net thread after the 'await' keyword. After replacing the 'OnActionExecutingAsync' method with the 'OnActionExecuting' for AuthenticationAttribute class and sync call redis server,
the cost can be eliminated.
Furthermore, we removed the AspNetSynchronizationContext inside the API to avoid unnecessary context switch as below
public async Task<ResultModel<OrderModel>> GetOrderById(long id)
var capturedContext = SynchronizationContext.Current;
// Tricky, set current SynchronizationContext to null, to avoid capturing context during call await
return new ResultModel<OrderModel>(order);
// Restore the sync context
However at the end of callstack, sometimes, there is still a few seconds unknown cost. My question is what happened here? is there any article or direction I should do further investigation?
BTW. currently in our project we are still mixing using async & sync webapi and most of api are still using sync. Is it the root cause for the performance issue?
And, We have monitored the PROD machine. It shows the thread number is around 120 and there is rare 'Requests Queued' number (8 at peak).
Mar 05, 2018 02:37 AM|anders06|LINK
We noticed the min thread pool number uses the default value which is 8 (IIS 8.0, default mode, auto). So we suspected maybe the problem was caused by insufficient Asp.net thread pool number, since the CLR allows to allocate no more than 2 threads in a
second. After setting the min thread pool number to 100, We can see the thread number is around 200, but the problem is still there.
Mar 05, 2018 02:59 AM|DA924|LINK
How often is the Web API being used? It could be that the ASP.NET WebAPI is being rolled out of scope if not used frequently.
Mar 05, 2018 05:22 AM|anders06|LINK
Thanks for your reply. It was quite often, near 10 request per minute.
Mar 05, 2018 03:14 PM|bruce (sqlwork.com)|LINK
you condition sounds like a timeout for a constrained resource. look at:
1) use of httpclient and not releasing properly. a using statement is not enough. (though i'd expect a 1.5 second delay that built up) see:
2) database contention. use sql profiler to check for this.
3) a network constraint. 5 seconds sounds like a kerberos timeout falling back to ntlm. use wireshark or similar to look for timeout in network packages.
Mar 06, 2018 06:16 AM|anders06|LINK
Hi bruce, thanks for your help.
1) We only use HttpClient to call 3rd services and we didn't find any connection to them via 'NETSTAT' command
2). The profiler can trace sql calls and for the second figure I post above, there wouldn't have any sql between 'RedisDatabase.HashGetAsync' and 'OutputCacheModule.OnLeave'.
3). Will do more research on this topic.