perf: improve init performance (#3074)

* perf: improve init performance

* refactor: consolidate backend_meta code

e2e/backend/test_asdf_fake_list

@@ -0,0 +1,8 @@
+#!/usr/bin/env bash
+
+mise uninstall --all tiny
+mise install tiny@1 tiny@2
+mise asdf install tiny
+assert "mise asdf list tiny" "1.1.0
+2.1.0
+3.1.0"

e2e/plugins/test_plugin_install

@@ -33,3 +33,6 @@ mise plugin uninstall tiny
 mise plugin update
 mise plugin update shfmt
 mise i
+
+assert_contains "mise plugin install mise-x 2>&1 || true" "No repository found for plugin mise-x"
+assert_contains "mise plugin add node 2>&1 || true" "node is a core plugin and does not need to be installed"

src/backend/mod.rs

@@ -55,46 +55,22 @@ pub fn load_tools() {
     let core_tools = CORE_PLUGINS.values().cloned().collect::<Vec<ABackend>>();
     let mut tools = core_tools;
     time!("load_tools core");
-    let plugins = install_state::list_plugins()
-        .map_err(|err| {
-            warn!("{err:#}");
-        })
-        .unwrap_or_default();
-    if !SETTINGS.disable_backends.contains(&"asdf".to_string()) {
-        tools.extend(
-            plugins
-                .iter()
-                .filter(|(_, p)| **p == PluginType::Asdf)
-                .map(|(p, _)| {
-                    arg_to_backend(BackendArg::new(p.to_string(), Some(format!("asdf:{p}"))))
-                        .unwrap()
-                }),
-        );
-    }
-    time!("load_tools asdf");
-    if !SETTINGS.disable_backends.contains(&"vfox".to_string()) {
-        tools.extend(
-            plugins
-                .iter()
-                .filter(|(_, p)| **p == PluginType::Vfox)
-                .map(|(p, _)| {
-                    arg_to_backend(BackendArg::new(p.to_string(), Some(format!("vfox:{p}"))))
-                        .unwrap()
-                }),
-        );
-    }
-    time!("load_tools vfox");
     tools.extend(
         install_state::list_tools()
             .map_err(|err| {
                 warn!("{err:#}");
             })
             .unwrap_or_default()
             .into_values()
-            .flat_map(|ist| arg_to_backend(BackendArg::new(ist.short, Some(ist.full)))),
+            .flat_map(|ist| arg_to_backend(ist.into())),
     );
     time!("load_tools install_state");
     tools.retain(|backend| !SETTINGS.disable_tools().contains(backend.id()));
+    tools.retain(|backend| {
+        !SETTINGS
+            .disable_backends
+            .contains(&backend.get_type().to_string())
+    });
 
     let tools: BackendMap = tools
         .into_iter()
@@ -395,7 +371,7 @@ pub trait Backend: Debug + Send + Sync {
             return Err(e);
         }
 
-        self.write_backend_meta()?;
+        install_state::write_backend_meta(self.ba())?;
 
         self.cleanup_install_dirs(&ctx.tv);
         // attempt to touch all the .tool-version files to trigger updates in hook-env
@@ -604,13 +580,6 @@ pub trait Backend: Debug + Send + Sync {
             })
             .clone()
     }
-
-    fn write_backend_meta(&self) -> eyre::Result<()> {
-        file::write(
-            self.ba().installs_path.join(".mise.backend"),
-            format!("{}\n{}", self.ba().short, self.ba().full()),
-        )
-    }
 }
 
 fn find_match_in_list(list: &[String], query: &str) -> Option<String> {

src/cli/args/backend_arg.rs

@@ -2,6 +2,7 @@ use crate::backend::backend_type::BackendType;
 use crate::backend::{unalias_backend, ABackend};
 use crate::config::CONFIG;
 use crate::registry::REGISTRY;
+use crate::toolset::install_state::InstallStateTool;
 use crate::toolset::{install_state, parse_tool_options, ToolVersionOptions};
 use crate::{backend, config, dirs, registry};
 use contracts::requires;
@@ -49,6 +50,12 @@ impl<A: AsRef<str>> From<A> for BackendArg {
     }
 }
 
