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 /

Moderators: martimiz, Sean, biapar, Willr, Ingo, swaiba

Testing Partial Caching - Notes


Go to End
Reply


5 Posts   1498 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, 5521 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