Capture Performance metrics (#108)

Author: DonJayamanne

crates/pet-core/src/telemetry/mod.rs

@@ -4,17 +4,19 @@
 use inaccurate_python_info::InaccuratePythonEnvironmentInfo;
 use missing_conda_info::MissingCondaEnvironments;
 use missing_poetry_info::MissingPoetryEnvironments;
+use refresh_performance::RefreshPerformance;
 use serde::{Deserialize, Serialize};
 
 pub mod inaccurate_python_info;
 pub mod missing_conda_info;
 pub mod missing_poetry_info;
+pub mod refresh_performance;
 
 pub type NumberOfCustomSearchPaths = u32;
 
 #[derive(Serialize, Deserialize)]
 #[serde(rename_all = "camelCase")]
-#[derive(Debug, Clone, Copy)]
+#[derive(Debug, Clone)]
 pub enum TelemetryEvent {
     /// Total time taken to search for Global environments.
     GlobalEnvironmentsSearchCompleted(std::time::Duration),
@@ -34,6 +36,8 @@ pub enum TelemetryEvent {
     MissingCondaEnvironments(MissingCondaEnvironments),
     /// Sent when an environment is discovered by spawning poetry and not found otherwise.
     MissingPoetryEnvironments(MissingPoetryEnvironments),
+    /// Telemetry with metrics for finding all environments as a result of refresh.
+    RefreshPerformance(RefreshPerformance),
 }
 
 pub fn get_telemetry_event_name(event: &TelemetryEvent) -> &'static str {
@@ -52,5 +56,6 @@ pub fn get_telemetry_event_name(event: &TelemetryEvent) -> &'static str {
         TelemetryEvent::InaccuratePythonEnvironmentInfo(_) => "InaccuratePythonEnvironmentInfo",
         TelemetryEvent::MissingCondaEnvironments(_) => "MissingCondaEnvironments",
         TelemetryEvent::MissingPoetryEnvironments(_) => "MissingPoetryEnvironments",
+        TelemetryEvent::RefreshPerformance(_) => "RefreshPerformance",
     }
 }

crates/pet-core/src/telemetry/refresh_performance.rs

@@ -0,0 +1,20 @@
+// Copyright (c) Microsoft Corporation.
+// Licensed under the MIT License.
+
+use std::collections::BTreeMap;
+
+use serde::{Deserialize, Serialize};
+
+/// Telemetry with metrics for finding all environments as a result of refresh.
+/// All durations are in milliseconds.
+#[derive(Serialize, Deserialize)]
+#[serde(rename_all = "camelCase")]
+#[derive(Debug, Clone)]
+pub struct RefreshPerformance {
+    /// Total time taken to find all envs.
+    pub total: u128,
+    /// Breakdown of Global VirtualEnvs, Path, Workspace and the locators.
+    pub breakdown: BTreeMap<String, u128>,
+    /// Breakdown of each individual locators such as conda, pyenv, etc.
+    pub locators: BTreeMap<String, u128>,
+}

crates/pet-reporter/src/jsonrpc.rs

