Over 66 seconds to fetch a simple css file on IIS 6 - follow up

Hi there,
This is a follow up on a question I posted earlier. I got great help
that moved me a step further, but still trying to isolate the problem.

When accessing pages on my Web site, sometimes it takes a very long time
(randomly). It doesn't seem to be database related, because even simple
files, such as robots.txt sometimes take over a minute to return. Also, SQL
server profiler doesn't show any delays. Here are more details:

- I checked the IIS log files to make sure it's not a network issue. It's
not. IIS logs report the extremely long times it's taking to respond.

- While waiting for a slow page to load (often more than a minute), I use
terminal services to log in to the server and check perfmon, cpu utilization
is less than 5%, and the machine is very responsive, including access to the
file system.

- There are no errors in the event log or the iis httperror files.

- The problem happens randomly, and it affects all kinds of files, weather
static (.txt,.css,.png) or dynamic (.aspx,asmx).

- I'm using IIS6 on Windows Server 2003. It's a virtual host (vps). I'm
using .net 2.0.


This is what I got from ETW (I removed irrelevant details to keep it
readable, but kept the titles all events). The main delay (3 seconds in this
case, but I caught cases with over 40 seconds) is happening between the
HTTPSYS_CACHEABLE and NOTIFY_ISAPI_COMPLETION events. I'm not sure what that
means? Is that time spent inside my asp.net app? Any suggestions on how to
drill deeper?


AspNetReq: Start - Start
ConnId: 17059336
Timestamp: 22:00:45.946.969600

IISCache: URL_CACHE_ACCESS_START - IIS starts accessing URL cache to get
metadata
IISGeneral: GENERAL_GET_URL_METADATA - IIS gets URL metadata
IISCache: URL_CACHE_ACCESS_END - IIS ends accessing URL cache
IISCache: URL_CACHE_ACCESS_START - IIS starts accessing URL cache to get
metadata
IISGeneral: GENERAL_GET_URL_METADATA - IIS gets URL metadata
IISCache: URL_CACHE_ACCESS_END - IIS ends accessing URL cache

IISCache: HTTPSYS_CACHEABLE - IIS decides if the request is HTTP.SYS
cacheable
HttpsysCacheable: 0
Reason: URL_CHANGE_BY_FILTER
ContextIDSeq: 9
Timestamp: 22:00:45.966.998400

W3Isapi: NOTIFY_ISAPI_COMPLETION - Notify Isapi of Completion
ContextIDSeq: 9
Timestamp: 22:00:48.320.382400

AspNetReq: End - End
ConnId: 17059336
ContextIDSeq: 9
Timestamp: 22:00:48.320.382400


Thanks

David
Wed Jan 16 01:59:20 CST 2008

Please provide the entire trace.

It helps me to provide an independent assessment of your issue,
instead of one that is tainted by your observations. When you choose
to abbreviate the ETW trace, you are assuming that you can interpret
the ETW trace better than everyone.

At this point, it sounds like you have user-configuration that affects
the "simple" CSS file with ASP.Net -- which is hardly default behavior
-- and please be aware that the IIS Static File handler is orders of
magnitude more efficient than the ASP.Net static file handler...


//David
http://w3-4u.blogspot.com
http://blogs.msdn.com/David.Wang
//








On Jan 15, 8:46=A0pm, Waleed ninua com> <waleed <atdot> wrote:
> Hi there,
> =A0 =A0 This is a follow up on a question I posted earlier. I got great he=
lp
> that moved me a step further, but still trying to isolate the problem.
>
> =A0 =A0 When accessing pages on my Web site, sometimes it takes a very lon=
g time
> (randomly). It doesn't seem to be database related, because even simple
> files, such as robots.txt sometimes take over a minute to return. Also, SQ=
L
> server profiler doesn't show any delays. Here are more details:
>
> - I checked the IIS log files to make sure it's not a network issue. It's
> not. IIS logs report the extremely long times it's taking to respond.
>
> - While waiting for a slow page to load (often more than a minute), I use
> terminal services to log in to the server and check perfmon, cpu utilizati=
on
> is less than 5%, and the machine is very responsive, including access to t=
he
> file system.
>
> - There are no errors in the event log or the iis httperror files.
>
> - The problem happens randomly, and it affects all kinds of files, weather=

