Instrument edit events (#4006)

The goal of this PR is to send up events that contain the duration of
keyboard activity within Zed. I built the `EventCoalescer`, which gets
called called each time a key is pressed, within any environment (in the
case of this PR, within "editor" and "terminal). The" `EventCoalescer`
holds a start and end DateTime and adjusts the end instant as events
come in, until a timeout from the last event is hit.

I did my best to keep this mechanism efficient (avoiding vectors to
store moments in time, avoiding spawning timers threads, etc.), because
I know this is going to be per keystroke, but its behind a lock on the
telemetry struck, since it has to know when the environment changes, in
which point, it will automatically end the activity period, even if
there is no timeout. Because we have to have access to it from different
parts of the system, we have to go through the lock, which worried me a
bit (@mikayla-maki's intuition is that it should be fine).

As for the event, I take the time between the durations reported by the
event coalescer and send that up to zed - the indention is to
reconstruct the start and end times on zed.dev, in the same way we use
the event offset times and the time on zed.dev to get the official event
timestamp, and avoid the issue of the user having their system clocks
set wrong.

I'd really appreciate it if @nathansobo or @maxbrunsfeld could check
this out.

Release Notes:

- N/A

crates/client/src/telemetry.rs

@@ -1,3 +1,5 @@
+mod event_coalescer;
+
 use crate::{TelemetrySettings, ZED_SECRET_CLIENT_TOKEN, ZED_SERVER_URL};
 use chrono::{DateTime, Utc};
 use futures::Future;
@@ -5,7 +7,6 @@ use gpui::{AppContext, AppMetadata, BackgroundExecutor, Task};
 use lazy_static::lazy_static;
 use parking_lot::Mutex;
 use serde::Serialize;
-use serde_json;
 use settings::{Settings, SettingsStore};
 use std::{env, io::Write, mem, path::PathBuf, sync::Arc, time::Duration};
 use sysinfo::{
@@ -15,6 +16,8 @@ use tempfile::NamedTempFile;
 use util::http::HttpClient;
 use util::{channel::ReleaseChannel, TryFutureExt};
 
+use self::event_coalescer::EventCoalescer;
+
 pub struct Telemetry {
     http_client: Arc<dyn HttpClient>,
     executor: BackgroundExecutor,
@@ -34,6 +37,7 @@ struct TelemetryState {
     log_file: Option<NamedTempFile>,
     is_staff: Option<bool>,
     first_event_datetime: Option<DateTime<Utc>>,
+    event_coalescer: EventCoalescer,
 }
 
 const EVENTS_URL_PATH: &'static str = "/api/events";
@@ -118,19 +122,24 @@ pub enum Event {
         value: String,
         milliseconds_since_first_event: i64,
     },
+    Edit {
+        duration: i64,
+        environment: &'static str,
+        milliseconds_since_first_event: i64,
+    },
 }
 
 #[cfg(debug_assertions)]
-const MAX_QUEUE_LEN: usize = 1;
+const MAX_QUEUE_LEN: usize = 5;
 
 #[cfg(not(debug_assertions))]
 const MAX_QUEUE_LEN: usize = 50;
 
 #[cfg(debug_assertions)]
-const DEBOUNCE_INTERVAL: Duration = Duration::from_secs(1);
+const FLUSH_DEBOUNCE_INTERVAL: Duration = Duration::from_secs(1);
 
 #[cfg(not(debug_assertions))]
-const DEBOUNCE_INTERVAL: Duration = Duration::from_secs(60 * 5);
+const FLUSH_DEBOUNCE_INTERVAL: Duration = Duration::from_secs(60 * 5);
 
 impl Telemetry {
     pub fn new(client: Arc<dyn HttpClient>, cx: &mut AppContext) -> Arc<Self> {
@@ -150,11 +159,12 @@ impl Telemetry {
             installation_id: None,
             metrics_id: None,
             session_id: None,
-            events_queue: Default::default(),
-            flush_events_task: Default::default(),
+            events_queue: Vec::new(),
+            flush_events_task: None,
             log_file: None,
             is_staff: None,
             first_event_datetime: None,
+            event_coalescer: EventCoalescer::new(),
         }));
 
         cx.observe_global::<SettingsStore>({
@@ -194,7 +204,7 @@ impl Telemetry {
     #[cfg(not(any(test, feature = "test-support")))]
     fn shutdown_telemetry(self: &Arc<Self>) -> impl Future<Output = ()> {
         self.report_app_event("close");
-        self.flush_events();
+        // TODO: close final edit period and make sure it's sent
         Task::ready(())
     }
 
@@ -392,6 +402,22 @@ impl Telemetry {
         }
     }
 
+    pub fn log_edit_event(self: &Arc<Self>, environment: &'static str) {
+        let mut state = self.state.lock();
+        let coalesced_duration = state.event_coalescer.log_event(environment);
+        drop(state);
+
+        if let Some((start, end)) = coalesced_duration {
+            let event = Event::Edit {
+                duration: end.timestamp_millis() - start.timestamp_millis(),
+                environment,
+                milliseconds_since_first_event: self.milliseconds_since_first_event(),
+            };
+
+            self.report_event(event);
+        }
+    }
+
     fn report_event(self: &Arc<Self>, event: Event) {
         let mut state = self.state.lock();
 
@@ -410,7 +436,7 @@ impl Telemetry {
                 let this = self.clone();
                 let executor = self.executor.clone();
                 state.flush_events_task = Some(self.executor.spawn(async move {
-                    executor.timer(DEBOUNCE_INTERVAL).await;
+                    executor.timer(FLUSH_DEBOUNCE_INTERVAL).await;
                     this.flush_events();
                 }));
             }
@@ -435,6 +461,9 @@ impl Telemetry {
         let mut events = mem::take(&mut state.events_queue);
         state.flush_events_task.take();
         drop(state);
+        if events.is_empty() {
+            return;
+        }
 
         let this = self.clone();
         self.executor

crates/client/src/telemetry/event_coalescer.rs

@@ -0,0 +1,228 @@
+use chrono::{DateTime, Duration, Utc};
+use std::time;
+
+const COALESCE_TIMEOUT: time::Duration = time::Duration::from_secs(20);
+const SIMULATED_DURATION_FOR_SINGLE_EVENT: time::Duration = time::Duration::from_millis(1);
+
+pub struct EventCoalescer {
+    environment: Option<&'static str>,
+    period_start: Option<DateTime<Utc>>,
+    period_end: Option<DateTime<Utc>>,
+}
+
+impl EventCoalescer {
+    pub fn new() -> Self {
+        Self {
+            environment: None,
+            period_start: None,
+            period_end: None,
+        }
+    }
+
+    pub fn log_event(
+        &mut self,
+        environment: &'static str,
+    ) -> Option<(DateTime<Utc>, DateTime<Utc>)> {
+        self.log_event_with_time(Utc::now(), environment)
+    }
+
+    // pub fn close_current_period(&mut self) -> Option<(DateTime<Utc>, DateTime<Utc>)> {
+    //     self.environment.map(|env| self.log_event(env)).flatten()
+    // }
+
+    fn log_event_with_time(
+        &mut self,
+        log_time: DateTime<Utc>,
+        environment: &'static str,
+    ) -> Option<(DateTime<Utc>, DateTime<Utc>)> {
+        let coalesce_timeout = Duration::from_std(COALESCE_TIMEOUT).unwrap();
+
+        let Some(period_start) = self.period_start else {
+            self.period_start = Some(log_time);
+            self.environment = Some(environment);
+            return None;
+        };
+
+        let period_end = self
+            .period_end
+            .unwrap_or(period_start + SIMULATED_DURATION_FOR_SINGLE_EVENT);
+        let within_timeout = log_time - period_end < coalesce_timeout;
+        let environment_is_same = self.environment == Some(environment);
+        let should_coaelesce = !within_timeout || !environment_is_same;
+
+        if should_coaelesce {
+            self.period_start = Some(log_time);
+            self.period_end = None;
+            self.environment = Some(environment);
+            return Some((
+                period_start,
+                if within_timeout { log_time } else { period_end },
+            ));
+        }
+
+        self.period_end = Some(log_time);
+
+        None
+    }
+}
+
+#[cfg(test)]
+mod tests {
+    use chrono::TimeZone;
+
+    use super::*;
+
+    #[test]
+    fn test_same_context_exceeding_timeout() {
+        let environment_1 = "environment_1";
+        let mut event_coalescer = EventCoalescer::new();
+
+        assert_eq!(event_coalescer.period_start, None);
+        assert_eq!(event_coalescer.period_end, None);
+        assert_eq!(event_coalescer.environment, None);
+
+        let period_start = Utc.with_ymd_and_hms(1990, 4, 12, 0, 0, 0).unwrap();
+        let coalesced_duration = event_coalescer.log_event_with_time(period_start, environment_1);
+
+        assert_eq!(coalesced_duration, None);
+        assert_eq!(event_coalescer.period_start, Some(period_start));
+        assert_eq!(event_coalescer.period_end, None);
+        assert_eq!(event_coalescer.environment, Some(environment_1));
+
+        let within_timeout_adjustment = Duration::from_std(COALESCE_TIMEOUT / 2).unwrap();
+        let mut period_end = period_start;
+
+        // Ensure that many calls within the timeout don't start a new period
+        for _ in 0..100 {
+            period_end += within_timeout_adjustment;
+            let coalesced_duration = event_coalescer.log_event_with_time(period_end, environment_1);
+
+            assert_eq!(coalesced_duration, None);
+            assert_eq!(event_coalescer.period_start, Some(period_start));
+            assert_eq!(event_coalescer.period_end, Some(period_end));
+            assert_eq!(event_coalescer.environment, Some(environment_1));
+        }
+
+        let exceed_timeout_adjustment = Duration::from_std(COALESCE_TIMEOUT * 2).unwrap();
+        // Logging an event exceeding the timeout should start a new period
+        let new_period_start = period_end + exceed_timeout_adjustment;
+        let coalesced_duration =
+            event_coalescer.log_event_with_time(new_period_start, environment_1);
+
+        assert_eq!(coalesced_duration, Some((period_start, period_end)));
+        assert_eq!(event_coalescer.period_start, Some(new_period_start));
+        assert_eq!(event_coalescer.period_end, None);
+        assert_eq!(event_coalescer.environment, Some(environment_1));
+    }
+
+    #[test]
+    fn test_different_environment_under_timeout() {
+        let environment_1 = "environment_1";
+        let mut event_coalescer = EventCoalescer::new();
+
+        assert_eq!(event_coalescer.period_start, None);
+        assert_eq!(event_coalescer.period_end, None);
+        assert_eq!(event_coalescer.environment, None);
+
+        let period_start = Utc.with_ymd_and_hms(1990, 4, 12, 0, 0, 0).unwrap();
+        let coalesced_duration = event_coalescer.log_event_with_time(period_start, environment_1);
+
+        assert_eq!(coalesced_duration, None);
+        assert_eq!(event_coalescer.period_start, Some(period_start));
+        assert_eq!(event_coalescer.period_end, None);
+        assert_eq!(event_coalescer.environment, Some(environment_1));
+
+        let within_timeout_adjustment = Duration::from_std(COALESCE_TIMEOUT / 2).unwrap();
+        let period_end = period_start + within_timeout_adjustment;
+        let coalesced_duration = event_coalescer.log_event_with_time(period_end, environment_1);
+
+        assert_eq!(coalesced_duration, None);
+        assert_eq!(event_coalescer.period_start, Some(period_start));
+        assert_eq!(event_coalescer.period_end, Some(period_end));
+        assert_eq!(event_coalescer.environment, Some(environment_1));
+
+        // Logging an event within the timeout but with a different environment should start a new period
+        let period_end = period_end + within_timeout_adjustment;
+        let environment_2 = "environment_2";
+        let coalesced_duration = event_coalescer.log_event_with_time(period_end, environment_2);
+
+        assert_eq!(coalesced_duration, Some((period_start, period_end)));
+        assert_eq!(event_coalescer.period_start, Some(period_end));
+        assert_eq!(event_coalescer.period_end, None);
+        assert_eq!(event_coalescer.environment, Some(environment_2));
+    }
+
+    #[test]
+    fn test_switching_environment_while_within_timeout() {
+        let environment_1 = "environment_1";
+        let mut event_coalescer = EventCoalescer::new();
+
+        assert_eq!(event_coalescer.period_start, None);
+        assert_eq!(event_coalescer.period_end, None);
+        assert_eq!(event_coalescer.environment, None);
+
+        let period_start = Utc.with_ymd_and_hms(1990, 4, 12, 0, 0, 0).unwrap();
+        let coalesced_duration = event_coalescer.log_event_with_time(period_start, environment_1);
+
+        assert_eq!(coalesced_duration, None);
+        assert_eq!(event_coalescer.period_start, Some(period_start));
+        assert_eq!(event_coalescer.period_end, None);
+        assert_eq!(event_coalescer.environment, Some(environment_1));
+
+        let within_timeout_adjustment = Duration::from_std(COALESCE_TIMEOUT / 2).unwrap();
+        let period_end = period_start + within_timeout_adjustment;
+        let environment_2 = "environment_2";
+        let coalesced_duration = event_coalescer.log_event_with_time(period_end, environment_2);
+
+        assert_eq!(coalesced_duration, Some((period_start, period_end)));
+        assert_eq!(event_coalescer.period_start, Some(period_end));
+        assert_eq!(event_coalescer.period_end, None);
+        assert_eq!(event_coalescer.environment, Some(environment_2));
+    }
+    // 0                   20                  40                  60
+    // |-------------------|-------------------|-------------------|-------------------
+    // |--------|----------env change
+    //          |-------------------
+    // |period_start       |period_end
+    //                     |new_period_start
+
+    #[test]
+    fn test_switching_environment_while_exceeding_timeout() {
+        let environment_1 = "environment_1";
+        let mut event_coalescer = EventCoalescer::new();
+
+        assert_eq!(event_coalescer.period_start, None);
+        assert_eq!(event_coalescer.period_end, None);
+        assert_eq!(event_coalescer.environment, None);
+
+        let period_start = Utc.with_ymd_and_hms(1990, 4, 12, 0, 0, 0).unwrap();
+        let coalesced_duration = event_coalescer.log_event_with_time(period_start, environment_1);
+
+        assert_eq!(coalesced_duration, None);
+        assert_eq!(event_coalescer.period_start, Some(period_start));
+        assert_eq!(event_coalescer.period_end, None);
+        assert_eq!(event_coalescer.environment, Some(environment_1));
+
+        let exceed_timeout_adjustment = Duration::from_std(COALESCE_TIMEOUT * 2).unwrap();
+        let period_end = period_start + exceed_timeout_adjustment;
+        let environment_2 = "environment_2";
+        let coalesced_duration = event_coalescer.log_event_with_time(period_end, environment_2);
+
+        assert_eq!(
+            coalesced_duration,
+            Some((
+                period_start,
+                period_start + SIMULATED_DURATION_FOR_SINGLE_EVENT
+            ))
+        );
+        assert_eq!(event_coalescer.period_start, Some(period_end));
+        assert_eq!(event_coalescer.period_end, None);
+        assert_eq!(event_coalescer.environment, Some(environment_2));
+    }
+    // 0                   20                  40                  60
+    // |-------------------|-------------------|-------------------|-------------------
+    // |--------|----------------------------------------env change
+    //          |-------------------|
+    // |period_start                |period_end
+    //                                                   |new_period_start
+}

crates/editor/src/editor.rs

@@ -8678,6 +8678,10 @@ impl Editor {
                         }
                     }
                 }
+
+                let Some(project) = &self.project else { return };
+                let telemetry = project.read(cx).client().telemetry().clone();
+                telemetry.log_edit_event("editor");
             }
             multi_buffer::Event::ExcerptsAdded {
                 buffer,

crates/terminal_view/src/terminal_element.rs

@@ -6,7 +6,7 @@ use gpui::{
     InteractiveElementState, Interactivity, IntoElement, LayoutId, Model, ModelContext,
     ModifiersChangedEvent, MouseButton, MouseMoveEvent, Pixels, PlatformInputHandler, Point,
     ShapedLine, StatefulInteractiveElement, Styled, TextRun, TextStyle, TextSystem, UnderlineStyle,
-    WhiteSpace, WindowContext,
+    WeakView, WhiteSpace, WindowContext,
 };
 use itertools::Itertools;
 use language::CursorShape;
@@ -24,6 +24,7 @@ use terminal::{
 };
 use theme::{ActiveTheme, Theme, ThemeSettings};
 use ui::Tooltip;
+use workspace::Workspace;
 
 use std::mem;
 use std::{fmt::Debug, ops::RangeInclusive};
@@ -142,6 +143,7 @@ impl LayoutRect {
 ///We need to keep a reference to the view for mouse events, do we need it for any other terminal stuff, or can we move that to connection?
 pub struct TerminalElement {
     terminal: Model<Terminal>,
+    workspace: WeakView<Workspace>,
     focus: FocusHandle,
     focused: bool,
     cursor_visible: bool,
@@ -160,6 +162,7 @@ impl StatefulInteractiveElement for TerminalElement {}
 impl TerminalElement {
     pub fn new(
         terminal: Model<Terminal>,
+        workspace: WeakView<Workspace>,
         focus: FocusHandle,
         focused: bool,
         cursor_visible: bool,
@@ -167,6 +170,7 @@ impl TerminalElement {
     ) -> TerminalElement {
         TerminalElement {
             terminal,
+            workspace,
             focused,
             focus: focus.clone(),
             cursor_visible,
@@ -762,6 +766,7 @@ impl Element for TerminalElement {
                 .cursor
                 .as_ref()
                 .map(|cursor| cursor.bounding_rect(origin)),
+            workspace: self.workspace.clone(),
         };
 
         self.register_mouse_listeners(origin, layout.mode, bounds, cx);
@@ -831,6 +836,7 @@ impl IntoElement for TerminalElement {
 struct TerminalInputHandler {
     cx: AsyncWindowContext,
     terminal: Model<Terminal>,
+    workspace: WeakView<Workspace>,
     cursor_bounds: Option<Bounds<Pixels>>,
 }
 
@@ -871,7 +877,14 @@ impl PlatformInputHandler for TerminalInputHandler {
             .update(|_, cx| {
                 self.terminal.update(cx, |terminal, _| {
                     terminal.input(text.into());
-                })
+                });
+
+                self.workspace
+                    .update(cx, |this, cx| {
+                        let telemetry = this.project().read(cx).client().telemetry().clone();
+                        telemetry.log_edit_event("terminal");
+                    })
+                    .ok();
             })
             .ok();
     }

crates/terminal_view/src/terminal_view.rs

@@ -73,6 +73,7 @@ pub fn init(cx: &mut AppContext) {
 ///A terminal view, maintains the PTY's file handles and communicates with the terminal
 pub struct TerminalView {
     terminal: Model<Terminal>,
+    workspace: WeakView<Workspace>,
     focus_handle: FocusHandle,
     has_new_content: bool,
     //Currently using iTerm bell, show bell emoji in tab until input is received
@@ -135,6 +136,7 @@ impl TerminalView {
         workspace_id: WorkspaceId,
         cx: &mut ViewContext<Self>,
     ) -> Self {
+        let workspace_handle = workspace.clone();
         cx.observe(&terminal, |_, _, cx| cx.notify()).detach();
         cx.subscribe(&terminal, move |this, _, event, cx| match event {
             Event::Wakeup => {
@@ -279,6 +281,7 @@ impl TerminalView {
 
         Self {
             terminal,
+            workspace: workspace_handle,
             has_new_content: true,
             has_bell: false,
             focus_handle: cx.focus_handle(),
@@ -661,6 +664,7 @@ impl Render for TerminalView {
                 // TODO: Oddly this wrapper div is needed for TerminalElement to not steal events from the context menu
                 div().size_full().child(TerminalElement::new(
                     terminal_handle,
+                    self.workspace.clone(),
                     self.focus_handle.clone(),
                     focused,
                     self.should_show_cursor(focused, cx),