Fun with code profiling

Pascal Hakim

Pascal is the Online Director at IDG Australia. With his team, he makes sure that the servers, code and ads that you can see on this page are all doing what they are supposed to. So please let him know if things are broken.

I am always amazed at how rarely people actually profile their code. You can get some amazing insights into what's happening in your code with some simple profiling tools. Caleb and I have been looking at getting better performance out of our sites lately, which has involved spending a bit of time looking at profiling data.

We normally use the Advanced PHP Debugger (APD), which we engage with a simple bit of code.

if ($_SERVER['REMOTE_ADDR'] == 'x.x.x.x' && isset($_GET['profiling'])) {
  ini_set("apd.statement_tracing", 1);

Using it is pretty easy. If you want to know what's going on, just add a profiling argument to the request and profiling data gets added to a file in /var/log/php5-apd.

You can convert this file into a file which kcachegrind can read using a tool called pprof2calltree which is included in the APD package.

Once you've done those steps, you can start playing around with your profiling data in kcachegrind. I find the columns which show how long a function ran for in total and the number of times it was called very useful, but I spend most of my time playing with the call graph.

While having my coffee this morning, I noticed this:

What's that? The memcacheCache->connect is being called 81 times? That can't be right. We shouldn't need anywhere near that many connections.

I looked a bit further up the graph and noticed:

As you can see on that graph, the CacheRouter->__init function is being called everytime the CacheRouter->get function is being run. Well, isn't that interesting?

I showed this to Caleb who found the problem soon after. CacheRouter was saving its status into a local variable $map instead of using $this->map to save it into the class variable.

Patch now available at:

Things looked much better afterwards:

As you can see, we're only calling it 4 times now, and execution times have gone from 14,097 ticks to just 666...

Twitter Feed

Featured Whitepapers