Skip to content

Commit

Permalink
Added compile progress tracker (#4182)
Browse files Browse the repository at this point in the history
* Added compile progress tracker
  • Loading branch information
RX14 authored and Santiago Palladino committed May 19, 2017
1 parent 96169cc commit be945b5
Show file tree
Hide file tree
Showing 9 changed files with 133 additions and 60 deletions.
5 changes: 4 additions & 1 deletion Makefile
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
Expand All @@ -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
Expand Down
31 changes: 21 additions & 10 deletions src/compiler/crystal/command.cr
Original file line number Diff line number Diff line change
Expand Up @@ -53,7 +53,7 @@ class Crystal::Command

def initialize(@options : Array(String))
@color = true
@stats = @time = false
@progress_tracker = ProgressTracker.new
end

def run
Expand Down Expand Up @@ -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
Expand All @@ -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
Expand All @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down
2 changes: 1 addition & 1 deletion src/compiler/crystal/command/cursor.cr
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
38 changes: 25 additions & 13 deletions src/compiler/crystal/compiler.cr
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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

Expand All @@ -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

Expand All @@ -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
Expand Down Expand Up @@ -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

Expand Down Expand Up @@ -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
Expand All @@ -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
Expand All @@ -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
Expand All @@ -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
Expand All @@ -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:"
Expand All @@ -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
Expand Down
7 changes: 3 additions & 4 deletions src/compiler/crystal/macros/macros.cr
Original file line number Diff line number Diff line change
Expand Up @@ -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)

Expand All @@ -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

Expand Down Expand Up @@ -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

Expand Down
4 changes: 2 additions & 2 deletions src/compiler/crystal/program.cr
Original file line number Diff line number Diff line change
Expand Up @@ -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")
Expand Down
68 changes: 68 additions & 0 deletions src/compiler/crystal/progress_tracker.cr
Original file line number Diff line number Diff line change
@@ -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
Loading

0 comments on commit be945b5

Please sign in to comment.