SharePoint’s Page Output Caching can offer a massive performance boost to publishing sites but only when its working and working correctly. One of the problems I have seen is when some administrators turn on Page Output Caching they just assume it works. While this may be the desire and in most cases it may just work for you I would suggest you verify; and I don’t mean hit the site with the browser to see if it speeds up.
This post is about troubleshooting SharePoint’s Page Output Caching. Now if you don’t use Page Output Caching or yours is working just fine you are the “Master of your Page Output Caching” – as for the rest of us we will likely need to put on our troubleshooting hat and dig a bit deeper. I find troubleshooting anything is allot easier if you know a little about how the component you are troubleshooting operates and how it is suppose to work.
A Little Background
SharePoint’s Page Output Caching is implemented via two HttpModules, the first being SharePoint’s own Publishing HttpModule and the second being ASP.Net’s Output Caching HttpModule – System.Web.Caching.OutputCacheModule. The two modules work together with the Publishing Module fronting all the work to determine what is available for cache and how items are to be cached based upon site collection settings, publishing page settings, and some other internal calculations which typically are the reason we end up needing troubleshooting this component (more on this later). Once the publishing cache determines the correct variables are in place to enable a page to be cached it calls into the HttpResponse.Cache.SetCaceability() which is the signal to the OutputCacheModule that we have a candidate for output caching. The PublishingModule also sets the various VaryBy parameters such as VaryByHeader, VaryByParam, and VaryByCustom which handles audience targeting, vary by browser, vary by permissions, etc. At runtime these VaryBy parameters are used to build a long string which will act as a case sensitive key which the OutputCacheModule will use to store and retrieve the contents of the page from the HttpCache which itself is stored in memory. The HttpCache is a bit like a dictionary where the key is used to lookup a value which in this case is the page contents and the key can change based upon the Page Output Cache Profile settings and the VaryBy(s).
If the Page Output Cache Profile is set to “Check for Changes” or “Perform ACL Check” then the Publishing Module will register a HttpCacheValidateHandler delegate to deal with Site Changes. When you choose “Check for Changes” every request for cached content will do a lookup to the SPSite.LastContentModifiedDate and if this date is more recent than when the item was cache the item will be invalidated and a full request is made. So any content change within a site will cause all cached pages within that site collection to be invalidated once requested – that is to say there is no “flush” operation as the documentation states but rather an item by item invalidation as the item is requested. The downside of course is for larger site collections with many sites and cached pages a single content change can cause the entire cache to become invalid – this could be a huge negative impact on performance. Pages or list items which may not have any relationship to the page requested could cause content changes which, would for a period, could cause a spike in cache misses.
So armed with our most valuable troubleshooting tool (the knowledge of how things work) it is time to look at a couple of other tools we can use. The ULS logs can be configured to log information related to Publishing Cache by jumping on over into Central Administration and enabling the Publishing Cache component’s logging. Unfortunately, while we will get a number of statements related to Output Caching we also pick up Blob Caching and Object Caching statements too. So when digging into the ULS logs be aware that some of the logging you just enabled may be related to these other caching mechanisms and not necessarily Page Output Caching.
Some of the statements you want to look for include strings like:
|Output cache not used due to [some reason]||5kaw|
|Enabling specified cache profile: [profile name]||5kb0|
|EnableCache: [true|false] Duration: [seconds] VaryByParam: [string] CheckForUpdates: [true|false] CheckForRights: [true|false]||5kb1|
|Invalidating URL [url to page] from the cache due to site change||921d|
If you were on a desert island and could take only one Page Output Caching ULS entry with you it would have to be the one with tag 5kaw – as it is this entry which will hopefully give you a reason why your page is not being cached. I say hopefully, because as I will discuss later this is not always the case. In addition, to the strings mentioned above you will likely see a number of VaryBy related strings such as “Calculating VaryByCustom”… littered throughout the ULS logs which can be useful if your cache is growing really large and you need to determine why that may be the case.
As most of you probably already know you can request the Publishing HttpModule write a debug statement into the page which helps guide troubleshooting.
Whenever I start troubleshooting Page Output Cache issues the first thing I typically enable is the debug cache information on pages for 2 reasons, 1) I dislike trolling through the ULS logs looking for something which may not be there, the noise to signal ratio in these logs make for interesting fishing but I like my fish in water, 2) the page’s debug statement gives me almost as much information as I will find in the ULS logs. Of course one of the annoying aspects to using the caching debug statements is you must “view source” of the page in a browser and scroll to the bottom to check out the debug statement; doing this more than a few times can grow really monotonous. A little trick I use use to read the caching debug statement it to leverage tinyget.exe (yes you could use curl and a number of other tools too). I use the tool like so:
tinyget -srv:www.sp.com -uri:/pages/default.aspx -data |find "<!– "
So the issues I typically hear the most around Page Output Caching is a page is not being cached or not being cached for the period around which is expected.
Before digging into why something is not cached we need to understand what is not inherently cached by page output caching otherwise we will be chasing a ghost. The SharePoint Publishing module ensures page requests with the POST verb and anything that lives under /_layouts will not be cached, The kicker is ASP.Net’s Output Cache module has some additional checks, such as additional verbs such as HEAD, DELETE. PUT which too are not cached.
As stated we can get reasons why pages are not cached from the ULS logs as well as with the page debug statement. The following table details these reasons
|The user is currently viewing the page with the console visible.||When you see this reason it typically means the page ribbon is visible and the page is in authoring mode.|
|Cache profile [profile name] disables caching for [Authenticated | Anonymous] users.||If you see this message and it is not what you want you need to verify the cache profile settings.|
|Could not load cache profile. Profile has ID [GUID]||This is an indication someone has gone and deleted a cache profile which was in use. Since there is no way to recreate a profile’s ID it will be necessary to create a new profile and set the sites to use this profile instead of the missing cache profile.|
|Unable to get publishing page object for current request||This is the results of not being able to get the publishing page for for the URL passed.|
|Page contains personalized parts||The user making the request has at least one personalized WebPart on the page.|
|User has edit rights in the site collection||The user is currently viewing a page which is not in a published state and the user has Edit List Items permissions on the site (SPWeb) (not site collection as the message might indicate)|
|User can view an unpublished version of the current page||You might see this when “Vary by User Rights” is selected and the user has Edit List Item rights. This again, may not be an issue and you might want to check the Cache Profile settings if you see this message and don’t expect to.|
|There are more than 10000 uniquely secured objects in the site collection||When more than 10,000 uniquely permissioned items exist in a site collection Object Caching will just stop working. This number is hard coded and is not impacted by the Throttling settings of the web application.|
|The page was requested to not be cached by other code||Any User Control, WebPart, or really any other customization can explicitly request a page not be cached by calling DontEnableCachingForRequest. If you see this as a reason it is likely because of some customization calling this API.|
10000 uniquely secured objects
Of the errors mentioned above the one which might leave you scratching you head is the 10,000 uniquely secured objects. Once the number of uniquely secured objects within a Site Collection hits 10,000, Object Caching just stops working – no warning, no events will be logged, just the performance of your site may drop. So do we need a health rule for this? You bet. If you happen to be lucky enough to be saddled with this reason for Page Output Caching not working, the first thing you are going to ask your self is how many are there and where are they located. For a large site collection this may be hard to determine or mitigate which means you may need to split up your site collection to help spread out the uniquely permissioned items. But before you do that you should get an idea of what they are and were they are located. We can do this with a little TSQL
SELECT ScopeUrl FROM TVF_Perms_Site(‘[Site ID GUID’)
Before you can use this bit of TSQL you need 3 things, the target SQL server, the target database, and the Site ID. By using the URL of the site collection and this small bit of PowerShell you can get all 3.
Add-PSSnapin Microsoft.SharePoint.Powershell -EA 0 $site = Get-SPSite "http://www.sp.com" $siteId = $site.Id $server = $site.ContentDatabase.Server $dbName = $site.ContentDatabase.Name Write-Host "SQLServerName=$server DBName=$dbName ID=$siteId"
This TSQL tells us the number of uniquely secured items. If your query returns more than 10,000 rows you know you have a problem. For my demo I created a list named ListWithPermissions and added 4 items, the first 3 items I broke permissions and the 4th I left alone. I deleted item #3 and emptied it out of the recycle bin which moved it into the second level recycle bin, I then deleted item #2 and left it in the recycle bin. I then went back and modified the permissions on item #1 from what was copied from the parent permissions. As you can see from the image below we have a few things we can take away from this little demo:
- Items in the recycle bin count toward our unique permission count.
- Items in the 2nd level recycle bin count toward our unique permission count.
- Items were the only thing we did was break permissions and copy from the parent show as unique permissions.
- Items were we do not make any permission modification (item #4) do not appear in this list.
So even though my list only has two visible items with only one having unique permissions it is in fact hosting 3 uniquely permissioned items which count toward a hard coded limit of 10,000.
How you decide to fix this issue is entirely up to you but I would point out that if these types of lists are used for internal authoring or editor tracking workflow its important to understand that while the 10,000 item count might not get you the fact that any updates to these items will cause the site collection cache to be invalidated is reason enough to move them away from your content. To put it another way, if I were to edit an item in this list, a list mind you that authenticated users cannot see or use, I will effectively render my Page Output Cache invalid and cause every cached page in the Site Collection to re-render. So if you have these types of lists do not set “Check for Changes”.
As I mentioned earlier in this post the Publishing Module and ASP.Net’s Output Cache module work together to implement Page Output Caching for SharePoint. In most cases this works however there is one very important scenario which we need to discuss and that involves HTTP Cookies.
Lets suppose you set a page an an anonymous site to cache for 1 hour. Now normally you will see a debug cache statement such as:
<!– Rendered using cache profile:Public Internet (Purely Anonymous) at: 2012-01-31T06:20:30 –>
What you may notice however is the date/time stamp changes more frequently than every hour. We discussed one of the reasons this may happen – content changes when “Check for Changes” is enabled. But what if this is not selected – well that leaves us with the web application is restarting, hitting another server in the load balancer with a different time stamp, or HttpCache getting trimmed. Unless you are tweaking with the web.config, deploying solutions, or running IISReset it is unlikely the web application is restarting but you might want to verify. Also if you are using a load balancer without sticky sessions you may want to eliminate this as a possible reason. With x64 systems and without making an explicit Application Pool setting you will not likely see HttpCache being trimmed due to memory pressure (if you do you have other issues you need to address first).
One scenario which everyone needs to be aware when dealing with Page Output Caching is that if a page’s response contains a cookie in its cookie collection (Response.Cookies.Add()) ASP.Net’s Output Caching module will not cache the output. So this leaves us with a debug statement and ULS log entry from SharePoint which state the page output is cached but in fact it is not – in fact you can see this by looking at ASP.Net Applications –> Output Cache Entries count in Performance Monitor. As you navigate a SharePoint site and see the “Rendered using Cache Profile…” debug statement on pages on a freshly restarted site you should see this performance counter increase. If you do not then you are likely running into this issue.
Wictor Wilen and I were recently discussing an issue with Page Output caching not working with one of his client’s environments. A Fiddler trace showed the WSS_KeepSessionAuthenticated cookie was being sent on every page response and as previously mentioned if cookies are sent in the response then a page will not be served from page output caching. The SharePoint farm had MS11-100 installed and once Wictor removed that patch the cookies were no longer being sent in every request and Page Output caching started working again. At this time we are not clear on why a .Net fix would impact this behavior of resending this cookie which is sourced from the SharePoint HttpModule but we did want to get it out that this patch (MS11-100) will break Page Output caching.
So hopefully after you read this you take away a few tips to help troubleshoot SharePoint’s Page Output Caching as well as understand its not a set and forget it feature of SharePoint – in fact I cannot think of very many that are.