From 00fb3329dc43c6095668083d92a626031aa1eead Mon Sep 17 00:00:00 2001 From: Crystal Jin Date: Wed, 21 Oct 2026 10:03:13 -0700 Subject: [PATCH] Add idle recovery debug telemetry Summary: Add debug-gated QUIC lifecycle snapshots to distinguish stale-connection recovery from general request slowness. Requests now record connection age, last RX/TX age, signed idle-deadline distance, and timer counts at request start and completion. mvfst reports separate idle and keepalive callbacks plus overdue-deadline observations; ngtcp2 reports its unified transport timer. Recreated requests preserve the prior connection UUID so the request can be joined to the close reason and replacement connection. Reviewed By: jbeshay Differential Revision: D125287129 fbshipit-source-id: 921046a7ed2a6273fde59be0125dcbd8904ccaf4 --- quic/api/QuicTransportBaseLite.cpp | 18 ++++++++++ quic/api/QuicTransportBaseLite.h | 6 ++++ quic/client/QuicClientTransportLite.cpp | 29 +++++++++++++++ quic/client/QuicClientTransportLite.h | 13 +++++++ .../test/QuicClientTransportLiteTest.cpp | 35 +++++++++++++++++++ 5 files changed, 101 insertions(+) diff --git a/quic/api/QuicTransportBaseLite.cpp b/quic/api/QuicTransportBaseLite.cpp index 7d0fe728c..776c70855 100644 --- a/quic/api/QuicTransportBaseLite.cpp +++ b/quic/api/QuicTransportBaseLite.cpp @@ -2723,6 +2723,12 @@ void QuicTransportBaseLite::lossTimeoutExpired() noexcept { void QuicTransportBaseLite::idleTimeoutExpired(bool drain) noexcept { MVVLOG(4) << __func__ << " " << *this; [[maybe_unused]] auto self = sharedGuard(); + const auto now = Clock::now(); + if (idleTimeoutDeadline_.has_value() && now >= *idleTimeoutDeadline_) { + lastIdleDeadlineOverdue_ = + std::chrono::duration_cast( + now - *idleTimeoutDeadline_); + } // idle timeout is expired, just close the connection and drain or // send connection close immediately depending on 'drain' MVDCHECK_NE(closeState_, CloseState::CLOSED); @@ -2759,6 +2765,16 @@ void QuicTransportBaseLite::sendPing( void QuicTransportBaseLite::keepaliveTimeoutExpired() noexcept { [[maybe_unused]] auto self = sharedGuard(); + ++keepaliveTimeoutFiredCount_; + const auto now = Clock::now(); + const bool idleDeadlineExpired = + idleTimeoutDeadline_.has_value() && now >= *idleTimeoutDeadline_; + if (idleDeadlineExpired) { + ++keepaliveExpiredIdleDeadlineCount_; + lastIdleDeadlineOverdue_ = + std::chrono::duration_cast( + now - *idleTimeoutDeadline_); + } conn_->pendingEvents.sendPing = true; updateWriteLooper(true); } @@ -3323,6 +3339,7 @@ void QuicTransportBaseLite::setIdleTimer() { } cancelTimeout(&idleTimeout_); cancelTimeout(&keepaliveTimeout_); + idleTimeoutDeadline_.reset(); auto localIdleTimeout = conn_->transportSettings.idleTimeout; // The local idle timeout being zero means it is disabled. if (localIdleTimeout == 0ms) { @@ -3332,6 +3349,7 @@ void QuicTransportBaseLite::setIdleTimer() { conn_->peerIdleTimeout > 0ms ? conn_->peerIdleTimeout : localIdleTimeout; auto idleTimeout = timeMin(localIdleTimeout, peerIdleTimeout); + idleTimeoutDeadline_ = Clock::now() + idleTimeout; scheduleTimeout(&idleTimeout_, idleTimeout); auto idleTimeoutCount = idleTimeout.count(); if (conn_->transportSettings.enableKeepalive) { diff --git a/quic/api/QuicTransportBaseLite.h b/quic/api/QuicTransportBaseLite.h index 006b9e31f..bdeed0750 100644 --- a/quic/api/QuicTransportBaseLite.h +++ b/quic/api/QuicTransportBaseLite.h @@ -382,6 +382,7 @@ class QuicTransportBaseLite : virtual public QuicSocketLite, : transport_(transport) {} void timeoutExpired() noexcept override { + ++transport_->idleTimeoutFiredCount_; transport_->idleTimeoutExpired(true /* drain */); } @@ -950,6 +951,11 @@ class QuicTransportBaseLite : virtual public QuicSocketLite, ExcessWriteTimeout excessWriteTimeout_; IdleTimeout idleTimeout_; KeepaliveTimeout keepaliveTimeout_; + Optional idleTimeoutDeadline_; + uint64_t idleTimeoutFiredCount_{0}; + uint64_t keepaliveTimeoutFiredCount_{0}; + uint64_t keepaliveExpiredIdleDeadlineCount_{0}; + Optional lastIdleDeadlineOverdue_; AckTimeout ackTimeout_; PathValidationTimeout pathValidationTimeout_; DrainTimeout drainTimeout_; diff --git a/quic/client/QuicClientTransportLite.cpp b/quic/client/QuicClientTransportLite.cpp index f221a6545..7a526ec34 100644 --- a/quic/client/QuicClientTransportLite.cpp +++ b/quic/client/QuicClientTransportLite.cpp @@ -2353,6 +2353,35 @@ std::chrono::milliseconds QuicClientTransportLite::getConnectionIdleDuration() now - lastReceivedPacketTime); } +ConnectionLifecycleDebugState +QuicClientTransportLite::getConnectionLifecycleDebugState() const { + const auto now = Clock::now(); + const auto ageSince = [now](TimePoint time) { + return time >= now + ? std::chrono::milliseconds::zero() + : std::chrono::duration_cast(now - time); + }; + const auto lastTxTime = + conn_->lossState.maybeLastPacketSentTime.value_or(conn_->connectionTime); + + ConnectionLifecycleDebugState state{ + .connectionAge = ageSince(conn_->connectionTime), + .lastRxAge = getConnectionIdleDuration(), + .lastTxAge = ageSince(lastTxTime), + .idleDeadlineDelta = std::nullopt, + .lastIdleDeadlineOverdue = lastIdleDeadlineOverdue_, + .idleTimeoutFiredCount = idleTimeoutFiredCount_, + .keepaliveTimeoutFiredCount = keepaliveTimeoutFiredCount_, + .keepaliveExpiredIdleDeadlineCount = keepaliveExpiredIdleDeadlineCount_, + }; + if (idleTimeoutDeadline_.has_value()) { + state.idleDeadlineDelta = + std::chrono::duration_cast( + *idleTimeoutDeadline_ - now); + } + return state; +} + int64_t QuicClientTransportLite::getNetworkReadCallbackStartTimeMs() const { if (networkReadCallbackStartTime_ == TimePoint{}) { return -1; diff --git a/quic/client/QuicClientTransportLite.h b/quic/client/QuicClientTransportLite.h index 59579715c..fd7e7ea9f 100644 --- a/quic/client/QuicClientTransportLite.h +++ b/quic/client/QuicClientTransportLite.h @@ -27,6 +27,17 @@ namespace quic { class ClientHandshakeFactory; class QuicTokenCache; +struct ConnectionLifecycleDebugState { + std::chrono::milliseconds connectionAge{0}; + std::chrono::milliseconds lastRxAge{0}; + std::chrono::milliseconds lastTxAge{0}; + Optional idleDeadlineDelta; + Optional lastIdleDeadlineOverdue; + uint64_t idleTimeoutFiredCount{0}; + uint64_t keepaliveTimeoutFiredCount{0}; + uint64_t keepaliveExpiredIdleDeadlineCount{0}; +}; + class QuicClientTransportLite : virtual public QuicTransportBaseLite, public QuicAsyncUDPSocket::ReadCallback, @@ -247,6 +258,8 @@ class QuicClientTransportLite std::chrono::milliseconds getConnectionIdleDuration() const; + ConnectionLifecycleDebugState getConnectionLifecycleDebugState() const; + int64_t getNetworkReadCallbackStartTimeMs() const; uint64_t getReceivedUdpDatagramCount() const; diff --git a/quic/client/test/QuicClientTransportLiteTest.cpp b/quic/client/test/QuicClientTransportLiteTest.cpp index f0f8358b0..4294aeca7 100644 --- a/quic/client/test/QuicClientTransportLiteTest.cpp +++ b/quic/client/test/QuicClientTransportLiteTest.cpp @@ -50,6 +50,14 @@ class QuicClientTransportLiteMock : public QuicClientTransportLite { [[nodiscard]] quic::Expected invokeWriteSocketData() { return writeSocketData(); } + + void setIdleTimeoutDeadlineForTest(TimePoint deadline) { + idleTimeoutDeadline_ = deadline; + } + + void invokeKeepaliveTimeoutExpiredForTest() { + keepaliveTimeoutExpired(); + } }; class QuicClientTransportLiteTest : public Test { @@ -190,6 +198,33 @@ TEST_F( EXPECT_LT(idleDuration, std::chrono::milliseconds(3000)); } +TEST_F( + QuicClientTransportLiteTest, + ConnectionLifecycleDebugStateTracksIdleDeadlineAndTimer) { + const auto now = Clock::now(); + auto* conn = quicClient_->getConn(); + conn->connectionTime = now - std::chrono::seconds(20); + conn->ackStates.appDataAckState.largestRecvdPacketTime = + now - std::chrono::seconds(2); + conn->lossState.maybeLastPacketSentTime = now - std::chrono::seconds(3); + quicClient_->setIdleTimeoutDeadlineForTest( + now - std::chrono::milliseconds(500)); + + quicClient_->invokeKeepaliveTimeoutExpiredForTest(); + const auto state = quicClient_->getConnectionLifecycleDebugState(); + + EXPECT_GE(state.connectionAge, std::chrono::milliseconds(19'900)); + EXPECT_GE(state.lastRxAge, std::chrono::milliseconds(1'900)); + EXPECT_GE(state.lastTxAge, std::chrono::milliseconds(2'900)); + ASSERT_TRUE(state.idleDeadlineDelta.has_value()); + EXPECT_LE(*state.idleDeadlineDelta, std::chrono::milliseconds(-500)); + ASSERT_TRUE(state.lastIdleDeadlineOverdue.has_value()); + EXPECT_GE(*state.lastIdleDeadlineOverdue, std::chrono::milliseconds(500)); + EXPECT_EQ(state.idleTimeoutFiredCount, 0); + EXPECT_EQ(state.keepaliveTimeoutFiredCount, 1); + EXPECT_EQ(state.keepaliveExpiredIdleDeadlineCount, 1); +} + TEST_F( QuicClientTransportLiteTest, SetTransportSettingsPreservesPeerTimestampFrameExponent) {