[terminal] IJPL-182482 Implement terminal frontend output latency FUS

The hardest part here is to understand when the received data
is actually displayed. The problem is that it may not be displayed
at all, for example, if the editor is hidden or scrolled away.

Using the hooks added to the editor, we can make an assumption:
if the editor is showing, and there was a repaint request,
then it's very likely to be repainted soon. In that case we wait
for the repaint before reporting the latency.

If there's no repaint request, then we report the latency immediately,
adding a boolean flag to the event to distinguish between the cases.

Because events are received and applied as whole,
there are no separate events for the first and last characters.
Instead, we report both character indices in one event.
So for two backend events we have one frontend event.

GitOrigin-RevId: df72687dc3ef31bece6eeaf7cd624dc18c462d6e

platform/execution-impl/src/com/intellij/terminal/session/TerminalOutputEvent.kt

@@ -18,6 +18,8 @@ data class TerminalContentUpdatedEvent(
   val text: String,
   val styles: List<StyleRangeDto>,
   val startLineLogicalIndex: Long,
+  val firstCharIndex: Long,
+  val lastCharIndex: Long,
 ) : TerminalOutputEvent
 
 @ApiStatus.Internal

plugins/terminal/backend/src/com/intellij/terminal/backend/TerminalContentChangesTracker.kt

@@ -102,7 +102,8 @@ internal class TerminalContentChangesTracker(
     anyLineChanged = false
 
     val styles = output.styleRanges.map { it.toDto() }
-    val contentUpdatedEvent = TerminalContentUpdatedEvent(output.text, styles, logicalLineIndex)
+    val charRange = fusActivity.textBufferCharacterIndices()
+    val contentUpdatedEvent = TerminalContentUpdatedEvent(output.text, styles, logicalLineIndex, charRange.first, charRange.last)
     fusActivity.textBufferCollected(contentUpdatedEvent)
     return contentUpdatedEvent
   }

plugins/terminal/backend/testSrc/com/intellij/terminal/backend/TerminalCursorPositionTrackerTest.kt

@@ -35,7 +35,8 @@ internal class TerminalCursorPositionTrackerTest {
 
     // We expect that moving cursor position to the next line creates this line in the TextBuffer,
     // and it is being caught by the TerminalContentChangesTracker.
-    assertThat(contentUpdate).isEqualTo(TerminalContentUpdatedEvent("", emptyList(), 1))
+    // The strange 6/5 combination of character indices corresponds to the cursor position change without any characters read.
+    assertThat(contentUpdate).isEqualTo(TerminalContentUpdatedEvent("", emptyList(), 1, 6L, 5L))
     assertThat(cursorUpdate).isEqualTo(TerminalCursorPositionChangedEvent(1, 0))
   }
 }

plugins/terminal/frontend/src/com/intellij/terminal/frontend/ReworkedTerminalView.kt

@@ -43,6 +43,7 @@ import org.jetbrains.plugins.terminal.block.reworked.hyperlinks.TerminalHyperlin
 import org.jetbrains.plugins.terminal.block.ui.*
 import org.jetbrains.plugins.terminal.block.ui.TerminalUi.useTerminalDefaultBackground
 import org.jetbrains.plugins.terminal.block.util.TerminalDataContextUtils
+import org.jetbrains.plugins.terminal.fus.ReworkedTerminalUsageCollector
 import org.jetbrains.plugins.terminal.util.terminalProjectScope
 import java.awt.Component
 import java.awt.Dimension
