YJIT: Allow specifying either a file or directory name for the YJIT c…

…ompilation 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.

doc/yjit/yjit.md

@@ -179,7 +179,7 @@ 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-compilation-log`: print a log of all compiled methods to the console.
+- `--yjit-compilation-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-compilation-log=quiet`: gather a circular buffer of recent YJIT compilations. The compilation log entries are accessible through `RubyVM::YJIT.compilation_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).

yjit.rb

@@ -189,7 +189,9 @@ def self.stats_string
  # Return an array of compilation log entries.
  # Return `nil` when option is not passed or unavailable.
  def self.compilation_log
- Primitive.rb_yjit_get_compilation_log
+ Primitive.rb_yjit_get_compilation_log.map do |path, timestamp|
+ [path, Time.at(timestamp)]
+ end
  end
 
  # Produce disassembly for an iseq. This requires a `--enable-yjit=dev` build.
@@ -263,9 +265,9 @@ def print_and_dump_stats # :nodoc:
  # Print the compilation log
  def print_compilation_log # :nodoc:
  if Primitive.rb_yjit_print_compilation_log_p
+ $stderr.puts "***YJIT: Printing YJIT compilation log on exit***"
  RubyVM::YJIT.compilation_log.each do |iseq_path, timestamp|
- t = Time.at(timestamp)
- $stderr.puts "%15.6f: %s" % [t.to_f, iseq_path]
+ $stderr.puts "%15.6f: %s" % [timestamp.to_f, iseq_path]
  end
  end
  end

yjit/src/compilation_log.rs

@@ -1,5 +1,6 @@
 #![allow(dead_code)]
 
+use std::fmt::{Display, Formatter};
 use crate::core::BlockId;
 use crate::cruby::*;
 use crate::options::*;
@@ -16,6 +17,12 @@ pub struct CompilationLogEntry {
  pub timestamp: f64,
 }
 
+impl Display for CompilationLogEntry {
+ fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
+ write!(f, "{:15.6}: {}", self.timestamp, self.block_id.iseq_name())
+ }
+}
+
 pub type CompilationLog = CircularBuffer<CompilationLogEntry, 1024>;
 static mut COMPILATION_LOG : Option<CompilationLog> = None;
 
