YJIT: Add compilation time counter (#8417)

* YJIT: Add compilation time counter

* YJIT: Use Instant instead

yjit.rb

@@ -307,6 +307,7 @@ def _print_stats(out: $stderr) # :nodoc:
         out.puts "versions_per_block:    " + format_number(13, "%4.3f" % (stats[:compiled_block_count].fdiv(stats[:compiled_blockid_count])))
       end
       out.puts "compiled_branch_count: " + format_number(13, stats[:compiled_branch_count])
+      out.puts "compile_time_ms:       " + format_number(13, stats[:compile_time_ns] / (1000 * 1000))
       out.puts "block_next_count:      " + format_number(13, stats[:block_next_count])
       out.puts "defer_count:           " + format_number(13, stats[:defer_count])
       out.puts "defer_empty_count:     " + format_number(13, stats[:defer_empty_count])

yjit/src/core.rs

@@ -2248,7 +2248,7 @@ c_callable! {
     /// See [gen_call_entry_stub_hit].
     fn entry_stub_hit(entry_ptr: *const c_void, ec: EcPtr) -> *const u8 {
         with_vm_lock(src_loc!(), || {
-            match entry_stub_hit_body(entry_ptr, ec) {
+            match with_compile_time(|| { entry_stub_hit_body(entry_ptr, ec) }) {
                 Some(addr) => addr,
                 // Failed to service the stub by generating a new block so now we
                 // need to exit to the interpreter at the stubbed location.
@@ -2441,7 +2441,7 @@ c_callable! {
         ec: EcPtr,
     ) -> *const u8 {
         with_vm_lock(src_loc!(), || {
-            branch_stub_hit_body(branch_ptr, target_idx, ec)
+            with_compile_time(|| { branch_stub_hit_body(branch_ptr, target_idx, ec) })
         })
     }
 }

yjit/src/stats.rs

@@ -3,6 +3,8 @@
 
 #![allow(dead_code)] // Counters are only used with the stats features
 
+use std::time::Instant;
+
 use crate::codegen::CodegenGlobals;
 use crate::core::Context;
 use crate::core::for_each_iseq_payload;
@@ -411,6 +413,7 @@ make_counters! {
     compiled_blockid_count,
     compiled_block_count,
     compiled_branch_count,
+    compile_time_ns,
     compilation_failure,
     block_next_count,
     defer_count,
@@ -839,3 +842,16 @@ fn global_allocation_size() -> usize {
     let stats = GLOBAL_ALLOCATOR.stats();
     stats.bytes_allocated.saturating_sub(stats.bytes_deallocated)
 }
+
+/// Measure the time taken by func() and add that to yjit_compile_time.
+pub fn with_compile_time<F, R>(func: F) -> R where F: FnOnce() -> R {
+    if get_option!(gen_stats) {
+        let start = Instant::now();
+        let ret = func();
+        let nanos = Instant::now().duration_since(start).as_nanos();
+        incr_counter_by!(compile_time_ns, nanos);
+        ret
+    } else {
+        func()
+    }
+}

yjit/src/yjit.rs

@@ -5,6 +5,7 @@ use crate::invariants::*;
 use crate::options::*;
 use crate::stats::YjitExitLocations;
 use crate::stats::incr_counter;
+use crate::stats::with_compile_time;
 
 use std::os::raw;
 use std::sync::atomic::{AtomicBool, Ordering};
@@ -130,7 +131,7 @@ pub extern "C" fn rb_yjit_iseq_gen_entry_point(iseq: IseqPtr, ec: EcPtr, jit_exc
         return std::ptr::null();
     }
 
-    let maybe_code_ptr = gen_entry_point(iseq, ec, jit_exception);
+    let maybe_code_ptr = with_compile_time(|| { gen_entry_point(iseq, ec, jit_exception) });
 
     match maybe_code_ptr {
         Some(ptr) => ptr.raw_ptr(),