diff --git a/.github/workflows/tquic-goodput-debug.yml b/.github/workflows/tquic-goodput-debug.yml new file mode 100644 index 00000000..613f2960 --- /dev/null +++ b/.github/workflows/tquic-goodput-debug.yml @@ -0,0 +1,85 @@ +name: GoodputDebug + +on: + schedule: + - cron: '30 1 * * *' + workflow_dispatch: + +env: + CARGO_TERM_COLOR: always + QUIC_IMAGES: gquiche=tquicgroup/qirgq,lsquic=tquicgroup/qirls,picoquic=tquicgroup/qirpq,quiche=tquicgroup/qircq + +jobs: + measure: + runs-on: ubuntu-latest + + strategy: + matrix: + impl: [tquic] + case: [goodput] + cc: [bbr] + + # The scheduled workflow only runs for the main repository. + # You can manually trigger it if necessary. + if: ${{ ( github.event_name == 'schedule' && github.repository == 'tencent/tquic' ) || github.event_name == 'workflow_dispatch' }} + steps: + - uses: actions/checkout@v4 + with: + submodules: 'recursive' + + - name: Build docker image + run: docker build -t tquic_interop:v1 -f interop/Dockerfile . + + - name: Install quic-interop-runner + run: | + git clone https://github.com/tquic-group/quic-interop-runner.git + cd quic-interop-runner + pip3 install -r requirements.txt + + - name: Install dependencies + run: | + sudo modprobe ip6table_filter + sudo add-apt-repository -y ppa:wireshark-dev/stable + sudo apt install -y tshark + + - name: Run the interop tests + run: | + cd quic-interop-runner + python3 run.py -r "$QUIC_IMAGES,tquic=tquic_interop:v1" -s ${{ matrix.impl }} -c ${{ matrix.impl }} -t ${{ matrix.case }} -a ${{ matrix.cc }} -d -n "drop-rate --delay=15ms --bandwidth=10Mbps --queue=25 --rate_to_server=0 --rate_to_client=0" -j ${{ matrix.case }}-0-${{ matrix.cc }}-${{ matrix.impl }}.json + + - name: Store measurement results + uses: actions/upload-artifact@v4 + with: + name: ${{ matrix.case }}-${{ matrix.cc }}-${{ matrix.impl }} + path: quic-interop-runner/* + + result: + runs-on: ubuntu-latest + needs: measure + steps: + - name: Download all workflow run artifacts + uses: actions/download-artifact@v4 + + - name: Display structure of downloaded files + run: ls -R + + - name: Display all measurement details + run: grep "details.*" . -Ro + + - name: Download plot tools + uses: actions/checkout@v4 + with: + path: tools + + - name: Install dependencies + run: | + sudo apt install python3-matplotlib + + - name: Plot all measurement results + run: python3 tools/.github/workflows/plot-goodput.py . + + - name: Store all measurement results + uses: actions/upload-artifact@v4 + with: + name: goodput-all-result + path: goodput* diff --git a/interop/run_endpoint.sh b/interop/run_endpoint.sh index 030c6ec6..e29667d4 100644 --- a/interop/run_endpoint.sh +++ b/interop/run_endpoint.sh @@ -64,7 +64,7 @@ esac # Note: You can add extra command-line options to tquic_client/tquic_sever by # using the `EXTRA_ARGS` environment variable. -COMMON_ARGS="--keylog-file $SSLKEYLOGFILE --log-level DEBUG --log-file $LOG_DIR/$ROLE.log --idle-timeout 30000 --handshake-timeout 30000 --initial-rtt 100 --congestion-control-algor $CC_ALGOR $EXTRA_ARGS" +COMMON_ARGS="--keylog-file $SSLKEYLOGFILE --log-level trace --log-file $LOG_DIR/$ROLE.log --idle-timeout 30000 --handshake-timeout 30000 --initial-rtt 100 --congestion-control-algor $CC_ALGOR $EXTRA_ARGS" if [ "$TESTCASE" != "transfer" ]; then COMMON_ARGS="$COMMON_ARGS --qlog-dir $QLOG_DIR" diff --git a/src/connection/connection.rs b/src/connection/connection.rs index 2af19cee..bbfda99c 100644 --- a/src/connection/connection.rs +++ b/src/connection/connection.rs @@ -1775,6 +1775,7 @@ impl Connection { in_flight: write_status.in_flight, has_data: write_status.has_data, pmtu_probe: write_status.is_pmtu_probe, + pacing: write_status.pacing, frames: write_status.frames, rate_sample_state: Default::default(), buffer_flags: write_status.buffer_flags, @@ -1918,6 +1919,7 @@ impl Connection { if !st.is_probe && !r.can_send() { return Err(Error::Done); } + st.pacing = true; // Write PMTU probe frames // Note: To probe the path MTU, the write size will exceed `left` but @@ -2350,6 +2352,10 @@ impl Connection { .map(|(&k, &v)| (k, v)) .collect::>() { + log::debug!( + "~~~ stream {} is blocked, sending STREAM_DATA_BLOCKED", + stream_id + ); let frame = frame::Frame::StreamDataBlocked { stream_id, max: limit, @@ -4461,6 +4467,9 @@ struct FrameWriteStatus { /// Whether it is a PMTU probe packet is_pmtu_probe: bool, + /// Whether it consumes the pacer's tokens + pacing: bool, + /// Packet overhead (i.e. packet header and crypto overhead) in bytes overhead: usize, diff --git a/src/connection/flowcontrol.rs b/src/connection/flowcontrol.rs index 0739bc9e..a81ccfa3 100644 --- a/src/connection/flowcontrol.rs +++ b/src/connection/flowcontrol.rs @@ -103,7 +103,15 @@ impl FlowControl { /// Return true if the available window is smaller than the half /// of the current window. pub fn should_send_max_data(&self) -> bool { - (self.max_data - self.read_off) * 2 < self.window + let v = (self.max_data - self.read_off) * 2 < self.window; + log::debug!( + "~~~ should_send_max_data {}: max_data {} - read_off {} < window {} / 2", + v, + self.max_data, + self.read_off, + self.window + ); + v } /// Get the next max_data limit which will be sent to the peer diff --git a/src/connection/recovery.rs b/src/connection/recovery.rs index bb4c9669..27148826 100644 --- a/src/connection/recovery.rs +++ b/src/connection/recovery.rs @@ -163,6 +163,7 @@ impl Recovery { ) { let in_flight = pkt.in_flight; let ack_eliciting = pkt.ack_eliciting; + let pacing = pkt.pacing; let sent_size = pkt.sent_size; pkt.time_sent = now; @@ -214,7 +215,9 @@ impl Recovery { } // Update pacing tokens number. - self.pacer.on_sent(sent_size as u64); + if pacing { + self.pacer.on_sent(sent_size as u64); + } } /// Handle packet acknowledgment event. @@ -830,8 +833,25 @@ impl Recovery { /// Check whether this path can still send packets. pub(crate) fn can_send(&mut self) -> bool { - self.bytes_in_flight < self.congestion.congestion_window() as usize - && (!self.pacer.enabled() || self.can_pacing()) + if self.bytes_in_flight >= self.congestion.congestion_window() as usize { + debug!( + "{} sending is limited by congestion controller, inflight {}, window {}", + self.trace_id, + self.bytes_in_flight, + self.congestion.congestion_window() + ); + return false; + } + if self.pacer.enabled() && !self.can_pacing() { + debug!( + "{} sending is limited by pacer, pacing timer {:?}", + self.trace_id, + self.pacer_timer + .map(|t| t.saturating_duration_since(Instant::now())) + ); + return false; + } + true } fn can_pacing(&mut self) -> bool { @@ -850,12 +870,7 @@ impl Recovery { ); } - if self.pacer_timer.is_none() { - true - } else { - trace!("{} pacing timer is {:?}", self.trace_id, self.pacer_timer); - false - } + self.pacer_timer.is_none() } /// Update statistics for the packet sent event diff --git a/src/connection/space.rs b/src/connection/space.rs index 6ec9f577..154cc95c 100644 --- a/src/connection/space.rs +++ b/src/connection/space.rs @@ -369,6 +369,9 @@ pub struct SentPacket { /// Whether it is a PMUT probe packet pub pmtu_probe: bool, + /// Whether it consumes the pacer's tokens + pub pacing: bool, + /// The number of bytes sent in the packet, not including UDP or IP overhead, /// but including QUIC framing overhead. pub sent_size: usize, @@ -393,6 +396,7 @@ impl Default for SentPacket { in_flight: false, has_data: false, pmtu_probe: false, + pacing: false, sent_size: 0, rate_sample_state: RateSamplePacketState::default(), buffer_flags: BufferFlags::default(), diff --git a/src/connection/stream.rs b/src/connection/stream.rs index e267bf7f..0b9a0c8c 100644 --- a/src/connection/stream.rs +++ b/src/connection/stream.rs @@ -379,9 +379,21 @@ impl StreamMap { let empty_fin = buf_len == 0 && fin; if written < buf_len { + log::debug!( + "~~~ stream {} not all data has been written buf_len {}, written{}", + stream_id, + buf_len, + written + ); let max_data = stream.send.max_data(); if stream.send.blocked_at() != Some(max_data) { + log::debug!( + "~~~ stream {} sendbuf blocked_at() {:?} != max_data() {:?}, mark stream blocked", + stream_id, + stream.send.blocked_at(), + Some(max_data) + ); stream.send.update_blocked_at(Some(max_data)); self.mark_blocked(stream_id, true, max_data); } @@ -525,6 +537,12 @@ impl StreamMap { // The connection-level flow control credit is not enough, mark the connection // blocked and schedule a DATA_BLOCKED frame to be sent to the peer. if self.max_tx_data_left() < len as u64 { + trace!( + "{} stream {} was blocked by connection-level flow control at {}", + self.trace_id, + stream_id, + self.send_capacity.max_data + ); self.update_data_blocked_at(Some(self.send_capacity.max_data)); } @@ -544,6 +562,10 @@ impl StreamMap { if stream.send.capacity()? < len { let max_data = stream.send.max_data(); if stream.send.blocked_at() != Some(max_data) { + debug!( + "~~~ stream {} was blocked by stream-level flow control at {}", + stream_id, max_data + ); stream.send.update_blocked_at(Some(max_data)); self.mark_blocked(stream_id, true, max_data); } diff --git a/tools/src/bin/tquic_client.rs b/tools/src/bin/tquic_client.rs index f7aa2c78..f47ef2c9 100644 --- a/tools/src/bin/tquic_client.rs +++ b/tools/src/bin/tquic_client.rs @@ -546,6 +546,7 @@ impl Worker { config.enable_multipath(option.enable_multipath); config.set_multipath_algorithm(option.multipath_algor); config.set_active_connection_id_limit(option.active_cid_limit); + config.enable_pacing(false); config.enable_encryption(!option.disable_encryption); let tls_config = TlsConfig::new_client_config( ApplicationProto::convert_to_vec(&option.alpn),