Class: Zif::Services::TickTraceService

Inherits:
Object
  • Object
show all
Defined in:
lib/zif/services/tick_trace_service.rb

Overview

This service is for performance tuning your game.

It is set up and torn down for you if you use Zif::Game The idea is that you

  • #reset_tick in the beginning of your tick, then

  • include Traceable and then use #mark to timestamp important areas in your code during a tick,

    (e.g. mark("#my_method: Just did something!") )

  • and finally #finish the tick

If your tick takes longer than #time_threshold, it will report the full trace info and highlight the section which took the most time to execute. The game will begin to dip below 60fps if your tick takes longer than about 16ms, but the default threshold is 20ms so it should only notify you if something is really off.

Turn on running average calculation by setting #measure_averages to true

Instance Attribute Summary collapse

1. Public Interface collapse

2. Private-ish methods collapse

Constructor Details

#initialize(time_threshold: 0.02, measure_averages: false) ⇒ TickTraceService

Returns a new instance of TickTraceService.

Parameters:



44
45
46
47
48
49
50
 
# File 'lib/zif/services/tick_trace_service.rb', line 44

def initialize(time_threshold: 0.02, measure_averages: false)
  @time_threshold = time_threshold
  @measure_averages = measure_averages
  @enabled = true
  clear_averages
  reset_tick
end

Instance Attribute Details

#averages ⇒ Hash (readonly)

Returns A data structure used to save min/max/avg times for each marked section of code.

Returns:

  • (Hash) —

    A data structure used to save min/max/avg times for each marked section of code.



31
32
33
 
# File 'lib/zif/services/tick_trace_service.rb', line 31

def averages
  @averages
end

#last_tick_ms ⇒ String (readonly)

Returns The amount of time the last tick took, in milliseconds, as a string.

Returns:

  • (String) —

    The amount of time the last tick took, in milliseconds, as a string



25
26
27
 
# File 'lib/zif/services/tick_trace_service.rb', line 25

def last_tick_ms
  @last_tick_ms
end

#measure_averages ⇒ Boolean

Returns Should the service report average times? This is somewhat computationally expensive.

Returns:

  • (Boolean) —

    Should the service report average times? This is somewhat computationally expensive.



28
29
30
 
# File 'lib/zif/services/tick_trace_service.rb', line 28

def measure_averages
  @measure_averages
end

#slowest_avg_mark ⇒ String

Returns The amount of time the average slowest marked section of code takes every tick, in ms.

Returns:

  • (String) —

    The amount of time the average slowest marked section of code takes every tick, in ms



34
35
36
 
# File 'lib/zif/services/tick_trace_service.rb', line 34

def slowest_avg_mark
  @slowest_avg_mark
end

#slowest_mark ⇒ String (readonly)

Returns A string label for the slowest measured #marked section of code.

Returns:

  • (String) —

    A string label for the slowest measured #marked section of code.



22
23
24
 
# File 'lib/zif/services/tick_trace_service.rb', line 22

def slowest_mark
  @slowest_mark
end

#slowest_max_mark ⇒ String

Returns The amount of time the slowest marked section of code ever seen took, in ms.

Returns:

  • (String) —

    The amount of time the slowest marked section of code ever seen took, in ms



37
38
39
 
# File 'lib/zif/services/tick_trace_service.rb', line 37

def slowest_max_mark
  @slowest_max_mark
end

#time_threshold ⇒ Float

Returns Time, in seconds. A trace report is generated if your tick takes longer than this amount.

Returns:

  • (Float) —

    Time, in seconds. A trace report is generated if your tick takes longer than this amount.



19
20
21
 
# File 'lib/zif/services/tick_trace_service.rb', line 19

def time_threshold
  @time_threshold
end

Instance Method Details

#clear_averages ⇒ Object

Resets the data saved for average time spent in your marked sections of code. Calculating averages is computationally expensive based on the number of unique marked sections of code that have been measured, so clearing the averages is a good idea if you have built up too many unique sections.



77
78
79
80
81
82
83
84
85
86
 
# File 'lib/zif/services/tick_trace_service.rb', line 77

def clear_averages
  @averages = Hash.new do |h, k|
    h[k] = {
      min:   Float::INFINITY,
      max:   -Float::INFINITY,
      avg:   nil,
      count: 0
    }
  end
end

#disable! ⇒ Object

Turns off the TickTrace analysis



58
59
60
 
# File 'lib/zif/services/tick_trace_service.rb', line 58

def disable!
  @enabled = false
end

#enable! ⇒ Object

Turns on the TickTrace analysis



53
54
55
 
