It’s easy to make assumptions about what we think is the problem with the speed of our code. Lets say you have a loop like so:

foreach( $big_list_of_things as $thing ) {
	$res1 = somefunc1( $thing );
	$res2 = somefunc2( $thing );
	$res3 = somefunc3( $thing );
	$res4 = somefunc4( $thing );
}

Since its your code you’re pretty sure most all of the time me being spent inside somefunc2 and everything seems pretty fast except somefunc2 which is noticeably slow. Maybe you did something like this to get a kind of anecdotal feel for how long things are taking (I do this kind of thing a lot…)

foreach( $big_list_of_things as $thing ) {
	$res1 = somefunc1( $thing ); echo "1";
	$res2 = somefunc2( $thing ); echo "2";
	$res3 = somefunc3( $thing ); echo "3";
	$res4 = somefunc4( $thing ); echo "4 ";
}

So you even see some slowness on func2 — Solved! well… maybe… Just because func2 is obviously a problem doesn’t mean that there aren’t other problems going on in your code that you weren’t expecting. And it’s not a huge amount of work just to make sure, so we might as well, here I’ll show you how.

$big_list_of_things = range( 1, 100 );

function somefunc1() { usleep( mt_rand(0, 100) ); }
function somefunc2() { usleep( mt_rand(0, 30000) ); }
function somefunc3() { usleep( mt_rand(0, 14000) ); }
function somefunc4() { usleep( mt_rand(0, 150) ); }

$t1 = $t2 = $t3 = $t4 = 0;
foreach( $big_list_of_things as $thing ) {
        $s = microtime(1);  
        $res1 = somefunc1( $thing );
        $t1 += ( microtime(1) - $s ); 
        $s = microtime(1);
        $res2 = somefunc2( $thing );
        $t2 += ( microtime(1) - $s ); 
        $s = microtime(1);
        $res3 = somefunc3( $thing );
        $t3 += ( microtime(1) - $s ); 
        $s = microtime(1);
        $res4 = somefunc4( $thing );
        $t4 += ( microtime(1) - $s );
}
echo "1: $t1, 2: $t2, 3: $t3, 4: $t4
";

Gives me the following output… and oh look… 2 is a problem but maybe 3 needs to be looked into as well. Would I have known about how much time 3 was taking? probably not since it “seemed” so fast…

php ./test.php
1: 0.0077567100524902, 2: 1.4149680137634, 3: 0.70513272285461, 4: 0.013875484466553
php ./test.php
1: 0.0079605579376221, 2: 1.5631670951843, 3: 0.62554883956909, 4: 0.013876676559448
php ./test.php
1: 0.0080087184906006, 2: 1.4883117675781, 3: 0.66886830329895, 4: 0.013206481933594
php ./test.php
1: 0.0074846744537354, 2: 1.5641448497772, 3: 0.64763903617859, 4: 0.012674331665039

Just last night I found and fixed a bug that must have been there for ages that I had no idea about by exactly this method. And in case you were wondering whether or not it’s worth it… Trust me… Sometimes it is…