[warmup] Use more verbose logging for transparency

GitOrigin-RevId: 751e472b18fa251881dd2f733b236a5199bccadf

platform/warmup/src/com/intellij/warmup/util/logging.kt

@@ -1,40 +1,41 @@
 // Copyright 2000-2023 JetBrains s.r.o. and contributors. Use of this source code is governed by the Apache 2.0 license.
 package com.intellij.warmup.util
 
-import com.intellij.application.subscribe
 import com.intellij.ide.warmup.WarmupStatus
 import com.intellij.idea.logEssentialInfoAboutIde
 import com.intellij.openapi.application.ApplicationInfo
+import com.intellij.openapi.application.ApplicationManager
 import com.intellij.openapi.application.ApplicationNamesInfo
 import com.intellij.openapi.application.PathManager
+import com.intellij.openapi.components.Service
+import com.intellij.openapi.components.service
 import com.intellij.openapi.diagnostic.JulLogger
 import com.intellij.openapi.diagnostic.Logger
 import com.intellij.openapi.diagnostic.RollingFileHandler
 import com.intellij.openapi.progress.ProgressIndicator
+import com.intellij.openapi.progress.ProgressManagerListener
+import com.intellij.openapi.progress.Task
 import com.intellij.openapi.progress.asContextElement
 import com.intellij.openapi.progress.impl.ProgressState
 import com.intellij.openapi.progress.impl.TextDetailsProgressReporter
 import com.intellij.openapi.progress.util.ProgressIndicatorBase
-import com.intellij.openapi.progress.util.ProgressWindow
-import com.intellij.openapi.util.Disposer
 import com.intellij.openapi.util.io.findOrCreateFile
+import com.intellij.openapi.util.text.Formats
+import com.intellij.openapi.wm.ex.ProgressIndicatorEx
 import com.intellij.util.application
 import com.intellij.util.lazyPub
 import kotlinx.coroutines.*
-import kotlinx.coroutines.channels.Channel
-import kotlinx.coroutines.channels.SendChannel
-import kotlinx.coroutines.channels.onClosed
-import kotlinx.coroutines.flow.Flow
-import kotlinx.coroutines.flow.consumeAsFlow
+import kotlinx.coroutines.channels.BufferOverflow
+import kotlinx.coroutines.flow.MutableSharedFlow
 import kotlinx.coroutines.flow.distinctUntilChanged
 import kotlinx.coroutines.flow.sample
 import java.io.IOException
 import java.nio.file.Path
 import java.text.SimpleDateFormat
 import java.util.*
+import java.util.concurrent.ConcurrentHashMap
 import java.util.logging.Level
 import java.util.logging.LogRecord
-import java.util.logging.SimpleFormatter
 import kotlin.io.path.div
 import kotlin.time.Duration.Companion.milliseconds
 
@@ -44,10 +45,15 @@ object WarmupLogger {
     warmupLogger?.info(message)
   }
 
