diff --git a/CHANGELOG.md b/CHANGELOG.md index c83cef690f..7197ee5e81 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -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: diff --git a/src/Config.php b/src/Config.php index ee50bc79d9..0137f2ddb7 100644 --- a/src/Config.php +++ b/src/Config.php @@ -143,6 +143,7 @@ class Config 'stdin' => null, 'stdinContent' => null, 'stdinPath' => null, + 'trackTime' => null, 'unknown' => null, ]; @@ -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; @@ -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'); @@ -1428,8 +1444,8 @@ public function printPHPCSUsage() echo ' How many files should be checked simultaneously (default is 1)'.PHP_EOL; echo ' 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 ' Write the report to the specified file path'.PHP_EOL; echo ' How many columns wide screen reports should be printed'.PHP_EOL; diff --git a/src/Files/File.php b/src/Files/File.php index f0c2e747a4..eb2357a15e 100644 --- a/src/Files/File.php +++ b/src/Files/File.php @@ -209,6 +209,7 @@ class File * An array of sniffs being processed and how long they took. * * @var array + * @see getListenerTimes() */ protected $listenerTimes = []; @@ -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; @@ -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.'... '; } @@ -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; } @@ -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; } @@ -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. * diff --git a/src/Reports/Performance.php b/src/Reports/Performance.php new file mode 100644 index 0000000000..d5b94074d4 --- /dev/null +++ b/src/Reports/Performance.php @@ -0,0 +1,160 @@ + + * @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 diff --git a/src/Util/Timing.php b/src/Util/Timing.php index 8cd3524186..36f4346343 100644 --- a/src/Util/Timing.php +++ b/src/Util/Timing.php @@ -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. * @@ -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;