YJIT: Add compilation log (#11818)

* YJIT: Add `--yjit-compilation-log` flag to print out the compilation log at exit.

* YJIT: Add an option to enable the compilation log at runtime.

* YJIT: Fix a typo in the `IseqPayload` docs.

* YJIT: Add stubs for getting the YJIT compilation log in memory.

* YJIT: Add a compilation log based on a circular buffer to cap the log size.

* YJIT: Allow specifying either a file or directory name for the YJIT compilation log.

The compilation log will be populated as compilation events occur. If a directory is supplied, then a filename based on the PID will be used as the write target. If a file name is supplied instead, the log will be written to that file.

* YJIT: Add JIT compilation of C function substitutions to the compilation log.

* YJIT: Add compilation events to the circular buffer even if output is sent to a file.

Previously, the two modes were treated as being exclusive of one another. However, it could be beneficial to log all events to a file while also allowing for direct access of the last N events via `RubyVM::YJIT.compilation_log`.

* YJIT: Make timestamps the first element in the YJIT compilation log tuple.

* YJIT: Stream log to stderr if `--yjit-compilation-log` is supplied without an argument.

* YJIT: Eagerly compute compilation log messages to avoid hanging on to references that may GC.

* YJIT: Log all compiled blocks, not just the method entry points.

* YJIT: Remove all compilation events other than block compilation to slim down the log.

* YJIT: Replace circular buffer iterator with a consuming loop.

* YJIT: Support `--yjit-compilation-log=quiet` as a way to activate the in-memory log without printing it.

Co-authored-by: Randy Stauner <randy.stauner@shopify.com>

* YJIT: Promote the compilation log to being the one YJIT log.

Co-authored-by: Randy Stauner <randy.stauner@shopify.com>

* Update doc/yjit/yjit.md

* Update doc/yjit/yjit.md

---------

Co-authored-by: Randy Stauner <randy.stauner@shopify.com>
Co-authored-by: Maxime Chevalier-Boisvert <maximechevalierb@gmail.com>

Author: 3 people

doc/yjit/yjit.md

@@ -166,6 +166,12 @@ You can dump statistics about compilation and execution by running YJIT with the
 ./miniruby --yjit-stats myscript.rb
 ```
 
+You can see what YJIT has compiled by running YJIT with the `--yjit-log` command-line option:
+
+```sh
+./miniruby --yjit-log myscript.rb
+```
+
 The machine code generated for a given method can be printed by adding `puts RubyVM::YJIT.disasm(method(:method_name))` to a Ruby script. Note that no code will be generated if the method is not compiled.
 
 <h3 id="command-line-options">Command-Line Options</h3>
@@ -181,6 +187,8 @@ YJIT supports all command-line options supported by upstream CRuby, but also add
   compiled, lower values mean less code is compiled (default 200K)
 - `--yjit-stats`: print statistics after the execution of a program (incurs a run-time cost)
 - `--yjit-stats=quiet`: gather statistics while running a program but don't print them. Stats are accessible through `RubyVM::YJIT.runtime_stats`. (incurs a run-time cost)
+- `--yjit-log[=file|dir]`: log all compilation events to the specified file or directory. If no name is supplied, the last 1024 log entries will be printed to stderr when the application exits.
+- `--yjit-log=quiet`: gather a circular buffer of recent YJIT compilations. The compilation log entries are accessible through `RubyVM::YJIT.log` and old entries will be discarded if the buffer is not drained quickly. (incurs a run-time cost)
 - `--yjit-disable`: disable YJIT despite other `--yjit*` flags for lazily enabling it with `RubyVM::YJIT.enable`
 - `--yjit-code-gc`: enable code GC (disabled by default as of Ruby 3.3).
   It will cause all machine code to be discarded when the executable memory size limit is hit, meaning JIT compilation will then start over.

yjit.c

@@ -1226,15 +1226,18 @@ rb_yjit_set_exception_return(rb_control_frame_t *cfp, void *leave_exit, void *le
 // Primitives used by yjit.rb
 VALUE rb_yjit_stats_enabled_p(rb_execution_context_t *ec, VALUE self);
 VALUE rb_yjit_print_stats_p(rb_execution_context_t *ec, VALUE self);
+VALUE rb_yjit_log_enabled_p(rb_execution_context_t *c, VALUE self);
+VALUE rb_yjit_print_log_p(rb_execution_context_t *c, VALUE self);
 VALUE rb_yjit_trace_exit_locations_enabled_p(rb_execution_context_t *ec, VALUE self);
 VALUE rb_yjit_get_stats(rb_execution_context_t *ec, VALUE self, VALUE key);
 VALUE rb_yjit_reset_stats_bang(rb_execution_context_t *ec, VALUE self);
+VALUE rb_yjit_get_log(rb_execution_context_t *ec, VALUE self);
 VALUE rb_yjit_disasm_iseq(rb_execution_context_t *ec, VALUE self, VALUE iseq);
 VALUE rb_yjit_insns_compiled(rb_execution_context_t *ec, VALUE self, VALUE iseq);
 VALUE rb_yjit_code_gc(rb_execution_context_t *ec, VALUE self);
 VALUE rb_yjit_simulate_oom_bang(rb_execution_context_t *ec, VALUE self);
 VALUE rb_yjit_get_exit_locations(rb_execution_context_t *ec, VALUE self);
-VALUE rb_yjit_enable(rb_execution_context_t *ec, VALUE self, VALUE gen_stats, VALUE print_stats);
+VALUE rb_yjit_enable(rb_execution_context_t *ec, VALUE self, VALUE gen_stats, VALUE print_stats, VALUE gen_compilation_log, VALUE print_compilation_log);
 
 // Preprocessed yjit.rb generated during build
 #include "yjit.rbinc"

yjit.rb

@@ -18,6 +18,11 @@ def self.stats_enabled?
     Primitive.rb_yjit_stats_enabled_p
   end
 
+  # Check if `--yjit-log` is used.
+  def self.log_enabled?
+    Primitive.rb_yjit_log_enabled_p
+  end
+
   # Check if rb_yjit_trace_exit_locations_enabled_p is enabled.
   def self.trace_exit_locations_enabled? # :nodoc:
     Primitive.rb_yjit_trace_exit_locations_enabled_p
@@ -28,15 +33,22 @@ def self.reset_stats!
     Primitive.rb_yjit_reset_stats_bang
   end
 
-  # Enable \YJIT compilation. `stats` option decides whether to enable \YJIT stats or not.
+  # Enable \YJIT compilation. `stats` option decides whether to enable \YJIT stats or not. `compilation_log` decides
+  # whether to enable \YJIT compilation logging or not.
   #
+  # `stats`:
   # * `false`: Disable stats.
   # * `true`: Enable stats. Print stats at exit.
   # * `:quiet`: Enable stats. Do not print stats at exit.
-  def self.enable(stats: false)
+  #
+  # `log`:
+  # * `false`: Don't enable the log.
+  # * `true`: Enable the log. Print log at exit.
+  # * `:quiet`: Enable the log. Do not print log at exit.
+  def self.enable(stats: false, log: false)
     return false if enabled?
     at_exit { print_and_dump_stats } if stats
-    Primitive.rb_yjit_enable(stats, stats != :quiet)
+    Primitive.rb_yjit_enable(stats, stats != :quiet, log, log != :quiet)
   end
 
   # If --yjit-trace-exits is enabled parse the hashes from
@@ -173,6 +185,16 @@ def self.stats_string
     strio.string
   end
 
+  # Return an array of log entries.
+  # Return `nil` when option is not passed or unavailable.
+  def self.log
+    return nil unless log_enabled?
+
+    Primitive.rb_yjit_get_log.map do |timestamp, path|
+      [Time.at(timestamp), path]
+    end
+  end
+
   # Produce disassembly for an iseq. This requires a `--enable-yjit=dev` build.
   def self.disasm(iseq) # :nodoc:
     # If a method or proc is passed in, get its iseq

yjit/src/codegen.rs

@@ -458,6 +458,7 @@ macro_rules! perf_call {
 }
 
 use crate::codegen::JCCKinds::*;
+use crate::log::Log;
 
 #[allow(non_camel_case_types, unused)]
 pub enum JCCKinds {
@@ -1223,6 +1224,8 @@ pub fn gen_single_block(
         asm_comment!(asm, "reg_mapping: {:?}", asm.ctx.get_reg_mapping());
     }
 
+    Log::add_block_with_chain_depth(blockid, asm.ctx.get_chain_depth());
+
     // Mark the start of an ISEQ for --yjit-perf
     jit_perf_symbol_push!(jit, &mut asm, &get_iseq_name(iseq), PerfMap::ISEQ);
 

yjit/src/core.rs

@@ -1763,7 +1763,7 @@ pub struct IseqPayload {
     // Basic block versions
     pub version_map: VersionMap,
 
-    // Indexes of code pages used by this this ISEQ
+    // Indexes of code pages used by this ISEQ
     pub pages: HashSet<usize>,
 
     // List of ISEQ entry codes

yjit/src/cruby.rs

@@ -84,6 +84,7 @@
 
 use std::convert::From;
 use std::ffi::{CString, CStr};
+use std::fmt::{Debug, Formatter};
 use std::os::raw::{c_char, c_int, c_uint};
 use std::panic::{catch_unwind, UnwindSafe};
 
@@ -563,6 +564,18 @@ impl From<*const rb_callable_method_entry_t> for VALUE {
     }
 }
 
+impl From<&str> for VALUE {
+    fn from(value: &str) -> Self {
+        rust_str_to_ruby(value)
+    }
+}
+
+impl From<String> for VALUE {
+    fn from(value: String) -> Self {
+        rust_str_to_ruby(&value)
+    }
+}
+
 impl From<VALUE> for u64 {
     fn from(value: VALUE) -> Self {
         let VALUE(uimm) = value;
@@ -594,7 +607,6 @@ impl From<VALUE> for u16 {
 }
 
 /// Produce a Ruby string from a Rust string slice
-#[cfg(feature = "disasm")]
 pub fn rust_str_to_ruby(str: &str) -> VALUE {
     unsafe { rb_utf8_str_new(str.as_ptr() as *const _, str.len() as i64) }
 }
@@ -625,6 +637,12 @@ pub struct SourceLocation {
     pub line: c_int,
 }
 
+impl Debug for SourceLocation {
+    fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
+        f.write_fmt(format_args!("{}:{}", self.file.to_string_lossy(), self.line))
+    }
+}
+
 /// Make a [SourceLocation] at the current spot.
 macro_rules! src_loc {
     () => {

yjit/src/lib.rs

@@ -15,3 +15,4 @@ mod stats;
 mod utils;
 mod yjit;
 mod virtualmem;
+mod log;

yjit/src/log.rs

@@ -0,0 +1,179 @@
+use crate::core::BlockId;
+use crate::cruby::*;
+use crate::options::*;
+use crate::yjit::yjit_enabled_p;
+
+use std::fmt::{Display, Formatter};
+use std::os::raw::c_long;
+use crate::utils::iseq_get_location;
+
+type Timestamp = f64;
+
+#[derive(Clone, Debug)]
+pub struct LogEntry {
+    /// The time when the block was compiled.
+    pub timestamp: Timestamp,
+
+    /// The log message.
+    pub message: String,
+}
+
+impl Display for LogEntry {
+    fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
+        write!(f, "{:15.6}: {}", self.timestamp, self.message)
+    }
+}
+
+pub type Log = CircularBuffer<LogEntry, 1024>;
+static mut LOG: Option<Log> = None;
+
+impl Log {
+    pub fn init() {
+        unsafe {
+            LOG = Some(Log::new());
+        }
+    }
+
+    pub fn get_instance() -> &'static mut Log {
+        unsafe {
+            LOG.as_mut().unwrap()
+        }
+    }
+
+    pub fn has_instance() -> bool {
+        unsafe {
+            LOG.as_mut().is_some()
+        }
+    }
+
+    pub fn add_block_with_chain_depth(block_id: BlockId, chain_depth: u8) {
+        if !Self::has_instance() {
+            return;
+        }
+
+        let print_log = get_option!(log);
+        let timestamp = std::time::SystemTime::now().duration_since(std::time::UNIX_EPOCH).unwrap().as_secs_f64();
+
+        let location = iseq_get_location(block_id.iseq, block_id.idx);
+        let index = block_id.idx;
+        let message = if chain_depth > 0 {
+            format!("{} (index: {}, chain_depth: {})", location, index, chain_depth)
+        } else {
+            format!("{} (index: {})", location, index)
+        };
+
+        let entry = LogEntry {
+            timestamp,
+            message
+        };
+
+        if let Some(output) = print_log {
+            match output {
+                LogOutput::Stderr => {
+                    eprintln!("{}", entry);
+                }
+
+                LogOutput::File(fd) => {
+                    use std::os::unix::io::{FromRawFd, IntoRawFd};
+                    use std::io::Write;
+
+                    // Write with the fd opened during boot
+                    let mut file = unsafe { std::fs::File::from_raw_fd(fd) };
+                    writeln!(file, "{}", entry).unwrap();
+                    file.flush().unwrap();
+                    file.into_raw_fd(); // keep the fd open
+                }
+
+                LogOutput::MemoryOnly => () // Don't print or write anything
+            }
+        }
+
+        Self::get_instance().push(entry);
+    }
+}
+
+pub struct CircularBuffer<T, const N: usize> {
+    buffer: Vec<Option<T>>,
+    head: usize,
+    tail: usize,
+    size: usize
+}
+
+impl<T: Clone, const N: usize> CircularBuffer<T, N> {
+    pub fn new() -> Self {
+        Self {
+            buffer: vec![None; N],
+            head: 0,
+            tail: 0,
+            size: 0
+        }
+    }
+
+    pub fn push(&mut self, value: T) {
+        self.buffer[self.head] = Some(value);
+        self.head = (self.head + 1) % N;
+        if self.size == N {
+            self.tail = (self.tail + 1) % N;
+        } else {
+            self.size += 1;
+        }
+    }
+
+    pub fn pop(&mut self) -> Option<T> {
+        if self.size == 0 {
+            return None;
+        }
+
+        let value = self.buffer[self.tail].take();
+        self.tail = (self.tail + 1) % N;
+        self.size -= 1;
+        value
+    }
+
+    pub fn len(&self) -> usize {
+        self.size
+    }
+}
+
+
+//===========================================================================
+
+/// Primitive called in yjit.rb
+/// Check if log generation is enabled
+#[no_mangle]
+pub extern "C" fn rb_yjit_log_enabled_p(_ec: EcPtr, _ruby_self: VALUE) -> VALUE {
+    if get_option!(log).is_some() {
+        return Qtrue;
+    } else {
+        return Qfalse;
+    }
+}
+
+/// Primitive called in yjit.rb.
+/// Export all YJIT log entries as a Ruby array.
+#[no_mangle]
+pub extern "C" fn rb_yjit_get_log(_ec: EcPtr, _ruby_self: VALUE) -> VALUE {
+    with_vm_lock(src_loc!(), || rb_yjit_get_log_array())
+}
+
+fn rb_yjit_get_log_array() -> VALUE {
+    if !yjit_enabled_p() || get_option!(log).is_none() {
+        return Qnil;
+    }
+
+    let log = Log::get_instance();
+    let array = unsafe { rb_ary_new_capa(log.len() as c_long) };
+
+    while log.len() > 0 {
+        let entry = log.pop().unwrap();
+
+        unsafe {
+            let entry_array = rb_ary_new_capa(2);
+            rb_ary_push(entry_array, rb_float_new(entry.timestamp));
+            rb_ary_push(entry_array, entry.message.into());
+            rb_ary_push(array, entry_array);
+        }
+    }
+
+    return array;
+}