How to collect per request Performance Stats for IIS on Exchange 2007

  • [アーティクル]

Ever had a time where you were trying to troubleshoot an IIS Performance related issue on Exchange 2007 and the built-in performance counters were not giving you the data that you needed to gain insight in to the problem? I know I have run in to these before and they are not always the easiest to track as we cannot see latencies at a per request level easily.

As part of the default installation of Exchange 2007, you may have also seen IIS log entries similar to the following, but didn’t know what the appended IIS data meant.

/owa/ev.owa oeh=1&ns=DatePicker&ev=GetFreeBusy&m=2009-04-01T00%3a00%3a00&fId=LgAAAADBC0ggZ4mHTKllH8Mc0937AQBmBiNCEaM7R53LcWBj0I1aAAAAAACrAAAC&prfltncy=98&prfrpccnt=6&prfrpcltncy=78&prfldpcnt=0&prfldpltncy=0&prfavlcnt=0&prfavlltncy=0

The information I am calling out in this IIS Log request is prfltncy, prfrpccnt, prfrpcltncy, prfldpcnt, prfldpltncy, prfavlltncy. These entries are specific to latency entries at the end of each call that is being made. There may only be a handful of these throughout the logs by default.

Luckily, there is a way to enable additional per request user tracing in to the IIS logs to help you with troubleshooting these performance type problems. This tracing will allow you to see per request latencies for OWA, RPC and Availability requests.

To enable this additional logging, you would do the following:

Go to "Program Files\Microsoft\Exchange Server\ClientAccess\OWA". Edit web.config in Notepad. Add the following line of text under appSettings:
<add key="CollectPerRequestPerformanceStats" value="true"/>

After saving the web.config file, you should start seeing entries in the IIS logs similar to the above, but here is another log example:

/owa/default.aspx modurl=7&prfltncy=84212&prfrpccnt=37&prfrpcltncy=84011&prfldpcnt=9&prfldpltncy=30&prfavlcnt=0&prfavlltncy=0

In the above request, we can see that the RPC latencies are high (prfltncy=84212&prfrpccnt=37&prfrpcltncy=84011) , so this was most likely a bottleneck between the CAS and the backend Mailbox server. Now wasn’t that easy to determine where the potential bottleneck might lie?

Per Request Tracing Legend
Prfltncy - Overall Performance Latencies for this request
Prfrpccnt - RPC request count
Prfrpcltncy - RPC Latencies
Prfldpcnt - LDAP request count
Prfldpltncy – LDAP Latencies
Prfavlltncy - Availability Latencies

If you break one of these log requests down, here is the way you would look at this based on the first request example above. (Note: This was a call to get Free/Busy Data for a specific time period)

  • prfltncy=98 - Overall Performance Latency for the request
  • prfrpccnt=6&prfrpcltncy=78 - 6 RPC requests with a latency of 78ms
  • prfldpcnt=0&prfldpltncy=0 - 0 LDAP requests with a latency of 0ms
  • prfavlcnt=0&prfavlltncy=0 - 0 Availability requests with a latency of 0ms

You can use any log parser (ie.logparser.exe) of your choice to get further information, but this should help you understand some of the latencies down to a per request level.

I hope this helps in your performance troubleshooting…..