From 560735e5a60ddf3b2e4b5638bb3f887a4bd183a6 Mon Sep 17 00:00:00 2001 From: Sergei Tachenov Date: Wed, 19 Mar 2025 15:54:42 +0200 Subject: [PATCH] [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 --- .../terminal/session/TerminalOutputEvent.kt | 2 + .../backend/TerminalContentChangesTracker.kt | 3 +- .../TerminalCursorPositionTrackerTest.kt | 3 +- .../terminal/frontend/ReworkedTerminalView.kt | 8 + .../frontend/TerminalSessionController.kt | 5 + .../session/FrontendTerminalSession.kt | 2 +- .../fus/ReworkedTerminalUsageCollector.kt | 150 ++++++++++++++++-- 7 files changed, 161 insertions(+), 12 deletions(-) diff --git a/platform/execution-impl/src/com/intellij/terminal/session/TerminalOutputEvent.kt b/platform/execution-impl/src/com/intellij/terminal/session/TerminalOutputEvent.kt index dd7718f0bfcf..7a806f65cf2e 100644 --- a/platform/execution-impl/src/com/intellij/terminal/session/TerminalOutputEvent.kt +++ b/platform/execution-impl/src/com/intellij/terminal/session/TerminalOutputEvent.kt @@ -18,6 +18,8 @@ data class TerminalContentUpdatedEvent( val text: String, val styles: List, val startLineLogicalIndex: Long, + val firstCharIndex: Long, + val lastCharIndex: Long, ) : TerminalOutputEvent @ApiStatus.Internal diff --git a/plugins/terminal/backend/src/com/intellij/terminal/backend/TerminalContentChangesTracker.kt b/plugins/terminal/backend/src/com/intellij/terminal/backend/TerminalContentChangesTracker.kt index 9488a8be2497..6e91c595b724 100644 --- a/plugins/terminal/backend/src/com/intellij/terminal/backend/TerminalContentChangesTracker.kt +++ b/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 } diff --git a/plugins/terminal/backend/testSrc/com/intellij/terminal/backend/TerminalCursorPositionTrackerTest.kt b/plugins/terminal/backend/testSrc/com/intellij/terminal/backend/TerminalCursorPositionTrackerTest.kt index a7b00086eae5..cbbbfad82129 100644 --- a/plugins/terminal/backend/testSrc/com/intellij/terminal/backend/TerminalCursorPositionTrackerTest.kt +++ b/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)) } } \ No newline at end of file diff --git a/plugins/terminal/frontend/src/com/intellij/terminal/frontend/ReworkedTerminalView.kt b/plugins/terminal/frontend/src/com/intellij/terminal/frontend/ReworkedTerminalView.kt index 2c5f659b38fa..9608f21b1256 100644 --- a/plugins/terminal/frontend/src/com/intellij/terminal/frontend/ReworkedTerminalView.kt +++ b/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 -> diff --git a/plugins/terminal/frontend/src/com/intellij/terminal/frontend/TerminalSessionController.kt b/plugins/terminal/frontend/src/com/intellij/terminal/frontend/TerminalSessionController.kt index 1e505d54d8eb..02e902bab09c 100644 --- a/plugins/terminal/frontend/src/com/intellij/terminal/frontend/TerminalSessionController.kt +++ b/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 = 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 -> { diff --git a/plugins/terminal/src/org/jetbrains/plugins/terminal/block/reworked/session/FrontendTerminalSession.kt b/plugins/terminal/src/org/jetbrains/plugins/terminal/block/reworked/session/FrontendTerminalSession.kt index a8d4d8fe3258..07a86021b55d 100644 --- a/plugins/terminal/src/org/jetbrains/plugins/terminal/block/reworked/session/FrontendTerminalSession.kt +++ b/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 diff --git a/plugins/terminal/src/org/jetbrains/plugins/terminal/fus/ReworkedTerminalUsageCollector.kt b/plugins/terminal/src/org/jetbrains/plugins/terminal/fus/ReworkedTerminalUsageCollector.kt index 0d65118fbe9d..3978456edc4a 100644 --- a/plugins/terminal/src/org/jetbrains/plugins/terminal/fus/ReworkedTerminalUsageCollector.kt +++ b/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) { 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, + 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, 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, + private val outputEditor: EditorImpl, + private val alternateBufferEditor: EditorImpl, +) : FrontendOutputActivity { + + private val sessionId = AtomicReference() + private val pendingEvents = ArrayBlockingQueue(100) + private val pendingPaints = ArrayBlockingQueue(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 ArrayBlockingQueue.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()