Skip to content

Commit

Permalink
Merge pull request #60 from PHPCSStandards/feature/3784-add-new-sniff…
Browse files Browse the repository at this point in the history
…-performance-report

New `Performance` report to measure sniff run time performance
  • Loading branch information
jrfnl authored Dec 5, 2023
2 parents 3c80ec8 + 70a3d56 commit 38c2caf
Show file tree
Hide file tree
Showing 5 changed files with 251 additions and 21 deletions.
3 changes: 3 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -40,6 +40,9 @@ The file documents changes to the PHP_CodeSniffer project.
- Generic.PHP.LowerCaseType
- PSr12.Functions.NullableTypeDeclaration
- Thanks to Juliette Reinders Folmer (@jrfnl) for the patch
- Added a Performance report, mostly useful for sniff maintainers, to allow for finding "slow" sniffs.
- To run this report, run PHPCS with --report=Performance.
- Thanks to Juliette Reinders Folmer (@jrfnl) for the patch
- Squiz.Commenting.FunctionComment: new ParamNameUnexpectedAmpersandPrefix error for parameters annotated as passed by reference while the parameter is not passed by reference
- Thanks to Dan Wallis (@fredden) for the patch
- Documentation has been added for the following sniffs:
Expand Down
20 changes: 18 additions & 2 deletions src/Config.php
Original file line number Diff line number Diff line change
Expand Up @@ -143,6 +143,7 @@ class Config
'stdin' => null,
'stdinContent' => null,
'stdinPath' => null,
'trackTime' => null,
'unknown' => null,
];

Expand Down Expand Up @@ -277,6 +278,20 @@ public function __set($name, $value)

$value = $cleaned;
break;

// Only track time when explicitly needed.
case 'verbosity':
if ($value > 2) {
$this->settings['trackTime'] = true;
}
break;
case 'reports':
$reports = array_change_key_case($value, CASE_LOWER);
if (array_key_exists('performance', $reports) === true) {
$this->settings['trackTime'] = true;
}
break;

default :
// No validation required.
break;
Expand Down Expand Up @@ -530,6 +545,7 @@ public function restoreDefaults()
$this->stdin = false;
$this->stdinContent = null;
$this->stdinPath = null;
$this->trackTime = false;
$this->unknown = [];

$standard = self::getConfigData('default_standard');
Expand Down Expand Up @@ -1428,8 +1444,8 @@ public function printPHPCSUsage()
echo ' <processes> How many files should be checked simultaneously (default is 1)'.PHP_EOL;
echo ' <report> Print either the "full", "xml", "checkstyle", "csv"'.PHP_EOL;
echo ' "json", "junit", "emacs", "source", "summary", "diff"'.PHP_EOL;
echo ' "svnblame", "gitblame", "hgblame" or "notifysend" report,'.PHP_EOL;
echo ' or specify the path to a custom report class'.PHP_EOL;
echo ' "svnblame", "gitblame", "hgblame", "notifysend" or "performance",'.PHP_EOL;
echo ' report or specify the path to a custom report class'.PHP_EOL;
echo ' (the "full" report is printed by default)'.PHP_EOL;
echo ' <reportFile> Write the report to the specified file path'.PHP_EOL;
echo ' <reportWidth> How many columns wide screen reports should be printed'.PHP_EOL;
Expand Down
26 changes: 22 additions & 4 deletions src/Files/File.php
Original file line number Diff line number Diff line change
Expand Up @@ -209,6 +209,7 @@ class File
* An array of sniffs being processed and how long they took.
*
* @var array
* @see getListenerTimes()
*/
protected $listenerTimes = [];

Expand Down Expand Up @@ -253,6 +254,7 @@ public function __construct($path, Ruleset $ruleset, Config $config)
$this->configCache['errorSeverity'] = $this->config->errorSeverity;
$this->configCache['warningSeverity'] = $this->config->warningSeverity;
$this->configCache['recordErrors'] = $this->config->recordErrors;
$this->configCache['trackTime'] = $this->config->trackTime;
$this->configCache['ignorePatterns'] = $this->ruleset->ignorePatterns;
$this->configCache['includePatterns'] = $this->ruleset->includePatterns;

Expand Down Expand Up @@ -505,8 +507,11 @@ public function process()

$this->activeListener = $class;

if (PHP_CODESNIFFER_VERBOSITY > 2) {
if ($this->configCache['trackTime'] === true) {
$startTime = microtime(true);
}

if (PHP_CODESNIFFER_VERBOSITY > 2) {
echo "\t\t\tProcessing ".$this->activeListener.'... ';
}

Expand All @@ -515,14 +520,16 @@ public function process()
$listenerIgnoreTo[$this->activeListener] = $ignoreTo;
}

