Nick's Hotaru CMS Blog

I recently blogged about my concerns over Hotaru's loading speed, but before I attempt Jon's suggestions of using Expires Headers and gzip, I thought I'd run some tests to see exactly what is consuming those valuable microseconds.

The first thing to note is the total time:

22 Jan 2010 12:52:22: INDEX TEMPLATE START - 1264132342.8745
22 Jan 2010 12:52:23: INDEX TEMPLATE END - 1264132343.9985

It took about 1.12 seconds which is well over my desired time of around 0.5 seconds. I know even 1.12 seconds sounds reasonable, but this test was done on my own computer using WampServer, so it's quicker than what you see on the demo site.

Let's get into the nitty-gritty. The full output is too long to post here, but here's an excerpt. Can you spot which plugins are eating up the time?

22 Jan 2010 12:52:22: INDEX TEMPLATE START - 1264132342.8745
22 Jan 2010 12:52:22: 1264132342.8762 pluginHook: theme_index_top (sb_base)
22 Jan 2010 12:52:22: 1264132342.8857 pluginHook: sb_base_theme_index_top (search)
22 Jan 2010 12:52:22: 1264132342.8882 pluginHook: sb_base_theme_index_top (tags)
22 Jan 2010 12:52:22: 1264132342.8904 pluginHook: sb_base_theme_index_top (media_select)
22 Jan 2010 12:52:22: 1264132342.8928 pluginHook: sb_base_theme_index_top (categories)
22 Jan 2010 12:52:22: 1264132342.8993 pluginHook: sb_base_functions_preparelist (search)
22 Jan 2010 12:52:22: 1264132342.9001 pluginHook: sb_base_functions_preparelist (tags)
22 Jan 2010 12:52:22: 1264132342.9008 pluginHook: sb_base_functions_preparelist (media_select)
22 Jan 2010 12:52:22: 1264132342.9016 pluginHook: sb_base_functions_preparelist (users)
22 Jan 2010 12:52:22: 1264132342.9051 pluginHook: sb_base_functions_preparelist (categories)
22 Jan 2010 12:52:22: 1264132342.9988 pluginHook: theme_index_top (submit)
22 Jan 2010 12:52:23: 1264132342.9995 pluginHook: theme_index_top (submit_light)
22 Jan 2010 12:52:23: 1264132343.0075 pluginHook: theme_index_top (vote)
22 Jan 2010 12:52:23: 1264132343.0108 pluginHook: theme_index_top (widgets)
22 Jan 2010 12:52:23: 1264132343.0247 pluginHook: theme_index_top (tweet_this)
22 Jan 2010 12:52:23: 1264132343.0272 pluginHook: theme_index_top (activity)
22 Jan 2010 12:52:23: 1264132343.0313 pluginHook: theme_index_top (video_inc)
22 Jan 2010 12:52:23: 1264132343.0333 pluginHook: theme_index_top (comments)
22 Jan 2010 12:52:23: 1264132343.042 pluginHook: theme_index_top (rpx)
22 Jan 2010 12:52:23: 1264132343.0462 pluginHook: theme_index_top (user_signin)
22 Jan 2010 12:52:23: 1264132343.0511 pluginHook: theme_index_top (users)

It's not obvious, but the second Categories function takes very close to 0.1 seconds. Of the 300+ lines of total output, if we can isolate other functions that take 0.1 seconds, then we've got a full second right there! Let's keep looking...

The header_include hook takes a combined 0.15 seconds, but that's not bad for 36 iterations so we'll leave that...

Ah! Here again, we've got Categories eating up another 0.08 seconds:

22 Jan 2010 12:52:23: 1264132343.2432 pluginHook: header_end (categories)
22 Jan 2010 12:52:23: 1264132343.3253 pluginHook: category_bar_end (media_select)

So that's 0.18 seconds already for just two iterations of Categories....

... and that's it. The rest seems to just be the result of over 300 pluginHook calls for my sample index page. One interesting observation though is that the avatar hooks are getting triggered 54 times out of the total 301. Looking at them closely, each one takes about 0.002 seconds, so that would total about 0.1 seconds.

Hmm... so if we disabled Categories and Gravatar, we should save nearly 0.3 seconds. Obviously we don't want to do that, but just for fun let's see what the total would be...

As expected, the number of pluginHook calls is cut to under 250, and the total time is 0.84 seconds:

22 Jan 2010 13:19:00: INDEX TEMPLATE START - 1264133940.0368
22 Jan 2010 13:19:00: INDEX TEMPLATE END - 1264133940.8732

So by disabling those two plugins, we've shaved 25% off the load time. The next challenge will be to speed up the Categories plugin so we can keep it. It must be getting caught up in its recursive functions that look for sub categories. Hmm... perhaps that can be cached...

AFTER LUNCH...

Now this is very interesting. I've just noticed that even though I disabled categories, it was still showing up in the log:

22 Jan 2010 13:45:44: 1264135544.7432 pluginHook: sb_base_theme_index_top (media_select)
22 Jan 2010 13:45:44: 1264135544.7456 pluginHook: sb_base_theme_index_top (categories)
22 Jan 2010 13:45:44: 1264135544.7538 pluginHook: sb_base_functions_preparelist (search)
22 Jan 2010 13:45:44: 1264135544.7547 pluginHook: sb_base_functions_preparelist (tags)
22 Jan 2010 13:45:44: 1264135544.7554 pluginHook: sb_base_functions_preparelist (media_select)
22 Jan 2010 13:45:44: 1264135544.7561 pluginHook: sb_base_functions_preparelist (users)
22 Jan 2010 13:45:44: 1264135544.7587 pluginHook: sb_base_functions_preparelist (categories)
22 Jan 2010 13:45:44: 1264135544.8612 pluginHook: theme_index_top (submit)

Looking at the pluginHook function, I can see that I'm writing to the log file just before skipping disabled plugins, so there's nothing out of the ordinary here... or is there? If the plugin is disabled, why is it still taking such a long time to ...erm... not run? Looking at the output above, we can see that Categories is the last plugin to be check at each hook. I wonder, if we move it up the plugin list, will the results change? Let's move it above Media Select and see...

22 Jan 2010 13:57:22: 1264136242.4893 pluginHook: sb_base_theme_index_top (tags)
22 Jan 2010 13:57:22: 1264136242.4916 pluginHook: sb_base_theme_index_top (categories)
22 Jan 2010 13:57:22: 1264136242.4916 pluginHook: sb_base_theme_index_top (media_select)
22 Jan 2010 13:57:22: 1264136242.5045 pluginHook: sb_base_functions_preparelist (search)
22 Jan 2010 13:57:22: 1264136242.5056 pluginHook: sb_base_functions_preparelist (tags)
22 Jan 2010 13:57:22: 1264136242.5063 pluginHook: sb_base_functions_preparelist (categories)
22 Jan 2010 13:57:22: 1264136242.5063 pluginHook: sb_base_functions_preparelist (media_select)
22 Jan 2010 13:57:22: 1264136242.507 pluginHook: sb_base_functions_preparelist (users)
22 Jan 2010 13:57:22: 1264136242.6088 pluginHook: theme_index_top (submit)

Bingo! That's more like it. The Categories plugin has been disabled so it takes no time at all, and now the Users plugin is last and appears to take 0.1 seconds to run, which we now know is not true! The most time consuming task must be happening somewhere between sb_base_functions_preparelist and theme_index_top.

That raises the question of why my earlier results shaved 0.3 seconds off the total time if Categories wasn't the problem? That, I don't yet know. Perhaps a caching thing...

Anyway, I will investigate this further and see if I can isolate the true cause of that 0.1 second delay!