# File 'lib/zif/services/tick_trace_service.rb', line 53

def enable!
  @enabled = true
end

#enabled? ⇒ Boolean

Returns Is TickTrace turned on?.

Returns:

  • (Boolean) —

    Is TickTrace turned on?



63
64
65
 
# File 'lib/zif/services/tick_trace_service.rb', line 63

def enabled?
  @enabled
end

#finish ⇒ Object

This method is part of a private API. You should avoid using this method if possible, as it may be removed or be changed in the future.

You only need to call this method directly if you are using this service without Game. Tells the TickTraceService that the tick is complete and it should finish analysis for this tick. If your tick has taken longer than #time_threshold, a report is generated.



132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
 
# File 'lib/zif/services/tick_trace_service.rb', line 132

def finish
  return unless enabled?

  elapsed = @last_time - @start_time
  @last_tick_ms = format_ms(elapsed)

  if @measure_averages
    avg_culprit, avg_culprit_time = @averages.max_by { |_label, time| time[:avg] }
    @slowest_avg_mark = "'#{avg_culprit}' #{format_ms(avg_culprit_time[:avg])}"
    max_culprit, max_culprit_time = @averages.max_by { |_label, time| time[:max] }
    @slowest_max_mark = "'#{max_culprit}' #{format_ms(max_culprit_time[:max])}"
  end

  over_threshold = (elapsed > @time_threshold)
  return unless over_threshold

  culprit = @times.max_by { |time| time[:delta] }
  @slowest_mark = "'#{culprit[:label]}' #{format_ms(culprit[:delta])}"

  tick_details = "#{@last_tick_ms} elapsed > #{format_ms(@time_threshold)} threshold, "
  tick_details += "longest step #{@slowest_mark}"
  puts '=' * 80
  puts "Zif::Services::TickTraceService: Slow tick. #{tick_details}:"
  print_times
end

#format_ms(in_seconds) ⇒ Object

This method is part of a private API. You should avoid using this method if possible, as it may be removed or be changed in the future.

There’s gotta be a better way to do this.. …all because ‘%3.3f’ % 0.12 will print ‘0.120’ instead of ‘ 0.120’



171
172
173
174
175
176
 
# File 'lib/zif/services/tick_trace_service.rb', line 171

def format_ms(in_seconds)
  ms = in_seconds * 1000.0
  whole_ms = ms.floor
  dec = ms - whole_ms
  "#{'%3d' % whole_ms}#{('%.3f' % dec).gsub('0.', '.')}ms"
end

#last_label ⇒ Object

This is used to extract the name of the last #mark-ed code. Useful for exception messages.



121
122
123
 
# File 'lib/zif/services/tick_trace_service.rb', line 121

def last_label
  @times&.last&.dig(:label)
end

#mark(label) ⇒ Object

Invoke this method to tell the TickTraceService that a section of code has completed. Time is measured between marked sections.

Parameters:

  • label (String) —

    The name of the section of code prior to this call. Used in reporting



91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
 
# File 'lib/zif/services/tick_trace_service.rb', line 91

def mark(label)
  return unless enabled?

  t = Time.now
  delta = t - @last_time
  @times << {
    label:   label,
    delta:   delta,
    elapsed: t - @start_time
  }
  @last_time = t

  return unless @measure_averages

  @averages[label][:min] = [@averages[label][:min], delta].min
  @averages[label][:max] = [@averages[label][:max], delta].max

  if @averages[label][:avg]
    @averages[label][:avg] =
      ((@averages[label][:avg] * @averages[label][:count]) + delta).fdiv(@averages[label][:count] + 1)

  else
    @averages[label][:avg] = delta
  end

  @averages[label][:count] += 1
end

#print_times(indented = 2) ⇒ Object

This method is part of a private API. You should avoid using this method if possible, as it may be removed or be changed in the future.

Prints the time elapsed for each marked section of code in this tick.



160
161
162
163
164
165
166
 
# File 'lib/zif/services/tick_trace_service.rb', line 160

def print_times(indented=2)
  indent = ' ' * indented
  puts "#{indent}#{'%9s' % 'mark'} #{'%9s' % 'delta'} label"
  @times.each do |time|
    puts "#{' ' * indented}#{format_ms(time[:elapsed])} #{format_ms(time[:delta])} #{time[:label]}"
  end
end

#reset_tick ⇒ Object

Resets the time measurement for this tick, typically used at the beginning of your tick.



68
69
70
71
72
 
# File 'lib/zif/services/tick_trace_service.rb', line 68

def reset_tick
  @times = []
  @start_time = Time.now
  @last_time = @start_time
end