diff --git a/usvm-core/src/main/kotlin/org/usvm/statistics/UDebugProfileObserver.kt b/usvm-core/src/main/kotlin/org/usvm/statistics/UDebugProfileObserver.kt index 91467ef299..145e3907be 100644 --- a/usvm-core/src/main/kotlin/org/usvm/statistics/UDebugProfileObserver.kt +++ b/usvm-core/src/main/kotlin/org/usvm/statistics/UDebugProfileObserver.kt @@ -79,18 +79,43 @@ open class UDebugProfileObserver>() protected val methodCalls = hashMapOf>() - private val stackTraceTracker = StackTraceTracker(statementOperations) + private val stackTraceTracker = StackTraceTracker(statementOperations) private val stackTraces = hashMapOf, MutableMap>() private val forksCount = hashMapOf, MutableMap>() + private val instructionTime = hashMapOf, MutableMap>() + + private var lastPeekMoment = 0L + private var lastStackTrace: TrieNode? = null override fun onStatePeeked(state: State) { - if (profilerOptions.momentOfUpdate == MomentOfUpdate.BeforeStep) { - processStateUpdate(state) + if (profilerOptions.momentOfUpdate != MomentOfUpdate.BeforeStep) { + return + } + + processStateUpdate(state) + + if (profilerOptions.profileTime) { + lastPeekMoment = System.nanoTime() } } @@ -100,6 +125,20 @@ open class UDebugProfileObserver, time: Long) { + var st = stackTrace + while (true) { + instructionTime.increment(st, state, value = time) + st = st.parent() ?: break + } } private fun processStateUpdate(state: State) { @@ -124,6 +163,7 @@ open class UDebugProfileObserver MutableMap>.increment(key: K, state: State) { + private fun MutableMap>.increment(key: K, state: State, value: Long = 1L) { val stateStats = this.getOrPut(key) { hashMapOf() } val stats = stateStats.getOrPut(state.id) { StatsCounter() } - stats.increment() + stats.add(value) } private fun aggregateStackTraces(slice: StateId?): ProfileFrame { @@ -143,16 +183,26 @@ open class UDebugProfileObserver time + TimeFormat.Microseconds -> time / MICRO_IN_NANO + TimeFormat.Milliseconds -> time / MILLIES_IN_NANO + } + } + private fun computeProfileFrame( slice: StateId?, inst: Statement, @@ -160,19 +210,24 @@ open class UDebugProfileObserver { val allNodeStats = stackTraces[root].orEmpty() val allForkStats = forksCount[root].orEmpty() + val allTimeStats = instructionTime[root].orEmpty() val children = root.children.mapValues { (i, node) -> computeProfileFrame(slice, i, node) } val nodeStats = allNodeStats.sumOfSlice(slice) val forkStats = allForkStats.sumOfSlice(slice) + val timeStats = allTimeStats.sumOfSlice(slice) - val selfStat = nodeStats - children.values.sumOf { it.total } + val selfStat = nodeStats - children.values.sumOf { it.totalSteps } val selfForks = forkStats - children.values.sumOf { it.totalForks } + val selfTime = timeStats - children.values.sumOf { it.totalTime } return ProfileFrame( inst, - nodeStats, - selfStat, - forkStats, - selfForks, + totalSteps = nodeStats, + selfSteps = selfStat, + totalForks = forkStats, + selfForks = selfForks, + totalTime = formatTime(timeStats), + selfTime = formatTime(selfTime), children, profilerOptions, statementOperations, @@ -181,10 +236,12 @@ open class UDebugProfileObserver>( val inst: Statement?, - val total: Long, - val self: Long, + val totalSteps: Long, + val selfSteps: Long, val totalForks: Long, val selfForks: Long, + val totalTime: Long, + val selfTime: Long, val children: Map>, private val profilerOptions: Options, private val statementOperations: StatementOperations, @@ -192,15 +249,23 @@ open class UDebugProfileObserver entry.value.sumOf { it.value.total } } + .sortedByDescending { entry -> entry.value.sumOf { it.value.totalSteps } } for ((method, inst) in sortedChildren) { - val total = inst.sumOf { it.value.total } - val self = inst.sumOf { it.value.self } + val total = inst.sumOf { it.value.totalSteps } + val self = inst.sumOf { it.value.selfSteps } val totalForks = inst.sumOf { it.value.totalForks } val selfForks = inst.sumOf { it.value.selfForks } val methodRepr = statementOperations.printMethodName(method) - str.appendLine("$indent|__ $methodRepr | Steps $self/$total | Forks $selfForks/$totalForks") + + str.append("$indent|__ $methodRepr | Steps $self/$total") + if (profilerOptions.profileForks) { + str.append(" | Forks $selfForks/$totalForks") + } + if (profilerOptions.profileTime) { + str.append(" | Time $selfTime/$totalTime") + } + str.appendLine() val children = if (profilerOptions.printNonVisitedStatements) { val allStatements = statementOperations.getAllMethodStatements(method) @@ -212,10 +277,12 @@ open class UDebugProfileObserver