Skip to content

2009

IIS 5 and 6 time-taken field

IIS_time_takenWhile checking the performance problem a client was having with a legacy ASP.NET 1.1 application (yep, I am still young enough to call a 6 years old system, legacy J ), I asked myself what seems like a basic question. **Does the time-taken column in IIS 5 logs takes into account the network time ? ** That is, Is the stop watch stopped when the response is ready or when the last TCP acknowledge is received from the client. After googling for a while I was quite disappointed by the lack of information regarding this specific column. The only useful information I found concerned IIS 6 and were …hum, let’s just say that Microsoft doesn’t seems to be able to make up its mind about this field: According to :http://support.microsoft.com/kb/944884

Beginning in IIS 6.0, the time-taken field typically includes network time. Before HTTP.sys logs the value in the time-taken field, HTTP.sys usually 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. Therefore, when a large response or large responses are sent to a client over a slow network connection, the value of the time-taken field may be more than expected.

According to :http://www.microsoft.com/technet/prodtechnol/WindowsServer2003/Library/IIS/676400bc-8969-4aa7-851a-9319490a9bbb.mspx?mfr=true

For the time-taken field, the client-request timestamp is initialized when HTTP.sys receives the first byte, but before HTTP.sys begins parsing the request. The client-request timestamp is stopped when the last IIS send completion occurs. Time taken does not reflect time across the network. The first request to the site shows a slightly longer time taken than other similar requests because HTTP.sys opens the log file with the first request.

Perplexed, I figured out I could know the answer for sure by firing up Fiddler and comparing Fiddler time with the value of the time-taken columns in IIS log. I had limited access to the client environment but managed to get some measures nonetheless. Once again, it was a dead-end, the Fiddler times were sometimes higher than the IIS log time, sometimes lower. That’s when I decided to contact the Microsoft Partner Support. The definite answer they gave me for the time-taken field in IIS 5 logs is:

Since the calculation includes the time for the acknowledgement from the client, it may be skewed by any network latency issues.

The not so definite answer the support gave me for the IIS 6 time-taken field is that after checking the source code, the network time is not included in the time-taken field. However they also say that that if the request is aborted during its execution, no value are logged for the request; Therefore it would seems like IIS 6 waits for the last ACK to log BUT it doesn’t log the network. And that would be why the public available information is as clear as mud. I hope it helps. Edit : 29/06/2009 A reader (thank you Joe) pointed out to me that the http://www.microsoft.com/technet/prodtechnol/WindowsServer2003/Library/IIS/676400bc-8969-4aa7-851a-9319490a9bbb.mspx?mfr=true article as been updated with the following :

This is no longer true for II6, and you can check the KB94483. IIS TIME-TAKEN field takes into account the last ACK from the answer to the response, so in fact does reflect time across the network. There is only 2 exceptions for this:

  • The response size is less than or equal to 2 KB, and the response size is from memory.
  • TCP buffering is used.

So problem solved, but if anyone find the trace of the KB94483 mentionned, let me know because I can't !

SharePoint : Search using « This Site » or “This List” scope returning no results

I met a problem with the Search scope on a MOSS 2007 farm the other day that I thought was worth blogging about. On all the content sites of our farm, the “All Sites” scope worked as expected, but the “This Site” or “This List” search scopes wouldn’t return a single result. There are several reasons that can explains this problem according to this technet forum thread (http://social.technet.microsoft.com/Forums/en-US/sharepointsearch/thread/906045d8-8782-4c39-be1b-7632f7239019/#page:1), in our case the problem was due to a difference between the Content Source defined for the crawl and the default zone defined in the Alternate Access mapping. Our Alternate Access Mapping for this zone was defined as follow:

Private URL Zone Public URL
http://hostname Default http://hostname
http://intra.dnsname.com Intranet http://intra.dnsname.com
And we used http://intra.dnsname.com as the start address for the crawl.
We tried changing the content source start address from http://intra.dnsname.com to http://hostname, resetted the crawl content and launched a full crawl and that was it. The “This Site” and list scopes worked perfectly from then on.
That could have been it, except that this change caused another problem. Before this modification we had no trouble with links URL, I mean if I used http://intra.dnsname.com to reach the site, all the links in the pages would use this dns name, not the hostname. After the modification of the content source however, some search results would sometimes be presented with the hostname in the url instead of the dns name.
To solve that problem we changed the Alternate Acces Mapping configuration to:
Private URL Zone Public URL
http://hostname Default http://intra.dnsname.com
http://intra.dnsname.com Default http://intra.dnsname.com
Voila! The Site and List scopes are working and the URL are always based on the DNS name when someone uses the DNS name to reach to site.
By the way, you might find this article about Alternate Access Mapping very useful: http://blogs.msdn.com/sharepoint/archive/2007/03/06/what-every-sharepoint-administrator-needs-to-know-about-alternate-access-mappings-part-1.aspx

Infinite looping the MOSS OOTB approval workflow

A few days ago, I noticed something weird with the Microsoft Office SharePoint Server out of the box workflow, most specifically with the workflow option to start when an item is modified. I was trying to set up the Approval Workflow on a SharePoint List with content approval activated. I first set up the workflow to ask for approval when a new item is submitted to the list. It worked fine but we also needed to ask for approval when an item was updated (e.g. the writer made a mistake and notice it after the approver did his job, thus he modify the item that as a result needs to be approved a second time). I fired up the workflow configuration page and checked the infamous “Start Workflow when an item is modified” in the start options. From a french MOSS install And from then everything went wrong. Whenever an approvers did his job by approving an item, the workflow would be launched again and a new approval task would be added to the workflow task list. I tried tweaking the workflow, modifying the tasks list used … but nothing would do the trick, the workflow was stuck in an infinite loop whenever the “Start on item edit” was activated.

And that’s when it hit me, changing the approval status of an item seemed to be considered as a modification of the item itself.
I am still surprised by what I can’t help but see as a major flaw of SharePoint. I definitely don’t think that the approval status of an item is part of the item itself, it is only a SharePoint information about OUR piece of information (the item).

I also was surprised by how few people seems to react to this fact based on a few google search I made. Yet it seems other people faced the same problem (http://social.msdn.microsoft.com/Forums/en-US/sharepointworkflow/thread/62f5921d-9d02-4924-a61f-97ad169d1043/ and http://unitedsupplyco.sharepointsite.net/publicfacing/bensblog/Lists/Posts/Post.aspx?ID=34 ). If you have any information about this subject, I would enjoy to know it.