Mike Lagase

Saving the Exchange world one day at a time.....

July, 2008

  • Mike Lagase

    Think powershell startup is slow?

    • 0 Comments

    Take a look at http://blogs.msdn.com/powershell/archive/2008/07/11/speeding-up-powershell-startup.aspx for a fix to this most annoying issue

  • Mike Lagase

    How to set System Cache upon Startup of a Windows 2003 server

    • 3 Comments

    In certain scenarios on Exchange 2007 servers, there may be the need to set the System File Cache on a server to prevent working set trimming scenarios due to other applications or processes running on the server. This can be any application or process that makes use of this Cache on the server. Note:  This blog entry was created as a reference in http://blogs.technet.com/mikelag/archive/2007/12/19/working-set-trimming.aspx.

    Here are the steps how to do this.

    • Create a directory on your server to house the startup batch file. (Ex. c:\batch_files)
    • Download Cacheset from http://technet.microsoft.com/en-us/sysinternals/bb897561.aspx and extract it to the directory above.
    • Run Cacheset
    • Note the minimum working set value on the server (For Example, 1980 KB)
    • Close Cacheset
    • Calculate the maximum value by taking 10% of Physical RAM. You can use an online tool such as http://www.calculateme.com/ComputerStorage/Gigabytes/ToKilobytes.htm for help with determining this to simplify things. (For Example, if you had 24GB of physical RAM in the server, the value would be 25165824)
    • Create a batch file with the following contents and save it as setcache.cmd in the above directory

      C:\batch_files\cacheset.exe 1980 25165824
       
    • Since setting the cache using this utility does not survive a reboot, we need to find a way to enable this upon startup. We can do this with the built-in Schtasks utility that is part of Windows 2003. Open a command prompt and type the following:

      schtasks /create /tn "Set Cache On Startup" /tr "c:\batch_files\setcache.cmd" /sc onstart /ru ""

      Note: Specifying "" for the /RU switch, tells the task to run as SYSTEM.

      More information regarding this tool can be found in the following locations:

      Windows 2008 schtasks help
      Windows 2003 schtasks help

    • Before we can run cacheset using SYSTEM rights, we need to bypass the EULA acceptance, otherwise the utility will hang upon starting waiting for you to click the Accept button and this procedure will not work.. To workaround this, open up a command prompt interactively following these steps 

      • Open a command prompt
      • Note the current time in military time. For example, if it is 4PM, then this equates to 16:00.
      • Type at 16:01 /interactive cmd.exe making sure that the time you enter is at least one minute past the current time.
      • Wait for the command window to open.
      • Type c:\batch_files\cacheset.exe  and accept the EULA.
      • Close the command prompt.

    • To verify that the scheduled task has been added properly, type schtasks from a command prompt. This should return the 'TaskName" and the "Next Run Time" of "At system start up"
    • Reboot the server
    • If all went well, run the cacheset.exe utility manually to ensure that the cache size is set accordingly. The minimum and maximum values should match what you added in the setcache.cmd file.

    Mike

  • Mike Lagase

    Iphone 2.0 and high Store CPU usage on Exchange Servers

    • 2 Comments

    Recently, we had a case where Outlook 2007 users were complaining of slow response from their Exchange servers and RPC latencies were high.

    I was then contacted to take a look at the overall performance of the server to see what might be going on. Hey, performance stuff is right up my alley!!

    So I added a few counters as shown below to get an overall picture of what the server was doing.

    Process(Store)\% Processor time - Purple
    MSExchangeIS\RPC Averaged Latency - Red
    MSExchangeIS\RPC Requests - Dark Blue

    image

    ---------------

    Whoah, High Store CPU with Averaged RPC latencies soaring over 1100ms. I can see why users were complaining.The other odd thing is RPC requests constantly climbing, so we knew we had a request that was blocking other requests from being processed or the server could not process the requests in a timely fashion causing this stair stepping pattern. I would presume that the high CPU was the main culprit, but it was most likely a combination of the two since rises in store CPU normally occur from some client action or operation.

    With Exchange 2007, we can now break down RPC Operations/sec and RPC Averaged Latencies per protocol via the MSExchangeIS Client Performance counter. I've documented this in the Performance counter/threshold section of the help file that I wrote at http://technet.microsoft.com/en-us/library/bb201689(EXCHG.80).aspx

    So I added all instances of of MSExchangeIS Client and found that the same time the high Store CPU occurs, is the same time Exchange ActiveSync latencies go through the roof. The odd thing is that ActiveSync was not performing a lot of operations, it's just that the latencies were extremely high. In green below is the ActiveSync latencies along with the high Store CPU counter. Looks like that coincides with the CPU problem.

    image

    Now that we have some kind of idea what is happening here, we needed to find a way to narrow down a possible user. Exmon to the rescue!!. Exmon is an invaluable tool for troubleshooting issues just like this to find high CPU offenders and folks that start generating hundreds of transaction logs on a server.

    After Exmon was fired up, there was one user that was taking 97-98% of the CPU for Store, so we know this person is most likely the culprit. You can see this Live in Exmon.

    image

    So we know right here that they are not generating a lot of transaction logs as our Log bytes columns is low, but the amount of Referenced Pages is extremely high as shown below. This means one thing, this client is performing a lot of "Reads" in the database with a minimal amount of transactions. With the client version being 2049.-32477.1, this is coming from a managed component (MAPI.NET) and this case, it was directly from the CAS Servers IP Address. 
     image

    The Exchange administrator at the company ran to that person's desk to find out what they were doing to cause this. There he was sitting in his chair next to his Mac computer playing with his shiny new Iphone 2.0. Hmmmm. Since the new Iphone uses ActiveSync to connect to exchange, this confirms what we saw in perfmon.

    So we had to do something with that Iphone device by either stepping on it or simply shutting if off. They obviously used the latter. :) Oddly enough, the problem persisted even with the device off.

    The best way to find ActiveSync behavior is via the IIS logs. After scouring the logs since we knew the name of the person at fault, we noticed these POST events being written to the log.

    POST /Microsoft-Server-ActiveSync/default.eas User=<username>&DeviceId=Appl7U745351WH8&DeviceType=iPhone&Cmd=Sync&Log=V25_ Fc1_Fid:5_Ty:Em_Filt2_St:S_Sk:67_Sst12_Srv:1a0c1d0s0e0r_LdapC0_LdapL0_RpcC19_ RpcL15_Pk3155156895_S1_ 443 Apple-iPhone/501.347 200 0 0

    OST /Microsoft-Server-ActiveSync/default.eas User=<username>&DeviceId=Appl7U745351WH8&DeviceType=iPhone&Cmd=Sync&Log=V25_ Fc1_Fid:1_Ty:Ca_Filt0_St:F_Sk:0_LdapC0_LdapL0_RpcC1097_RpcL7796252_Ers1_ Pk3155156895_Error:SyncStateNotFound_ 443 Apple-iPhone/501.347 500 0 0

    Error:SyncStateNotFound was the interesting error code being logged here as that simply means that we either have never synched with the Exchange server or the Sync State information was removed from the Exchange server or we just can't get there from here.

    After investingating this further, we visited the httperr.log file on the CAS server and found this same user that was performing some operations that was being rejected at a very high rate.Here is a snippet of the httperr.log.

    2008-07-14 12:00:43 <Client IP Address> 35779 <Server IP Address> 443 HTTP/1.1 POST /Microsoft-Server-ActiveSync?User=username&DeviceId=Appl7U745351WH8&DeviceType=iPhone&Cmd=Sync - 1 Connection_Abandoned_By_AppPool MSExchangeSyncAppPool
    2008-07-14 12:00:43 <Client IP Address> 48447 <Server IP Address> 443 HTTP/1.1 POST /Microsoft-Server-ActiveSync?User=username&DeviceId=Appl7U745351WH8&DeviceType=iPhone&Cmd=Sync - 1 Connection_Abandoned_By_AppPool MSExchangeSyncAppPool
    2008-07-14 12:00:43 <Client IP Address> 49065 <Server IP Address> 443 HTTP/1.1 POST /Microsoft-Server-ActiveSync?User=username&DeviceId=Appl7U745351WH8&DeviceType=iPhone&Cmd=Sync - 1 Connection_Abandoned_By_AppPool MSExchangeSyncAppPool
    2008-07-14 12:00:43 <Client IP Address> 35358 <Server IP Address> 443 HTTP/1.1 POST /Microsoft-Server-ActiveSync?User=username&DeviceId=Appl7U745351WH8&DeviceType=iPhone&Cmd=Sync - 1 Connection_Abandoned_By_AppPool MSExchangeSyncAppPool
    2008-07-14 12:00:43 <Client IP Address> 38680 <Server IP Address> 443 HTTP/1.1 POST /Microsoft-Server-ActiveSync?User=username&DeviceId=Appl7U745351WH8&DeviceType=iPhone&Cmd=Sync - 1 Connection_Abandoned_By_AppPool MSExchangeSyncAppPool
    2008-07-14 12:00:43 <Client IP Address> 39976 <Server IP Address> 443 HTTP/1.1 POST /Microsoft-Server-ActiveSync?User=username&DeviceId=Appl7U745351WH8&DeviceType=iPhone&Cmd=Sync - 1 Connection_Abandoned_By_AppPool MSExchangeSyncAppPool
    2008-07-14 12:00:43 <Client IP Address> 37161 <Server IP Address> 443 HTTP/1.1 POST /Microsoft-Server-ActiveSync?User=username&DeviceId=Appl7U745351WH8&DeviceType=iPhone&Cmd=Sync - 1 Connection_Abandoned_By_AppPool MSExchangeSyncAppPool
    2008-07-14 12:00:43 <Client IP Address> 47280 <Server IP Address> 443 HTTP/1.1 POST /Microsoft-Server-ActiveSync?User=username&DeviceId=Appl7U745351WH8&DeviceType=iPhone&Cmd=Sync - 1 Connection_Abandoned_By_AppPool MSExchangeSyncAppPool
    2008-07-14 12:00:43 <Client IP Address> 40009 <Server IP Address> 443 HTTP/1.1 POST /Microsoft-Server-ActiveSync?User=username&DeviceId=Appl7U745351WH8&DeviceType=iPhone&Cmd=Sync - 1 Connection_Abandoned_By_AppPool MSExchangeSyncAppPool
    2008-07-14 12:00:43 <Client IP Address> 36976 <Server IP Address> 443 HTTP/1.1 POST /Microsoft-Server-ActiveSync?User=username&DeviceId=Appl7U745351WH8&DeviceType=iPhone&Cmd=Sync - 1 Connection_Abandoned_By_AppPool MSExchangeSyncAppPool
    2008-07-14 12:00:43 <Client IP Address> 46031 <Server IP Address> 443 HTTP/1.1 POST /Microsoft-Server-ActiveSync?User=username&DeviceId=Appl7U745351WH8&DeviceType=iPhone&Cmd=Sync - 1 Connection_Abandoned_By_AppPool MSExchangeSyncAppPool
    2008-07-14 12:00:43 <Client IP Address> 47795 <Server IP Address> 443 HTTP/1.1 POST /Microsoft-Server-ActiveSync?User=username&DeviceId=Appl7U745351WH8&DeviceType=iPhone&Cmd=Sync - 1 Connection_Abandoned_By_AppPool MSExchangeSyncAppPool
    2008-07-14 12:00:43 <Client IP Address> 38463 <Server IP Address> 443 HTTP/1.1 POST /Microsoft-Server-ActiveSync?User=username&DeviceId=Appl7U745351WH8&DeviceType=iPhone&Cmd=Sync - 1 Connection_Abandoned_By_AppPool MSExchangeSyncAppPool
    2008-07-14 12:00:43 <Client IP Address> 41603 <Server IP Address> 443 HTTP/1.1 POST /Microsoft-Server-ActiveSync?User=username&DeviceId=Appl7U745351WH8&DeviceType=iPhone&Cmd=Sync - 1 Connection_Abandoned_By_AppPool MSExchangeSyncAppPool
    2008-07-14 12:00:43 <Client IP Address> 35323 <Server IP Address> 443 HTTP/1.1 POST /Microsoft-Server-ActiveSync?User=username&DeviceId=Appl7U745351WH8&DeviceType=iPhone&Cmd=Sync - 1 Connection_Abandoned_By_AppPool MSExchangeSyncAppPool
    2008-07-14 12:00:43 <Client IP Address> 41749 <Server IP Address> 443 HTTP/1.1 POST /Microsoft-Server-ActiveSync?User=username&DeviceId=Appl7U745351WH8&DeviceType=iPhone&Cmd=Sync - 1 Connection_Abandoned_By_AppPool MSExchangeSyncAppPool
    2008-07-14 12:00:43 <Client IP Address> 34537 <Server IP Address> 443 HTTP/1.1 POST /Microsoft-Server-ActiveSync?User=username&DeviceId=Appl7U745351WH8&DeviceType=iPhone&Cmd=Sync - 1 Connection_Abandoned_By_AppPool MSExchangeSyncAppPool

    So how did we stop the madness to bring service back to the Mailbox server? They ended up recycling the IIS services on the CAS box, but the same results could have been had by recycling just the MSExchangeSyncAppPool application pool. Immediately after doing this, the CAS connection was dropped which then terminated that users connection bringing Store CPU back under control.

    After looking at the users mailbox via the Get-MailboxFolderStatistics cmdlet, we found over 43,000 items in the users calendar folder. Ouch!!. Simply turning off calendar sync for this one user allowed service to be returned to all users. How about them apples?

    Troubleshooting performance issues in Exchange can be complex in nature due to the many moving parts and underlying dependencies, but using the proper tools and a methodical approach to narrowing down the issues is key to finding root cause.

    Unfortunately, the customer was not willing to risk taking the store down for a couple of minutes to see what was happening with a store dump file, so we don't know if this is an actual issue or not at the current time.

    Update!!! What we found this to be is a corrupted recurring meeting and viewing this in Outlook 2007 or OWA, shows the same accordian type behavior as shown below, but oddly enough, through an Entourage client, it shows as a single meeting only. This explains why there was so many calendar items in this users mailbox.

    image 

    So it appears that the root cause of this problem was having SyncServices in Entoruage enabled at the same time the Iphone was using EAS causing these duplicates. So we sync'd up the data to Exchange and then sync'd the data down to the IPhone which caused the Iphone to hang which is exactly when the high CPU started occurring. Somewhere in the August timeframe, there will be an update to Office for Mac (12.1.2) that addresses the duplicate issues.

    So the moral of the story is, that if you previously had SyncServices enabled in Entourage and upgrade your Iphone to the latest firmware, be sure to disable SyncServices if you are planning on switching to EAS.

    Update!!
    One of the other reasons you might get this 100% CPU issue is if your run Get-ActiveSyncDeviceStatistics using the RTM management tools against a CAS server. This is a known issue that has been fixed in the SP1 management tools. What happens is that when you run this command using RTM tools against a CAS server in which a user has previously synched their device,, the Get-ActiveSyncDeviceStatistics cmdlet attempts to look at the sync state of the user. There has been some changes in the SP1 tools that makes this information seem corrupt from the RTM tools, so we remove that data from the users mailbox. This essentially causes a full sync with the server. With the SP1 tools installed, we now use an API with read only flags, so if we should have problems reading the sync state for the user, we no longer go in and reset the data in the mailbox.

    ike

Page 1 of 1 (3 items)