diff --git a/gradle.properties b/gradle.properties index f335e5ca8e..83d31d88cd 100644 --- a/gradle.properties +++ b/gradle.properties @@ -102,7 +102,7 @@ commonsIOVersion=2.11.0 javaxVersion=2.2 jakartaVersion=3.1.0 jacoDbVersion=1.4.1 -usvmVersion=comp-231121-1810 +usvmVersion=comp-231122-1058 # use latest Java 8 compaitable Spring and Spring Boot versions springVersion=5.3.28 diff --git a/utbot-core/src/main/kotlin/org/utbot/common/ThreadUtil.kt b/utbot-core/src/main/kotlin/org/utbot/common/ThreadUtil.kt index 1aee3398bd..2dd7fb9969 100644 --- a/utbot-core/src/main/kotlin/org/utbot/common/ThreadUtil.kt +++ b/utbot-core/src/main/kotlin/org/utbot/common/ThreadUtil.kt @@ -61,7 +61,12 @@ class ThreadBasedExecutor { * * [stopWatch] is used to respect specific situations (such as class loading and transforming) while invoking. */ - fun invokeWithTimeout(timeoutMillis: Long, stopWatch: StopWatch? = null, action:() -> Any?) : Result? { + fun invokeWithTimeout( + timeoutMillis: Long, + stopWatch: StopWatch? = null, + threadDeathThrowPeriodMillis: Long = 10_000, + action:() -> Any? + ) : Result? { ensureThreadIsAlive() requestQueue.offer { @@ -95,10 +100,10 @@ class ThreadBasedExecutor { t.stop() } // If somebody catches `ThreadDeath`, for now we - // just wait for at most 10s and throw another one. + // just wait for [threadDeathThrowPeriod] and throw another one. // // A better approach may be to kill instrumented process. - t.join(10_000) + t.join(threadDeathThrowPeriodMillis) } } catch (_: Throwable) {} } diff --git a/utbot-junit-contest/src/main/kotlin/org/utbot/contest/usvm/ContestUsvm.kt b/utbot-junit-contest/src/main/kotlin/org/utbot/contest/usvm/ContestUsvm.kt index 8364cfaac3..22a7cb0af3 100644 --- a/utbot-junit-contest/src/main/kotlin/org/utbot/contest/usvm/ContestUsvm.kt +++ b/utbot-junit-contest/src/main/kotlin/org/utbot/contest/usvm/ContestUsvm.kt @@ -12,8 +12,11 @@ import org.jacodb.approximation.Approximations import org.jacodb.impl.features.InMemoryHierarchy import org.objectweb.asm.Type import org.usvm.UMachineOptions +import org.usvm.api.targets.JcTarget import org.usvm.instrumentation.util.jcdbSignature +import org.usvm.machine.JcMachine import org.usvm.machine.state.JcState +import org.usvm.statistics.collectors.StatesCollector import org.utbot.common.ThreadBasedExecutor import org.utbot.common.info import org.utbot.common.measureTime @@ -36,13 +39,15 @@ import org.utbot.framework.plugin.api.* import org.utbot.framework.plugin.api.util.constructor import org.utbot.framework.plugin.api.util.jClass import org.utbot.framework.plugin.api.util.method +import org.utbot.framework.plugin.api.util.utContext +import org.utbot.framework.plugin.api.util.withUtContext import org.utbot.framework.plugin.services.JdkInfoService import org.utbot.fuzzer.ReferencePreservingIntIdGenerator import org.utbot.fuzzer.UtFuzzedExecution import org.utbot.summary.usvm.summarizeAll import java.io.File import java.net.URLClassLoader -import kotlin.math.max +import kotlin.system.measureTimeMillis import kotlin.time.Duration.Companion.milliseconds private val logger = KotlinLogging.logger {} @@ -65,13 +70,10 @@ fun runUsvmGeneration( // 15% to terminate all activities and finalize code in file val generationTimeoutMillisWithoutCodegen: Long = timeBudgetMs - timeBudgetMs * 15 / 100 - // 15% for instrumentation - // TODO usvm-sbft: when `jcMachine.analyzeAsync(): Flow` is added run `analyze` and `execute` under common timeout - val jcMachineTimeoutMillis: Long = generationTimeoutMillisWithoutCodegen - timeBudgetMs * 15 / 100 logger.debug { "-----------------------------------------------------------------------------" } logger.info( - "Contest.runGeneration: Time budget: $timeBudgetMs ms, jcMachine timeout=$jcMachineTimeoutMillis ms, " + + "Contest.runGeneration: Time budget: $timeBudgetMs ms, generation timeout=$generationTimeoutMillisWithoutCodegen ms, " + "classpath=$classpathString, methodNameFilter=$methodNameFilter" ) @@ -80,7 +82,11 @@ fun runUsvmGeneration( val jcContainer by lazy { JcContainer( classpath = classpathFiles, - machineOptions = UMachineOptions(timeout = jcMachineTimeoutMillis.milliseconds) + machineOptions = UMachineOptions( + // TODO usvm-sbft: if we have less than CONTEST_TEST_EXECUTION_TIMEOUT time left, we should try execute + // with smaller timeout, but instrumentation currently doesn't allow to change timeout for individual runs + timeout = generationTimeoutMillisWithoutCodegen.milliseconds - CONTEST_TEST_EXECUTION_TIMEOUT + ) ) { // TODO usvm-sbft: we may want to tune these JcSettings for contest useJavaRuntime(JdkInfoService.provide().path.toFile()) @@ -107,10 +113,6 @@ fun runUsvmGeneration( logger.info { "STARTED COUNTING BUDGET FOR ${cut.classId.name}" } - val startTime = System.currentTimeMillis() - fun remainingBudgetMillisWithoutCodegen() = - max(0, generationTimeoutMillisWithoutCodegen - (System.currentTimeMillis() - startTime)) - if (cut.classLoader.javaClass != URLClassLoader::class.java) { logger.error("Seems like classloader for cut not valid (maybe it was backported to system): ${cut.classLoader}") } @@ -159,78 +161,62 @@ fun runUsvmGeneration( // nothing to process further if (jcMethods.isEmpty()) return@runBlocking statsForClass - val states = logger.info().measureTime({ "machine.analyze(${cut.classId.name})" }) { - ((ThreadBasedExecutor.threadLocal.invokeWithTimeout(jcMachineTimeoutMillis * 11 / 10) { - // TODO usvm-sbft: sometimes `machine.analyze` hangs forever, completely ignoring timeout specified for it - jcContainer.machine.analyze(jcMethods, targets = emptyList()) - } as? Result>) ?: run { - logger.error { "machine.analyze(${cut.classId.name}) timed out" } - Result.success(emptyList()) - }).getOrElse { e -> - logger.error(e) { "machine.analyze(${cut.classId.name}) failed" } - emptyList() - } - } - - val jcExecutions = logger.info().measureTime({ "executor.execute(${cut.classId.name})" }) { - states.mapNotNull { state -> - // TODO usvm-sbft: if we have less than CONTEST_TEST_EXECUTION_TIMEOUT time left, we should - // try executing with smaller timeout, but instrumentation currently doesn't allow to change timeout - if (remainingBudgetMillisWithoutCodegen() > CONTEST_TEST_EXECUTION_TIMEOUT.inWholeMilliseconds) { - runCatching { - executor.execute(state.entrypoint.typedMethod, state) - }.getOrElse { e -> - logger.error(e) { "executor.execute(${state.entrypoint}) failed" } - null - } - } else { - logger.warn { "executor.execute(${cut.classId.name}) run out of time" } - null + val timeStats = mutableMapOf() + + jcContainer.machine.analyzeAsync( + forceTerminationTimeout = (generationTimeoutMillisWithoutCodegen + timeBudgetMs) / 2, + methods = jcMethods, + targets = emptyList() + ) { state -> + val jcExecution = accumulateMeasureTime("executor.execute(${cut.classId.name})", timeStats) { + runCatching { + executor.execute(state.entrypoint.typedMethod, state) + }.getOrElse { e -> + logger.error(e) { "executor.execute(${state.entrypoint}) failed" } + return@analyzeAsync } } - } - - val utExecutions = logger.info().measureTime({"JcToUtExecutionConverter.convert(${cut.classId.name})"}) { - jcExecutions.mapNotNull { jcExecution -> - try { - val methodId = jcExecution.method.method.toExecutableId(jcContainer.cp) + val methodId = jcExecution.method.method.toExecutableId(jcContainer.cp) + val utExecution = accumulateMeasureTime("JcToUtExecutionConverter.convert(${cut.classId.name})", timeStats) { + runCatching { JcToUtExecutionConverter( jcExecution = jcExecution, jcClasspath = jcContainer.cp, idGenerator = utModelIdGenerator, instructionIdProvider = instructionIdGenerator, utilMethodProvider = codeGenerator.context.utilMethodProvider - ).convert()?.let { it to methodId } - } catch (e: Exception) { + ).convert() + // for some JcExecutions like RD faults we don't construct UtExecutions, converter logs such cases + ?: return@analyzeAsync + }.getOrElse { e -> logger.error(e) { "JcToUtExecutionConverter.convert(${jcExecution.method.method}) failed" } - null + return@analyzeAsync } } - } - - logger.info().measureTime({"Collect stats for ${cut.classId.name}"}) { - utExecutions.forEach { (utExecution, methodId) -> - try { - val className = Type.getInternalName(methodId.classId.jClass) - val statsForMethod = methodToStats.getValue(methodId) - statsForMethod.testsGeneratedCount++ - utExecution.result.exceptionOrNull()?.let { exception -> - statsForMethod.detectedExceptionFqns += exception::class.java.name - } - utExecution.coverage?.let { - statsForClass.updateCoverage( - newCoverage = it, - isNewClass = !statsForClass.testedClassNames.contains(className), - fromFuzzing = utExecution is UtFuzzedExecution - ) - } - statsForClass.testedClassNames.add(className) - testsByMethod.getOrPut(methodId) { mutableListOf() } += utExecution - } catch (e: Throwable) { - logger.error(e) { "Test generation failed during stats update for $methodId" } + runCatching { + val className = Type.getInternalName(methodId.classId.jClass) + val statsForMethod = methodToStats.getValue(methodId) + statsForMethod.testsGeneratedCount++ + utExecution.result.exceptionOrNull()?.let { exception -> + statsForMethod.detectedExceptionFqns += exception::class.java.name } + utExecution.coverage?.let { + statsForClass.updateCoverage( + newCoverage = it, + isNewClass = !statsForClass.testedClassNames.contains(className), + fromFuzzing = utExecution is UtFuzzedExecution + ) + } + statsForClass.testedClassNames.add(className) + testsByMethod.getOrPut(methodId) { mutableListOf() } += utExecution + }.getOrElse { e -> + logger.error(e) { "Test generation failed during stats update for $methodId" } } } + + timeStats.forEach { (regionName, timeMillis) -> + logger.info { "Region [$regionName] finished in $timeMillis ms" } + } } val testSets = logger.info().measureTime({ "Code generation for ${cut.classId.name}" }) { @@ -261,3 +247,48 @@ val ExecutableId.jcdbSignature: String get() = when (this) { is ConstructorId -> constructor.jcdbSignature is MethodId -> method.jcdbSignature } + +fun JcMachine.analyzeAsync( + forceTerminationTimeout: Long, + methods: List, + targets: List, + callback: (JcState) -> Unit +) { + val utContext = utContext + // TODO usvm-sbft: sometimes `machine.analyze` or `executor.execute` hangs forever, + // completely ignoring timeout specified for it, so additional hard time out is enforced here. + // Hard timeout seems to be working ok so far, however it may leave machine or executor in an inconsistent state. + // Also, `machine` or `executor` may catch `ThreadDeath` and still continue working (that is in fact what happens, + // but throwing `ThreadDeath` every 500 ms seems to eventually work). + ThreadBasedExecutor.threadLocal.invokeWithTimeout(forceTerminationTimeout, threadDeathThrowPeriodMillis = 500) { + withUtContext(utContext) { + analyze( + methods = methods, + statesCollector = object : StatesCollector { + override var count: Int = 0 + private set + + override fun addState(state: JcState) { + count++ + callback(state) + } + }, + targets = targets + ) + } + }?.onFailure { e -> + logger.error(e) { "analyzeAsync failed" } + } ?: logger.error { "analyzeAsync time exceeded hard time out" } +} + +inline fun accumulateMeasureTime( + regionName: String, + timeAccumulatorMillis: MutableMap, + block: () -> T +): T { + var res: T + timeAccumulatorMillis[regionName] = (timeAccumulatorMillis[regionName] ?: 0) + measureTimeMillis { + res = block() + } + return res +} diff --git a/utbot-junit-contest/src/main/kotlin/org/utbot/contest/usvm/converter/JcToUtExecutionConverter.kt b/utbot-junit-contest/src/main/kotlin/org/utbot/contest/usvm/converter/JcToUtExecutionConverter.kt index adab60cc8f..061f89cd42 100644 --- a/utbot-junit-contest/src/main/kotlin/org/utbot/contest/usvm/converter/JcToUtExecutionConverter.kt +++ b/utbot-junit-contest/src/main/kotlin/org/utbot/contest/usvm/converter/JcToUtExecutionConverter.kt @@ -33,7 +33,6 @@ import org.utbot.framework.plugin.api.UtExecutionFailure import org.utbot.framework.plugin.api.UtExecutionSuccess import org.utbot.framework.plugin.api.UtExplicitlyThrownException import org.utbot.framework.plugin.api.UtImplicitlyThrownException -import org.utbot.framework.plugin.api.UtInstrumentation import org.utbot.framework.plugin.api.UtPrimitiveModel import org.utbot.framework.plugin.api.UtStatementCallModel import org.utbot.framework.plugin.api.UtVoidModel @@ -94,14 +93,14 @@ class JcToUtExecutionConverter( is UTestExecutionInitFailedResult -> { logger.warn(convertException(executionResult.cause)) { - "Execution failed before method under test call" + "Execution failed before method under test call on ${jcExecution.method.method}" } null } is UTestExecutionFailedResult -> { logger.error(convertException(executionResult.cause)) { - "Concrete execution failed" + "Concrete execution failed on ${jcExecution.method.method}" } null }