> static (.txt,.css,.png) or dynamic (.aspx,asmx).
>
> - I'm using IIS6 on Windows Server 2003. It's a virtual host (vps). I'm
> using .net 2.0.
>
> =A0 =A0 This is what I got from ETW (I removed irrelevant details to keep =
it
> readable, but kept the titles all events). The main delay (3 seconds in th=
is
> case, but I caught cases with over 40 seconds) is happening between the
> HTTPSYS_CACHEABLE and NOTIFY_ISAPI_COMPLETION events. I'm not sure what th=
at
> means? Is that time spent inside my asp.net app? Any suggestions on how to=

> drill deeper?
>
> AspNetReq: Start - Start
> ConnId: 17059336
> Timestamp: 22:00:45.946.969600
>
> IISCache: URL_CACHE_ACCESS_START - IIS starts accessing URL cache to get
> metadata
> IISGeneral: GENERAL_GET_URL_METADATA - IIS gets URL metadata
> IISCache: URL_CACHE_ACCESS_END - IIS ends accessing URL cache
> IISCache: URL_CACHE_ACCESS_START - IIS starts accessing URL cache to get
> metadata
> IISGeneral: GENERAL_GET_URL_METADATA - IIS gets URL metadata
> IISCache: URL_CACHE_ACCESS_END - IIS ends accessing URL cache
>
> IISCache: HTTPSYS_CACHEABLE - IIS decides if the request is HTTP.SYS
> cacheable
> HttpsysCacheable: 0
> Reason: URL_CHANGE_BY_FILTER
> ContextIDSeq: 9
> Timestamp: 22:00:45.966.998400
>
> W3Isapi: NOTIFY_ISAPI_COMPLETION - Notify Isapi of Completion
> ContextIDSeq: 9
> Timestamp: 22:00:48.320.382400
>
> AspNetReq: End - End
> ConnId: 17059336
> ContextIDSeq: 9
> Timestamp: 22:00:48.320.382400
>
> Thanks

ninua
Wed Jan 16 13:23:01 CST 2008

> Please provide the entire trace.

Here is the full trace for a css file that took about 20 seconds. You bring
up a good point about it going through .NET, I'll look into this further. I
use Helicon's ISAPI_Rewrite to map URLs, and I have two domain names that can
access the same static files (and hence, I'm mapping all domain1 to domain2
so that I can use the same URL Rewriting rules rather than duplicating them
for each domain). Please note that during the 20 seconds it takes to get the
file, the CPU utilization if near 0% and the machine is otherwise very
responsive. Thanks.

Note: I did a search & replace on the domain names for privacy reasons.


Request n.37: http://domain1.com:80/common/css/build/Styles.css
{00000000-0000-0000-b50f-0060400000f4} 2008-0-16 11:43:8

IISGeneral: GENERAL_REQUEST_START - IIS starts processing a new request
AppPoolId: DefaultAppPool
ConnId: 1073745844
RawConnId: 0
RequestURL: http://domain1.com:80/common/css/build/Styles.css
RequestVerb: GET
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISFilter: FILTER_START - W3 filter starts
FilterName: C:\Program Files\Helicon\ISAPI_Rewrite\ISAPI_Rewrite.dll
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISFilter: FILTER_PREPROC_HEADERS_START - Filter starts PREPROC_HEADERS
notification
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISFilter: FILTER_SET_REQ_HEADER - IIS filter SET_REQ_HEADER
HeaderName: X-Rewrite-URL:
HeaderValue: /common/css/build/Styles.css
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISFilter: FILTER_SET_REQ_HEADER - IIS filter SET_REQ_HEADER
HeaderName: host:
HeaderValue: domain2.com
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISFilter: FILTER_SET_REQ_HEADER - IIS filter SET_REQ_HEADER
HeaderName: URL
HeaderValue: /common/css/build/Styles.css
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISFilter: FILTER_PREPROC_HEADERS_END - Filter ends PREPROC_HEADERS
notification
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISFilter: FILTER_END - W3 filter ends
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISFilter: FILTER_START - W3 filter starts
FilterName:
C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\aspnet_filter.dll
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISFilter: FILTER_PREPROC_HEADERS_START - Filter starts PREPROC_HEADERS
notification
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISFilter: FILTER_SET_REQ_HEADER - IIS filter SET_REQ_HEADER
HeaderName: AspFilterSessionId:
HeaderValue:
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISFilter: FILTER_PREPROC_HEADERS_END - Filter ends PREPROC_HEADERS
notification
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISFilter: FILTER_END - W3 filter ends
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISCache: URL_CACHE_ACCESS_START - IIS starts accessing URL cache to get
metadata
RequestURL: /common/css/build/Styles.css
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISGeneral: GENERAL_GET_URL_METADATA - IIS gets URL metadata
PhysicalPath: C:\domain2\domain2.com\common\css\build\Styles.css
AccessPerms: Read+Script
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISCache: URL_CACHE_ACCESS_END - IIS ends accessing URL cache
PhysicalPath: C:\domain2\domain2.com\common\css\build\Styles.css
ErrorCode: 0x00000000
URLInfoFromCache: 0
URLInfoAddedToCache: 0
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISFilter: FILTER_START - W3 filter starts
FilterName:
C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\aspnet_filter.dll
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISFilter: FILTER_URL_MAP_START - IIS starts URL_MAP notification
AccessPerms: 0x00000201
MatchingPath: 18
MatchingURL: 0
ScriptMapEntry:
OrigURL: /common/css/build/Styles.css
OrigPath: C:\domain2\domain2.com\common\css\build\Styles.css
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISFilter: FILTER_URL_MAP_END - IIS ends URL_MAP notification
AccessPerms: 0x00000201
FinalURL: /common/css/build/Styles.css
FinalPath: C:\domain2\domain2.com\common\css\build\Styles.css
MatchingPath: 18
MatchingURL: 0
ScriptMapEntry:
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISFilter: FILTER_END - W3 filter ends
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISAuthentication: AUTH_START - IIS authentication starts
AuthTypeSupported: Anonymous+NT
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISAuthentication: AUTH_REQUEST_AUTH_TYPE - Authentication type in the
request
RequestAuthType: Anonymous
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISAuthentication: AUTH_SUCCEEDED - IIS authentication succeeds
NTLMUsed: 0
AuthType: Anonymous
RemoteUserName:
AuthUserName:
TokenImpersonationLevel: 0x00000002
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISAuthentication: AUTH_END - IIS authentication ends
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISGeneral: GENERAL_STATIC_FILE_HANDLER - IIS processes a static file
request
FileName: C:\domain2\domain2.com\common\css\build\Styles.css
ContextIDSeq: 37
Timestamp: 11:43:08.655.398400