if (PHP_CODESNIFFER_VERBOSITY > 2) {
if ($this->configCache['trackTime'] === true) {
$timeTaken = (microtime(true) - $startTime);
if (isset($this->listenerTimes[$this->activeListener]) === false) {
$this->listenerTimes[$this->activeListener] = 0;
}

$this->listenerTimes[$this->activeListener] += $timeTaken;
}

if (PHP_CODESNIFFER_VERBOSITY > 2) {
$timeTaken = round(($timeTaken), 4);
echo "DONE in $timeTaken seconds".PHP_EOL;
}
Expand Down Expand Up @@ -556,8 +563,7 @@ public function process()
echo "\t*** END TOKEN PROCESSING ***".PHP_EOL;
echo "\t*** START SNIFF PROCESSING REPORT ***".PHP_EOL;

asort($this->listenerTimes, SORT_NUMERIC);
$this->listenerTimes = array_reverse($this->listenerTimes, true);
arsort($this->listenerTimes, SORT_NUMERIC);
foreach ($this->listenerTimes as $listener => $timeTaken) {
echo "\t$listener: ".round(($timeTaken), 4).' secs'.PHP_EOL;
}
Expand Down Expand Up @@ -1232,6 +1238,18 @@ public function getMetrics()
}//end getMetrics()


/**
* Returns the time taken processing this file for each invoked sniff.
*
* @return array
*/
public function getListenerTimes()
{
return $this->listenerTimes;

}//end getListenerTimes()


/**
* Returns the absolute filename of this file.
*
Expand Down
160 changes: 160 additions & 0 deletions src/Reports/Performance.php
Original file line number Diff line number Diff line change
@@ -0,0 +1,160 @@
<?php
/**
* Performance report for PHP_CodeSniffer.
*
* @author Juliette Reinders Folmer <phpcs_nospam@adviesenzo.nl>
* @copyright 2023 Juliette Reinders Folmer. All rights reserved.
* @license https://github.com/squizlabs/PHP_CodeSniffer/blob/master/licence.txt BSD Licence
*/

namespace PHP_CodeSniffer\Reports;

use PHP_CodeSniffer\Files\File;
use PHP_CodeSniffer\Util\Common;
use PHP_CodeSniffer\Util\Timing;

