Skip to content

Commit

Permalink
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
@@ -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
31 changes: 21 additions & 10 deletions src/compiler/crystal/command.cr
Original file line number Diff line number Diff line change
@@ -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
2 changes: 1 addition & 1 deletion src/compiler/crystal/command/cursor.cr
Original file line number Diff line number Diff line change
@@ -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

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

4 changes: 2 additions & 2 deletions src/compiler/crystal/program.cr
Original file line number Diff line number Diff line change
@@ -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")
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
18 changes: 9 additions & 9 deletions src/compiler/crystal/semantic.cr
Original file line number Diff line number Diff line change
@@ -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}
20 changes: 0 additions & 20 deletions src/compiler/crystal/util.cr
Original file line number Diff line number Diff line change
@@ -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

0 comments on commit be945b5

Please sign in to comment.