@@ -39,10 +46,29 @@ impl CompilationLog {
  }
 
  pub fn add_entry(block_id: BlockId) {
- Self::get_instance().push(CompilationLogEntry {
- block_id: block_id,
- timestamp: std::time::SystemTime::now().duration_since(std::time::UNIX_EPOCH).unwrap().as_secs_f64()
- });
+ let print_compilation_log = get_option!(print_compilation_log);
+ let timestamp = std::time::SystemTime::now().duration_since(std::time::UNIX_EPOCH).unwrap().as_secs_f64();
+
+ let entry = CompilationLogEntry {
+ block_id,
+ timestamp
+ };
+
+ match print_compilation_log {
+ Some(CompilationLogOutput::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
+ },
+ _ => {
+ Self::get_instance().push(entry);
+ }
+ }
  }
 
  pub fn clear() {
@@ -150,7 +176,7 @@ pub extern "C" fn rb_yjit_compilation_log_enabled_p(_ec: EcPtr, _ruby_self: VALU
 /// Check if the compilation log should print at exit
 #[no_mangle]
 pub extern "C" fn rb_yjit_print_compilation_log_p(_ec: EcPtr, _ruby_self: VALUE) -> VALUE {
- if yjit_enabled_p() && get_option!(print_compilation_log) {
+ if yjit_enabled_p() && get_option!(print_compilation_log) == Some(CompilationLogOutput::Stdout) {
  return Qtrue;
  } else {
  return Qfalse;
@@ -175,7 +201,7 @@ fn rb_yjit_get_compilation_log_array() -> VALUE {
  for entry in log.iter() {
  unsafe {
  let entry_array = rb_ary_new_capa(2);
- rb_ary_push(entry_array, entry.block_id.iseq_name());
+ rb_ary_push(entry_array, entry.block_id.iseq_name().into());
  rb_ary_push(entry_array, rb_float_new(entry.timestamp));
  rb_ary_push(array, entry_array);
  }

yjit/src/core.rs

@@ -3001,9 +3001,8 @@ impl BlockId {
  unsafe { rb_yjit_dump_iseq_loc(self.iseq, self.idx as u32) }
  }
 
- pub fn iseq_name(&self) -> VALUE {
- let path = get_iseq_name(self.iseq);
- rust_str_to_ruby(&path)
+ pub fn iseq_name(&self) -> String {
+ get_iseq_name(self.iseq)
  }
 }
 

yjit/src/cruby.rs

@@ -125,6 +125,7 @@ extern "C" {
  pub fn rb_hash_empty_p(hash: VALUE) -> VALUE;
  pub fn rb_yjit_str_concat_codepoint(str: VALUE, codepoint: VALUE);
  pub fn rb_str_setbyte(str: VALUE, index: VALUE, value: VALUE) -> VALUE;
+ pub fn rb_string_value_cstr(str: VALUE) -> *const c_char;
  pub fn rb_vm_splat_array(flag: VALUE, ary: VALUE) -> VALUE;
  pub fn rb_vm_concat_array(ary1: VALUE, ary2st: VALUE) -> VALUE;
  pub fn rb_vm_concat_to_array(ary1: VALUE, ary2st: VALUE) -> VALUE;
@@ -495,6 +496,15 @@ impl VALUE {
  us
  }
 
+ pub fn as_string(self) -> String {
+ assert!(self.string_p() == true);
+
+ unsafe {
+ let str = rb_string_value_cstr(self);
+ cstr_to_rust_string(str).unwrap()
+ }
+ }
+
  pub fn as_ptr<T>(self) -> *const T {
  let VALUE(us) = self;
  us as *const T
@@ -566,6 +576,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;

yjit/src/options.rs

@@ -82,7 +82,7 @@ pub struct Options {
  pub gen_compilation_log: bool,
 
  // Print compilation log on exit (when gen_compilation_log is also true)
- pub print_compilation_log: bool,
+ pub print_compilation_log: Option<CompilationLogOutput>,
 }
 
 // Initialize the options to default values
@@ -104,7 +104,7 @@ pub static mut OPTIONS: Options = Options {
  code_gc: false,
  perf_map: None,
  gen_compilation_log: false,
- print_compilation_log: true,
+ print_compilation_log: None,
 };
 
 /// YJIT option descriptions for `ruby --help`.
@@ -113,7 +113,7 @@ static YJIT_OPTIONS: [(&str, &str); 10] = [
  ("--yjit-call-threshold=num", "Number of calls to trigger JIT."),
  ("--yjit-cold-threshold=num", "Global calls after which ISEQs not compiled (default: 200K)."),
  ("--yjit-stats", "Enable collecting YJIT statistics."),
- ("--yjit-compilation-log",  "Enable logging of YJIT's compilation activity."),
+ ("--yjit-compilation-log[=file|dir]", "Enable logging of YJIT's compilation activity."),
  ("--yjit-disable", "Disable YJIT for lazily enabling it with RubyVM::YJIT.enable."),
  ("--yjit-code-gc", "Run code GC when the code size reaches the limit."),
  ("--yjit-perf", "Enable frame pointers and perf profiling."),
@@ -129,6 +129,14 @@ pub enum TraceExits {
  Counter(Counter),
 }
 
+#[derive(Clone, Copy, PartialEq, Eq, Debug)]
+pub enum CompilationLogOutput {
+ // Dump to stdout when the process exits
+ Stdout,
+ // Dump to the log file as compilation events occur.
+ File(std::os::unix::io::RawFd)
+}
+
 #[derive(Debug)]
 pub enum DumpDisasm {
  // Dump to stdout
@@ -301,11 +309,24 @@ pub fn parse_option(str_ptr: *const std::os::raw::c_char) -> Option<()> {
  ("compilation-log", _) => match opt_val {
  "" => unsafe {
  OPTIONS.gen_compilation_log = true;
- OPTIONS.print_compilation_log = true;
+ OPTIONS.print_compilation_log = Some(CompilationLogOutput::Stdout);
  CompilationLog::init();
- }
- _ => {
- return None;
+ },
+ arg_value => {
+ let log_file_path = if std::path::Path::new(arg_value).is_dir() {
+ format!("{arg_value}/yjit_compilation_{}.log", std::process::id())
+ } else {
+ arg_value.to_string()
+ };
+
+ match File::options().create(true).write(true).truncate(true).open(&log_file_path) {
+ Ok(file) => {
+ use std::os::unix::io::IntoRawFd;
+ eprintln!("YJIT compilation log: {log_file_path}");
+ unsafe { OPTIONS.print_compilation_log = Some(CompilationLogOutput::File(file.into_raw_fd())) }
+ }
+ Err(err) => panic!("Failed to create {log_file_path}: {err}"),
+ }
  }
  },
  ("trace-exits", _) => unsafe {

yjit/src/yjit.rs

@@ -181,7 +181,14 @@ pub extern "C" fn rb_yjit_enable(_ec: EcPtr, _ruby_self: VALUE, gen_stats: VALUE
  if gen_compilation_log.test() {
  unsafe {
  OPTIONS.gen_compilation_log = gen_compilation_log.test();
- OPTIONS.print_compilation_log = print_compilation_log.test();
+
+ // TODO (nirvdrum 01-Oct-2024): Should this support specifying a directory for file output?
+ if print_compilation_log.test() {
+ OPTIONS.print_compilation_log = Some(CompilationLogOutput::Stdout);
+ } else {
+ OPTIONS.print_compilation_log = None;
+ }
+
  CompilationLog::init();
  }
  }