Tracking the script execution time in PHP

Question

PHP must track the amount of CPU time a particular script has used in order to enforce the max_execution_time limit.

Is there a way to get access to this inside of the script? I'd like to include some logging with my tests about how much CPU was burnt in the actual PHP (the time is not incremented when the script is sitting and waiting for the database).

I am using a Linux box.

Answer 1

If all you need is the wall-clock time, rather than the CPU execution time, then it is simple to calculate:

//place this before any script you want to calculate time
$time_start = microtime(true); 

//sample script
for($i=0; $i<1000; $i++){
 //do anything
}

$time_end = microtime(true);

//dividing with 60 will give the execution time in minutes otherwise seconds
$execution_time = ($time_end - $time_start)/60;

//execution time of the script
echo '<b>Total Execution Time:</b> '.$execution_time.' Mins';
// if you get weird results, use number_format((float) $execution_time, 10) 

Note that this will include the time that PHP is sat waiting for external resources such as disks or databases, which is not used for max_execution_time.

Answer 2

On unixoid systems (and in php 7+ on Windows as well), you can use getrusage, like:

// Script start
$rustart = getrusage();

// Code ...

// Script end
function rutime($ru, $rus, $index) {
    return ($ru["ru_$index.tv_sec"]*1000 + intval($ru["ru_$index.tv_usec"]/1000))
     -  ($rus["ru_$index.tv_sec"]*1000 + intval($rus["ru_$index.tv_usec"]/1000));
}

$ru = getrusage();
echo "This process used " . rutime($ru, $rustart, "utime") .
    " ms for its computations\n";
echo "It spent " . rutime($ru, $rustart, "stime") .
    " ms in system calls\n";

Note that you don't need to calculate a difference if you are spawning a php instance for every test.

Answer 3

Shorter version of talal7860's answer

<?php
// At start of script
$time_start = microtime(true); 

// Anywhere else in the script
echo 'Total execution time in seconds: ' . (microtime(true) - $time_start);

As pointed out, this is 'wallclock time' not 'cpu time'

Answer 4

<?php
// Randomize sleeping time
usleep(mt_rand(100, 10000));

// As of PHP 5.4.0, REQUEST_TIME_FLOAT is available in the $_SERVER superglobal array.
// It contains the timestamp of the start of the request with microsecond precision.
$time = microtime(true) - $_SERVER["REQUEST_TIME_FLOAT"];

echo "Did nothing in $time seconds\n";
?>

Answer 5

I created an ExecutionTime class out of phihag answer that you can use out of box:

class ExecutionTime
{
     private $startTime;
     private $endTime;

     public function start() {
         $this->startTime = getrusage();
     }

     public function end() {
         $this->endTime = getrusage();
     }

     private function runTime($ru, $rus, $index) {
         return ($ru["ru_$index.tv_sec"]*1000 + intval($ru["ru_$index.tv_usec"]/1000))
     -  ($rus["ru_$index.tv_sec"]*1000 + intval($rus["ru_$index.tv_usec"]/1000));
     }    

     public function __toString() {
         return "This process used " . $this->runTime($this->endTime, $this->startTime, "utime") .
        " ms for its computations\nIt spent " . $this->runTime($this->endTime, $this->startTime, "stime") .
        " ms in system calls\n";
     }
 }

Usage:

$executionTime = new ExecutionTime();
$executionTime->start();
// Code
$executionTime->end();
echo $executionTime;

Note: In PHP 5, the getrusage function only works in Unix-oid systems. Since PHP 7, it also works on Windows.

Answer 6

It is going to be prettier if you format the seconds output like:

echo "Process took ". number_format(microtime(true) - $start, 2). " seconds.";

will print

Process took 6.45 seconds.

This is much better than

Process took 6.4518549156189 seconds.

Answer 7

Gringod at developerfusion.com gives this good answer:

<!-- put this at the top of the page --> 
<?php 
   $mtime = microtime(); 
   $mtime = explode(" ",$mtime); 
   $mtime = $mtime[1] + $mtime[0]; 
   $starttime = $mtime; 
;?> 

<!-- put other code and html in here -->


<!-- put this code at the bottom of the page -->
<?php 
   $mtime = microtime(); 
   $mtime = explode(" ",$mtime); 
   $mtime = $mtime[1] + $mtime[0]; 
   $endtime = $mtime; 
   $totaltime = ($endtime - $starttime); 
   echo "This page was created in ".$totaltime." seconds"; 
;?>

