Add time_to_first_test_discovery

Summary: This timing information gives an insight of how long it takes to finish building the first test binary when 'buck2 test' is executed. It captures the first test discovery time because it occurs earlier than all the test execution.

Reviewed By: iguridi

Differential Revision: D51673956

fbshipit-source-id: 82ee4c9da2a5971ab805768b0af5595367a1228b

app/buck2_client_ctx/src/subscribers/recorder.rs

@@ -103,6 +103,7 @@ mod imp {
         time_to_first_analysis: Option<Duration>,
         time_to_load_first_build_file: Option<Duration>,
         time_to_first_command_execution_start: Option<Duration>,
+        time_to_first_test_discovery: Option<Duration>,
         system_total_memory_bytes: Option<u64>,
         file_watcher_stats: Option<buck2_data::FileWatcherStats>,
         time_to_last_action_execution_end: Option<Duration>,
@@ -195,6 +196,7 @@ mod imp {
                 time_to_first_analysis: None,
                 time_to_load_first_build_file: None,
                 time_to_first_command_execution_start: None,
+                time_to_first_test_discovery: None,
                 system_total_memory_bytes: Some(system_memory_stats()),
                 file_watcher_stats: None,
                 time_to_last_action_execution_end: None,
@@ -356,6 +358,9 @@ mod imp {
                 time_to_first_command_execution_start_ms: self
                     .time_to_first_command_execution_start
                     .and_then(|d| u64::try_from(d.as_millis()).ok()),
+                time_to_first_test_discovery_ms: self
+                    .time_to_first_test_discovery
+                    .and_then(|d| u64::try_from(d.as_millis()).ok()),
                 system_total_memory_bytes: self.system_total_memory_bytes,
                 file_watcher_stats: self.file_watcher_stats.take(),
                 time_to_last_action_execution_end_ms: self
@@ -706,6 +711,16 @@ mod imp {
             Ok(())
         }
 
+        fn handle_test_discovery_start(
+            &mut self,
+            _test_discovery: &buck2_data::TestDiscoveryStart,
+            _event: &BuckEvent,
+        ) -> anyhow::Result<()> {
+            self.time_to_first_test_discovery
+                .get_or_insert_with(|| self.start_time.elapsed());
+            Ok(())
+        }
+
         fn handle_build_graph_info(
             &mut self,
             info: &buck2_data::BuildGraphExecutionInfo,
@@ -921,6 +936,9 @@ mod imp {
                         buck2_data::span_start_event::Data::ExecutorStage(stage) => {
                             self.handle_executor_stage_start(stage, event)
                         }
+                        buck2_data::span_start_event::Data::TestDiscovery(test_discovery) => {
+                            self.handle_test_discovery_start(test_discovery, event)
+                        }
                         _ => Ok(()),
                     }
                 }

app/buck2_data/data.proto

@@ -1738,8 +1738,9 @@ message InvocationRecord {
   repeated ProcessedErrorReport errors = 79;
   // Cache hit rate as it appears in the console
   float cache_hit_rate = 78;
-
   repeated string target_rule_type_names = 80;
+  // Time elapsed from a build's start until first test discovery begins.
+  optional uint64 time_to_first_test_discovery_ms = 81;
 }
 
 // Record event sent directly to scribe.