Update debug logs for recovery module

Add tquic-goodput-debug.yml for debuging

.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*

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"

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::<Vec<(u64, u64)>>()
         {
+            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,
 

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

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

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(),

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);
             }

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),