IISCache: FILE_CACHE_ACCESS_START - IIS starts accessing file cache
FileName: C:\domain2\domain2.com\common\css\build\Styles.css
UserName: IUSR_TEMPLATE
DomainName: DOMAIN2COM
ContextIDSeq: 37
Timestamp: 11:43:08.665.412800

IISCache: FILE_CACHE_ACCESS_END - IIS ends accessing file cache
ErrorCode: 0x00000000
Successful: 1
FileFromCache: 0
FileAddedToCache: 0
FileDirmoned: 1
LastModCheckErrorIgnored: 0
ContextIDSeq: 37
Timestamp: 11:43:08.665.412800

IISCache: HTTPSYS_CACHEABLE - IIS decides if the request is HTTP.SYS
cacheable
HttpsysCacheable: 0
Reason: URL_CHANGE_BY_FILTER
ContextIDSeq: 37
Timestamp: 11:43:08.665.412800

IISGeneral: GENERAL_REQUEST_END - IIS ends processing a request
HttpSubStatus: 0
BytesReceived: 693
ContextIDSeq: 37
Timestamp: 11:43:28.413.809600

LONG OPERATION
Total time: 20000 msecs

David
Wed Jan 16 16:31:27 CST 2008

This trace is missing the AspNetReq, etc traces of the abbreviated
trace that you provided yesterday. I do not believe we are looking at
the same thing or the same trace detail.

Also, the ISAPI Filter is rewriting the Host header in
SF_NOTIFY_PREPROC_HEADER, which is useless on IIS because by the time
the filter executes, IIS has already decided (based on the prior Host
header) which IIS website handles the response. Thus, this only
changes the value of the Host header and not the associated metadata
that governs how the request will be processed.

Furthermore, I believe your ISAPI Filter is preventing the kernel
response cache from ever succeeding (i.e. it turns off the kernel
response cache), thus your static file performance has already taken a
10x hit from the optimum on your machine. There is a property a filter
can set to tell IIS it is "cache friendly", though IIS will determine
if a filter is truly "cache friendly" and act accordingly.

Please make sure to show me the correct traces to make progress.

Sample trace config file for logman.exe:
"IIS: WWW Server" 0xFFFFFFFE 4
"IIS: WWW ISAPI Extension" 0 4
"ASP.NET Events" 0xF 5


//David
http://w3-4u.blogspot.com
http://blogs.msdn.com/David.Wang
//






