Tracking the script execution time in PHP

Viewed 502128

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.

20 Answers

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.

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.

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

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

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/

$_SERVER['REQUEST_TIME']

check out that too. i.e.

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

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.

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

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

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.

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!

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.

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

Related