3212 Posts in 847 Topics by 809 members
|
Page:
1
|
Go to End | |
| Author | Topic: | 715 Views |
-
Testing Partial Caching - Notes
26 April 2011 at 7:39pm Last edited: 26 April 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 %) unprofiled2.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 %) unprofiled1.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
-
Re: Testing Partial Caching - Notes
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 %) unprofiled7.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 %) unprofiled2.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
-
Re: Testing Partial Caching - Notes
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.
-
Re: Testing Partial Caching - Notes
26 April 2011 at 8:34pm Last edited: 26 April 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
-
Re: Testing Partial Caching - Notes
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
| 715 Views | ||
|
Page:
1
|
Go to Top |
