다음을 통해 공유

GENERAL_READ_ENTITY_START

  • 아티클

I was looking around for some understanding on the what this event within the request pipeline meant.  As seen in Figure 1, you can find this event when you are capturing a Failed Request trace.

I wrote a lab about capturing Failed Request Traces here –> Lab 4: Install and configure Failed Request Tracing

image

Figure 1, What does GENERAL_READ_ENTITY_START mean

In Figure 1 you can see that the entry into that event is the last one in the log, so pre IIS 10 we must conclude that this is where the time taken rule of this trace has been triggered.  The request could have completed successfully or timed out we don’t know, but what we do know is that it took some time to get to the GENERAL_READ_ENTITY_END event which was greater than the Failed Request rule configuration.  In IIS 10 you can enable traceAllAfterTimeout and then you will get the trace for the entire request, I describe that here.

So what does it mean when the request takes time between the GENERAL_READ_ENTITY_START and GENERAL_READ_ENTITY_END event?

When I correlated this trace with IIS and HTTP logs I found an HTTP reason code of Timer_EntityBody which is discussed here.  The description of that HTTP reason phrase is:

“The connection expired before the request entity body arrived. When a request clearly has an entity body, the HTTP API turns on the Timer_EntityBody timer. At first, the limit of this timer is set to the ConnectionTimeout value (typically, two minutes). Every time that another data indication is received on this request, the HTTP API resets the timer to give the connection two more minutes (or whatever is specified in ConnectionTimeout).”

And what I translate this to mean is that the client has made a connection and there is a problem with the client starting, continuing or completing the upload of the request body.

If you get this issue, you might want to see which kinds of clients are having this issue, is it a specific client software or browser?  Look at the client IP in the IIS logs to see if the issue is coming from a specific geographic location, is that location far away from your server?  Try a different client browser or connection methods.

As you can see in Figure 2, the request has entered and left the GENERAL_READ_ENTITY the first time pretty quick 15ms, but then the second time the request enters the GENERAL_READ_ENTITY_START event, the log is written because the time taken Failed Request rule threshold has been breached.  This relates back to the description of the Timer_EntityBody reason in that “..Every time that another data indication is received on this request, the HTTP API resets the timer…” and in the case of Figure 2, this timer would have been reset.  As already mentioned, pre IIS 10 we do not know how long it took to complete the request, but you can look at the IIS and HTTP logs to get more details now that you have a trace with a specific date and time stamp.

image

Figure 2, What does GENERAL_READ_ENTITY_START mean

Comments