Mike Lagase

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

Iphone 2.0 and high Store CPU usage on Exchange Servers

Iphone 2.0 and high Store CPU usage on Exchange Servers

  • Comments 2
  • Likes

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

Comments
  • I"m not sure about how entourage fits into this since the 2 users (on 2 different exchange 2007 servers) do not use mac's and don't have entourage.  

    To fix the issue I disable active sync on the users's account and then move them to a different storage group.   (there's probably a better way to force it to update but i'm not sure what it is.)  

    BTW, turning off the IPhone after it has caused this problem does not appear to fix the server CPU issues.   (Client access server is separate from mailbox server and we are using ISA as well.)

    If you disable calendar synch on the iphone and then re-enable the activesync on the account it does not have the problem, so i'm sure that the problem is from calendar sych (like you found.)

    I'm going to call Premier support tomorrow since this is pretty much a show stopper for the IPhones

  • Thank you very much for sharing this information as it helped me resolve a similar issue I was seeing with a SCC Exchange 2007 mailbox server, we have with 4,100 users on it.

    RPC Requests were around 50 and slowly climbing and Average RPC Requests were around 60 and slowly climbing.  I had run Extra and Exmon but couldn't get a good feel for what was causing the problem until I found your article.  When I looked at the Averaged Latency for the Microsoft Active Sync client it was boucing between 250 and 300 significantly higher than any of the other clients.  So then I was sure it was a mobile device causing the issue.  I went ahead and did the IIS Reset on our 4 internet facing CAS servers and the high latency we were seeing on the server went back to normal.  I have more digging to do yet but you saved me from having to roll the cluster to the passive node, thus bringing down 4100 users for 10 - 15 minutes or longer.  Awesome stuff.  Thanks

Your comment has been posted.   Close
Thank you, your comment requires moderation so it may take a while to appear.   Close
Leave a Comment