Added compile progress tracker (#4182)

* Added compile progress tracker
crystal-lang · May 19, 2017 · be945b5 · be945b5
1 parent 96169cc
commit be945b5
Showing 9 changed files with 133 additions and 60 deletions.
diff --git a/Makefile b/Makefile
@@ -4,6 +4,8 @@
 
 ## Build the compiler
 ##   $ make
+## Build the compiler with progress output
+##   $ make progress=true
 ## Clean up built files then build the compiler
 ##   $ make clean crystal
 ## Build the compiler in release mode
@@ -15,6 +17,7 @@ LLVM_CONFIG ?= ## llvm-config command path to use
 
 release ?=      ## Compile in release mode
 stats ?=        ## Enable statistics output
+progress ?=     ## Enable progress output
 threads ?=      ## Maximum number of threads to use
 debug ?=        ## Add symbolic debug info
 verbose ?=      ## Run specs in verbose mode
@@ -23,7 +26,7 @@ junit_output ?= ## Directory to output junit results
 O := .build
 SOURCES := $(shell find src -name '*.cr')
 SPEC_SOURCES := $(shell find spec -name '*.cr')
-FLAGS := $(if $(release),--release )$(if $(stats),--stats )$(if $(threads),--threads $(threads) )$(if $(debug),-d )
+FLAGS := $(if $(release),--release )$(if $(stats),--stats )$(if $(progress),--progress )$(if $(threads),--threads $(threads) )$(if $(debug),-d )
 SPEC_FLAGS := $(if $(verbose),-v )$(if $(junit_output),--junit_output $(junit_output) )
 EXPORTS := $(if $(release),,CRYSTAL_CONFIG_PATH=`pwd`/src)
 SHELL = bash

diff --git a/src/compiler/crystal/command.cr b/src/compiler/crystal/command.cr
@@ -53,7 +53,7 @@ class Crystal::Command
 
   def initialize(@options : Array(String))
     @color = true
-    @stats = @time = false
+    @progress_tracker = ProgressTracker.new
   end
 
   def run
@@ -177,7 +177,7 @@ class Crystal::Command
 
   private def hierarchy
     config, result = compile_no_codegen "tool hierarchy", hierarchy: true, top_level: true
-    Crystal.timing("Tool (hierarchy)", @stats, delay: true) do
+    @progress_tracker.stage("Tool (hierarchy)") do
       Crystal.print_hierarchy result.program, config.hierarchy_exp, config.output_format
     end
   end
@@ -197,7 +197,7 @@ class Crystal::Command
 
   private def types
     config, result = compile_no_codegen "tool types"
-    Crystal.timing("Tool (types)", @stats, delay: true) do
+    @progress_tracker.stage("Tool (types)") do
       Crystal.print_types result.node
     end
   end
@@ -212,20 +212,25 @@ class Crystal::Command
   end
 
   private def execute(output_filename, run_args)
-    stats = @stats || !@time
-    status = Crystal.timing("Execute", @stats || @time, delay: true, display_memory: stats, padding_size: stats ? 34 : 0) do
+    time? = @time && !@progress_tracker.stats?
+    status, elapsed_time = @progress_tracker.stage("Execute") do
       begin
+        start_time = Time.now
         Process.run(output_filename, args: run_args, input: true, output: true, error: true) do |process|
           # Ignore the signal so we don't exit the running process
           # (the running process can still handle this signal)
           Signal::INT.ignore # do
         end
-        $?
+        {$?, Time.now - start_time}
       ensure
         File.delete(output_filename) rescue nil
       end
     end
 
+    if time?
+      puts "Execute: #{elapsed_time}"
+    end
+
     if status.normal_exit?
       exit status.exit_code
     else
@@ -268,6 +273,7 @@ class Crystal::Command
                               hierarchy = false, cursor_command = false,
                               single_file = false)
     compiler = Compiler.new
+    compiler.progress_tracker = @progress_tracker
     link_flags = [] of String
     opt_filenames = nil
     opt_arguments = nil
@@ -370,8 +376,11 @@ class Crystal::Command
       end
 
       opts.on("-s", "--stats", "Enable statistics output") do
