Add RequestResult.first_byte field for measuring first body byte latency

src/client.rs

@@ -46,6 +46,8 @@ pub struct RequestResult {
     /// DNS + dialup
     /// None when reuse connection
     pub connection_time: Option<ConnectionTime>,
+    /// First body byte received
+    pub first_byte: Option<std::time::Instant>,
     /// When the query ends
     pub end: std::time::Instant,
     /// HTTP status
@@ -616,6 +618,7 @@ impl Client {
         let do_req = async {
             let (url, rng) = self.generate_url(&mut client_state.rng)?;
             let mut start = std::time::Instant::now();
+            let mut first_byte: Option<std::time::Instant> = None;
             let mut connection_time: Option<ConnectionTime> = None;
 
             let mut send_request = if let Some(send_request) = client_state.send_request.take() {
@@ -646,6 +649,9 @@ impl Client {
 
                     let mut len_bytes = 0;
                     while let Some(chunk) = stream.frame().await {
+                        if first_byte.is_none() {
+                            first_byte = Some(std::time::Instant::now())
+                        }
                         len_bytes += chunk?.data_ref().map(|d| d.len()).unwrap_or_default();
                     }
 
@@ -673,6 +679,7 @@ impl Client {
                         rng,
                         start_latency_correction: None,
                         start,
+                        first_byte,
                         end,
                         status,
                         len_bytes,
@@ -768,6 +775,7 @@ impl Client {
         let do_req = async {
             let (url, rng) = self.generate_url(&mut client_state.rng)?;
             let start = std::time::Instant::now();
+            let mut first_byte: Option<std::time::Instant> = None;
             let connection_time: Option<ConnectionTime> = None;
 
             let request = self.request(&url)?;
@@ -778,6 +786,9 @@ impl Client {
 
                     let mut len_bytes = 0;
                     while let Some(chunk) = stream.frame().await {
+                        if first_byte.is_none() {
+                            first_byte = Some(std::time::Instant::now())
+                        }
                         len_bytes += chunk?.data_ref().map(|d| d.len()).unwrap_or_default();
                     }
 
@@ -787,6 +798,7 @@ impl Client {
                         rng,
                         start_latency_correction: None,
                         start,
+                        first_byte,
                         end,
                         status,
                         len_bytes,

src/db.rs

@@ -66,6 +66,7 @@ mod test_db {
             start_latency_correction: None,
             start: std::time::Instant::now(),
             connection_time: None,
+            first_byte: None,
             end: std::time::Instant::now(),
         };
         let test_vec = vec![test_val.clone(), test_val.clone()];

src/printer.rs

@@ -380,7 +380,7 @@ fn print_csv<W: Write>(w: &mut W, start: Instant, res: &ResultData) -> std::io::
     // csv header
     writeln!(
         w,
-        "request-start,DNS,DNS+dialup,request-duration,bytes,status"
+        "request-start,DNS,DNS+dialup,Response-delay,request-duration,bytes,status"
     )?;
 
     let mut success_requests = res.success().to_vec();
@@ -394,12 +394,17 @@ fn print_csv<W: Write>(w: &mut W, start: Instant, res: &ResultData) -> std::io::
             ),
             None => (std::time::Duration::ZERO, std::time::Duration::ZERO),
         };
+        let first_byte = match request.first_byte {
+            Some(first_byte) => first_byte - request.start,
+            None => std::time::Duration::ZERO,
+        };
         writeln!(
             w,
-            "{},{},{},{},{},{}",
+            "{},{},{},{},{},{},{}",
             (request.start - start).as_secs_f64(),
             dns_and_dialup.0.as_secs_f64(),
             dns_and_dialup.1.as_secs_f64(),
+            first_byte.as_secs_f64(),
             request.duration().as_secs_f64(),
             request.len_bytes,
             request.status.as_u16(),

src/result_data.rs

@@ -198,6 +198,7 @@ mod tests {
         request_time: u64,
         connection_time_dns_lookup: u64,
         connection_time_dialup: u64,
+        first_byte: u64,
         size: usize,
     ) -> Result<RequestResult, ClientError> {
         let now = Instant::now();
@@ -213,6 +214,7 @@ mod tests {
                     .checked_add(Duration::from_millis(connection_time_dialup))
                     .unwrap(),
             }),
+            first_byte: Some(now.checked_add(Duration::from_millis(first_byte)).unwrap()),
             end: now
                 .checked_add(Duration::from_millis(request_time))
                 .unwrap(),
@@ -229,20 +231,23 @@ mod tests {
             1000,
             200,
             50,
+            300,
             100,
         ));
         results.push(build_mock_request_result(
             StatusCode::BAD_REQUEST,
             100000,
             250,
             100,
+            400,
             200,
         ));
         results.push(build_mock_request_result(
             StatusCode::INTERNAL_SERVER_ERROR,
             1000000,
             300,
             150,
+            500,
             300,
         ));
         results

tests/tests.rs

@@ -1008,30 +1008,30 @@ async fn test_csv_output() {
 
     // Validate that we get CSV output in following format,
     // header and one row for each request:
-    // request-start,DNS,DNS+dialup,request-duration,bytes,status
-    // 0.002219628,0.000309806,0.001021632,0.002023073,11,200
+    // request-start,DNS,DNS+dialup,Response-delay,request-duration,bytes,status
+    // 0.002211678,0.000374078,0.001148565,0.002619327,0.002626127,11,200
     // ...
 
     let lines: Vec<&str> = output_csv.lines().collect();
     assert_eq!(lines.len(), 6);
     assert_eq!(
         lines[0],
-        "request-start,DNS,DNS+dialup,request-duration,bytes,status"
+        "request-start,DNS,DNS+dialup,Response-delay,request-duration,bytes,status"
     );
     let mut latest_start = 0f64;
     for line in lines.iter().skip(1) {
         let parts: Vec<&str> = line.split(",").collect();
-        assert_eq!(parts.len(), 6);
+        assert_eq!(parts.len(), 7);
         // validate that the requests are in ascending time order
         let current_start = f64::from_str(parts[0]).unwrap();
-        println!("current: {current_start}");
         assert!(current_start >= latest_start);
         latest_start = current_start;
         assert!(f64::from_str(parts[1]).unwrap() > 0f64);
         assert!(f64::from_str(parts[2]).unwrap() > 0f64);
         assert!(f64::from_str(parts[3]).unwrap() > 0f64);
-        assert_eq!(usize::from_str(parts[4]).unwrap(), 11);
-        assert_eq!(u16::from_str(parts[5]).unwrap(), 200);
+        assert!(f64::from_str(parts[4]).unwrap() > 0f64);
+        assert_eq!(usize::from_str(parts[5]).unwrap(), 11);
+        assert_eq!(u16::from_str(parts[6]).unwrap(), 200);
     }
 }