From 8e248b9571e0f1627ded1d650f6b7d2351224462 Mon Sep 17 00:00:00 2001 From: Cursor Agent Date: Wed, 22 Oct 2025 12:38:36 +0000 Subject: [PATCH 1/5] feat: Add Server-Timing header support Co-authored-by: contact --- src/render.rs | 16 +++++++++++-- src/webserver/http.rs | 22 ++++++++++++++++- src/webserver/mod.rs | 1 + src/webserver/server_timing.rs | 43 ++++++++++++++++++++++++++++++++++ 4 files changed, 79 insertions(+), 3 deletions(-) create mode 100644 src/webserver/server_timing.rs diff --git a/src/render.rs b/src/render.rs index aecd118b..52b635a2 100644 --- a/src/render.rs +++ b/src/render.rs @@ -80,7 +80,7 @@ pub enum PageContext { /// Handles the first SQL statements, before the headers have been sent to pub struct HeaderContext { app_state: Arc, - request_context: RequestContext, + pub request_context: RequestContext, pub writer: ResponseWriter, response: HttpResponseBuilder, has_status: bool, @@ -368,7 +368,13 @@ impl HeaderContext { Ok(PageContext::Header(self)) } - async fn start_body(self, data: JsonValue) -> anyhow::Result { + async fn start_body(mut self, data: JsonValue) -> anyhow::Result { + if let Some(ref timing) = self.request_context.server_timing { + let header_value = timing.as_header_value(); + if !header_value.is_empty() { + self.response.insert_header(("Server-Timing", header_value)); + } + } let html_renderer = HtmlRenderContext::new(self.app_state, self.request_context, self.writer, data) .await @@ -382,6 +388,12 @@ impl HeaderContext { } pub fn close(mut self) -> HttpResponse { + if let Some(ref timing) = self.request_context.server_timing { + let header_value = timing.as_header_value(); + if !header_value.is_empty() { + self.response.insert_header(("Server-Timing", header_value)); + } + } self.response.finish() } } diff --git a/src/webserver/http.rs b/src/webserver/http.rs index 88c9966e..d41b07b5 100644 --- a/src/webserver/http.rs +++ b/src/webserver/http.rs @@ -7,6 +7,7 @@ use crate::webserver::content_security_policy::ContentSecurityPolicy; use crate::webserver::database::execute_queries::stop_at_first_error; use crate::webserver::database::{execute_queries::stream_query_results_with_conn, DbItem}; use crate::webserver::http_request_info::extract_request_info; +use crate::webserver::server_timing::ServerTiming; use crate::webserver::ErrorWithStatus; use crate::{AppConfig, AppState, ParsedSqlFile, DEFAULT_404_FILE}; use actix_web::dev::{fn_service, ServiceFactory, ServiceRequest}; @@ -46,6 +47,7 @@ pub struct RequestContext { pub is_embedded: bool, pub source_path: PathBuf, pub content_security_policy: ContentSecurityPolicy, + pub server_timing: Option, } async fn stream_response(stream: impl Stream, mut renderer: AnyRenderBodyContext) { @@ -104,7 +106,14 @@ async fn build_response_header_and_stream>( let writer = ResponseWriter::new(sender); let mut head_context = HeaderContext::new(app_state, request_context, writer); let mut stream = Box::pin(database_entries); + let mut first_row = true; while let Some(item) = stream.next().await { + if first_row { + if let Some(ref mut timing) = head_context.request_context.server_timing { + timing.record("query"); + } + first_row = false; + } let page_context = match item { DbItem::Row(data) => head_context.handle_row(data).await?, DbItem::FinishedQuery => { @@ -167,14 +176,24 @@ async fn render_sql( let app_state = srv_req .app_data::>() .ok_or_else(|| ErrorInternalServerError("no state"))? - .clone() // Cheap reference count increase + .clone() .into_inner(); + let mut server_timing = if !app_state.config.environment.is_prod() { + Some(ServerTiming::new()) + } else { + None + }; + let mut req_param = extract_request_info(srv_req, Arc::clone(&app_state)) .await .map_err(|e| anyhow_err_to_actix(e, &app_state))?; log::debug!("Received a request with the following parameters: {req_param:?}"); + if let Some(ref mut timing) = server_timing { + timing.record("parse"); + } + let (resp_send, resp_recv) = tokio::sync::oneshot::channel::(); let source_path: PathBuf = sql_file.source_path.clone(); actix_web::rt::spawn(async move { @@ -182,6 +201,7 @@ async fn render_sql( is_embedded: req_param.get_variables.contains_key("_sqlpage_embed"), source_path, content_security_policy: ContentSecurityPolicy::with_random_nonce(), + server_timing, }; let mut conn = None; let database_entries_stream = diff --git a/src/webserver/mod.rs b/src/webserver/mod.rs index 9a74cc04..484ad40d 100644 --- a/src/webserver/mod.rs +++ b/src/webserver/mod.rs @@ -38,6 +38,7 @@ pub mod http_client; pub mod http_request_info; mod https; pub mod request_variables; +pub mod server_timing; pub use database::Database; pub use error_with_status::ErrorWithStatus; diff --git a/src/webserver/server_timing.rs b/src/webserver/server_timing.rs new file mode 100644 index 00000000..47a71dae --- /dev/null +++ b/src/webserver/server_timing.rs @@ -0,0 +1,43 @@ +use std::time::Instant; + +#[derive(Debug, Clone)] +pub struct ServerTiming { + start: Instant, + events: Vec, +} + +#[derive(Debug, Clone)] +struct TimingEvent { + name: &'static str, + duration_ms: f64, +} + +impl ServerTiming { + #[must_use] + pub fn new() -> Self { + Self { + start: Instant::now(), + events: Vec::new(), + } + } + + pub fn record(&mut self, name: &'static str) { + let duration_ms = self.start.elapsed().as_secs_f64() * 1000.0; + self.events.push(TimingEvent { name, duration_ms }); + } + + #[must_use] + pub fn as_header_value(&self) -> String { + self.events + .iter() + .map(|event| format!("{};dur={:.2}", event.name, event.duration_ms)) + .collect::>() + .join(", ") + } +} + +impl Default for ServerTiming { + fn default() -> Self { + Self::new() + } +} From faf19a66603feef2e7f3f07899fbacb7e2b3c672 Mon Sep 17 00:00:00 2001 From: Cursor Agent Date: Wed, 22 Oct 2025 19:47:39 +0000 Subject: [PATCH 2/5] feat: Add Server-Timing header to track request performance Co-authored-by: contact --- src/render.rs | 21 +++--- src/webserver/database/execute_queries.rs | 8 ++- src/webserver/http.rs | 42 +++++------ src/webserver/http_request_info.rs | 4 ++ src/webserver/server_timing.rs | 88 ++++++++++++++++++++++- 5 files changed, 123 insertions(+), 40 deletions(-) diff --git a/src/render.rs b/src/render.rs index 52b635a2..520d5576 100644 --- a/src/render.rs +++ b/src/render.rs @@ -368,13 +368,15 @@ impl HeaderContext { Ok(PageContext::Header(self)) } - async fn start_body(mut self, data: JsonValue) -> anyhow::Result { - if let Some(ref timing) = self.request_context.server_timing { - let header_value = timing.as_header_value(); - if !header_value.is_empty() { - self.response.insert_header(("Server-Timing", header_value)); - } + fn add_server_timing_header(&mut self) { + let header_value = self.request_context.server_timing.as_header_value(); + if !header_value.is_empty() { + self.response.insert_header(("Server-Timing", header_value)); } + } + + async fn start_body(mut self, data: JsonValue) -> anyhow::Result { + self.add_server_timing_header(); let html_renderer = HtmlRenderContext::new(self.app_state, self.request_context, self.writer, data) .await @@ -388,12 +390,7 @@ impl HeaderContext { } pub fn close(mut self) -> HttpResponse { - if let Some(ref timing) = self.request_context.server_timing { - let header_value = timing.as_header_value(); - if !header_value.is_empty() { - self.response.insert_header(("Server-Timing", header_value)); - } - } + self.add_server_timing_header(); self.response.finish() } } diff --git a/src/webserver/database/execute_queries.rs b/src/webserver/database/execute_queries.rs index 80883e24..352cd7b3 100644 --- a/src/webserver/database/execute_queries.rs +++ b/src/webserver/database/execute_queries.rs @@ -52,13 +52,13 @@ pub fn stream_query_results_with_conn<'a>( for res in &sql_file.statements { match res { ParsedStatement::CsvImport(csv_import) => { - let connection = take_connection(&request.app_state.db, db_connection).await?; + let connection = take_connection(&request.app_state.db, db_connection, request).await?; log::debug!("Executing CSV import: {csv_import:?}"); run_csv_import(connection, csv_import, request).await.with_context(|| format!("Failed to import the CSV file {:?} into the table {:?}", csv_import.uploaded_file, csv_import.table_name))?; }, ParsedStatement::StmtWithParams(stmt) => { let query = bind_parameters(stmt, request, db_connection).await?; - let connection = take_connection(&request.app_state.db, db_connection).await?; + let connection = take_connection(&request.app_state.db, db_connection, request).await?; log::trace!("Executing query {:?}", query.sql); let mut stream = connection.fetch_many(query); let mut error = None; @@ -192,7 +192,7 @@ async fn execute_set_variable_query<'a>( source_file: &Path, ) -> anyhow::Result<()> { let query = bind_parameters(statement, request, db_connection).await?; - let connection = take_connection(&request.app_state.db, db_connection).await?; + let connection = take_connection(&request.app_state.db, db_connection, request).await?; log::debug!( "Executing query to set the {variable:?} variable: {:?}", query.sql @@ -276,6 +276,7 @@ fn vars_and_name<'a, 'b>( async fn take_connection<'a>( db: &'a Database, conn: &'a mut DbConn, + request: &RequestInfo, ) -> anyhow::Result<&'a mut PoolConnection> { if let Some(c) = conn { return Ok(c); @@ -283,6 +284,7 @@ async fn take_connection<'a>( match db.connection.acquire().await { Ok(c) => { log::debug!("Acquired a database connection"); + request.server_timing.borrow_mut().record("db_conn"); *conn = Some(c); Ok(conn.as_mut().unwrap()) } diff --git a/src/webserver/http.rs b/src/webserver/http.rs index d41b07b5..30e0eaa9 100644 --- a/src/webserver/http.rs +++ b/src/webserver/http.rs @@ -47,7 +47,7 @@ pub struct RequestContext { pub is_embedded: bool, pub source_path: PathBuf, pub content_security_policy: ContentSecurityPolicy, - pub server_timing: Option, + pub server_timing: ServerTiming, } async fn stream_response(stream: impl Stream, mut renderer: AnyRenderBodyContext) { @@ -106,16 +106,12 @@ async fn build_response_header_and_stream>( let writer = ResponseWriter::new(sender); let mut head_context = HeaderContext::new(app_state, request_context, writer); let mut stream = Box::pin(database_entries); - let mut first_row = true; while let Some(item) = stream.next().await { - if first_row { - if let Some(ref mut timing) = head_context.request_context.server_timing { - timing.record("query"); - } - first_row = false; - } let page_context = match item { - DbItem::Row(data) => head_context.handle_row(data).await?, + DbItem::Row(data) => { + head_context.request_context.server_timing.record("row"); + head_context.handle_row(data).await? + } DbItem::FinishedQuery => { log::debug!("finished query"); continue; @@ -172,6 +168,7 @@ enum ResponseWithWriter { async fn render_sql( srv_req: &mut ServiceRequest, sql_file: Arc, + server_timing: ServerTiming, ) -> actix_web::Result { let app_state = srv_req .app_data::>() @@ -179,29 +176,23 @@ async fn render_sql( .clone() .into_inner(); - let mut server_timing = if !app_state.config.environment.is_prod() { - Some(ServerTiming::new()) - } else { - None - }; - - let mut req_param = extract_request_info(srv_req, Arc::clone(&app_state)) - .await - .map_err(|e| anyhow_err_to_actix(e, &app_state))?; + let mut req_param = + extract_request_info(srv_req, Arc::clone(&app_state), server_timing.clone()) + .await + .map_err(|e| anyhow_err_to_actix(e, &app_state))?; log::debug!("Received a request with the following parameters: {req_param:?}"); - if let Some(ref mut timing) = server_timing { - timing.record("parse"); - } + req_param.server_timing.borrow_mut().record("parse"); let (resp_send, resp_recv) = tokio::sync::oneshot::channel::(); let source_path: PathBuf = sql_file.source_path.clone(); actix_web::rt::spawn(async move { + let server_timing_for_context = req_param.server_timing.borrow().clone(); let request_context = RequestContext { is_embedded: req_param.get_variables.contains_key("_sqlpage_embed"), source_path, content_security_policy: ContentSecurityPolicy::with_random_nonce(), - server_timing, + server_timing: server_timing_for_context, }; let mut conn = None; let database_entries_stream = @@ -295,13 +286,18 @@ async fn process_sql_request( sql_path: PathBuf, ) -> actix_web::Result { let app_state: &web::Data = req.app_data().expect("app_state"); + let mut server_timing = ServerTiming::new(!app_state.config.environment.is_prod()); + server_timing.record("request"); + let sql_file = app_state .sql_file_cache .get_with_privilege(app_state, &sql_path, false) .await .with_context(|| format!("Unable to read SQL file \"{}\"", sql_path.display())) .map_err(|e| anyhow_err_to_actix(e, app_state))?; - render_sql(req, sql_file).await + server_timing.record("sql_file"); + + render_sql(req, sql_file, server_timing).await } async fn serve_file( diff --git a/src/webserver/http_request_info.rs b/src/webserver/http_request_info.rs index 23675a51..7797af21 100644 --- a/src/webserver/http_request_info.rs +++ b/src/webserver/http_request_info.rs @@ -42,6 +42,7 @@ pub struct RequestInfo { pub clone_depth: u8, pub raw_body: Option>, pub oidc_claims: Option, + pub server_timing: std::cell::RefCell, } impl RequestInfo { @@ -62,6 +63,7 @@ impl RequestInfo { clone_depth: self.clone_depth + 1, raw_body: self.raw_body.clone(), oidc_claims: self.oidc_claims.clone(), + server_timing: std::cell::RefCell::new(self.server_timing.borrow().clone()), } } } @@ -78,6 +80,7 @@ impl Clone for RequestInfo { pub(crate) async fn extract_request_info( req: &mut ServiceRequest, app_state: Arc, + server_timing: super::server_timing::ServerTiming, ) -> anyhow::Result { let (http_req, payload) = req.parts_mut(); let method = http_req.method().clone(); @@ -123,6 +126,7 @@ pub(crate) async fn extract_request_info( clone_depth: 0, raw_body, oidc_claims, + server_timing: std::cell::RefCell::new(server_timing), }) } diff --git a/src/webserver/server_timing.rs b/src/webserver/server_timing.rs index 47a71dae..ee89fb55 100644 --- a/src/webserver/server_timing.rs +++ b/src/webserver/server_timing.rs @@ -2,6 +2,7 @@ use std::time::Instant; #[derive(Debug, Clone)] pub struct ServerTiming { + enabled: bool, start: Instant, events: Vec, } @@ -14,20 +15,32 @@ struct TimingEvent { impl ServerTiming { #[must_use] - pub fn new() -> Self { + pub fn new(enabled: bool) -> Self { Self { + enabled, start: Instant::now(), events: Vec::new(), } } pub fn record(&mut self, name: &'static str) { + if !self.enabled { + return; + } let duration_ms = self.start.elapsed().as_secs_f64() * 1000.0; self.events.push(TimingEvent { name, duration_ms }); } + #[must_use] + pub fn is_enabled(&self) -> bool { + self.enabled + } + #[must_use] pub fn as_header_value(&self) -> String { + if !self.enabled { + return String::new(); + } self.events .iter() .map(|event| format!("{};dur={:.2}", event.name, event.duration_ms)) @@ -38,6 +51,77 @@ impl ServerTiming { impl Default for ServerTiming { fn default() -> Self { - Self::new() + Self::new(false) + } +} + +#[cfg(test)] +mod tests { + use super::*; + use std::thread; + use std::time::Duration; + + #[test] + fn test_disabled_timing() { + let mut timing = ServerTiming::new(false); + assert!(!timing.is_enabled()); + timing.record("event1"); + timing.record("event2"); + assert_eq!(timing.as_header_value(), ""); + } + + #[test] + fn test_enabled_timing() { + let mut timing = ServerTiming::new(true); + assert!(timing.is_enabled()); + timing.record("event1"); + thread::sleep(Duration::from_millis(10)); + timing.record("event2"); + let header = timing.as_header_value(); + assert!(header.contains("event1;dur=")); + assert!(header.contains("event2;dur=")); + assert!(header.contains(", ")); + } + + #[test] + fn test_timing_values_increase() { + let mut timing = ServerTiming::new(true); + timing.record("first"); + thread::sleep(Duration::from_millis(5)); + timing.record("second"); + assert_eq!(timing.events.len(), 2); + assert!(timing.events[1].duration_ms > timing.events[0].duration_ms); + } + + #[test] + fn test_default_is_disabled() { + let timing = ServerTiming::default(); + assert!(!timing.is_enabled()); + } + + #[test] + fn test_header_format() { + let mut timing = ServerTiming::new(true); + timing.events.push(TimingEvent { + name: "test", + duration_ms: 123.456, + }); + let header = timing.as_header_value(); + assert_eq!(header, "test;dur=123.46"); + } + + #[test] + fn test_multiple_events_format() { + let mut timing = ServerTiming::new(true); + timing.events.push(TimingEvent { + name: "first", + duration_ms: 10.5, + }); + timing.events.push(TimingEvent { + name: "second", + duration_ms: 25.75, + }); + let header = timing.as_header_value(); + assert_eq!(header, "first;dur=10.50, second;dur=25.75"); } } From 5c415984bf6eb1630f9cc6aa5e0627bd3ed98d81 Mon Sep 17 00:00:00 2001 From: Cursor Agent Date: Wed, 22 Oct 2025 20:03:09 +0000 Subject: [PATCH 3/5] Refactor Server-Timing header generation and add tests This commit refactors the Server-Timing header generation to be more efficient and adds comprehensive tests for its behavior in development and production environments. It also includes a new test SQL file for server timing verification. Co-authored-by: contact --- src/render.rs | 3 +- src/webserver/http.rs | 2 +- src/webserver/server_timing.rs | 109 +++++---------------------- tests/mod.rs | 1 + tests/server_timing/mod.rs | 100 ++++++++++++++++++++++++ tests/server_timing/simple_query.sql | 2 + 6 files changed, 124 insertions(+), 93 deletions(-) create mode 100644 tests/server_timing/mod.rs create mode 100644 tests/server_timing/simple_query.sql diff --git a/src/render.rs b/src/render.rs index 520d5576..476e3638 100644 --- a/src/render.rs +++ b/src/render.rs @@ -371,7 +371,8 @@ impl HeaderContext { fn add_server_timing_header(&mut self) { let header_value = self.request_context.server_timing.as_header_value(); if !header_value.is_empty() { - self.response.insert_header(("Server-Timing", header_value)); + self.response + .insert_header(("Server-Timing", header_value.to_string())); } } diff --git a/src/webserver/http.rs b/src/webserver/http.rs index 30e0eaa9..7ce3e022 100644 --- a/src/webserver/http.rs +++ b/src/webserver/http.rs @@ -182,7 +182,7 @@ async fn render_sql( .map_err(|e| anyhow_err_to_actix(e, &app_state))?; log::debug!("Received a request with the following parameters: {req_param:?}"); - req_param.server_timing.borrow_mut().record("parse"); + req_param.server_timing.borrow_mut().record("parse_req"); let (resp_send, resp_recv) = tokio::sync::oneshot::channel::(); let source_path: PathBuf = sql_file.source_path.clone(); diff --git a/src/webserver/server_timing.rs b/src/webserver/server_timing.rs index ee89fb55..11a524db 100644 --- a/src/webserver/server_timing.rs +++ b/src/webserver/server_timing.rs @@ -3,14 +3,8 @@ use std::time::Instant; #[derive(Debug, Clone)] pub struct ServerTiming { enabled: bool, - start: Instant, - events: Vec, -} - -#[derive(Debug, Clone)] -struct TimingEvent { - name: &'static str, - duration_ms: f64, + previous_event: Instant, + header: String, } impl ServerTiming { @@ -18,8 +12,8 @@ impl ServerTiming { pub fn new(enabled: bool) -> Self { Self { enabled, - start: Instant::now(), - events: Vec::new(), + previous_event: Instant::now(), + header: String::new(), } } @@ -27,8 +21,15 @@ impl ServerTiming { if !self.enabled { return; } - let duration_ms = self.start.elapsed().as_secs_f64() * 1000.0; - self.events.push(TimingEvent { name, duration_ms }); + let now = Instant::now(); + let duration_ms = (now - self.previous_event).as_secs_f64() * 1000.0; + self.previous_event = now; + + if !self.header.is_empty() { + self.header.push_str(", "); + } + use std::fmt::Write; + write!(&mut self.header, "{};dur={:.2}", name, duration_ms).unwrap(); } #[must_use] @@ -37,15 +38,12 @@ impl ServerTiming { } #[must_use] - pub fn as_header_value(&self) -> String { - if !self.enabled { - return String::new(); + pub fn as_header_value(&self) -> &str { + if self.enabled { + &self.header + } else { + "" } - self.events - .iter() - .map(|event| format!("{};dur={:.2}", event.name, event.duration_ms)) - .collect::>() - .join(", ") } } @@ -54,74 +52,3 @@ impl Default for ServerTiming { Self::new(false) } } - -#[cfg(test)] -mod tests { - use super::*; - use std::thread; - use std::time::Duration; - - #[test] - fn test_disabled_timing() { - let mut timing = ServerTiming::new(false); - assert!(!timing.is_enabled()); - timing.record("event1"); - timing.record("event2"); - assert_eq!(timing.as_header_value(), ""); - } - - #[test] - fn test_enabled_timing() { - let mut timing = ServerTiming::new(true); - assert!(timing.is_enabled()); - timing.record("event1"); - thread::sleep(Duration::from_millis(10)); - timing.record("event2"); - let header = timing.as_header_value(); - assert!(header.contains("event1;dur=")); - assert!(header.contains("event2;dur=")); - assert!(header.contains(", ")); - } - - #[test] - fn test_timing_values_increase() { - let mut timing = ServerTiming::new(true); - timing.record("first"); - thread::sleep(Duration::from_millis(5)); - timing.record("second"); - assert_eq!(timing.events.len(), 2); - assert!(timing.events[1].duration_ms > timing.events[0].duration_ms); - } - - #[test] - fn test_default_is_disabled() { - let timing = ServerTiming::default(); - assert!(!timing.is_enabled()); - } - - #[test] - fn test_header_format() { - let mut timing = ServerTiming::new(true); - timing.events.push(TimingEvent { - name: "test", - duration_ms: 123.456, - }); - let header = timing.as_header_value(); - assert_eq!(header, "test;dur=123.46"); - } - - #[test] - fn test_multiple_events_format() { - let mut timing = ServerTiming::new(true); - timing.events.push(TimingEvent { - name: "first", - duration_ms: 10.5, - }); - timing.events.push(TimingEvent { - name: "second", - duration_ms: 25.75, - }); - let header = timing.as_header_value(); - assert_eq!(header, "first;dur=10.50, second;dur=25.75"); - } -} diff --git a/tests/mod.rs b/tests/mod.rs index 9eab13f2..aeaf5dc9 100644 --- a/tests/mod.rs +++ b/tests/mod.rs @@ -5,6 +5,7 @@ mod core; mod data_formats; mod errors; mod requests; +mod server_timing; pub mod sql_test_files; mod transactions; mod uploads; diff --git a/tests/server_timing/mod.rs b/tests/server_timing/mod.rs new file mode 100644 index 00000000..3a4fd815 --- /dev/null +++ b/tests/server_timing/mod.rs @@ -0,0 +1,100 @@ +use actix_web::{http::StatusCode, test}; +use sqlpage::webserver::http::main_handler; + +use crate::common::{get_request_to, make_app_data_from_config, test_config}; + +#[actix_web::test] +async fn test_server_timing_disabled_in_production() -> actix_web::Result<()> { + let mut config = test_config(); + config.environment = sqlpage::app_config::DevOrProd::Production; + let app_data = make_app_data_from_config(config).await; + + let req = + crate::common::get_request_to_with_data("/tests/server_timing/simple_query.sql", app_data) + .await? + .to_srv_request(); + let resp = main_handler(req).await?; + + assert_eq!(resp.status(), StatusCode::OK); + assert!( + resp.headers().get("Server-Timing").is_none(), + "Server-Timing header should not be present in production mode" + ); + Ok(()) +} + +#[actix_web::test] +async fn test_server_timing_enabled_in_development() -> actix_web::Result<()> { + let mut config = test_config(); + config.environment = sqlpage::app_config::DevOrProd::Development; + let app_data = make_app_data_from_config(config).await; + + let req = + crate::common::get_request_to_with_data("/tests/server_timing/simple_query.sql", app_data) + .await? + .to_srv_request(); + let resp = main_handler(req).await?; + + assert_eq!(resp.status(), StatusCode::OK); + let server_timing_header = resp + .headers() + .get("Server-Timing") + .expect("Server-Timing header should be present in development mode"); + let header_value = server_timing_header.to_str().unwrap(); + + assert!( + header_value.contains("request;dur="), + "Should contain request timing: {header_value}" + ); + assert!( + header_value.contains("sql_file;dur="), + "Should contain sql_file timing: {header_value}" + ); + assert!( + header_value.contains("parse_req;dur="), + "Should contain parse_req timing: {header_value}" + ); + assert!( + header_value.contains("db_conn;dur="), + "Should contain db_conn timing: {header_value}" + ); + assert!( + header_value.contains("row;dur="), + "Should contain row timing: {header_value}" + ); + + Ok(()) +} + +#[actix_web::test] +async fn test_server_timing_format() -> actix_web::Result<()> { + let req = get_request_to("/tests/server_timing/simple_query.sql") + .await? + .to_srv_request(); + let resp = main_handler(req).await?; + + assert_eq!(resp.status(), StatusCode::OK); + let server_timing_header = resp.headers().get("Server-Timing").unwrap(); + let header_value = server_timing_header.to_str().unwrap(); + + let parts: Vec<&str> = header_value.split(", ").collect(); + assert!(parts.len() >= 4, "Should have at least 4 timing events"); + + for part in parts { + assert!( + part.contains(";dur="), + "Each part should have name;dur= format: {part}" + ); + let dur_parts: Vec<&str> = part.split(";dur=").collect(); + assert_eq!(dur_parts.len(), 2, "Should have name and duration: {part}"); + let duration: f64 = dur_parts[1] + .parse() + .expect("Duration should be a valid number"); + assert!( + duration >= 0.0, + "Duration should be non-negative: {duration}" + ); + } + + Ok(()) +} diff --git a/tests/server_timing/simple_query.sql b/tests/server_timing/simple_query.sql new file mode 100644 index 00000000..738ec0d0 --- /dev/null +++ b/tests/server_timing/simple_query.sql @@ -0,0 +1,2 @@ +SELECT 'text' AS component, 'Server timing test' AS contents; +SELECT 'Hello' AS value FROM (SELECT 1 UNION ALL SELECT 2 UNION ALL SELECT 3); From 38e08d78d1bce3574762008da9a90c312e84af4d Mon Sep 17 00:00:00 2001 From: Cursor Agent Date: Wed, 22 Oct 2025 22:08:10 +0000 Subject: [PATCH 4/5] Refactor: Pass ServerTiming to extract_request_info Co-authored-by: contact --- src/webserver/http_request_info.rs | 9 ++++++--- src/webserver/server_timing.rs | 4 ++-- tests/server_timing/mod.rs | 22 +++++++++++++--------- tests/server_timing/simple_query.sql | 2 -- 4 files changed, 21 insertions(+), 16 deletions(-) delete mode 100644 tests/server_timing/simple_query.sql diff --git a/src/webserver/http_request_info.rs b/src/webserver/http_request_info.rs index 7797af21..a6e459f2 100644 --- a/src/webserver/http_request_info.rs +++ b/src/webserver/http_request_info.rs @@ -288,7 +288,8 @@ mod test { serde_json::from_str::(r#"{"listen_on": "localhost:1234"}"#).unwrap(); let mut service_request = TestRequest::default().to_srv_request(); let app_data = Arc::new(AppState::init(&config).await.unwrap()); - let request_info = extract_request_info(&mut service_request, app_data) + let server_timing = super::server_timing::ServerTiming::new(false); + let request_info = extract_request_info(&mut service_request, app_data, server_timing) .await .unwrap(); assert_eq!(request_info.post_variables.len(), 0); @@ -306,7 +307,8 @@ mod test { .set_payload("my_array[]=3&my_array[]=Hello%20World&repeated=1&repeated=2") .to_srv_request(); let app_data = Arc::new(AppState::init(&config).await.unwrap()); - let request_info = extract_request_info(&mut service_request, app_data) + let server_timing = super::server_timing::ServerTiming::new(false); + let request_info = extract_request_info(&mut service_request, app_data, server_timing) .await .unwrap(); assert_eq!( @@ -355,7 +357,8 @@ mod test { ) .to_srv_request(); let app_data = Arc::new(AppState::init(&config).await.unwrap()); - let request_info = extract_request_info(&mut service_request, app_data) + let server_timing = super::server_timing::ServerTiming::new(false); + let request_info = extract_request_info(&mut service_request, app_data, server_timing) .await .unwrap(); assert_eq!( diff --git a/src/webserver/server_timing.rs b/src/webserver/server_timing.rs index 11a524db..08ed5b5a 100644 --- a/src/webserver/server_timing.rs +++ b/src/webserver/server_timing.rs @@ -1,3 +1,4 @@ +use std::fmt::Write; use std::time::Instant; #[derive(Debug, Clone)] @@ -28,8 +29,7 @@ impl ServerTiming { if !self.header.is_empty() { self.header.push_str(", "); } - use std::fmt::Write; - write!(&mut self.header, "{};dur={:.2}", name, duration_ms).unwrap(); + write!(&mut self.header, "{name};dur={duration_ms:.2}").unwrap(); } #[must_use] diff --git a/tests/server_timing/mod.rs b/tests/server_timing/mod.rs index 3a4fd815..718eea5d 100644 --- a/tests/server_timing/mod.rs +++ b/tests/server_timing/mod.rs @@ -9,10 +9,12 @@ async fn test_server_timing_disabled_in_production() -> actix_web::Result<()> { config.environment = sqlpage::app_config::DevOrProd::Production; let app_data = make_app_data_from_config(config).await; - let req = - crate::common::get_request_to_with_data("/tests/server_timing/simple_query.sql", app_data) - .await? - .to_srv_request(); + let req = crate::common::get_request_to_with_data( + "/tests/sql_test_files/it_works_simple.sql", + app_data, + ) + .await? + .to_srv_request(); let resp = main_handler(req).await?; assert_eq!(resp.status(), StatusCode::OK); @@ -29,10 +31,12 @@ async fn test_server_timing_enabled_in_development() -> actix_web::Result<()> { config.environment = sqlpage::app_config::DevOrProd::Development; let app_data = make_app_data_from_config(config).await; - let req = - crate::common::get_request_to_with_data("/tests/server_timing/simple_query.sql", app_data) - .await? - .to_srv_request(); + let req = crate::common::get_request_to_with_data( + "/tests/sql_test_files/it_works_simple.sql", + app_data, + ) + .await? + .to_srv_request(); let resp = main_handler(req).await?; assert_eq!(resp.status(), StatusCode::OK); @@ -68,7 +72,7 @@ async fn test_server_timing_enabled_in_development() -> actix_web::Result<()> { #[actix_web::test] async fn test_server_timing_format() -> actix_web::Result<()> { - let req = get_request_to("/tests/server_timing/simple_query.sql") + let req = get_request_to("/tests/sql_test_files/it_works_simple.sql") .await? .to_srv_request(); let resp = main_handler(req).await?; diff --git a/tests/server_timing/simple_query.sql b/tests/server_timing/simple_query.sql deleted file mode 100644 index 738ec0d0..00000000 --- a/tests/server_timing/simple_query.sql +++ /dev/null @@ -1,2 +0,0 @@ -SELECT 'text' AS component, 'Server timing test' AS contents; -SELECT 'Hello' AS value FROM (SELECT 1 UNION ALL SELECT 2 UNION ALL SELECT 3); From 06df761eee152f42cdbf3275aa64f7b63cb047a9 Mon Sep 17 00:00:00 2001 From: lovasoa Date: Thu, 23 Oct 2025 12:42:09 +0200 Subject: [PATCH 5/5] Refactor: Update ServerTiming to use Arc and simplify header generation This commit modifies the ServerTiming structure to utilize Arc for thread-safe reference counting, enhancing performance and memory management. The header generation logic is streamlined, and related code is updated to reflect these changes. Additionally, tests are adjusted to ensure proper functionality with the new implementation. Co-authored-by: contact --- src/render.rs | 6 +- src/webserver/database/execute_queries.rs | 2 +- src/webserver/http.rs | 17 ++--- src/webserver/http_request_info.rs | 17 ++--- src/webserver/server_timing.rs | 78 ++++++++++++++--------- tests/server_timing/mod.rs | 10 +-- 6 files changed, 69 insertions(+), 61 deletions(-) diff --git a/src/render.rs b/src/render.rs index 476e3638..c9229ce7 100644 --- a/src/render.rs +++ b/src/render.rs @@ -369,10 +369,8 @@ impl HeaderContext { } fn add_server_timing_header(&mut self) { - let header_value = self.request_context.server_timing.as_header_value(); - if !header_value.is_empty() { - self.response - .insert_header(("Server-Timing", header_value.to_string())); + if let Some(header_value) = self.request_context.server_timing.header_value() { + self.response.insert_header(("Server-Timing", header_value)); } } diff --git a/src/webserver/database/execute_queries.rs b/src/webserver/database/execute_queries.rs index 352cd7b3..9f780f72 100644 --- a/src/webserver/database/execute_queries.rs +++ b/src/webserver/database/execute_queries.rs @@ -284,7 +284,7 @@ async fn take_connection<'a>( match db.connection.acquire().await { Ok(c) => { log::debug!("Acquired a database connection"); - request.server_timing.borrow_mut().record("db_conn"); + request.server_timing.record("db_conn"); *conn = Some(c); Ok(conn.as_mut().unwrap()) } diff --git a/src/webserver/http.rs b/src/webserver/http.rs index 7ce3e022..dbf3e208 100644 --- a/src/webserver/http.rs +++ b/src/webserver/http.rs @@ -47,7 +47,7 @@ pub struct RequestContext { pub is_embedded: bool, pub source_path: PathBuf, pub content_security_policy: ContentSecurityPolicy, - pub server_timing: ServerTiming, + pub server_timing: Arc, } async fn stream_response(stream: impl Stream, mut renderer: AnyRenderBodyContext) { @@ -176,23 +176,21 @@ async fn render_sql( .clone() .into_inner(); - let mut req_param = - extract_request_info(srv_req, Arc::clone(&app_state), server_timing.clone()) - .await - .map_err(|e| anyhow_err_to_actix(e, &app_state))?; + let mut req_param = extract_request_info(srv_req, Arc::clone(&app_state), server_timing) + .await + .map_err(|e| anyhow_err_to_actix(e, &app_state))?; log::debug!("Received a request with the following parameters: {req_param:?}"); - req_param.server_timing.borrow_mut().record("parse_req"); + req_param.server_timing.record("parse_req"); let (resp_send, resp_recv) = tokio::sync::oneshot::channel::(); let source_path: PathBuf = sql_file.source_path.clone(); actix_web::rt::spawn(async move { - let server_timing_for_context = req_param.server_timing.borrow().clone(); let request_context = RequestContext { is_embedded: req_param.get_variables.contains_key("_sqlpage_embed"), source_path, content_security_policy: ContentSecurityPolicy::with_random_nonce(), - server_timing: server_timing_for_context, + server_timing: Arc::clone(&req_param.server_timing), }; let mut conn = None; let database_entries_stream = @@ -286,8 +284,7 @@ async fn process_sql_request( sql_path: PathBuf, ) -> actix_web::Result { let app_state: &web::Data = req.app_data().expect("app_state"); - let mut server_timing = ServerTiming::new(!app_state.config.environment.is_prod()); - server_timing.record("request"); + let server_timing = ServerTiming::for_env(app_state.config.environment); let sql_file = app_state .sql_file_cache diff --git a/src/webserver/http_request_info.rs b/src/webserver/http_request_info.rs index a6e459f2..ff0f3114 100644 --- a/src/webserver/http_request_info.rs +++ b/src/webserver/http_request_info.rs @@ -1,3 +1,4 @@ +use crate::webserver::server_timing::ServerTiming; use crate::AppState; use actix_multipart::form::bytes::Bytes; use actix_multipart::form::tempfile::TempFile; @@ -42,7 +43,7 @@ pub struct RequestInfo { pub clone_depth: u8, pub raw_body: Option>, pub oidc_claims: Option, - pub server_timing: std::cell::RefCell, + pub server_timing: Arc, } impl RequestInfo { @@ -63,7 +64,7 @@ impl RequestInfo { clone_depth: self.clone_depth + 1, raw_body: self.raw_body.clone(), oidc_claims: self.oidc_claims.clone(), - server_timing: std::cell::RefCell::new(self.server_timing.borrow().clone()), + server_timing: Arc::clone(&self.server_timing), } } } @@ -80,7 +81,7 @@ impl Clone for RequestInfo { pub(crate) async fn extract_request_info( req: &mut ServiceRequest, app_state: Arc, - server_timing: super::server_timing::ServerTiming, + server_timing: ServerTiming, ) -> anyhow::Result { let (http_req, payload) = req.parts_mut(); let method = http_req.method().clone(); @@ -126,7 +127,7 @@ pub(crate) async fn extract_request_info( clone_depth: 0, raw_body, oidc_claims, - server_timing: std::cell::RefCell::new(server_timing), + server_timing: Arc::new(server_timing), }) } @@ -279,7 +280,7 @@ async fn is_file_field_empty( mod test { use super::super::http::SingleOrVec; use super::*; - use crate::app_config::AppConfig; + use crate::{app_config::AppConfig, webserver::server_timing::ServerTiming}; use actix_web::{http::header::ContentType, test::TestRequest}; #[actix_web::test] @@ -288,7 +289,7 @@ mod test { serde_json::from_str::(r#"{"listen_on": "localhost:1234"}"#).unwrap(); let mut service_request = TestRequest::default().to_srv_request(); let app_data = Arc::new(AppState::init(&config).await.unwrap()); - let server_timing = super::server_timing::ServerTiming::new(false); + let server_timing = ServerTiming::default(); let request_info = extract_request_info(&mut service_request, app_data, server_timing) .await .unwrap(); @@ -307,7 +308,7 @@ mod test { .set_payload("my_array[]=3&my_array[]=Hello%20World&repeated=1&repeated=2") .to_srv_request(); let app_data = Arc::new(AppState::init(&config).await.unwrap()); - let server_timing = super::server_timing::ServerTiming::new(false); + let server_timing = ServerTiming::default(); let request_info = extract_request_info(&mut service_request, app_data, server_timing) .await .unwrap(); @@ -357,7 +358,7 @@ mod test { ) .to_srv_request(); let app_data = Arc::new(AppState::init(&config).await.unwrap()); - let server_timing = super::server_timing::ServerTiming::new(false); + let server_timing = ServerTiming::enabled(false); let request_info = extract_request_info(&mut service_request, app_data, server_timing) .await .unwrap(); diff --git a/src/webserver/server_timing.rs b/src/webserver/server_timing.rs index 08ed5b5a..44ad4683 100644 --- a/src/webserver/server_timing.rs +++ b/src/webserver/server_timing.rs @@ -1,54 +1,70 @@ use std::fmt::Write; +use std::sync::Mutex; use std::time::Instant; -#[derive(Debug, Clone)] +use crate::app_config::DevOrProd; + +#[derive(Debug)] pub struct ServerTiming { enabled: bool, - previous_event: Instant, - header: String, + created_at: Instant, + events: Mutex>, } -impl ServerTiming { - #[must_use] - pub fn new(enabled: bool) -> Self { +#[derive(Debug)] +struct PerfEvent { + time: Instant, + name: &'static str, +} + +impl Default for ServerTiming { + fn default() -> Self { Self { - enabled, - previous_event: Instant::now(), - header: String::new(), + enabled: false, + created_at: Instant::now(), + events: Mutex::new(Vec::new()), } } +} - pub fn record(&mut self, name: &'static str) { - if !self.enabled { - return; - } - let now = Instant::now(); - let duration_ms = (now - self.previous_event).as_secs_f64() * 1000.0; - self.previous_event = now; - - if !self.header.is_empty() { - self.header.push_str(", "); +impl ServerTiming { + #[must_use] + pub fn enabled(enabled: bool) -> Self { + Self { + enabled, + ..Default::default() } - write!(&mut self.header, "{name};dur={duration_ms:.2}").unwrap(); } #[must_use] - pub fn is_enabled(&self) -> bool { - self.enabled + pub fn for_env(env: DevOrProd) -> Self { + Self::enabled(!env.is_prod()) } - #[must_use] - pub fn as_header_value(&self) -> &str { + pub fn record(&self, name: &'static str) { if self.enabled { - &self.header - } else { - "" + self.events.lock().unwrap().push(PerfEvent { + time: Instant::now(), + name, + }); } } -} -impl Default for ServerTiming { - fn default() -> Self { - Self::new(false) + pub fn header_value(&self) -> Option { + if !self.enabled { + return None; + } + let evts = self.events.lock().unwrap(); + let mut s = String::with_capacity(evts.len() * 16); + let mut last = self.created_at; + for (i, PerfEvent { name, time }) in evts.iter().enumerate() { + if i > 0 { + s.push_str(", "); + } + let millis = time.saturating_duration_since(last).as_millis(); + write!(&mut s, "{name};dur={millis}").ok()?; + last = *time; + } + Some(s) } } diff --git a/tests/server_timing/mod.rs b/tests/server_timing/mod.rs index 718eea5d..a64eef23 100644 --- a/tests/server_timing/mod.rs +++ b/tests/server_timing/mod.rs @@ -1,4 +1,4 @@ -use actix_web::{http::StatusCode, test}; +use actix_web::http::StatusCode; use sqlpage::webserver::http::main_handler; use crate::common::{get_request_to, make_app_data_from_config, test_config}; @@ -32,7 +32,7 @@ async fn test_server_timing_enabled_in_development() -> actix_web::Result<()> { let app_data = make_app_data_from_config(config).await; let req = crate::common::get_request_to_with_data( - "/tests/sql_test_files/it_works_simple.sql", + "/tests/sql_test_files/it_works_sqrt.sql", app_data, ) .await? @@ -46,10 +46,6 @@ async fn test_server_timing_enabled_in_development() -> actix_web::Result<()> { .expect("Server-Timing header should be present in development mode"); let header_value = server_timing_header.to_str().unwrap(); - assert!( - header_value.contains("request;dur="), - "Should contain request timing: {header_value}" - ); assert!( header_value.contains("sql_file;dur="), "Should contain sql_file timing: {header_value}" @@ -72,7 +68,7 @@ async fn test_server_timing_enabled_in_development() -> actix_web::Result<()> { #[actix_web::test] async fn test_server_timing_format() -> actix_web::Result<()> { - let req = get_request_to("/tests/sql_test_files/it_works_simple.sql") + let req = get_request_to("/tests/sql_test_files/it_works_sqrt.sql") .await? .to_srv_request(); let resp = main_handler(req).await?;