Introduce and use JcMachine.analyzeAsync in ContestUsvm

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

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<Any?>? {
+    fun invokeWithTimeout(
+        timeoutMillis: Long,
+        stopWatch: StopWatch? = null,
+        threadDeathThrowPeriodMillis: Long = 10_000,
+        action:() -> Any?
+    ) : Result<Any?>? {
         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) {}
         }

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<JcState>` 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<List<JcState>>) ?: 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<String, Long>()
+
+        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<JcMethod>,
+    targets: List<JcTarget>,
+    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<JcState> {
+                    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 <T> accumulateMeasureTime(
+    regionName: String,
+    timeAccumulatorMillis: MutableMap<String, Long>,
+    block: () -> T
+): T {
+    var res: T
+    timeAccumulatorMillis[regionName] = (timeAccumulatorMillis[regionName] ?: 0) + measureTimeMillis {
+        res = block()
+    }
+    return res
+}

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
             }