Skip to main content

This site requires you to update your browser. Your browsing experience maybe affected by not having the most up to date version.

Template Questions /

Testing Partial Caching - Notes


Reply


5 Posts   1197 Views

Avatar
elgordo

Community Member, 70 Posts

26 April 2011 at 7:39pm

Edited: 26/04/2011 7:45pm

hi

There does not seem to be a huge amount of information out there regarding partial caching so here are a few notes from my experiences.

1) You can manually delete the cache manually from disk by deleting the contents of /tmp/silverstripe-name-of-install-path/cache

2) debug_profile is your friend. This shows the the length of time a method takes and how often it was called, those with high values are often a good candidate for partial caching.

As an example let us consider a template for a sitemap, which has to iterate through the entire site tree in order to form the sitemap.

Without caching the debug profile shows this:

============================================================================
PROFILER OUTPUT
============================================================================
Calls Time Routine
-----------------------------------------------------------------------------
1 525.6441 ms (73.30 %) obj.SiteMap
1 132.5247 ms (18.48 %) all_execution
2 28.6548 ms (4.00 %) SSViewer::process
1 6.3190 ms (0.88 %) obj.Menu
2 5.7511 ms (0.80 %) obj.LastEdited
1 2.8870 ms (0.40 %) obj.Content
1 2.8121 ms (0.39 %) obj.Title
2 2.3530 ms (0.33 %) obj.TheCurrentLocale
1 2.3081 ms (0.32 %) SSViewer::process - compile
3 1.3778 ms (0.19 %) obj.Aggregate
1 0.9809 ms (0.14 %) DB::connect
1 0.7699 ms (0.11 %) main.php init
2 0.4091 ms (0.06 %) obj.ID
2 0.3302 ms (0.05 %) obj.ContentLocale
1 0.3102 ms (0.04 %) obj.Level
1 0.3080 ms (0.04 %) obj.Form
3 0.3011 ms (0.04 %) obj.IsLive
1 0.2770 ms (0.04 %) obj.isImageItem
1 0.2739 ms (0.04 %) obj.SectionPage
1 0.1020 ms (0.01 %) obj.Layout
2 0.0880 ms (0.01 %) Requirements::includeInHTML
1 0.0250 ms (0.00 %) unprofiled

2.3386 ms (0.33 %) Missed
============================================================================
717.1459 ms (100.00 %) OVERALL TIME
============================================================================

With caching, it is a different story:

============================================================================
PROFILER OUTPUT
============================================================================
Calls Time Routine
-----------------------------------------------------------------------------
1 139.0479 ms (75.54 %) all_execution
2 21.5411 ms (11.70 %) SSViewer::process
1 9.3021 ms (5.05 %) obj.Menu
2 3.9222 ms (2.13 %) obj.LastEdited
2 2.2361 ms (1.21 %) obj.TheCurrentLocale
3 1.5733 ms (0.85 %) obj.Aggregate
1 0.9320 ms (0.51 %) DB::connect
1 0.7181 ms (0.39 %) main.php init
1 0.5250 ms (0.29 %) obj.Form
1 0.4790 ms (0.26 %) obj.SectionPage
2 0.4361 ms (0.24 %) obj.ContentLocale
2 0.4070 ms (0.22 %) obj.ID
1 0.3579 ms (0.19 %) obj.Level
3 0.3407 ms (0.19 %) obj.IsLive
1 0.3231 ms (0.18 %) obj.isImageItem
1 0.1051 ms (0.06 %) obj.Layout
2 0.0911 ms (0.05 %) Requirements::includeInHTML
1 0.0269 ms (0.01 %) unprofiled

1.6961 ms (0.92 %) Missed
============================================================================
184.0608 ms (100.00 %) OVERALL TIME
============================================================================

You can see here that the caching has ensured that the Site Tree was not traversed in the database, saving half a second.

Incidentally the template used was

<% cached 'Sitemap', Aggregate(Page).Max(LastEdited) %>

<h1 class="head">$Title</h1>
<span class="txt">
$Content
<div id="sitemap">
$SiteMap
</div>

</span><!--/txt-->

<% end_cached %>

$Form

Each time a page is saved, the sitemap cache is invalidated. Thus the sitemap is always rendered up to date, but if no editing is occurring then a cached version will be served.

3) Make sure your cache key contains all the input parameters. For example I initially cached a search result page by query, but then page 1, page 2 etc are the same.

4) Don't put $Form inside a cached/end_cached construct. i did this with the Page class template and then could not log in.

Cheers

Gordon

Avatar
elgordo

Community Member, 70 Posts

26 April 2011 at 7:42pm

A second example showing trace from the menu:

Uncached:

