Class: Fable::Profiler

Inherits:
Object
  • Object
show all
Defined in:
lib/fable/profiler.rb

Overview

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!;

Defined Under Namespace

Classes: ProfileNode, Stopwatch

Instance Attribute Summary collapse

Class Method Summary collapse

Instance Method Summary collapse

Constructor Details

#initialize ⇒ Profiler

Returns a new instance of Profiler.



19
20
21
22
23
24
25
26
27
28
29
 
# 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

Instance Attribute Details

#continue_total ⇒ Object

The root node in the hierarchical tree of recorded ink timings



14
15
16
 
# File 'lib/fable/profiler.rb', line 14

def continue_total
  @continue_total
end

#continue_watch ⇒ Object

The root node in the hierarchical tree of recorded ink timings



14
15
16
 
# File 'lib/fable/profiler.rb', line 14

def continue_watch
  @continue_watch
end

#current_step_details ⇒ Object

The root node in the hierarchical tree of recorded ink timings



14
15
16
 
# File 'lib/fable/profiler.rb', line 14

def current_step_details
  @current_step_details
end

#current_step_stack ⇒ Object

The root node in the hierarchical tree of recorded ink timings



14
15
16
 
# File 'lib/fable/profiler.rb', line 14

def current_step_stack
  @current_step_stack
end

#number_of_continues ⇒ Object

The root node in the hierarchical tree of recorded ink timings



14
15
16
 
# File 'lib/fable/profiler.rb', line 14

def number_of_continues
  @number_of_continues
end

#root_node ⇒ Object

The root node in the hierarchical tree of recorded ink timings



14
15
16
 
# File 'lib/fable/profiler.rb', line 14

def root_node
  @root_node
end

#snapshot_total ⇒ Object

The root node in the hierarchical tree of recorded ink timings



14
15
16
 
# File 'lib/fable/profiler.rb', line 14

def snapshot_total
  @snapshot_total
end

#snapshot_watch ⇒ Object

The root node in the hierarchical tree of recorded ink timings



14
15
16
 
# File 'lib/fable/profiler.rb', line 14

def snapshot_watch
  @snapshot_watch
end

#step_details ⇒ Object

The root node in the hierarchical tree of recorded ink timings



14
15
16
 
# File 'lib/fable/profiler.rb', line 14

def step_details
  @step_details
end

#step_total ⇒ Object

The root node in the hierarchical tree of recorded ink timings



14
15
16
 
# File 'lib/fable/profiler.rb', line 14

def step_total
  @step_total
end

#step_watch ⇒ Object

The root node in the hierarchical tree of recorded ink timings



14
15
16
 
# File 'lib/fable/profiler.rb', line 14

def step_watch
  @step_watch
end

Class Method Details

.format_milliseconds(milliseconds) ⇒ Object 



157
158
159
160
161
162
163
 
# 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

Instance Method Details

#mega_log ⇒ Object

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



136
137
138
139
140
141
142
143
144
145
146
 
# 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! ⇒ Object 



46
47
48
49
50
 
# 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! ⇒ Object 



152
153
154
155
 
# 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! ⇒ Object 



94
95
96
97
98
99
100
101
102
 
# 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! ⇒ Object 



42
43
44
 
# File 'lib/fable/profiler.rb', line 42

def pre_continue!
  self.continue_watch.restart!
end

#pre_snapshot! ⇒ Object 



148
149
150
 
# File 'lib/fable/profiler.rb', line 148

def pre_snapshot!
  self.snapshot_watch.restart!
end

#pre_step! ⇒ Object 



52
53
54
55
 
# File 'lib/fable/profiler.rb', line 52

def pre_step!
  self.current_step_stack = nil
  self.step_watch.restart!
end

#report ⇒ Object

Generate a printable report based on the data recorded during profiling



32
33
34
35
36
37
38
39
40
 
# 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) ⇒ Object 



57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
 
# 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 ⇒ Object

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.



108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
 
# 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