Network performance measurement in asp.net 2.0 via HttpHandlers and HttpModules strangeness

Question

We have a performance measurement module that relies on HttpModule and HttpHandlers and works like this:

1. Request comes in to server for a page.
2. HttpModule_Begin writes start time in the cookie.
3. HttpModule_End writes end time in the cookie.
4. On client, when page load is finished, fire off a special request via AJAX that is handled by HttpHandler_ProcessRequest
5. In HttpHandler_ProcessRequest subtract DateTime.Now from end time written by the previous HttpModule_End (which is stored in the cookie) and store it in the database. One thing I forgot to mention: all data is shared via a cookie, so the HttpHandler, just pulls the data from the cookie without any session id's, etc... All participants are in the same time zone.

This process works fine for most cases, but there are some instances that report network time in excess of an hour! This indicates a very large passage of time between the the writing of end time and firing off the AJAX request or a large passage of time between firing off AJAX request and the time it gets to the app server. I am trying to figure what could be causing this issues in the wild. Why does the operation not simply time out?

Answer 1

Are you including some unique id that allows the AJAX request handler to figure out the which end time to use for the calculation? If not, perhaps enough of the page has been rendered on the client that the AJAX request is actually coming before the end time has been written to the database and it is using the wrong end time.

Answer 2

Extend your troubleshooting: append values to the IIS log (HttpContext.Current.Response.AppendToLog(string)).

The IIS log will show your entries and you can determine when those requests were actually recorded. You can append whatever you want and it shows up in the query field of the log (assuming you're using W3C format.)

If you're experiencing delays in requests, as the evidence suggests, you can verify it. This will give you the IIS log as a comparative source against the recorded values in cookies.