Skip to content

Commit 38c2caf

Browse files
jrfnljrfnl
authored
Merge pull request #60 from PHPCSStandards/feature/3784-add-new-sniff-performance-report
New `Performance` report to measure sniff run time performance
2 parents 3c80ec8 + 70a3d56 commit 38c2caf

File tree

5 files changed

+251
-21
lines changed

5 files changed

+251
-21
lines changed

‎CHANGELOG.md

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -40,6 +40,9 @@ The file documents changes to the PHP_CodeSniffer project.
4040
- Generic.PHP.LowerCaseType
4141
- PSr12.Functions.NullableTypeDeclaration
4242
- Thanks to Juliette Reinders Folmer (@jrfnl) for the patch
43+
- Added a Performance report, mostly useful for sniff maintainers, to allow for finding "slow" sniffs.
44+
- To run this report, run PHPCS with --report=Performance.
45+
- Thanks to Juliette Reinders Folmer (@jrfnl) for the patch
4346
- Squiz.Commenting.FunctionComment: new ParamNameUnexpectedAmpersandPrefix error for parameters annotated as passed by reference while the parameter is not passed by reference
4447
- Thanks to Dan Wallis (@fredden) for the patch
4548
- Documentation has been added for the following sniffs:

‎src/Config.php

Lines changed: 18 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -143,6 +143,7 @@ class Config
143143
'stdin' => null,
144144
'stdinContent' => null,
145145
'stdinPath' => null,
146+
'trackTime' => null,
146147
'unknown' => null,
147148
];
148149

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

278279
$value = $cleaned;
279280
break;
281+
282+
// Only track time when explicitly needed.
283+
case 'verbosity':
284+
if ($value > 2) {
285+
$this->settings['trackTime'] = true;
286+
}
287+
break;
288+
case 'reports':
289+
$reports = array_change_key_case($value, CASE_LOWER);
290+
if (array_key_exists('performance', $reports) === true) {
291+
$this->settings['trackTime'] = true;
292+
}
293+
break;
294+
280295
default :
281296
// No validation required.
282297
break;
@@ -530,6 +545,7 @@ public function restoreDefaults()
530545
$this->stdin = false;
531546
$this->stdinContent = null;
532547
$this->stdinPath = null;
548+
$this->trackTime = false;
533549
$this->unknown = [];
534550

535551
$standard = self::getConfigData('default_standard');
@@ -1428,8 +1444,8 @@ public function printPHPCSUsage()
14281444
echo ' <processes> How many files should be checked simultaneously (default is 1)'.PHP_EOL;
14291445
echo ' <report> Print either the "full", "xml", "checkstyle", "csv"'.PHP_EOL;
14301446
echo ' "json", "junit", "emacs", "source", "summary", "diff"'.PHP_EOL;
1431-
echo ' "svnblame", "gitblame", "hgblame" or "notifysend" report,'.PHP_EOL;
1432-
echo ' or specify the path to a custom report class'.PHP_EOL;
1447+
echo ' "svnblame", "gitblame", "hgblame", "notifysend" or "performance",'.PHP_EOL;
1448+
echo ' report or specify the path to a custom report class'.PHP_EOL;
14331449
echo ' (the "full" report is printed by default)'.PHP_EOL;
14341450
echo ' <reportFile> Write the report to the specified file path'.PHP_EOL;
14351451
echo ' <reportWidth> How many columns wide screen reports should be printed'.PHP_EOL;

‎src/Files/File.php

Lines changed: 22 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -209,6 +209,7 @@ class File
209209
* An array of sniffs being processed and how long they took.
210210
*
211211
* @var array
212+
* @see getListenerTimes()
212213
*/
213214
protected $listenerTimes = [];
214215

