Add roc_tracing crate and initial traces in mono

Cargo.lock

@@ -2154,6 +2154,15 @@ version = "1.0.2"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "3e2e65a1a2e43cfcb47a895c4c8b10d1f4a61097f9f254f183aee60cad9c651d"
 
+[[package]]
+name = "matchers"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558"
+dependencies = [
+ "regex-automata",
+]
+
 [[package]]
 name = "memchr"
 version = "2.5.0"
@@ -3226,6 +3235,9 @@ name = "regex-automata"
 version = "0.1.10"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132"
+dependencies = [
+ "regex-syntax",
+]
 
 [[package]]
 name = "regex-syntax"
@@ -3473,6 +3485,7 @@ dependencies = [
  "roc_reporting",
  "roc_target",
  "roc_test_utils",
+ "roc_tracing",
  "serial_test",
  "signal-hook",
  "strum",
@@ -3884,6 +3897,7 @@ dependencies = [
  "roc_region",
  "roc_std",
  "roc_target",
+ "roc_tracing",
  "roc_types",
  "static_assertions",
  "ven_pretty",
@@ -4124,6 +4138,14 @@ dependencies = [
  "remove_dir_all 0.7.0",
 ]
 
+[[package]]
+name = "roc_tracing"
+version = "0.0.1"
+dependencies = [
+ "tracing",
+ "tracing-subscriber",
+]
+
 [[package]]
 name = "roc_types"
 version = "0.0.1"
@@ -4463,6 +4485,15 @@ dependencies = [
  "digest 0.10.3",
 ]
 
+[[package]]
+name = "sharded-slab"
+version = "0.1.4"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "900fba806f70c630b0a382d0d825e17a0f19fcd059a2ade1ff237bcddf446b31"
+dependencies = [
+ "lazy_static",
+]
+
 [[package]]
 name = "shlex"
 version = "0.1.1"
@@ -4927,6 +4958,15 @@ dependencies = [
  "syn",
 ]
 
+[[package]]
+name = "thread_local"
+version = "1.1.4"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "5516c27b78311c50bf42c071425c560ac799b11c30b31f87e3081965fe5e0180"
+dependencies = [
+ "once_cell",
+]
+
 [[package]]
 name = "threadpool"
 version = "1.8.1"
@@ -5028,9 +5068,9 @@ dependencies = [
 
 [[package]]
 name = "tracing"
-version = "0.1.35"
+version = "0.1.36"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "a400e31aa60b9d44a52a8ee0343b5b18566b03a8321e0d321f695cf56e940160"
+checksum = "2fce9567bd60a67d08a16488756721ba392f24f29006402881e43b19aac64307"
 dependencies = [
  "cfg-if 1.0.0",
  "log",
@@ -5052,11 +5092,41 @@ dependencies = [
 
 [[package]]
 name = "tracing-core"
-version = "0.1.28"
+version = "0.1.29"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "7b7358be39f2f274f322d2aaed611acc57f382e8eb1e5b48cb9ae30933495ce7"
+checksum = "5aeea4303076558a00714b823f9ad67d58a3bbda1df83d8827d21193156e22f7"
 dependencies = [
  "once_cell",
+ "valuable",
+]
+
+[[package]]
+name = "tracing-log"
+version = "0.1.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "78ddad33d2d10b1ed7eb9d1f518a5674713876e97e5bb9b7345a7984fbb4f922"
+dependencies = [
+ "lazy_static",
+ "log",
+ "tracing-core",
+]
+
+[[package]]
+name = "tracing-subscriber"
+version = "0.3.15"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "60db860322da191b40952ad9affe65ea23e7dd6a5c442c2c42865810c6ab8e6b"
+dependencies = [
+ "ansi_term",
+ "matchers",
+ "once_cell",
+ "regex",
+ "sharded-slab",
+ "smallvec",
+ "thread_local",
+ "tracing",
+ "tracing-core",
+ "tracing-log",
 ]
 
 [[package]]
@@ -5142,6 +5212,12 @@ dependencies = [
  "getrandom",
 ]
 
+[[package]]
+name = "valuable"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d"
+
 [[package]]
 name = "ven_graph"
 version = "2.0.5-pre"

Cargo.toml

@@ -48,6 +48,7 @@ members = [
     "crates/repl_wasm",
     "crates/repl_expect",
     "crates/test_utils",
+    "crates/tracing",
     "crates/utils",
     "crates/docs",
     "crates/docs_cli",

crates/cli/Cargo.toml

@@ -60,6 +60,7 @@ roc_editor = { path = "../editor", optional = true }
 roc_linker = { path = "../linker" }
 roc_repl_cli = { path = "../repl_cli", optional = true }
 roc_repl_expect = { path = "../repl_expect" }
+roc_tracing = { path = "../tracing" }
 clap = { version = "3.1.15", default-features = false, features = ["std", "color", "suggestions"] }
 const_format = { version = "0.2.23", features = ["const_generics"] }
 bumpalo = { version = "3.8.0", features = ["collections"] }

crates/cli/src/main.rs

@@ -25,6 +25,8 @@ use std::ffi::{OsStr, OsString};
 use roc_cli::build;
 
 fn main() -> io::Result<()> {
+    roc_tracing::setup_tracing!();
+
     let matches = build_app().get_matches();
 
     let exit_code = match matches.subcommand() {

crates/compiler/mono/Cargo.toml

@@ -21,6 +21,7 @@ roc_builtins = { path = "../builtins" }
 roc_target = { path = "../roc_target" }
 roc_error_macros = {path="../../error_macros"}
 roc_debug_flags = {path="../debug_flags"}
+roc_tracing = { path = "../../tracing" }
 ven_pretty = { path = "../../vendor/pretty" }
 bumpalo = { version = "3.8.0", features = ["collections"] }
 hashbrown = { version = "0.12.3", features = [ "bumpalo" ] }

crates/compiler/mono/src/ir.rs

@@ -3652,6 +3652,7 @@ where
     instantiate_rigids(env.subs, annotation_var);
 
     procs.push_active_specialization(proc_name.name());
+    roc_tracing::debug!(?proc_name, ?fn_var, fn_content = ?roc_types::subs::SubsFmtContent(env.subs.get_content_without_compacting(fn_var), env.subs), "specialization start");
 
     let specialized = specialize_external(
         env,
@@ -3663,6 +3664,11 @@ where
         partial_proc_id,
     );
 
+    roc_tracing::debug!(
+        ?proc_name,
+        succeeded = specialized.is_ok(),
+        "specialization end"
+    );
     procs.pop_active_specialization(proc_name.name());
 
     match specialized {

crates/tracing/Cargo.toml

@@ -0,0 +1,11 @@
+[package]
+name = "roc_tracing"
+version = "0.0.1"
+authors = ["The Roc Contributors"]
+license = "UPL-1.0"
+edition = "2021"
+description = "Utilities for setting up tracing at various executable entry points."
+
+[dependencies]
+tracing = { version = "0.1.36", features = ["release_max_level_off"] }
+tracing-subscriber = { version = "0.3.15", features = ["env-filter"] }

crates/tracing/src/lib.rs

@@ -0,0 +1,42 @@
+//! Utilities for turning on tracing in user-facing or test executables of the Roc compiler.
+//!
+//! Tracing always writes to stderr, and is controlled with the ROC_LOG environment variable.
+//!
+//! Rather than using the Rust `tracing` crate (or any other tracing crate) directly,
+//! you should use the exposed members of `roc_tracing` for your tracing needs.
+//! This enables us to easily modify the tracing infrastructure without inducing sweeping changes.
+//!
+//! Tracing is only turned on in debug builds. Use the provided [setup_tracing] macro to turn on
+//! tracing at an executable's entry point.
+
+/// Sets up tracing of a Roc executable.
+///
+/// This macro should only be invoked at an executable's entry point.
+/// Tracing will only be enabled in debug builds.
+/// Tracing is controlled with the `ROC_LOG` environment variable. See [directive-syntax] for the filtering directive syntax.
+///
+/// [directive-syntax]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html#directives
+#[macro_export]
+macro_rules! setup_tracing {
+    () => {
+        if cfg!(debug_assertions) {
+            $crate::setup_tracing();
+        }
+    };
+}
+
+pub use tracing::debug;
+pub use tracing::info;
+
+const ENV_FILTER: &str = "ROC_LOG";
+
+use tracing_subscriber::{fmt, prelude::*, EnvFilter, Layer, Registry};
+
+#[doc(hidden)]
+pub fn setup_tracing() {
+    let stderr_layer = fmt::Layer::default()
+        .with_writer(std::io::stderr)
+        .with_filter(EnvFilter::from_env(ENV_FILTER));
+
+    Registry::default().with(stderr_layer).init();
+}