On Jan 16, 11:23=A0am, Waleed ninua com> <waleed <atdot> wrote:
> > Please provide the entire trace.
>
> Here is the full trace for a css file that took about 20 seconds. You brin=
g
> up a good point about it going through .NET, I'll look into this further. =
=A0I
> use Helicon's ISAPI_Rewrite to map URLs, and I have two domain names that =
can
> access the same static files (and hence, I'm mapping all domain1 to domain=
2
> so that I can use the same URL Rewriting rules rather than duplicating the=
m
> for each domain). Please note that during the 20 seconds it takes to get t=
he
> file, the CPU utilization if near 0% and the machine is otherwise very
> responsive. =A0Thanks.
>
> Note: I did a search & replace on the domain names for privacy reasons.
>
> Request n.37:http://domain1.com:80/common/css/build/Styles.css
> {00000000-0000-0000-b50f-0060400000f4} 2008-0-16 11:43:8
>
> =A0 IISGeneral: GENERAL_REQUEST_START - IIS starts processing a new reques=
t
> =A0 =A0 AppPoolId: DefaultAppPool
> =A0 =A0 ConnId: 1073745844
> =A0 =A0 RawConnId: 0
> =A0 =A0 RequestURL:http://domain1.com:80/common/css/build/Styles.css
> =A0 =A0 RequestVerb: GET
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISFilter: FILTER_START - W3 filter starts
> =A0 =A0 FilterName: C:\Program Files\Helicon\ISAPI_Rewrite\ISAPI_Rewrite.d=
ll
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISFilter: FILTER_PREPROC_HEADERS_START - Filter starts PREPROC_HEADER=
S
> notification
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISFilter: FILTER_SET_REQ_HEADER - IIS filter SET_REQ_HEADER
> =A0 =A0 HeaderName: X-Rewrite-URL:
> =A0 =A0 HeaderValue: /common/css/build/Styles.css
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISFilter: FILTER_SET_REQ_HEADER - IIS filter SET_REQ_HEADER
> =A0 =A0 HeaderName: host:
> =A0 =A0 HeaderValue: domain2.com
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISFilter: FILTER_SET_REQ_HEADER - IIS filter SET_REQ_HEADER
> =A0 =A0 HeaderName: URL
> =A0 =A0 HeaderValue: /common/css/build/Styles.css
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISFilter: FILTER_PREPROC_HEADERS_END - Filter ends PREPROC_HEADERS
> notification
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISFilter: FILTER_END - W3 filter ends
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISFilter: FILTER_START - W3 filter starts
> =A0 =A0 FilterName:
> C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\aspnet_filter.dll
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISFilter: FILTER_PREPROC_HEADERS_START - Filter starts PREPROC_HEADER=
S
> notification
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISFilter: FILTER_SET_REQ_HEADER - IIS filter SET_REQ_HEADER
> =A0 =A0 HeaderName: AspFilterSessionId:
> =A0 =A0 HeaderValue:
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISFilter: FILTER_PREPROC_HEADERS_END - Filter ends PREPROC_HEADERS
> notification
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISFilter: FILTER_END - W3 filter ends
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISCache: URL_CACHE_ACCESS_START - IIS starts accessing URL cache to g=
et
> metadata
> =A0 =A0 RequestURL: /common/css/build/Styles.css
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISGeneral: GENERAL_GET_URL_METADATA - IIS gets URL metadata
> =A0 =A0 PhysicalPath: C:\domain2\domain2.com\common\css\build\Styles.css
> =A0 =A0 AccessPerms: Read+Script
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISCache: URL_CACHE_ACCESS_END - IIS ends accessing URL cache
> =A0 =A0 PhysicalPath: C:\domain2\domain2.com\common\css\build\Styles.css
> =A0 =A0 ErrorCode: 0x00000000
> =A0 =A0 URLInfoFromCache: 0
> =A0 =A0 URLInfoAddedToCache: 0
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISFilter: FILTER_START - W3 filter starts
> =A0 =A0 FilterName:
> C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\aspnet_filter.dll
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISFilter: FILTER_URL_MAP_START - IIS starts URL_MAP notification
> =A0 =A0 AccessPerms: 0x00000201
> =A0 =A0 MatchingPath: 18
> =A0 =A0 MatchingURL: 0
> =A0 =A0 ScriptMapEntry:
> =A0 =A0 OrigURL: /common/css/build/Styles.css
> =A0 =A0 OrigPath: C:\domain2\domain2.com\common\css\build\Styles.css
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISFilter: FILTER_URL_MAP_END - IIS ends URL_MAP notification
> =A0 =A0 AccessPerms: 0x00000201
> =A0 =A0 FinalURL: /common/css/build/Styles.css
> =A0 =A0 FinalPath: C:\domain2\domain2.com\common\css\build\Styles.css
> =A0 =A0 MatchingPath: 18
> =A0 =A0 MatchingURL: 0
> =A0 =A0 ScriptMapEntry:
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISFilter: FILTER_END - W3 filter ends
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISAuthentication: AUTH_START - IIS authentication starts
> =A0 =A0 AuthTypeSupported: Anonymous+NT
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISAuthentication: AUTH_REQUEST_AUTH_TYPE - Authentication type in the=