@@ -253,6 +254,7 @@ public function __construct($path, Ruleset $ruleset, Config $config)
253254
$this->configCache['errorSeverity'] = $this->config->errorSeverity;
254255
$this->configCache['warningSeverity'] = $this->config->warningSeverity;
255256
$this->configCache['recordErrors'] = $this->config->recordErrors;
257+
$this->configCache['trackTime'] = $this->config->trackTime;
256258
$this->configCache['ignorePatterns'] = $this->ruleset->ignorePatterns;
257259
$this->configCache['includePatterns'] = $this->ruleset->includePatterns;
258260

@@ -505,8 +507,11 @@ public function process()
505507

506508
$this->activeListener = $class;
507509

508-
if (PHP_CODESNIFFER_VERBOSITY > 2) {
510+
if ($this->configCache['trackTime'] === true) {
509511
$startTime = microtime(true);
512+
}
513+
514+
if (PHP_CODESNIFFER_VERBOSITY > 2) {
510515
echo "\t\t\tProcessing ".$this->activeListener.'... ';
511516
}
512517

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

518-
if (PHP_CODESNIFFER_VERBOSITY > 2) {
523+
if ($this->configCache['trackTime'] === true) {
519524
$timeTaken = (microtime(true) - $startTime);
520525
if (isset($this->listenerTimes[$this->activeListener]) === false) {
521526
$this->listenerTimes[$this->activeListener] = 0;
522527
}
523528

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

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

559-
asort($this->listenerTimes, SORT_NUMERIC);
560-
$this->listenerTimes = array_reverse($this->listenerTimes, true);
566+
arsort($this->listenerTimes, SORT_NUMERIC);
561567
foreach ($this->listenerTimes as $listener => $timeTaken) {
562568
echo "\t$listener: ".round(($timeTaken), 4).' secs'.PHP_EOL;
563569
}
@@ -1232,6 +1238,18 @@ public function getMetrics()
12321238
}//end getMetrics()
12331239

12341240

1241+
/**
1242+
* Returns the time taken processing this file for each invoked sniff.
1243+
*
1244+
* @return array
1245+
*/
1246+
public function getListenerTimes()
1247+
{
1248+
return $this->listenerTimes;
1249+
1250+
}//end getListenerTimes()
1251+
1252+
12351253
/**
12361254
* Returns the absolute filename of this file.
12371255
*

‎src/Reports/Performance.php

Lines changed: 160 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,160 @@
1+
<?php
2+
/**
3+
* Performance report for PHP_CodeSniffer.
4+
*
5+
* @author Juliette Reinders Folmer <[email protected]>
6+
* @copyright 2023 Juliette Reinders Folmer. All rights reserved.
7+
* @license https://github.com/squizlabs/PHP_CodeSniffer/blob/master/licence.txt BSD Licence
8+
*/
9+
10+
namespace PHP_CodeSniffer\Reports;
11+
12+
use PHP_CodeSniffer\Files\File;
13+
use PHP_CodeSniffer\Util\Common;
14+
use PHP_CodeSniffer\Util\Timing;
15+
16+
class Performance implements Report
17+
{
18+
19+
20+
/**
21+
* Generate a partial report for a single processed file.
22+
*
23+
* Function should return TRUE if it printed or stored data about the file
24+
* and FALSE if it ignored the file. Returning TRUE indicates that the file and
25+
* its data should be counted in the grand totals.
26+
*
27+
* @param array $report Prepared report data.
28+
* @param \PHP_CodeSniffer\File $phpcsFile The file being reported on.
29+
* @param bool $showSources Show sources?
30+
* @param int $width Maximum allowed line width.
31+
*
32+
* @return bool
33+
*/
34+
public function generateFileReport($report, File $phpcsFile, $showSources=false, $width=80)
35+
{
36+
$times = $phpcsFile->getListenerTimes();
37+
foreach ($times as $sniff => $time) {
38+
echo "$sniff>>$time".PHP_EOL;
39+
}
40+
41+
return true;
42+
43+
}//end generateFileReport()
44+
45+
46+
/**
47+
* Prints the sniff performance report.
48+
*
49+
* @param string $cachedData Any partial report data that was returned from
50+
* generateFileReport during the run.
51+
* @param int $totalFiles Total number of files processed during the run.
52+
* @param int $totalErrors Total number of errors found during the run.
53+
* @param int $totalWarnings Total number of warnings found during the run.
54+
* @param int $totalFixable Total number of problems that can be fixed.
55+
* @param bool $showSources Show sources?
56+
* @param int $width Maximum allowed line width.
57+
* @param bool $interactive Are we running in interactive mode?
58+
* @param bool $toScreen Is the report being printed to screen?
59+
*
60+
* @return void
61+
*/
62+
public function generate(
63+
$cachedData,
64+
$totalFiles,
65+
$totalErrors,
66+
$totalWarnings,
67+
$totalFixable,
68+
$showSources=false,
69+
$width=80,
70+
$interactive=false,
71+
$toScreen=true
72+
) {
73+
$lines = explode(PHP_EOL, $cachedData);
74+
array_pop($lines);
75+
76+
if (empty($lines) === true) {
77+
return;
78+
}
79+
80+
// First collect the accumulated timings.
81+
$timings = [];
82+
$totalSniffTime = 0;
83+
foreach ($lines as $line) {
84+
$parts = explode('>>', $line);
85+
$sniffClass = $parts[0];
86+
$time = $parts[1];
87+
88+
if (isset($timings[$sniffClass]) === false) {
89+
$timings[$sniffClass] = 0;
90+
}
91+
92+
$timings[$sniffClass] += $time;
93+
$totalSniffTime += $time;
94+
}
95+
96+
// Next, tidy up the sniff names and determine max needed column width.
97+
$totalTimes = [];
98+
$maxNameWidth = 0;
99+
foreach ($timings as $sniffClass => $secs) {
100+
$sniffCode = Common::getSniffCode($sniffClass);
101+
$maxNameWidth = max($maxNameWidth, strlen($sniffCode));
102+
$totalTimes[$sniffCode] = $secs;
103+
}
104+
105+
// Leading space + up to 12 chars for the number.
106+
$maxTimeWidth = 13;
107+
// Leading space, open parenthesis, up to 5 chars for the number, space + % and close parenthesis.
108+
$maxPercWidth = 10;
109+
// Calculate the maximum width available for the sniff name.
110+
$maxNameWidth = min(($width - $maxTimeWidth - $maxPercWidth), max(($width - $maxTimeWidth - $maxPercWidth), $maxNameWidth));
111+
112+
arsort($totalTimes);
113+
114+
echo PHP_EOL."\033[1m".'PHP CODE SNIFFER SNIFF PERFORMANCE REPORT'."\033[0m".PHP_EOL;
115+
echo str_repeat('-', $width).PHP_EOL;
116+
echo "\033[1m".'SNIFF'.str_repeat(' ', ($width - 31)).'TIME TAKEN (SECS) (%)'."\033[0m".PHP_EOL;
117+
echo str_repeat('-', $width).PHP_EOL;
118+
119+
// Mark sniffs which take more than twice as long as the average processing time per sniff
120+
// in orange and when they take more than three times as long as the average,
121+
// mark them in red.
122+
$avgSniffTime = ($totalSniffTime / count($totalTimes));
123+
$doubleAvgSniffTime = (2 * $avgSniffTime);
124+
$tripleAvgSniffTime = (3 * $avgSniffTime);
125+
126+
$format = "%- {$maxNameWidth}.{$maxNameWidth}s % 12.6f (% 5.1f %%)".PHP_EOL;
127+
$formatBold = "\033[1m%- {$maxNameWidth}.{$maxNameWidth}s % 12.6f (% 5.1f %%)\033[0m".PHP_EOL;
128+
$formatWarning = "%- {$maxNameWidth}.{$maxNameWidth}s \033[33m% 12.6f (% 5.1f %%)\033[0m".PHP_EOL;
129+
$formatError = "%- {$maxNameWidth}.{$maxNameWidth}s \033[31m% 12.6f (% 5.1f %%)\033[0m".PHP_EOL;
130+
131+
foreach ($totalTimes as $sniff => $time) {
132+
$percent = round((($time / $totalSniffTime) * 100), 1);
133+
134+
if ($time > $tripleAvgSniffTime) {
135+
printf($formatError, $sniff, $time, $percent);
136+
} else if ($time > $doubleAvgSniffTime) {
137+
printf($formatWarning, $sniff, $time, $percent);
138+
} else {
139+
printf($format, $sniff, $time, $percent);
140+
}
141+
}
142+
143+
echo str_repeat('-', $width).PHP_EOL;
144+
printf($formatBold, 'TOTAL SNIFF PROCESSING TIME', $totalSniffTime, 100);
145+
146+
$runTime = (Timing::getDuration() / 1000);
147+
$phpcsTime = ($runTime - $totalSniffTime);
148+
149+
echo PHP_EOL.str_repeat('-', $width).PHP_EOL;
150+
printf($format, 'Time taken by sniffs', $totalSniffTime, round((($totalSniffTime / $runTime) * 100), 1));
151+
printf($format, 'Time taken by PHPCS runner', $phpcsTime, round((($phpcsTime / $runTime) * 100), 1));
152+
153+
echo str_repeat('-', $width).PHP_EOL;
154+
printf($formatBold, 'TOTAL RUN TIME', $runTime, 100);
155+
echo str_repeat('-', $width).PHP_EOL;
156+
157+
}//end generate()
158+
159+
160+
}//end class

‎src/Util/Timing.php

Lines changed: 48 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -40,6 +40,51 @@ public static function startTiming()
4040
}//end startTiming()
4141

4242

43+
/**
44+
* Get the duration of the run up to "now".
45+
*
46+
* @return int Duration in microseconds.
47+
*/
48+
public static function getDuration()
49+
{
50+
if (self::$startTime === null) {
51+
// Timing was never started.
52+
return 0;
53+
}
54+
55+
return ((microtime(true) - self::$startTime) * 1000);
56+
57+
}//end getDuration()
58+
59+
60+
/**
61+
* Convert a duration in microseconds to a human readable duration string.
62+
*
63+
* @param int $duration Duration in microseconds.
64+
*
65+
* @return string
66+
*/
67+
public static function getHumanReadableDuration($duration)
68+
{
69+
$timeString = '';
70+
if ($duration > 60000) {
71+
$mins = floor($duration / 60000);
72+
$secs = round((fmod($duration, 60000) / 1000), 2);
73+
$timeString = $mins.' mins';
74+
if ($secs !== 0) {
75+
$timeString .= ", $secs secs";
76+
}
77+
} else if ($duration > 1000) {
78+
$timeString = round(($duration / 1000), 2).' secs';
79+
} else {
80+
$timeString = round($duration).'ms';
81+
}
82+
83+
return $timeString;
84+
85+
}//end getHumanReadableDuration()
86+
87+
4388
/**
4489
* Print information about the run.
4590
*
@@ -60,23 +105,11 @@ public static function printRunTime($force=false)
60105
return;
61106
}
62107

63-
$time = ((microtime(true) - self::$startTime) * 1000);
64-
65-
if ($time > 60000) {
66-
$mins = floor($time / 60000);
67-
$secs = round((fmod($time, 60000) / 1000), 2);
68-
$time = $mins.' mins';
69-
if ($secs !== 0) {
70-
$time .= ", $secs secs";
71-
}
72-
} else if ($time > 1000) {
73-
$time = round(($time / 1000), 2).' secs';
74-
} else {
75-
$time = round($time).'ms';
76-
}
108+
$duration = self::getDuration();
109+
$duration = self::getHumanReadableDuration($duration);
77110

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

81114
self::$printed = true;
82115

0 commit comments

Comments
 (0)