Sunday, November 27, 2016

Large time-taken value in IISlogs do not per se mean an issue on IIS / SharePoint server level

The time-taken field measures the length of time that it takes for a request to be processed. The client-request time stamp is initialized when HTTP.sys receives the first byte of the request. HTTP.sys is the kernel-mode component that is responsible for HTTP logging for IIS activity. The client-request time stamp is initialized before HTTP.sys begins parsing the request. The client-request time stamp is stopped when the last IIS response send completion occurs.
In the IIS logs of our SharePoint WFEs I observed large time-taken values for the responses of several GET requests, with times above 2500 (!!) seconds.
LogParser.exe "SELECT TOP 10 date,time,c-ip,cs-uri-stem,sc-status,sc-substatus,time-taken from u_ex*.log WHERE time-taken > 2500000 ORDER BY time-taken DESC"
We investigated whether this points to an actual performance problem on SharePoint server side, or is merely to be considered a false positive wrt the performance of the SharePoint environment. An indication of the latter is that our end-users have not reported (complained) on reoccuring long wait times for these requests. After some lengthy investigation - the observed symptom is not well documented -, we conclude to the last.
The justification for this conclusion is a) that we did not identify any performance issue due these specific requests on the SharePoint WFEs, and b) that beginning in IIS 6.0, the time-taken field typically includes “all the network time” being spent when transferring all the bytes to/from client:
HTTP.sys waits for the client to acknowledge the last response packet send operation or HTTP.sys waits for the client to reset the underlying TCP connection, before it logs the value for process duration in the time-taken field in the IIS logs.
This correlates with our observation that the longer time-taken responses were all for the download of large static files, typical powerpoint files (.pptx), that are rendered in browser via Office Web Apps (OWA). It appears that the browser on occassion takes long time before it completely processed the received file response, and acknowledges the last packet.

No comments:

Post a Comment