Last post Feb 20, 2017 08:19 AM by Skatrix
Feb 13, 2017 07:06 PM|Skatrix|LINK
I have a a standard ASP.NET (Web Forms) application running on IIS8 and receiving complaints that sometimes it takes to the website too much time to process requests.
After deep investigation and logging I've figured out that delays take place wherever after the end of
PreRequestHandlerExecute event in my last HTTP module and before
ProcessRequest event in my HTTP handler.
As far as I understand I don't have any code in between and this part of the pipeline is absolutely managed by IIS and ASP.NET framework. I've also seen that Module and Handler processing thread ID changes when delays take place.
I've read tons of docs and haven't got closer to the resolution :(
What can be reason for these delays?
Thanks in advance
Feb 14, 2017 02:02 AM|Jean Sun|LINK
I've also seen that Module and Handler processing thread ID changes when delays take place.
Could you please share the log here?
And you can use IIS Failed Request Tracing the trace the request execute information, the following link shows how to use failed request tracing, please take it as reference.
Feb 14, 2017 10:16 AM|Skatrix|LINK
Hi Jean, thanks a lot for your reply.
This is my internal log:
2017-02-13 19:21:15,966  INFO Skatrix.CMS.Rewrite.RewriteModule [(null)] - PreRequestHandlerExecute: start
2017-02-13 19:21:15,966  INFO Skatrix.CMS.Rewrite.RewriteModule [(null)] - PreRequestHandlerExecute: end (00:00:00)
2017-02-13 19:21:19,712  INFO Skatrix.CMS.Base.BaseCorePage [(null)] - ProcessRequest start
2017-02-13 19:21:19,713  INFO Skatrix.CMS.Base.BaseCorePage [(null)] - OnPreInit - enter (IsRedirected=False, IsCompletedRequestCalled=False)
First two lines are written on the start and before the end of PreRequestHandlerExecute in my last module (last in the modules sequence)
Last two lines are written on the start of ProcessRequest in my Handler (ASPX page)
In this specific case the delay was for 4 seconds, but it happens a lot that delay takes 30 seconds and above.
As for enabling IIS logs - thanks for the reference. I will enable it tonight (don't want to restart the website application during the working day).
Hope these logs will help to understand what happens. I will report the results tomorrow.
Feb 20, 2017 08:19 AM|Skatrix|LINK
I've got necessary IIS Failed Request Tracing logs, but it doesn't help too much, but I've noted a weird point.
The FRT log usually starts with GENERAL_REQUEST_START and ends with GENERAL_REQUEST_END entries.
In my case the log starts with GENERAL_REQUEST_START and ends with GENERAL_READ_ENTITY_START entry. It's exactly the point where the delay begins and in my own log I also see that ID of the thread handling the request changes (after the delay).
Do you have any idea how it can be fixed?
How can I get the log for the entire request to see what happens?
Thanks in advance.