Sr. Web Developer
mediabistro.com
US-NY-New York

Justtechjobs.com Post A Job | Post A Resume

Timing Script Execution
Allan Kent picture of A. Kent
Timing Script Execution
No doubt you've all seen on Google's search page where it tells you how long your search took to complete. This, and some talk I noticed a while back in one of the forums about some of the scripts that were taking a while to execute made me think about how you would go about timing your scripts.
The easiest way of timing a script would be to get the time at the beginning of the script and then get the time at the end of the script. The difference between the two is the time it took your script to run. PHP has a function time() which returns the number of seconds since 1970. Now I can't speak for everyone here, but typically the scripts that I write tend to finish running within a second. So measuring the time in seconds is not really going to help me. A topical example would be using something like an egg timer to time the 100m Olympic final - unless someone breaks both their legs on the starting blocks, all the runners will be within 1 egg timer. The microtime() function gives us what we need - the fractional part of the second at the time that the function was called. It also gives us the number of seconds since 1970 like time() does, so we don't need to call both functions. The only problem with the microtime() function is that it returns to us a string with 2 numbers in it - the seconds part, and the fractional part - separated by a space.
<?php

  echo microtime();

?>
Returns:
0.13554500 968578758
This is not all that useful to us when trying to work out differences, so what we need to do is drop the 0 from the front of the fractional part and tack the rest onto the end of the seconds part:

<?php

  $timeparts = explode(' ',microtime());
  $thetime = $timeparts[1].substr($timeparts[0],1);

?>
Both the explode() and substr() functions are well documented in the manual and have been dealt with on numerous occasions on this site, so I'm not going to waste time going through them here again.
Once we have 2 times (a start and finish) we can subtract the start time from the finish time and we'll have the difference. If you use the bcsub() function, remember to indicate to the function how many places after the decimal point you want to preserve. If you don't, then it'll default to integers and you'll be back in the egg timer scenario again.

<?php

  $timeparts = explode(' ',microtime());
  $starttime = $timeparts[1].substr($timeparts[0],1);
  $timeparts = explode(' ',microtime());
  $endtime = $timeparts[1].substr($timeparts[0],1);
  echo bcsub($endtime,$starttime,6)

?>
returns to us
0.000457
You can now pop that code in amongst your script to debug what's taking so long in your script.

Getting Clever
The problem with the previous script is that what happens when you want to find exactly which part of your script is taking all the time? You have to move the start time and end time bits around all over the script and write down the results, comparing notes and invariably losing half the little bits of paper you wrote them down on. What if we want to create markers all the way through our script and see the time it takes between each marker? Sounds like a lot code to add into our scripts, so what I did instead was create a timer object, which we could use to time our scripts.
The timer object
Our object will only need one property - an array of the times that we have marked parts of the script. I also added in a descriptor for the time. Our object will have to have a number of methods - a method to start the timer, a method to stop the timer and a method to add markers for any points in between. We will also need a method to display the information that we have collected. Because I found that a lot the code was being duplicated, I created a function to join the times together.
Here then is the code for the include file phptimer.inc. I've added comments through the code as explanation, but if you are happy with arrays and understand a bit of OO programming, you should have no worries:

<?php

// begin class PHP_timer
class PHP_timer {

    // array to store the information that we collect during the script
    // this array will be manipulated by the functions within our object
    var $points = array();
    
    // call this function at the beginning of the script
    function start() {
        // see the addmarker() function later on
        $this->addmarker("Start");
    }
    // end function start()

    // call this function at the end of the script
    function stop() {
        // see the addmarker() function later on
        $this->addmarker('Stop');
    }
    // end function stop()

    // this function is called to add a marker during the scripts execution
    // it requires a descriptive name
    function addmarker($name) {
        // call the jointime() function and pass it the output of the microtime() function
        //  as an argument
        $markertime = $this->jointime(microtime());
        // $ae (stands for Array Elements) will contain the number of elements
        // currently in the $points array
        $ae = count($this->points);
        // store the timestamp and the descriptive name in the array
        $this->points[$ae][0] = $markertime;
        $this->points[$ae][1] = $name;
    }
    // end function addmarker()

    // this function manipulates the string that we get back from the microtime() function
    function jointime($mtime) {
        // split up the output string from microtime() that has been passed
        // to the function
        $timeparts = explode(' ',$mtime);
        // concatenate the two bits together, dropping the leading 0 from the
        // fractional part
        $finaltime = $timeparts[1].substr($timeparts[0],1);
        // return the concatenated string
        return $finaltime;
    }
    // end function jointime()
    
    // this function simply give the difference in seconds betwen the start of the script and
    // the end of the script
    function showtime() {
        echo bcsub($this->points[count($this->points)-1][0],$this->points[0][0],6);
    }
    // end function showtime()
    
    // this function displays all of the information that was collected during the
    // course of the script
    function debug() {
        echo 'Script execution debug information:';
        echo "<table border="0" cellspacing="5" cellpadding="5">\n";
        // the format of our table will be 3 columns:
        // Marker name, Timestamp, difference
        echo "<tr><td><b>Marker</b></td><td><b>Time</b></td><td><b>Diff</b></td></tr>\n";
        // the first row will have no difference since it is the first timestamp
        echo "<tr>\n";
        echo '<td>'.$this->points[0][1].'</td>';
        echo '<td>'.$this->points[0][0].'</td>';
        echo "<td>-</td>\n";
        echo "</tr>\n";
        // our loop through the $points array must start at 1 rather than 0 because we have
        // already written out the first row
        for ($i = 1; $i < count($this->points);$i++) {
            echo "<tr>\n";
            echo '<td>'.$this->points[$i][1].'</td>';
            echo '<td>'.$this->points[$i][0].'</td>';
            echo '<td>';
            // write out the difference between this row and the previous row
            echo bcsub($this->points[$i][0],$this->points[$i-1][0],6);
            echo '</td>';
            echo "</tr>\n";
        }
        echo '</table>';
    }
    // end function debug()
}
// end class PHP_timer

?>

My PHP script to use this object now looks like this:

<?php

include ('phptimer.inc');
$timer = new PHP_timer;
$timer->start();
$timer->addmarker('marker 1');
$timer->stop();
$timer->debug();
$timer->showtime();

?>
and will return to me something like:
Script execution debug information:
MarkerTimeDiff
Start968594548.36899100-
here be marker 1968594548.369701000.000710
Stop968594548.370145000.000444
0.001154
Last Word
I've intended this script to be a quick and easy way for programmers to debug lock ups and timing problems in their scripts. Therefore I haven't included any error checking code. Also use a bit of common sense about where you put markers in your code - inside a loop that is iterating through a database is probably not a good idea. Once before and one after the loop would be a better idea.
I have started working on some ways of improving the debug information and output with graphs and being able to nest or group markers, but this should be a start on debugging your scripts.
-Allan