Skip to content

Commit 26751a5

Browse files
authored
Introduce and use JcMachine.analyzeAsync in ContestUsvm (#2696)
1 parent 65dd727 commit 26751a5

File tree

4 files changed

+110
-75
lines changed

4 files changed

+110
-75
lines changed

gradle.properties

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -102,7 +102,7 @@ commonsIOVersion=2.11.0
102102
javaxVersion=2.2
103103
jakartaVersion=3.1.0
104104
jacoDbVersion=1.4.1
105-
usvmVersion=comp-231121-1810
105+
usvmVersion=comp-231122-1058
106106

107107
# use latest Java 8 compaitable Spring and Spring Boot versions
108108
springVersion=5.3.28

utbot-core/src/main/kotlin/org/utbot/common/ThreadUtil.kt

Lines changed: 8 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -61,7 +61,12 @@ class ThreadBasedExecutor {
6161
*
6262
* [stopWatch] is used to respect specific situations (such as class loading and transforming) while invoking.
6363
*/
64-
fun invokeWithTimeout(timeoutMillis: Long, stopWatch: StopWatch? = null, action:() -> Any?) : Result<Any?>? {
64+
fun invokeWithTimeout(
65+
timeoutMillis: Long,
66+
stopWatch: StopWatch? = null,
67+
threadDeathThrowPeriodMillis: Long = 10_000,
68+
action:() -> Any?
69+
) : Result<Any?>? {
6570
ensureThreadIsAlive()
6671

6772
requestQueue.offer {
@@ -95,10 +100,10 @@ class ThreadBasedExecutor {
95100
t.stop()
96101
}
97102
// If somebody catches `ThreadDeath`, for now we
98-
// just wait for at most 10s and throw another one.
103+
// just wait for [threadDeathThrowPeriod] and throw another one.
99104
//
100105
// A better approach may be to kill instrumented process.
101-
t.join(10_000)
106+
t.join(threadDeathThrowPeriodMillis)
102107
}
103108
} catch (_: Throwable) {}
104109
}

utbot-junit-contest/src/main/kotlin/org/utbot/contest/usvm/ContestUsvm.kt

Lines changed: 99 additions & 68 deletions
Original file line numberDiff line numberDiff line change
@@ -12,8 +12,11 @@ import org.jacodb.approximation.Approximations
1212
import org.jacodb.impl.features.InMemoryHierarchy
1313
import org.objectweb.asm.Type
1414
import org.usvm.UMachineOptions
15+
import org.usvm.api.targets.JcTarget
1516
import org.usvm.instrumentation.util.jcdbSignature
17+
import org.usvm.machine.JcMachine
1618
import org.usvm.machine.state.JcState
19+
import org.usvm.statistics.collectors.StatesCollector
1720
import org.utbot.common.ThreadBasedExecutor
1821
import org.utbot.common.info
1922
import org.utbot.common.measureTime
@@ -36,13 +39,15 @@ import org.utbot.framework.plugin.api.*
3639
import org.utbot.framework.plugin.api.util.constructor
3740
import org.utbot.framework.plugin.api.util.jClass
3841
import org.utbot.framework.plugin.api.util.method
42+
import org.utbot.framework.plugin.api.util.utContext
43+
import org.utbot.framework.plugin.api.util.withUtContext
3944
import org.utbot.framework.plugin.services.JdkInfoService
4045
import org.utbot.fuzzer.ReferencePreservingIntIdGenerator
4146
import org.utbot.fuzzer.UtFuzzedExecution
4247
import org.utbot.summary.usvm.summarizeAll
4348
import java.io.File
4449
import java.net.URLClassLoader
45-
import kotlin.math.max
50+
import kotlin.system.measureTimeMillis
4651
import kotlin.time.Duration.Companion.milliseconds
4752

4853
private val logger = KotlinLogging.logger {}
@@ -65,13 +70,10 @@ fun runUsvmGeneration(
6570

6671
// 15% to terminate all activities and finalize code in file
6772
val generationTimeoutMillisWithoutCodegen: Long = timeBudgetMs - timeBudgetMs * 15 / 100
68-
// 15% for instrumentation
69-
// TODO usvm-sbft: when `jcMachine.analyzeAsync(): Flow<JcState>` is added run `analyze` and `execute` under common timeout
70-
val jcMachineTimeoutMillis: Long = generationTimeoutMillisWithoutCodegen - timeBudgetMs * 15 / 100
7173

7274
logger.debug { "-----------------------------------------------------------------------------" }
7375
logger.info(
74-
"Contest.runGeneration: Time budget: $timeBudgetMs ms, jcMachine timeout=$jcMachineTimeoutMillis ms, " +
76+
"Contest.runGeneration: Time budget: $timeBudgetMs ms, generation timeout=$generationTimeoutMillisWithoutCodegen ms, " +
7577
"classpath=$classpathString, methodNameFilter=$methodNameFilter"
7678
)
7779

@@ -80,7 +82,11 @@ fun runUsvmGeneration(
8082
val jcContainer by lazy {
8183
JcContainer(
8284
classpath = classpathFiles,
83-
machineOptions = UMachineOptions(timeout = jcMachineTimeoutMillis.milliseconds)
85+
machineOptions = UMachineOptions(
86+
// TODO usvm-sbft: if we have less than CONTEST_TEST_EXECUTION_TIMEOUT time left, we should try execute
87+
// with smaller timeout, but instrumentation currently doesn't allow to change timeout for individual runs
88+
timeout = generationTimeoutMillisWithoutCodegen.milliseconds - CONTEST_TEST_EXECUTION_TIMEOUT
89+
)
8490
) {
8591
// TODO usvm-sbft: we may want to tune these JcSettings for contest
8692
useJavaRuntime(JdkInfoService.provide().path.toFile())
@@ -107,10 +113,6 @@ fun runUsvmGeneration(
107113

108114
logger.info { "STARTED COUNTING BUDGET FOR ${cut.classId.name}" }
109115

110-
val startTime = System.currentTimeMillis()
111-
fun remainingBudgetMillisWithoutCodegen() =
112-
max(0, generationTimeoutMillisWithoutCodegen - (System.currentTimeMillis() - startTime))
113-
114116
if (cut.classLoader.javaClass != URLClassLoader::class.java) {
115117
logger.error("Seems like classloader for cut not valid (maybe it was backported to system): ${cut.classLoader}")
116118
}
@@ -159,78 +161,62 @@ fun runUsvmGeneration(
159161
// nothing to process further
160162
if (jcMethods.isEmpty()) return@runBlocking statsForClass
161163

162-
val states = logger.info().measureTime({ "machine.analyze(${cut.classId.name})" }) {
163-
((ThreadBasedExecutor.threadLocal.invokeWithTimeout(jcMachineTimeoutMillis * 11 / 10) {
164-
// TODO usvm-sbft: sometimes `machine.analyze` hangs forever, completely ignoring timeout specified for it
165-
jcContainer.machine.analyze(jcMethods, targets = emptyList())
166-
} as? Result<List<JcState>>) ?: run {
167-
logger.error { "machine.analyze(${cut.classId.name}) timed out" }
168-
Result.success(emptyList())
169-
}).getOrElse { e ->
170-
logger.error(e) { "machine.analyze(${cut.classId.name}) failed" }
171-
emptyList()
172-
}
173-
}
174-
175-
val jcExecutions = logger.info().measureTime({ "executor.execute(${cut.classId.name})" }) {
176-
states.mapNotNull { state ->
177-
// TODO usvm-sbft: if we have less than CONTEST_TEST_EXECUTION_TIMEOUT time left, we should
178-
// try executing with smaller timeout, but instrumentation currently doesn't allow to change timeout
179-
if (remainingBudgetMillisWithoutCodegen() > CONTEST_TEST_EXECUTION_TIMEOUT.inWholeMilliseconds) {
180-
runCatching {
181-
executor.execute(state.entrypoint.typedMethod, state)
182-
}.getOrElse { e ->
183-
logger.error(e) { "executor.execute(${state.entrypoint}) failed" }
184-
null
185-
}
186-
} else {
187-
logger.warn { "executor.execute(${cut.classId.name}) run out of time" }
188-
null
164+
val timeStats = mutableMapOf<String, Long>()
165+
166+
jcContainer.machine.analyzeAsync(
167+
forceTerminationTimeout = (generationTimeoutMillisWithoutCodegen + timeBudgetMs) / 2,
168+
methods = jcMethods,
169+
targets = emptyList()
170+
) { state ->
171+
val jcExecution = accumulateMeasureTime("executor.execute(${cut.classId.name})", timeStats) {
172+
runCatching {
173+
executor.execute(state.entrypoint.typedMethod, state)
174+
}.getOrElse { e ->
175+
logger.error(e) { "executor.execute(${state.entrypoint}) failed" }
176+
return@analyzeAsync
189177
}
190178
}
191-
}
192-
193-
val utExecutions = logger.info().measureTime({"JcToUtExecutionConverter.convert(${cut.classId.name})"}) {
194-
jcExecutions.mapNotNull { jcExecution ->
195-
try {
196-
val methodId = jcExecution.method.method.toExecutableId(jcContainer.cp)
179+
val methodId = jcExecution.method.method.toExecutableId(jcContainer.cp)
180+
val utExecution = accumulateMeasureTime("JcToUtExecutionConverter.convert(${cut.classId.name})", timeStats) {
181+
runCatching {
197182
JcToUtExecutionConverter(
198183
jcExecution = jcExecution,
199184
jcClasspath = jcContainer.cp,
200185
idGenerator = utModelIdGenerator,
201186
instructionIdProvider = instructionIdGenerator,
202187
utilMethodProvider = codeGenerator.context.utilMethodProvider
203-
).convert()?.let { it to methodId }
204-
} catch (e: Exception) {
188+
).convert()
189+
// for some JcExecutions like RD faults we don't construct UtExecutions, converter logs such cases
190+
?: return@analyzeAsync
191+
}.getOrElse { e ->
205192
logger.error(e) { "JcToUtExecutionConverter.convert(${jcExecution.method.method}) failed" }
206-
null
193+
return@analyzeAsync
207194
}
208195
}
209-
}
210-
211-
logger.info().measureTime({"Collect stats for ${cut.classId.name}"}) {
212-
utExecutions.forEach { (utExecution, methodId) ->
213-
try {
214-
val className = Type.getInternalName(methodId.classId.jClass)
215-
val statsForMethod = methodToStats.getValue(methodId)
216-
statsForMethod.testsGeneratedCount++
217-
utExecution.result.exceptionOrNull()?.let { exception ->
218-
statsForMethod.detectedExceptionFqns += exception::class.java.name
219-
}
220-
utExecution.coverage?.let {
221-
statsForClass.updateCoverage(
222-
newCoverage = it,
223-
isNewClass = !statsForClass.testedClassNames.contains(className),
224-
fromFuzzing = utExecution is UtFuzzedExecution
225-
)
226-
}
227-
statsForClass.testedClassNames.add(className)
228-
testsByMethod.getOrPut(methodId) { mutableListOf() } += utExecution
229-
} catch (e: Throwable) {
230-
logger.error(e) { "Test generation failed during stats update for $methodId" }
196+
runCatching {
197+
val className = Type.getInternalName(methodId.classId.jClass)
198+
val statsForMethod = methodToStats.getValue(methodId)
199+
statsForMethod.testsGeneratedCount++
200+
utExecution.result.exceptionOrNull()?.let { exception ->
201+
statsForMethod.detectedExceptionFqns += exception::class.java.name
231202
}
203+
utExecution.coverage?.let {
204+
statsForClass.updateCoverage(
205+
newCoverage = it,
206+
isNewClass = !statsForClass.testedClassNames.contains(className),
207+
fromFuzzing = utExecution is UtFuzzedExecution
208+
)
209+
}
210+
statsForClass.testedClassNames.add(className)
211+
testsByMethod.getOrPut(methodId) { mutableListOf() } += utExecution
212+
}.getOrElse { e ->
213+
logger.error(e) { "Test generation failed during stats update for $methodId" }
232214
}
233215
}
216+
217+
timeStats.forEach { (regionName, timeMillis) ->
218+
logger.info { "Region [$regionName] finished in $timeMillis ms" }
219+
}
234220
}
235221

236222
val testSets = logger.info().measureTime({ "Code generation for ${cut.classId.name}" }) {
@@ -261,3 +247,48 @@ val ExecutableId.jcdbSignature: String get() = when (this) {
261247
is ConstructorId -> constructor.jcdbSignature
262248
is MethodId -> method.jcdbSignature
263249
}
250+
251+
fun JcMachine.analyzeAsync(
252+
forceTerminationTimeout: Long,
253+
methods: List<JcMethod>,
254+
targets: List<JcTarget>,
255+
callback: (JcState) -> Unit
256+
) {
257+
val utContext = utContext
258+
// TODO usvm-sbft: sometimes `machine.analyze` or `executor.execute` hangs forever,
259+
// completely ignoring timeout specified for it, so additional hard time out is enforced here.
260+
// Hard timeout seems to be working ok so far, however it may leave machine or executor in an inconsistent state.
261+
// Also, `machine` or `executor` may catch `ThreadDeath` and still continue working (that is in fact what happens,
262+
// but throwing `ThreadDeath` every 500 ms seems to eventually work).
263+
ThreadBasedExecutor.threadLocal.invokeWithTimeout(forceTerminationTimeout, threadDeathThrowPeriodMillis = 500) {
264+
withUtContext(utContext) {
265+
analyze(
266+
methods = methods,
267+
statesCollector = object : StatesCollector<JcState> {
268+
override var count: Int = 0
269+
private set
270+
271+
override fun addState(state: JcState) {
272+
count++
273+
callback(state)
274+
}
275+
},
276+
targets = targets
277+
)
278+
}
279+
}?.onFailure { e ->
280+
logger.error(e) { "analyzeAsync failed" }
281+
} ?: logger.error { "analyzeAsync time exceeded hard time out" }
282+
}
283+
284+
inline fun <T> accumulateMeasureTime(
285+
regionName: String,
286+
timeAccumulatorMillis: MutableMap<String, Long>,
287+
block: () -> T
288+
): T {
289+
var res: T
290+
timeAccumulatorMillis[regionName] = (timeAccumulatorMillis[regionName] ?: 0) + measureTimeMillis {
291+
res = block()
292+
}
293+
return res
294+
}

utbot-junit-contest/src/main/kotlin/org/utbot/contest/usvm/converter/JcToUtExecutionConverter.kt

Lines changed: 2 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -33,7 +33,6 @@ import org.utbot.framework.plugin.api.UtExecutionFailure
3333
import org.utbot.framework.plugin.api.UtExecutionSuccess
3434
import org.utbot.framework.plugin.api.UtExplicitlyThrownException
3535
import org.utbot.framework.plugin.api.UtImplicitlyThrownException
36-
import org.utbot.framework.plugin.api.UtInstrumentation
3736
import org.utbot.framework.plugin.api.UtPrimitiveModel
3837
import org.utbot.framework.plugin.api.UtStatementCallModel
3938
import org.utbot.framework.plugin.api.UtVoidModel
@@ -94,14 +93,14 @@ class JcToUtExecutionConverter(
9493

9594
is UTestExecutionInitFailedResult -> {
9695
logger.warn(convertException(executionResult.cause)) {
97-
"Execution failed before method under test call"
96+
"Execution failed before method under test call on ${jcExecution.method.method}"
9897
}
9998
null
10099
}
101100

102101
is UTestExecutionFailedResult -> {
103102
logger.error(convertException(executionResult.cause)) {
104-
"Concrete execution failed"
103+
"Concrete execution failed on ${jcExecution.method.method}"
105104
}
106105
null
107106
}

0 commit comments

Comments
 (0)