diff --git a/src/index/CompressedRelation.cpp b/src/index/CompressedRelation.cpp index a575bf22d4..35c0a5b729 100644 --- a/src/index/CompressedRelation.cpp +++ b/src/index/CompressedRelation.cpp @@ -392,7 +392,7 @@ IdTable CompressedRelationReader::scan( // block in parallel #pragma omp task { - if (!cancellationHandle->isCancelled()) { + if (!cancellationHandle->isCancelled("CompressedRelation scan")) { decompressLambda(); } } diff --git a/src/util/CancellationHandle.cpp b/src/util/CancellationHandle.cpp index 277790f350..f17e2b5c26 100644 --- a/src/util/CancellationHandle.cpp +++ b/src/util/CancellationHandle.cpp @@ -36,10 +36,13 @@ void CancellationHandle::startWatchDogInternal() requires WatchDogEnabled cancellationState_.compare_exchange_strong(state, WAITING_FOR_CHECK, std::memory_order_relaxed); } else if (state == WAITING_FOR_CHECK) { - if (cancellationState_.compare_exchange_strong( - state, CHECK_WINDOW_MISSED, std::memory_order_relaxed)) { - startTimeoutWindow_ = steady_clock::now(); - } + // This variable needs to be set before compare exchange, + // otherwise another thread might read an old value before + // the new value is set. This might lead to redundant stores, + // which is acceptable here. + startTimeoutWindow_ = steady_clock::now(); + cancellationState_.compare_exchange_strong(state, CHECK_WINDOW_MISSED, + std::memory_order_relaxed); } } while (!watchDogState_.conditionVariable_.wait_for( lock, DESIRED_CANCELLATION_CHECK_INTERVAL, diff --git a/src/util/CancellationHandle.h b/src/util/CancellationHandle.h index 0ad2a75001..79fe48879a 100644 --- a/src/util/CancellationHandle.h +++ b/src/util/CancellationHandle.h @@ -121,6 +121,8 @@ class CancellationHandle { /// Make sure internal state is set back to /// `CancellationState::NOT_CANCELLED`, in order to prevent logging warnings /// in the console that would otherwise be triggered by the watchdog. + /// NOTE: The parameter state is expected to be one of `CHECK_WINDOW_MISSED` + /// or `WAITING_FOR_CHECK`, otherwise it will violate the correctness check. template void pleaseWatchDog(CancellationState state, const InvocableWithConvertibleReturnType< @@ -128,20 +130,35 @@ class CancellationHandle { ArgTypes&&... argTypes) requires WatchDogEnabled { using DurationType = std::remove_const_t; + AD_CORRECTNESS_CHECK(!detail::isCancelled(state) && + state != CancellationState::NOT_CANCELLED); - if (state == CancellationState::CHECK_WINDOW_MISSED) { - LOG(WARN) << "Cancellation check missed deadline of " - << ParseableDuration{DESIRED_CANCELLATION_CHECK_INTERVAL} - << " by " - << ParseableDuration{duration_cast( - steady_clock::now() - startTimeoutWindow_.load())} - << ". Stage: " - << std::invoke(detailSupplier, AD_FWD(argTypes)...) - << std::endl; - } - - cancellationState_.compare_exchange_strong( - state, CancellationState::NOT_CANCELLED, std::memory_order_relaxed); + bool windowMissed = state == CancellationState::CHECK_WINDOW_MISSED; + // Because we know `state` will be one of `CHECK_WINDOW_MISSED` or + // `WAITING_FOR_CHECK` at this point, we can skip the initial check. + do { + if (cancellationState_.compare_exchange_weak( + state, CancellationState::NOT_CANCELLED, + std::memory_order_relaxed)) { + if (windowMissed) { + LOG(WARN) << "The time since the last timeout check is at least " + << ParseableDuration{duration_cast( + steady_clock::now() - + startTimeoutWindow_.load()) + + DESIRED_CANCELLATION_CHECK_INTERVAL} + << ", should be at most " + << ParseableDuration{DESIRED_CANCELLATION_CHECK_INTERVAL} + << ". Stage: " + << std::invoke(detailSupplier, AD_FWD(argTypes)...) + << std::endl; + } + break; + } + // If state is NOT_CANCELLED this means another thread already reported + // the missed deadline, so we don't report a second time or a cancellation + // kicked in and there is no need to continue the loop. + } while (!detail::isCancelled(state) && + state != CancellationState::NOT_CANCELLED); } /// Internal function that starts the watch dog. It will set this @@ -196,12 +213,18 @@ class CancellationHandle { /// Return true if this cancellation handle has been cancelled, false /// otherwise. Note: Make sure to not use this value to set any other atomic /// value with relaxed memory ordering, as this may lead to out-of-thin-air - /// values. It also does not interact with the watchdog at all, prefer - /// `throwIfCancelled` if possible. - AD_ALWAYS_INLINE bool isCancelled() const { + /// values. If the watchdog is enabled, this will please it and print + /// a warning with the passed detail string. + AD_ALWAYS_INLINE bool isCancelled(std::string_view details) { if constexpr (CancellationEnabled) { - return detail::isCancelled( - cancellationState_.load(std::memory_order_relaxed)); + auto state = cancellationState_.load(std::memory_order_relaxed); + bool isCancelled = detail::isCancelled(state); + if constexpr (WatchDogEnabled) { + if (!isCancelled && state != CancellationState::NOT_CANCELLED) { + pleaseWatchDog(state, std::identity{}, details); + } + } + return isCancelled; } else { return false; } @@ -234,6 +257,10 @@ class CancellationHandle { FRIEND_TEST(CancellationHandle, verifyCheckAfterDeadlineMissDoesReportProperly); FRIEND_TEST(CancellationHandle, verifyWatchDogDoesNotChangeStateAfterCancel); + FRIEND_TEST(CancellationHandle, verifyPleaseWatchDogReportsOnlyWhenNecessary); + FRIEND_TEST(CancellationHandle, verifyIsCancelledDoesPleaseWatchDog); + FRIEND_TEST(CancellationHandle, + verifyPleaseWatchDogDoesNotAcceptInvalidState); }; using SharedCancellationHandle = std::shared_ptr>; diff --git a/test/CancellationHandleTest.cpp b/test/CancellationHandleTest.cpp index 8d3d170a05..7b0683dc62 100644 --- a/test/CancellationHandleTest.cpp +++ b/test/CancellationHandleTest.cpp @@ -48,7 +48,7 @@ TEST(CancellationHandle, verifyConstructorDoesNotAcceptNoReason) { TYPED_TEST(CancellationHandleFixture, verifyNotCancelledByDefault) { auto& handle = this->handle_; - EXPECT_FALSE(handle.isCancelled()); + EXPECT_FALSE(handle.isCancelled("")); EXPECT_NO_THROW(handle.throwIfCancelled("")); EXPECT_NO_THROW(handle.throwIfCancelled([]() { return ""; })); } @@ -70,7 +70,7 @@ TYPED_TEST(CancellationHandleFixture, verifyTimeoutCancellationWorks) { handle.cancel(TIMEOUT); auto timeoutMessageMatcher = AllOf(HasSubstr(detail), HasSubstr("timeout")); - EXPECT_TRUE(handle.isCancelled()); + EXPECT_TRUE(handle.isCancelled("")); AD_EXPECT_THROW_WITH_MESSAGE_AND_TYPE(handle.throwIfCancelled(detail), timeoutMessageMatcher, CancellationException); @@ -88,7 +88,7 @@ TYPED_TEST(CancellationHandleFixture, verifyManualCancellationWorks) { auto cancellationMessageMatcher = AllOf(HasSubstr(detail), HasSubstr("manual cancellation")); - EXPECT_TRUE(handle.isCancelled()); + EXPECT_TRUE(handle.isCancelled("")); AD_EXPECT_THROW_WITH_MESSAGE_AND_TYPE(handle.throwIfCancelled(detail), cancellationMessageMatcher, CancellationException); @@ -116,7 +116,7 @@ TYPED_TEST(CancellationHandleFixture, } }, CancellationException); - EXPECT_TRUE(handle.isCancelled()); + EXPECT_TRUE(handle.isCancelled("")); } // _____________________________________________________________________________ @@ -264,6 +264,8 @@ TEST(CancellationHandle, verifyCheckDoesNotOverrideCancelledState) { // _____________________________________________________________________________ TEST(CancellationHandle, verifyCheckAfterDeadlineMissDoesReportProperly) { + // If the log level is not high enough this test will fail + static_assert(LOGLEVEL >= WARN); auto& choice = ad_utility::LogstreamChoice::get(); CancellationHandle handle; @@ -284,7 +286,94 @@ TEST(CancellationHandle, verifyCheckAfterDeadlineMissDoesReportProperly) { HasSubstr(ParseableDuration{DESIRED_CANCELLATION_CHECK_INTERVAL} .toString()), // Check for small miss window - ContainsRegex("by [0-9]ms"))); + ContainsRegex("least 5[0-9]ms"))); + // This test assumes this interval to be 50ms to build the regex + static_assert(DESIRED_CANCELLATION_CHECK_INTERVAL == 50ms); +} + +// _____________________________________________________________________________ + +TEST(CancellationHandle, verifyPleaseWatchDogReportsOnlyWhenNecessary) { + // If the log level is not high enough this test will fail + static_assert(LOGLEVEL >= WARN); + auto& choice = ad_utility::LogstreamChoice::get(); + CancellationHandle handle; + + auto& originalOStream = choice.getStream(); + absl::Cleanup cleanup{[&]() { choice.setStream(&originalOStream); }}; + + std::ostringstream testStream; + choice.setStream(&testStream); + + handle.startTimeoutWindow_ = std::chrono::steady_clock::now(); + handle.cancellationState_ = CHECK_WINDOW_MISSED; + + // The first call should trigger a log + handle.pleaseWatchDog(CHECK_WINDOW_MISSED, std::identity{}, "my-detail"); + + EXPECT_EQ(handle.cancellationState_, NOT_CANCELLED); + EXPECT_THAT(std::move(testStream).str(), HasSubstr("my-detail")); + + testStream.str(""); + + // The second call should not trigger a log because the state has already + // been reset + handle.pleaseWatchDog(CHECK_WINDOW_MISSED, std::identity{}, "other-detail"); + + EXPECT_EQ(handle.cancellationState_, NOT_CANCELLED); + EXPECT_THAT(std::move(testStream).str(), Not(HasSubstr("other-detail"))); + + handle.cancellationState_ = CHECK_WINDOW_MISSED; + testStream.str(""); + + // WAITING_FOR_CHECK should not trigger a log + handle.pleaseWatchDog(WAITING_FOR_CHECK, std::identity{}, "my-detail"); + + EXPECT_EQ(handle.cancellationState_, NOT_CANCELLED); + EXPECT_THAT(std::move(testStream).str(), Not(HasSubstr("my-detail"))); +} + +// _____________________________________________________________________________ + +TEST(CancellationHandle, verifyPleaseWatchDogDoesNotAcceptInvalidState) { + CancellationHandle handle; + EXPECT_THROW(handle.pleaseWatchDog(NOT_CANCELLED, std::identity{}, ""), + ad_utility::Exception); + EXPECT_THROW(handle.pleaseWatchDog(MANUAL, std::identity{}, ""), + ad_utility::Exception); + EXPECT_THROW(handle.pleaseWatchDog(TIMEOUT, std::identity{}, ""), + ad_utility::Exception); +} + +// _____________________________________________________________________________ + +TEST(CancellationHandle, verifyIsCancelledDoesPleaseWatchDog) { + // If the log level is not high enough this test will fail + static_assert(LOGLEVEL >= WARN); + auto& choice = ad_utility::LogstreamChoice::get(); + CancellationHandle handle; + + auto& originalOStream = choice.getStream(); + absl::Cleanup cleanup{[&]() { choice.setStream(&originalOStream); }}; + + std::ostringstream testStream; + choice.setStream(&testStream); + + handle.startTimeoutWindow_ = std::chrono::steady_clock::now(); + handle.cancellationState_ = CHECK_WINDOW_MISSED; + + handle.isCancelled("my-detail"); + + EXPECT_EQ(handle.cancellationState_, NOT_CANCELLED); + EXPECT_THAT(std::move(testStream).str(), HasSubstr("my-detail")); + + handle.cancellationState_ = WAITING_FOR_CHECK; + testStream.str(""); + + handle.isCancelled("my-detail"); + + EXPECT_EQ(handle.cancellationState_, NOT_CANCELLED); + EXPECT_THAT(std::move(testStream).str(), Not(HasSubstr("my-detail"))); } // _____________________________________________________________________________ @@ -292,7 +381,7 @@ TEST(CancellationHandle, verifyCheckAfterDeadlineMissDoesReportProperly) { TEST(CancellationHandle, expectDisabledHandleIsAlwaysFalse) { CancellationHandle handle; - EXPECT_FALSE(handle.isCancelled()); + EXPECT_FALSE(handle.isCancelled("")); EXPECT_NO_THROW(handle.throwIfCancelled("Abc")); } diff --git a/test/WebSocketSessionTest.cpp b/test/WebSocketSessionTest.cpp index 81363113d6..898f1facd3 100644 --- a/test/WebSocketSessionTest.cpp +++ b/test/WebSocketSessionTest.cpp @@ -193,7 +193,7 @@ ASYNC_TEST(WebSocketSession, verifyCancelStringTriggersCancellation) { net::use_awaitable); ASSERT_TRUE(webSocket.is_open()); - EXPECT_FALSE(cancellationHandle->isCancelled()); + EXPECT_FALSE(cancellationHandle->isCancelled("")); // Wrong keyword should be ignored co_await webSocket.async_write(toBuffer("other"), net::use_awaitable); @@ -202,7 +202,7 @@ ASYNC_TEST(WebSocketSession, verifyCancelStringTriggersCancellation) { net::steady_timer timer{c.strand_, clientTimeout}; co_await timer.async_wait(net::use_awaitable); - EXPECT_FALSE(cancellationHandle->isCancelled()); + EXPECT_FALSE(cancellationHandle->isCancelled("")); co_await webSocket.async_write(toBuffer("cancel"), net::use_awaitable); @@ -210,7 +210,7 @@ ASYNC_TEST(WebSocketSession, verifyCancelStringTriggersCancellation) { timer.expires_after(clientTimeout); co_await timer.async_wait(net::use_awaitable); - EXPECT_TRUE(cancellationHandle->isCancelled()); + EXPECT_TRUE(cancellationHandle->isCancelled("")); AD_EXPECT_THROW_WITH_MESSAGE_AND_TYPE( cancellationHandle->throwIfCancelled(""), HasSubstr("manual cancellation"), ad_utility::CancellationException); @@ -298,17 +298,17 @@ ASYNC_TEST(WebSocketSession, verifyCancelOnCloseStringTriggersCancellation) { net::use_awaitable); ASSERT_TRUE(webSocket.is_open()); - EXPECT_FALSE(cancellationHandle->isCancelled()); + EXPECT_FALSE(cancellationHandle->isCancelled("")); // Wrong keyword should be ignored co_await webSocket.async_write(toBuffer("other"), net::use_awaitable); - EXPECT_FALSE(cancellationHandle->isCancelled()); + EXPECT_FALSE(cancellationHandle->isCancelled("")); co_await webSocket.async_write(toBuffer("cancel_on_close"), net::use_awaitable); - EXPECT_FALSE(cancellationHandle->isCancelled()); + EXPECT_FALSE(cancellationHandle->isCancelled("")); // Wrong keyword should be ignored co_await webSocket.async_write(toBuffer("other2"), net::use_awaitable); @@ -317,7 +317,7 @@ ASYNC_TEST(WebSocketSession, verifyCancelOnCloseStringTriggersCancellation) { net::steady_timer timer{c.strand_, clientTimeout}; co_await timer.async_wait(net::use_awaitable); - EXPECT_FALSE(cancellationHandle->isCancelled()); + EXPECT_FALSE(cancellationHandle->isCancelled("")); co_await webSocket.async_close(boost::beast::websocket::close_code::normal, net::use_awaitable); @@ -326,7 +326,7 @@ ASYNC_TEST(WebSocketSession, verifyCancelOnCloseStringTriggersCancellation) { timer.expires_after(clientTimeout); co_await timer.async_wait(net::use_awaitable); - EXPECT_TRUE(cancellationHandle->isCancelled()); + EXPECT_TRUE(cancellationHandle->isCancelled("")); AD_EXPECT_THROW_WITH_MESSAGE_AND_TYPE( cancellationHandle->throwIfCancelled(""), HasSubstr("manual cancellation"), ad_utility::CancellationException); @@ -365,7 +365,7 @@ ASYNC_TEST(WebSocketSession, verifyWithoutClientActionNoCancelDoesHappen) { net::use_awaitable); ASSERT_TRUE(webSocket.is_open()); - EXPECT_FALSE(cancellationHandle->isCancelled()); + EXPECT_FALSE(cancellationHandle->isCancelled("")); // Wrong keyword should be ignored co_await webSocket.async_write(toBuffer("other"), net::use_awaitable); @@ -374,7 +374,7 @@ ASYNC_TEST(WebSocketSession, verifyWithoutClientActionNoCancelDoesHappen) { co_await net::co_spawn(c.strand_, c.serverLogic() && controllerActions(), net::use_awaitable); - EXPECT_FALSE(cancellationHandle->isCancelled()); + EXPECT_FALSE(cancellationHandle->isCancelled("")); } // _____________________________________________________________________________