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

@@ -3050,9 +3050,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

@@ -564,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;
@@ -595,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) }
 }

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();
             }
         }