> request
> =A0 =A0 RequestAuthType: Anonymous
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISAuthentication: AUTH_SUCCEEDED - IIS authentication succeeds
> =A0 =A0 NTLMUsed: 0
> =A0 =A0 AuthType: Anonymous
> =A0 =A0 RemoteUserName:
> =A0 =A0 AuthUserName:
> =A0 =A0 TokenImpersonationLevel: 0x00000002
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISAuthentication: AUTH_END - IIS authentication ends
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISGeneral: GENERAL_STATIC_FILE_HANDLER - IIS processes a static file
> request
> =A0 =A0 FileName: C:\domain2\domain2.com\common\css\build\Styles.css
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.655.398400
>
> =A0 IISCache: FILE_CACHE_ACCESS_START - IIS starts accessing file cache
> =A0 =A0 FileName: C:\domain2\domain2.com\common\css\build\Styles.css
> =A0 =A0 UserName: IUSR_TEMPLATE
> =A0 =A0 DomainName: DOMAIN2COM
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.665.412800
>
> =A0 IISCache: FILE_CACHE_ACCESS_END - IIS ends accessing file cache
> =A0 =A0 ErrorCode: 0x00000000
> =A0 =A0 Successful: 1
> =A0 =A0 FileFromCache: 0
> =A0 =A0 FileAddedToCache: 0
> =A0 =A0 FileDirmoned: 1
> =A0 =A0 LastModCheckErrorIgnored: 0
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.665.412800
>
> =A0 IISCache: HTTPSYS_CACHEABLE - IIS decides if the request is HTTP.SYS
> cacheable
> =A0 =A0 HttpsysCacheable: 0
> =A0 =A0 Reason: URL_CHANGE_BY_FILTER
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:08.665.412800
>
> =A0 IISGeneral: GENERAL_REQUEST_END - IIS ends processing a request
> =A0 =A0 HttpSubStatus: 0
> =A0 =A0 BytesReceived: 693
> =A0 =A0 ContextIDSeq: 37
> =A0 =A0 Timestamp: 11:43:28.413.809600
>
> LONG OPERATION
> =A0Total time: 20000 msecs

ninua
Wed Jan 16 19:08:00 CST 2008

Thanks David. More details:

> Also, the ISAPI Filter is rewriting the Host header in
> SF_NOTIFY_PREPROC_HEADER, which is useless on IIS because by the time
> the filter executes, IIS has already decided (based on the prior Host
> header) which IIS website handles the response. Thus, this only
> changes the value of the Host header and not the associated metadata
> that governs how the request will be processed.

Yes, I'm aware of that. I'm changing the host header for my own need. I have
URL rewriting rules (using Helicon) that apply to two domains and go by the
host header value, and I don't want to repeate the rules for each domain.


> Furthermore, I believe your ISAPI Filter is preventing the kernel
> response cache from ever succeeding (i.e. it turns off the kernel
> response cache), thus your static file performance has already taken a
> 10x hit from the optimum on your machine. There is a property a filter
> can set to tell IIS it is "cache friendly", though IIS will determine
> if a filter is truly "cache friendly" and act accordingly.

Interesting. I'll look into that further. But this doesn't cause such long
delays, does it?

> Please make sure to show me the correct traces to make progress.

I changed the logman config file to use the one you suggested. Here is a new
trace that I caught in the last hour to access a small image and it took 9
seconds. Thank you so much for your help so far. I'm grateful.




Request n.406:
http://domain1.com:80/community/themes/domain1/CommunityLogo.png
{00000000-0000-0000-1d10-00604000001d} 2008-0-17 0:19:26

