search

artichoke / artichoke

💎 Artichoke is a Ruby made with Rust
https://www.artichokeruby.org/
MIT License
3.05k stars 110 forks source link

Replace `log` with `tracing` #1043

Closed lopopolo closed 2 years ago

lopopolo commented 3 years ago

tracing is much more feature-ful than log and seems to be where the ecosystem is moving. tracing can instrument Artichoke in more ways than just plaintext logs, e.g. timing functions.

Below is a WIP patch that I put together, but this needs a more thought out design. This is what the patch looks like with debug logging enabled:

Screen Shot 2021-01-13 at 7 33 38 PM
WIP patch ```patch diff --git a/Cargo.lock b/Cargo.lock index 910ef8373f..d533c71e3c 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -18,6 +18,15 @@ dependencies = [ "winapi", ] +[[package]] +name = "ansi_term" +version = "0.12.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d52a9bb7ec0cf484c551830a7ce27bd20d67eac647e1befb56b0be4ee39a55d2" +dependencies = [ + "winapi", +] + [[package]] name = "artichoke" version = "0.1.0-pre.0" @@ -28,6 +37,8 @@ dependencies = [ "rustyline", "target-lexicon", "termcolor", + "tracing", + "tracing-subscriber", ] [[package]] @@ -40,7 +51,6 @@ dependencies = [ "cc", "intaglio", "itoa", - "log", "once_cell", "onig", "quickcheck", @@ -56,6 +66,7 @@ dependencies = [ "spinoso-symbol", "spinoso-time", "target-lexicon", + "tracing", ] [[package]] @@ -119,6 +130,12 @@ dependencies = [ "memchr", ] +[[package]] +name = "byteorder" +version = "1.4.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ae44d1a3d5a19df61dd0c8beb138458ac2a53a7ac09eba97d55592540004306b" + [[package]] name = "cc" version = "1.0.66" @@ -185,7 +202,7 @@ version = "2.33.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "37e58ac78573c40708d45522f0d80fa2f01cc4f9b4e2bf749807255454312002" dependencies = [ - "ansi_term", + "ansi_term 0.11.0", "atty", "bitflags", "strsim", @@ -291,6 +308,15 @@ dependencies = [ "cfg-if 0.1.10", ] +[[package]] +name = "matchers" +version = "0.0.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f099785f7595cc4b4553a174ce30dd7589ef93391ff414dbb67f62392b9e0ce1" +dependencies = [ + "regex-automata", +] + [[package]] name = "memchr" version = "2.3.4" @@ -381,6 +407,12 @@ version = "0.1.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "19b17cddbe7ec3f8bc800887bab5e717348c95ea2ca0b1bf0837fb964dc67099" +[[package]] +name = "pin-project-lite" +version = "0.2.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "439697af366c49a6d0a010c56a0d97685bc140ce0d377b13a2ea2aa42d64a827" + [[package]] name = "pkg-config" version = "0.3.19" @@ -472,6 +504,16 @@ dependencies = [ "thread_local", ] +[[package]] +name = "regex-automata" +version = "0.1.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ae1ded71d66a4a97f5e961fd0cb25a5f366a42a41570d16a763a69c092c26ae4" +dependencies = [ + "byteorder", + "regex-syntax", +] + [[package]] name = "regex-syntax" version = "0.6.22" @@ -521,6 +563,15 @@ version = "1.1.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "d29ab0c6d3fc0ee92fe66e2d99f700eab17a8d57d1c1d3b748380fb20baa78cd" +[[package]] +name = "sharded-slab" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "79c719719ee05df97490f80a45acfc99e5a30ce98a1e4fb67aee422745ae14e3" +dependencies = [ + "lazy_static", +] + [[package]] name = "shlex" version = "0.1.1" @@ -617,6 +668,17 @@ version = "0.8.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "8ea5119cdb4c55b55d432abb513a0429384878c15dde60cc77b1c99de1a95a6a" +[[package]] +name = "syn" +version = "1.0.58" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "cc60a3d73ea6594cd712d830cc1f0390fd71542d8c8cd24e70cc54cdfd5e05d5" +dependencies = [ + "proc-macro2", + "quote", + "unicode-xid", +] + [[package]] name = "target-lexicon" version = "0.11.1" @@ -650,6 +712,54 @@ dependencies = [ "lazy_static", ] +[[package]] +name = "tracing" +version = "0.1.22" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9f47026cdc4080c07e49b37087de021820269d996f581aac150ef9e5583eefe3" +dependencies = [ + "cfg-if 1.0.0", + "pin-project-lite", + "tracing-attributes", + "tracing-core", +] + +[[package]] +name = "tracing-attributes" +version = "0.1.11" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "80e0ccfc3378da0cce270c946b676a376943f5cd16aeba64568e7939806f4ada" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + +[[package]] +name = "tracing-core" +version = "0.1.17" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f50de3927f93d202783f4513cda820ab47ef17f624b03c096e86ef00c67e6b5f" +dependencies = [ + "lazy_static", +] + +[[package]] +name = "tracing-subscriber" +version = "0.2.15" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a1fa8f0c8f4c594e4fc9debc1990deab13238077271ba84dd853d54902ee3401" +dependencies = [ + "ansi_term 0.12.1", + "lazy_static", + "matchers", + "regex", + "sharded-slab", + "thread_local", + "tracing", + "tracing-core", +] + [[package]] name = "unicode-segmentation" version = "1.7.1" diff --git a/Cargo.toml b/Cargo.toml index 841fb82c5f..9a6a8d5da7 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -21,12 +21,19 @@ categories = ["command-line-utilities"] clap = { version = "2.33", optional = true } rustyline = { version = "7", default-features = false, optional = true } termcolor = { version = "1.1", optional = true } +tracing = { version = "0.1", default-features = false, optional = true } [dependencies.artichoke-backend] version = "0.1" path = "artichoke-backend" default-features = false +[dependencies.tracing-subscriber] +version = "0.2" +default-features = false +features = ["env-filter", "fmt", "ansi", "registry"] +optional = true + [build-dependencies] chrono = { version = "0.4.19", default-features = false, features = ["clock"] } target-lexicon = "0.11.1" @@ -70,7 +77,7 @@ default = [ ] # Enable a CLI frontend for Artichoke, including a `ruby`-equivalent CLI and # REPL. -cli = ["backtrace", "clap", "rustyline"] +cli = ["backtrace", "clap", "rustyline", "tracing", "tracing-subscriber"] # Enable a module for formtting backtraces from Ruby exceptions. backtrace = ["termcolor"] # Enable all features of Ruby Core, Standard Library, and the underlying VM. diff --git a/artichoke-backend/Cargo.toml b/artichoke-backend/Cargo.toml index 25f127eb95..007a415309 100644 --- a/artichoke-backend/Cargo.toml +++ b/artichoke-backend/Cargo.toml @@ -15,7 +15,6 @@ artichoke-core = { version = "0.7", path = "../artichoke-core" } bstr = { version = "0.2, >= 0.2.2", default-features = false, features = ["std"] } intaglio = "1.2" itoa = "0.4" -log = "0.4, >= 0.4.5" once_cell = "1" regex = "1" scolapasta-string-escape = { version = "0.1", path = "../scolapasta-string-escape" } @@ -28,6 +27,7 @@ spinoso-regexp = { version = "0.1", path = "../spinoso-regexp", default-features spinoso-securerandom = { version = "0.1", path = "../spinoso-securerandom", optional = true } spinoso-symbol = { version = "0.1", path = "../spinoso-symbol" } spinoso-time = { version = "0.1", path = "../spinoso-time", optional = true } +tracing = { version = "0.1", default-features = false } [dependencies.onig] version = "6.1" diff --git a/artichoke-backend/src/artichoke.rs b/artichoke-backend/src/artichoke.rs index 2c73b93eab..70bbb2358a 100644 --- a/artichoke-backend/src/artichoke.rs +++ b/artichoke-backend/src/artichoke.rs @@ -1,6 +1,7 @@ use std::ffi::c_void; use std::ops::{Deref, DerefMut}; use std::ptr::NonNull; +use tracing::{span, trace, Level}; use crate::ffi::{self, InterpreterExtractError}; use crate::state::State; @@ -69,6 +70,9 @@ impl Artichoke { F: FnOnce(*mut sys::mrb_state) -> T, { if let Some(state) = self.state.take() { + let span = span!(Level::TRACE, "with_ffi_boundary"); + let _enter = span.enter(); + // Ensure we don't create multiple mutable references by moving the // `mrb` out of the `Artichoke` and converting to a raw pointer. // @@ -89,6 +93,7 @@ impl Artichoke { // moved back into the `mrb`. // 9. Replace `self` with the new interpreter. + trace!("Serializing interpreter"); // Step 1 let mrb = self.mrb.as_ptr(); @@ -96,9 +101,11 @@ impl Artichoke { (*mrb).ud = Box::into_raw(state) as *mut c_void; // Steps 5-7 + trace!("Crossing FFI boundary"); let result = func(mrb); // Step 8 + trace!("Deserializing interpreter"); let extracted = ffi::from_user_data(mrb)?; // Step 9 @@ -132,6 +139,9 @@ impl Artichoke { /// Consume an interpreter and free all live objects. pub fn close(mut self) { + let span = span!(Level::DEBUG, "interpreter close"); + let _enter = span.enter(); + // Safety: // // It is permissible to directly access the `*mut sys::mrb_state` @@ -161,8 +171,12 @@ impl Artichoke { // for Ruby types defined with type tag `MRB_TT_DATA`. unsafe { if let Some(parser) = parser { + let parser_close_span = span!(Level::DEBUG, "parser close"); + let _parser_close_enter = parser_close_span.enter(); parser.close(mrb); } + let mrb_close_span = span!(Level::DEBUG, "mrb_close"); + let _mrb_close_enter = mrb_close_span.enter(); sys::mrb_close(mrb); } diff --git a/artichoke-backend/src/def.rs b/artichoke-backend/src/def.rs index 52f8ef65ac..711251859e 100644 --- a/artichoke-backend/src/def.rs +++ b/artichoke-backend/src/def.rs @@ -3,6 +3,7 @@ use std::error; use std::ffi::{c_void, CStr}; use std::fmt; use std::ptr::NonNull; +use tracing::{error, span, Level}; use crate::class; use crate::class_registry::ClassRegistry; @@ -37,6 +38,9 @@ pub unsafe extern "C" fn box_unbox_free(_mrb: *mut sys::mrb_state, data: *mut where T: 'static + BoxUnboxVmValue, { + let span = span!(Level::TRACE, "box_unbox_free", ruby_type = T::RUBY_TYPE); + let _enter = span.enter(); + if data.is_null() { error!("Received null pointer in box_unbox_free<{}>: {:p}", T::RUBY_TYPE, data); eprintln!("Received null pointer in box_unbox_free<{}>: {:p}", T::RUBY_TYPE, data); diff --git a/artichoke-backend/src/error.rs b/artichoke-backend/src/error.rs index 2ffbcd1261..9cdc415e78 100644 --- a/artichoke-backend/src/error.rs +++ b/artichoke-backend/src/error.rs @@ -2,6 +2,7 @@ use std::borrow::Cow; use std::error; use std::fmt; use std::hint; +use tracing::{error, span, trace, Level}; use crate::sys; use crate::{Artichoke, Guard}; @@ -57,6 +58,9 @@ pub unsafe fn raise(mut guard: Guard<'_>, exception: T) -> ! where T: RubyException + fmt::Debug, { + let span = span!(Level::DEBUG, "raise"); + let enter = span.enter(); + let exc = exception.as_mrb_value(&mut guard); let mrb: *mut sys::mrb_state = guard.mrb.as_mut(); drop(guard); @@ -64,6 +68,8 @@ where // Any non-`Copy` objects that we haven't cleaned up at this point will // leak, so drop everything. drop(exception); + trace!("Unwinding in raise"); + drop(enter); // `mrb_exc_raise` will call longjmp which will unwind the stack. sys::mrb_exc_raise(mrb, exc); } else { @@ -71,6 +77,8 @@ where // Any non-`Copy` objects that we haven't cleaned up at this point will // leak, so drop everything. drop(exception); + trace!("Unwinding in raise"); + drop(enter); // `mrb_sys_raise` will call longjmp which will unwind the stack. sys::mrb_sys_raise( mrb, diff --git a/artichoke-backend/src/eval.rs b/artichoke-backend/src/eval.rs index cd1b9c8c18..59e7acf2c9 100644 --- a/artichoke-backend/src/eval.rs +++ b/artichoke-backend/src/eval.rs @@ -1,6 +1,7 @@ use bstr::ByteSlice; use std::ffi::OsStr; use std::path::Path; +use tracing::{debug, error, span, trace, Level}; use crate::core::{Eval, LoadSources, Parser, Value as _}; use crate::error::Error; @@ -19,6 +20,9 @@ impl Eval for Artichoke { type Error = Error; fn eval(&mut self, code: &[u8]) -> Result { + let span = span!(Level::DEBUG, "eval"); + let _enter = span.enter(); + trace!("Attempting eval of Ruby source"); let result = unsafe { let state = self.state.as_deref_mut().ok_or_else(InterpreterExtractError::new)?; @@ -44,19 +48,25 @@ impl Eval for Artichoke { } Err(exception) => { let exception = self.protect(Value::from(exception)); - let debug = exception.inspect(self); - debug!("Failed eval raised exception: {:?}", debug.as_bstr()); + let inspect = exception.inspect(self); + debug!("Failed eval raised exception: {:?}", inspect.as_bstr()); Err(exception_handler::last_error(self, exception)?) } } } fn eval_os_str(&mut self, code: &OsStr) -> Result { + let span = span!(Level::DEBUG, "eval_os_str"); + let _enter = span.enter(); + let code = ffi::os_str_to_bytes(code)?; self.eval(code) } fn eval_file(&mut self, file: &Path) -> Result { + let span = span!(Level::DEBUG, "eval_file"); + let _enter = span.enter(); + let context = Context::new(ffi::os_str_to_bytes(file.as_os_str())?.to_vec()) .ok_or_else(|| ArgumentError::with_message("path name contains null byte"))?; self.push_context(context)?; diff --git a/artichoke-backend/src/exception_handler.rs b/artichoke-backend/src/exception_handler.rs index 5ebb8a8500..be6618d813 100644 --- a/artichoke-backend/src/exception_handler.rs +++ b/artichoke-backend/src/exception_handler.rs @@ -2,6 +2,7 @@ use bstr::BString; use std::borrow::Cow; use std::error; use std::fmt; +use tracing::{debug, span, Level}; use crate::core::{TryConvertMut, Value as _}; use crate::error::{Error, RubyException}; @@ -127,6 +128,9 @@ impl From for Error { /// exception. If these calls return an error, that error is returned from this /// function. pub fn last_error(interp: &mut Artichoke, exception: Value) -> Result { + let span = span!(Level::DEBUG, "last_error"); + let _enter = span.enter(); + let mut arena = interp.create_arena_savepoint()?; // Clear the current exception from the mruby interpreter so subsequent diff --git a/artichoke-backend/src/extn/core/array/ffi.rs b/artichoke-backend/src/extn/core/array/ffi.rs index 0b46e8289b..42321aa992 100644 --- a/artichoke-backend/src/extn/core/array/ffi.rs +++ b/artichoke-backend/src/extn/core/array/ffi.rs @@ -1,5 +1,6 @@ use std::convert::TryFrom; use std::slice; +use tracing::warn; use crate::extn::core::array::Array; use crate::extn::prelude::*; diff --git a/artichoke-backend/src/extn/core/array/mruby.rs b/artichoke-backend/src/extn/core/array/mruby.rs index 3bce8890b3..4e069d2d6b 100644 --- a/artichoke-backend/src/extn/core/array/mruby.rs +++ b/artichoke-backend/src/extn/core/array/mruby.rs @@ -1,4 +1,5 @@ use std::convert::TryFrom; +use tracing::trace; use crate::extn::core::array; use crate::extn::prelude::*; diff --git a/artichoke-backend/src/extn/core/artichoke/mod.rs b/artichoke-backend/src/extn/core/artichoke/mod.rs index fb55876880..ad105595b3 100644 --- a/artichoke-backend/src/extn/core/artichoke/mod.rs +++ b/artichoke-backend/src/extn/core/artichoke/mod.rs @@ -1,3 +1,5 @@ +use tracing::trace; + use crate::extn::prelude::*; pub fn init(interp: &mut crate::Artichoke) -> InitializeResult<()> { diff --git a/artichoke-backend/src/extn/core/comparable/mod.rs b/artichoke-backend/src/extn/core/comparable/mod.rs index bdfdc6b4f4..71da695482 100644 --- a/artichoke-backend/src/extn/core/comparable/mod.rs +++ b/artichoke-backend/src/extn/core/comparable/mod.rs @@ -1,3 +1,5 @@ +use tracing::trace; + use crate::extn::prelude::*; pub fn init(interp: &mut Artichoke) -> InitializeResult<()> { diff --git a/artichoke-backend/src/extn/core/enumerable/mod.rs b/artichoke-backend/src/extn/core/enumerable/mod.rs index 0c071904be..028863f5d5 100644 --- a/artichoke-backend/src/extn/core/enumerable/mod.rs +++ b/artichoke-backend/src/extn/core/enumerable/mod.rs @@ -1,3 +1,5 @@ +use tracing::trace; + use crate::extn::prelude::*; pub fn init(interp: &mut Artichoke) -> InitializeResult<()> { diff --git a/artichoke-backend/src/extn/core/enumerator/mod.rs b/artichoke-backend/src/extn/core/enumerator/mod.rs index 72fa294621..2ffb0303d3 100644 --- a/artichoke-backend/src/extn/core/enumerator/mod.rs +++ b/artichoke-backend/src/extn/core/enumerator/mod.rs @@ -1,3 +1,5 @@ +use tracing::trace; + use crate::extn::prelude::*; pub fn init(interp: &mut Artichoke) -> InitializeResult<()> { diff --git a/artichoke-backend/src/extn/core/env/mruby.rs b/artichoke-backend/src/extn/core/env/mruby.rs index e1231bc6f1..e52a0b2eea 100644 --- a/artichoke-backend/src/extn/core/env/mruby.rs +++ b/artichoke-backend/src/extn/core/env/mruby.rs @@ -1,6 +1,7 @@ //! FFI glue between the Rust trampolines and the mruby C interpreter. use spinoso_env::RUBY_API_POLYFILLS; +use tracing::trace; use crate::extn::core::artichoke; use crate::extn::core::env::{self, trampoline}; diff --git a/artichoke-backend/src/extn/core/exception/mruby.rs b/artichoke-backend/src/extn/core/exception/mruby.rs index 0c6feae5f6..20d712a7bd 100644 --- a/artichoke-backend/src/extn/core/exception/mruby.rs +++ b/artichoke-backend/src/extn/core/exception/mruby.rs @@ -1,5 +1,7 @@ //! FFI glue between the Rust trampolines and the mruby C interpreter. +use tracing::trace; + use crate::extn::prelude::*; pub fn init(interp: &mut Artichoke) -> InitializeResult<()> { diff --git a/artichoke-backend/src/extn/core/float/mod.rs b/artichoke-backend/src/extn/core/float/mod.rs index 5e69583c2c..c62f8b3019 100644 --- a/artichoke-backend/src/extn/core/float/mod.rs +++ b/artichoke-backend/src/extn/core/float/mod.rs @@ -1,3 +1,5 @@ +use tracing::trace; + use crate::extn::core::numeric::{self, Coercion, Outcome}; use crate::extn::prelude::*; diff --git a/artichoke-backend/src/extn/core/hash/mod.rs b/artichoke-backend/src/extn/core/hash/mod.rs index f3c6eaf6e3..11d35a64e5 100644 --- a/artichoke-backend/src/extn/core/hash/mod.rs +++ b/artichoke-backend/src/extn/core/hash/mod.rs @@ -1,3 +1,5 @@ +use tracing::trace; + use crate::extn::prelude::*; pub fn init(interp: &mut Artichoke) -> InitializeResult<()> { diff --git a/artichoke-backend/src/extn/core/integer/mruby.rs b/artichoke-backend/src/extn/core/integer/mruby.rs index 12408b8e84..14a8905340 100644 --- a/artichoke-backend/src/extn/core/integer/mruby.rs +++ b/artichoke-backend/src/extn/core/integer/mruby.rs @@ -1,3 +1,5 @@ +use tracing::trace; + use crate::extn::core::integer::trampoline; use crate::extn::core::integer::Integer; use crate::extn::prelude::*; diff --git a/artichoke-backend/src/extn/core/kernel/mruby.rs b/artichoke-backend/src/extn/core/kernel/mruby.rs index 64a4dd4f68..723bead888 100644 --- a/artichoke-backend/src/extn/core/kernel/mruby.rs +++ b/artichoke-backend/src/extn/core/kernel/mruby.rs @@ -1,3 +1,5 @@ +use tracing::trace; + use crate::extn::core::artichoke; use crate::extn::core::kernel::{self, trampoline}; use crate::extn::prelude::*; diff --git a/artichoke-backend/src/extn/core/matchdata/mruby.rs b/artichoke-backend/src/extn/core/matchdata/mruby.rs index f960baccd0..d04339cdd8 100644 --- a/artichoke-backend/src/extn/core/matchdata/mruby.rs +++ b/artichoke-backend/src/extn/core/matchdata/mruby.rs @@ -1,3 +1,5 @@ +use tracing::trace; + use crate::extn::core::matchdata::{self, trampoline}; use crate::extn::prelude::*; use crate::sys; diff --git a/artichoke-backend/src/extn/core/method/mod.rs b/artichoke-backend/src/extn/core/method/mod.rs index 316a37f362..4785e608f2 100644 --- a/artichoke-backend/src/extn/core/method/mod.rs +++ b/artichoke-backend/src/extn/core/method/mod.rs @@ -1,3 +1,5 @@ +use tracing::trace; + use crate::extn::prelude::*; pub fn init(interp: &mut Artichoke) -> InitializeResult<()> { diff --git a/artichoke-backend/src/extn/core/mod.rs b/artichoke-backend/src/extn/core/mod.rs index 56671e3a9e..28e568594a 100644 --- a/artichoke-backend/src/extn/core/mod.rs +++ b/artichoke-backend/src/extn/core/mod.rs @@ -1,5 +1,7 @@ #![allow(clippy::too_many_lines)] +use tracing::{debug, span, Level}; + use crate::extn::prelude::*; pub mod array; @@ -36,6 +38,10 @@ pub mod time; pub mod warning; pub fn init(interp: &mut Artichoke) -> InitializeResult<()> { + let span = span!(Level::DEBUG, "initialize interpreter core"); + let _enter = span.enter(); + debug!("begin"); + // These core classes are ordered according to the dependency DAG between // them. let _ = interp.eval(&include_bytes!("object.rb")[..])?; @@ -74,5 +80,7 @@ pub fn init(interp: &mut Artichoke) -> InitializeResult<()> { #[cfg(feature = "core-time")] time::mruby::init(interp)?; warning::init(interp)?; + + debug!("Patched Ruby core onto interpreter"); Ok(()) } diff --git a/artichoke-backend/src/extn/core/module/mod.rs b/artichoke-backend/src/extn/core/module/mod.rs index 4fb0dc555a..8175b03ba3 100644 --- a/artichoke-backend/src/extn/core/module/mod.rs +++ b/artichoke-backend/src/extn/core/module/mod.rs @@ -1,3 +1,5 @@ +use tracing::trace; + use crate::extn::prelude::*; pub fn init(interp: &mut Artichoke) -> InitializeResult<()> { diff --git a/artichoke-backend/src/extn/core/numeric/mod.rs b/artichoke-backend/src/extn/core/numeric/mod.rs index d40d0173a5..e6c8b5124d 100644 --- a/artichoke-backend/src/extn/core/numeric/mod.rs +++ b/artichoke-backend/src/extn/core/numeric/mod.rs @@ -1,3 +1,5 @@ +use tracing::trace; + use crate::extn::core::integer::Integer; use crate::extn::prelude::*; diff --git a/artichoke-backend/src/extn/core/object/mod.rs b/artichoke-backend/src/extn/core/object/mod.rs index a12c603a7e..dd4ce35eb4 100644 --- a/artichoke-backend/src/extn/core/object/mod.rs +++ b/artichoke-backend/src/extn/core/object/mod.rs @@ -1,3 +1,5 @@ +use tracing::trace; + use crate::extn::prelude::*; pub fn init(interp: &mut Artichoke) -> InitializeResult<()> { diff --git a/artichoke-backend/src/extn/core/proc/mod.rs b/artichoke-backend/src/extn/core/proc/mod.rs index 521ddc5d19..1d8c08da28 100644 --- a/artichoke-backend/src/extn/core/proc/mod.rs +++ b/artichoke-backend/src/extn/core/proc/mod.rs @@ -1,3 +1,5 @@ +use tracing::trace; + use crate::extn::prelude::*; pub fn init(interp: &mut Artichoke) -> InitializeResult<()> { diff --git a/artichoke-backend/src/extn/core/random/mruby.rs b/artichoke-backend/src/extn/core/random/mruby.rs index d52668e8ef..c9abc20560 100644 --- a/artichoke-backend/src/extn/core/random/mruby.rs +++ b/artichoke-backend/src/extn/core/random/mruby.rs @@ -1,5 +1,7 @@ //! FFI glue between the Rust trampolines and the mruby C interpreter. +use tracing::trace; + use super::{trampoline, Rng}; use crate::extn::prelude::*; diff --git a/artichoke-backend/src/extn/core/range/mod.rs b/artichoke-backend/src/extn/core/range/mod.rs index d6fcf2fbca..549f6e9f80 100644 --- a/artichoke-backend/src/extn/core/range/mod.rs +++ b/artichoke-backend/src/extn/core/range/mod.rs @@ -1,3 +1,5 @@ +use tracing::trace; + use crate::extn::prelude::*; pub fn init(interp: &mut Artichoke) -> InitializeResult<()> { diff --git a/artichoke-backend/src/extn/core/regexp/mruby.rs b/artichoke-backend/src/extn/core/regexp/mruby.rs index 1710bbaed0..84c59fa83b 100644 --- a/artichoke-backend/src/extn/core/regexp/mruby.rs +++ b/artichoke-backend/src/extn/core/regexp/mruby.rs @@ -1,4 +1,5 @@ use std::convert::TryFrom; +use tracing::trace; use super::{trampoline, Flags, Regexp}; use crate::extn::prelude::*; diff --git a/artichoke-backend/src/extn/core/string/mruby.rs b/artichoke-backend/src/extn/core/string/mruby.rs index e6ba5dcc7f..a8492e458c 100644 --- a/artichoke-backend/src/extn/core/string/mruby.rs +++ b/artichoke-backend/src/extn/core/string/mruby.rs @@ -1,3 +1,5 @@ +use tracing::trace; + use crate::extn::core::string::{self, trampoline}; use crate::extn::prelude::*; diff --git a/artichoke-backend/src/extn/core/symbol/mruby.rs b/artichoke-backend/src/extn/core/symbol/mruby.rs index ecd83054ac..1653547c1a 100644 --- a/artichoke-backend/src/extn/core/symbol/mruby.rs +++ b/artichoke-backend/src/extn/core/symbol/mruby.rs @@ -1,3 +1,5 @@ +use tracing::trace; + use crate::extn::core::symbol::{self, trampoline}; use crate::extn::prelude::*; diff --git a/artichoke-backend/src/extn/core/thread/mod.rs b/artichoke-backend/src/extn/core/thread/mod.rs index 9f946c62fb..a1b3bbfec4 100644 --- a/artichoke-backend/src/extn/core/thread/mod.rs +++ b/artichoke-backend/src/extn/core/thread/mod.rs @@ -1,3 +1,5 @@ +use tracing::trace; + use crate::extn::prelude::*; pub fn init(interp: &mut Artichoke) -> InitializeResult<()> { diff --git a/artichoke-backend/src/extn/core/time/mruby.rs b/artichoke-backend/src/extn/core/time/mruby.rs index 2b26055156..7c5e1f124f 100644 --- a/artichoke-backend/src/extn/core/time/mruby.rs +++ b/artichoke-backend/src/extn/core/time/mruby.rs @@ -1,5 +1,7 @@ //! FFI glue between the Rust trampolines and the mruby C interpreter. +use tracing::trace; + use crate::extn::core::time::{self, trampoline}; use crate::extn::prelude::*; diff --git a/artichoke-backend/src/extn/core/warning/mod.rs b/artichoke-backend/src/extn/core/warning/mod.rs index 7bc35a0a8f..7ff243a93e 100644 --- a/artichoke-backend/src/extn/core/warning/mod.rs +++ b/artichoke-backend/src/extn/core/warning/mod.rs @@ -1,3 +1,5 @@ +use tracing::trace; + use crate::extn::prelude::*; pub fn init(interp: &mut Artichoke) -> InitializeResult<()> { diff --git a/artichoke-backend/src/extn/mod.rs b/artichoke-backend/src/extn/mod.rs index 3fa38d48ee..bd1d488638 100644 --- a/artichoke-backend/src/extn/mod.rs +++ b/artichoke-backend/src/extn/mod.rs @@ -1,5 +1,7 @@ #![allow(clippy::needless_pass_by_value)] +use tracing::{debug, span, Level}; + use crate::release_metadata::ReleaseMetadata; pub mod core; @@ -11,6 +13,13 @@ use prelude::*; pub const INPUT_RECORD_SEPARATOR: &str = "\n"; pub fn init(interp: &mut Artichoke, config: ReleaseMetadata<'_>) -> InitializeResult<()> { + let init_span = span!(Level::DEBUG, "initialize interpreter"); + let _init_enter = init_span.enter(); + debug!("begin"); + + let global_constants_span = span!(Level::TRACE, "initialize global constants"); + let global_constants_enter = global_constants_span.enter(); + let mut copyright = interp.convert_mut(config.ruby_copyright()); copyright.freeze(interp)?; interp.define_global_constant("RUBY_COPYRIGHT", copyright)?; @@ -57,7 +66,11 @@ pub fn init(interp: &mut Artichoke, config: ReleaseMetadata<'_>) -> InitializeRe compiler_version.freeze(interp)?; interp.define_global_constant("ARTICHOKE_COMPILER_VERSION", compiler_version)?; + drop(global_constants_enter); + core::init(interp)?; stdlib::init(interp)?; + + debug!("Successfully initialized Ruby Core and Standard Library"); Ok(()) } diff --git a/artichoke-backend/src/extn/stdlib/mod.rs b/artichoke-backend/src/extn/stdlib/mod.rs index e58b5952dd..fc4d4efbd6 100644 --- a/artichoke-backend/src/extn/stdlib/mod.rs +++ b/artichoke-backend/src/extn/stdlib/mod.rs @@ -1,3 +1,5 @@ +use tracing::{debug, span, Level}; + use crate::extn::prelude::*; #[cfg(feature = "stdlib-abbrev")] @@ -31,6 +33,10 @@ pub mod uri; #[allow(unused_variables)] pub fn init(interp: &mut Artichoke) -> InitializeResult<()> { + let span = span!(Level::DEBUG, "initialize interpreter stdlib"); + let _enter = span.enter(); + debug!("begin"); + #[cfg(feature = "stdlib-abbrev")] abbrev::init(interp)?; #[cfg(feature = "stdlib-base64")] @@ -60,6 +66,6 @@ pub fn init(interp: &mut Artichoke) -> InitializeResult<()> { #[cfg(feature = "stdlib-uri")] uri::init(interp)?; - trace!("Patched Ruby standard library onto interpreter"); + debug!("Patched Ruby standard library onto interpreter"); Ok(()) } diff --git a/artichoke-backend/src/extn/stdlib/securerandom/mruby.rs b/artichoke-backend/src/extn/stdlib/securerandom/mruby.rs index 4da69ca2b5..c5c953e3ae 100644 --- a/artichoke-backend/src/extn/stdlib/securerandom/mruby.rs +++ b/artichoke-backend/src/extn/stdlib/securerandom/mruby.rs @@ -1,5 +1,7 @@ //! FFI glue between the Rust trampolines and the mruby C interpreter. +use tracing::trace; + use crate::extn::prelude::*; use crate::extn::stdlib::securerandom::{self, trampoline}; diff --git a/artichoke-backend/src/ffi.rs b/artichoke-backend/src/ffi.rs index 1aca8d4ddc..ae109d802a 100644 --- a/artichoke-backend/src/ffi.rs +++ b/artichoke-backend/src/ffi.rs @@ -9,6 +9,7 @@ use std::ffi::{OsStr, OsString}; use std::fmt; use std::mem; use std::ptr::{self, NonNull}; +use tracing::{error, trace, warn}; use crate::class_registry::ClassRegistry; use crate::core::ConvertMut; diff --git a/artichoke-backend/src/interpreter.rs b/artichoke-backend/src/interpreter.rs index c6a845134d..6ed78c6a27 100644 --- a/artichoke-backend/src/interpreter.rs +++ b/artichoke-backend/src/interpreter.rs @@ -2,6 +2,7 @@ use std::borrow::Cow; use std::error; use std::ffi::c_void; use std::fmt; +use tracing::{debug, span, Level}; use crate::class_registry::ClassRegistry; use crate::core::{ConvertMut, Eval}; @@ -32,12 +33,16 @@ pub fn interpreter() -> Result { /// [`interpreter`] function. #[allow(clippy::module_name_repetitions)] pub fn interpreter_with_config(config: ReleaseMetadata<'_>) -> Result { + let span = span!(Level::INFO, "interpreter_with_config"); + let _enter = span.enter(); + let state = State::new()?; let state = Box::new(state); let alloc_ud = Box::into_raw(state) as *mut c_void; + debug!("begin allocate"); let raw = unsafe { sys::mrb_open_allocf(Some(sys::mrb_default_allocf), alloc_ud) }; - debug!("Try initializing mrb interpreter"); + debug!("begin init"); let mut interp = unsafe { ffi::from_user_data(raw).map_err(|_| InterpreterAllocError::new())? }; if let Some(ref mut state) = interp.state { @@ -52,9 +57,9 @@ pub fn interpreter_with_config(config: ReleaseMetadata<'_>) -> Result) -> Result, T: File, { + let span = span!(Level::TRACE, "def_file_for_type", file = type_name::()); + let _enter = span.enter(); + let state = self.state.as_deref_mut().ok_or_else(InterpreterExtractError::new)?; let mut path = path.as_ref(); let absolute_path; @@ -34,6 +39,9 @@ impl LoadSources for Artichoke { P: AsRef, T: Into>, { + let span = span!(Level::TRACE, "def_rb_source_file"); + let _enter = span.enter(); + let state = self.state.as_deref_mut().ok_or_else(InterpreterExtractError::new)?; let mut path = path.as_ref(); let absolute_path; @@ -59,6 +67,9 @@ impl LoadSources for Artichoke { where P: AsRef, { + let span = span!(Level::TRACE, "load_source"); + let _enter = span.enter(); + { let state = self.state.as_deref_mut().ok_or_else(InterpreterExtractError::new)?; // Load Rust `File` first because an File may define classes and @@ -73,7 +84,7 @@ impl LoadSources for Artichoke { } let contents = self.read_source_file_contents(path.as_ref())?.into_owned(); self.eval(contents.as_ref())?; - trace!(r#"Successful load of {}"#, path.as_ref().display()); + trace!("Successful load of {}", path.as_ref().display()); Ok(true) } @@ -81,6 +92,9 @@ impl LoadSources for Artichoke { where P: AsRef, { + let span = span!(Level::TRACE, "require_source"); + let _enter = span.enter(); + { let state = self.state.as_deref_mut().ok_or_else(InterpreterExtractError::new)?; // If a file is already required, short circuit. @@ -109,6 +123,9 @@ impl LoadSources for Artichoke { where P: AsRef, { + let span = span!(Level::TRACE, "read_source_file_contents"); + let _enter = span.enter(); + let state = self.state.as_deref().ok_or_else(InterpreterExtractError::new)?; let contents = state.vfs.read_file(path.as_ref())?; Ok(contents.to_vec().into()) diff --git a/artichoke-backend/src/macros.rs b/artichoke-backend/src/macros.rs index c67ded9f2e..6bb93b572f 100644 --- a/artichoke-backend/src/macros.rs +++ b/artichoke-backend/src/macros.rs @@ -3,6 +3,20 @@ // available to all modules within the artichoke-backend crate in addition to // being exported. +#[macro_export] +macro_rules! function_name { + () => {{ + // Okay, this is ugly, I get it. However, this is the best we can get on a stable rust. + fn f() {} + fn type_name_of(_: T) -> &'static str { + std::any::type_name::() + } + let name = type_name_of(f); + // `3` is the length of the `::f`. + &name[..name.len() - 3] + }}; +} + /// Extract an [`Artichoke`] instance from the userdata on a [`sys::mrb_state`]. /// /// If there is an error when extracting the Rust wrapper around the @@ -15,6 +29,8 @@ #[macro_export] macro_rules! unwrap_interpreter { ($mrb:expr, to => $to:ident, or_else = ()) => { + let span = tracing::span!(tracing::Level::TRACE, "Entering Rust from mruby", trampoline = function_name!()); + let _enter = span.enter(); let mut interp = if let Ok(interp) = $crate::ffi::from_user_data($mrb) { interp } else { @@ -31,6 +47,8 @@ macro_rules! unwrap_interpreter { let mut $to = $crate::Guard::new(arena.interp()); }; ($mrb:expr, to => $to:ident, or_else = $default:expr) => { + let span = tracing::span!(tracing::Level::TRACE, "Entering Rust from mruby", trampoline = function_name!()); + let _enter = span.enter(); let mut interp = if let Ok(interp) = $crate::ffi::from_user_data($mrb) { interp } else { diff --git a/artichoke-backend/src/value.rs b/artichoke-backend/src/value.rs index 1173bf6b5c..14e30ea430 100644 --- a/artichoke-backend/src/value.rs +++ b/artichoke-backend/src/value.rs @@ -8,6 +8,7 @@ use std::error; use std::fmt; use std::mem; use std::ptr; +use tracing::{span, trace, warn, Level}; use crate::class_registry::ClassRegistry; use crate::convert::BoxUnboxVmValue; @@ -231,6 +232,15 @@ impl ValueCore for Value { args: &[Self::Arg], block: Option, ) -> Result { + let span = span!( + Level::TRACE, + "Value::funcall", + func, + arg_count = args.len(), + block_present = block.is_some() + ); + let _enter = span.enter(); + if let Ok(arg_count_error) = ArgCountError::try_from(args) { warn!("{}", arg_count_error); return Err(arg_count_error.into()); diff --git a/src/bin/artichoke.rs b/src/bin/artichoke.rs index 905e32a1a5..f43e15e27d 100644 --- a/src/bin/artichoke.rs +++ b/src/bin/artichoke.rs @@ -48,8 +48,20 @@ use std::io::{self, Write}; use std::path::PathBuf; use std::process; use termcolor::{ColorChoice, StandardStream, WriteColor}; +use tracing::{debug, span, trace, Level}; +use tracing_subscriber::EnvFilter; fn main() { + tracing_subscriber::fmt() + .with_env_filter(EnvFilter::from_env("ARTICHOKE_LOG")) + .init(); + let program_span = span!(Level::DEBUG, "main", bin = "artichoke"); + let program_enter = program_span.enter(); + + let arg_parse_span = span!(Level::TRACE, "arg_parse"); + let arg_parse_enter = arg_parse_span.enter(); + trace!("begin"); + let app = App::new("artichoke"); let app = app.about("Artichoke is a Ruby made with Rust."); let app = app.arg( @@ -89,14 +101,29 @@ fn main() { .with_fixture(matches.value_of_os("fixture").map(PathBuf::from)) .with_programfile(matches.value_of_os("programfile").map(PathBuf::from)); + trace!("end"); + drop(arg_parse_enter); + let mut stderr = StandardStream::stderr(ColorChoice::Auto); - match ruby::run(args, io::stdin(), &mut stderr) { + + let run_span = span!(Level::DEBUG, "run"); + let run_enter = run_span.enter(); + debug!("begin"); + let result = ruby::run(args, io::stdin(), &mut stderr); + debug!("end"); + drop(run_enter); + + match result { Ok(Ok(())) => {} - Ok(Err(())) => process::exit(1), + Ok(Err(())) => { + drop(program_enter); + process::exit(1); + } Err(err) => { // reset colors let _ = stderr.reset(); let _ = writeln!(stderr, "{}", err); + drop(program_enter); process::exit(1); } } ```
lopopolo commented 3 years ago

Moving forward with a PR is blocked on https://github.com/tokio-rs/tracing/pull/1173 because Artichoke denies time in its dep tree.

lopopolo commented 2 years ago

https://github.com/artichoke/artichoke/pull/1576 takes the approach to remove the dependency on log since the types of things being logged tended to be fatal errors which are better served by writing directly to stderr.