From a73eade46842f23b1aaefeac6acd06ebd720c93b Mon Sep 17 00:00:00 2001 From: Joseph Beshay Date: Fri, 7 Jan 2022 18:41:05 -0800 Subject: [PATCH] Add more fields to Qlog Transport Summary to track spurious retransmissions Summary: Add three new fields to the qlog transport summary to help analyze spurious transmissions and how they are affected by using adaptive loss thresholds. Sample transport summary with added fields: ``` "transport_summary", { "current_conn_flow_control": 1068498609, "current_writable_bytes": 106330, "dsr_packet_count": 0, "final_packet_loss_reordering_threshold": 77, "final_packet_loss_time_reordering_threshold_dividend": 29, "quic_version": 4207849474, "sum_cur_stream_buffer_len": 0, "sum_cur_write_offset": 5243215, "sum_max_observed_offset": 67, "total_bytes_cloned": 0, "total_bytes_recvd": 38157, "total_bytes_retransmitted": 244982, "total_bytes_sent": 5605121, "total_crypto_data_recvd": 342, "total_crypto_data_written": 1548, "total_packets_spuriously_marked_lost": 203, "total_stream_bytes_cloned": 0, "used_zero_rtt": false } ``` Reviewed By: afrind, mjoras Differential Revision: D33354583 fbshipit-source-id: 55d9880ef02f6914b74c1b6508863bea7807950b --- quic/api/QuicTransportBase.cpp | 3 +++ quic/logging/FileQLogger.cpp | 3 +++ quic/logging/QLogger.h | 3 +++ quic/logging/QLoggerTypes.cpp | 13 +++++++++++++ quic/logging/QLoggerTypes.h | 6 ++++++ quic/logging/test/QLoggerTest.cpp | 28 +++++++++++++++++++++++++++- 6 files changed, 55 insertions(+), 1 deletion(-) diff --git a/quic/api/QuicTransportBase.cpp b/quic/api/QuicTransportBase.cpp index 73ef0f130..35d04471e 100644 --- a/quic/api/QuicTransportBase.cpp +++ b/quic/api/QuicTransportBase.cpp @@ -290,6 +290,9 @@ void QuicTransportBase::closeImpl( ? conn_->congestionController->getWritableBytes() : std::numeric_limits::max(), getSendConnFlowControlBytesWire(*conn_), + conn_->lossState.totalPacketsSpuriouslyMarkedLost, + conn_->lossState.reorderingThreshold, + uint64_t(conn_->transportSettings.timeReorderingThreshDividend), conn_->usedZeroRtt, conn_->version.value_or(QuicVersion::MVFST_INVALID), conn_->dsrPacketCount}); diff --git a/quic/logging/FileQLogger.cpp b/quic/logging/FileQLogger.cpp index 4b9d54b50..29d5d8d2c 100644 --- a/quic/logging/FileQLogger.cpp +++ b/quic/logging/FileQLogger.cpp @@ -244,6 +244,9 @@ void FileQLogger::addTransportSummary(const TransportSummaryArgs& args) { args.totalCryptoDataRecvd, args.currentWritableBytes, args.currentConnFlowControl, + args.totalPacketsSpuriouslyMarkedLost, + args.finalPacketLossReorderingThreshold, + args.finalPacketLossTimeReorderingThreshDividend, args.usedZeroRtt, args.quicVersion, args.dsrPacketCount, diff --git a/quic/logging/QLogger.h b/quic/logging/QLogger.h index db8668659..97787ece4 100644 --- a/quic/logging/QLogger.h +++ b/quic/logging/QLogger.h @@ -66,6 +66,9 @@ class QLogger { uint64_t totalCryptoDataRecvd{}; uint64_t currentWritableBytes{}; uint64_t currentConnFlowControl{}; + uint64_t totalPacketsSpuriouslyMarkedLost{}; + uint64_t finalPacketLossReorderingThreshold{}; + uint64_t finalPacketLossTimeReorderingThreshDividend{}; bool usedZeroRtt{}; QuicVersion quicVersion{QuicVersion::MVFST_INVALID}; uint64_t dsrPacketCount{}; diff --git a/quic/logging/QLoggerTypes.cpp b/quic/logging/QLoggerTypes.cpp index 454b932b5..6d0cc8c71 100644 --- a/quic/logging/QLoggerTypes.cpp +++ b/quic/logging/QLoggerTypes.cpp @@ -355,6 +355,9 @@ QLogTransportSummaryEvent::QLogTransportSummaryEvent( uint64_t totalCryptoDataRecvdIn, uint64_t currentWritableBytesIn, uint64_t currentConnFlowControlIn, + uint64_t totalPacketsSpuriouslyMarkedLost, + uint64_t finalPacketLossReorderingThreshold, + uint64_t finalPacketLossTimeReorderingThreshDividend, bool usedZeroRttIn, QuicVersion quicVersionIn, uint64_t dsrPacketCountIn, @@ -371,6 +374,10 @@ QLogTransportSummaryEvent::QLogTransportSummaryEvent( totalCryptoDataRecvd{totalCryptoDataRecvdIn}, currentWritableBytes{currentWritableBytesIn}, currentConnFlowControl{currentConnFlowControlIn}, + totalPacketsSpuriouslyMarkedLost{totalPacketsSpuriouslyMarkedLost}, + finalPacketLossReorderingThreshold{finalPacketLossReorderingThreshold}, + finalPacketLossTimeReorderingThreshDividend{ + finalPacketLossTimeReorderingThreshDividend}, usedZeroRtt{usedZeroRttIn}, quicVersion{quicVersionIn}, dsrPacketCount{dsrPacketCountIn} { @@ -399,6 +406,12 @@ folly::dynamic QLogTransportSummaryEvent::toDynamic() const { data["total_crypto_data_recvd"] = totalCryptoDataRecvd; data["current_writable_bytes"] = currentWritableBytes; data["current_conn_flow_control"] = currentConnFlowControl; + data["total_packets_spuriously_marked_lost"] = + totalPacketsSpuriouslyMarkedLost; + data["final_packet_loss_reordering_threshold"] = + finalPacketLossReorderingThreshold; + data["final_packet_loss_time_reordering_threshold_dividend"] = + finalPacketLossTimeReorderingThreshDividend; data["used_zero_rtt"] = usedZeroRtt; data["quic_version"] = static_cast::type>( diff --git a/quic/logging/QLoggerTypes.h b/quic/logging/QLoggerTypes.h index 9df01c7c9..7b7a8358d 100644 --- a/quic/logging/QLoggerTypes.h +++ b/quic/logging/QLoggerTypes.h @@ -426,6 +426,9 @@ class QLogTransportSummaryEvent : public QLogEvent { uint64_t totalCryptoDataRecvd, uint64_t currentWritableBytes, uint64_t currentConnFlowControl, + uint64_t totalPacketsSpuriouslyMarkedLost, + uint64_t finalPacketLossReorderingThreshold, + uint64_t finalPacketLossTimeReorderingThreshDividend, bool usedZeroRtt, QuicVersion version, uint64_t dsrPacketCount, @@ -443,6 +446,9 @@ class QLogTransportSummaryEvent : public QLogEvent { uint64_t totalCryptoDataRecvd; uint64_t currentWritableBytes; uint64_t currentConnFlowControl; + uint64_t totalPacketsSpuriouslyMarkedLost; + uint64_t finalPacketLossReorderingThreshold; + uint64_t finalPacketLossTimeReorderingThreshDividend; bool usedZeroRtt; QuicVersion quicVersion; uint64_t dsrPacketCount; diff --git a/quic/logging/test/QLoggerTest.cpp b/quic/logging/test/QLoggerTest.cpp index 5b5b223ea..f5ca50403 100644 --- a/quic/logging/test/QLoggerTest.cpp +++ b/quic/logging/test/QLoggerTest.cpp @@ -112,6 +112,9 @@ TEST_F(QLoggerTest, TransportSummaryEvent) { 238, 22, 44, + 45, + 46, + 47, false, QuicVersion::MVFST, 37}); @@ -131,6 +134,9 @@ TEST_F(QLoggerTest, TransportSummaryEvent) { EXPECT_EQ(gotEvent->totalCryptoDataRecvd, 238); EXPECT_EQ(gotEvent->currentWritableBytes, 22); EXPECT_EQ(gotEvent->currentConnFlowControl, 44); + EXPECT_EQ(gotEvent->totalPacketsSpuriouslyMarkedLost, 45); + EXPECT_EQ(gotEvent->finalPacketLossReorderingThreshold, 46); + EXPECT_EQ(gotEvent->finalPacketLossTimeReorderingThreshDividend, 47); EXPECT_EQ(gotEvent->usedZeroRtt, false); EXPECT_EQ(gotEvent->dsrPacketCount, 37); } @@ -759,6 +765,9 @@ TEST_F(QLoggerTest, TransportSummaryFollyDynamic) { "total_crypto_data_recvd": 10, "current_writable_bytes": 11, "current_conn_flow_control": 12, + "total_packets_spuriously_marked_lost": 13, + "final_packet_loss_reordering_threshold": 14, + "final_packet_loss_time_reordering_threshold_dividend": 15, "used_zero_rtt": true, "quic_version": 4207849474, "dsr_packet_count": 37 @@ -768,7 +777,24 @@ TEST_F(QLoggerTest, TransportSummaryFollyDynamic) { FileQLogger q(VantagePoint::Client); q.addTransportSummary( - {1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, true, QuicVersion::MVFST, 37}); + {1, + 2, + 3, + 4, + 5, + 6, + 7, + 8, + 9, + 10, + 11, + 12, + 13, + 14, + 15, + true, + QuicVersion::MVFST, + 37}); folly::dynamic gotDynamic = q.toDynamic(); gotDynamic["traces"][0]["events"][0][0] = "0"; // hardcode reference time folly::dynamic gotEvents = gotDynamic["traces"][0]["events"];