IISGeneral: GENERAL_REQUEST_START - IIS starts processing a new request
SiteId: 439452719
AppPoolId: DefaultAppPool
ConnId: 1073745948
RawConnId: 0
RequestURL:
http://domain1.com:80/community/themes/domain1/CommunityLogo.png
RequestVerb: GET
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISFilter: FILTER_START - W3 filter starts
FilterName: C:\Program Files\Helicon\ISAPI_Rewrite\ISAPI_Rewrite.dll
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISFilter: FILTER_PREPROC_HEADERS_START - Filter starts PREPROC_HEADERS
notification
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISFilter: FILTER_SET_REQ_HEADER - IIS filter SET_REQ_HEADER
HeaderName: X-Rewrite-URL:
HeaderValue: /community/themes/domain1/CommunityLogo.png
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISFilter: FILTER_SET_REQ_HEADER - IIS filter SET_REQ_HEADER
HeaderName: host:
HeaderValue: domain2.com
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISFilter: FILTER_SET_REQ_HEADER - IIS filter SET_REQ_HEADER
HeaderName: URL
HeaderValue: /community/themes/domain1/CommunityLogo.png
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISFilter: FILTER_PREPROC_HEADERS_END - Filter ends PREPROC_HEADERS
notification
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISFilter: FILTER_END - W3 filter ends
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISFilter: FILTER_START - W3 filter starts
FilterName:
C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\aspnet_filter.dll
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISFilter: FILTER_PREPROC_HEADERS_START - Filter starts PREPROC_HEADERS
notification
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISFilter: FILTER_SET_REQ_HEADER - IIS filter SET_REQ_HEADER
HeaderName: AspFilterSessionId:
HeaderValue:
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISFilter: FILTER_PREPROC_HEADERS_END - Filter ends PREPROC_HEADERS
notification
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISFilter: FILTER_END - W3 filter ends
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISCache: URL_CACHE_ACCESS_START - IIS starts accessing URL cache to get
metadata
RequestURL: /community/themes/domain1/CommunityLogo.png
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISGeneral: GENERAL_GET_URL_METADATA - IIS gets URL metadata
PhysicalPath:
C:\domain2\domain2.com\community\themes\domain1\CommunityLogo.png
AccessPerms: Read+Script
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISCache: URL_CACHE_ACCESS_END - IIS ends accessing URL cache
PhysicalPath:
C:\domain2\domain2.com\community\themes\domain1\CommunityLogo.png
ErrorCode: 0x00000000
URLInfoFromCache: 0
URLInfoAddedToCache: 0
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISFilter: FILTER_START - W3 filter starts
FilterName:
C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\aspnet_filter.dll
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISFilter: FILTER_URL_MAP_START - IIS starts URL_MAP notification
AccessPerms: 0x00000201
MatchingPath: 18
MatchingURL: 0
ScriptMapEntry:
OrigURL: /community/themes/domain1/CommunityLogo.png
OrigPath:
C:\domain2\domain2.com\community\themes\domain1\CommunityLogo.png
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISFilter: FILTER_URL_MAP_END - IIS ends URL_MAP notification
AccessPerms: 0x00000201
FinalURL: /community/themes/domain1/CommunityLogo.png
FinalPath:
C:\domain2\domain2.com\community\themes\domain1\CommunityLogo.png
MatchingPath: 18
MatchingURL: 0
ScriptMapEntry:
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISFilter: FILTER_END - W3 filter ends
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISAuthentication: AUTH_START - IIS authentication starts
AuthTypeSupported: Anonymous+NT
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISAuthentication: AUTH_REQUEST_AUTH_TYPE - Authentication type in the
request
RequestAuthType: Anonymous
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISAuthentication: AUTH_SUCCEEDED - IIS authentication succeeds
NTLMUsed: 0
AuthType: Anonymous
RemoteUserName:
AuthUserName:
TokenImpersonationLevel: 0x00000002
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISAuthentication: AUTH_END - IIS authentication ends
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISGeneral: GENERAL_STATIC_FILE_HANDLER - IIS processes a static file
request
FileName:
C:\domain2\domain2.com\community\themes\domain1\CommunityLogo.png
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISCache: FILE_CACHE_ACCESS_START - IIS starts accessing file cache
FileName:
C:\domain2\domain2.com\community\themes\domain1\CommunityLogo.png
UserName: IUSR_TEMPLATE
DomainName: DOMAIN2COM
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISCache: FILE_CACHE_ACCESS_END - IIS ends accessing file cache
ErrorCode: 0x00000000
Successful: 1
FileFromCache: 0
FileAddedToCache: 0
FileDirmoned: 1
LastModCheckErrorIgnored: 0
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISCache: HTTPSYS_CACHEABLE - IIS decides if the request is HTTP.SYS
cacheable
HttpsysCacheable: 0
Reason: URL_CHANGE_BY_FILTER
ContextIDSeq: 406
Timestamp: 00:19:26.515.556800