-        @stats = true
-        compiler.stats = true
+        @progress_tracker.stats = true
+      end
+
+      opts.on("-p", "--progress", "Enable progress output") do
+        @progress_tracker.progress = true
       end
 
       opts.on("-t", "--time", "Enable execution time output") do
@@ -467,8 +476,10 @@ class Crystal::Command
       compiler.release = true
     end
     opts.on("-s", "--stats", "Enable statistics output") do
-      @stats = true
-      compiler.stats = true
+      compiler.progress_tracker.stats = true
+    end
+    opts.on("-p", "--progress", "Enable progress output") do
+      compiler.progress_tracker.progress = true
     end
     opts.on("-t", "--time", "Enable execution time output") do
       @time = true

diff --git a/src/compiler/crystal/command/cursor.cr b/src/compiler/crystal/command/cursor.cr
@@ -51,7 +51,7 @@ class Crystal::Command
 
     file = File.expand_path(file)
 
-    result = Crystal.timing("Tool (#{command.split(' ')[1]})", @stats) do
+    result = @progress_tracker.stage("Tool (#{command.split(' ')[1]})") do
       yield Location.new(file, line_number, column_number), config, result
     end
 

diff --git a/src/compiler/crystal/compiler.cr b/src/compiler/crystal/compiler.cr
@@ -82,8 +82,8 @@ module Crystal
     # one LLVM module is created for each type in a program.
     property? single_module = false
 
-    # If `true`, prints time and memory stats to `stdout`.
-    property? stats = false
+    # Set to a `ProgressTracker` object which tracks compilation progress.
+    property progress_tracker = ProgressTracker.new
 
     # Target triple to use in the compilation.
     # If not set, asks LLVM the default one for the current machine.
@@ -136,8 +136,11 @@ module Crystal
       node = parse program, source
       node = program.semantic node, cleanup: !no_cleanup?
       result = codegen program, node, source, output_filename unless @no_codegen
+
+      @progress_tracker.clear
       print_macro_run_stats(program)
       print_codegen_stats(result)
+
       Result.new program, node
     end
 
@@ -156,7 +159,10 @@ module Crystal
       program = new_program(source)
       node = parse program, source
       node, processor = program.top_level_semantic(node)
+
+      @progress_tracker.clear
       print_macro_run_stats(program)
+
       Result.new program, node
     end
 
@@ -172,12 +178,12 @@ module Crystal
       program.color = color?
       program.stdout = stdout
       program.show_error_trace = show_error_trace?
-      program.wants_stats = @stats
+      program.progress_tracker = @progress_tracker
       program
     end
 
     private def parse(program, sources : Array)
-      Crystal.timing("Parse", @stats) do
+      @progress_tracker.stage("Parse") do
         nodes = sources.map do |source|
           # We add the source to the list of required file,
           # so it can't be required again
@@ -222,7 +228,7 @@ module Crystal
     private def codegen(program : Program, node, sources, output_filename)
       @link_flags = "#{@link_flags} -rdynamic"
 
-      llvm_modules = Crystal.timing("Codegen (crystal)", @stats) do
+      llvm_modules = @progress_tracker.stage("Codegen (crystal)") do
         program.codegen node, debug: debug, single_module: @single_module || @release || @cross_compile || @emit, expose_crystal_main: false
       end
 
@@ -272,7 +278,9 @@ module Crystal
       target_triple = target_machine.triple
       reused = [] of String
 
-      Crystal.timing("Codegen (bc+obj)", @stats) do
+      @progress_tracker.stage("Codegen (bc+obj)") do
+        @progress_tracker.stage_progress_total = units.size
+
         if units.size == 1
           first_unit = units.first
           first_unit.compile
@@ -293,7 +301,7 @@ module Crystal
 
       output_filename = File.expand_path(output_filename)
 
