From f73c47dc12d6e0ad85182fca2d4ea099d5fdb7ce Mon Sep 17 00:00:00 2001 From: jrfnl Date: Mon, 24 Apr 2023 21:24:21 +0200 Subject: [PATCH 1/4] Util\Timing: split `printRunTime()` method ... into logical parts to allow the Performance report access to the total run time information (at the point of report creation) as well. --- src/Util/Timing.php | 63 ++++++++++++++++++++++++++++++++++----------- 1 file changed, 48 insertions(+), 15 deletions(-) diff --git a/src/Util/Timing.php b/src/Util/Timing.php index 95ee85216d..652d48bd76 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; From 9d05a82ff890f33309e9bb841f2131500f397c90 Mon Sep 17 00:00:00 2001 From: jrfnl Date: Mon, 24 Apr 2023 21:25:45 +0200 Subject: [PATCH 2/4] File: add `getListenerTimes()` method ... to allow for access to the recorded listener times from within a report class. --- src/Files/File.php | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/src/Files/File.php b/src/Files/File.php index 21cbeb2158..be314261bc 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 = []; @@ -1216,6 +1217,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. * From b9d7f9ef639c5f8574f44b79ce1131fe910afb35 Mon Sep 17 00:00:00 2001 From: jrfnl Date: Mon, 24 Apr 2023 21:37:59 +0200 Subject: [PATCH 3/4] Config: add `trackTime` toggle for whether or not to track listener times As recording the time taken by each sniff has a performance impact in and of itself on a CS run, only record the time taken by each sniff when needed. [*] Originally, this was already done conditionally based on the `PHP_CODESNIFFER_VERBOSITY > 2` condition. However, adding the Performance report would add a second criteria. This commit adds a new (internal) Config setting `trackTime`, which will be set to `true` when `PHP_CODESNIFFER_VERBOSITY > 2`. This commit paves the way for adding the second criteria in the next commit. --- [*] I've done some unscientific benchmarks for this by running PHPCS multiple times, with and without tracking the listener times, over a 300+ file codebase. Without tracking listener times, the run time was always around 39 seconds with 56Mb memory use. With tracking listener times, the run time was always around 54 seconds with 64Mb memory use. This, to me, shows a significant enough difference and sufficient reason to put this toggle in place to only track time when needed. --- src/Config.php | 9 +++++++++ src/Files/File.php | 13 +++++++++---- 2 files changed, 18 insertions(+), 4 deletions(-) diff --git a/src/Config.php b/src/Config.php index 8d3fb173e6..63eec92866 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, ]; @@ -264,6 +265,13 @@ public function __set($name, $value) $value = $cleaned; break; + + // Only track time when explicitly needed. + case 'verbosity': + if ($value > 2) { + $this->settings['trackTime'] = true; + } + break; default : // No validation required. break; @@ -517,6 +525,7 @@ public function restoreDefaults() $this->stdin = false; $this->stdinContent = null; $this->stdinPath = null; + $this->trackTime = false; $this->unknown = []; $standard = self::getConfigData('default_standard'); diff --git a/src/Files/File.php b/src/Files/File.php index be314261bc..8fe0b451bd 100644 --- a/src/Files/File.php +++ b/src/Files/File.php @@ -254,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; @@ -497,8 +498,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.'... '; } @@ -507,14 +511,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; } @@ -541,8 +547,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; } From 109cddc2ee52cc00e3ba3e86a1d45bc0e1e66ffe Mon Sep 17 00:00:00 2001 From: jrfnl Date: Mon, 24 Apr 2023 21:58:34 +0200 Subject: [PATCH 4/4] New `Performance` report to measure sniff run time performance The report will print the sniff name, cumulative listener run time and % of the total sniff run time for each sniff triggered during a run. The report is order by cumulative listener run time in descending order. Additionally, it will highlight sniffs which have a cumulative listener run time more than twice the average run time per sniff in orange and sniffs with a cumulative listener run time of more than three times the average run time per sniff in red. At the bottom of the report it will also compare the total sniff relative run time with the total run time. Fixes 3784 Includes mention of the report in the CLI help test. --- package.xml | 1 + src/Config.php | 11 ++- src/Reports/Performance.php | 160 ++++++++++++++++++++++++++++++++++++ 3 files changed, 170 insertions(+), 2 deletions(-) create mode 100644 src/Reports/Performance.php diff --git a/package.xml b/package.xml index a5c8053d05..2906f12677 100644 --- a/package.xml +++ b/package.xml @@ -328,6 +328,7 @@ http://pear.php.net/dtd/package-2.0.xsd"> + diff --git a/src/Config.php b/src/Config.php index 63eec92866..59d12d9e0d 100644 --- a/src/Config.php +++ b/src/Config.php @@ -272,6 +272,13 @@ public function __set($name, $value) $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; @@ -1420,8 +1427,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/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