Performance improvement

lib/steep.rb

@@ -140,7 +140,7 @@ def self.logger
   def self.new_logger(output, prev_level)
     ActiveSupport::TaggedLogging.new(Logger.new(output)).tap do |logger|
       logger.push_tags "Steep #{VERSION}"
-      logger.level = prev_level || Logger::WARN
+      logger.level = prev_level || Logger::ERROR
     end
   end
 
@@ -157,7 +157,7 @@ def self.log_output=(output)
   @logger = nil
   self.log_output = STDERR
 
-  def self.measure(message, level: :info)
+  def self.measure(message, level: :warn)
     start = Time.now
     yield.tap do
       time = Time.now - start
@@ -174,4 +174,63 @@ def self.log_error(exn, message: "Unexpected error: #{exn.inspect}")
       Steep.logger.warn "  #{loc}"
     end
   end
+
+  class Sampler
+    def initialize()
+      @samples = []
+    end
+
+    def sample(message)
+      start = Time.now
+      yield.tap do
+        time = Time.now - start
+        @samples << [message, time]
+      end
+    end
+
+    def count
+      @samples.count
+    end
+
+    def total
+      @samples.sum(&:last)
+    end
+
+    def slowests(num)
+      @samples.sort_by(&:last).reverse.take(num)
+    end
+
+    def average
+      if count > 0
+        total/count
+      else
+        0
+      end
+    end
+
+    def percentile(p)
+      slowests(count - count * p / 100r).last&.last || 0
+    end
+  end
+
+  def self.measure2(message, level: :warn)
+    sampler = Sampler.new
+    result = yield(sampler)
+
+    if level.is_a?(Symbol)
+      level = Logger.const_get(level.to_s.upcase)
+    end
+    logger.log(level) { "#{sampler.total}secs for \"#{message}\"" }
+    logger.log(level) { "  Average: #{sampler.average}secs"}
+    logger.log(level) { "  Median: #{sampler.percentile(50)}secs"}
+    logger.log(level) { "  Samples: #{sampler.count}"}
+    logger.log(level) { "  99 percentile: #{sampler.percentile(99)}secs"}
+    logger.log(level) { "  90 percentile: #{sampler.percentile(90)}secs"}
+    logger.log(level) { "  10 Slowests:"}
+    sampler.slowests(10).each do |message, time|
+      logger.log(level) { "    #{message} (#{time}secs)"}
+    end
+
+    result
+  end
 end

lib/steep/ast/types/class.rb

@@ -8,6 +8,10 @@ def initialize(location: nil)
           @location = location
         end
 
+        def to_s
+          "class"
+        end
+
         def ==(other)
           other.is_a?(Class)
         end

lib/steep/drivers/validate.rb

@@ -23,13 +23,16 @@ def run
           changes = file_loader.load_changes(target.signature_pattern, changes: {})
           controller.update(changes)
 
-          errors = case controller.status
-                   when Services::SignatureService::SyntaxErrorStatus, Services::SignatureService::AncestorErrorStatus
-                     controller.status.diagnostics
-                   when Services::SignatureService::LoadedStatus
-                     check = Subtyping::Check.new(factory: AST::Types::Factory.new(builder: controller.latest_builder))
-                     Signature::Validator.new(checker: check).tap {|v| v.validate() }.each_error.to_a
-                   end
+          errors =
+            Steep.measure "Validation" do
+              case controller.status
+              when Services::SignatureService::SyntaxErrorStatus, Services::SignatureService::AncestorErrorStatus
+                controller.status.diagnostics
+              when Services::SignatureService::LoadedStatus
+                check = Subtyping::Check.new(factory: AST::Types::Factory.new(builder: controller.latest_builder))
+                Signature::Validator.new(checker: check).tap {|v| v.validate() }.each_error.to_a
+              end
+            end
 
           any_error ||= !errors.empty?
 

lib/steep/server/change_buffer.rb

@@ -24,12 +24,16 @@ def pop_buffer
       end
 
       def load_files(project:, commandline_args:)
-        push_buffer do |changes|
-          loader = Services::FileLoader.new(base_dir: project.base_dir)
+        Steep.logger.tagged "#load_files" do
+          push_buffer do |changes|
+            loader = Services::FileLoader.new(base_dir: project.base_dir)
 
-          project.targets.each do |target|
-            loader.load_changes(target.source_pattern, commandline_args, changes: changes)
-            loader.load_changes(target.signature_pattern, changes: changes)
+            Steep.measure "load changes from disk" do
+              project.targets.each do |target|
+                loader.load_changes(target.source_pattern, commandline_args, changes: changes)
+                loader.load_changes(target.signature_pattern, changes: changes)
+              end
+            end
           end
         end
       end

lib/steep/server/master.rb

@@ -305,11 +305,11 @@ def process_message_from_worker(message, worker:)
         case
         when message.key?(:id) && !message.key?(:method)
           # Response from worker
-          Steep.logger.info "Received response #{message[:id]} from worker"
+          Steep.logger.debug { "Received response #{message[:id]} from worker" }
           recon_queue << [message, worker]
         when message.key?(:method) && !message.key?(:id)
           # Notification from worker
-          Steep.logger.info "Received notification #{message[:method]} from worker"
+          Steep.logger.debug { "Received notification #{message[:method]} from worker" }
           write_queue << message
         end
       end