Visitar URL original
Unnecessary stream scanning when logging is disabled increases latency · Issue #6362 · microsoft/msquic · GitHub
Skip to content

Unnecessary stream scanning when logging is disabled increases latency #6362

Closed

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

  1. Build with logging disabled (-DQUIC_ENABLE_LOGGING=OFF)
  2. Start secnetperf server
  3. 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

Labels

Type

Projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions