From 6b23db7360d49541a0ea33a634d84c613b8b7188 Mon Sep 17 00:00:00 2001 From: youknowdot Date: Sun, 18 Oct 2026 19:30:32 +0900 Subject: [PATCH 1/3] Implement import timing and cached import diagnostics Support -X importtime and PYTHONPROFILEIMPORTTIME, including mode 2 cached imports. Track nested timing separately in each VM thread and share the output header per interpreter. Assisted-by: OpenAI Codex:model version unavailable --- crates/vm/src/import.rs | 95 +++++++++++++++++++++++++++++++++ crates/vm/src/vm/interpreter.rs | 1 + crates/vm/src/vm/mod.rs | 4 ++ crates/vm/src/vm/setting.rs | 4 +- crates/vm/src/vm/thread.rs | 1 + src/settings.rs | 32 ++++++++++- 6 files changed, 135 insertions(+), 2 deletions(-) diff --git a/crates/vm/src/import.rs b/crates/vm/src/import.rs index a6d137d7d2c..d650aeecb1c 100644 --- a/crates/vm/src/import.rs +++ b/crates/vm/src/import.rs @@ -8,11 +8,105 @@ use crate::{ vm::{VirtualMachine, resolve_frozen_alias, thread}, }; +use core::{cell::Cell, sync::atomic::Ordering, time::Duration}; +use std::{io::Write, time::Instant}; + +/// Nested imports are timed per thread, so concurrent imports do not subtract +/// each other's elapsed time. The output header belongs to the interpreter. +#[derive(Clone, Copy, Default)] +pub(crate) struct ImportTimingState { + depth: usize, + children: Duration, +} + +fn import_time_header(vm: &VirtualMachine) { + let mut stderr = std::io::stderr().lock(); + if !vm.state.import_time_header.swap(true, Ordering::Relaxed) { + let _ = writeln!( + stderr, + "import time: self [us] | cumulative | imported package" + ); + } +} + +fn import_time_name(name: &Py) -> String { + use core::fmt::Write; + let mut output = String::with_capacity(name.as_bytes().len()); + for codepoint in name.as_wtf8().code_points() { + match codepoint.to_char() { + Some(ch) => output.push(ch), + None => { + let _ = write!(output, "\\u{:04x}", codepoint.to_u32()); + } + } + } + output +} + +pub(crate) fn report_cached_import(name: &Py, vm: &VirtualMachine) { + if vm.state.config.settings.import_time == 2 { + import_time_header(vm); + let width = vm.import_timing.get().depth * 2; + let _ = writeln!( + std::io::stderr(), + "import time: cached | cached | {:>width$}", + import_time_name(name) + ); + } +} + +struct ImportTimer<'a> { + state: &'a Cell, + parent: ImportTimingState, + start: Instant, + name: &'a Py, +} + +impl<'a> ImportTimer<'a> { + fn start(name: &'a Py, vm: &'a VirtualMachine) -> Option { + if vm.state.config.settings.import_time == 0 { + return None; + } + import_time_header(vm); + let parent = vm.import_timing.replace(ImportTimingState { + depth: vm.import_timing.get().depth + 1, + children: Duration::ZERO, + }); + Some(Self { + state: &vm.import_timing, + parent, + start: Instant::now(), + name, + }) + } +} + +impl Drop for ImportTimer<'_> { + fn drop(&mut self) { + let cumulative = self.start.elapsed(); + let own = cumulative.saturating_sub(self.state.get().children); + self.state.set(ImportTimingState { + depth: self.parent.depth, + children: self.parent.children.saturating_add(cumulative), + }); + let width = self.parent.depth * 2; + let _ = writeln!( + std::io::stderr(), + "import time: {:9} | {:10} | {:width$}{}", + own.as_nanos().div_ceil(1000), + cumulative.as_nanos().div_ceil(1000), + "", + import_time_name(self.name), + ); + } +} + pub(crate) fn find_and_load( name: &Py, function: &'static str, vm: &VirtualMachine, ) -> PyResult { + let _timer = ImportTimer::start(name, vm); vm.importlib .get_attr(function, vm)? .call((name.to_owned(), vm.import_func.clone()), vm) @@ -194,6 +288,7 @@ fn import_ensure_initialized( let lock_unlock = vm.importlib.get_attr("_lock_unlock_module", vm)?; lock_unlock.call((name.to_owned(),), vm)?; } + report_cached_import(name, vm); Ok(()) } diff --git a/crates/vm/src/vm/interpreter.rs b/crates/vm/src/vm/interpreter.rs index b703da7d3ae..6fa735c1659 100644 --- a/crates/vm/src/vm/interpreter.rs +++ b/crates/vm/src/vm/interpreter.rs @@ -166,6 +166,7 @@ where atexit_funcs: PyMutex::default(), audit_hooks: PyMutex::default(), codec_registry, + import_time_header: AtomicBool::new(false), lazy_imports, struct_format_cache: crate::buffer::FormatSpecCache::default(), finalizing: AtomicBool::new(false), diff --git a/crates/vm/src/vm/mod.rs b/crates/vm/src/vm/mod.rs index 0ef153b7248..6e1a74a2242 100644 --- a/crates/vm/src/vm/mod.rs +++ b/crates/vm/src/vm/mod.rs @@ -95,6 +95,7 @@ pub struct VirtualMachine { exceptions: RefCell, pub import_func: PyObjectRef, pub(crate) importlib: PyObjectRef, + pub(crate) import_timing: Cell, pub profile_func: RefCell, pub trace_func: RefCell, pub use_tracing: Cell, @@ -875,6 +876,7 @@ pub struct PyGlobalState { /// `sys.addaudithook` hooks, shared by all threads of this interpreter. pub(crate) audit_hooks: PyMutex>, pub codec_registry: CodecsRegistry, + pub(crate) import_time_header: AtomicBool, pub(crate) lazy_imports: crate::lazy_import::LazyImportsState, pub struct_format_cache: crate::buffer::FormatSpecCache, pub finalizing: AtomicBool, @@ -1353,6 +1355,7 @@ impl VirtualMachine { exceptions: RefCell::default(), import_func, importlib, + import_timing: Cell::default(), profile_func, trace_func, use_tracing: Cell::new(false), @@ -3373,6 +3376,7 @@ impl VirtualMachine { && builtins.is(self.builtins.dict().as_object()) && let Some(cached) = self.try_import_cached(module)? { + import::report_cached_import(module, self); return Ok(cached); } diff --git a/crates/vm/src/vm/setting.rs b/crates/vm/src/vm/setting.rs index 9f3ef85f7d4..458174910c5 100644 --- a/crates/vm/src/vm/setting.rs +++ b/crates/vm/src/vm/setting.rs @@ -64,7 +64,8 @@ pub struct Settings { // int tracemalloc; // int perf_profiling; - // int import_time; + /// -X importtime, PYTHONPROFILEIMPORTTIME: 2 also reports cached imports. + pub import_time: u8, /// -X no_debug_ranges: disable column info in bytecode pub code_debug_ranges: bool, // int show_ref_count; @@ -222,6 +223,7 @@ impl Default for Settings { argv: vec![], hash_seed: None, faulthandler: false, + import_time: 0, code_debug_ranges: true, buffered_stdio: true, check_hash_pycs_mode: CheckHashPycsMode::Default, diff --git a/crates/vm/src/vm/thread.rs b/crates/vm/src/vm/thread.rs index 8d0aa70e6eb..cbbc729b41c 100644 --- a/crates/vm/src/vm/thread.rs +++ b/crates/vm/src/vm/thread.rs @@ -1467,6 +1467,7 @@ impl VirtualMachine { exceptions: RefCell::default(), import_func: self.import_func.clone(), importlib: self.importlib.clone(), + import_timing: Cell::default(), profile_func: RefCell::new(global_profile.unwrap_or_else(|| self.ctx.none())), trace_func: RefCell::new(global_trace.unwrap_or_else(|| self.ctx.none())), use_tracing: Cell::new(use_tracing), diff --git a/src/settings.rs b/src/settings.rs index a5b210a5f2c..08a69506535 100644 --- a/src/settings.rs +++ b/src/settings.rs @@ -309,8 +309,13 @@ pub fn parse_opts() -> Result<(Settings, RunMode), lexopt::Error> { settings.lazy_imports = parse_lazy_imports(val.to_str(), "PYTHON_LAZY_IMPORTS"); } - // CPython uses the first occurrence of this -X option. + if let Some(value) = get_env("PYTHONPROFILEIMPORTTIME").filter(|value| !value.is_empty()) { + settings.import_time = parse_import_time(value.to_str(), "PYTHONPROFILEIMPORTTIME"); + } + + // CPython uses the first occurrence of these -X options. let mut lazy_imports_option_seen = false; + let mut import_time_option_seen = false; let xopts = args.implementation_option.into_iter().map(|s| { let (name, value) = match s.split_once('=') { Some((name, value)) => (name.to_owned(), Some(value)), @@ -318,6 +323,10 @@ pub fn parse_opts() -> Result<(Settings, RunMode), lexopt::Error> { }; match &*name { "dev" => settings.dev_mode = true, + "importtime" if !import_time_option_seen => { + settings.import_time = parse_import_time(value, "-X importtime"); + import_time_option_seen = true; + } "faulthandler" => settings.faulthandler = true, "warn_default_encoding" => settings.warn_default_encoding = true, "utf8" => { @@ -504,6 +513,27 @@ fn parse_cpu_count(value: Option<&str>) -> Result, ()> { } } +/// = config_init_import_time +fn parse_import_time(value: Option<&str>, source: &str) -> u8 { + let value = value + .and_then(|value| { + value + .trim_start_matches([' ', '\t', '\n', '\r', '\x0b', '\x0c']) + .parse::() + .ok() + }) + .unwrap_or(1); + if !(0..=2).contains(&value) { + eprintln!( + "Fatal Python error: config_init_import_time: {source}: \ + values other than 1 and 2 are reserved for future use.\n\ + Python runtime state: preinitialized" + ); + std::process::exit(1); + } + value as u8 +} + /// = config_init_lazy_imports fn parse_lazy_imports(value: Option<&str>, source: &str) -> i8 { match value { From 487ca226b7c091e4b386ae7bb986c7da0e41e4b2 Mon Sep 17 00:00:00 2001 From: youknowdot Date: Sun, 18 Oct 2026 19:41:01 +0900 Subject: [PATCH 2/3] Enable canonical import timing coverage and align diagnostics Retire only test_import_time expectedFailure after the independent runtime passes its canonical assertions. Preserve other cmd-line markers and align environment range errors with CPython. Assisted-by: OpenAI Codex:model version unavailable --- Lib/test/test_cmd_line.py | 1 - src/settings.rs | 9 +++++++-- 2 files changed, 7 insertions(+), 3 deletions(-) diff --git a/Lib/test/test_cmd_line.py b/Lib/test/test_cmd_line.py index 248d6047f45..b9d1b9493a7 100644 --- a/Lib/test/test_cmd_line.py +++ b/Lib/test/test_cmd_line.py @@ -1266,7 +1266,6 @@ def test_cpu_count_default(self): res = assert_python_ok('-c', code, PYTHON_CPU_COUNT='default') self.assertEqual(self.res2int(res), (os.cpu_count(), os.process_cpu_count())) - @unittest.expectedFailure # TODO: RUSTPYTHON def test_import_time(self): # os is not imported at startup code = 'import os; import os' diff --git a/src/settings.rs b/src/settings.rs index 08a69506535..40b67e27eb3 100644 --- a/src/settings.rs +++ b/src/settings.rs @@ -278,7 +278,7 @@ pub fn parse_opts() -> Result<(Settings, RunMode), lexopt::Error> { "Fatal Python error: config_init_cpu_count: \ -X cpu_count=n option: n is missing or an invalid number, \ n must be greater than 0\n\ - Python runtime state: preinitialized" + Python runtime state: preinitialized\n" ); std::process::exit(1); } @@ -524,9 +524,14 @@ fn parse_import_time(value: Option<&str>, source: &str) -> u8 { }) .unwrap_or(1); if !(0..=2).contains(&value) { + let numeric = if source == "PYTHONPROFILEIMPORTTIME" { + "numeric " + } else { + "" + }; eprintln!( "Fatal Python error: config_init_import_time: {source}: \ - values other than 1 and 2 are reserved for future use.\n\ + {numeric}values other than 1 and 2 are reserved for future use.\n\ Python runtime state: preinitialized" ); std::process::exit(1); From 4fae3992c8703bc2e4f5499f24a588e4d0b452a3 Mon Sep 17 00:00:00 2001 From: youknowdot Date: Sun, 18 Oct 2026 19:46:18 +0900 Subject: [PATCH 3/3] Match encoded-byte padding for cached imports Keep CPython cached-import minimum width semantics for UTF-8 and backslash-replaced surrogate names. Scope the diagnostic blank line to importtime without changing CPU-count errors. Assisted-by: OpenAI Codex:model version unavailable --- crates/vm/src/import.rs | 9 ++++++--- src/settings.rs | 4 ++-- 2 files changed, 8 insertions(+), 5 deletions(-) diff --git a/crates/vm/src/import.rs b/crates/vm/src/import.rs index d650aeecb1c..02c1048f6dd 100644 --- a/crates/vm/src/import.rs +++ b/crates/vm/src/import.rs @@ -46,11 +46,14 @@ fn import_time_name(name: &Py) -> String { pub(crate) fn report_cached_import(name: &Py, vm: &VirtualMachine) { if vm.state.config.settings.import_time == 2 { import_time_header(vm); - let width = vm.import_timing.get().depth * 2; + let name = import_time_name(name); + // printf("%*s") counts encoded bytes, not Unicode scalar values. + let padding = (vm.import_timing.get().depth * 2).saturating_sub(name.len()); let _ = writeln!( std::io::stderr(), - "import time: cached | cached | {:>width$}", - import_time_name(name) + "import time: cached | cached | {:padding$}{}", + "", + name ); } } diff --git a/src/settings.rs b/src/settings.rs index 40b67e27eb3..af9cf418876 100644 --- a/src/settings.rs +++ b/src/settings.rs @@ -278,7 +278,7 @@ pub fn parse_opts() -> Result<(Settings, RunMode), lexopt::Error> { "Fatal Python error: config_init_cpu_count: \ -X cpu_count=n option: n is missing or an invalid number, \ n must be greater than 0\n\ - Python runtime state: preinitialized\n" + Python runtime state: preinitialized" ); std::process::exit(1); } @@ -532,7 +532,7 @@ fn parse_import_time(value: Option<&str>, source: &str) -> u8 { eprintln!( "Fatal Python error: config_init_import_time: {source}: \ {numeric}values other than 1 and 2 are reserved for future use.\n\ - Python runtime state: preinitialized" + Python runtime state: preinitialized\n" ); std::process::exit(1); }