@@ -131,6 +132,12 @@ internal class ReworkedTerminalView(
     TerminalBlocksDecorator(outputEditor, blocksModel, scrollingModel, coroutineScope.childScope("TerminalBlocksDecorator"))
     outputEditor.putUserData(TerminalBlocksModel.KEY, blocksModel)
 
+    val fusActivity = ReworkedTerminalUsageCollector.startFrontendOutputActivity(
+      sessionFuture,
+      outputEditor = outputEditor as EditorImpl,
+      alternateBufferEditor = alternateBufferEditor as EditorImpl,
+    )
+
     controller = TerminalSessionController(
       sessionModel,
       outputModel,
@@ -138,6 +145,7 @@ internal class ReworkedTerminalView(
       blocksModel,
       settings,
       coroutineScope.childScope("TerminalSessionController"),
+      fusActivity,
     )
 
     sessionFuture.thenAccept { session ->

plugins/terminal/frontend/src/com/intellij/terminal/frontend/TerminalSessionController.kt

@@ -18,6 +18,7 @@ import org.jetbrains.plugins.terminal.block.reworked.TerminalBlocksModel
 import org.jetbrains.plugins.terminal.block.reworked.TerminalOutputModel
 import org.jetbrains.plugins.terminal.block.reworked.TerminalSessionModel
 import org.jetbrains.plugins.terminal.block.reworked.TerminalShellIntegrationEventsListener
+import org.jetbrains.plugins.terminal.fus.FrontendOutputActivity
 import java.awt.Toolkit
 import kotlin.coroutines.cancellation.CancellationException
 
@@ -28,6 +29,7 @@ internal class TerminalSessionController(
   private val blocksModel: TerminalBlocksModel,
   private val settings: JBTerminalSystemSettingsProviderBase,
   private val coroutineScope: CoroutineScope,
+  private val fusActivity: FrontendOutputActivity,
 ) {
 
   private val terminationListeners: DisposableWrapperList<Runnable> = DisposableWrapperList()
@@ -70,9 +72,12 @@ internal class TerminalSessionController(
         }
       }
       is TerminalContentUpdatedEvent -> {
+        fusActivity.eventReceived(event)
         updateOutputModel { model ->
+          fusActivity.beforeModelUpdate()
           val styles = event.styles.map { it.toStyleRange() }
           model.updateContent(event.startLineLogicalIndex, event.text, styles)
+          fusActivity.afterModelUpdate()
         }
       }
       is TerminalCursorPositionChangedEvent -> {

plugins/terminal/src/org/jetbrains/plugins/terminal/block/reworked/session/FrontendTerminalSession.kt

@@ -19,7 +19,7 @@ import org.jetbrains.plugins.terminal.block.reworked.session.rpc.TerminalSession
  * Normally, it should be located in the frontend module, but it can't be moved there
  * because it should be accessible from the shared terminal widget creating API with a lot of external usages.
  */
-internal class FrontendTerminalSession(private val id: TerminalSessionId) : TerminalSession {
+internal class FrontendTerminalSession(internal val id: TerminalSessionId) : TerminalSession {
   @Volatile
   override var isClosed: Boolean = false
     private set

plugins/terminal/src/org/jetbrains/plugins/terminal/fus/ReworkedTerminalUsageCollector.kt

@@ -5,21 +5,24 @@ import com.intellij.internal.statistic.eventLog.EventLogGroup
 import com.intellij.internal.statistic.eventLog.events.EventFields
 import com.intellij.internal.statistic.service.fus.collectors.CounterUsagesCollector
 import com.intellij.openapi.diagnostic.logger
+import com.intellij.openapi.editor.impl.EditorImpl
 import com.intellij.openapi.project.Project
 import com.intellij.openapi.util.Version
 import com.intellij.platform.rpc.UID
 import com.intellij.terminal.session.TerminalContentUpdatedEvent
 import com.intellij.terminal.session.TerminalInputEvent
+import com.intellij.terminal.session.TerminalSession
 import com.intellij.terminal.session.TerminalWriteBytesEvent
 import com.intellij.util.concurrency.ThreadingAssertions
 import com.intellij.util.system.OS
-import com.jetbrains.rhizomedb.EID
 import fleet.multiplatform.shims.ConcurrentHashMap
 import org.jetbrains.annotations.ApiStatus
 import org.jetbrains.plugins.terminal.block.reworked.session.FrontendTerminalSession
 import org.jetbrains.plugins.terminal.fus.TerminalShellInfoStatistics.KNOWN_SHELLS
 import org.jetbrains.plugins.terminal.fus.TerminalShellInfoStatistics.getShellNameForStat
 import java.awt.event.KeyEvent
+import java.util.concurrent.ArrayBlockingQueue
+import java.util.concurrent.CompletableFuture
 import java.util.concurrent.LinkedBlockingQueue
 import java.util.concurrent.atomic.AtomicInteger
 import java.util.concurrent.atomic.AtomicReference
@@ -43,7 +46,10 @@ object ReworkedTerminalUsageCollector : CounterUsagesCollector() {
   private val INPUT_EVENT_ID_FIELD = EventFields.Int("input_event_id")
   private val SESSION_ID = EventFields.Int("session_id")
   private val CHAR_INDEX = EventFields.Long("char_index")
+  private val FIRST_CHAR_INDEX = EventFields.Long("first_char_index")
+  private val LAST_CHAR_INDEX = EventFields.Long("last_char_index")
   private val DURATION_FIELD = EventFields.createDurationField(DurationUnit.MICROSECONDS, "duration_micros")
+  private val REPAINTED_FIELD = EventFields.Boolean("editor_repainted")
 
   private val localShellStartedEvent = GROUP.registerEvent("local.exec",
                                                            OS_VERSION_FIELD,
@@ -87,6 +93,15 @@ object ReworkedTerminalUsageCollector : CounterUsagesCollector() {
     DURATION_FIELD,
   )
 
+  private val frontendOutputLatencyEvent = GROUP.registerVarargEvent(
+    "terminal.frontend.output.latency",
+    SESSION_ID,
+    FIRST_CHAR_INDEX,
+    LAST_CHAR_INDEX,
+    DURATION_FIELD,
+    REPAINTED_FIELD,
+  )
+
   @JvmStatic
   fun logLocalShellStarted(project: Project, shellCommand: Array<String>) {
     localShellStartedEvent.log(project,
@@ -139,6 +154,16 @@ object ReworkedTerminalUsageCollector : CounterUsagesCollector() {
     )
   }
 
+  internal fun logFrontendOutputLatency(sessionId: UID, firstCharIndex: Long, lastCharIndex: Long, duration: Duration, repainted: Boolean) {
+    frontendOutputLatencyEvent.log(
+      SESSION_ID with sessionId,
+      FIRST_CHAR_INDEX with firstCharIndex,
+      LAST_CHAR_INDEX with lastCharIndex,
+      DURATION_FIELD with duration,
+      REPAINTED_FIELD with repainted,
+    )
+  }
+
   fun startFrontendTypingActivity(e: KeyEvent): FrontendTypingActivity? {
     ThreadingAssertions.softAssertEventDispatchThread()
     if (e.id != KeyEvent.KEY_TYPED) return null
@@ -172,6 +197,15 @@ object ReworkedTerminalUsageCollector : CounterUsagesCollector() {
   fun startBackendOutputActivity(): BackendOutputActivity {
     return BackendOutputActivityImpl()
   }
+
+  @JvmStatic
+  fun startFrontendOutputActivity(
+    sessionFuture: CompletableFuture<TerminalSession>,
+    outputEditor: EditorImpl,
+    alternateBufferEditor: EditorImpl,
+  ): FrontendOutputActivity {
+    return FrontendOutputActivityImpl(sessionFuture, outputEditor, alternateBufferEditor)
+  }
 }
 
 @ApiStatus.Internal
@@ -198,10 +232,18 @@ interface BackendOutputActivity {
   fun charsProcessed(count: Int)
   fun processedCharsReachedTextBuffer()
   fun charProcessingFinished()
+  fun textBufferCharacterIndices(): LongRange
   fun textBufferCollected(event: TerminalContentUpdatedEvent)
   fun eventCollected(event: TerminalContentUpdatedEvent)
 }
 
+@ApiStatus.Internal
+interface FrontendOutputActivity {
+  fun eventReceived(event: TerminalContentUpdatedEvent)
+  fun beforeModelUpdate()
+  fun afterModelUpdate()
+}
+
 private val frontendTypingActivityId = AtomicInteger()
 private var currentKeyEventTypingActivity: FrontendTypingActivityImpl? = null
 private val frontendTypingActivityByInputEvent = ConcurrentHashMap<IdentityWrapper<TerminalInputEvent>, FrontendTypingActivityImpl>()
@@ -411,8 +453,8 @@ private class BackendOutputActivityImpl : BackendOutputActivity {
     /**
      * Invoked every time the text buffer is collected ("scrapped").
      */
-    fun textBufferCollected(event: TerminalContentUpdatedEvent, collectedRange: LongRange) {
-      collectedRanges[event.toIdentity()] = collectedRange
+    fun textBufferCollected(event: TerminalContentUpdatedEvent) {
+      collectedRanges[event.toIdentity()] = event.firstCharIndex..event.lastCharIndex
     }
 
     /**
@@ -478,13 +520,14 @@ private class BackendOutputActivityImpl : BackendOutputActivity {
 
   override fun charProcessingFinished() = processingState.charProcessingFinished()
 
+  // cross-state safe interaction: these two functions are called under the same text buffer lock textBufferState is updated under
+
+  override fun textBufferCharacterIndices(): LongRange {
+    return textBufferState.textBufferCollected() ?: LongRange.EMPTY
+  }
+
   override fun textBufferCollected(event: TerminalContentUpdatedEvent) {
-    // cross-state safe interaction: this function is called under the same text buffer lock textBufferState is updated under...
-    val collectedRange = textBufferState.textBufferCollected()
-    if (collectedRange != null) {
-      // ...and this thing is backed by a concurrent map, so it's thread-safe
-      eventFlowState.textBufferCollected(event, collectedRange)
-    }
+    eventFlowState.textBufferCollected(event)
   }
 
   override fun eventCollected(event: TerminalContentUpdatedEvent) {
@@ -502,4 +545,93 @@ private class BackendOutputActivityImpl : BackendOutputActivity {
   }
 }
 
+private class FrontendOutputActivityImpl(
+  sessionFuture: CompletableFuture<TerminalSession>,
+  private val outputEditor: EditorImpl,
+  private val alternateBufferEditor: EditorImpl,
+) : FrontendOutputActivity {
+
+  private val sessionId = AtomicReference<UID?>()
+  private val pendingEvents = ArrayBlockingQueue<ReceivedEvent>(100)
+  private val pendingPaints = ArrayBlockingQueue<ReceivedEvent>(100)
+  private var editorRepaintRequests = 0L
+  private var editorRepaintRequestsBeforeModelUpdate = 0L
+
+  init {
+    sessionFuture.whenComplete { session, _ ->
+      sessionId.set((session as? FrontendTerminalSession?)?.id?.uid)
+    }
+    outputEditor.setRepaintCallback { editorRepaintRequested() }
+    alternateBufferEditor.setRepaintCallback { editorRepaintRequested() }
+    outputEditor.setPaintCallback { editorPainted() }
+    alternateBufferEditor.setPaintCallback { editorPainted() }
+  }
+
+  override fun eventReceived(event: TerminalContentUpdatedEvent) {
+    pendingEvents.addDroppingOldest(ReceivedEvent(TimeSource.Monotonic.markNow(), event))
+  }
+
+  override fun beforeModelUpdate() {
+    editorRepaintRequestsBeforeModelUpdate = editorRepaintRequests
+  }
+
+  private fun editorRepaintRequested() {
+    ++editorRepaintRequests
+  }
+
+  override fun afterModelUpdate() {
+    val repaintRequested = editorRepaintRequests > editorRepaintRequestsBeforeModelUpdate
+    val editorShowing = outputEditor.component.isShowing || alternateBufferEditor.component.isShowing
+    if (!editorShowing) {
+      pendingPaints.clear() // editor no longer showing, so if there were unprocessed requests, they won't complete
+    }
+    val repaintExpected = repaintRequested && editorShowing
+    while (true) {
+      val pendingEvent = pendingEvents.poll() ?: break
+      if (repaintExpected) {
+        pendingPaints.addDroppingOldest(pendingEvent)
+      }
+      else {
+        reportLatency(pendingEvent, false)
+      }
+    }
+  }
+
+  private fun editorPainted() {
+    while (true) {
+      val pendingPaint = pendingPaints.poll() ?: break
+      reportLatency(pendingPaint, true)
+    }
+  }
+
+  private fun reportLatency(receivedEvent: ReceivedEvent, painted: Boolean) {
+    val latency = receivedEvent.time.elapsedNow()
+    val sessionId = this.sessionId.get()
+    if (sessionId == null) {
+      LOG.error("For some reason sessionId was not initialized, likely a bug")
+      return
+    }
+    ReworkedTerminalUsageCollector.logFrontendOutputLatency(
+      sessionId = sessionId,
+      firstCharIndex = receivedEvent.event.firstCharIndex,
+      lastCharIndex = receivedEvent.event.lastCharIndex,
+      duration = latency,
+      repainted = painted,
+    )
+  }
+
+  private data class ReceivedEvent(val time: TimeMark, val event: TerminalContentUpdatedEvent)
+}
+
+private fun <T> ArrayBlockingQueue<T>.addDroppingOldest(element: T) {
+  var overflow = false
+  while (!offer(element)) {
+    overflow = true
+    poll()
+  }
+  if (overflow) {
+    LOG.warn("Overflow in the frontend output activity queue, too many requests, maybe the queue is too small?")
+  }
+}
+
 private val LOG = logger<FrontendTerminalSession>()