[php] Tracking the script execution time in PHP

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.

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->systemTime += $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->systemTime . " ms in system calls\n";
      }
   }

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');

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

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/

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'

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 time that PHP is sat waiting for external resources such as disks or databases, which is not used for max_execution_time.

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.
    }
}

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.

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.

<?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";
?>

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.

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/)

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!

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/

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.

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

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

$_SERVER['REQUEST_TIME']

check out that too. i.e.

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