From e33b8c4083a256e03ea2e40758ba4ec6ec74b112 Mon Sep 17 00:00:00 2001 From: Alexandre Emsenhuber Date: Wed, 28 Mar 2012 20:42:03 +0200 Subject: [PATCH] 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 --- includes/profiler/Profiler.php | 67 ++++++++++++++++++----- includes/profiler/ProfilerSimple.php | 38 +++++++------ includes/profiler/ProfilerSimpleTrace.php | 11 ++-- 3 files changed, 81 insertions(+), 35 deletions(-) diff --git a/includes/profiler/Profiler.php b/includes/profiler/Profiler.php index f6d8b3a293..f88406397a 100644 --- 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 df3736396d..1091495947 100644 --- 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 3abdbe1f77..57fbb6feab 100644 --- 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"; } -- 2.20.1