+impl From<InstallStateTool> for BackendArg {
+    fn from(ist: InstallStateTool) -> Self {
+        Self::new(ist.short, ist.full)
+    }
+}
+
 impl BackendArg {
     #[requires(!short.is_empty())]
     pub fn new(short: String, full: Option<String>) -> Self {

src/cli/exec.rs

@@ -53,21 +53,27 @@ pub struct Exec {
 
 impl Exec {
     pub fn run(self) -> Result<()> {
-        let mut ts = ToolsetBuilder::new()
-            .with_args(&self.tool)
-            .with_default_to_latest(true)
-            .build(&CONFIG)?;
+        let mut ts = measure!("toolset", {
+            ToolsetBuilder::new()
+                .with_args(&self.tool)
+                .with_default_to_latest(true)
+                .build(&CONFIG)?
+        });
         let opts = InstallOptions {
             force: false,
             jobs: self.jobs,
             raw: self.raw,
             resolve_options: Default::default(),
         };
-        ts.install_arg_versions(&CONFIG, &opts)?;
-        ts.notify_if_versions_missing();
+        measure!("install_arg_versions", {
+            ts.install_arg_versions(&CONFIG, &opts)?
+        });
+        measure!("notify_if_versions_missing", {
+            ts.notify_if_versions_missing()
+        });
 
         let (program, args) = parse_command(&env::SHELL, &self.command, &self.c);
-        let env = ts.env_with_path(&CONFIG)?;
+        let env = measure!("env_with_path", { ts.env_with_path(&CONFIG)? });
 
         time!("exec");
         self.exec(program, args, env)

src/cli/mod.rs

@@ -124,7 +124,6 @@ pub enum Commands {
 
 impl Commands {
     pub fn run(self) -> Result<()> {
-        time!("run {self}");
         match self {
             Self::Activate(cmd) => cmd.run(),
             Self::Alias(cmd) => cmd.run(),
@@ -208,38 +207,51 @@ pub static CLI: Lazy<clap::Command> = Lazy::new(|| {
 impl Cli {
     pub fn run(args: &Vec<String>) -> Result<()> {
         crate::env::ARGS.write().unwrap().clone_from(args);
-        time!("run init");
-        shims::handle_shim()?;
-        time!("run handle_shim");
+        measure!("hande_shim", { shims::handle_shim() })?;
         ctrlc::init();
         version::print_version_if_requested(args)?;
-        time!("run print_version_if_requested");
 
-        let matches = CLI.clone().try_get_matches_from(args).unwrap_or_else(|_| {
-            time!("run get_matches_from fallback");
-            CLI.clone()
-                .subcommands(external::commands())
-                .get_matches_from(args)
+        let matches = measure!("pre_settings", { Self::pre_settings(args) })?;
+        measure!("add_cli_matches", { Settings::add_cli_matches(&matches) });
+        measure!("settings", {
+            let _ = Settings::try_get();
         });
-        time!("run get_matches_from");
-        Settings::add_cli_matches(&matches);
-        time!("run add_cli_matches");
-        logger::init();
-        time!("run logger init");
-        migrate::run();
+        measure!("logger", { logger::init() });
+        measure!("migrate", { migrate::run() });
         if let Err(err) = crate::cache::auto_prune() {
             warn!("auto_prune failed: {err:?}");
         }
 
         debug!("ARGS: {}", &args.join(" "));
         match Commands::from_arg_matches(&matches) {
-            Ok(cmd) => cmd.run(),
+            Ok(cmd) => measure!("run {cmd}", { cmd.run() }),
             Err(err) => matches
                 .subcommand()
                 .ok_or(err)
                 .map(|(command, sub_m)| external::execute(&command.into(), sub_m))?,
         }
     }
+
+    fn pre_settings(args: &Vec<String>) -> Result<clap::ArgMatches> {
+        let mut results = vec![];
+        let mut matches = None;
+        rayon::scope(|r| {
+            r.spawn(|_| {
+                measure!("install_state", {
+                    results.push(crate::install_state::init())
+                });
+            });
+            measure!("get_matches_from", {
+                matches = Some(CLI.clone().try_get_matches_from(args).unwrap_or_else(|_| {
+                    CLI.clone()
+                        .subcommands(external::commands())
+                        .get_matches_from(args)
+                }));
+            });
+        });
+        results.into_iter().try_for_each(|r| r)?;
+        Ok(matches.unwrap())
+    }
 }
 
 const LONG_ABOUT: &str = indoc! {"

src/config/settings.rs

@@ -71,6 +71,10 @@ static DEFAULT_SETTINGS: Lazy<SettingsPartial> = Lazy::new(|| {
     s
 });
 
+// pub fn is_loaded() -> bool {
+//     BASE_SETTINGS.read().unwrap().is_some()
+// }
+
 #[derive(Serialize, Deserialize)]
 pub struct SettingsFile {
     #[serde(default)]

src/main.rs

@@ -15,6 +15,9 @@ mod output;
 #[macro_use]
 mod hint;
 
+#[macro_use]
+mod timings;
+
 #[macro_use]
 mod cmd;
 
@@ -62,19 +65,18 @@ mod toolset;
 mod ui;
 mod versions_host;
 
-pub use crate::exit::exit;
+pub(crate) use crate::exit::exit;
+pub(crate) use crate::toolset::install_state;
 
 fn main() -> eyre::Result<()> {
     color_eyre::install()?;
-    output::get_time_diff(""); // throwaway call to initialize the timer
-    let args = env::args().collect_vec();
-    time!("main start");
-
-    match Cli::run(&args).with_section(|| VERSION.to_string().header("Version:")) {
-        Ok(()) => Ok(()),
-        Err(err) => handle_err(err),
-    }?;
-    time!("main done");
+    measure!("main", {
+        let args = env::args().collect_vec();
+        match Cli::run(&args).with_section(|| VERSION.to_string().header("Version:")) {
+            Ok(()) => Ok(()),
+            Err(err) => handle_err(err),
+        }?;
+    });
     Ok(())
 }
 

src/output.rs

@@ -1,5 +1,3 @@
-use crate::env;
-use crate::ui::{style, time};
 use once_cell::sync::Lazy;
 use std::collections::HashSet;
 use std::sync::Mutex;
@@ -98,69 +96,6 @@ macro_rules! info {
     }};
 }
 
-pub fn get_time_diff(module: &str) -> String {
-    if *env::MISE_TIMINGS == 0 {
-        return "".to_string();
-    }
-    static START: std::sync::Mutex<Option<std::time::Instant>> = std::sync::Mutex::new(None);
-    static PREV: std::sync::Mutex<Option<std::time::Instant>> = std::sync::Mutex::new(None);
-    let now = std::time::Instant::now();
-    if PREV.lock().unwrap().is_none() {
-        *START.lock().unwrap() = Some(std::time::Instant::now());
-        *PREV.lock().unwrap() = Some(std::time::Instant::now());
-    }
-    let mut prev = PREV.lock().unwrap();
-    let diff = now.duration_since(prev.unwrap());
-    *prev = Some(now);
-    let diff_str = if *env::MISE_TIMINGS == 2 {
-        let relative = time::format_duration(diff);
-        let from_start = time::format_duration(now.duration_since(START.lock().unwrap().unwrap()));
-        format!("{relative} {from_start}")
-    } else {
-        time::format_duration(diff)
-    };
-    let thread_id = crate::logger::thread_id();
-    let out = format!("[TIME] {thread_id} {module} {diff_str}")
-        .trim()
-        .to_string();
-    if diff.as_micros() > 8000 {
-        style::eblack(out).on_red().on_bright()
-    } else if diff.as_micros() > 4000 {
-        style::eblack(out).on_red()
-    } else if diff.as_micros() > 2000 {
-        style::ered(out).bright()
-    } else if diff.as_micros() > 1000 {
-        style::eyellow(out).bright()
-    } else if diff.as_micros() > 500 {
-        style::eyellow(out).dim()
-    } else if diff.as_micros() > 100 {
-        style::ecyan(out).dim()
-    } else {
-        style::edim(out)
-    }
-    .to_string()
-}
-
-#[macro_export]
-macro_rules! time {
-    ($fn:expr) => {{
-        if *$crate::env::MISE_TIMINGS > 0 {
-            let module = format!("{}::{}", module_path!(), format!($fn));
-            eprintln!("{}", $crate::output::get_time_diff(&module));
-        } else {
-            trace!($fn);
-        }
-    }};
-    ($fn:expr, $($arg:tt)+) => {{
-        if *$crate::env::MISE_TIMINGS > 0 {
-            let module = format!("{}::{}", module_path!(), format!($fn, $($arg)+));
-            eprintln!("{}", $crate::output::get_time_diff(&module));
-        } else {
-            trace!($fn, $($arg)+);
-        }
-    }};
-}
-
 #[macro_export]
 macro_rules! info_trunc {
     ($($arg:tt)*) => {{