From 53ff8d82e0a1e63a3e08990fb963e596d6d2a7bd Mon Sep 17 00:00:00 2001 From: Alexey Kryuchkov Date: Fri, 19 Jul 2024 17:03:03 +0300 Subject: [PATCH] WaitForFinishedCodeAnalysis traceId for logging stopping events GitOrigin-RevId: b50c2c39317e0386df5a993c4841d9b0000677c2 --- .../commands/WaitForFinishedCodeAnalysis.kt | 77 +++++++++---------- 1 file changed, 36 insertions(+), 41 deletions(-) diff --git a/plugins/performanceTesting/core/src/com/jetbrains/performancePlugin/commands/WaitForFinishedCodeAnalysis.kt b/plugins/performanceTesting/core/src/com/jetbrains/performancePlugin/commands/WaitForFinishedCodeAnalysis.kt index 054be5769f04..918bc632f6fe 100644 --- a/plugins/performanceTesting/core/src/com/jetbrains/performancePlugin/commands/WaitForFinishedCodeAnalysis.kt +++ b/plugins/performanceTesting/core/src/com/jetbrains/performancePlugin/commands/WaitForFinishedCodeAnalysis.kt @@ -27,9 +27,11 @@ import com.intellij.openapi.vfs.VirtualFile import com.intellij.platform.diagnostic.telemetry.Scope import com.intellij.platform.diagnostic.telemetry.TelemetryManager import com.intellij.platform.ide.diagnostic.startUpPerformanceReporter.FUSProjectHotStartUpMeasurerService +import com.intellij.psi.PsiElement import com.intellij.util.concurrency.annotations.RequiresReadLock import com.intellij.util.ui.UIUtil import kotlinx.coroutines.* +import java.util.UUID import java.util.concurrent.ConcurrentHashMap import java.util.concurrent.Semaphore import java.util.concurrent.TimeUnit @@ -53,9 +55,11 @@ private fun Collection.getWorthy(): List { internal class WaitForFinishedCodeAnalysis(text: String, line: Int) : PerformanceCommandCoroutineAdapter(text, line) { companion object { const val PREFIX = CMD_PREFIX + "waitForFinishedCodeAnalysis" + val LOG = logger() } override suspend fun doExecute(context: PlaybackContext) { + LOG.info("WaitForFinishedCodeAnalysis started its execution") val checkingJob = coroutineScope { launch { while (true) { @@ -114,8 +118,10 @@ class CodeAnalysisStateListener(val project: Project, val cs: CoroutineScope) { @Suppress("UsePropertyAccessSyntax") // inhibit weak warning, for property access is a warning if (sessions.isEmpty()) { - LOG.info("Highlighting done") - LOG.info("Total opening time is : ${(System.nanoTime() - StartUpMeasurer.getStartTime()).nanoseconds.inWholeMilliseconds}") + LOG.info(""" + Highlighting done, + Total opening time is : ${(System.nanoTime() - StartUpMeasurer.getStartTime()).nanoseconds.inWholeMilliseconds} + """) highlightingFinishedEverywhere.release() locked = false } @@ -125,7 +131,6 @@ class CodeAnalysisStateListener(val project: Project, val cs: CoroutineScope) { val editor = it.key.editor printCodeAnalyzerStatistic(editor) printFileStatusMapInfo(editor) - printEditorInfo(editor) } LOG.info("Highlighting still in progress: ${sessions.keys.joinToString(separator = ",\n") { it.description }}") } @@ -145,7 +150,8 @@ class CodeAnalysisStateListener(val project: Project, val cs: CoroutineScope) { if (throws) { LOG.error(errorText) throw TimeoutException(errorText) - } else { + } + else { LOG.error(errorText) } } @@ -177,7 +183,7 @@ class CodeAnalysisStateListener(val project: Project, val cs: CoroutineScope) { val isStartedInDumbMode = runReadAction { DumbService.isDumb(project) } synchronized(stateLock) { for (editor in fileEditors) { - LOG.info("daemon starting for ${editor.description}") + LOG.info("Daemon starting for ${editor.description}") val previousSessionStartTrace = sessions.put(editor, ExceptionWithTime.createForAnalysisStart(editor, isStartedInDumbMode)) ExceptionWithTime.createIntersectionErrorIfNeeded(editor, previousSessionStartTrace)?.let { errors.add(it) } } @@ -216,23 +222,23 @@ class CodeAnalysisStateListener(val project: Project, val cs: CoroutineScope) { @RequiresReadLock fun create(editor: TextEditor, project: Project, isCancelled: Boolean, isFinishedInDumbMode: Boolean): HighlightedEditor { if (!UIUtil.isShowing(editor.getComponent())) { - LOG.info("Invisible editor ${editor.description}") + LOG.info("Creating invisible editor ${editor.description}") return InvisibleEditor(editor) } else if (isFinishedInDumbMode || isCancelled) { - LOG.info("Unfinished editor isFinishedInDumbMode=$isFinishedInDumbMode, isCancelled=$isCancelled ${editor.description}") + LOG.info("Creating unfinished editor isFinishedInDumbMode=$isFinishedInDumbMode, isCancelled=$isCancelled ${editor.description}") return IncompletelyHighlightedEditor(editor) } else { val isHighlighted = DaemonCodeAnalyzerImpl.isHighlightingCompleted(editor, project) - LOG.info("Visible editor ${editor.description}\nisHighlighted $isHighlighted") + LOG.info("Creating visible editor ${editor.description}\nisHighlighted $isHighlighted") return VisibleEditor(editor, isHighlighted) } } } } - internal fun registerAnalysisFinished(highlightedEditors: Map) { + internal fun registerAnalysisFinished(highlightedEditors: Map, status: String, traceId: UUID) { val currentTime = System.currentTimeMillis() synchronized(stateLock) { val iterator = sessions.entries.iterator() @@ -246,15 +252,13 @@ class CodeAnalysisStateListener(val project: Project, val cs: CoroutineScope) { } else { val shouldWait = highlightedEditor.shouldWaitForNextHighlighting || exceptionWithTime.wasStartedInLimitedSetup - LOG.info("daemon stopped for ${highlightedEditor.editor.description}, " + - "shouldWaitForHighlighting=${shouldWait}, " + - "editor.shouldWaitForNextHighlighting=${highlightedEditor.shouldWaitForNextHighlighting}") - LOG.info("""daemon stopped for ${highlightedEditor.editor.description}, - shouldWaitForHighlighting=${shouldWait}, - highlightedEditor.shouldWaitForNextHighlighting=${highlightedEditor.shouldWaitForNextHighlighting} - """ - .trimIndent() - ) + LOG.info(""" + Registering analysis finished for: + daemon $status for ${highlightedEditor.editor.description}, + shouldWaitForHighlighting = ${shouldWait}, + shouldWaitForNextHighlighting = ${highlightedEditor.shouldWaitForNextHighlighting}, + traceId = $traceId + """.trimIndent()) if (shouldWait) { ExceptionWithTime.markAnalysisFinished(exceptionWithTime) } @@ -274,8 +278,8 @@ class CodeAnalysisStateListener(val project: Project, val cs: CoroutineScope) { LOG.info("Analyzer status for ${editor.virtualFile.path}\n ${TrafficLightRenderer(project, editor.document).use { it.daemonCodeAnalyzerStatus }}") } } - catch (_: Throwable) { - LOG.warn("Print Analyzer status failed") + catch (ex: Throwable) { + LOG.warn("Print Analyzer status failed", ex) } } @@ -286,20 +290,8 @@ class CodeAnalysisStateListener(val project: Project, val cs: CoroutineScope) { .toString(editor.document) LOG.info("File status map $fileStatus") } - catch (_: Throwable) { - LOG.warn("Print Analyzer status map failed") - } - } - - internal fun printEditorInfo(editor: Editor) { - try { - LOG.info(""" - Editor document ${editor.virtualFile.path} - document is in bulkUpdate ${editor.document.isInBulkUpdate} - """.trimIndent()); - } - catch (_: Throwable) { - LOG.warn("Print editor info failed") + catch (ex: Throwable) { + LOG.warn("Print Analyzer status map failed", ex) } } @@ -323,23 +315,26 @@ internal class WaitForFinishedCodeAnalysisListener(private val project: Project) } override fun daemonStarting(fileEditors: Collection) { - CodeAnalysisStateListener.LOG.info("daemon starting with ${fileEditors.size} unfiltered editors: " + + CodeAnalysisStateListener.LOG.info("Daemon starting with ${fileEditors.size} unfiltered editors: " + fileEditors.joinToString(separator = "\n") { it.description }) project.service().registerAnalysisStarted(fileEditors.getWorthy()) } override fun daemonCanceled(reason: String, fileEditors: Collection) { - CodeAnalysisStateListener.LOG.info("daemon canceled by the reason of '$reason'") - daemonStopped(fileEditors, true) + val traceId = UUID.randomUUID() + CodeAnalysisStateListener.LOG.info("Daemon canceled by the reason of '$reason', traceId = $traceId") + daemonStopped(fileEditors, true, traceId) } override fun daemonFinished(fileEditors: Collection) { - daemonStopped(fileEditors, false) + val traceId = UUID.randomUUID() + CodeAnalysisStateListener.LOG.info("Daemon finished, traceId = $traceId") + daemonStopped(fileEditors, false, traceId) } - private fun daemonStopped(fileEditors: Collection, isCancelled: Boolean) { + private fun daemonStopped(fileEditors: Collection, isCancelled: Boolean, traceId: UUID) { val status = if (isCancelled) "cancelled" else "stopped" - CodeAnalysisStateListener.LOG.info("daemon $status with ${fileEditors.size} unfiltered editors") + CodeAnalysisStateListener.LOG.info("Daemon $status with ${fileEditors.size} unfiltered editors, traceId = $traceId") val worthy = fileEditors.getWorthy() if (worthy.isEmpty()) return @@ -348,7 +343,7 @@ internal class WaitForFinishedCodeAnalysisListener(private val project: Project) worthy.associateWith { CodeAnalysisStateListener.HighlightedEditor.create(it, project, isCancelled = isCancelled, isFinishedInDumbMode = isFinishedInDumbMode) } } - project.service().registerAnalysisFinished(highlightedEditors) + project.service().registerAnalysisFinished(highlightedEditors, status, traceId) } }