Refactor Profiler to get the actual and initial time:

* Added $metric parameter to Profiler::getTime() and
  Profiler::getInitialTime() so that the time calculating method can be
  easily overriden
* Added 'cpu' time metric (for ProfilerSimple)
* Made Profiler::getInitialTime() protected so that it can be used by
  ProfilerSimple and ProfilerSimpleTrace

Change-Id: I12d1bcb43ec179396a3f8ed46ba4128412e2f65b

diff --git a/includes/profiler/Profiler.php b/includes/profiler/Profiler.php
index f6d8b3a..f884063 100644 (file)
--- a/includes/profiler/Profiler.php
+++ b/includes/profiler/Profiler.php
@@ -272,28 +272,69 @@ class Profiler {
                return sprintf( "%10s %s %s\n", trim( sprintf( "%7.3f", $delta * 1000.0 ) ), $space, $fname );
        }
 
-       function getTime() {
-               if ( $this->mTimeMetric === 'user' ) {
-                       return $this->getUserTime();
+       /**
+        * Get the initial time of the request, based either on $wgRequestTime or
+        * $wgRUstart. Will return null if not able to find data.
+        *
+        * @param $metric string|false: metric to use, with the following possibilities:
+        *   - user: User CPU time (without system calls)
+        *   - cpu: Total CPU time (user and system calls)
+        *   - wall (or any other string): elapsed time
+        *   - false (default): will fall back to default metric
+        * @return float|null
+        */
+       function getTime( $metric = false ) {
+               if ( $metric === false ) {
+                       $metric = $this->mTimeMetric;
+               }
+
+               if ( $metric === 'cpu' || $this->mTimeMetric === 'user' ) {
+                       if ( !function_exists( 'getrusage' ) ) {
+                               return 0;
+                       }
+                       $ru = getrusage();
+                       $time = $ru['ru_utime.tv_sec'] + $ru['ru_utime.tv_usec'] / 1e6;
+                       if ( $metric === 'cpu' ) {
+                               # This is the time of system calls, added to the user time
+                               # it gives the total CPU time
+                               $time += $ru['ru_stime.tv_sec'] + $ru['ru_stime.tv_usec'] / 1e6;
+                       }
+                       return $time;
                } else {
                        return microtime( true );
                }
        }
 
-       function getUserTime() {
-               $ru = getrusage();
-               return $ru['ru_utime.tv_sec'] + $ru['ru_utime.tv_usec'] / 1e6;
-       }
-
-       private function getInitialTime() {
+       /**
+        * Get the initial time of the request, based either on $wgRequestTime or
+        * $wgRUstart. Will return null if not able to find data.
+        *
+        * @param $metric string|false: metric to use, with the following possibilities:
+        *   - user: User CPU time (without system calls)
+        *   - cpu: Total CPU time (user and system calls)
+        *   - wall (or any other string): elapsed time
+        *   - false (default): will fall back to default metric
+        * @return float|null
+        */
+       protected function getInitialTime( $metric = false ) {
                global $wgRequestTime, $wgRUstart;
 
-               if ( $this->mTimeMetric === 'user' ) {
-                       if ( count( $wgRUstart ) ) {
-                               return $wgRUstart['ru_utime.tv_sec'] + $wgRUstart['ru_utime.tv_usec'] / 1e6;
-                       } else {
+               if ( $metric === false ) {
+                       $metric = $this->mTimeMetric;
+               }
+
+               if ( $metric === 'cpu' || $this->mTimeMetric === 'user' ) {
+                       if ( !count( $wgRUstart ) ) {
                                return null;
                        }
+
+                       $time = $wgRUstart['ru_utime.tv_sec'] + $wgRUstart['ru_utime.tv_usec'] / 1e6;
+                       if ( $metric === 'cpu' ) {
+                               # This is the time of system calls, added to the user time
+                               # it gives the total CPU time
+                               $time += $wgRUstart['ru_stime.tv_sec'] + $wgRUstart['ru_stime.tv_usec'] / 1e6;
+                       }
+                       return $time;
                } else {
                        if ( empty( $wgRequestTime ) ) {
                                return null;

diff --git a/includes/profiler/ProfilerSimple.php b/includes/profiler/ProfilerSimple.php
index df37363..1091495 100644 (file)
--- a/includes/profiler/ProfilerSimple.php
+++ b/includes/profiler/ProfilerSimple.php
@@ -16,15 +16,14 @@ class ProfilerSimple extends Profiler {
        var $errorEntry;
 
        protected function addInitialStack() {
-               global $wgRequestTime, $wgRUstart;
-
                $this->errorEntry = $this->zeroEntry;
                $this->errorEntry['count'] = 1;
 
-               if ( !empty( $wgRequestTime ) && !empty( $wgRUstart ) ) {
-                       $initialCpu = $this->getCpuTime( $wgRUstart );
-                       $this->mWorkStack[] = array( '-total', 0, $wgRequestTime, $initialCpu );
-                       $this->mWorkStack[] = array( '-setup', 1, $wgRequestTime, $initialCpu );
+               $initialTime = $this->getInitialTime();
+               $initialCpu = $this->getInitialTime( 'cpu' );
+               if ( $initialTime !== null && $initialCpu !== null ) {
+                       $this->mWorkStack[] = array( '-total', 0, $initialTime, $initialCpu );
+                       $this->mWorkStack[] = array( '-setup', 1, $initialTime, $initialCpu );
 
                        $this->profileOut( '-setup' );
                } else {
@@ -41,7 +40,7 @@ class ProfilerSimple extends Profiler {
                if ($wgDebugFunctionEntry) {
                        $this->debug(str_repeat(' ', count($this->mWorkStack)).'Entering '.$functionname."\n");
                }
-               $this->mWorkStack[] = array($functionname, count( $this->mWorkStack ), microtime(true), $this->getCpuTime());
+               $this->mWorkStack[] = array( $functionname, count( $this->mWorkStack ), $this->getTime(), $this->getTime( 'cpu' ) );
        }
 
        function profileOut($functionname) {
@@ -68,8 +67,8 @@ class ProfilerSimple extends Profiler {
                                $this->mCollated[$message] = $this->errorEntry;
                        }
                        $entry =& $this->mCollated[$functionname];
-                       $elapsedcpu = $this->getCpuTime() - $octime;
-                       $elapsedreal = microtime(true) - $ortime;
+                       $elapsedcpu = $this->getTime( 'cpu' ) - $octime;
+                       $elapsedreal = $this->getTime() - $ortime;
                        if (!is_array($entry)) {
                                $entry = $this->zeroEntry;
                                $this->mCollated[$functionname] =& $entry;
@@ -92,15 +91,20 @@ class ProfilerSimple extends Profiler {
                /* Implement in subclasses */
        }
 
-       function getCpuTime($ru=null) {
-               if ( function_exists( 'getrusage' ) ) {
-                       if ( $ru == null ) {
-                               $ru = getrusage();
-                       }
-                       return ($ru['ru_utime.tv_sec'] + $ru['ru_stime.tv_sec'] + ($ru['ru_utime.tv_usec'] +
-                               $ru['ru_stime.tv_usec']) * 1e-6);
+       /**
+        * Get the actual CPU time or the initial one if $ru is set.
+        *
+        * @deprecated in 1.20
+        * @return float|null
+        */
+       function getCpuTime( $ru = null ) {
+               wfDeprecated( __METHOD__, '1.20' );
+
+               if ( $ru === null ) {
+                       return $this->getTime( 'cpu' );
                } else {
-                       return 0;
+                       # It theory we should use $ru here, but it always $wgRUstart that is passed here
+                       return $this->getInitialTime( 'cpu' );
                }
        }
 }

diff --git a/includes/profiler/ProfilerSimpleTrace.php b/includes/profiler/ProfilerSimpleTrace.php
index 3abdbe1..57fbb6f 100644 (file)
--- a/includes/profiler/ProfilerSimpleTrace.php
+++ b/includes/profiler/ProfilerSimpleTrace.php
@@ -14,15 +14,16 @@ class ProfilerSimpleTrace extends ProfilerSimple {
        var $memory = 0;
 
        function addInitialStack() {
-               global $wgRequestTime, $wgRUstart;
-               if ( !empty( $wgRequestTime ) && !empty( $wgRUstart ) ) {
-                       $this->mWorkStack[] = array( '-total', 0, $wgRequestTime, $this->getCpuTime( $wgRUstart ) );
+               $initialTime = $this->getInitialTime();
+               $initialCpu = $this->getInitialTime( 'cpu' );
+               if ( $initialTime !== null && $initialCpu !== null ) {
+                       $this->mWorkStack[] = array( '-total', 0, $initialTime, $initialCpu );
                }
                $this->trace .= "Beginning trace: \n";
        }
 
        function profileIn($functionname) {
-               $this->mWorkStack[] = array($functionname, count( $this->mWorkStack ), microtime(true), $this->getCpuTime());
+               $this->mWorkStack[] = array( $functionname, count( $this->mWorkStack ), $this->getTime(), $this->getTime( 'cpu' ) );
                $this->trace .= "         " . sprintf("%6.1f",$this->memoryDiff()) .
                                str_repeat( " ", count($this->mWorkStack)) . " > " . $functionname . "\n";
        }
@@ -47,7 +48,7 @@ class ProfilerSimpleTrace extends ProfilerSimple {
                        elseif ( $ofname != $functionname ) {
                                $this->trace .= "Profiling error: in({$ofname}), out($functionname)";
                        }
-                       $elapsedreal = microtime( true ) - $ortime;
+                       $elapsedreal = $this->getTime() - $ortime;
                        $this->trace .= sprintf( "%03.6f %6.1f", $elapsedreal, $this->memoryDiff() ) .
                                        str_repeat(" ", count( $this->mWorkStack ) + 1 ) . " < " . $functionname . "\n";
                }