diff --git a/command/src/command.proto b/command/src/command.proto index 2487e5ef4..4b0261a1a 100644 --- a/command/src/command.proto +++ b/command/src/command.proto @@ -744,8 +744,6 @@ message ProtobufAccessLog { optional uint64 client_rtt = 9; // round trip time for the backend (microseconds) optional uint64 server_rtt = 10; - // time for the backend to respond (microseconds) - required uint64 response_time = 12; // time spent on a session (microseconds) required uint64 service_time = 13; // number of bytes received from the client @@ -760,6 +758,12 @@ message ProtobufAccessLog { required string tag = 18; // POSIX timestamp, nanoseconds required Uint128 time = 19; + // Entire time between first byte received and last byte of the response. + // If a request ends abruptly before the last byte is transmitted, + // the `request_time` produced is the time elapsed since the first byte received. + optional uint64 request_time = 20; + // time for the backend to respond (microseconds) + optional uint64 response_time = 21; } message ProtobufEndpoint { diff --git a/command/src/logging/access_logs.rs b/command/src/logging/access_logs.rs index 85231067a..0e57c0cdb 100644 --- a/command/src/logging/access_logs.rs +++ b/command/src/logging/access_logs.rs @@ -112,7 +112,10 @@ pub struct RequestRecord<'a> { pub server_rtt: Option, pub user_agent: Option<&'a str>, pub service_time: Duration, - pub response_time: Duration, + /// time from connecting to the backend until the end of the response + pub response_time: Option, + /// time between first byte of the request and last byte of the response + pub request_time: Duration, pub bytes_in: usize, pub bytes_out: usize, @@ -167,7 +170,7 @@ impl RequestRecord<'_> { message: self.message.duplicate(), protocol: self.protocol.duplicate(), request_id: self.context.request_id.into(), - response_time: self.response_time.as_micros() as u64, + response_time: self.response_time.map(|t| t.as_micros() as u64), server_rtt: self.server_rtt.map(|t| t.as_micros() as u64), service_time: self.service_time.as_micros() as u64, session_address: self.session_address.map(Into::into), @@ -178,6 +181,7 @@ impl RequestRecord<'_> { user_agent: self.user_agent.duplicate(), tag: self.tag.duplicate(), time: self.precise_time.into(), + request_time: Some(self.request_time.as_micros() as u64), }) } } diff --git a/command/src/logging/logs.rs b/command/src/logging/logs.rs index 8927b8903..b8f1181c9 100644 --- a/command/src/logging/logs.rs +++ b/command/src/logging/logs.rs @@ -267,13 +267,14 @@ impl InnerLogger { log.tag, ], standard: { - formats: ["{} {} {} {}/{}/{}/{} {} {} [{}] {} {}{}\n"], + formats: ["{} {} {} {}/{}/{}/{}/{} {} {} [{}] {} {}{}\n"], args: [ log.context, log.session_address.as_string_or("-"), log.backend_address.as_string_or("-"), - LogDuration(Some(log.response_time)), + LogDuration(Some(log.request_time)), LogDuration(Some(log.service_time)), + LogDuration(log.response_time), LogDuration(log.client_rtt), LogDuration(log.server_rtt), log.bytes_in, @@ -285,7 +286,7 @@ impl InnerLogger { ] }, colored: { - formats: ["\x1b[;1m{}\x1b[m {} {} {}/{}/{}/{} {} {} \x1b[2m[{}] \x1b[;1m{} {:#}\x1b[m{}\n"], + formats: ["\x1b[;1m{}\x1b[m {} {} {}/{}/{}/{}/{} {} {} \x1b[2m[{}] \x1b[;1m{} {:#}\x1b[m{}\n"], args: @, } }, diff --git a/lib/src/lib.rs b/lib/src/lib.rs index 6cc2282c3..62f27d265 100644 --- a/lib/src/lib.rs +++ b/lib/src/lib.rs @@ -1026,7 +1026,8 @@ impl SessionMetrics { } } - pub fn response_time(&self) -> Duration { + /// time elapsed since the beginning of the session + pub fn request_time(&self) -> Duration { match self.start { Some(start) => Instant::now() - start, None => Duration::from_secs(0), @@ -1061,14 +1062,14 @@ impl SessionMetrics { } pub fn register_end_of_session(&self, context: &LogContext) { - let response_time = self.response_time(); + let request_time = self.request_time(); let service_time = self.service_time(); if let Some(cluster_id) = context.cluster_id { - time!("response_time", cluster_id, response_time.as_millis()); + time!("request_time", cluster_id, request_time.as_millis()); time!("service_time", cluster_id, service_time.as_millis()); } - time!("response_time", response_time.as_millis()); + time!("request_time", request_time.as_millis()); time!("service_time", service_time.as_millis()); if let Some(backend_id) = self.backend_id.as_ref() { diff --git a/lib/src/protocol/kawa_h1/mod.rs b/lib/src/protocol/kawa_h1/mod.rs index e5feaab79..0ba8e3a66 100644 --- a/lib/src/protocol/kawa_h1/mod.rs +++ b/lib/src/protocol/kawa_h1/mod.rs @@ -940,7 +940,8 @@ impl Http Pipe { client_rtt: socket_rtt(self.front_socket()), server_rtt: self.backend_socket.as_ref().and_then(socket_rtt), service_time: metrics.service_time(), - response_time: metrics.response_time(), + response_time: metrics.backend_response_time(), + request_time: metrics.request_time(), bytes_in: metrics.bin, bytes_out: metrics.bout, user_agent: None diff --git a/lib/src/tcp.rs b/lib/src/tcp.rs index 9307808a6..70de45ad6 100644 --- a/lib/src/tcp.rs +++ b/lib/src/tcp.rs @@ -225,7 +225,8 @@ impl TcpSession { server_rtt: None, user_agent: None, service_time: self.metrics.service_time(), - response_time: self.metrics.response_time(), + response_time: self.metrics.backend_response_time(), + request_time: self.metrics.request_time(), bytes_in: self.metrics.bin, bytes_out: self.metrics.bout );