Class: Rubinius::Profiler::Instrumenter
- Inherits:
-
Object
- Object
- Rubinius::Profiler::Instrumenter
- Includes:
- Stats::Units
- Defined in:
- lib/rubinius/profiler/profiler.rb
Overview
Interface to VM’s instrumenting profiler.
Constant Summary collapse
- SHORT_LINES =
45
- HEADER_INDEX =
{ :percent => 0, :total_seconds => 1, :self_seconds => 2, :calls => 3, :self_ms => 4, :total_ms => 5, :name => 6 }
Instance Attribute Summary collapse
-
#info ⇒ Object
readonly
Returns the value of attribute info.
-
#options ⇒ Object
readonly
Returns the value of attribute options.
Class Method Summary collapse
Instance Method Summary collapse
- #__stop__ ⇒ Object
- #epilogue(out, size, calls) ⇒ Object
- #flat(out) ⇒ Object
- #graph(out) ⇒ Object
- #graph_method_index(index) ⇒ Object
-
#initialize(options = {}) ⇒ Instrumenter
constructor
A new instance of Instrumenter.
- #json(path) ⇒ Object
-
#profile(display = true) ⇒ Object
Convenience method to profile snippets of code in a larger script or program.
-
#set_options(options) ⇒ Object
Set options for profiler output.
- #show(out = $stdout) ⇒ Object
- #sort_order ⇒ Object
- #start ⇒ Object
- #stop ⇒ Object
- #thread_flat(out, t_id, info) ⇒ Object
-
#thread_graph(out, t_id, info) ⇒ Object
Prints an entry for each method, along with the method’s callers and the methods called.
Constructor Details
#initialize(options = {}) ⇒ Instrumenter
Returns a new instance of Instrumenter.
27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 |
# File 'lib/rubinius/profiler/profiler.rb', line 27 def initialize( = {}) Instrumenter.load @options = { :sort => :percent } :full_report => true if Config["profiler.full_report"] :graph => true if Config["profiler.graph"] if path = Config["profiler.json"] :json => path end if name = Config["profiler.output"] :output => "#{File.(name)}-#{$$}" end if Config['profiler.cumulative_percentage'] :cumulative_percentage => true end if Config['profiler.classes'] :classes => true end end |
Instance Attribute Details
#info ⇒ Object (readonly)
Returns the value of attribute info.
10 11 12 |
# File 'lib/rubinius/profiler/profiler.rb', line 10 def info @info end |
#options ⇒ Object (readonly)
Returns the value of attribute options.
10 11 12 |
# File 'lib/rubinius/profiler/profiler.rb', line 10 def @options end |
Class Method Details
.active? ⇒ Boolean
16 17 18 |
# File 'lib/rubinius/profiler/profiler.rb', line 16 def self.active? Rubinius::Tooling.active? end |
.available? ⇒ Boolean
12 13 14 |
# File 'lib/rubinius/profiler/profiler.rb', line 12 def self.available? Rubinius::Tooling.available? end |
.load ⇒ Object
21 22 23 24 25 |
# File 'lib/rubinius/profiler/profiler.rb', line 21 def self.load return if @loaded Rubinius::Tooling.load File.("../ext/profiler", __FILE__) @loaded = true end |
Instance Method Details
#__stop__ ⇒ Object
74 75 76 |
# File 'lib/rubinius/profiler/profiler.rb', line 74 def __stop__ Rubinius::Tooling.disable end |
#epilogue(out, size, calls) ⇒ Object
122 123 124 125 126 127 |
# File 'lib/rubinius/profiler/profiler.rb', line 122 def epilogue(out, size, calls) unless [:full_report] or size < SHORT_LINES out.puts "\n#{comma(size-SHORT_LINES)} methods omitted" end out.puts "\n#{comma(size)} methods called a total of #{comma(calls)} times" end |
#flat(out) ⇒ Object
129 130 131 132 133 134 135 136 |
# File 'lib/rubinius/profiler/profiler.rb', line 129 def flat(out) keys = @info.keys.sort keys.each do |t_id| thread_flat out, t_id, @info[t_id] puts end end |
#graph(out) ⇒ Object
295 296 297 298 299 300 301 302 |
# File 'lib/rubinius/profiler/profiler.rb', line 295 def graph(out) keys = @info.keys.sort keys.each do |t_id| thread_graph out, t_id, @info[t_id] out.puts end end |
#graph_method_index(index) ⇒ Object
424 425 426 |
# File 'lib/rubinius/profiler/profiler.rb', line 424 def graph_method_index(index) index ? " [#{index}]" : "" end |
#json(path) ⇒ Object
232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275 276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 |
# File 'lib/rubinius/profiler/profiler.rb', line 232 def json(path) File.open path, "w" do |f| t_final = @info.size - 1 t_idx = 0 f.puts "[" @info.each do |t_id, info| f.puts "{" f.puts " \"thread_id\": #{t_id}," f.puts " \"runtime\": #{info[:runtime]}," f.puts " \"total_nodes\": #{info[:total_nodes]}," roots = info[:roots].map { |x| x.to_s.dump }.join(',') f.puts " \"roots\": [ #{roots} ]," f.puts " \"nodes\": {" idx = 0 final = info[:nodes].size - 1 info[:nodes].each do |n_id, data| f.puts " \"#{n_id}\": {" f.puts " \"method\": #{data[0]}, \"total\": #{data[1]}, \"called\": #{data[2]}," f.puts " \"total_nodes\": #{data[3]}, \"sub_nodes\": [ #{data[4].join(', ')} ]" if idx == final f.puts " }" else f.puts " }," end idx += 1 end f.puts " }," f.puts " \"methods\": {" idx = 0 final = info[:methods].size - 1 info[:methods].each do |m_id, m| f.puts " \"#{m_id}\": {" f.puts " \"name\": \"#{m[:name]}\", \"file\": \"#{m[:file]}\", \"line\": #{m[:line] || 0}," f.puts " \"cumulative\": #{m[:cumulative]}, \"total\": #{m[:total]}, \"called\": #{m[:called]}" if idx == final f.puts " }" else f.puts " }," end idx += 1 end f.puts " }" if t_idx == t_final f.puts "}" else f.puts "}," end t_idx += 1 end f.puts "]" end puts "Wrote JSON to: #{path}" end |
#profile(display = true) ⇒ Object
Convenience method to profile snippets of code in a larger script or program. Enables the profiler and yields to the given block.
pr = Rubinius::Profiler::Instrumenter.new
pr.profile { # do some work here }
87 88 89 90 91 92 93 |
# File 'lib/rubinius/profiler/profiler.rb', line 87 def profile(display = true) start yield if block_given? stop show if display @info end |
#set_options(options) ⇒ Object
Add options for GC allocation counts
Set options for profiler output. Presently, the only option is :sort. It takes a single symbol or an array of symbols to specify the column(s) to sort by. The recognized symbols are:
Symbol Profiler heading
:percent % time
:total_seconds cumulative seconds
:self_seconds self seconds
:calls calls
:self_ms self ms/call
:total_ms total ms/call
:name name
66 67 68 |
# File 'lib/rubinius/profiler/profiler.rb', line 66 def () @options.merge!() end |
#show(out = $stdout) ⇒ Object
97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 |
# File 'lib/rubinius/profiler/profiler.rb', line 97 def show(out=$stdout) unless self.class.available? and @info out.puts "No profiling data was available" return end begin if name = [:output] out = File.open name, "w" end if [:json] json [:json] elsif [:graph] graph out else flat out end ensure out.close if [:output] end nil end |
#sort_order ⇒ Object
438 439 440 441 |
# File 'lib/rubinius/profiler/profiler.rb', line 438 def sort_order # call to_i so if unrecognized symbol is passed, column will be percent Array(@options[:sort]).map { |header| HEADER_INDEX[header].to_i } end |
#start ⇒ Object
70 71 72 |
# File 'lib/rubinius/profiler/profiler.rb', line 70 def start Rubinius::Tooling.enable end |
#stop ⇒ Object
78 79 80 |
# File 'lib/rubinius/profiler/profiler.rb', line 78 def stop @info = __stop__ end |
#thread_flat(out, t_id, info) ⇒ Object
138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 |
# File 'lib/rubinius/profiler/profiler.rb', line 138 def thread_flat(out, t_id, info) total_calls = 0 total = 0.0 all_selves = 0.0 # Because the info is actually in a tree form and we to just see it # flat for each method, we need to go through and collect all the stats # for each unique method. info[:nodes].each do |n_id, data| sub = data[4].inject(0) do |a,n| next unless x = info[:nodes][n] a + x[1] end meth = info[:methods][data[0]] if cur = meth[:edge_total] meth[:edge_total] = cur + sub else meth[:edge_total] = sub end end data = info[:methods].values.map do |m| cumulative = m[:cumulative] method_total = m[:total] edges_total = m[:edge_total] self_total = method_total - edges_total called = m[:called] total += method_total total_calls += called all_selves += self_total name = m[:name] name = "#toplevel" if name == "<metaclass>#__script__ {}" [ 0, sec(cumulative), sec(self_total), called, msec(self_total) / called, msec(cumulative) / called, name ] end all_selves = sec(all_selves) if [:cumulative_percentage] data.each do |d| d[0] = (d[1] / sec(info[:runtime])) * 100 end else data.each do |d| d[0] = (d[2] / all_selves) * 100 end end columns = sort_order data = data.sort_by do |row| columns.map {|col| row[col] } end.reverse out.puts "Thread #{t_id}: total running time: #{sec(info[:runtime])}s" out.puts "" out.puts " % cumulative self self total" out.puts " time seconds seconds calls ms/call ms/call name" out.puts "------------------------------------------------------------" report = [:full_report] ? data : data.first(SHORT_LINES) report.each do |d| out.printf " %6s", ("%.2f" % d[0]) out.printf "%8.2f %8.2f %10d %8.2f %8.2f %s\n", *d.last(6) end epilogue out, data.size, total_calls if [:classes] classes = Hash.new { |h,k| h[k] = 0.0 } data.each do |row| if m = /(.*)[#\.]/.match(row.last) classes[m[1]] += ((row[2] / all_selves) * 100) end end out.puts "\nUsage percentage by class:" sorted = classes.to_a.sort_by { |row| row[1] }.reverse sorted.each do |row| out.printf "%6s: %s\n", ("%.2f" % row[1]), row[0] end end end |
#thread_graph(out, t_id, info) ⇒ Object
Prints an entry for each method, along with the method’s callers and the methods called. The entry is delimited by the dashed lines. The line for the method itself is called the “primary” line. The callers are printed above the primary line and the methods called are printed below.
309 310 311 312 313 314 315 316 317 318 319 320 321 322 323 324 325 326 327 328 329 330 331 332 333 334 335 336 337 338 339 340 341 342 343 344 345 346 347 348 349 350 351 352 353 354 355 356 357 358 359 360 361 362 363 364 365 366 367 368 369 370 371 372 373 374 375 376 377 378 379 380 381 382 383 384 385 386 387 388 389 390 391 392 393 394 395 396 397 398 399 400 401 402 403 404 405 406 407 408 409 410 411 412 413 414 415 416 417 418 419 420 421 422 |
# File 'lib/rubinius/profiler/profiler.rb', line 309 def thread_graph(out, t_id, info) total_calls = 0 run_total = 0.0 data = info[:nodes] methods = info[:methods] run_total = info[:runtime].to_f all_callers = Hash.new { |h,k| h[k] = [] } data.each do |n_id, n_data| n_data[4].each do |sub| all_callers[sub] << n_id end end indexes = data.keys.sort do |a, b| data[b][1] <=> data[a][1] end indexes = indexes.first(SHORT_LINES) unless [:full_report] shown_indexes = {} indexes.each_with_index do |id, index| shown_indexes[id] = index + 1 end out.puts "===== Thread #{t_id} =====" out.puts "Total running time: #{sec(info[:runtime])}s" out.puts "index % time self children called name" out.puts "----------------------------------------------------------" primary = "%-7s%6s %8.2f %9.2f %8d %s [%d]\n" secondary = " %8.2f %9.2f %8d %s%s\n" indexes.each do |id| m_id, total, called, tn, sub_nodes = data[id] # The idea is to report information about caller as a ratio of the # time it called method. # callers = all_callers[id].sort_by do |c_id| clr = data[c_id] clr[total] end callers = callers.first(10) unless [:full_report] callers.each do |c_id| clr_m_id, clr_total, clr_called, clr_tn, clr_sub = data[c_id] sub_total = clr_sub.inject(0) { |a,s| a + data[s][1] } self_total = clr_total - sub_total out.printf(secondary, sec(self_total), sec(sub_total), clr_called, methods[clr_m_id][:name], graph_method_index(shown_indexes[c_id])) end # Now the primary line. children = sub_nodes.inject(0) { |a,s| a + data[s][1] } # children = method[:cumulative] * (method[:edges_total].to_f / method[:total]) self_total = total - children out.printf primary, ("[%d]" % shown_indexes[id]), percentage(total, run_total, 1, nil), sec(self_total), sec(children), called, methods[m_id][:name], shown_indexes[id] # Same as caller, the idea is to report information about callee methods # as a ratio of the time it was called from method. # edges = sub_nodes.sort_by do |e_id| if edge = data[e_id] edge[1] else 0.0 end end edges = edges.last(10) unless [:full_report] # method[:edges] = method[:edges].first(10) unless options[:full_report] edges.reverse_each do |e_id| c_m_id, c_total, c_called, c_tn, c_sub_nodes = data[e_id] grandchildren = c_sub_nodes.inject(0) { |a,s| a + data[s][1] } grandchildren = 0 if grandchildren < 0 self_total = c_total - grandchildren out.printf secondary, sec(self_total), sec(grandchildren), c_called, methods[c_m_id][:name], graph_method_index(shown_indexes[e_id]) end out.puts "-------------------------------------------------------" end epilogue out, data.size, total_calls end |