-      Crystal.timing("Codegen (linking)", @stats) do
+      @progress_tracker.stage("Codegen (linking)") do
         Dir.cd(output_dir) do
           system %(#{CC} -o "#{output_filename}" "${@}" #{@link_flags} #{lib_flags}), object_names
         end
@@ -314,11 +322,13 @@ module Crystal
           # .o files were reused, mainly to detect performance regressions.
           # Because we fork, we must communicate using a pipe.
           reused = [] of String
-          if @stats
+          if @progress_tracker.stats? || @progress_tracker.progress?
             pr, pw = IO.pipe
             spawn do
               pr.each_line do |line|
-                reused << line
+                unit = JSON.parse(line)
+                reused << unit["name"].as_s if unit["reused"].as_bool
+                @progress_tracker.stage_progress += 1
               end
             end
           end
@@ -327,8 +337,9 @@ module Crystal
             pipe_w = pw
             slice.each do |unit|
               unit.compile
-              if pipe_w && unit.reused_previous_compilation?
-                pipe_w.puts unit.name
+              if pipe_w
+                unit_json = {name: unit.name, reused: unit.reused_previous_compilation?}.to_json
+                pipe_w.puts unit_json
               end
             end
           end
@@ -352,7 +363,8 @@ module Crystal
     end
 
     private def print_macro_run_stats(program)
-      return unless @stats && !program.compiled_macros_cache.empty?
+      return unless @progress_tracker.stats?
+      return if program.compiled_macros_cache.empty?
 
       puts
       puts "Macro runs:"
@@ -370,7 +382,7 @@ module Crystal
     end
 
     private def print_codegen_stats(result)
-      return unless @stats
+      return unless @progress_tracker.stats?
       return unless result
 
       units, reused = result

diff --git a/src/compiler/crystal/macros/macros.cr b/src/compiler/crystal/macros/macros.cr
@@ -101,7 +101,7 @@ class Crystal::Program
   end
 
   def macro_compile(filename)
-    time = wants_stats? ? Time.now : Time.epoch(0)
+    time = Time.now
 
     source = File.read(filename)
 
@@ -124,7 +124,7 @@ class Crystal::Program
     File.utime(now, now, program_dir)
 
     if can_reuse_previous_compilation?(filename, executable_path, recorded_requires_path, requires_path)
-      elapsed_time = wants_stats? ? (Time.now - time) : Time::Span.zero
+      elapsed_time = Time.now - time
       return CompiledMacroRun.new(executable_path, elapsed_time, true)
     end
 
@@ -163,8 +163,7 @@ class Crystal::Program
       requires_with_timestamps.to_json(file)
     end
 
-    elapsed_time = wants_stats? ? (Time.now - time) : Time::Span.zero
-
+    elapsed_time = Time.now - time
     CompiledMacroRun.new(executable_path, elapsed_time, false)
   end
 

diff --git a/src/compiler/crystal/program.cr b/src/compiler/crystal/program.cr
@@ -110,8 +110,8 @@ module Crystal
     # The main filename of this program
     property filename : String?
 
-    # If `true`, prints time and memory stats to `stdout`.
-    property? wants_stats = false
+    # Set to a `ProgressTracker` object which tracks compilation progress.
+    property progress_tracker = ProgressTracker.new
 
     def initialize
       super(self, self, "main")

diff --git a/src/compiler/crystal/progress_tracker.cr b/src/compiler/crystal/progress_tracker.cr
@@ -0,0 +1,68 @@
+module Crystal
+  class ProgressTracker
+    # FIXME: This assumption is not always true
+    STAGES        = 13
+    STAGE_PADDING = 34
+
+    property? stats = false
+    property? progress = false
+
+    getter current_stage = 1
+    getter current_stage_name : String?
+    getter stage_progress = 0
+    getter stage_progress_total : Int32?
+
+    def stage(name)
+      @current_stage_name = name
+
+      print_progress
+
+      start_time = Time.now
+      retval = yield
+      time_taken = Time.now - start_time
+
+      print_stats(time_taken)
+      print_progress
+
+      @current_stage += 1
+      @stage_progress = 0
+      @stage_progress_total = nil
+
+      retval
+    end
+
+    def clear
+      return unless @progress
+      print " " * (STAGE_PADDING + 5)
+      print "\r"
+    end
+
+    def print_stats(time_taken)
+      return unless @stats
+
+      memory_usage_mb = GC.stats.heap_size / 1024.0 / 1024.0
+      memory_usage_str = " (%7.2fMB)" % {memory_usage_mb} if true # display_memory?
+      justified_name = "#{current_stage_name}:".ljust(STAGE_PADDING)
+      puts "#{justified_name} #{time_taken}#{memory_usage_str}"
+    end
+
+    def print_progress
+      return unless @progress
+
+      if stage_progress_total = @stage_progress_total
+        progress = " [#{@stage_progress}/#{stage_progress_total}]"
+      end
+
+      stage_name = @current_stage_name.try(&.ljust(STAGE_PADDING))
+      print "[#{@current_stage}/#{STAGES}]#{progress} #{stage_name}\r"
+    end
+
+    def stage_progress=(@stage_progress)
+      print_progress
+    end
+
+    def stage_progress_total=(@stage_progress_total)
+      print_progress
+    end
+  end
+end
diff --git a/src/compiler/crystal/semantic.cr b/src/compiler/crystal/semantic.cr
@@ -21,30 +21,30 @@ class Crystal::Program
   def semantic(node : ASTNode, cleanup = true) : ASTNode
     node, processor = top_level_semantic(node)
 
-    Crystal.timing("Semantic (ivars initializers)", @wants_stats) do
+    @progress_tracker.stage("Semantic (ivars initializers)") do
       visitor = InstanceVarsInitializerVisitor.new(self)
       visit_with_finished_hooks(node, visitor)
       visitor.finish
     end
 
-    Crystal.timing("Semantic (cvars initializers)", @wants_stats) do
+    @progress_tracker.stage("Semantic (cvars initializers)") do
       visit_class_vars_initializers(node)
     end
 
     # Check that class vars without an initializer are nilable,
     # give an error otherwise
     processor.check_non_nilable_class_vars_without_initializers
 
-    result = Crystal.timing("Semantic (main)", @wants_stats) do
+    result = @progress_tracker.stage("Semantic (main)") do
       visit_main(node, process_finished_hooks: true, cleanup: cleanup)
     end
 
-    Crystal.timing("Semantic (cleanup)", @wants_stats) do
+    @progress_tracker.stage("Semantic (cleanup)") do
       cleanup_types
       cleanup_files
     end
 
-    Crystal.timing("Semantic (recursive struct check)", @wants_stats) do
+    @progress_tracker.stage("Semantic (recursive struct check)") do
       RecursiveStructChecker.new(self).run
     end
 
@@ -57,19 +57,19 @@ class Crystal::Program
   # This alone is useful for some tools like doc or hierarchy
   # where a full semantic of the program is not needed.
   def top_level_semantic(node)
-    new_expansions = Crystal.timing("Semantic (top level)", @wants_stats) do
+    new_expansions = @progress_tracker.stage("Semantic (top level)") do
       visitor = TopLevelVisitor.new(self)
       node.accept visitor
       visitor.process_finished_hooks
       visitor.new_expansions
     end
-    Crystal.timing("Semantic (new)", @wants_stats) do
+    @progress_tracker.stage("Semantic (new)") do
       define_new_methods(new_expansions)
     end
-    node, processor = Crystal.timing("Semantic (type declarations)", @wants_stats) do
+    node, processor = @progress_tracker.stage("Semantic (type declarations)") do
       TypeDeclarationProcessor.new(self).process(node)
     end
-    Crystal.timing("Semantic (abstract def check)", @wants_stats) do
+    @progress_tracker.stage("Semantic (abstract def check)") do
       AbstractDefChecker.new(self).run
     end
     {node, processor}

diff --git a/src/compiler/crystal/util.cr b/src/compiler/crystal/util.cr
@@ -23,26 +23,6 @@ module Crystal
     exit(exit_code) if exit_code
   end
 
-  def self.timing(label, stats, delay = false, display_memory = true, padding_size = 34)
-    if stats
-      print "%-*s" % {padding_size, "#{label}:"} unless delay
-      time = Time.now
-      value = yield
-      elapsed_time = Time.now - time
-      LibGC.get_heap_usage_safe(out heap_size, out free_bytes, out unmapped_bytes, out bytes_since_gc, out total_bytes)
-      mb = heap_size / 1024.0 / 1024.0
-      print "%-*s" % {padding_size, "#{label}:"} if delay
-      if display_memory
-        puts " %s (%7.2fMB)" % {elapsed_time, mb}
-      else
-        puts " %s" % elapsed_time
-      end
-      value
-    else
-      yield
-    end
-  end
-
   def self.tempfile(basename)
     CacheDir.instance.join("crystal-run-#{basename}.tmp")
   end