Add performance logging under a --debug-performance flag

Author: muglug

src/Psalm/Internal/Analyzer/FunctionLikeAnalyzer.php

@@ -557,8 +557,29 @@ function (FunctionLikeParameter $p) {
             ]);
         }
 
+        $time = \microtime(true);
+
+        $project_analyzer = $statements_analyzer->getProjectAnalyzer();
+
         $statements_analyzer->analyze($function_stmts, $context, $global_context, true);
 
+        if (!$context->collect_initializations
+            && !$context->collect_mutations
+            && $project_analyzer->debug_performance
+            && $cased_method_id
+        ) {
+            $traverser = new PhpParser\NodeTraverser;
+
+            $node_counter = new \Psalm\Internal\PhpVisitor\NodeCounterVisitor();
+            $traverser->addVisitor($node_counter);
+            $traverser->traverse($function_stmts);
+
+            if ($node_counter->count > 5) {
+                $time_taken = \microtime(true) - $time;
+                $codebase->analyzer->addFunctionTiming($cased_method_id, $time_taken / $node_counter->count);
+            }
+        }
+
         $this->examineParamTypes($statements_analyzer, $context, $codebase);
 
         foreach ($storage->params as $offset => $function_param) {

src/Psalm/Internal/Analyzer/ProjectAnalyzer.php

@@ -135,6 +135,11 @@ class ProjectAnalyzer
      */
     public $debug_lines = false;
 
+    /**
+     * @var bool
+     */
+    public $debug_performance = false;
+
     /**
      * @var bool
      */

src/Psalm/Internal/Analyzer/StatementsAnalyzer.php

@@ -151,6 +151,10 @@ public function analyze(
         Context $global_context = null,
         $root_scope = false
     ) {
+        if (!$stmts) {
+            return;
+        }
+
         // hoist functions to the top
         $this->hoistFunctions($stmts);
 

src/Psalm/Internal/Codebase/Analyzer.php

@@ -46,6 +46,7 @@
  *      file_references_to_missing_class_members: array<string, array<string,bool>>,
  *      mixed_counts: array<string, array{0: int, 1: int}>,
  *      mixed_member_names: array<string, array<string, bool>>,
+ *      function_timings: array<string, float>,
  *      file_manipulations: array<string, FileManipulation[]>,
  *      method_references_to_class_members: array<string, array<string,bool>>,
  *      method_references_to_missing_class_members: array<string, array<string,bool>>,
@@ -108,6 +109,13 @@ class Analyzer
      */
     private $count_mixed = true;
 
+    /**
+     * Used to store debug performance data
+     *
+     * @var array<string, float>
+     */
+    private $function_timings = [];
+
     /**
      * We analyze more files than we necessarily report errors in
      *
@@ -316,7 +324,7 @@ function (string $file_path) : bool {
         }
     }
 
-    private function doAnalysis(ProjectAnalyzer $project_analyzer, int $pool_size, bool $rerun = false) : void
+    private function doAnalysis(ProjectAnalyzer $project_analyzer, int $pool_size) : void
     {
         $this->progress->start(count($this->files_to_analyze));
 
@@ -426,7 +434,7 @@ function () {
                 },
                 $analysis_worker,
                 /** @return WorkerData */
-                function () use ($rerun) {
+                function () {
                     $project_analyzer = ProjectAnalyzer::getInstance();
                     $codebase = $project_analyzer->getCodebase();
                     $analyzer = $codebase->analyzer;
@@ -438,22 +446,23 @@ function () use ($rerun) {
                     return [
                         'issues' => IssueBuffer::getIssuesData(),
                         'fixable_issue_counts' => IssueBuffer::getFixableIssues(),
-                        'nonmethod_references_to_classes' => $rerun ? [] : $file_reference_provider->getAllNonMethodReferencesToClasses(),
-                        'method_references_to_classes' => $rerun ? [] : $file_reference_provider->getAllMethodReferencesToClasses(),
-                        'file_references_to_class_members' => $rerun ? [] : $file_reference_provider->getAllFileReferencesToClassMembers(),
-                        'method_references_to_class_members' => $rerun ? [] : $file_reference_provider->getAllMethodReferencesToClassMembers(),
-                        'file_references_to_missing_class_members' => $rerun ? [] : $file_reference_provider->getAllFileReferencesToMissingClassMembers(),
-                        'method_references_to_missing_class_members' => $rerun ? [] : $file_reference_provider->getAllMethodReferencesToMissingClassMembers(),
-                        'method_param_uses' => $rerun ? [] : $file_reference_provider->getAllMethodParamUses(),
-                        'mixed_member_names' => $rerun ? [] : $analyzer->getMixedMemberNames(),
-                        'file_manipulations' => $rerun ? [] : FileManipulationBuffer::getAll(),
-                        'mixed_counts' => $rerun ? [] : $analyzer->getMixedCounts(),
-                        'analyzed_methods' => $rerun ? [] : $analyzer->getAnalyzedMethods(),
-                        'file_maps' => $rerun ? [] : $analyzer->getFileMaps(),
-                        'class_locations' => $rerun ? [] : $file_reference_provider->getAllClassLocations(),
-                        'class_method_locations' => $rerun ? [] : $file_reference_provider->getAllClassMethodLocations(),
-                        'class_property_locations' => $rerun ? [] : $file_reference_provider->getAllClassPropertyLocations(),
-                        'possible_method_param_types' => $rerun ? [] : $analyzer->getPossibleMethodParamTypes(),
+                        'nonmethod_references_to_classes' => $file_reference_provider->getAllNonMethodReferencesToClasses(),
+                        'method_references_to_classes' => $file_reference_provider->getAllMethodReferencesToClasses(),
+                        'file_references_to_class_members' => $file_reference_provider->getAllFileReferencesToClassMembers(),
+                        'method_references_to_class_members' => $file_reference_provider->getAllMethodReferencesToClassMembers(),
+                        'file_references_to_missing_class_members' => $file_reference_provider->getAllFileReferencesToMissingClassMembers(),
+                        'method_references_to_missing_class_members' => $file_reference_provider->getAllMethodReferencesToMissingClassMembers(),
+                        'method_param_uses' => $file_reference_provider->getAllMethodParamUses(),
+                        'mixed_member_names' => $analyzer->getMixedMemberNames(),
+                        'file_manipulations' => FileManipulationBuffer::getAll(),
+                        'mixed_counts' => $analyzer->getMixedCounts(),
+                        'function_timings' => $analyzer->getFunctionTimings(),
+                        'analyzed_methods' => $analyzer->getAnalyzedMethods(),
+                        'file_maps' => $analyzer->getFileMaps(),
+                        'class_locations' => $file_reference_provider->getAllClassLocations(),
+                        'class_method_locations' => $file_reference_provider->getAllClassMethodLocations(),
+                        'class_property_locations' => $file_reference_provider->getAllClassPropertyLocations(),
+                        'possible_method_param_types' => $analyzer->getPossibleMethodParamTypes(),
                         'taint_data' => $codebase->taint,
                         'unused_suppressions' => $codebase->track_unused_suppressions ? IssueBuffer::getUnusedSuppressions() : [],
                         'used_suppressions' => $codebase->track_unused_suppressions ? IssueBuffer::getUsedSuppressions() : [],
@@ -486,10 +495,6 @@ function () use ($rerun) {
                     $codebase->taint->addThreadData($pool_data['taint_data']);
                 }
 
-                if ($rerun) {
-                    continue;
-                }
-
                 $codebase->file_reference_provider->addNonMethodReferencesToClasses(
                     $pool_data['nonmethod_references_to_classes']
                 );
@@ -514,6 +519,7 @@ function () use ($rerun) {
                 $this->addMixedMemberNames(
                     $pool_data['mixed_member_names']
                 );
+                $this->function_timings += $pool_data['function_timings'];
                 $codebase->file_reference_provider->addClassLocations(
                     $pool_data['class_locations']
                 );
@@ -1145,6 +1151,19 @@ public function getMixedCounts()
         return array_intersect_key($this->mixed_counts, $all_deep_scanned_files);
     }
 
+    /**
+     * @return array<string, float>
+     */
+    public function getFunctionTimings()
+    {
+        return $this->function_timings;
+    }
+
+    public function addFunctionTiming(string $function_id, float $time_per_node) : void
+    {
+        $this->function_timings[$function_id] = $time_per_node;
+    }
+
     /**
      * @return void
      */

src/Psalm/Internal/PhpVisitor/NodeCounterVisitor.php

@@ -0,0 +1,23 @@
+<?php
+namespace Psalm\Internal\PhpVisitor;
+
+use PhpParser;
+
+/**
+ * @internal
+ */
+class NodeCounterVisitor extends PhpParser\NodeVisitorAbstract implements PhpParser\NodeVisitor
+{
+    /** @var int */
+    public $count = 0;
+
+    /**
+     * @param  PhpParser\Node $node
+     *
+     * @return null|int
+     */
+    public function enterNode(PhpParser\Node $node)
+    {
+        $this->count++;
+    }
+}

src/Psalm/IssueBuffer.php

@@ -633,6 +633,28 @@ function (IssueData $d1, IssueData $d2) : int {
                     echo $codebase->analyzer->getNonMixedStats();
                     echo "\n";
                 }
+
+                if ($project_analyzer->debug_performance) {
+                    echo '-----------------' . "\n";
+                    echo 'Slow-to-analyze functions' . "\n";
+                    echo '-----------------' . "\n\n";
+
+                    $function_timings = $codebase->analyzer->getFunctionTimings();
+
+                    \arsort($function_timings);
+
+                    $i = 0;
+
+                    foreach ($function_timings as $function_id => $time) {
+                        if (++$i > 10) {
+                            break;
+                        }
+
+                        echo $function_id . ': ' . \round(1000 * $time, 2) . 'ms per node' . "\n";
+                    }
+
+                    echo "\n";
+                }
             }
         }
 

src/psalm.php

@@ -80,6 +80,7 @@
     'config:',
     'debug',
     'debug-by-line',
+    'debug-performance',
     'debug-emitted-issues',
     'diff',
     'diff-methods',
@@ -624,6 +625,10 @@ function ($arg) {
     $project_analyzer->debug_lines = true;
 }
 
+if (array_key_exists('debug-performance', $options)) {
+    $project_analyzer->debug_performance = true;
+}
+
 if ($config->find_unused_code) {
     $find_unused_code = 'auto';
 }