From fe83c20f4c86853f91d727bbd595cd7a86cebac0 Mon Sep 17 00:00:00 2001 From: Egor Kulikov Date: Tue, 6 Dec 2022 12:51:35 +0300 Subject: [PATCH] Adding logs for phases start and finish --- .../utbot/framework/codegen/CodeGenerator.kt | 12 ++++++++++ .../generator/UtTestsDialogProcessor.kt | 24 ++++++++++--------- .../plugin/ui/GenerateTestsDialogWindow.kt | 14 +++++++++-- 3 files changed, 37 insertions(+), 13 deletions(-) diff --git a/utbot-framework/src/main/kotlin/org/utbot/framework/codegen/CodeGenerator.kt b/utbot-framework/src/main/kotlin/org/utbot/framework/codegen/CodeGenerator.kt index 243dd6cb8f..f969e35cd4 100644 --- a/utbot-framework/src/main/kotlin/org/utbot/framework/codegen/CodeGenerator.kt +++ b/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(), diff --git a/utbot-intellij/src/main/kotlin/org/utbot/intellij/plugin/generator/UtTestsDialogProcessor.kt b/utbot-intellij/src/main/kotlin/org/utbot/intellij/plugin/generator/UtTestsDialogProcessor.kt index 79807c2afc..8e4524cd20 100644 --- a/utbot-intellij/src/main/kotlin/org/utbot/intellij/plugin/generator/UtTestsDialogProcessor.kt +++ b/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,6 +200,8 @@ object UtTestsDialogProcessor { continue } + logger.info { "Collecting information phase finished at ${now()}" } + updateIndicator( indicator, ProgressRange.SOLVING, @@ -198,15 +209,6 @@ object UtTestsDialogProcessor { 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 { project.basePath?.let { Paths.get(it) } diff --git a/utbot-intellij/src/main/kotlin/org/utbot/intellij/plugin/ui/GenerateTestsDialogWindow.kt b/utbot-intellij/src/main/kotlin/org/utbot/intellij/plugin/ui/GenerateTestsDialogWindow.kt index 15200394d4..cf681a3b42 100644 --- a/utbot-intellij/src/main/kotlin/org/utbot/intellij/plugin/ui/GenerateTestsDialogWindow.kt +++ b/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() }