Adding logs for phases start and finish (#1460)

Author: EgorkaKulikov

utbot-framework/src/main/kotlin/org/utbot/framework/codegen/CodeGenerator.kt

@@ -1,5 +1,6 @@
 package org.utbot.framework.codegen
 
+import mu.KotlinLogging
 import org.utbot.framework.codegen.domain.ForceStaticMocking
 import org.utbot.framework.codegen.domain.HangingTestsTimeout
 import org.utbot.framework.codegen.domain.ParametrizedTestSource
@@ -19,6 +20,8 @@ import org.utbot.framework.plugin.api.CodegenLanguage
 import org.utbot.framework.plugin.api.ExecutableId
 import org.utbot.framework.plugin.api.MockFramework
 import org.utbot.framework.plugin.api.UtMethodTestSet
+import java.time.LocalDateTime
+import java.time.format.DateTimeFormatter
 
 open class CodeGenerator(
     val classUnderTest: ClassId,
@@ -37,6 +40,8 @@ open class CodeGenerator(
     testClassPackageName: String = classUnderTest.packageName,
 ) {
 
+    private val logger = KotlinLogging.logger {}
+
     open var context: CgContext = CgContext(
         classUnderTest = classUnderTest,
         generateUtilClassFile = generateUtilClassFile,
@@ -71,8 +76,15 @@ open class CodeGenerator(
                 val renderer = CgAbstractRenderer.makeRenderer(context)
                 val testClassModel = TestClassModel.fromTestSets(classUnderTest, cgTestSets)
 
+                fun now() = LocalDateTime.now().format(DateTimeFormatter.ofPattern("HH:mm:ss.SSS"))
+
+                logger.info { "Code generation phase started at ${now()}" }
                 val testClassFile = astConstructor.construct(testClassModel)
+                logger.info { "Code generation phase finished at ${now()}" }
+
+                logger.info { "Rendering phase started at ${now()}" }
                 testClassFile.accept(renderer)
+                logger.info { "Rendering phase finished at ${now()}" }
 
                 CodeGeneratorResult(
                     generatedCode = renderer.toString(),

utbot-intellij/src/main/kotlin/org/utbot/intellij/plugin/generator/UtTestsDialogProcessor.kt

@@ -22,8 +22,6 @@ import com.intellij.task.ProjectTaskManager
 import com.intellij.util.concurrency.AppExecutorUtil
 import com.intellij.util.containers.nullize
 import com.intellij.util.io.exists
-import com.jetbrains.rd.util.lifetime.LifetimeDefinition
-import kotlinx.coroutines.runBlocking
 import mu.KotlinLogging
 import org.jetbrains.kotlin.idea.util.module
 import org.utbot.framework.UtSettings
@@ -50,6 +48,8 @@ import kotlin.io.path.pathString
 import org.utbot.framework.plugin.api.util.LockFile
 import org.utbot.intellij.plugin.ui.utils.isBuildWithGradle
 import org.utbot.rd.terminateOnException
+import java.time.LocalDateTime
+import java.time.format.DateTimeFormatter
 
 object UtTestsDialogProcessor {
     private val logger = KotlinLogging.logger {}
@@ -134,7 +134,15 @@ object UtTestsDialogProcessor {
                     if (!LockFile.lock()) {
                         return
                     }
+
+                    UtSettings.concreteExecutionTimeoutInInstrumentedProcess = model.hangingTestsTimeout.timeoutMs
+                    UtSettings.useCustomJavaDocTags = model.commentStyle == JavaDocCommentStyle.CUSTOM_JAVADOC_TAGS
+                    UtSettings.enableSummariesGeneration = model.enableSummariesGeneration
+
+                    fun now() = LocalDateTime.now().format(DateTimeFormatter.ofPattern("HH:mm:ss.SSS"))
+
                     try {
+                        logger.info { "Collecting information phase started at ${now()}" }
                         val secondsTimeout = TimeUnit.MILLISECONDS.toSeconds(model.timeout)
 
                         indicator.isIndeterminate = false
@@ -166,6 +174,7 @@ object UtTestsDialogProcessor {
                                 })
                             }
 
+
                             for (srcClass in model.srcClasses) {
                                 val (methods, className) = DumbService.getInstance(project)
                                     .runReadActionInSmartMode(Computable {
@@ -191,22 +200,15 @@ object UtTestsDialogProcessor {
                                     continue
                                 }
 
+                                logger.info { "Collecting information phase finished at ${now()}" }
+
                                 updateIndicator(
                                     indicator,
                                     ProgressRange.SOLVING,
                                     "Generate test cases for class $className",
                                     processedClasses.toDouble() / totalClasses
                                 )
 
-                                // set timeout for concrete execution and for generated tests
-                                UtSettings.concreteExecutionTimeoutInInstrumentedProcess =
-                                    model.hangingTestsTimeout.timeoutMs
-
-                                UtSettings.useCustomJavaDocTags =
-                                    model.commentStyle == JavaDocCommentStyle.CUSTOM_JAVADOC_TAGS
-
-                                UtSettings.enableSummariesGeneration = model.enableSummariesGeneration
-
                                 val searchDirectory = ReadAction
                                     .nonBlocking<Path> {
                                         project.basePath?.let { Paths.get(it) }

utbot-intellij/src/main/kotlin/org/utbot/intellij/plugin/ui/GenerateTestsDialogWindow.kt

@@ -72,6 +72,7 @@ import com.intellij.util.ui.JBUI.scale
 import com.intellij.util.ui.JBUI.size
 import com.intellij.util.ui.UIUtil
 import com.intellij.util.ui.components.BorderLayoutPanel
+import mu.KotlinLogging
 import java.awt.BorderLayout
 import java.awt.Color
 import java.awt.Dimension
@@ -80,7 +81,6 @@ import java.nio.file.Files
 import java.nio.file.Path
 import java.nio.file.Paths
 import java.text.ParseException
-import java.util.Objects
 import java.util.concurrent.TimeUnit
 import javax.swing.AbstractAction
 import javax.swing.Action
@@ -116,6 +116,7 @@ import org.utbot.framework.plugin.api.utils.MOCKITO_EXTENSIONS_FILE_CONTENT
 import org.utbot.framework.plugin.api.utils.MOCKITO_EXTENSIONS_FOLDER
 import org.utbot.framework.plugin.api.utils.MOCKITO_MOCKMAKER_FILE_NAME
 import org.utbot.framework.util.Conflict
+import org.utbot.intellij.plugin.generator.UtTestsDialogProcessor
 import org.utbot.intellij.plugin.models.GenerateTestsModel
 import org.utbot.intellij.plugin.models.id
 import org.utbot.intellij.plugin.models.jUnit4LibraryDescriptor
@@ -142,6 +143,9 @@ import org.utbot.intellij.plugin.ui.utils.testRootType
 import org.utbot.intellij.plugin.util.IntelliJApiHelper
 import org.utbot.intellij.plugin.util.extractFirstLevelMembers
 import org.utbot.intellij.plugin.util.findSdkVersion
+import java.time.LocalDateTime
+import java.time.format.DateTimeFormatter
+import java.util.*
 
 private const val RECENTS_KEY = "org.utbot.recents"
 
@@ -160,6 +164,8 @@ class GenerateTestsDialogWindow(val model: GenerateTestsModel) : DialogWrapper(m
         const val maxSupportedSdkVersion = 17
     }
 
+    private val logger = KotlinLogging.logger {}
+
     private val membersTable = MemberSelectionTable(emptyList(), null)
 
     private val cbSpecifyTestPackage = CheckBox("Specify destination package", false)
@@ -486,6 +492,10 @@ class GenerateTestsDialogWindow(val model: GenerateTestsModel) : DialogWrapper(m
     override fun getOKAction() = okOptionAction
 
     override fun doOKAction() {
+        fun now() = LocalDateTime.now().format(DateTimeFormatter.ofPattern("HH:mm:ss.SSS"))
+
+        logger.info { "Tests generation instantiation phase started at ${now()}" }
+
         model.testPackageName =
             if (testPackageField.text != SAME_PACKAGE_LABEL) testPackageField.text else ""
 
@@ -542,7 +552,6 @@ class GenerateTestsDialogWindow(val model: GenerateTestsModel) : DialogWrapper(m
             }
         } catch (e: IncorrectOperationException) {
             println(e.message)
-
         }
 
         configureJvmTargetIfRequired()
@@ -551,6 +560,7 @@ class GenerateTestsDialogWindow(val model: GenerateTestsModel) : DialogWrapper(m
         configureStaticMockingIfRequired()
         configureParametrizedTestsIfRequired()
 
+        logger.info { "Tests generation instantiation phase finished at ${now()}" }
         super.doOKAction()
     }