IISGeneral: GENERAL_REQUEST_END - IIS ends processing a request
HttpStatus: 200
HttpSubStatus: 0
BytesSent: 8101
BytesReceived: 646
ContextIDSeq: 406
Timestamp: 00:19:35.979.164800

Total time: 9000 msecs

David
Wed Jan 16 19:24:23 CST 2008

At this point, either you're missing traces (is this obtained by
logparser script -- what's the raw output), or it's a networking
problem -- because IIS shows no evidence of processing within those
nine seconds... and that's not an IIS issue since the handler has
already executed.

The nine seconds includes time spent over the network to the client
(time-taken). Virtual Machines are known to have random hiccups on
network bandwidth/latency.


//David
http://w3-4u.blogspot.com
http://blogs.msdn.com/David.Wang
//



On Jan 16, 5:08=A0pm, Waleed ninua com> <waleed <atdot> wrote:
> Thanks David. More details:
>
> > Also, the ISAPI Filter is rewriting the Host header in
> > SF_NOTIFY_PREPROC_HEADER, which is useless on IIS because by the time
> > the filter executes, IIS has already decided (based on the prior Host
> > header) which IIS website handles the response. Thus, this only
> > changes the value of the Host header and not the associated metadata
> > that governs how the request will be processed.
>
> Yes, I'm aware of that. I'm changing the host header for my own need. I ha=
ve
> URL rewriting rules (using Helicon) that apply to two domains and go by th=
e
> host header value, and I don't want to repeate the rules for each domain.
>
> > Furthermore, I believe your ISAPI Filter is preventing the kernel
> > response cache from ever succeeding (i.e. it turns off the kernel
> > response cache), thus your static file performance has already taken a
> > 10x hit from the optimum on your machine. There is a property a filter
> > can set to tell IIS it is "cache friendly", though IIS will determine
> > if a filter is truly "cache friendly" and act accordingly.
>
> Interesting. I'll look into that further. But this doesn't cause such long=

> delays, does it?
>
> > Please make sure to show me the correct traces to make progress.
>
> I changed the logman config file to use the one you suggested. Here is a n=
ew
> trace that I caught in the last hour to access a small image and it took 9=

> seconds. =A0Thank you so much for your help so far. I'm grateful.
>
> Request n.406:http://domain1.com:80/community/themes/domain1/CommunityLogo=
.png
> {00000000-0000-0000-1d10-00604000001d} 2008-0-17 0:19:26
>
> =A0 IISGeneral: GENERAL_REQUEST_START - IIS starts processing a new reques=
t
> =A0 =A0 SiteId: 439452719
> =A0 =A0 AppPoolId: DefaultAppPool
> =A0 =A0 ConnId: 1073745948
> =A0 =A0 RawConnId: 0
> =A0 =A0 RequestURL:http://domain1.com:80/community/themes/domain1/Communit=
yLogo.png
> =A0 =A0 RequestVerb: GET
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISFilter: FILTER_START - W3 filter starts
> =A0 =A0 FilterName: C:\Program Files\Helicon\ISAPI_Rewrite\ISAPI_Rewrite.d=
ll
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISFilter: FILTER_PREPROC_HEADERS_START - Filter starts PREPROC_HEADER=
S
> notification
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISFilter: FILTER_SET_REQ_HEADER - IIS filter SET_REQ_HEADER
> =A0 =A0 HeaderName: X-Rewrite-URL:
> =A0 =A0 HeaderValue: /community/themes/domain1/CommunityLogo.png
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISFilter: FILTER_SET_REQ_HEADER - IIS filter SET_REQ_HEADER
> =A0 =A0 HeaderName: host:
> =A0 =A0 HeaderValue: domain2.com
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISFilter: FILTER_SET_REQ_HEADER - IIS filter SET_REQ_HEADER
> =A0 =A0 HeaderName: URL
> =A0 =A0 HeaderValue: /community/themes/domain1/CommunityLogo.png
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISFilter: FILTER_PREPROC_HEADERS_END - Filter ends PREPROC_HEADERS
> notification
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISFilter: FILTER_END - W3 filter ends
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISFilter: FILTER_START - W3 filter starts
> =A0 =A0 FilterName:
> C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\aspnet_filter.dll
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISFilter: FILTER_PREPROC_HEADERS_START - Filter starts PREPROC_HEADER=
S
> notification
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISFilter: FILTER_SET_REQ_HEADER - IIS filter SET_REQ_HEADER
> =A0 =A0 HeaderName: AspFilterSessionId:
> =A0 =A0 HeaderValue:
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISFilter: FILTER_PREPROC_HEADERS_END - Filter ends PREPROC_HEADERS
> notification
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISFilter: FILTER_END - W3 filter ends
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISCache: URL_CACHE_ACCESS_START - IIS starts accessing URL cache to g=
et
> metadata
> =A0 =A0 RequestURL: /community/themes/domain1/CommunityLogo.png
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISGeneral: GENERAL_GET_URL_METADATA - IIS gets URL metadata
> =A0 =A0 PhysicalPath:
> C:\domain2\domain2.com\community\themes\domain1\CommunityLogo.png
> =A0 =A0 AccessPerms: Read+Script
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISCache: URL_CACHE_ACCESS_END - IIS ends accessing URL cache
> =A0 =A0 PhysicalPath:
> C:\domain2\domain2.com\community\themes\domain1\CommunityLogo.png
> =A0 =A0 ErrorCode: 0x00000000
> =A0 =A0 URLInfoFromCache: 0
> =A0 =A0 URLInfoAddedToCache: 0
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISFilter: FILTER_START - W3 filter starts
> =A0 =A0 FilterName:
> C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\aspnet_filter.dll
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISFilter: FILTER_URL_MAP_START - IIS starts URL_MAP notification
> =A0 =A0 AccessPerms: 0x00000201
> =A0 =A0 MatchingPath: 18
> =A0 =A0 MatchingURL: 0
> =A0 =A0 ScriptMapEntry:
> =A0 =A0 OrigURL: /community/themes/domain1/CommunityLogo.png
> =A0 =A0 OrigPath:
> C:\domain2\domain2.com\community\themes\domain1\CommunityLogo.png
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISFilter: FILTER_URL_MAP_END - IIS ends URL_MAP notification
> =A0 =A0 AccessPerms: 0x00000201
> =A0 =A0 FinalURL: /community/themes/domain1/CommunityLogo.png
> =A0 =A0 FinalPath:
> C:\domain2\domain2.com\community\themes\domain1\CommunityLogo.png
> =A0 =A0 MatchingPath: 18
> =A0 =A0 MatchingURL: 0
> =A0 =A0 ScriptMapEntry:
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISFilter: FILTER_END - W3 filter ends
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISAuthentication: AUTH_START - IIS authentication starts
> =A0 =A0 AuthTypeSupported: Anonymous+NT
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISAuthentication: AUTH_REQUEST_AUTH_TYPE - Authentication type in the=

