When Page Output Caching Does Not Output


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.

Troubleshooting

Tools

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:

String Tag
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 “<!– “

Using tinyget in this manner has a couple of advantages, the first being you can zero in on the debug statement, and the second is you don’t have to deal with any browser-isms as tinyget will not post any cookies, will not request any dependent requests such as style sheets, JavaScript, etc and will instead focus on and make a single page request with only the headers you supply. The downside to this tool is if you are trying to troubleshoot a problem with a specific caching profile you might not have the permissions or audience settings necessary to reproduce the issue so at this point you need to pick up your favorite fishing pole (I use ULSViewer) and cozy up to the ULS logs.

Common Issues

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

Reason Description
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 permission(ed) 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 permission(ed) 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:

  1. Items in the recycle bin count toward our unique permission count.
  2. Items in the 2nd level recycle bin count toward our unique permission count.
  3. Items were the only thing we did was break permissions and copy from the parent show as unique permissions.
  4. 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 permission(ed) 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’.

Other Issues

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.

The issue tends to occur when there is some customization such as a 3rd party web analytics and/or HttpModule which uses cookies to track user activity. When these modules write new or refresh cookies using the HttpResponse’s cookie collection the page output cache will not function. But what if you don’t have any such customization(s)? The SharePoint product team fixed an issue with its WSS_KeepSessionAuthenticated cookie in the SharePoint 2010 December 2010 CU. This cookie was being refreshed in such a way that caused the Page Output Caching to not work properly for authenticated sites. You may want to use Fiddler’s Inspector feature to see if you have any cookies being sent back in the response headers.

Update

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.

Conclusion

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.

10 thoughts on “When Page Output Caching Does Not Output

  1. HI. great post, thanks for sharing. You mention that you might have other issues if the output cache is clearing. We’re occasionally seeing both the object and output cache completely flush, and as far as we can tell the app pool is not resetting at this point. Any ideas on the possible causes.
    Also im still a bit unlcear from your post about when the output cache is flushed, are you saying a content change to one page can cause a flush of the entire cache, or are you saying it will simply flush that one page (which sounds the likely (intended) scenario).
    cheers

    Like

  2. By default if any content changes on the site, that is, you edit a list item, you edit a page (which is really a list item), you add a new image to an images library, etc – this will cause the output cache to flush for the entire site collection if you have "check for changes" selected. This occurs for object cache too — so for your scenario I suspect there is some content changing somewhere within your site collection. You may want to check the ContentLastModified date/timestamp and/or disable the "check for changes" option.

    Like

  3. Thanks for the quick reply. Think thats unlikely to be it, we’re a very large publishing site, with around 30 content editors generally publishing stuff all day, so we’d see far more issues. Interestingly we spotted a link to people trying to move objects in the sitemanager at the time of both caches being dropped, so maybe there’s something around the movement of sites and pages. Thanks

    Like

  4. Hi, very good article. Please help me understand, if 2 WFE servers, users connected to both servers, servers which maintains its own cache dose it flush every 3 mins(by default 180 sec), even when no one connects or it flush upon users activity after every 3 mins?, both the servers flush cache at the same time? Also, the other thing the TechNet article says there would be inconsistency when 2 WFE servers with load balancer, what are those inconsistency? any particular content can and can’t see? Thanks

    Like

  5. Good questions – The time period for expiry (180 seconds in your example) starts when the page is first cached, for multiple WFE servers this typically will be at different times therefore the expiry will occur at different times as well. ASP.Net has a background cache flush/trim thread which will remove expire cached items, so there is no traffic required for items to be removed from cache when they expire. I am not sure what TechNet article you are referring but the WFE should be consistent wrt the content being served, they will be inconsistent when it comes to what is cached and when each cached item will expire.

    Like

  6. Thanks for your reply. Correct me if am wrong, After 180 sec’s ASP.Net thread will flush the whole cached pages and download again from SQL server irrespective whether there is a change or no change in the page? if it is then, is it a delta download or full download? and how can we track? and the other thing i need your input to understand better. Will the clients after every 3 mins see some performance impact? will the time stamp in view source change every 3mins if I perform refresh or it continue to show the time we do a page refresh? Thanks

    Like

  7. Once the ASP.Net cache flush thread runs the next request for the cached page will result in a cache miss and SharePoint will rebuild the page as it would if caching were not enabled (there is no delta rebuild here). So if your page takes 3 seconds to render at least one client every 180 seconds will see a slow response. Your clients will only see a performance impact if the page is naturally slow – that is, if the page responds normally within a second I doubt they will notice when there is a cache miss. Once the page is rebuilt and put into cache a new timestamp is added (assuming you turned on the debug statement option). Remember the entire contents of the page is stored in cache and this includes the timestamp. There are ASP.Net performance counters which you can view to help you track what is going on at a very high level.

    Like

Comments are closed.