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

continue_total[RW]

The root node in the hierarchical tree of recorded ink timings

continue_watch[RW]

The root node in the hierarchical tree of recorded ink timings

current_step_details[RW]

The root node in the hierarchical tree of recorded ink timings

current_step_stack[RW]

The root node in the hierarchical tree of recorded ink timings

number_of_continues[RW]

The root node in the hierarchical tree of recorded ink timings

root_node[RW]

The root node in the hierarchical tree of recorded ink timings

snapshot_total[RW]

The root node in the hierarchical tree of recorded ink timings

snapshot_watch[RW]

The root node in the hierarchical tree of recorded ink timings

step_details[RW]

The root node in the hierarchical tree of recorded ink timings

step_total[RW]

The root node in the hierarchical tree of recorded ink timings

step_watch[RW]

The root node in the hierarchical tree of recorded ink timings

Public Class Methods

format_milliseconds(milliseconds) click to toggle source
# 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
new() click to toggle source
# 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

mega_log() click to toggle source

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
post_continue!() click to toggle source
# 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
post_snapshot!() click to toggle source
# File lib/fable/profiler.rb, line 152
def post_snapshot!
  self.snapshot_watch.stop!
  self.snapshot_total += self.snapshot_watch.elapsed_milliseconds
end
post_step!() click to toggle source
# 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
pre_continue!() click to toggle source
# File lib/fable/profiler.rb, line 42
def pre_continue!
  self.continue_watch.restart!
end
pre_snapshot!() click to toggle source
# File lib/fable/profiler.rb, line 148
def pre_snapshot!
  self.snapshot_watch.restart!
end
pre_step!() click to toggle source
# File lib/fable/profiler.rb, line 52
def pre_step!
  self.current_step_stack = nil
  self.step_watch.restart!
end
report() click to toggle source

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
step!(callstack) click to toggle source
# 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
step_length_report() click to toggle source

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