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()