Skip to content

Commit 3195505

Browse files
k0kubunst0012
andauthored
ZJIT: Add compile/profile/GC/invalidation time stats (ruby#14158)
Co-authored-by: Stan Lo <stan001212@gmail.com>
1 parent 6968668 commit 3195505

6 files changed

Lines changed: 138 additions & 48 deletions

File tree

zjit.rb

Lines changed: 23 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,7 @@ def enabled?
2222
# Return \ZJIT statistics as a Hash
2323
def stats
2424
stats = Primitive.rb_zjit_stats
25+
return nil if stats.nil?
2526

2627
if stats.key?(:vm_insns_count) && stats.key?(:zjit_insns_count)
2728
stats[:total_insns_count] = stats[:vm_insns_count] + stats[:zjit_insns_count]
@@ -37,15 +38,29 @@ def stats_string
3738
stats = self.stats
3839

3940
[
41+
:compile_time_ns,
42+
:profile_time_ns,
43+
:gc_time_ns,
44+
:invalidation_time_ns,
4045
:total_insns_count,
4146
:vm_insns_count,
4247
:zjit_insns_count,
4348
:ratio_in_zjit,
4449
].each do |key|
50+
# Some stats like vm_insns_count and ratio_in_zjit are not supported on the release build
51+
next unless stats.key?(key)
4552
value = stats[key]
46-
if key == :ratio_in_zjit
53+
54+
case key
55+
when :ratio_in_zjit
4756
value = '%0.1f%%' % value
57+
when /_time_ns\z/
58+
key = key.to_s.sub(/_time_ns\z/, '_time')
59+
value = "#{number_with_delimiter(value / 10**6)}ms"
60+
else
61+
value = number_with_delimiter(value)
4862
end
63+
4964
buf << "#{'%-18s' % "#{key}:"} #{value}\n"
5065
end
5166
buf
@@ -59,6 +74,13 @@ def assert_compiles # :nodoc:
5974
# :stopdoc:
6075
private
6176

77+
def number_with_delimiter(number)
78+
s = number.to_s
79+
i = s.index('.') || s.size
80+
s.insert(i -= 3, ',') while i > 3
81+
s
82+
end
83+
6284
# Print ZJIT stats
6385
def print_stats
6486
$stderr.write stats_string

zjit/src/codegen.rs

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,7 @@ use crate::backend::current::{Reg, ALLOC_REGS};
77
use crate::invariants::{track_bop_assumption, track_cme_assumption, track_single_ractor_assumption, track_stable_constant_names_assumption};
88
use crate::gc::{append_gc_offsets, get_or_create_iseq_payload, get_or_create_iseq_payload_ptr};
99
use crate::state::ZJITState;
10-
use crate::stats::{counter_ptr, Counter};
10+
use crate::stats::{counter_ptr, with_time_stat, Counter, Counter::compile_time_ns};
1111
use crate::{asm::CodeBlock, cruby::*, options::debug, virtualmem::CodePtr};
1212
use crate::backend::lir::{self, asm_comment, asm_ccall, Assembler, Opnd, SideExitContext, Target, CFP, C_ARG_OPNDS, C_RET_OPND, EC, NATIVE_STACK_PTR, NATIVE_BASE_PTR, SP};
1313
use crate::hir::{iseq_to_hir, Block, BlockId, BranchEdge, Invariant, RangeType, SideExitReason, SideExitReason::*, SpecialObjectType, SELF_PARAM_IDX};
@@ -86,7 +86,7 @@ pub extern "C" fn rb_zjit_iseq_gen_entry_point(iseq: IseqPtr, _ec: EcPtr) -> *co
8686
// Take a lock to avoid writing to ISEQ in parallel with Ractors.
8787
// with_vm_lock() does nothing if the program doesn't use Ractors.
8888
let code_ptr = with_vm_lock(src_loc!(), || {
89-
gen_iseq_entry_point(iseq)
89+
with_time_stat(compile_time_ns, || gen_iseq_entry_point(iseq))
9090
});
9191

9292
// Assert that the ISEQ compiles if RubyVM::ZJIT.assert_compiles is enabled
@@ -1359,7 +1359,8 @@ c_callable! {
13591359
with_vm_lock(src_loc!(), || {
13601360
// Get a pointer to compiled code or the side-exit trampoline
13611361
let cb = ZJITState::get_code_block();
1362-
let code_ptr = if let Some(code_ptr) = function_stub_hit_body(cb, iseq, branch_ptr) {
1362+
let code_ptr = with_time_stat(compile_time_ns, || function_stub_hit_body(cb, iseq, branch_ptr));
1363+
let code_ptr = if let Some(code_ptr) = code_ptr {
13631364
code_ptr
13641365
} else {
13651366
// gen_push_frame() doesn't set PC and SP, so we need to set them for side-exit

zjit/src/gc.rs

Lines changed: 27 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,8 @@
11
// This module is responsible for marking/moving objects on GC.
22

33
use std::{ffi::c_void, ops::Range};
4-
use crate::{cruby::*, profile::IseqProfile, state::ZJITState, virtualmem::CodePtr};
4+
use crate::{cruby::*, profile::IseqProfile, state::ZJITState, stats::with_time_stat, virtualmem::CodePtr};
5+
use crate::stats::Counter::gc_time_ns;
56

67
/// This is all the data ZJIT stores on an ISEQ. We mark objects in this struct on GC.
78
#[derive(Debug)]
@@ -65,6 +66,7 @@ fn payload_ptr_as_mut(payload_ptr: *mut IseqPayload) -> &'static mut IseqPayload
6566
unsafe { payload_ptr.as_mut() }.unwrap()
6667
}
6768

69+
/// GC callback for marking GC objects in the per-ISEQ payload.
6870
#[unsafe(no_mangle)]
6971
pub extern "C" fn rb_zjit_iseq_mark(payload: *mut c_void) {
7072
let payload = if payload.is_null() {
@@ -80,7 +82,29 @@ pub extern "C" fn rb_zjit_iseq_mark(payload: *mut c_void) {
8082
&*(payload as *const IseqPayload)
8183
}
8284
};
85+
with_time_stat(gc_time_ns, || iseq_mark(payload));
86+
}
87+
88+
/// GC callback for updating GC objects in the per-ISEQ payload.
89+
#[unsafe(no_mangle)]
90+
pub extern "C" fn rb_zjit_iseq_update_references(payload: *mut c_void) {
91+
let payload = if payload.is_null() {
92+
return; // nothing to update
93+
} else {
94+
// SAFETY: The GC takes the VM lock while marking, which
95+
// we assert, so we should be synchronized and data race free.
96+
//
97+
// For aliasing, having the VM lock hopefully also implies that no one
98+
// else has an overlapping &mut IseqPayload.
99+
unsafe {
100+
rb_assert_holding_vm_lock();
101+
&mut *(payload as *mut IseqPayload)
102+
}
103+
};
104+
with_time_stat(gc_time_ns, || iseq_update_references(payload));
105+
}
83106

107+
fn iseq_mark(payload: &IseqPayload) {
84108
// Mark objects retained by profiling instructions
85109
payload.profile.each_object(|object| {
86110
unsafe { rb_gc_mark_movable(object); }
@@ -100,24 +124,8 @@ pub extern "C" fn rb_zjit_iseq_mark(payload: *mut c_void) {
100124
}
101125
}
102126

103-
/// GC callback for updating GC objects in the per-ISEQ payload.
104-
/// This is a mirror of [rb_zjit_iseq_mark].
105-
#[unsafe(no_mangle)]
106-
pub extern "C" fn rb_zjit_iseq_update_references(payload: *mut c_void) {
107-
let payload = if payload.is_null() {
108-
return; // nothing to update
109-
} else {
110-
// SAFETY: The GC takes the VM lock while marking, which
111-
// we assert, so we should be synchronized and data race free.
112-
//
113-
// For aliasing, having the VM lock hopefully also implies that no one
114-
// else has an overlapping &mut IseqPayload.
115-
unsafe {
116-
rb_assert_holding_vm_lock();
117-
&mut *(payload as *mut IseqPayload)
118-
}
119-
};
120-
127+
/// This is a mirror of [iseq_mark].
128+
fn iseq_update_references(payload: &mut IseqPayload) {
121129
// Move objects retained by profiling instructions
122130
payload.profile.each_object_mut(|object| {
123131
*object = unsafe { rb_gc_location(*object) };

zjit/src/invariants.rs

Lines changed: 14 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -1,20 +1,24 @@
11
use std::{collections::{HashMap, HashSet}, mem};
22

33
use crate::{backend::lir::{asm_comment, Assembler}, cruby::{rb_callable_method_entry_t, ruby_basic_operators, src_loc, with_vm_lock, IseqPtr, RedefinitionFlag, ID}, gc::IseqPayload, hir::Invariant, options::debug, state::{zjit_enabled_p, ZJITState}, virtualmem::CodePtr};
4+
use crate::stats::with_time_stat;
5+
use crate::stats::Counter::invalidation_time_ns;
46
use crate::gc::remove_gc_offsets;
57

68
macro_rules! compile_patch_points {
79
($cb:expr, $patch_points:expr, $($comment_args:tt)*) => {
8-
for patch_point in $patch_points {
9-
let written_range = $cb.with_write_ptr(patch_point.patch_point_ptr, |cb| {
10-
let mut asm = Assembler::new();
11-
asm_comment!(asm, $($comment_args)*);
12-
asm.jmp(patch_point.side_exit_ptr.into());
13-
asm.compile(cb).expect("can write existing code");
14-
});
15-
// Stop marking GC offsets corrupted by the jump instruction
16-
remove_gc_offsets(patch_point.payload_ptr, &written_range);
17-
}
10+
with_time_stat(invalidation_time_ns, || {
11+
for patch_point in $patch_points {
12+
let written_range = $cb.with_write_ptr(patch_point.patch_point_ptr, |cb| {
13+
let mut asm = Assembler::new();
14+
asm_comment!(asm, $($comment_args)*);
15+
asm.jmp(patch_point.side_exit_ptr.into());
16+
asm.compile(cb).expect("can write existing code");
17+
});
18+
// Stop marking GC offsets corrupted by the jump instruction
19+
remove_gc_offsets(patch_point.payload_ptr, &written_range);
20+
}
21+
});
1822
};
1923
}
2024

zjit/src/profile.rs

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,8 @@
33

44
use crate::{cruby::*, gc::get_or_create_iseq_payload, options::get_option};
55
use crate::distribution::{Distribution, DistributionSummary};
6+
use crate::stats::Counter::profile_time_ns;
7+
use crate::stats::with_time_stat;
68

79
/// Ephemeral state for profiling runtime information
810
struct Profiler {
@@ -41,13 +43,13 @@ impl Profiler {
4143
#[unsafe(no_mangle)]
4244
pub extern "C" fn rb_zjit_profile_insn(bare_opcode: u32, ec: EcPtr) {
4345
with_vm_lock(src_loc!(), || {
44-
let mut profiler = Profiler::new(ec);
45-
profile_insn(&mut profiler, bare_opcode as ruby_vminsn_type);
46+
with_time_stat(profile_time_ns, || profile_insn(bare_opcode as ruby_vminsn_type, ec));
4647
});
4748
}
4849

4950
/// Profile a YARV instruction
50-
fn profile_insn(profiler: &mut Profiler, bare_opcode: ruby_vminsn_type) {
51+
fn profile_insn(bare_opcode: ruby_vminsn_type, ec: EcPtr) {
52+
let profiler = &mut Profiler::new(ec);
5153
let profile = &mut get_or_create_iseq_payload(profiler.iseq).profile;
5254
match bare_opcode {
5355
YARVINSN_opt_nil_p => profile_operands(profiler, profile, 1),

zjit/src/stats.rs

Lines changed: 65 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -1,38 +1,75 @@
1-
// Maxime would like to rebuild an improved stats system
2-
// Individual stats should be tagged as always available, or only available in stats mode
3-
// We could also tag which stats are fallback or exit counters, etc. Maybe even tag units?
4-
//
5-
// Comptime vs Runtime stats?
1+
use std::time::Instant;
62

73
use crate::{cruby::*, options::get_option, state::{zjit_enabled_p, ZJITState}};
84

95
macro_rules! make_counters {
10-
($($counter_name:ident,)+) => {
6+
(
7+
default {
8+
$($default_counter_name:ident,)+
9+
}
10+
$($counter_name:ident,)+
11+
) => {
1112
/// Struct containing the counter values
1213
#[derive(Default, Debug)]
13-
pub struct Counters { $(pub $counter_name: u64),+ }
14+
pub struct Counters {
15+
$(pub $default_counter_name: u64,)+
16+
$(pub $counter_name: u64,)+
17+
}
1418

1519
/// Enum to represent a counter
1620
#[allow(non_camel_case_types)]
1721
#[derive(Clone, Copy, PartialEq, Eq, Debug)]
18-
pub enum Counter { $($counter_name),+ }
22+
pub enum Counter {
23+
$($default_counter_name,)+
24+
$($counter_name,)+
25+
}
26+
27+
impl Counter {
28+
pub fn name(&self) -> String {
29+
match self {
30+
$( Counter::$default_counter_name => stringify!($default_counter_name).to_string(), )+
31+
$( Counter::$counter_name => stringify!($counter_name).to_string(), )+
32+
}
33+
}
34+
}
1935

2036
/// Map a counter to a pointer
2137
pub fn counter_ptr(counter: Counter) -> *mut u64 {
2238
let counters = $crate::state::ZJITState::get_counters();
2339
match counter {
24-
$( Counter::$counter_name => std::ptr::addr_of_mut!(counters.$counter_name) ),+
40+
$( Counter::$default_counter_name => std::ptr::addr_of_mut!(counters.$default_counter_name), )+
41+
$( Counter::$counter_name => std::ptr::addr_of_mut!(counters.$counter_name), )+
2542
}
2643
}
44+
45+
/// The list of counters that are available without --zjit-stats.
46+
/// They are incremented only by `incr_counter()` and don't use `gen_incr_counter()`.
47+
pub const DEFAULT_COUNTERS: &'static [Counter] = &[
48+
$( Counter::$default_counter_name, )+
49+
];
2750
}
2851
}
2952

3053
// Declare all the counters we track
3154
make_counters! {
55+
// Default counters that are available without --zjit-stats
56+
default {
57+
compile_time_ns,
58+
profile_time_ns,
59+
gc_time_ns,
60+
invalidation_time_ns,
61+
}
62+
3263
// The number of times YARV instructions are executed on JIT code
3364
zjit_insns_count,
3465
}
3566

67+
/// Increase a counter by a specified amount
68+
fn incr_counter(counter: Counter, amount: u64) {
69+
let ptr = counter_ptr(counter);
70+
unsafe { *ptr += amount; }
71+
}
72+
3673
pub fn zjit_alloc_size() -> usize {
3774
0 // TODO: report the actual memory usage
3875
}
@@ -49,14 +86,30 @@ pub extern "C" fn rb_zjit_stats(_ec: EcPtr, _self: VALUE) -> VALUE {
4986
}
5087

5188
let hash = unsafe { rb_hash_new() };
52-
// TODO: Set counters that are always available here
89+
let counters = ZJITState::get_counters();
90+
91+
for &counter in DEFAULT_COUNTERS {
92+
let counter_val = unsafe { *counter_ptr(counter) };
93+
set_stat(hash, &counter.name(), counter_val);
94+
}
5395

5496
// Set counters that are enabled when --zjit-stats is enabled
5597
if get_option!(stats) {
56-
let counters = ZJITState::get_counters();
5798
set_stat(hash, "zjit_insns_count", counters.zjit_insns_count);
58-
set_stat(hash, "vm_insns_count", unsafe { rb_vm_insns_count });
99+
100+
if unsafe { rb_vm_insns_count } > 0 {
101+
set_stat(hash, "vm_insns_count", unsafe { rb_vm_insns_count });
102+
}
59103
}
60104

61105
hash
62106
}
107+
108+
/// Measure the time taken by func() and add that to zjit_compile_time.
109+
pub fn with_time_stat<F, R>(counter: Counter, func: F) -> R where F: FnOnce() -> R {
110+
let start = Instant::now();
111+
let ret = func();
112+
let nanos = Instant::now().duration_since(start).as_nanos();
113+
incr_counter(counter, nanos as u64);
114+
ret
115+
}

0 commit comments

Comments
 (0)