-  fun logError(message: String, t : Throwable? = null) {
+  fun logError(message: String, t: Throwable? = null) {
     ConsoleLog.error(message, t)
     warmupLogger?.error(message, t)
   }
+
+  internal fun logStructured(message: StructuredMessage) {
+    ConsoleLog.info(message.fullMessage)
+    warmupLogger?.info(message.contractedMessage)
+  }
 }
 
 internal fun initLogger(args: List<String>) {
@@ -55,63 +61,45 @@ internal fun initLogger(args: List<String>) {
   val info = ApplicationInfo.getInstance()
   val buildDate = SimpleDateFormat("dd MMM yyyy HH:mm", Locale.US).format(info.buildDate.time)
   logEssentialInfoAboutIde(logger, info, args)
+  val connection = ApplicationManager.getApplication().messageBus.connect()
+  connection.subscribe(ProgressManagerListener.TOPIC, WarmupProgressListener())
   logger.info("IDE: ${ApplicationNamesInfo.getInstance().fullProductName} (build #${info.build.asString()}, ${buildDate})")
 }
 
-@OptIn(FlowPreview::class)
+
 suspend fun <Y> withLoggingProgresses(action: suspend CoroutineScope.(ProgressIndicator) -> Y): Y {
-  val messages = Channel<String>(128)
-  val indicator = ChannelingProgressIndicator(messages)
+  val indicator = ChannelingProgressIndicator("")
 
   return coroutineScope {
-    val disposable = Disposer.newDisposable()
-
-    ProgressWindow.TOPIC.subscribe(disposable, ProgressWindow.Listener { pw ->
-      pw.addStateDelegate(ChannelingProgressIndicator(messages))
-    })
-
-    @Suppress("EXPERIMENTAL_API_USAGE")
-    val job = launch(Dispatchers.IO) {
-      messages.consumeAsFlow()
-        .sample(300)
-        .distinctUntilChanged()
-        .collect {
-          ConsoleLog.info(it)
-        }
-    }
-    job.invokeOnCompletion { Disposer.dispose(disposable) }
-
-    try {
-      action(indicator)
-    }
-    finally {
-      job.cancelAndJoin()
-    }
+    action(indicator)
   }
 }
 
 private fun trimProgressTextAndNullize(s: String?) = s?.trim()?.trimEnd('.', '\u2026', ' ')?.takeIf { it.isNotBlank() }
 
-internal fun progressStateText(state: ProgressState): String? {
+internal fun progressStateText(state: ProgressState): StructuredMessage? {
   val text = trimProgressTextAndNullize(state.text)
   val text2 = trimProgressTextAndNullize(state.details)
   if (text.isNullOrBlank() && text2.isNullOrBlank()) {
     return null
   }
 
-  val message = (text ?: "") + (text2?.let { " ($it)" } ?: "")
-  if (message.isBlank() || state.fraction < 0.0) {
-    return message.takeIf { it.isNotBlank() }
+  val shortText = text ?: ""
+  val verboseText = shortText + (text2?.let { " ($it)"} ?: "")
+  if (shortText.isBlank() || state.fraction < 0.0) {
+    return StructuredMessage(shortText, verboseText)
   }
 
   val v = (100.0 * state.fraction).toInt()
   val total = 18
   val completed = (total * state.fraction).toInt().coerceAtLeast(0)
   val d = ".".repeat(completed).padEnd(total, ' ')
-  return message.take(75).padEnd(79) + "$d $v%"
+  val verboseReport = verboseText.take(100).padEnd(105) + "$d $v%"
+  val shortReport = shortText.take(100).padEnd(105) + "$d $v%"
+  return StructuredMessage(verboseReport, shortReport)
 }
 
-private class ChannelingProgressIndicator(private val messages: SendChannel<String>) : ProgressIndicatorBase() {
+private class ChannelingProgressIndicator(private val prefix: String) : ProgressIndicatorBase() {
   override fun setIndeterminate(indeterminate: Boolean) {
     super.setIndeterminate(indeterminate)
     offerState()
@@ -134,13 +122,14 @@ private class ChannelingProgressIndicator(private val messages: SendChannel<Stri
   }
 
   private fun offerState() {
-    messages.trySend(progressStateText(dumpProgressState()) ?: return).onClosed {
-      throw IllegalStateException(it)
-    }
+    val messages = ApplicationManager.getApplication().service<WarmupLoggingService>().messages
+    val progressState = progressStateText(dumpProgressState()) ?: return
+    val actualPrefix = if (prefix.isEmpty()) "" else "[$prefix]: "
+    messages.tryEmit(progressState.copy(contractedMessage = actualPrefix + progressState.contractedMessage, fullMessage = actualPrefix + progressState.fullMessage))
   }
 }
 
-private fun ProgressIndicator.dumpProgressState() : ProgressState =
+private fun ProgressIndicator.dumpProgressState(): ProgressState =
   ProgressState(text = text, details = text2, fraction = if (isIndeterminate) -1.0 else fraction)
 
 /**
@@ -148,36 +137,27 @@ private fun ProgressIndicator.dumpProgressState() : ProgressState =
  */
 suspend fun <T> withLoggingProgressReporter(action: suspend CoroutineScope.() -> T): T = coroutineScope {
   TextDetailsProgressReporter(this).use { reporter ->
-    val reportToCommandLineJob = reportLogsJob(reporter.progressState)
+    val messageFlow = ApplicationManager.getApplication().service<WarmupLoggingService>().messages
+    val job = launch {
+      reporter.progressState.collect { progressState ->
+        progressStateText(progressState)?.let { messageFlow.emit(it) }
+      }
+    }
     try {
       withContext(reporter.asContextElement(), action)
-    }
-    finally {
-      reportToCommandLineJob.cancel()
+    } finally {
+      job.cancel()
     }
   }
 }
 
-@OptIn(FlowPreview::class)
-private fun CoroutineScope.reportLogsJob(
-  stateFlow: Flow<ProgressState>
-): Job {
-  return launch(Dispatchers.IO) {
-    stateFlow.sample(300.milliseconds).distinctUntilChanged().collect { state ->
-      val text = progressStateText(state)
-      text?.let {
-        ConsoleLog.info(it)
-        warmupLogger?.info(it)
-      }
-    }
-  }
-}
 
 private class WarmupLoggerFactory : Logger.Factory {
 
   companion object {
     val basePath: Path = Path.of(PathManager.getLogPath()) / "warmup" / "warmup.log"
   }
+
   private val appender: RollingFileHandler = RollingFileHandler(basePath, 20_000_000, 50, false)
 
   override fun getLoggerInstance(category: String): Logger {
@@ -195,10 +175,11 @@ private class WarmupLoggerFactory : Logger.Factory {
   }
 }
 
-private val loggerFactory : WarmupLoggerFactory? by lazyPub {
+private val loggerFactory: WarmupLoggerFactory? by lazyPub {
   try {
     WarmupLoggerFactory.basePath.findOrCreateFile()
-  } catch (e : IOException) {
+  }
+  catch (e: IOException) {
     return@lazyPub null
   }
   val instance = WarmupLoggerFactory()
@@ -209,8 +190,54 @@ private val loggerFactory : WarmupLoggerFactory? by lazyPub {
 private val warmupLogger: Logger? by lazyPub {
   if (WarmupStatus.currentStatus(application) != WarmupStatus.InProgress) {
     null
-  } else {
+  }
+  else {
     val instance = loggerFactory?.getLoggerInstance("Warmup") ?: return@lazyPub null
     instance
   }
 }
+
+internal data class StructuredMessage(
+  // a complete message as it is shown in the UI ide
+  val fullMessage: String,
+  // a short message, suitable for logging as it does not contain sensitive information
+  val contractedMessage: String,
+  )
+
+@OptIn(FlowPreview::class)
+@Service(Service.Level.APP)
+private class WarmupLoggingService(scope: CoroutineScope) {
+  val messages = MutableSharedFlow<StructuredMessage>(replay = 0, extraBufferCapacity = 128, onBufferOverflow = BufferOverflow.DROP_OLDEST)
+
+
+  init {
+    scope.launch(Dispatchers.IO) {
+      messages.sample(300.milliseconds).distinctUntilChanged().collect {
+        WarmupLogger.logStructured(it)
+      }
+    }
+  }
+}
+
+class WarmupProgressListener : ProgressManagerListener {
+
+  private val taskDurationMap = ConcurrentHashMap<Int, Long>()
+
+
+  override fun beforeTaskStart(task: Task, indicator: ProgressIndicator) {
+    if (indicator !is ProgressIndicatorEx) {
+      return
+    }
+    WarmupLogger.logInfo("[IDE]: Task '${task.title}' started")
+    taskDurationMap[System.identityHashCode(task)] = System.currentTimeMillis()
+    indicator.addStateDelegate(ChannelingProgressIndicator("IDE"))
+    super.beforeTaskStart(task, indicator)
+  }
+
+  override fun afterTaskFinished(task: Task) {
+    val currentTime = System.currentTimeMillis()
+    val startTime = taskDurationMap.remove(System.identityHashCode(task))
+    val elapsedTimeSuffix = if (startTime == null) "" else " in ${Formats.formatDuration(currentTime - startTime)}"
+    WarmupLogger.logInfo("[IDE]: Task '${task.title}' ended" + elapsedTimeSuffix)
+  }
+}

platform/warmup/src/com/intellij/warmup/util/utils-time-logger.kt

@@ -52,7 +52,7 @@ suspend fun <Y> runTaskAndLogTime(
   action: suspend CoroutineScope.(TimeCookie) -> Y
 ): Y = coroutineScope {
   val cookie = TimeCookie()
-  WarmupLogger.logInfo("Waiting for '$progressName'...")
+  WarmupLogger.logInfo("Started waiting for '$progressName'...")
 
   val stackElement = coroutineContext[TaskAndLogTimeKey] ?: TaskAndLogTimeElement()
   stackElement.push(progressName)