[ruby/irb] Change debug test workaround only enabled when output is
[ruby.git] / yjit.rb
blob6612d8bd82cd6563020aed3c6a641bc059b2e31f
1 # frozen_string_literal: true
2 # :markup: markdown
4 # This module allows for introspection of \YJIT, CRuby's just-in-time compiler.
5 # Everything in the module is highly implementation specific and the API might
6 # be less stable compared to the standard library.
8 # This module may not exist if \YJIT does not support the particular platform
9 # for which CRuby is built.
10 module RubyVM::YJIT
11   # Check if \YJIT is enabled.
12   def self.enabled?
13     Primitive.cexpr! 'RBOOL(rb_yjit_enabled_p)'
14   end
16   # Check if `--yjit-stats` is used.
17   def self.stats_enabled?
18     Primitive.rb_yjit_stats_enabled_p
19   end
21   # Check if rb_yjit_trace_exit_locations_enabled_p is enabled.
22   def self.trace_exit_locations_enabled? # :nodoc:
23     Primitive.rb_yjit_trace_exit_locations_enabled_p
24   end
26   # Discard statistics collected for `--yjit-stats`.
27   def self.reset_stats!
28     Primitive.rb_yjit_reset_stats_bang
29   end
31   # Enable \YJIT compilation. `stats` option decides whether to enable \YJIT stats or not.
32   #
33   # * `false`: Disable stats.
34   # * `true`: Enable stats. Print stats at exit.
35   # * `:quiet`: Enable stats. Do not print stats at exit.
36   def self.enable(stats: false)
37     return false if enabled?
38     at_exit { print_and_dump_stats } if stats
39     Primitive.rb_yjit_enable(stats, stats != :quiet)
40   end
42   # If --yjit-trace-exits is enabled parse the hashes from
43   # Primitive.rb_yjit_get_exit_locations into a format readable
44   # by Stackprof. This will allow us to find the exact location of a
45   # side exit in YJIT based on the instruction that is exiting.
46   def self.exit_locations # :nodoc:
47     return unless trace_exit_locations_enabled?
49     results = Primitive.rb_yjit_get_exit_locations
50     raw_samples = results[:raw].dup
51     line_samples = results[:lines].dup
52     frames = results[:frames].dup
53     samples_count = 0
55     # Loop through the instructions and set the frame hash with the data.
56     # We use nonexistent.def for the file name, otherwise insns.def will be displayed
57     # and that information isn't useful in this context.
58     RubyVM::INSTRUCTION_NAMES.each_with_index do |name, frame_id|
59       frame_hash = { samples: 0, total_samples: 0, edges: {}, name: name, file: "nonexistent.def", line: nil, lines: {} }
60       results[:frames][frame_id] = frame_hash
61       frames[frame_id] = frame_hash
62     end
64     # Loop through the raw_samples and build the hashes for StackProf.
65     # The loop is based off an example in the StackProf documentation and therefore
66     # this functionality can only work with that library.
67     #
68     # Raw Samples:
69     # [ length, frame1, frame2, frameN, ..., instruction, count
70     #
71     # Line Samples
72     # [ length, line_1, line_2, line_n, ..., dummy value, count
73     i = 0
74     while i < raw_samples.length
75       stack_length = raw_samples[i]
76       i += 1 # consume the stack length
78       sample_count = raw_samples[i + stack_length]
80       prev_frame_id = nil
81       stack_length.times do |idx|
82         idx += i
83         frame_id = raw_samples[idx]
85         if prev_frame_id
86           prev_frame = frames[prev_frame_id]
87           prev_frame[:edges][frame_id] ||= 0
88           prev_frame[:edges][frame_id] += sample_count
89         end
91         frame_info = frames[frame_id]
92         frame_info[:total_samples] += sample_count
94         frame_info[:lines][line_samples[idx]] ||= [0, 0]
95         frame_info[:lines][line_samples[idx]][0] += sample_count
97         prev_frame_id = frame_id
98       end
100       i += stack_length # consume the stack
102       top_frame_id = prev_frame_id
103       top_frame_line = 1
105       frames[top_frame_id][:samples] += sample_count
106       frames[top_frame_id][:lines] ||= {}
107       frames[top_frame_id][:lines][top_frame_line] ||= [0, 0]
108       frames[top_frame_id][:lines][top_frame_line][1] += sample_count
110       samples_count += sample_count
111       i += 1
112     end
114     results[:samples] = samples_count
115     # Set missed_samples and gc_samples to 0 as their values
116     # don't matter to us in this context.
117     results[:missed_samples] = 0
118     results[:gc_samples] = 0
119     results
120   end
122   # Marshal dumps exit locations to the given filename.
123   #
124   # Usage:
125   #
126   # If `--yjit-exit-locations` is passed, a file named
127   # "yjit_exit_locations.dump" will automatically be generated.
128   #
129   # If you want to collect traces manually, call `dump_exit_locations`
130   # directly.
131   #
132   # Note that calling this in a script will generate stats after the
133   # dump is created, so the stats data may include exits from the
134   # dump itself.
135   #
136   # In a script call:
137   #
138   #     at_exit do
139   #       RubyVM::YJIT.dump_exit_locations("my_file.dump")
140   #     end
141   #
142   # Then run the file with the following options:
143   #
144   #     ruby --yjit --yjit-trace-exits test.rb
145   #
146   # Once the code is done running, use Stackprof to read the dump file.
147   # See Stackprof documentation for options.
148   def self.dump_exit_locations(filename)
149     unless trace_exit_locations_enabled?
150       raise ArgumentError, "--yjit-trace-exits must be enabled to use dump_exit_locations."
151     end
153     File.binwrite(filename, Marshal.dump(RubyVM::YJIT.exit_locations))
154   end
156   # Return a hash for statistics generated for the `--yjit-stats` command line option.
157   # Return `nil` when option is not passed or unavailable.
158   def self.runtime_stats(context: false)
159     stats = Primitive.rb_yjit_get_stats(context)
160     return stats if stats.nil?
162     stats[:object_shape_count] = Primitive.object_shape_count
163     return stats unless Primitive.rb_yjit_stats_enabled_p
165     side_exits = total_exit_count(stats)
166     total_exits = side_exits + stats[:leave_interp_return]
168     # Number of instructions that finish executing in YJIT.
169     # See :count-placement: about the subtraction.
170     retired_in_yjit = stats[:yjit_insns_count] - side_exits
172     # Average length of instruction sequences executed by YJIT
173     avg_len_in_yjit = total_exits > 0 ? retired_in_yjit.to_f / total_exits : 0
175     # Proportion of instructions that retire in YJIT
176     total_insns_count = retired_in_yjit + stats[:vm_insns_count]
177     yjit_ratio_pct = 100.0 * retired_in_yjit.to_f / total_insns_count
178     stats[:total_insns_count] = total_insns_count
179     stats[:ratio_in_yjit] = yjit_ratio_pct
181     # Make those stats available in RubyVM::YJIT.runtime_stats as well
182     stats[:side_exit_count]  = side_exits
183     stats[:total_exit_count] = total_exits
184     stats[:avg_len_in_yjit]  = avg_len_in_yjit
186     stats
187   end
189   # Format and print out counters as a String. This returns a non-empty
190   # content only when `--yjit-stats` is enabled.
191   def self.stats_string
192     # Lazily require StringIO to avoid breaking miniruby
193     require 'stringio'
194     strio = StringIO.new
195     _print_stats(out: strio)
196     strio.string
197   end
199   # Produce disassembly for an iseq. This requires a `--enable-yjit=dev` build.
200   def self.disasm(iseq) # :nodoc:
201     # If a method or proc is passed in, get its iseq
202     iseq = RubyVM::InstructionSequence.of(iseq)
204     if !self.enabled?
205       warn(
206         "YJIT needs to be enabled to produce disasm output, e.g.\n" +
207         "ruby --yjit-call-threshold=1 my_script.rb (see doc/yjit/yjit.md)"
208       )
209       return nil
210     end
212     disasm_str = Primitive.rb_yjit_disasm_iseq(iseq)
214     if !disasm_str
215       warn(
216         "YJIT disasm is only available when YJIT is built in dev mode, i.e.\n" +
217         "./configure --enable-yjit=dev (see doc/yjit/yjit.md)\n"
218       )
219       return nil
220     end
222     # Produce the disassembly string
223     # Include the YARV iseq disasm in the string for additional context
224     iseq.disasm + "\n" + disasm_str
225   end
227   # Produce a list of instructions compiled by YJIT for an iseq
228   def self.insns_compiled(iseq) # :nodoc:
229     return nil unless self.enabled?
231     # If a method or proc is passed in, get its iseq
232     iseq = RubyVM::InstructionSequence.of(iseq)
233     Primitive.rb_yjit_insns_compiled(iseq)
234   end
236   # Discard existing compiled code to reclaim memory
237   # and allow for recompilations in the future.
238   def self.code_gc
239     Primitive.rb_yjit_code_gc
240   end
242   def self.simulate_oom! # :nodoc:
243     Primitive.rb_yjit_simulate_oom_bang
244   end
246   # Avoid calling a Ruby method here to not interfere with compilation tests
247   if Primitive.rb_yjit_stats_enabled_p
248     at_exit { print_and_dump_stats }
249   end
251   class << self
252     # :stopdoc:
253     private
255     # Print stats and dump exit locations
256     def print_and_dump_stats # :nodoc:
257       if Primitive.rb_yjit_print_stats_p
258         _print_stats
259       end
260       _dump_locations
261     end
263     def _dump_locations # :nodoc:
264       return unless trace_exit_locations_enabled?
266       filename = "yjit_exit_locations.dump"
267       dump_exit_locations(filename)
269       $stderr.puts("YJIT exit locations dumped to `#{filename}`.")
270     end
272     # Print a summary of reasons for adverse performance events (e.g. exits)
273     def _print_stats_reasons(stats, out) # :nodoc:
274       print_counters(stats, out: out, prefix: 'send_', prompt: 'method call fallback reasons: ')
275       print_counters(stats, out: out, prefix: 'invokeblock_', prompt: 'invokeblock fallback reasons: ')
276       print_counters(stats, out: out, prefix: 'invokesuper_', prompt: 'invokesuper fallback reasons: ')
277       print_counters(stats, out: out, prefix: 'guard_send_', prompt: 'method call exit reasons: ')
278       print_counters(stats, out: out, prefix: 'guard_invokeblock_', prompt: 'invokeblock exit reasons: ')
279       print_counters(stats, out: out, prefix: 'guard_invokesuper_', prompt: 'invokesuper exit reasons: ')
280       print_counters(stats, out: out, prefix: 'gbpp_', prompt: 'getblockparamproxy exit reasons: ')
281       print_counters(stats, out: out, prefix: 'getivar_', prompt: 'getinstancevariable exit reasons:')
282       print_counters(stats, out: out, prefix: 'setivar_', prompt: 'setinstancevariable exit reasons:')
283       %w[
284         branchif
285         branchnil
286         branchunless
287         definedivar
288         expandarray
289         invokebuiltin
290         jump
291         leave
292         objtostring
293         opt_aref
294         opt_aref_with
295         opt_aset
296         opt_case_dispatch
297         opt_div
298         opt_getconstant_path
299         opt_minus
300         opt_mod
301         opt_mult
302         opt_plus
303         opt_succ
304         setlocal
305         splatkw
306       ].each do |insn|
307         print_counters(stats, out: out, prefix: "#{insn}_", prompt: "#{insn} exit reasons:", optional: true)
308       end
309       print_counters(stats, out: out, prefix: 'lshift_', prompt: 'left shift (opt_ltlt) exit reasons: ')
310       print_counters(stats, out: out, prefix: 'rshift_', prompt: 'right shift (>>) exit reasons: ')
311       print_counters(stats, out: out, prefix: 'invalidate_', prompt: 'invalidation reasons: ')
312     end
314     # Format and print out counters
315     def _print_stats(out: $stderr) # :nodoc:
316       stats = runtime_stats(context: true)
317       return unless Primitive.rb_yjit_stats_enabled_p
319       out.puts("***YJIT: Printing YJIT statistics on exit***")
321       _print_stats_reasons(stats, out)
323       # Number of failed compiler invocations
324       compilation_failure = stats[:compilation_failure]
326       code_region_overhead = stats[:code_region_size] - (stats[:inline_code_size] + stats[:outlined_code_size])
328       out.puts "num_send:              " + format_number(13, stats[:num_send])
329       out.puts "num_send_known_class:  " + format_number_pct(13, stats[:num_send_known_class], stats[:num_send])
330       out.puts "num_send_polymorphic:  " + format_number_pct(13, stats[:num_send_polymorphic], stats[:num_send])
331       out.puts "num_send_megamorphic:  " + format_number_pct(13, stats[:send_megamorphic], stats[:num_send])
332       out.puts "num_send_dynamic:      " + format_number_pct(13, stats[:num_send_dynamic], stats[:num_send])
333       out.puts "num_send_cfunc:        " + format_number_pct(13, stats[:num_send_cfunc], stats[:num_send])
334       out.puts "num_send_cfunc_inline: " + format_number_pct(13, stats[:num_send_cfunc_inline], stats[:num_send_cfunc])
335       out.puts "num_send_iseq:         " + format_number_pct(13, stats[:num_send_iseq], stats[:num_send])
336       out.puts "num_send_iseq_leaf:    " + format_number_pct(13, stats[:num_send_iseq_leaf], stats[:num_send_iseq])
337       out.puts "num_send_iseq_inline:  " + format_number_pct(13, stats[:num_send_iseq_inline], stats[:num_send_iseq])
338       if stats[:num_send_x86_rel32] != 0 || stats[:num_send_x86_reg] != 0
339         out.puts "num_send_x86_rel32:    " + format_number(13,  stats[:num_send_x86_rel32])
340         out.puts "num_send_x86_reg:      " + format_number(13, stats[:num_send_x86_reg])
341       end
342       out.puts "num_getivar_megamorphic: " + format_number(11, stats[:num_getivar_megamorphic])
343       out.puts "num_setivar_megamorphic: " + format_number(11, stats[:num_setivar_megamorphic])
344       out.puts "num_opt_case_megamorphic: " + format_number(10, stats[:num_opt_case_dispatch_megamorphic])
345       out.puts "num_throw:             " + format_number(13, stats[:num_throw])
346       out.puts "num_throw_break:       " + format_number_pct(13, stats[:num_throw_break], stats[:num_throw])
347       out.puts "num_throw_retry:       " + format_number_pct(13, stats[:num_throw_retry], stats[:num_throw])
348       out.puts "num_throw_return:      " + format_number_pct(13, stats[:num_throw_return], stats[:num_throw])
349       out.puts "num_lazy_frame_check:  " + format_number(13, stats[:num_lazy_frame_check])
350       out.puts "num_lazy_frame_push:   " + format_number_pct(13, stats[:num_lazy_frame_push], stats[:num_lazy_frame_check])
351       out.puts "lazy_frame_count:      " + format_number(13, stats[:lazy_frame_count])
352       out.puts "lazy_frame_failure:    " + format_number(13, stats[:lazy_frame_failure])
354       out.puts "iseq_stack_too_large:  " + format_number(13, stats[:iseq_stack_too_large])
355       out.puts "iseq_too_long:         " + format_number(13, stats[:iseq_too_long])
356       out.puts "temp_reg_opnd:         " + format_number(13, stats[:temp_reg_opnd])
357       out.puts "temp_mem_opnd:         " + format_number(13, stats[:temp_mem_opnd])
358       out.puts "temp_spill:            " + format_number(13, stats[:temp_spill])
359       out.puts "bindings_allocations:  " + format_number(13, stats[:binding_allocations])
360       out.puts "bindings_set:          " + format_number(13, stats[:binding_set])
361       out.puts "compilation_failure:   " + format_number(13, compilation_failure) if compilation_failure != 0
362       out.puts "live_iseq_count:       " + format_number(13, stats[:live_iseq_count])
363       out.puts "iseq_alloc_count:      " + format_number(13, stats[:iseq_alloc_count])
364       out.puts "compiled_iseq_entry:   " + format_number(13, stats[:compiled_iseq_entry])
365       out.puts "cold_iseq_entry:       " + format_number_pct(13, stats[:cold_iseq_entry], stats[:compiled_iseq_entry] + stats[:cold_iseq_entry])
366       out.puts "compiled_iseq_count:   " + format_number(13, stats[:compiled_iseq_count])
367       out.puts "compiled_blockid_count:" + format_number(13, stats[:compiled_blockid_count])
368       out.puts "compiled_block_count:  " + format_number(13, stats[:compiled_block_count])
369       if stats[:compiled_blockid_count] != 0
370         out.puts "versions_per_block:    " + format_number(13, "%4.3f" % (stats[:compiled_block_count].fdiv(stats[:compiled_blockid_count])))
371       end
372       out.puts "max_inline_versions:   " + format_number(13, stats[:max_inline_versions])
373       out.puts "compiled_branch_count: " + format_number(13, stats[:compiled_branch_count])
374       out.puts "compile_time_ms:       " + format_number(13, stats[:compile_time_ns] / (1000 * 1000))
375       out.puts "block_next_count:      " + format_number(13, stats[:block_next_count])
376       out.puts "defer_count:           " + format_number(13, stats[:defer_count])
377       out.puts "defer_empty_count:     " + format_number(13, stats[:defer_empty_count])
379       out.puts "branch_insn_count:     " + format_number(13, stats[:branch_insn_count])
380       out.puts "branch_known_count:    " + format_number_pct(13, stats[:branch_known_count], stats[:branch_insn_count])
382       out.puts "freed_iseq_count:      " + format_number(13, stats[:freed_iseq_count])
383       out.puts "invalidation_count:    " + format_number(13, stats[:invalidation_count])
384       out.puts "inline_code_size:      " + format_number(13, stats[:inline_code_size])
385       out.puts "outlined_code_size:    " + format_number(13, stats[:outlined_code_size])
386       out.puts "code_region_size:      " + format_number(13, stats[:code_region_size])
387       out.puts "code_region_overhead:  " + format_number_pct(13, code_region_overhead, stats[:code_region_size])
389       out.puts "freed_code_size:       " + format_number(13, stats[:freed_code_size])
390       out.puts "yjit_alloc_size:       " + format_number(13, stats[:yjit_alloc_size]) if stats.key?(:yjit_alloc_size)
391       out.puts "live_context_size:     " + format_number(13, stats[:live_context_size])
392       out.puts "live_context_count:    " + format_number(13, stats[:live_context_count])
393       out.puts "live_page_count:       " + format_number(13, stats[:live_page_count])
394       out.puts "freed_page_count:      " + format_number(13, stats[:freed_page_count])
395       out.puts "code_gc_count:         " + format_number(13, stats[:code_gc_count])
396       out.puts "num_gc_obj_refs:       " + format_number(13, stats[:num_gc_obj_refs])
397       out.puts "object_shape_count:    " + format_number(13, stats[:object_shape_count])
398       out.puts "side_exit_count:       " + format_number(13, stats[:side_exit_count])
399       out.puts "total_exit_count:      " + format_number(13, stats[:total_exit_count])
400       out.puts "total_insns_count:     " + format_number(13, stats[:total_insns_count])
401       out.puts "vm_insns_count:        " + format_number(13, stats[:vm_insns_count])
402       out.puts "yjit_insns_count:      " + format_number(13, stats[:yjit_insns_count])
403       out.puts "ratio_in_yjit:         " + ("%12.1f" % stats[:ratio_in_yjit]) + "%"
404       out.puts "avg_len_in_yjit:       " + ("%13.1f" % stats[:avg_len_in_yjit])
406       print_sorted_exit_counts(stats, out: out, prefix: "exit_")
408       print_sorted_method_calls(stats[:cfunc_calls], stats[:num_send_cfunc], out: out, type: 'C')
409       print_sorted_method_calls(stats[:iseq_calls], stats[:num_send_iseq], out: out, type: 'ISEQ')
410     end
412     def print_sorted_method_calls(calls, num_calls, out:, type:, how_many: 20, left_pad: 4) # :nodoc:
413       return if calls.empty?
415       # Sort calls by decreasing frequency and keep the top N
416       pairs = calls.map { |k,v| [k, v] }
417       pairs.sort_by! {|pair| -pair[1] }
418       pairs = pairs[0...how_many]
420       top_n_total = pairs.sum { |name, count| count }
421       top_n_pct = 100.0 * top_n_total / num_calls
423       out.puts "Top-#{pairs.size} most frequent #{type} calls (#{"%.1f" % top_n_pct}% of #{type} calls):"
425       count_width = format_number(0, pairs[0][1]).length
426       pairs.each do |name, count|
427         padded_count = format_number_pct(count_width, count, num_calls)
428         out.puts("  #{padded_count}: #{name}")
429       end
430     end
432     def print_sorted_exit_counts(stats, out:, prefix:, how_many: 20, left_pad: 4) # :nodoc:
433       total_exits = total_exit_count(stats)
435       if total_exits > 0
436         exits = []
437         stats.each do |k, v|
438           if k.start_with?(prefix)
439             exits.push [k.to_s.delete_prefix(prefix), v]
440           end
441         end
443         exits = exits.select { |_name, count| count > 0 }.max_by(how_many) { |_name, count| count }
445         top_n_total = exits.sum { |name, count| count }
446         top_n_exit_pct = 100.0 * top_n_total / total_exits
448         out.puts "Top-#{exits.size} most frequent exit ops (#{"%.1f" % top_n_exit_pct}% of exits):"
450         count_width = format_number(0, exits[0][1]).length
451         exits.each do |name, count|
452           padded_count = format_number_pct(count_width, count, total_exits)
453           out.puts("  #{padded_count}: #{name}")
454         end
455       else
456         out.puts "total_exits:           " + format_number(10, total_exits)
457       end
458     end
460     def total_exit_count(stats, prefix: "exit_") # :nodoc:
461       total = 0
462       stats.each do |k,v|
463         total += v if k.start_with?(prefix)
464       end
465       total
466     end
468     def print_counters(counters, out:, prefix:, prompt:, optional: false) # :nodoc:
469       counters = counters.filter { |key, _| key.start_with?(prefix) }
470       counters.filter! { |_, value| value != 0 }
471       counters.transform_keys! { |key| key.to_s.delete_prefix(prefix) }
473       if counters.empty?
474         unless optional
475           out.puts(prompt)
476           out.puts("    (all relevant counters are zero)")
477         end
478         return
479       else
480         out.puts(prompt)
481       end
483       counters = counters.to_a
484       counters.sort_by! { |(_, counter_value)| counter_value }
485       longest_name_length = counters.max_by { |(name, _)| name.length }.first.length
486       total = counters.sum { |(_, counter_value)| counter_value }
488       counters.reverse_each do |(name, value)|
489         padded_name = name.rjust(longest_name_length, ' ')
490         padded_count = format_number_pct(10, value, total)
491         out.puts("    #{padded_name}: #{padded_count}")
492       end
493     end
495     # Format large numbers with comma separators for readability
496     def format_number(pad, number) # :nodoc:
497       s = number.to_s
498       i = s.index('.') || s.size
499       s.insert(i -= 3, ',') while i > 3
500       s.rjust(pad, ' ')
501     end
503     # Format a number along with a percentage over a total value
504     def format_number_pct(pad, number, total) # :nodoc:
505       padded_count = format_number(pad, number)
506       percentage = number.fdiv(total) * 100
507       formatted_pct = "%4.1f%%" % percentage
508       "#{padded_count} (#{formatted_pct})"
509     end
511     # :startdoc:
512   end