profiler: Remove deprecated 'trace' feature in SectionProfiler
Bug: T305100 Change-Id: Ia0f6584d5eb533690fb0e1d12f80cf0d2f9ea48d
This commit is contained in:
parent
b65396485b
commit
dd5f374b51
2 changed files with 7 additions and 189 deletions
|
|
@ -118,6 +118,7 @@ because of Phabricator reports.
|
||||||
fallback to MediaWikiServices emitted deprecation notices since 1.37.
|
fallback to MediaWikiServices emitted deprecation notices since 1.37.
|
||||||
* EventRelayerKafka, deprecated in 1.38, was removed.
|
* EventRelayerKafka, deprecated in 1.38, was removed.
|
||||||
* MediaWiki\Logger\Monolog\KafkaHandler, deprecated in 1.38, was removed.
|
* MediaWiki\Logger\Monolog\KafkaHandler, deprecated in 1.38, was removed.
|
||||||
|
* The "trace" option of SectionProfiler, deprecated in 1.38, was removed.
|
||||||
* The global function wfWikiID(), deprecated since 1.35, has been removed.
|
* The global function wfWikiID(), deprecated since 1.35, has been removed.
|
||||||
* Database::wasKnownStatementRollbackError() was removed. Subclasses should
|
* Database::wasKnownStatementRollbackError() was removed. Subclasses should
|
||||||
override isKnownStatementRollbackError() instead.
|
override isKnownStatementRollbackError() instead.
|
||||||
|
|
|
||||||
|
|
@ -41,14 +41,11 @@ class SectionProfiler {
|
||||||
protected $stack = [];
|
protected $stack = [];
|
||||||
/** @var array Queue of open profile calls with start data */
|
/** @var array Queue of open profile calls with start data */
|
||||||
protected $workStack = [];
|
protected $workStack = [];
|
||||||
|
|
||||||
/** @var array[] Map of (function name => aggregate data array) */
|
/** @var array[] Map of (function name => aggregate data array) */
|
||||||
protected $collated = [];
|
protected $collated = [];
|
||||||
/** @var bool */
|
/** @var bool */
|
||||||
protected $collateDone = false;
|
protected $collateDone = false;
|
||||||
|
|
||||||
/** @var bool Whether to collect the full stack trace or just aggregates */
|
|
||||||
protected $collateOnly = true;
|
|
||||||
/** @var array Cache of a standard broken collation entry */
|
/** @var array Cache of a standard broken collation entry */
|
||||||
protected $errorEntry;
|
protected $errorEntry;
|
||||||
/** @var LoggerInterface */
|
/** @var LoggerInterface */
|
||||||
|
|
@ -59,12 +56,6 @@ class SectionProfiler {
|
||||||
*/
|
*/
|
||||||
public function __construct( array $params = [] ) {
|
public function __construct( array $params = [] ) {
|
||||||
$this->errorEntry = $this->getErrorEntry();
|
$this->errorEntry = $this->getErrorEntry();
|
||||||
// collateOnly (meaning: no tracing) is true by default.
|
|
||||||
// Setting trace=true produces collateOnly=false
|
|
||||||
$this->collateOnly = empty( $params['trace'] );
|
|
||||||
if ( !$this->collateOnly ) {
|
|
||||||
wfDeprecated( __CLASS__ . ' with "trace" option', '1.38' );
|
|
||||||
}
|
|
||||||
$this->logger = LoggerFactory::getInstance( 'profiler' );
|
$this->logger = LoggerFactory::getInstance( 'profiler' );
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|
@ -252,34 +243,22 @@ class SectionProfiler {
|
||||||
if ( $functionname === 'close' ) {
|
if ( $functionname === 'close' ) {
|
||||||
$message = "Profile section ended by close(): {$ofname}";
|
$message = "Profile section ended by close(): {$ofname}";
|
||||||
$this->logger->error( $message );
|
$this->logger->error( $message );
|
||||||
if ( $this->collateOnly ) {
|
|
||||||
$this->collated[$message] = $this->errorEntry;
|
$this->collated[$message] = $this->errorEntry;
|
||||||
} else {
|
|
||||||
$this->stack[] = [ $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 ];
|
|
||||||
}
|
|
||||||
$functionname = $ofname;
|
$functionname = $ofname;
|
||||||
} elseif ( $ofname !== $functionname ) {
|
} elseif ( $ofname !== $functionname ) {
|
||||||
$message = "Profiling error: in({$ofname}), out($functionname)";
|
$message = "Profiling error: in({$ofname}), out($functionname)";
|
||||||
$this->logger->error( $message );
|
$this->logger->error( $message );
|
||||||
if ( $this->collateOnly ) {
|
|
||||||
$this->collated[$message] = $this->errorEntry;
|
$this->collated[$message] = $this->errorEntry;
|
||||||
} else {
|
|
||||||
$this->stack[] = [ $message, 0, 0.0, 0.0, 0, 0.0, 0.0, 0 ];
|
|
||||||
}
|
|
||||||
}
|
}
|
||||||
|
|
||||||
$realTime = $this->getTime( 'wall' );
|
$realTime = $this->getTime( 'wall' );
|
||||||
$cpuTime = $this->getTime( 'cpu' );
|
$cpuTime = $this->getTime( 'cpu' );
|
||||||
$memUsage = memory_get_usage();
|
$memUsage = memory_get_usage();
|
||||||
|
|
||||||
if ( $this->collateOnly ) {
|
|
||||||
$elapsedcpu = $cpuTime - $octime;
|
$elapsedcpu = $cpuTime - $octime;
|
||||||
$elapsedreal = $realTime - $ortime;
|
$elapsedreal = $realTime - $ortime;
|
||||||
$memchange = $memUsage - $omem;
|
$memchange = $memUsage - $omem;
|
||||||
$this->updateEntry( $functionname, $elapsedcpu, $elapsedreal, $memchange );
|
$this->updateEntry( $functionname, $elapsedcpu, $elapsedreal, $memchange );
|
||||||
} else {
|
|
||||||
$this->stack[] = array_merge( $item, [ $realTime, $cpuTime, $memUsage ] );
|
|
||||||
}
|
|
||||||
|
|
||||||
$this->end = [
|
$this->end = [
|
||||||
'cpu' => $cpuTime,
|
'cpu' => $cpuTime,
|
||||||
|
|
@ -288,77 +267,6 @@ class SectionProfiler {
|
||||||
];
|
];
|
||||||
}
|
}
|
||||||
|
|
||||||
/**
|
|
||||||
* Returns a tree of function calls with their real times
|
|
||||||
* @return string
|
|
||||||
* @throws Exception
|
|
||||||
*/
|
|
||||||
public function getCallTreeReport() {
|
|
||||||
if ( $this->collateOnly ) {
|
|
||||||
throw new Exception( "Tree is only available for trace profiling." );
|
|
||||||
}
|
|
||||||
return implode( '', array_map(
|
|
||||||
[ $this, 'getCallTreeLine' ], $this->remapCallTree( $this->stack )
|
|
||||||
) );
|
|
||||||
}
|
|
||||||
|
|
||||||
/**
|
|
||||||
* Recursive function the format the current profiling array into a tree
|
|
||||||
*
|
|
||||||
* @param array $stack Profiling array
|
|
||||||
* @return array
|
|
||||||
*/
|
|
||||||
protected function remapCallTree( array $stack ) {
|
|
||||||
if ( count( $stack ) < 2 ) {
|
|
||||||
return $stack;
|
|
||||||
}
|
|
||||||
$outputs = [];
|
|
||||||
for ( $max = count( $stack ) - 1; $max > 0; ) {
|
|
||||||
/* Find all items under this entry */
|
|
||||||
$level = $stack[$max][1];
|
|
||||||
$working = [];
|
|
||||||
for ( $i = $max - 1; $i >= 0; $i-- ) {
|
|
||||||
if ( $stack[$i][1] > $level ) {
|
|
||||||
$working[] = $stack[$i];
|
|
||||||
} else {
|
|
||||||
break;
|
|
||||||
}
|
|
||||||
}
|
|
||||||
$working = $this->remapCallTree( array_reverse( $working ) );
|
|
||||||
$output = [];
|
|
||||||
foreach ( $working as $item ) {
|
|
||||||
array_push( $output, $item );
|
|
||||||
}
|
|
||||||
array_unshift( $output, $stack[$max] );
|
|
||||||
$max = $i;
|
|
||||||
|
|
||||||
array_unshift( $outputs, $output );
|
|
||||||
}
|
|
||||||
$final = [];
|
|
||||||
foreach ( $outputs as $output ) {
|
|
||||||
foreach ( $output as $item ) {
|
|
||||||
$final[] = $item;
|
|
||||||
}
|
|
||||||
}
|
|
||||||
return $final;
|
|
||||||
}
|
|
||||||
|
|
||||||
/**
|
|
||||||
* Callback to get a formatted line for the call tree
|
|
||||||
* @param array $entry
|
|
||||||
* @return string
|
|
||||||
*/
|
|
||||||
protected function getCallTreeLine( $entry ) {
|
|
||||||
// $entry has (name, level, stime, scpu, smem, etime, ecpu, emem)
|
|
||||||
list( $fname, $level, $startreal, , , $endreal ) = $entry;
|
|
||||||
$delta = $endreal - $startreal;
|
|
||||||
$space = str_repeat( ' ', $level );
|
|
||||||
# The ugly double sprintf is to work around a PHP bug,
|
|
||||||
# which has been fixed in recent releases.
|
|
||||||
return sprintf( "%10s %s %s\n",
|
|
||||||
trim( sprintf( "%7.3f", $delta * 1000.0 ) ), $space, $fname );
|
|
||||||
}
|
|
||||||
|
|
||||||
/**
|
/**
|
||||||
* Populate collated data
|
* Populate collated data
|
||||||
*/
|
*/
|
||||||
|
|
@ -371,97 +279,6 @@ class SectionProfiler {
|
||||||
while ( count( $this->workStack ) ) {
|
while ( count( $this->workStack ) ) {
|
||||||
$this->profileOutInternal( 'close' );
|
$this->profileOutInternal( 'close' );
|
||||||
}
|
}
|
||||||
|
|
||||||
if ( $this->collateOnly ) {
|
|
||||||
return; // already collated as methods exited
|
|
||||||
}
|
|
||||||
|
|
||||||
$this->collated = [];
|
|
||||||
|
|
||||||
# Estimate profiling overhead
|
|
||||||
$oldEnd = $this->end;
|
|
||||||
$profileCount = count( $this->stack );
|
|
||||||
$this->calculateOverhead( $profileCount );
|
|
||||||
|
|
||||||
# First, subtract the overhead!
|
|
||||||
$overheadTotal = $overheadMemory = $overheadInternal = [];
|
|
||||||
foreach ( $this->stack as $entry ) {
|
|
||||||
// $entry is (name,pos,rtime0,cputime0,mem0,rtime1,cputime1,mem1)
|
|
||||||
$fname = $entry[0];
|
|
||||||
$elapsed = $entry[5] - $entry[2];
|
|
||||||
$memchange = $entry[7] - $entry[4];
|
|
||||||
|
|
||||||
if ( $fname === '-overhead-total' ) {
|
|
||||||
$overheadTotal[] = $elapsed;
|
|
||||||
$overheadMemory[] = max( 0, $memchange );
|
|
||||||
} elseif ( $fname === '-overhead-internal' ) {
|
|
||||||
$overheadInternal[] = $elapsed;
|
|
||||||
}
|
|
||||||
}
|
|
||||||
$overheadTotal = $overheadTotal ?
|
|
||||||
array_sum( $overheadTotal ) / count( $overheadInternal ) : 0;
|
|
||||||
$overheadMemory = $overheadMemory ?
|
|
||||||
array_sum( $overheadMemory ) / count( $overheadInternal ) : 0;
|
|
||||||
$overheadInternal = $overheadInternal ?
|
|
||||||
array_sum( $overheadInternal ) / count( $overheadInternal ) : 0;
|
|
||||||
|
|
||||||
# Collate
|
|
||||||
foreach ( $this->stack as $index => $entry ) {
|
|
||||||
// $entry is (name,pos,rtime0,cputime0,mem0,rtime1,cputime1,mem1)
|
|
||||||
$fname = $entry[0];
|
|
||||||
$elapsedCpu = $entry[6] - $entry[3];
|
|
||||||
$elapsedReal = $entry[5] - $entry[2];
|
|
||||||
$memchange = $entry[7] - $entry[4];
|
|
||||||
$subcalls = $this->calltreeCount( $this->stack, $index );
|
|
||||||
|
|
||||||
if ( substr( $fname, 0, 9 ) !== '-overhead' ) {
|
|
||||||
# Adjust for profiling overhead (except special values with elapsed=0)
|
|
||||||
if ( $elapsedReal ) {
|
|
||||||
$elapsedReal -= $overheadInternal;
|
|
||||||
$elapsedReal -= ( $subcalls * $overheadTotal );
|
|
||||||
$memchange -= ( $subcalls * $overheadMemory );
|
|
||||||
}
|
|
||||||
}
|
|
||||||
|
|
||||||
$this->updateEntry( $fname, $elapsedCpu, $elapsedReal, $memchange );
|
|
||||||
}
|
|
||||||
|
|
||||||
$this->collated['-overhead-total']['count'] = $profileCount;
|
|
||||||
arsort( $this->collated, SORT_NUMERIC );
|
|
||||||
|
|
||||||
// Unclobber the end info map (the overhead checking alters it)
|
|
||||||
$this->end = $oldEnd;
|
|
||||||
}
|
|
||||||
|
|
||||||
/**
|
|
||||||
* Dummy calls to calculate profiling overhead
|
|
||||||
*
|
|
||||||
* @param int $profileCount
|
|
||||||
*/
|
|
||||||
protected function calculateOverhead( $profileCount ) {
|
|
||||||
$this->profileInInternal( '-overhead-total' );
|
|
||||||
for ( $i = 0; $i < $profileCount; $i++ ) {
|
|
||||||
$this->profileInInternal( '-overhead-internal' );
|
|
||||||
$this->profileOutInternal( '-overhead-internal' );
|
|
||||||
}
|
|
||||||
$this->profileOutInternal( '-overhead-total' );
|
|
||||||
}
|
|
||||||
|
|
||||||
/**
|
|
||||||
* Counts the number of profiled function calls sitting under
|
|
||||||
* the given point in the call graph. Not the most efficient algo.
|
|
||||||
*
|
|
||||||
* @param array $stack
|
|
||||||
* @param int $start
|
|
||||||
* @return int
|
|
||||||
*/
|
|
||||||
protected function calltreeCount( $stack, $start ) {
|
|
||||||
$level = $stack[$start][1];
|
|
||||||
$count = 0;
|
|
||||||
for ( $i = $start - 1; $i >= 0 && $stack[$i][1] > $level; $i-- ) {
|
|
||||||
$count++;
|
|
||||||
}
|
|
||||||
return $count;
|
|
||||||
}
|
}
|
||||||
|
|
||||||
/**
|
/**
|
||||||
|
|
|
||||||
Loading…
Reference in a new issue