Repository navigation
Unnecessary stream scanning when logging is disabled increases latency #6362
Description
Describe the bug
When MsQuic is built with QUIC_ENABLE_LOGGING=OFF, QuicConnLogOutFlowStats() still scans all live streams to collect statistics that goes nowhere.
I've added an early return in QuicConnLogOutFlowStats() and it reduced latency by 90% at following SecNetPerf benchmark:
./build/repro/bin/Release/secnetperf -target:localhost -conns:1 -streams:1000 -rstream:1 -run:10s -up:512 -down:4kb -plat:1
Modified code:
QUIC_INLINE
void
QuicConnLogOutFlowStats(
_In_ const QUIC_CONNECTION* const Connection
)
{
// Added this branching
#if defined(QUIC_EVENTS_STUB) && !defined(QUIC_EVENTS_STDOUT)
// Event tracing is a no-op; avoid scanning all live streams for statistics.
return;
#endif
if (!QuicTraceEventEnabled(ConnOutFlowStats)) {
return;
}
QuicCongestionControlLogOutFlowStatus(&Connection->CongestionControl);
uint64_t FcAvailable, SendWindow;
QuicStreamSetGetFlowControlSummary(
&Connection->Streams,
&FcAvailable,
&SendWindow);
QuicTraceEvent(
ConnOutFlowStreamStats,
"[conn][%p] OUT: StreamFC=%llu StreamSendWindow=%llu",
Connection,
FcAvailable,
SendWindow);
}Benchmark result with the current branch:
Result: 11383 RPS, Latency,us 0th: 10525, 50th: 86901, 90th: 88417, 99th: 123274, 99.9th: 132490, 99.99th: 135393, 99.999th: 137258, 99.9999th: 137265, Max: 137265
Benchmark result with the patched branch:
Result: 118139 RPS, Latency,us 0th: 6319, 50th: 8515, 90th: 8892, 99th: 12190, 99.9th: 15922, 99.99th: 25233, 99.999th: 25400, 99.9999th: 25450, Max: 25454
Affected OS
- Windows
- Linux
- macOS
- Other (specify below)
Additional OS information
Ubuntu 24.04 (x86_64)
Linux kernel: 6.8.0-142-generic
Reproduced with a Release build using QuicTLS and QUIC_ENABLE_LOGGING=OFF. Windows and macOS have not been tested.
MsQuic version
commit 900ef64
Steps taken to reproduce bug
- Build with logging disabled (
-DQUIC_ENABLE_LOGGING=OFF) - Start secnetperf server
- Run fairly big number of concurrent streams (~1000) over one connection. I've confirmed 100 concurrent streams already made noticeable latency in comparison to the patched version.
./build/repro/bin/Release/secnetperf -target:localhost -conns:1 -streams:1000 -rstream:1 -run:10s -up:512 -down:4kb -plat:1
Expected behavior
Packet processing should be faster when loggings are disabled because there is no need of scanning live streams.
Actual outcome
Packet processing stays the same as when the loggings are enabled.
Additional details
I've already made corresponding PR.
Also please let me know if this issue does not align the guideline, as this is my first time contributing to msquic.
Metadata
Metadata
Assignees
Labels
Type
Projects
- StatusShow more project fieldsDone
Activity
Skip flow statistics collection when event tracing is stubbed (#6363)