From 67296cd46eb6db92cb40e6fffa6cfcabae68aee3 Mon Sep 17 00:00:00 2001 From: "Aleksandr.Potapov" Date: Mon, 29 Jul 2024 01:55:34 +0300 Subject: [PATCH 1/8] Multiple suspension points support --- .../lincheck/runner/ParallelThreadsRunner.kt | 23 ++- .../MultipleSuspensionsTests.kt | 177 ++++++++++++++++++ .../expected_logs/single_suspension_trace.txt | 62 ++++++ .../expected_logs/suspended_not_awoke.txt | 5 +- .../two_suspension_points_bug.txt | 50 +++++ 5 files changed, 308 insertions(+), 9 deletions(-) create mode 100644 src/jvm/test/org/jetbrains/kotlinx/lincheck_test/representation/MultipleSuspensionsTests.kt create mode 100644 src/jvm/test/resources/expected_logs/single_suspension_trace.txt create mode 100644 src/jvm/test/resources/expected_logs/two_suspension_points_bug.txt diff --git a/src/jvm/main/org/jetbrains/kotlinx/lincheck/runner/ParallelThreadsRunner.kt b/src/jvm/main/org/jetbrains/kotlinx/lincheck/runner/ParallelThreadsRunner.kt index 3859ba290..bae7bc65d 100644 --- a/src/jvm/main/org/jetbrains/kotlinx/lincheck/runner/ParallelThreadsRunner.kt +++ b/src/jvm/main/org/jetbrains/kotlinx/lincheck/runner/ParallelThreadsRunner.kt @@ -258,16 +258,25 @@ internal open class ParallelThreadsRunner( // Coroutine will be resumed. Call method so that strategy can learn it. afterCoroutineResumed(threadId) // Check whether the result of the suspension point with the continuation has been stored - // by the resuming thread and invoke the follow-up part in this case. - if (completion.resWithCont.get() !== null) { - // Suspended thread got the result of the suspension point and continuation to resume. - val resumedValue = completion.resWithCont.get().first - // It is important to run the coroutine resumption part outside the ignored section - // to track the events inside resumption. + // by the resuming thread, and invoke the follow-up part in this case + val suspendResultToContinuation = completion.resWithCont.get() + if (suspendResultToContinuation !== null) { + // Suspended thread got result of the suspension point and continuation to resume + val (resumedValue, continuation) = suspendResultToContinuation + // Erase the current result + completion.resWithCont.set(null) + // We must exit the ignored section to keep tracking execution after the resumption. runOutsideIgnoredSection(thread) { - completion.resWithCont.get().second.resumeWith(resumedValue) + // Resume the execution of the coroutine. + continuation.resumeWith(resumedValue) } } + // If we've suspended again - then clean the completion status and rerun all the logic of this method to + // wait for resumption. + if (suspensionPointResults[threadId][actorId] == NoResult) { + completionStatuses[threadId].set(actorId, null) + return waitAndInvokeFollowUp(thread, actorId) + } return suspensionPointResults[threadId][actorId] } diff --git a/src/jvm/test/org/jetbrains/kotlinx/lincheck_test/representation/MultipleSuspensionsTests.kt b/src/jvm/test/org/jetbrains/kotlinx/lincheck_test/representation/MultipleSuspensionsTests.kt new file mode 100644 index 000000000..25315fa39 --- /dev/null +++ b/src/jvm/test/org/jetbrains/kotlinx/lincheck_test/representation/MultipleSuspensionsTests.kt @@ -0,0 +1,177 @@ +/* + * Lincheck + * + * Copyright (C) 2019 - 2024 JetBrains s.r.o. + * + * This Source Code Form is subject to the terms of the + * Mozilla Public License, v. 2.0. If a copy of the MPL was not distributed + * with this file, You can obtain one at http://mozilla.org/MPL/2.0/. + */ + +package org.jetbrains.kotlinx.lincheck_test.representation + +import kotlinx.atomicfu.atomic +import kotlinx.coroutines.CancellableContinuation +import kotlinx.coroutines.InternalCoroutinesApi +import kotlinx.coroutines.suspendCancellableCoroutine +import org.jetbrains.kotlinx.lincheck.annotations.Operation +import org.jetbrains.kotlinx.lincheck.checkImpl +import org.jetbrains.kotlinx.lincheck.strategy.managed.forClasses +import org.jetbrains.kotlinx.lincheck.strategy.managed.modelchecking.ModelCheckingOptions +import org.jetbrains.kotlinx.lincheck_test.AbstractLincheckTest +import org.jetbrains.kotlinx.lincheck_test.util.checkLincheckOutput +import org.junit.Test +import java.util.concurrent.ConcurrentLinkedQueue +import java.util.concurrent.atomic.AtomicInteger +import kotlin.coroutines.Continuation +import kotlin.coroutines.resume +import kotlin.coroutines.suspendCoroutine + +/** + * Checks that the bug, which can only be found with a proper multiple suspension point support, is found + * and correctly reported. See expected output for more details. + */ +@Suppress("RemoveExplicitTypeArguments") +class MultipleSuspensionTest { + + private var counter = AtomicInteger(0) + private var continuation1: Continuation? = null + private var continuation2: Continuation? = null + + @Operation + fun trigger() { + firstStep() + secondStep() + counter.set(3) + } + + private fun firstStep() { + counter.set(1) + continuation1?.resume(Unit) + } + + private fun secondStep() { + counter.set(2) + continuation2?.resume(Unit) + } + + @Operation + suspend fun operation(): Int { + if (part1()) return 0 + if (part2()) return 0 + counter.get() + return 1 + } + + private suspend fun part2(): Boolean { + if (counter.get() == 1) { + suspendCoroutine { continuation2 = it } + } else return true + return false + } + + private suspend fun part1(): Boolean { + if (counter.get() == 0) { + suspendCoroutine { continuation1 = it } + } else return true + return false + } + + @Test + fun test(): Unit = ModelCheckingOptions() + .addCustomScenario { + parallel { + thread { actor(::trigger) } + thread { actor(::operation) } + } + } + .addGuarantee(forClasses(this::class.java.name).methods("firstStep", "secondStep", "part1", "part2").treatAsAtomic()) + .checkImpl(this::class.java) + .checkLincheckOutput("two_suspension_points_bug.txt") + +} + +/** + * Check the proper output in case when one actor cause incorrect behaviour only after coroutine resumption. + */ +class SingleSuspensionTraceReportingTest { + + private var counter = AtomicInteger(0) + private var continuation1: Continuation? = null + @Volatile + private var fail: Boolean = false + + @Operation + fun triggerAndCheck(): Boolean { + return continueAndCheckIfFailed() + } + + private fun continueAndCheckIfFailed(): Boolean { + counter.set(1) + continuation1?.resume(Unit) + return fail + } + + @Operation + suspend fun operation(): Int { + // Nested method to check proper trace reporting + return suspendAndCauseFailure() + } + + @Suppress("SameReturnValue") + private suspend fun suspendAndCauseFailure(): Int { + if (counter.get() == 1) { + @Suppress("RemoveExplicitTypeArguments") + // Doesn't compile without explicit typing for now + suspendCoroutine { continuation1 = it } + } else return 0 + fail = true + return 0 + } + + @Test + fun test() = ModelCheckingOptions() + .addCustomScenario { + parallel { + thread { actor(::triggerAndCheck) } + thread { actor(::operation) } + } + } + .checkImpl(this::class.java) + .checkLincheckOutput("single_suspension_trace.txt") + +} + +/** + * Checks the data structure which actors may suspend multiple times. + * Passes only if the multiple suspension points are supported properly. + */ +@OptIn(InternalCoroutinesApi::class) +class CoroutinesMultipleSuspensionsTest : AbstractLincheckTest() { + private val locked = atomic(false) + private val waiters = ConcurrentLinkedQueue>() + + @Operation + suspend fun lock() { + while (true) { + if (locked.compareAndSet(false, true)) return + suspendCancellableCoroutine { cont -> + waiters.add(cont) + if (!locked.value) { + if (waiters.remove(cont)) cont.resume(Unit) + } + } + } + } + + @Operation + fun unlock() { + if (!locked.compareAndSet(true, false)) error("mutex was not locked") + while (true) { + val w = waiters.poll() ?: break + val token = w.tryResume(Unit, null) ?: continue + w.completeResume(token) + return + } + } +} \ No newline at end of file diff --git a/src/jvm/test/resources/expected_logs/single_suspension_trace.txt b/src/jvm/test/resources/expected_logs/single_suspension_trace.txt new file mode 100644 index 000000000..055722d78 --- /dev/null +++ b/src/jvm/test/resources/expected_logs/single_suspension_trace.txt @@ -0,0 +1,62 @@ += Invalid execution results = +| ---------------------------------------- | +| Thread 1 | Thread 2 | +| ---------------------------------------- | +| triggerAndCheck(): true | operation(): 0 | +| ---------------------------------------- | + +The following interleaving leads to the error: +| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ | +| Thread 1 | Thread 2 | +| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ | +| triggerAndCheck(): true | | +| continueAndCheckIfFailed(): true at SingleSuspensionTraceReportingTest.triggerAndCheck(MultipleSuspensionsTests.kt:106) | | +| counter.READ: AtomicInteger#1 at SingleSuspensionTraceReportingTest.continueAndCheckIfFailed(MultipleSuspensionsTests.kt:110) | | +| AtomicInteger#1.set(1) at SingleSuspensionTraceReportingTest.continueAndCheckIfFailed(MultipleSuspensionsTests.kt:110) | | +| switch | | +| | operation(): 0 | +| | suspendAndCauseFailure(): COROUTINE_SUSPENDED at SingleSuspensionTraceReportingTest.operation(MultipleSuspensionsTests.kt:118) | +| | counter.READ: AtomicInteger#1 at SingleSuspensionTraceReportingTest.suspendAndCauseFailure(MultipleSuspensionsTests.kt:123) | +| | AtomicInteger#1.get(): 1 at SingleSuspensionTraceReportingTest.suspendAndCauseFailure(MultipleSuspensionsTests.kt:123) | +| | continuation1.WRITE() at SingleSuspensionTraceReportingTest.suspendAndCauseFailure(MultipleSuspensionsTests.kt:126) | +| | .getOrThrow(): COROUTINE_SUSPENDED at SingleSuspensionTraceReportingTest.suspendAndCauseFailure(MultipleSuspensionsTests.kt:126) | +| | result.READ: UNDECIDED at SafeContinuation.getOrThrow(SafeContinuationJvm.kt:51) | +| | result.compareAndSet(UNDECIDED,COROUTINE_SUSPENDED): true at SafeContinuation.getOrThrow(SafeContinuationJvm.kt:53) | +| | switch (reason: coroutine is suspended) | +| continuation1.READ: at SingleSuspensionTraceReportingTest.continueAndCheckIfFailed(MultipleSuspensionsTests.kt:111) | | +| .resumeWith(Unit#1) at SingleSuspensionTraceReportingTest.continueAndCheckIfFailed(MultipleSuspensionsTests.kt:111) | | +| switch | | +| | fail.WRITE(true) at SingleSuspensionTraceReportingTest.suspendAndCauseFailure(MultipleSuspensionsTests.kt:128) | +| | result: 0 | +| fail.READ: true at SingleSuspensionTraceReportingTest.continueAndCheckIfFailed(MultipleSuspensionsTests.kt:112) | | +| result: true | | +| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ | + +Detailed trace: +| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ | +| Thread 1 | Thread 2 | +| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ | +| triggerAndCheck(): true | | +| continueAndCheckIfFailed(): true at SingleSuspensionTraceReportingTest.triggerAndCheck(MultipleSuspensionsTests.kt:106) | | +| counter.READ: AtomicInteger#1 at SingleSuspensionTraceReportingTest.continueAndCheckIfFailed(MultipleSuspensionsTests.kt:110) | | +| AtomicInteger#1.set(1) at SingleSuspensionTraceReportingTest.continueAndCheckIfFailed(MultipleSuspensionsTests.kt:110) | | +| switch | | +| | operation(): 0 | +| | suspendAndCauseFailure(): COROUTINE_SUSPENDED at SingleSuspensionTraceReportingTest.operation(MultipleSuspensionsTests.kt:118) | +| | counter.READ: AtomicInteger#1 at SingleSuspensionTraceReportingTest.suspendAndCauseFailure(MultipleSuspensionsTests.kt:123) | +| | AtomicInteger#1.get(): 1 at SingleSuspensionTraceReportingTest.suspendAndCauseFailure(MultipleSuspensionsTests.kt:123) | +| | continuation1.WRITE() at SingleSuspensionTraceReportingTest.suspendAndCauseFailure(MultipleSuspensionsTests.kt:126) | +| | .getOrThrow(): COROUTINE_SUSPENDED at SingleSuspensionTraceReportingTest.suspendAndCauseFailure(MultipleSuspensionsTests.kt:126) | +| | result.READ: UNDECIDED at SafeContinuation.getOrThrow(SafeContinuationJvm.kt:51) | +| | result.compareAndSet(UNDECIDED,COROUTINE_SUSPENDED): true at SafeContinuation.getOrThrow(SafeContinuationJvm.kt:53) | +| | switch (reason: coroutine is suspended) | +| continuation1.READ: at SingleSuspensionTraceReportingTest.continueAndCheckIfFailed(MultipleSuspensionsTests.kt:111) | | +| .resumeWith(Unit#1) at SingleSuspensionTraceReportingTest.continueAndCheckIfFailed(MultipleSuspensionsTests.kt:111) | | +| result.READ: COROUTINE_SUSPENDED at SafeContinuation.resumeWith(SafeContinuationJvm.kt:37) | | +| result.compareAndSet(COROUTINE_SUSPENDED,RESUMED): true at SafeContinuation.resumeWith(SafeContinuationJvm.kt:40) | | +| switch | | +| | fail.WRITE(true) at SingleSuspensionTraceReportingTest.suspendAndCauseFailure(MultipleSuspensionsTests.kt:128) | +| | result: 0 | +| fail.READ: true at SingleSuspensionTraceReportingTest.continueAndCheckIfFailed(MultipleSuspensionsTests.kt:112) | | +| result: true | | +| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ | diff --git a/src/jvm/test/resources/expected_logs/suspended_not_awoke.txt b/src/jvm/test/resources/expected_logs/suspended_not_awoke.txt index bc16ce266..20cbc4be8 100644 --- a/src/jvm/test/resources/expected_logs/suspended_not_awoke.txt +++ b/src/jvm/test/resources/expected_logs/suspended_not_awoke.txt @@ -27,7 +27,8 @@ The following interleaving leads to the error: | | trySuspend(): true at CancellableContinuationImpl.getResult(CancellableContinuationImpl.kt:300) | | | getParentHandle(): null at CancellableContinuationImpl.getResult(CancellableContinuationImpl.kt:310) | | | installParentHandle(): ChildContinuation#1 at CancellableContinuationImpl.getResult(CancellableContinuationImpl.kt:311) | -| | switch (reason: coroutine is suspended) | +| | _parentHandle.compareAndSet(null,ChildContinuation#1): true at CancellableContinuationImpl.installParentHandle(CancellableContinuationImpl.kt:352) | +| | switch (reason: coroutine is suspended) | | | result: Suspended | | allowed.WRITE(false) at SuspendedNotAwokeTest.trigger(SuspendedNotAwokeTest.kt:32) | | | result: void | | @@ -81,7 +82,7 @@ Detailed trace: | | _parentHandle.get(): null at CancellableContinuationImpl.getParentHandle(CancellableContinuationImpl.kt:106) | | | installParentHandle(): ChildContinuation#1 at CancellableContinuationImpl.getResult(CancellableContinuationImpl.kt:311) | | | _parentHandle.compareAndSet(null,ChildContinuation#1): true at CancellableContinuationImpl.installParentHandle(CancellableContinuationImpl.kt:352) | -| | switch (reason: coroutine is suspended) | +| | switch (reason: coroutine is suspended) | | | result: Suspended | | allowed.WRITE(false) at SuspendedNotAwokeTest.trigger(SuspendedNotAwokeTest.kt:32) | | | result: void | | diff --git a/src/jvm/test/resources/expected_logs/two_suspension_points_bug.txt b/src/jvm/test/resources/expected_logs/two_suspension_points_bug.txt new file mode 100644 index 000000000..98d40363a --- /dev/null +++ b/src/jvm/test/resources/expected_logs/two_suspension_points_bug.txt @@ -0,0 +1,50 @@ += Invalid execution results = +| -------------------------------- | +| Thread 1 | Thread 2 | +| -------------------------------- | +| trigger(): void | operation(): 1 | +| -------------------------------- | + +The following interleaving leads to the error: +| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| Thread 1 | Thread 2 | +| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| | operation(): 1 | +| | part1(): COROUTINE_SUSPENDED at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:56) | +| | switch (reason: coroutine is suspended) | +| trigger() | | +| firstStep() at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:39) | | +| switch | | +| | operation(): COROUTINE_SUSPENDED at MultipleSuspensionTest$operation$1.invokeSuspend(MultipleSuspensionsTests.kt:0) | +| | part2(): COROUTINE_SUSPENDED at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:57) | +| | switch (reason: coroutine is suspended) | +| secondStep() at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:40) | | +| counter.READ: AtomicInteger#1 at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:41) | | +| AtomicInteger#1.set(3) at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:41) | | +| result: void | | +| | counter.READ: AtomicInteger#1 at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:58) | +| | AtomicInteger#1.get(): 3 at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:58) | +| | result: 1 | +| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | + +Detailed trace: +| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| Thread 1 | Thread 2 | +| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| | operation(): 1 | +| | part1(): COROUTINE_SUSPENDED at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:56) | +| | switch (reason: coroutine is suspended) | +| trigger() | | +| firstStep() at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:39) | | +| switch | | +| | operation(): COROUTINE_SUSPENDED at MultipleSuspensionTest$operation$1.invokeSuspend(MultipleSuspensionsTests.kt:0) | +| | part2(): COROUTINE_SUSPENDED at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:57) | +| | switch (reason: coroutine is suspended) | +| secondStep() at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:40) | | +| counter.READ: AtomicInteger#1 at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:41) | | +| AtomicInteger#1.set(3) at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:41) | | +| result: void | | +| | counter.READ: AtomicInteger#1 at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:58) | +| | AtomicInteger#1.get(): 3 at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:58) | +| | result: 1 | +| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | From c410a894c0a066006b4b3b6f7b1fcc14e820659b Mon Sep 17 00:00:00 2001 From: Evgeniy Moiseenko Date: Thu, 26 Dec 2024 16:09:51 +0100 Subject: [PATCH 2/8] fix suspend switch point positions in the trace Signed-off-by: Evgeniy Moiseenko --- .../strategy/managed/ManagedStrategy.kt | 6 +- .../expected_logs/single_suspension_trace.txt | 4 +- .../expected_logs/suspend_trace_reporting.txt | 56 +++++++++---------- ...sumption_frame_skipping_reporting_test.txt | 4 +- ...uspend_trace_resumption_reporting_test.txt | 4 +- .../expected_logs/suspended_not_awoke.txt | 5 +- 6 files changed, 41 insertions(+), 38 deletions(-) diff --git a/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt b/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt index 169e329fa..48df065aa 100644 --- a/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt +++ b/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt @@ -1513,11 +1513,15 @@ abstract class ManagedStrategy( beforeMethodCallSwitch = beforeMethodCallSwitch ) } + val callStackTrace = when (reason) { + SwitchReason.SUSPENDED -> suspendedFunctionsStack[iThread].reversed() + else -> callStackTrace[iThread] + } _trace += SwitchEventTracePoint( iThread = iThread, actorId = currentActorId[iThread], reason = reason, - callStackTrace = callStackTrace[iThread] + callStackTrace = callStackTrace, ) spinCycleStartAdded = false } diff --git a/src/jvm/test/resources/expected_logs/single_suspension_trace.txt b/src/jvm/test/resources/expected_logs/single_suspension_trace.txt index 055722d78..68284fc87 100644 --- a/src/jvm/test/resources/expected_logs/single_suspension_trace.txt +++ b/src/jvm/test/resources/expected_logs/single_suspension_trace.txt @@ -15,7 +15,7 @@ The following interleaving leads to the error: | AtomicInteger#1.set(1) at SingleSuspensionTraceReportingTest.continueAndCheckIfFailed(MultipleSuspensionsTests.kt:110) | | | switch | | | | operation(): 0 | -| | suspendAndCauseFailure(): COROUTINE_SUSPENDED at SingleSuspensionTraceReportingTest.operation(MultipleSuspensionsTests.kt:118) | +| | suspendAndCauseFailure(): 0 at SingleSuspensionTraceReportingTest.operation(MultipleSuspensionsTests.kt:118) | | | counter.READ: AtomicInteger#1 at SingleSuspensionTraceReportingTest.suspendAndCauseFailure(MultipleSuspensionsTests.kt:123) | | | AtomicInteger#1.get(): 1 at SingleSuspensionTraceReportingTest.suspendAndCauseFailure(MultipleSuspensionsTests.kt:123) | | | continuation1.WRITE() at SingleSuspensionTraceReportingTest.suspendAndCauseFailure(MultipleSuspensionsTests.kt:126) | @@ -42,7 +42,7 @@ Detailed trace: | AtomicInteger#1.set(1) at SingleSuspensionTraceReportingTest.continueAndCheckIfFailed(MultipleSuspensionsTests.kt:110) | | | switch | | | | operation(): 0 | -| | suspendAndCauseFailure(): COROUTINE_SUSPENDED at SingleSuspensionTraceReportingTest.operation(MultipleSuspensionsTests.kt:118) | +| | suspendAndCauseFailure(): 0 at SingleSuspensionTraceReportingTest.operation(MultipleSuspensionsTests.kt:118) | | | counter.READ: AtomicInteger#1 at SingleSuspensionTraceReportingTest.suspendAndCauseFailure(MultipleSuspensionsTests.kt:123) | | | AtomicInteger#1.get(): 1 at SingleSuspensionTraceReportingTest.suspendAndCauseFailure(MultipleSuspensionsTests.kt:123) | | | continuation1.WRITE() at SingleSuspensionTraceReportingTest.suspendAndCauseFailure(MultipleSuspensionsTests.kt:126) | diff --git a/src/jvm/test/resources/expected_logs/suspend_trace_reporting.txt b/src/jvm/test/resources/expected_logs/suspend_trace_reporting.txt index 729d3dc27..277b43d7f 100644 --- a/src/jvm/test/resources/expected_logs/suspend_trace_reporting.txt +++ b/src/jvm/test/resources/expected_logs/suspend_trace_reporting.txt @@ -10,18 +10,18 @@ The following interleaving leads to the error: | Thread 1 | Thread 2 | | ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | | | bar(): -1 | -| | barStarted.WRITE(true) at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:38) | -| | lock.lock(null): Unit#1 at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:130) | -| | counter.READ: 0 at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:40) | -| | counter.WRITE(1) at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:40) | -| | lock.unlock(null) at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:134) | +| | barStarted.WRITE(true) at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:37) | +| | lock.lock(null): Unit#1 at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:193) | +| | counter.READ: 0 at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:39) | +| | counter.WRITE(1) at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:39) | +| | lock.unlock(null) at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:197) | | | isLocked(): true at MutexImpl.unlock(Mutex.kt:213) | | | owner.get(): null at MutexImpl.unlock(Mutex.kt:215) | | | switch | | foo() | | -| barStarted.READ: true at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:29) | | -| canEnterForbiddenBlock.WRITE(true) at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:29) | | -| lock.lock(null): COROUTINE_SUSPENDED at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:120) | | +| barStarted.READ: true at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:28) | | +| canEnterForbiddenBlock.WRITE(true) at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:28) | | +| lock.lock(null): COROUTINE_SUSPENDED at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:183) | | | MutexImpl.lock$suspendImpl(MutexImpl#1,null,): COROUTINE_SUSPENDED at MutexImpl.lock(Mutex.kt:0) | | | SuspendTraceReportingTest#1.lock.tryLock(null): false at MutexImpl.lock$suspendImpl(Mutex.kt:171) | | | SuspendTraceReportingTest#1.lock.lockSuspend(null): COROUTINE_SUSPENDED at MutexImpl.lock$suspendImpl(Mutex.kt:172) | | @@ -30,15 +30,15 @@ The following interleaving leads to the error: | trySuspend(): true at CancellableContinuationImpl.getResult(CancellableContinuationImpl.kt:300) | | | getParentHandle(): null at CancellableContinuationImpl.getResult(CancellableContinuationImpl.kt:310) | | | installParentHandle(): ChildContinuation#1 at CancellableContinuationImpl.getResult(CancellableContinuationImpl.kt:311) | | -| switch (reason: coroutine is suspended) | | +| switch (reason: coroutine is suspended) | | | | owner.compareAndSet(null,): true at MutexImpl.unlock(Mutex.kt:220) | | | release() at MutexImpl.unlock(Mutex.kt:222) | -| | canEnterForbiddenBlock.READ: true at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:42) | +| | canEnterForbiddenBlock.READ: true at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:41) | | | result: -1 | -| counter.READ: 1 at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:31) | | -| counter.WRITE(2) at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:31) | | -| lock.unlock(null) at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:124) | | -| canEnterForbiddenBlock.WRITE(false) at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:33) | | +| counter.READ: 1 at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:30) | | +| counter.WRITE(2) at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:30) | | +| lock.unlock(null) at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:187) | | +| canEnterForbiddenBlock.WRITE(false) at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:32) | | | result: void | | | ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | @@ -47,8 +47,8 @@ Detailed trace: | Thread 1 | Thread 2 | | ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | | | bar(): -1 | -| | barStarted.WRITE(true) at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:38) | -| | lock.lock(null): Unit#1 at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:130) | +| | barStarted.WRITE(true) at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:37) | +| | lock.lock(null): Unit#1 at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:193) | | | MutexImpl.lock$suspendImpl(MutexImpl#1,null,): Unit#1 at MutexImpl.lock(Mutex.kt:0) | | | SuspendTraceReportingTest#1.lock.tryLock(null): true at MutexImpl.lock$suspendImpl(Mutex.kt:171) | | | tryLockImpl(null): 0 at MutexImpl.tryLock(Mutex.kt:183) | @@ -57,18 +57,18 @@ Detailed trace: | | _availablePermits.compareAndSet(1,0): true at SemaphoreImpl.tryAcquire(Semaphore.kt:171) | | | owner.get(): at MutexImpl.tryLockImpl(Mutex.kt:190) | | | owner.set(null) at MutexImpl.tryLockImpl(Mutex.kt:191) | -| | counter.READ: 0 at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:40) | -| | counter.WRITE(1) at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:40) | -| | lock.unlock(null) at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:134) | +| | counter.READ: 0 at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:39) | +| | counter.WRITE(1) at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:39) | +| | lock.unlock(null) at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:197) | | | isLocked(): true at MutexImpl.unlock(Mutex.kt:213) | | | getAvailablePermits(): 0 at MutexImpl.isLocked(Mutex.kt:149) | | | _availablePermits.get(): 0 at SemaphoreImpl.getAvailablePermits(Semaphore.kt:152) | | | owner.get(): null at MutexImpl.unlock(Mutex.kt:215) | | | switch | | foo() | | -| barStarted.READ: true at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:29) | | -| canEnterForbiddenBlock.WRITE(true) at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:29) | | -| lock.lock(null): COROUTINE_SUSPENDED at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:120) | | +| barStarted.READ: true at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:28) | | +| canEnterForbiddenBlock.WRITE(true) at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:28) | | +| lock.lock(null): COROUTINE_SUSPENDED at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:183) | | | MutexImpl.lock$suspendImpl(MutexImpl#1,null,): COROUTINE_SUSPENDED at MutexImpl.lock(Mutex.kt:0) | | | SuspendTraceReportingTest#1.lock.tryLock(null): false at MutexImpl.lock$suspendImpl(Mutex.kt:171) | | | tryLockImpl(null): 1 at MutexImpl.tryLock(Mutex.kt:183) | | @@ -101,7 +101,7 @@ Detailed trace: | _parentHandle.get(): null at CancellableContinuationImpl.getParentHandle(CancellableContinuationImpl.kt:106) | | | installParentHandle(): ChildContinuation#1 at CancellableContinuationImpl.getResult(CancellableContinuationImpl.kt:311) | | | _parentHandle.compareAndSet(null,ChildContinuation#1): true at CancellableContinuationImpl.installParentHandle(CancellableContinuationImpl.kt:352) | | -| switch (reason: coroutine is suspended) | | +| switch (reason: coroutine is suspended) | | | | owner.compareAndSet(null,): true at MutexImpl.unlock(Mutex.kt:220) | | | release() at MutexImpl.unlock(Mutex.kt:222) | | | _availablePermits.getAndIncrement(): -1 at SemaphoreImpl.release(Semaphore.kt:250) | @@ -140,11 +140,11 @@ Detailed trace: | | .takeState$kotlinx_coroutines_core(): CompletedContinuation#1 at DispatchedTaskKt.resume(DispatchedTask.kt:174) | | | getState$kotlinx_coroutines_core(): CompletedContinuation#1 at CancellableContinuationImpl.takeState$kotlinx_coroutines_core(CancellableContinuationImpl.kt:168) | | | _state.get(): CompletedContinuation#1 at CancellableContinuationImpl.getState$kotlinx_coroutines_core(CancellableContinuationImpl.kt:108) | -| | canEnterForbiddenBlock.READ: true at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:42) | +| | canEnterForbiddenBlock.READ: true at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:41) | | | result: -1 | -| counter.READ: 1 at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:31) | | -| counter.WRITE(2) at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:31) | | -| lock.unlock(null) at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:124) | | +| counter.READ: 1 at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:30) | | +| counter.WRITE(2) at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:30) | | +| lock.unlock(null) at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:187) | | | isLocked(): true at MutexImpl.unlock(Mutex.kt:213) | | | getAvailablePermits(): 0 at MutexImpl.isLocked(Mutex.kt:149) | | | _availablePermits.get(): 0 at SemaphoreImpl.getAvailablePermits(Semaphore.kt:152) | | @@ -152,6 +152,6 @@ Detailed trace: | owner.compareAndSet(null,): true at MutexImpl.unlock(Mutex.kt:220) | | | release() at MutexImpl.unlock(Mutex.kt:222) | | | _availablePermits.getAndIncrement(): 0 at SemaphoreImpl.release(Semaphore.kt:250) | | -| canEnterForbiddenBlock.WRITE(false) at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:33) | | +| canEnterForbiddenBlock.WRITE(false) at SuspendTraceReportingTest.foo(SuspendTraceReportingTest.kt:32) | | | result: void | | | ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | diff --git a/src/jvm/test/resources/expected_logs/suspend_trace_resumption_frame_skipping_reporting_test.txt b/src/jvm/test/resources/expected_logs/suspend_trace_resumption_frame_skipping_reporting_test.txt index 7c734e81a..53a7648cf 100644 --- a/src/jvm/test/resources/expected_logs/suspend_trace_resumption_frame_skipping_reporting_test.txt +++ b/src/jvm/test/resources/expected_logs/suspend_trace_resumption_frame_skipping_reporting_test.txt @@ -28,7 +28,7 @@ The following interleaving leads to the error: | .getOrThrow(): COROUTINE_SUSPENDED at SuspendTraceResumptionFrameSkippingReportingTest.function3(SuspendTraceReportingTest.kt:160) | | | result.READ: UNDECIDED at SafeContinuation.getOrThrow(SafeContinuationJvm.kt:51) | | | result.compareAndSet(UNDECIDED,COROUTINE_SUSPENDED): true at SafeContinuation.getOrThrow(SafeContinuationJvm.kt:53) | | -| switch (reason: coroutine is suspended) | | +| switch (reason: coroutine is suspended) | | | | continuation.READ: at SuspendTraceResumptionFrameSkippingReportingTest.bar(SuspendTraceReportingTest.kt:140) | | | continuation.READ: at SuspendTraceResumptionFrameSkippingReportingTest.bar(SuspendTraceReportingTest.kt:141) | | | .resumeWith(Unit#1) at SuspendTraceResumptionFrameSkippingReportingTest.bar(SuspendTraceReportingTest.kt:141) | @@ -63,7 +63,7 @@ Detailed trace: | .getOrThrow(): COROUTINE_SUSPENDED at SuspendTraceResumptionFrameSkippingReportingTest.function3(SuspendTraceReportingTest.kt:160) | | | result.READ: UNDECIDED at SafeContinuation.getOrThrow(SafeContinuationJvm.kt:51) | | | result.compareAndSet(UNDECIDED,COROUTINE_SUSPENDED): true at SafeContinuation.getOrThrow(SafeContinuationJvm.kt:53) | | -| switch (reason: coroutine is suspended) | | +| switch (reason: coroutine is suspended) | | | | continuation.READ: at SuspendTraceResumptionFrameSkippingReportingTest.bar(SuspendTraceReportingTest.kt:140) | | | continuation.READ: at SuspendTraceResumptionFrameSkippingReportingTest.bar(SuspendTraceReportingTest.kt:141) | | | .resumeWith(Unit#1) at SuspendTraceResumptionFrameSkippingReportingTest.bar(SuspendTraceReportingTest.kt:141) | diff --git a/src/jvm/test/resources/expected_logs/suspend_trace_resumption_reporting_test.txt b/src/jvm/test/resources/expected_logs/suspend_trace_resumption_reporting_test.txt index d704efd57..c5af2227e 100644 --- a/src/jvm/test/resources/expected_logs/suspend_trace_resumption_reporting_test.txt +++ b/src/jvm/test/resources/expected_logs/suspend_trace_resumption_reporting_test.txt @@ -28,7 +28,7 @@ The following interleaving leads to the error: | .getOrThrow(): COROUTINE_SUSPENDED at SuspendTraceResumptionReportingTest.function3(SuspendTraceReportingTest.kt:98) | | | result.READ: UNDECIDED at SafeContinuation.getOrThrow(SafeContinuationJvm.kt:51) | | | result.compareAndSet(UNDECIDED,COROUTINE_SUSPENDED): true at SafeContinuation.getOrThrow(SafeContinuationJvm.kt:53) | | -| switch (reason: coroutine is suspended) | | +| switch (reason: coroutine is suspended) | | | | continuation.READ: at SuspendTraceResumptionReportingTest.bar(SuspendTraceReportingTest.kt:77) | | | continuation.READ: at SuspendTraceResumptionReportingTest.bar(SuspendTraceReportingTest.kt:78) | | | .resumeWith(Unit#1) at SuspendTraceResumptionReportingTest.bar(SuspendTraceReportingTest.kt:78) | @@ -67,7 +67,7 @@ Detailed trace: | .getOrThrow(): COROUTINE_SUSPENDED at SuspendTraceResumptionReportingTest.function3(SuspendTraceReportingTest.kt:98) | | | result.READ: UNDECIDED at SafeContinuation.getOrThrow(SafeContinuationJvm.kt:51) | | | result.compareAndSet(UNDECIDED,COROUTINE_SUSPENDED): true at SafeContinuation.getOrThrow(SafeContinuationJvm.kt:53) | | -| switch (reason: coroutine is suspended) | | +| switch (reason: coroutine is suspended) | | | | continuation.READ: at SuspendTraceResumptionReportingTest.bar(SuspendTraceReportingTest.kt:77) | | | continuation.READ: at SuspendTraceResumptionReportingTest.bar(SuspendTraceReportingTest.kt:78) | | | .resumeWith(Unit#1) at SuspendTraceResumptionReportingTest.bar(SuspendTraceReportingTest.kt:78) | diff --git a/src/jvm/test/resources/expected_logs/suspended_not_awoke.txt b/src/jvm/test/resources/expected_logs/suspended_not_awoke.txt index 20cbc4be8..37b6ff164 100644 --- a/src/jvm/test/resources/expected_logs/suspended_not_awoke.txt +++ b/src/jvm/test/resources/expected_logs/suspended_not_awoke.txt @@ -27,8 +27,7 @@ The following interleaving leads to the error: | | trySuspend(): true at CancellableContinuationImpl.getResult(CancellableContinuationImpl.kt:300) | | | getParentHandle(): null at CancellableContinuationImpl.getResult(CancellableContinuationImpl.kt:310) | | | installParentHandle(): ChildContinuation#1 at CancellableContinuationImpl.getResult(CancellableContinuationImpl.kt:311) | -| | _parentHandle.compareAndSet(null,ChildContinuation#1): true at CancellableContinuationImpl.installParentHandle(CancellableContinuationImpl.kt:352) | -| | switch (reason: coroutine is suspended) | +| | switch (reason: coroutine is suspended) | | | result: Suspended | | allowed.WRITE(false) at SuspendedNotAwokeTest.trigger(SuspendedNotAwokeTest.kt:32) | | | result: void | | @@ -82,7 +81,7 @@ Detailed trace: | | _parentHandle.get(): null at CancellableContinuationImpl.getParentHandle(CancellableContinuationImpl.kt:106) | | | installParentHandle(): ChildContinuation#1 at CancellableContinuationImpl.getResult(CancellableContinuationImpl.kt:311) | | | _parentHandle.compareAndSet(null,ChildContinuation#1): true at CancellableContinuationImpl.installParentHandle(CancellableContinuationImpl.kt:352) | -| | switch (reason: coroutine is suspended) | +| | switch (reason: coroutine is suspended) | | | result: Suspended | | allowed.WRITE(false) at SuspendedNotAwokeTest.trigger(SuspendedNotAwokeTest.kt:32) | | | result: void | | From fc1efc0beabefcec0ffdb9dd197e441c41189dcd Mon Sep 17 00:00:00 2001 From: Evgeniy Moiseenko Date: Thu, 26 Dec 2024 17:27:16 +0100 Subject: [PATCH 3/8] fix multiple suspension points trace Signed-off-by: Evgeniy Moiseenko --- .../strategy/managed/ManagedStrategy.kt | 18 +++-- .../MultipleSuspensionsTests.kt | 17 ++-- .../two_suspension_points_bug.txt | 78 +++++++++---------- 3 files changed, 61 insertions(+), 52 deletions(-) diff --git a/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt b/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt index 48df065aa..4b54395d4 100644 --- a/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt +++ b/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt @@ -970,6 +970,10 @@ abstract class ManagedStrategy( params: Array ) { val guarantee = runInIgnoredSection { + val iThread = currentThread + val suspendedMethodStack = suspendedFunctionsStack[iThread] + val isSuspending = isSuspendFunction(className, methodName, params) + val isResumption = isSuspending && suspendedMethodStack.isNotEmpty() val atomicMethodDescriptor = getAtomicMethodDescriptor(owner, methodName) val guarantee = when { (atomicMethodDescriptor != null) -> ManagedGuaranteeType.TREAT_AS_ATOMIC @@ -980,9 +984,13 @@ abstract class ManagedStrategy( } if (collectTrace) { traceCollector!!.checkActiveLockDetected() - addBeforeMethodCallTracePoint(owner, codeLocation, methodId, className, methodName, params, atomicMethodDescriptor) + addBeforeMethodCallTracePoint(iThread, owner, codeLocation, methodId, className, methodName, params, + atomicMethodDescriptor = atomicMethodDescriptor, + isSuspending = isSuspending, + isResumption = isResumption, + ) } - if (guarantee == ManagedGuaranteeType.TREAT_AS_ATOMIC) { + if (guarantee == ManagedGuaranteeType.TREAT_AS_ATOMIC && !isResumption) { newSwitchPointOnAtomicMethodCall(codeLocation, params) } if (guarantee == null) { @@ -1124,6 +1132,7 @@ abstract class ManagedStrategy( } private fun addBeforeMethodCallTracePoint( + iThread: Int, owner: Any?, codeLocation: Int, methodId: Int, @@ -1131,12 +1140,11 @@ abstract class ManagedStrategy( methodName: String, methodParams: Array, atomicMethodDescriptor: AtomicMethodDescriptor?, + isSuspending: Boolean, + isResumption: Boolean, ) { - val iThread = currentThread val callStackTrace = callStackTrace[iThread] val suspendedMethodStack = suspendedFunctionsStack[iThread] - val isSuspending = isSuspendFunction(className, methodName, methodParams) - val isResumption = isSuspending && suspendedMethodStack.isNotEmpty() if (isResumption) { // In case of resumption, we need to find a call stack frame corresponding to the resumed function var elementIndex = suspendedMethodStack.indexOfFirst { diff --git a/src/jvm/test/org/jetbrains/kotlinx/lincheck_test/representation/MultipleSuspensionsTests.kt b/src/jvm/test/org/jetbrains/kotlinx/lincheck_test/representation/MultipleSuspensionsTests.kt index 25315fa39..6b5488a74 100644 --- a/src/jvm/test/org/jetbrains/kotlinx/lincheck_test/representation/MultipleSuspensionsTests.kt +++ b/src/jvm/test/org/jetbrains/kotlinx/lincheck_test/representation/MultipleSuspensionsTests.kt @@ -63,16 +63,16 @@ class MultipleSuspensionTest { return 1 } - private suspend fun part2(): Boolean { - if (counter.get() == 1) { - suspendCoroutine { continuation2 = it } + private suspend fun part1(): Boolean { + if (counter.get() == 0) { + suspendCoroutine { continuation1 = it } } else return true return false } - private suspend fun part1(): Boolean { - if (counter.get() == 0) { - suspendCoroutine { continuation1 = it } + private suspend fun part2(): Boolean { + if (counter.get() == 1) { + suspendCoroutine { continuation2 = it } } else return true return false } @@ -85,7 +85,10 @@ class MultipleSuspensionTest { thread { actor(::operation) } } } - .addGuarantee(forClasses(this::class.java.name).methods("firstStep", "secondStep", "part1", "part2").treatAsAtomic()) + .addGuarantee( + forClasses(this::class.java.name).methods("firstStep", "secondStep", "part1", "part2") + .treatAsAtomic() + ) .checkImpl(this::class.java) .checkLincheckOutput("two_suspension_points_bug.txt") diff --git a/src/jvm/test/resources/expected_logs/two_suspension_points_bug.txt b/src/jvm/test/resources/expected_logs/two_suspension_points_bug.txt index 98d40363a..558e11d65 100644 --- a/src/jvm/test/resources/expected_logs/two_suspension_points_bug.txt +++ b/src/jvm/test/resources/expected_logs/two_suspension_points_bug.txt @@ -6,45 +6,43 @@ | -------------------------------- | The following interleaving leads to the error: -| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | -| Thread 1 | Thread 2 | -| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | -| | operation(): 1 | -| | part1(): COROUTINE_SUSPENDED at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:56) | -| | switch (reason: coroutine is suspended) | -| trigger() | | -| firstStep() at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:39) | | -| switch | | -| | operation(): COROUTINE_SUSPENDED at MultipleSuspensionTest$operation$1.invokeSuspend(MultipleSuspensionsTests.kt:0) | -| | part2(): COROUTINE_SUSPENDED at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:57) | -| | switch (reason: coroutine is suspended) | -| secondStep() at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:40) | | -| counter.READ: AtomicInteger#1 at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:41) | | -| AtomicInteger#1.set(3) at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:41) | | -| result: void | | -| | counter.READ: AtomicInteger#1 at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:58) | -| | AtomicInteger#1.get(): 3 at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:58) | -| | result: 1 | -| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| Thread 1 | Thread 2 | +| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| | operation(): 1 | +| | part1(): false at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:60) | +| | switch (reason: coroutine is suspended) | +| trigger() | | +| firstStep() at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:43) | | +| switch | | +| | part2(): false at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:61) | +| | switch (reason: coroutine is suspended) | +| secondStep() at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:44) | | +| counter.READ: AtomicInteger#1 at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:45) | | +| AtomicInteger#1.set(3) at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:45) | | +| result: void | | +| | counter.READ: AtomicInteger#1 at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:62) | +| | AtomicInteger#1.get(): 3 at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:62) | +| | result: 1 | +| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | Detailed trace: -| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | -| Thread 1 | Thread 2 | -| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | -| | operation(): 1 | -| | part1(): COROUTINE_SUSPENDED at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:56) | -| | switch (reason: coroutine is suspended) | -| trigger() | | -| firstStep() at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:39) | | -| switch | | -| | operation(): COROUTINE_SUSPENDED at MultipleSuspensionTest$operation$1.invokeSuspend(MultipleSuspensionsTests.kt:0) | -| | part2(): COROUTINE_SUSPENDED at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:57) | -| | switch (reason: coroutine is suspended) | -| secondStep() at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:40) | | -| counter.READ: AtomicInteger#1 at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:41) | | -| AtomicInteger#1.set(3) at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:41) | | -| result: void | | -| | counter.READ: AtomicInteger#1 at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:58) | -| | AtomicInteger#1.get(): 3 at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:58) | -| | result: 1 | -| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| Thread 1 | Thread 2 | +| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| | operation(): 1 | +| | part1(): false at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:60) | +| | switch (reason: coroutine is suspended) | +| trigger() | | +| firstStep() at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:43) | | +| switch | | +| | part2(): false at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:61) | +| | switch (reason: coroutine is suspended) | +| secondStep() at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:44) | | +| counter.READ: AtomicInteger#1 at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:45) | | +| AtomicInteger#1.set(3) at MultipleSuspensionTest.trigger(MultipleSuspensionsTests.kt:45) | | +| result: void | | +| | counter.READ: AtomicInteger#1 at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:62) | +| | AtomicInteger#1.get(): 3 at MultipleSuspensionTest.operation(MultipleSuspensionsTests.kt:62) | +| | result: 1 | +| ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | From 2365c3b1403ca7436f16f950847e688bba7d67e8 Mon Sep 17 00:00:00 2001 From: Evgeniy Moiseenko Date: Thu, 26 Dec 2024 17:28:01 +0100 Subject: [PATCH 4/8] optimize `isSuspendFunction` check Signed-off-by: Evgeniy Moiseenko --- .../lincheck/strategy/managed/ManagedStrategy.kt | 16 +++++++++++----- 1 file changed, 11 insertions(+), 5 deletions(-) diff --git a/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt b/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt index 4b54395d4..1c35c9a83 100644 --- a/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt +++ b/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt @@ -30,6 +30,7 @@ import org.jetbrains.kotlinx.lincheck.strategy.managed.UnsafeName.* import org.jetbrains.kotlinx.lincheck.strategy.managed.VarHandleMethodType.* import java.lang.reflect.* import java.util.* +import kotlin.coroutines.Continuation import kotlin.coroutines.intrinsics.COROUTINE_SUSPENDED /** @@ -1060,15 +1061,20 @@ abstract class ManagedStrategy( loopDetector.passParameters(params) } - private fun isSuspendFunction(className: String, methodName: String, params: Array): Boolean = - try { - // While this code is inefficient, it is called only when an error is detected. - getMethod(className.canonicalClassName, methodName, params)?.isSuspendable() ?: false - } catch (t: Throwable) { + private fun isSuspendFunction(className: String, methodName: String, params: Array): Boolean { + // fast-path: if the last parameter is not continuation - then this is not suspending function + if (params.lastOrNull() !is Continuation<*>) return false + val result = runCatching { + // While this code is inefficient, it is called only on the slow path. + val method = getMethod(className.canonicalClassName, methodName, params) + method?.isSuspendable() == true + } + return result.getOrElse { // Something went wrong. Ignore it, as the error might lead only // to an extra "" in the method call line in the trace. false } + } private fun getMethod(className: String, methodName: String, params: Array): Method? { val clazz = Class.forName(className) From 4a6b1cc366d14e40a470962ed6b59460d3cc66bd Mon Sep 17 00:00:00 2001 From: Evgeniy Moiseenko Date: Thu, 26 Dec 2024 18:01:55 +0100 Subject: [PATCH 5/8] move utils functions from `ManagedStrategy` to `utils` subpackage Signed-off-by: Evgeniy Moiseenko --- .../strategy/managed/ManagedStrategy.kt | 45 +----------- .../kotlinx/lincheck/util/Reflection.kt | 70 +++++++++++++++++++ 2 files changed, 72 insertions(+), 43 deletions(-) create mode 100644 src/jvm/main/org/jetbrains/kotlinx/lincheck/util/Reflection.kt diff --git a/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt b/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt index 1c35c9a83..f1b67d0fa 100644 --- a/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt +++ b/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt @@ -30,7 +30,6 @@ import org.jetbrains.kotlinx.lincheck.strategy.managed.UnsafeName.* import org.jetbrains.kotlinx.lincheck.strategy.managed.VarHandleMethodType.* import java.lang.reflect.* import java.util.* -import kotlin.coroutines.Continuation import kotlin.coroutines.intrinsics.COROUTINE_SUSPENDED /** @@ -973,12 +972,12 @@ abstract class ManagedStrategy( val guarantee = runInIgnoredSection { val iThread = currentThread val suspendedMethodStack = suspendedFunctionsStack[iThread] - val isSuspending = isSuspendFunction(className, methodName, params) + val isSuspending = isSuspendFunction(className.canonicalClassName, methodName, params) val isResumption = isSuspending && suspendedMethodStack.isNotEmpty() val atomicMethodDescriptor = getAtomicMethodDescriptor(owner, methodName) val guarantee = when { (atomicMethodDescriptor != null) -> ManagedGuaranteeType.TREAT_AS_ATOMIC - else -> methodGuaranteeType(owner, className, methodName) + else -> methodGuaranteeType(owner, className.canonicalClassName, methodName) } if (owner == null && atomicMethodDescriptor == null && guarantee == null) { // static method LincheckJavaAgent.ensureClassHierarchyIsTransformed(className.canonicalClassName) @@ -1061,46 +1060,6 @@ abstract class ManagedStrategy( loopDetector.passParameters(params) } - private fun isSuspendFunction(className: String, methodName: String, params: Array): Boolean { - // fast-path: if the last parameter is not continuation - then this is not suspending function - if (params.lastOrNull() !is Continuation<*>) return false - val result = runCatching { - // While this code is inefficient, it is called only on the slow path. - val method = getMethod(className.canonicalClassName, methodName, params) - method?.isSuspendable() == true - } - return result.getOrElse { - // Something went wrong. Ignore it, as the error might lead only - // to an extra "" in the method call line in the trace. - false - } - } - - private fun getMethod(className: String, methodName: String, params: Array): Method? { - val clazz = Class.forName(className) - - // Filter methods by name - val possibleMethods = clazz.declaredMethods.filter { it.name == methodName } - - for (method in possibleMethods) { - val parameterTypes = method.parameterTypes - if (parameterTypes.size != params.size) continue - - var match = true - for (i in parameterTypes.indices) { - val paramType = params[i]?.javaClass - if (paramType != null && !parameterTypes[i].isAssignableFrom(paramType)) { - match = false - break - } - } - - if (match) return method - } - - return null // or throw an exception if a match is mandatory - } - /** * This method is invoked by a test thread * if a coroutine was suspended. diff --git a/src/jvm/main/org/jetbrains/kotlinx/lincheck/util/Reflection.kt b/src/jvm/main/org/jetbrains/kotlinx/lincheck/util/Reflection.kt new file mode 100644 index 000000000..c763411cd --- /dev/null +++ b/src/jvm/main/org/jetbrains/kotlinx/lincheck/util/Reflection.kt @@ -0,0 +1,70 @@ +/* + * Lincheck + * + * Copyright (C) 2019 - 2024 JetBrains s.r.o. + * + * This Source Code Form is subject to the terms of the + * Mozilla Public License, v. 2.0. If a copy of the MPL was not distributed + * with this file, You can obtain one at http://mozilla.org/MPL/2.0/. + */ + +package org.jetbrains.kotlinx.lincheck.util + +import org.jetbrains.kotlinx.lincheck.isSuspendable +import kotlin.coroutines.Continuation +import java.lang.reflect.Method + + +/** + * Determines whether a given method is a suspending function. + * + * @param className The name of the class containing the method. + * @param methodName The name of the method to check. + * @param params An array of parameters passed to the method used to infer the method signature. + * @return `true` if the method is a suspending function; `false` otherwise. + */ +internal fun isSuspendFunction(className: String, methodName: String, params: Array): Boolean { + // fast-path: if the last parameter is not continuation - then this is not suspending function + if (params.lastOrNull() !is Continuation<*>) return false + val result = runCatching { + // While this code is inefficient, it is called only on the slow path. + val method = getMethod(className, methodName, params) + method?.isSuspendable() == true + } + return result.getOrElse { + // Something went wrong. Ignore it, as the error might lead only + // to an extra "" in the method call line in the trace. + false + } +} + +/** + * Retrieves a `Method` object representing a method of the specified name and parameter types. + * + * @param className The name of the class containing the method. + * @param methodName The name of the method to retrieve. + * @param params An array of parameters to match against the method's parameter types. + * The method is selected if its parameter types are compatible + * with the runtime classes of the elements in this array. + * @return The matching [Method] object if found, or `null` if no method matches. + */ +internal fun getMethod(className: String, methodName: String, params: Array): Method? { + val clazz = Class.forName(className) + // filter methods by name + val possibleMethods = clazz.declaredMethods.filter { it.name == methodName } + // search through all possible methods, matching the arguments' types + for (method in possibleMethods) { + val parameterTypes = method.parameterTypes + if (parameterTypes.size != params.size) continue + var match = true + for (i in parameterTypes.indices) { + val paramType = params[i]?.javaClass + if (paramType != null && !parameterTypes[i].isAssignableFrom(paramType)) { + match = false + break + } + } + if (match) return method + } + return null // or throw an exception if a match is mandatory +} \ No newline at end of file From 13ffe5c91a24c5caceb6a8af2e6c97933937304a Mon Sep 17 00:00:00 2001 From: Evgeniy Moiseenko Date: Thu, 26 Dec 2024 18:30:28 +0100 Subject: [PATCH 6/8] fix Java 8 trace test output Signed-off-by: Evgeniy Moiseenko --- .../resources/expected_logs/suspend_trace_reporting_jdk8.txt | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/jvm/test/resources/expected_logs/suspend_trace_reporting_jdk8.txt b/src/jvm/test/resources/expected_logs/suspend_trace_reporting_jdk8.txt index bd7c9b215..a5a3f0397 100644 --- a/src/jvm/test/resources/expected_logs/suspend_trace_reporting_jdk8.txt +++ b/src/jvm/test/resources/expected_logs/suspend_trace_reporting_jdk8.txt @@ -30,7 +30,7 @@ The following interleaving leads to the error: | trySuspend(): true at CancellableContinuationImpl.getResult(CancellableContinuationImpl.kt:300) | | | getParentHandle(): null at CancellableContinuationImpl.getResult(CancellableContinuationImpl.kt:310) | | | installParentHandle(): ChildContinuation#1 at CancellableContinuationImpl.getResult(CancellableContinuationImpl.kt:311) | | -| switch (reason: coroutine is suspended) | | +| switch (reason: coroutine is suspended) | | | | owner.compareAndSet(null,): true at MutexImpl.unlock(Mutex.kt:220) | | | release() at MutexImpl.unlock(Mutex.kt:222) | | | canEnterForbiddenBlock.READ: true at SuspendTraceReportingTest.bar(SuspendTraceReportingTest.kt:41) | @@ -101,7 +101,7 @@ Detailed trace: | _parentHandle.get(): null at CancellableContinuationImpl.getParentHandle(CancellableContinuationImpl.kt:106) | | | installParentHandle(): ChildContinuation#1 at CancellableContinuationImpl.getResult(CancellableContinuationImpl.kt:311) | | | _parentHandle.compareAndSet(null,ChildContinuation#1): true at CancellableContinuationImpl.installParentHandle(CancellableContinuationImpl.kt:352) | | -| switch (reason: coroutine is suspended) | | +| switch (reason: coroutine is suspended) | | | | owner.compareAndSet(null,): true at MutexImpl.unlock(Mutex.kt:220) | | | release() at MutexImpl.unlock(Mutex.kt:222) | | | _availablePermits.getAndIncrement(): -1 at SemaphoreImpl.release(Semaphore.kt:250) | From f2ed0c7f49e4818f65b44df5f4a4f6afc5d89b99 Mon Sep 17 00:00:00 2001 From: Evgeniy Moiseenko Date: Thu, 26 Dec 2024 20:30:07 +0100 Subject: [PATCH 7/8] optimize `isResumption` check Signed-off-by: Evgeniy Moiseenko --- .../strategy/managed/ManagedStrategy.kt | 32 +++++++++++-------- 1 file changed, 19 insertions(+), 13 deletions(-) diff --git a/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt b/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt index f1b67d0fa..0f0500539 100644 --- a/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt +++ b/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt @@ -970,10 +970,7 @@ abstract class ManagedStrategy( params: Array ) { val guarantee = runInIgnoredSection { - val iThread = currentThread - val suspendedMethodStack = suspendedFunctionsStack[iThread] - val isSuspending = isSuspendFunction(className.canonicalClassName, methodName, params) - val isResumption = isSuspending && suspendedMethodStack.isNotEmpty() + val threadId = currentThread val atomicMethodDescriptor = getAtomicMethodDescriptor(owner, methodName) val guarantee = when { (atomicMethodDescriptor != null) -> ManagedGuaranteeType.TREAT_AS_ATOMIC @@ -984,13 +981,14 @@ abstract class ManagedStrategy( } if (collectTrace) { traceCollector!!.checkActiveLockDetected() - addBeforeMethodCallTracePoint(iThread, owner, codeLocation, methodId, className, methodName, params, - atomicMethodDescriptor = atomicMethodDescriptor, - isSuspending = isSuspending, - isResumption = isResumption, + addBeforeMethodCallTracePoint(threadId, owner, codeLocation, methodId, className, methodName, params, + atomicMethodDescriptor ) } - if (guarantee == ManagedGuaranteeType.TREAT_AS_ATOMIC && !isResumption) { + if (guarantee == ManagedGuaranteeType.TREAT_AS_ATOMIC && + // do not create a trace point on resumption + !isResumptionMethodCall(threadId, className.canonicalClassName, methodName, params) + ) { newSwitchPointOnAtomicMethodCall(codeLocation, params) } if (guarantee == null) { @@ -1060,6 +1058,16 @@ abstract class ManagedStrategy( loopDetector.passParameters(params) } + private fun isResumptionMethodCall( + threadId: Int, + className: String, + methodName: String, + methodParams: Array + ): Boolean { + val suspendedMethodStack = suspendedFunctionsStack[threadId] + return suspendedMethodStack.isNotEmpty() && isSuspendFunction(className, methodName, methodParams) + } + /** * This method is invoked by a test thread * if a coroutine was suspended. @@ -1105,12 +1113,10 @@ abstract class ManagedStrategy( methodName: String, methodParams: Array, atomicMethodDescriptor: AtomicMethodDescriptor?, - isSuspending: Boolean, - isResumption: Boolean, ) { val callStackTrace = callStackTrace[iThread] val suspendedMethodStack = suspendedFunctionsStack[iThread] - if (isResumption) { + if (isResumptionMethodCall(iThread, className.canonicalClassName, methodName, methodParams)) { // In case of resumption, we need to find a call stack frame corresponding to the resumed function var elementIndex = suspendedMethodStack.indexOfFirst { it.tracePoint.className == className && it.tracePoint.methodName == methodName @@ -1145,7 +1151,7 @@ abstract class ManagedStrategy( return } val callId = callStackTraceElementId++ - val params = if (isSuspending) { + val params = if (isSuspendFunction(className.canonicalClassName, methodName, methodParams)) { methodParams.dropLast(1).toTypedArray() } else { methodParams From bedea5a34a0cf6b652d56e572d2c3567d0236b77 Mon Sep 17 00:00:00 2001 From: Evgeniy Moiseenko Date: Thu, 26 Dec 2024 21:06:35 +0100 Subject: [PATCH 8/8] optimize `isResumption` check Signed-off-by: Evgeniy Moiseenko --- .../lincheck/strategy/managed/ManagedStrategy.kt | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt b/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt index 0f0500539..bdd775b58 100644 --- a/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt +++ b/src/jvm/main/org/jetbrains/kotlinx/lincheck/strategy/managed/ManagedStrategy.kt @@ -987,7 +987,7 @@ abstract class ManagedStrategy( } if (guarantee == ManagedGuaranteeType.TREAT_AS_ATOMIC && // do not create a trace point on resumption - !isResumptionMethodCall(threadId, className.canonicalClassName, methodName, params) + !isResumptionMethodCall(threadId, className.canonicalClassName, methodName, params, atomicMethodDescriptor) ) { newSwitchPointOnAtomicMethodCall(codeLocation, params) } @@ -1062,8 +1062,12 @@ abstract class ManagedStrategy( threadId: Int, className: String, methodName: String, - methodParams: Array + methodParams: Array, + atomicMethodDescriptor: AtomicMethodDescriptor?, ): Boolean { + // optimization - first quickly check if the method is atomics API method, + // in which case it cannot be suspended/resumed method + if (atomicMethodDescriptor != null) return false val suspendedMethodStack = suspendedFunctionsStack[threadId] return suspendedMethodStack.isNotEmpty() && isSuspendFunction(className, methodName, methodParams) } @@ -1116,7 +1120,7 @@ abstract class ManagedStrategy( ) { val callStackTrace = callStackTrace[iThread] val suspendedMethodStack = suspendedFunctionsStack[iThread] - if (isResumptionMethodCall(iThread, className.canonicalClassName, methodName, methodParams)) { + if (isResumptionMethodCall(iThread, className.canonicalClassName, methodName, methodParams, atomicMethodDescriptor)) { // In case of resumption, we need to find a call stack frame corresponding to the resumed function var elementIndex = suspendedMethodStack.indexOfFirst { it.tracePoint.className == className && it.tracePoint.methodName == methodName