From (http://www.developerfusion.com/code/2058/determine-execution-time-in-php/)

Answer 8

To show minutes and seconds you can use:

$startTime = microtime(true);
$endTime = microtime(true);
$diff = round($endTime - $startTime);
$minutes = floor($diff / 60); // Only minutes
$seconds = $diff % 60; // Remaining seconds, using modulo operator
echo "script execution time: minutes:$minutes, seconds:$seconds"; // Value in seconds

Answer 9

The cheapest and dirtiest way to do it is simply make microtime() calls at places in your code you want to benchmark. Do it right before and right after database queries and it's simple to remove those durations from the rest of your script execution time.

A hint: your PHP execution time is rarely going to be the thing that makes your script timeout. If a script times out it's almost always going to be a call to an external resource.

PHP microtime documentation: http://us.php.net/microtime

Answer 10

I think you should look at xdebug. The profiling options will give you a head start toward knowing many process related items.

http://www.xdebug.org/

Answer 11

$_SERVER['REQUEST_TIME']

check out that too. i.e.

...
// your codes running
...
echo (time() - $_SERVER['REQUEST_TIME']);

Answer 12

when there is closure functionality in PHP, why not we get benefit out of it.

function startTime(){
    $startTime = microtime(true);
    return function () use ($startTime){
        return microtime(true) - $startTime;
    };
}

Now with the help of the above function, we can track time like this

$stopTime = startTime();
//some code block or line
$elapsedTime = $stopTime();

Every call to startTime function will initiate a separate time tracker. So you can initiate as many as you want and can stop them wherever you want them.

Answer 13

Small script that print, centered in bottom of the page, the script execution that started at server call with microsecond precision.

So as not to distort the result and to be 100% compatible with content in page, I used, to write the result on the page, a browser-side native javascript snippet.

//Uncomment the line below to test with 2 seconds 
//usleep(2000000);

$prec = 5; // numbers after comma
$time = number_format(microtime(true) - $_SERVER['REQUEST_TIME_FLOAT'], $prec, '.', '');
echo "<script>
    if(!tI) { 
        var tI=document.createElement('div');
        tI.style.fontSize='8px';
        tI.style.marginBottom='5px';
        tI.style.position='absolute';
        tI.style.bottom='0px';
        tI.style.textAlign='center';
        tI.style.width='98%';
        document.body.appendChild(tI);
    }
    tI.innerHTML='$time';
</script>";

Another approach is to make the snippet as small as possible, and style it with a class in your stylesheet.

1. Replace the echo ...; part with the following:

   echo "<script>if(!tI){var tI=document.createElement('div');tI.className='ldtme';document.body.appendChild(tI);}tI.innerHTML='$time';</script>";

2. In your CSS create and fill the .ldtme{...} class.

Answer 14

I wrote a function that check remaining execution time.

Warning: Execution time counting is different on Windows and on Linux platform.

/**
 * Check if more that `$miliseconds` ms remains
 * to error `PHP Fatal error:  Maximum execution time exceeded`
 * 
 * @param int $miliseconds
 * @return bool
 */
function isRemainingMaxExecutionTimeBiggerThan($miliseconds = 5000) {
    $max_execution_time = ini_get('max_execution_time');
    if ($max_execution_time === 0) {
        // No script time limitation
        return true;
    }
    if (strtoupper(substr(PHP_OS, 0, 3)) === 'WIN') {
        // On Windows: The real time is measured.
        $spendMiliseconds = (microtime(true) - $_SERVER["REQUEST_TIME_FLOAT"]) * 1000;
    } else {
        // On Linux: Any time spent on activity that happens outside the execution
        //           of the script such as system calls using system(), stream operations
        //           database queries, etc. is not included.
        //           @see http://php.net/manual/en/function.set-time-limit.php
        $resourceUsages = getrusage();
        $spendMiliseconds = $resourceUsages['ru_utime.tv_sec'] * 1000 + $resourceUsages['ru_utime.tv_usec'] / 1000;
    }
    $remainingMiliseconds = $max_execution_time * 1000 - $spendMiliseconds;
    return ($remainingMiliseconds >= $miliseconds);
}

Using:

while (true) {
    // so something

    if (!isRemainingMaxExecutionTimeBiggerThan(5000)) {
        // Time to die.
        // Safely close DB and done the iteration.
    }
}

Answer 15

Further expanding on Hamid's answer, I wrote a helper class that can be started and stopped repeatedly (for profiling inside a loop).

class ExecutionTime
{
    private $startTime;
    private $endTime;
    private $compTime = 0;
    private $sysTime = 0;

    public function Start() {
        $this->startTime = getrusage();
    }

    public function End() {
        $this->endTime = getrusage();
        $this->compTime += $this->runTime($this->endTime, $this->startTime, "utime");
        $this->sysTime += $this->runTime($this->endTime, $this->startTime, "stime");
    }

    private function runTime($ru, $rus, $index) {
        return ($ru["ru_$index.tv_sec"]*1000 + intval($ru["ru_$index.tv_usec"]/1000)) -  ($rus["ru_$index.tv_sec"]*1000 + intval($rus["ru_$index.tv_usec"]/1000));
    }

    public function __toString() {
        return "This process used " . $this->compTime . " ms for its computations\n" . "It spent " . $this->sysTime . " ms in system calls\n";
    }
}

Answer 16

You may only want to know the execution time of parts of your script. The most flexible way to time parts or an entire script is to create 3 simple functions (procedural code given here but you could turn it into a class by putting class timer{} around it and making a couple of tweaks). This code works, just copy and paste and run:

$tstart = 0;
$tend = 0;

function timer_starts()
{
global $tstart;

$tstart=microtime(true); ;

}

function timer_ends()
{
global $tend;

$tend=microtime(true); ;

}

function timer_calc()
{
global $tstart,$tend;

return (round($tend - $tstart,2));
}

timer_starts();
file_get_contents('http://google.com');
timer_ends();
print('It took '.timer_calc().' seconds to retrieve the google page');

Answer 17

Just to contribute to this conversation:

• what happens if the measurement targets two points A and B in different php files?

• what if we need different measurements like time based, code execution duration, external resource access duration?

• what if we need to organize our measurements in categories where every one has a different starting point?

As you suspect we need some global variables to be accessed by a class object or a static method: I choose the 2nd approach and here it is:

namespace g3;

class Utils {
   public function __construct() {}

   public static $UtilsDtStart = [];
   public static $UtilsDtStats = [];

   public static function dt() {
      global $UtilsDtStart, $UtilsDtStats;
      $obj = new \stdClass();
      $obj->start = function(int $ndx = 0) use (&$UtilsDtStart) {
         $UtilsDtStart[$ndx] = \microtime(true) * 1000;
      };
      $obj->codeStart = function(int $ndx = 0) use (&$UtilsDtStart) {
         $use = \getrusage();
         $UtilsDtStart[$ndx] = ($use["ru_utime.tv_sec"] * 1000) + ($use["ru_utime.tv_usec"] / 1000);
      };
      $obj->resourceStart = function(int $ndx = 0) use (&$UtilsDtStart) {
         $use = \getrusage();
         $UtilsDtStart[$ndx] = $use["ru_stime.tv_usec"] / 1000;
      };
      $obj->end = function(int $ndx = 0) use (&$UtilsDtStart, &$UtilsDtStats) {
         $t = @$UtilsDtStart[$ndx];
         if($t === null)
            return false;
         $end = \microtime(true) * 1000;
         $dt = $end - $t;
         $UtilsDtStats[$ndx][] = $dt;
         return $dt;
      };
      $obj->codeEnd = function(int $ndx = 0) use (&$UtilsDtStart, &$UtilsDtStats) {
         $t = @$UtilsDtStart[$ndx];
         if($t === null)
            return false;
         $use = \getrusage();
         $dt = ($use["ru_utime.tv_sec"] * 1000) + ($use["ru_utime.tv_usec"] / 1000) - $t;
         $UtilsDtStats[$ndx][] = $dt;
         return $dt;
      };
      $obj->resourceEnd = function(int $ndx = 0) use (&$UtilsDtStart, &$UtilsDtStats) {
         $t = @$UtilsDtStart[$ndx];
         if($t === null)
            return false;
         $use = \getrusage();
         $dt = ($use["ru_stime.tv_usec"] / 1000) - $t;
         $UtilsDtStats[$ndx][] = $dt;
         return $dt;
      };
      $obj->stats = function(int $ndx = 0) use (&$UtilsDtStats) {
         $s = @$UtilsDtStats[$ndx];
         if($s !== null)
            $s = \array_slice($s, 0);
         else
            $s = false;
         return $s;
      };
      $obj->statsLength = function() use (&$UtilsDtStats) {
         return \count($UtilsDtStats);
      };
      return $obj;
   }
}

Now all you have is to call the method that belongs to the specific category with the index that denotes it's unique group:

File A
------
\call_user_func_array(\g3\Utils::dt()->start, [0]);   // point A
...
File B
------
$dt = \call_user_func_array(\g3\Utils::dt()->end, [0]);  // point B

Value $dt contains the milliseconds of wall clock duration between points A and B.

To estimate the time took for php code to run:

File A
------
\call_user_func_array(\g3\Utils::dt()->codeStart, [1]);   // point A
...
File B
------
$dt = \call_user_func_array(\g3\Utils::dt()->codeEnd, [1]);  // point B

Notice how we changed the index that we pass at the methods.

The code is based on the closure effect that happens when we return an object/function from a function (see that \g3\Utils::dt() repeated at the examples).

I tested with php unit and between different test methods at the same test file it behaves fine so far!

Hope that helps someone!

Answer 18

As an alternative you can just put this line in your code blocks and check php logs, for really slow functions it's pretty useful:

trigger_error("Task done at ". strftime('%H:%m:%S', time()), E_USER_NOTICE); 

For serious debugging use XDebug + Cachegrind, see https://blog.nexcess.net/2011/01/29/diagnosing-slow-php-execution-with-xdebug-and-kcachegrind/

Answer 19

There are several way of doing this, listed here. But each have their own pro's and con's. And (in my opinion) the readability of all longer answers are terrible.

So I decided to put it all together in one answer, that is easily usable and readable.

Usage

$start = get_timers();
for( $i = 0; $i < 100000; $i++ ){
  // Code to check
}
$end = get_timers();
display_timer_statistics( $start, $end );

Function definitions

function display_timer_statistics( $start_timers, $end_timers ){

    // Settings
    $key_width = '100px';
    $decimals = 4;
    $decimals_wallclock = $decimals;
    $decimals_request_time_float = $decimals;

    // Variables
    $start_resource_usage_timer = $start_timers[0];
    $start_wallclock = $start_timers[1];
    $end_resource_usage_timer = $end_timers[0];
    $end_wallclock = $end_timers[1];

    // # User time
    // Add seconds and microseconds for the start/end, and subtract from another
    $end_user_time_seconds = $end_resource_usage_timer["ru_utime.tv_sec"]*1000;
    $end_user_time_microseconds = intval($end_resource_usage_timer["ru_utime.tv_usec"]/1000);
    $start_user_time_seconds = $start_resource_usage_timer["ru_utime.tv_sec"]*1000;
    $start_user_time_microseconds = intval($start_resource_usage_timer["ru_utime.tv_usec"]/1000);
    $total_user_time = ($end_user_time_seconds + $end_user_time_microseconds) - ($start_user_time_seconds + $start_user_time_microseconds);

    // # System time
    // Add seconds and microseconds for the start/end, and subtract from another
    $end_system_time_seconds = $end_resource_usage_timer["ru_stime.tv_sec"]*1000;
    $end_system_time_microseconds = intval($end_resource_usage_timer["ru_stime.tv_usec"]/1000);
    $start_system_time_seconds = $start_resource_usage_timer["ru_stime.tv_sec"]*1000;
    $start_system_time_microseconds = intval($start_resource_usage_timer["ru_stime.tv_usec"]/1000);
    $total_system_time = ($end_system_time_seconds + $end_system_time_microseconds) - ($start_system_time_seconds + $start_system_time_microseconds);

    // Wallclock
    $total_wallclock_time = number_format( ( $end_wallclock - $start_wallclock), $decimals_wallclock );

    // Server request_time_float
    $request_time_float = microtime(true) - $_SERVER["REQUEST_TIME_FLOAT"];
    $request_time_float = number_format( $request_time_float, $decimals_request_time_float );

    // Print
    $span_start = "<span style='width: $key_width; display: inline-block;'>";
    $span_end = "</span>";

    $output = "# RUNTIME AND TIMERS " . PHP_EOL ;
    $output .= PHP_EOL;
    $output .= $span_start . $total_user_time . $span_end . " User time (utime)" . PHP_EOL;
    $output .= $span_start . $total_system_time . $span_end . " System time (stime)" . PHP_EOL;
    $output .= PHP_EOL;
    $output .= $span_start . $total_wallclock_time . $span_end . " Wallclock" . PHP_EOL;
    $output .= PHP_EOL;
    $output .= $span_start . $request_time_float . $span_end . " REQUEST_TIME_FLOAT" . PHP_EOL . PHP_EOL . PHP_EOL;

    echo nl2br( $output );
}

function get_timers(){
    return [ getrusage(), microtime( true ) ];
}

Glossary

All gotten from PHP docs for getrusage

• Wallclock = How long it takes
• ru = Resource usage
• utime = User time used
• stime = System time used
• tv_sec = In seconds.
• tv_usec = In microseconds.
• tv = ?? Dunno

Answer 20

One liner, uses $_SERVER\['REQUEST_TIME_FLOAT'\] and display a runtime timer formatted as HH:MM:SS

   echo "Runtime ".explode(" ", date("H:i:s", (round(microtime(true) - $_SERVER['REQUEST_TIME_FLOAT']) % 60)))[0]."s\n";
   // Runtime 00:00:19s

Your task would have to complete in less than 99 hours and 59 minutes, of course.

Answer 21

return microtime(true) - $_SERVER["REQUEST_TIME_FLOAT"];