@@ -26,7 +26,7 @@ impl Reporter for JsonRpcReporter {
     fn report_telemetry(&self, event: &TelemetryEvent) {
         let event = TelemetryData {
             event: get_telemetry_event_name(event).to_string(),
-            data: *event,
+            data: event.clone(),
         };
         trace!("Telemetry event {:?}", event.event);
         send_message("telemetry", Some(event))

crates/pet/src/find.rs

@@ -24,12 +24,9 @@ use std::{sync::Arc, thread};
 use crate::locators::identify_python_environment_using_locators;
 
 pub struct Summary {
-    pub time: Duration,
-    pub find_locators_times: BTreeMap<&'static str, Duration>,
-    pub find_locators_time: Duration,
-    pub find_path_time: Duration,
-    pub find_global_virtual_envs_time: Duration,
-    pub find_workspace_directories_time: Duration,
+    pub total: Duration,
+    pub locators: BTreeMap<&'static str, Duration>,
+    pub breakdown: BTreeMap<&'static str, Duration>,
 }
 
 #[derive(Debug, Clone, Deserialize, Serialize)]
@@ -49,12 +46,9 @@ pub fn find_and_report_envs(
     search_scope: Option<SearchScope>,
 ) -> Arc<Mutex<Summary>> {
     let summary = Arc::new(Mutex::new(Summary {
-        time: Duration::from_secs(0),
-        find_locators_times: BTreeMap::new(),
-        find_locators_time: Duration::from_secs(0),
-        find_path_time: Duration::from_secs(0),
-        find_global_virtual_envs_time: Duration::from_secs(0),
-        find_workspace_directories_time: Duration::from_secs(0),
+        total: Duration::from_secs(0),
+        locators: BTreeMap::new(),
+        breakdown: BTreeMap::new(),
     }));
     let start = std::time::Instant::now();
 
@@ -88,13 +82,17 @@ pub fn find_and_report_envs(
                             summary
                                 .lock()
                                 .unwrap()
-                                .find_locators_times
+                                .locators
                                 .insert(locator.get_name(), start.elapsed());
                         });
                     }
                 });
             }
-            summary.lock().unwrap().find_locators_time = start.elapsed();
+            summary
+                .lock()
+                .unwrap()
+                .breakdown
+                .insert("Locators", start.elapsed());
         });
         // Step 2: Search in PATH variable
         s.spawn(|| {
@@ -115,7 +113,11 @@ pub fn find_and_report_envs(
                     &global_env_search_paths,
                 );
             }
-            summary.lock().unwrap().find_path_time = start.elapsed();
+            summary
+                .lock()
+                .unwrap()
+                .breakdown
+                .insert("Path", start.elapsed());
         });
         // Step 3: Search in some global locations for virtual envs.
         s.spawn(|| {
@@ -146,7 +148,11 @@ pub fn find_and_report_envs(
                     &global_env_search_paths,
                 );
             }
-            summary.lock().unwrap().find_global_virtual_envs_time = start.elapsed();
+            summary
+                .lock()
+                .unwrap()
+                .breakdown
+                .insert("GlobalVirtualEnvs", start.elapsed());
         });
         // Step 4: Find in workspace folders too.
         // This can be merged with step 2 as well, as we're only look for environments
@@ -176,10 +182,14 @@ pub fn find_and_report_envs(
                     });
                 }
             }
-            summary.lock().unwrap().find_workspace_directories_time = start.elapsed();
+            summary
+                .lock()
+                .unwrap()
+                .breakdown
+                .insert("Workspaces", start.elapsed());
         });
     });
-    summary.lock().unwrap().time = start.elapsed();
+    summary.lock().unwrap().total = start.elapsed();
 
     summary
 }

crates/pet/src/jsonrpc.rs

@@ -6,8 +6,11 @@ use pet::resolve::resolve_environment;
 use pet_conda::Conda;
 use pet_conda::CondaLocator;
 use pet_core::python_environment::PythonEnvironment;
+use pet_core::telemetry::refresh_performance::RefreshPerformance;
+use pet_core::telemetry::TelemetryEvent;
 use pet_core::{
     os_environment::{Environment, EnvironmentApi},
+    reporter::Reporter,
     Configuration, Locator,
 };
 use pet_env_var_path::get_search_paths_from_env_variables;
@@ -21,14 +24,17 @@ use pet_reporter::collect;
 use pet_reporter::{cache::CacheReporter, jsonrpc};
 use pet_telemetry::report_inaccuracies_identified_after_resolving;
 use serde::{Deserialize, Serialize};
+use serde_json::json;
 use serde_json::{self, Value};
+use std::collections::BTreeMap;
 use std::sync::atomic::{AtomicBool, Ordering};
+use std::time::Duration;
 use std::{
     ops::Deref,
     path::PathBuf,
     sync::{Arc, RwLock},
     thread,
-    time::{Duration, SystemTime},
+    time::SystemTime,
 };
 
 use crate::find::find_and_report_envs;