============================================================================
PROFILER OUTPUT
============================================================================
Calls Time Routine
-----------------------------------------------------------------------------
1 165.3121 ms (32.25 %) all_execution
2 132.0100 ms (25.75 %) SSViewer::process
15 79.0133 ms (15.41 %) obj.Children
35 68.0511 ms (13.28 %) obj.Link
3 20.8154 ms (4.06 %) obj.Menu
1 11.0559 ms (2.16 %) obj.PagesWithAccessKeys
35 7.7891 ms (1.52 %) obj.Title
3 5.4679 ms (1.07 %) obj.LastEdited
14 4.2307 ms (0.83 %) obj.LinkOrSection
5 2.1892 ms (0.43 %) obj.LinkingMode
2 1.9109 ms (0.37 %) obj.AccessKey
1 1.8830 ms (0.37 %) obj.PageMenuCacheKey
2 1.5960 ms (0.31 %) obj.Aggregate
1 0.8261 ms (0.16 %) DB::connect
1 0.7491 ms (0.15 %) main.php init
2 0.4711 ms (0.09 %) obj.ID
2 0.3660 ms (0.07 %) obj.TheCurrentLocale
1 0.3340 ms (0.07 %) obj.Level
1 0.3121 ms (0.06 %) obj.SectionPage
2 0.2999 ms (0.06 %) obj.ContentLocale
1 0.2980 ms (0.06 %) obj.Form
3 0.2520 ms (0.05 %) obj.IsLive
1 0.1280 ms (0.02 %) obj.Layout
2 0.0679 ms (0.01 %) Requirements::includeInHTML
1 0.0331 ms (0.01 %) unprofiled

7.1390 ms (1.39 %) Missed
============================================================================
512.6011 ms (100.00 %) OVERALL TIME
============================================================================

Cached:

============================================================================
PROFILER OUTPUT
============================================================================
Calls Time Routine
-----------------------------------------------------------------------------
1 138.5639 ms (76.44 %) all_execution
2 17.5796 ms (9.70 %) SSViewer::process
1 10.1490 ms (5.60 %) obj.Menu
3 4.1497 ms (2.29 %) obj.LastEdited
1 1.9250 ms (1.06 %) obj.PageMenuCacheKey
2 1.4620 ms (0.81 %) obj.Aggregate
1 1.1699 ms (0.65 %) DB::connect
1 0.7579 ms (0.42 %) main.php init
2 0.5391 ms (0.30 %) obj.ContentLocale
2 0.3932 ms (0.22 %) obj.ID
3 0.3729 ms (0.21 %) obj.IsLive
2 0.3190 ms (0.18 %) obj.TheCurrentLocale
1 0.3111 ms (0.17 %) obj.Form
1 0.2971 ms (0.16 %) obj.SectionPage
1 0.2940 ms (0.16 %) obj.Level
1 0.1400 ms (0.08 %) obj.Layout
2 0.0780 ms (0.04 %) Requirements::includeInHTML
1 0.0279 ms (0.02 %) unprofiled

2.7518 ms (1.52 %) Missed
============================================================================
181.2809 ms (100.00 %) OVERALL TIME
============================================================================

It should be immediately obvious that the number of calls to Link and Title are dramatically reduced, as the menu is cached as a partial

Avatar
Willr

Forum Moderator, 5513 Posts

26 April 2011 at 8:23pm

Hi Gordon,

Glad you found the partial caching functionality useful! For the forms there is an <% uncached %> tag you can use (so you can still cache the remainder) which I'm sure you found, just posting that in case anyone was wondering.

http://doc.silverstripe.org/sapphire/en/reference/partial-caching has quite a bit of documentation on it and examples.

It's all still pretty new so quite a few of the modules don't yet use partial caching but hopefully seeing those <% cached %> calls will be fairly standard pretty soon!

Debug_profile is useful, however there has been discussion whether to remove it. Tools like XHProf and xdebug profile much more accurate data and generally more sophisticated data reporting. Debug_profile won't be 100% accurate or will leave chucks unprofiled in bigger apps.

Avatar
elgordo

Community Member, 70 Posts

26 April 2011 at 8:34pm

Edited: 26/04/2011 8:35pm

hi Will

i did not now about the uncached tag, guess I am new to Silverstripe partial caching also :) I've used it in Rails many times, it is good to see the functionality in Silverstripe. Pages definitely feel 'snappier' now on the site I am working on.

Regarding documentation I think I was slightly confused by

<% cached 'loginblock', LastEdited, CurrentMember.isAdmin %>

I initially thought that that CurrentMember.isAdmin was a boolean conditional and that toggled whether or not the caching happened, but see now that is it just simply chaining a list of parameters together to make the cache key.

And thanks for the heads up regarding debug_profile - even if not 100% accurate it is useful in ascertaining whether or not partial caching is actually happening. I'll look into the other tools you mentioned when I get some time

Regards

Gordon

Avatar
elgordo

Community Member, 70 Posts

26 April 2011 at 8:36pm

hi Will

One other useful thing would be the ability to optionally log the cache keys being generated - e.g. by setting a condition in mysite/_config.php

Cheers

Gordon