Budget Snapshots in the IIS Logs

A few components (Outlook Web App, EAS, and EWS) log budget snapshot information to the IIS logs. EWS, notably, includes both a start and an end snapshot. Here is an example of an IIS log entry for EWS (lines are broken up to make it more readable):

2010-03-09 15:15:12 XX.XXX.XX.X POST /ews/Exchange.asmx ;RC:bfe35012-30fd-499e-90d6-552d0ca89fab;
Init>>Conn:0,AD:30000/30000/0%,CAS:54000/54000/0%,AB:30000/30000/0%,RPC:36000/36000/0%,FC:1000/0,Hash:14366112,Sub:20/0;
SoapAction=m:GetDelegate;Version=1;RpcC=14;RpcL=687;LdapC=0;LdapL=0;
End(17156.25ms)>>Conn:3,AD:30000/30000/0%,CAS:54000/36907/28%,AB:30000/30000/0%,RPC:36000/35985/0%,FC:1000/0,Hash:14366112,Sub:20/0;
443 Domain\User XX.XX.XXX.XX - 200 0 0 17468

I am not going to go into a lot of detail regarding all the information here at this point, but I do want to point out a few things.

The "Init" section indicates what the user’s throttling budget looked like when the call began, whereas the "End" section indicates what the user’s throttling budget looked like when the call ended.

You may be tempted to assume that the change in budget between Init and End was due only to this GetDelegate call. However, budgets take into account concurrent requests. So, if you have a number of client threads hitting Exchange for user X, a single budget actually tracks all this information. The end result is that each of these IIS logs is a snapshot that takes into consideration ALL the request threads that are currently accessing the budget.

So, for example, on this simple GetDelegate call, the initial connection count was zero and the ending connection count is 3. It would be erroneous to assume that GetDelegate created multiple connections. Instead, you would need to examine the IIS logs for the current user and see which ones overlap the current GetDelegate call. Then you can determine where those extra connections came from.

A few quick acronym helps…
RC – Request Correlation – used by Microsoft support. Enables them to correlate IIS log entries with server traces.
Conn – Connections/Concurrency (represents MaxConcurrency).
AD – Active Directory (represents PercentTimeInAD).
CAS – Client Access server (represents PercentTimeInCAS).
AB – Address Book (represents PercentTimeInAddressBook).
RPC – Remote Procedure Call (represents PercentTimeInMailboxRPC).
FC – Find Count Limit (how many records can be returned in a single paged FindItem/FindFolder call).
Sub – Number of active subscriptions (push or pull).
Hash – Hash code of the budget. You can ignore this.

You will also notice the following format in both the Init and End sections: X/Y/Z%

X - Total number of msec allowed per minute as defined by the active throttling policy.
Y – The remaining time in the budget for this policy part.
Z – The "effective percent" that represents how much of the policy the current budget has used.

David Sterling
Exchange Web Services
Inside Microsoft Exchange Server 2007 Web Services