@@ -132,6 +138,10 @@ impl RefreshResult {
 }
 
 pub fn handle_refresh(context: Arc<Context>, id: u32, params: Value) {
+    let params = match params {
+        Value::Null => json!({}),
+        _ => params,
+    };
     match serde_json::from_value::<RefreshOptions>(params.clone()) {
         Ok(refres_options) => {
             // Start in a new thread, we can have multiple requests.
@@ -148,25 +158,31 @@ pub fn handle_refresh(context: Arc<Context>, id: u32, params: Value) {
                     refres_options.search_scope,
                 );
                 let summary = summary.lock().unwrap();
-                for locator in summary.find_locators_times.iter() {
+                for locator in summary.locators.iter() {
                     info!("Locator {} took {:?}", locator.0, locator.1);
                 }
-                info!(
-                    "Environments found using locators in {:?}",
-                    summary.find_locators_time
-                );
-                info!("Environments in PATH found in {:?}", summary.find_path_time);
-                info!(
-                    "Environments in global virtual env paths found in {:?}",
-                    summary.find_global_virtual_envs_time
-                );
-                info!(
-                    "Environments in workspace folders found in {:?}",
-                    summary.find_workspace_directories_time
-                );
-                trace!("Finished refreshing environments in {:?}", summary.time);
-                send_reply(id, Some(RefreshResult::new(summary.time)));
+                for item in summary.breakdown.iter() {
+                    info!("Locator {} took {:?}", item.0, item.1);
+                }
+                trace!("Finished refreshing environments in {:?}", summary.total);
+                send_reply(id, Some(RefreshResult::new(summary.total)));
 
+                let perf = RefreshPerformance {
+                    total: summary.total.as_millis(),
+                    locators: summary
+                        .locators
+                        .clone()
+                        .iter()
+                        .map(|(k, v)| (k.to_string(), v.as_millis()))
+                        .collect::<BTreeMap<String, u128>>(),
+                    breakdown: summary
+                        .breakdown
+                        .clone()
+                        .iter()
+                        .map(|(k, v)| (k.to_string(), v.as_millis()))
+                        .collect::<BTreeMap<String, u128>>(),
+                };
+                reporter.report_telemetry(&TelemetryEvent::RefreshPerformance(perf));
                 // Find an report missing envs for the first launch of this process.
                 if MISSING_ENVS_REPORTED
                     .compare_exchange(false, true, Ordering::Acquire, Ordering::Relaxed)

crates/pet/src/lib.rs

@@ -125,32 +125,25 @@ fn find_envs(
 
     if options.print_summary {
         let summary = summary.lock().unwrap();
-        if !summary.find_locators_times.is_empty() {
+        if !summary.locators.is_empty() {
             println!();
             println!("Breakdown by each locator:");
             println!("--------------------------");
-            for locator in summary.find_locators_times.iter() {
+            for locator in summary.locators.iter() {
                 println!("{:<20} : {:?}", locator.0, locator.1);
             }
+            println!()
+        }
+
+        if !summary.breakdown.is_empty() {
+            println!("Breakdown for finding Environments:");
+            println!("-----------------------------------");
+            for item in summary.breakdown.iter() {
+                println!("{:<20} : {:?}", item.0, item.1);
+            }
             println!();
         }
 
-        println!("Breakdown for finding Environments:");
-        println!("-----------------------------------");
-        println!(
-            "{:<20} : {:?}",
-            "Using locators", summary.find_locators_time
-        );
-        println!("{:<20} : {:?}", "PATH Variable", summary.find_path_time);
-        println!(
-            "{:<20} : {:?}",
-            "Global virtual envs", summary.find_global_virtual_envs_time
-        );
-        println!(
-            "{:<20} : {:?}",
-            "Workspace folders", summary.find_workspace_directories_time
-        );
-        println!();
         let summary = stdio_reporter.get_summary();
         if !summary.managers.is_empty() {
             println!("Managers:");