Joomla profiling log

I am using Joomla for the content management, and it looks like my site is getting slow, no, not just slow, it’s SLOW.

Quick check in the MySQL database showed that there is no really big tables which could cause some delays if not indexed properly or getting locked. So, next step would be naturally looking into the PHP code itself trying to identify bottlenecks.

First of all – copy everything to test site – I don’t really want to shut the site down or display some debug info to the visitors. My test site is actually a linux box which is pretty old one, so it probably will run slower comparing to production, but hopefully still allow me to find which areas of code are causing that.

Next step – tools. To profile PHP scripts I’ll use APD (http://pecl.php.net/package/apd). Best case scenario – you type
pecl install apd
in the shell to install package from PECL.
You may also need to add it to PHP configuration, I just created extra config file
/etc/php.d/apd.ini
with content
[apd]zend_extension="/usr/lib/php/modules/apd.so"
apd.dumpdir = /var/apd
apd.statement_tracing = 0

(make sure directory specified in dumpdir is created and writable for PHP)

Now we need to add
apd_set_pprof_trace();
at the beginning of the index.php script and open the page we want to profile, front page would be a good place to start.

In the dump directory a file created after each page opening, something like
/var/apd/pprof.08711.0

Let’s see what consumes resources now, by running
/usr/bin/pprofp -R /var/apd/pprof.08711.0

Oh, that hurts:

Total Elapsed Time = 23.58
Total System Time = 0.65
Total User Time = 7.18

Log in to Joomla admin, go to Extensions->Module Manager, delete all modules I do not really use, but which came pre-setup with Joomla.

Total Elapsed Time = 19.51
Total System Time = 0.24
Total User Time = 2.48

Ok, I am starting to see results already :)

Now let’s pay attention to the actual calls and time spent by script in functions.

14 seconds spent in JDocumentRendererModule->getFeed…
Hm… I do have a feed from my blog, now I wonder what the cache settings for that block is. So, in admin Module Manager -> mod_feed, advanced settings, cache : use global, time 60 minutes (I think I am ok with blog posts delayed for 1 hour, but it’s your call, just make sure it won’t come on every page load). That slashed a lot from the page load – over 15 sec of wasted time (note – check why blog feed is so slow, there should be some reasons!!!)

JDocumentHTML->_parseTemplate – I reviewed template and got rid of calls for modules which are not required or not used (like user1, user2, user3 areas which came with template and similar) – that saved 1-2 seconds per call.

At this point I have

Total Elapsed Time = 2.82
Total System Time = 0.21
Total User Time = 2.48

Which is way better, but still makes me wonder if it can run faster.

There are other options to play with
/usr/bin/pprofp -u /var/apd/pprof.09573.15
gives an idea what subroutines consumed most user time.

Last but not least: for the profiling purposes I turned off cache (Site->admin->global configuration). For life site it should be turned on with reasonable time to keep cached copy, that shaves off another 50% of execution time on subsequent calls of the same page.

Total Elapsed Time = 1.78
Total System Time = 0.17
Total User Time = 1.55

For now it’s as good as it gets on my old server, next thing to do would be profiling the script on the production server to see what it looks like there.

Another tip: if you profile a live site, restrict profiler calls to your own IP:
if($_SERVER['REMOTE_ADDR']== "xxx.xxx.xxx.xxx") {
apd_set_pprof_trace();
}

otherwise you may get buried in a number of trace logs.