class Performance implements Report
{


/**
* Generate a partial report for a single processed file.
*
* Function should return TRUE if it printed or stored data about the file
* and FALSE if it ignored the file. Returning TRUE indicates that the file and
* its data should be counted in the grand totals.
*
* @param array $report Prepared report data.
* @param \PHP_CodeSniffer\File $phpcsFile The file being reported on.
* @param bool $showSources Show sources?
* @param int $width Maximum allowed line width.
*
* @return bool
*/
public function generateFileReport($report, File $phpcsFile, $showSources=false, $width=80)
{
$times = $phpcsFile->getListenerTimes();
foreach ($times as $sniff => $time) {
echo "$sniff>>$time".PHP_EOL;
}

return true;

}//end generateFileReport()


/**
* Prints the sniff performance report.
*
* @param string $cachedData Any partial report data that was returned from
* generateFileReport during the run.
* @param int $totalFiles Total number of files processed during the run.
* @param int $totalErrors Total number of errors found during the run.
* @param int $totalWarnings Total number of warnings found during the run.
* @param int $totalFixable Total number of problems that can be fixed.
* @param bool $showSources Show sources?
* @param int $width Maximum allowed line width.
* @param bool $interactive Are we running in interactive mode?
* @param bool $toScreen Is the report being printed to screen?
*
* @return void
*/
public function generate(
$cachedData,
$totalFiles,
$totalErrors,
$totalWarnings,
$totalFixable,
$showSources=false,
$width=80,
$interactive=false,
$toScreen=true
) {
$lines = explode(PHP_EOL, $cachedData);
array_pop($lines);

if (empty($lines) === true) {
return;
}

// First collect the accumulated timings.
$timings = [];
$totalSniffTime = 0;
foreach ($lines as $line) {
$parts = explode('>>', $line);
$sniffClass = $parts[0];
$time = $parts[1];

if (isset($timings[$sniffClass]) === false) {
$timings[$sniffClass] = 0;
}

$timings[$sniffClass] += $time;
$totalSniffTime += $time;
}

// Next, tidy up the sniff names and determine max needed column width.
$totalTimes = [];
$maxNameWidth = 0;
foreach ($timings as $sniffClass => $secs) {
$sniffCode = Common::getSniffCode($sniffClass);
$maxNameWidth = max($maxNameWidth, strlen($sniffCode));
$totalTimes[$sniffCode] = $secs;
}

// Leading space + up to 12 chars for the number.
$maxTimeWidth = 13;
// Leading space, open parenthesis, up to 5 chars for the number, space + % and close parenthesis.
$maxPercWidth = 10;
// Calculate the maximum width available for the sniff name.
$maxNameWidth = min(($width - $maxTimeWidth - $maxPercWidth), max(($width - $maxTimeWidth - $maxPercWidth), $maxNameWidth));

arsort($totalTimes);

echo PHP_EOL."\033[1m".'PHP CODE SNIFFER SNIFF PERFORMANCE REPORT'."\033[0m".PHP_EOL;
echo str_repeat('-', $width).PHP_EOL;
echo "\033[1m".'SNIFF'.str_repeat(' ', ($width - 31)).'TIME TAKEN (SECS) (%)'."\033[0m".PHP_EOL;
echo str_repeat('-', $width).PHP_EOL;

// Mark sniffs which take more than twice as long as the average processing time per sniff
// in orange and when they take more than three times as long as the average,
// mark them in red.
$avgSniffTime = ($totalSniffTime / count($totalTimes));
$doubleAvgSniffTime = (2 * $avgSniffTime);
$tripleAvgSniffTime = (3 * $avgSniffTime);

$format = "%- {$maxNameWidth}.{$maxNameWidth}s % 12.6f (% 5.1f %%)".PHP_EOL;
$formatBold = "\033[1m%- {$maxNameWidth}.{$maxNameWidth}s % 12.6f (% 5.1f %%)\033[0m".PHP_EOL;
$formatWarning = "%- {$maxNameWidth}.{$maxNameWidth}s \033[33m% 12.6f (% 5.1f %%)\033[0m".PHP_EOL;
$formatError = "%- {$maxNameWidth}.{$maxNameWidth}s \033[31m% 12.6f (% 5.1f %%)\033[0m".PHP_EOL;

foreach ($totalTimes as $sniff => $time) {
$percent = round((($time / $totalSniffTime) * 100), 1);

if ($time > $tripleAvgSniffTime) {
printf($formatError, $sniff, $time, $percent);
} else if ($time > $doubleAvgSniffTime) {
printf($formatWarning, $sniff, $time, $percent);
} else {
printf($format, $sniff, $time, $percent);
}
}

echo str_repeat('-', $width).PHP_EOL;
printf($formatBold, 'TOTAL SNIFF PROCESSING TIME', $totalSniffTime, 100);

$runTime = (Timing::getDuration() / 1000);
$phpcsTime = ($runTime - $totalSniffTime);

echo PHP_EOL.str_repeat('-', $width).PHP_EOL;
printf($format, 'Time taken by sniffs', $totalSniffTime, round((($totalSniffTime / $runTime) * 100), 1));
printf($format, 'Time taken by PHPCS runner', $phpcsTime, round((($phpcsTime / $runTime) * 100), 1));

echo str_repeat('-', $width).PHP_EOL;
printf($formatBold, 'TOTAL RUN TIME', $runTime, 100);
echo str_repeat('-', $width).PHP_EOL;

}//end generate()


}//end class
63 changes: 48 additions & 15 deletions src/Util/Timing.php
Original file line number Diff line number Diff line change
Expand Up @@ -40,6 +40,51 @@ public static function startTiming()
}//end startTiming()


/**
* Get the duration of the run up to "now".
*
* @return int Duration in microseconds.
*/
public static function getDuration()
{
if (self::$startTime === null) {
// Timing was never started.
return 0;
}

return ((microtime(true) - self::$startTime) * 1000);

}//end getDuration()


/**
* Convert a duration in microseconds to a human readable duration string.
*
* @param int $duration Duration in microseconds.
*
* @return string
*/
public static function getHumanReadableDuration($duration)
{
$timeString = '';
if ($duration > 60000) {
$mins = floor($duration / 60000);
$secs = round((fmod($duration, 60000) / 1000), 2);
$timeString = $mins.' mins';
if ($secs !== 0) {
$timeString .= ", $secs secs";
}
} else if ($duration > 1000) {
$timeString = round(($duration / 1000), 2).' secs';
} else {
$timeString = round($duration).'ms';
}

return $timeString;

}//end getHumanReadableDuration()


/**
* Print information about the run.
*
Expand All @@ -60,23 +105,11 @@ public static function printRunTime($force=false)
return;
}

$time = ((microtime(true) - self::$startTime) * 1000);

if ($time > 60000) {
$mins = floor($time / 60000);
$secs = round((fmod($time, 60000) / 1000), 2);
$time = $mins.' mins';
if ($secs !== 0) {
$time .= ", $secs secs";
}
} else if ($time > 1000) {
$time = round(($time / 1000), 2).' secs';
} else {
$time = round($time).'ms';
}
$duration = self::getDuration();
$duration = self::getHumanReadableDuration($duration);

$mem = round((memory_get_peak_usage(true) / (1024 * 1024)), 2).'MB';
echo "Time: $time; Memory: $mem".PHP_EOL.PHP_EOL;
echo "Time: $duration; Memory: $mem".PHP_EOL.PHP_EOL;

self::$printed = true;

Expand Down

0 comments on commit 38c2caf

Please sign in to comment.