> request
> =A0 =A0 RequestAuthType: Anonymous
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISAuthentication: AUTH_SUCCEEDED - IIS authentication succeeds
> =A0 =A0 NTLMUsed: 0
> =A0 =A0 AuthType: Anonymous
> =A0 =A0 RemoteUserName:
> =A0 =A0 AuthUserName:
> =A0 =A0 TokenImpersonationLevel: 0x00000002
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISAuthentication: AUTH_END - IIS authentication ends
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISGeneral: GENERAL_STATIC_FILE_HANDLER - IIS processes a static file
> request
> =A0 =A0 FileName:
> C:\domain2\domain2.com\community\themes\domain1\CommunityLogo.png
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISCache: FILE_CACHE_ACCESS_START - IIS starts accessing file cache
> =A0 =A0 FileName:
> C:\domain2\domain2.com\community\themes\domain1\CommunityLogo.png
> =A0 =A0 UserName: IUSR_TEMPLATE
> =A0 =A0 DomainName: DOMAIN2COM
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISCache: FILE_CACHE_ACCESS_END - IIS ends accessing file cache
> =A0 =A0 ErrorCode: 0x00000000
> =A0 =A0 Successful: 1
> =A0 =A0 FileFromCache: 0
> =A0 =A0 FileAddedToCache: 0
> =A0 =A0 FileDirmoned: 1
> =A0 =A0 LastModCheckErrorIgnored: 0
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISCache: HTTPSYS_CACHEABLE - IIS decides if the request is HTTP.SYS
> cacheable
> =A0 =A0 HttpsysCacheable: 0
> =A0 =A0 Reason: URL_CHANGE_BY_FILTER
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:26.515.556800
>
> =A0 IISGeneral: GENERAL_REQUEST_END - IIS ends processing a request
> =A0 =A0 HttpStatus: 200
> =A0 =A0 HttpSubStatus: 0
> =A0 =A0 BytesSent: 8101
> =A0 =A0 BytesReceived: 646
> =A0 =A0 ContextIDSeq: 406
> =A0 =A0 Timestamp: 00:19:35.979.164800
>
> =A0Total time: 9000 msecs