class Fable::Profiler
Simple ink profiler that logs every instruction in the story and counts frequency and timing. To use:
profiler = story.start_profiling! (play your story for a bit) report = profiler.report; story.end_profiling!;
Attributes
The root node in the hierarchical tree of recorded ink timings
The root node in the hierarchical tree of recorded ink timings
The root node in the hierarchical tree of recorded ink timings
The root node in the hierarchical tree of recorded ink timings
The root node in the hierarchical tree of recorded ink timings
The root node in the hierarchical tree of recorded ink timings
The root node in the hierarchical tree of recorded ink timings
The root node in the hierarchical tree of recorded ink timings
The root node in the hierarchical tree of recorded ink timings
The root node in the hierarchical tree of recorded ink timings
The root node in the hierarchical tree of recorded ink timings
Public Class Methods
# File lib/fable/profiler.rb, line 157 def self.format_milliseconds(milliseconds) if milliseconds > 1_000 "#{(milliseconds/1_000.0).round(2)} s" else "#{(milliseconds).round(3)} ms" end end
# File lib/fable/profiler.rb, line 19 def initialize self.root_node = ProfileNode.new self.continue_watch = Stopwatch.new self.step_watch = Stopwatch.new self.snapshot_watch = Stopwatch.new self.step_details = [] self.number_of_continues = 0 self.step_total = 0 self.snapshot_total = 0 self.continue_total = 0 end
Public Instance Methods
Create a large log of all the internal instructions that were evaluated while profiling was active. Log is in a tab-separated format, for easing loading into a spreadsheet
# File lib/fable/profiler.rb, line 136 def mega_log report = StringIO.new report << "Step type\tDescription\tPath\tTime\n" step_details.each do |step| report << "#{step.type}\t#{step.object.to_s}\t#{step.object.path.to_s}\t#{step.time.to_s}\n" end report.rewind report.read end
# File lib/fable/profiler.rb, line 46 def post_continue! self.continue_watch.stop! self.continue_total += continue_watch.elapsed_milliseconds self.number_of_continues += 1 end
# File lib/fable/profiler.rb, line 152 def post_snapshot! self.snapshot_watch.stop! self.snapshot_total += self.snapshot_watch.elapsed_milliseconds end
# File lib/fable/profiler.rb, line 94 def post_step! self.step_watch.stop! duration = step_watch.elapsed_milliseconds self.step_total += duration self.root_node.add_sample(self.current_step_stack, duration) self.current_step_details.time = duration self.step_details << self.current_step_details end
# File lib/fable/profiler.rb, line 42 def pre_continue! self.continue_watch.restart! end
# File lib/fable/profiler.rb, line 148 def pre_snapshot! self.snapshot_watch.restart! end
# File lib/fable/profiler.rb, line 52 def pre_step! self.current_step_stack = nil self.step_watch.restart! end
Generate a printable report based on the data recorded during profiling
# File lib/fable/profiler.rb, line 32 def report <<~STR #{number_of_continues} CONTINUES / LINES: TOTAL TIME: #{self.class.format_milliseconds(continue_total)} SNAPSHOTTING: #{self.class.format_milliseconds(snapshot_total)} OTHER: #{self.class.format_milliseconds(continue_total - (step_total + snapshot_total))} #{root_node.to_s} STR end
# File lib/fable/profiler.rb, line 57 def step!(callstack) self.step_watch.stop! stack = [] callstack.elements.each do |element| stack_element_name = "" if !element.current_pointer.null_pointer? path = element.current_pointer.path path.components.each do |component| if !component.is_index? stack_element_name = component.name break end end end stack << stack_element_name end self.current_step_stack = stack current_object = callstack.current_element.current_pointer.resolve! if current_object.is_a?(ControlCommand) step_type = "#{current_object} CC" else step_type = current_object.class.to_s end self.current_step_details = OpenStruct.new( type: step_type, object: current_object ) self.step_watch.start! end
Generate a printable report specifying the average and maximum times spent stepping over different internal ink instruction types. This report type is primarily used to profile the ink engine itself rather than your own specific ink.
# File lib/fable/profiler.rb, line 108 def step_length_report report = StringIO.new report << "TOTAL:#{root_node.total_milliseconds}ms\n" grouped_step_times = step_details.group_by{|x| x.type } average_step_times = grouped_step_times.map do |type, details| average = details.sum{|x| x.time }/details.size [type, average] end.sort_by{|type, average| average}.reverse.map{|type, average| "#{type}: #{average}ms" } report << "AVERAGE STEP TIMES: #{average_step_times.join(", ")}\n" accumulated_step_times = grouped_step_times.map do |type, details| sum = details.sum{|x| x.time } ["#{type} (x#{details.size})", sum] end.sort_by{|type, sum| sum}.reverse.map{|type, sum| "#{type}: #{sum}ms" } report << "ACCUMULATED STEP TIMES: #{accumulated_step_times.join(", ")}\n" report.rewind report.read end