From 94ed34b5bacaf2d8d4e4b6c45863f3b79aa713e2 Mon Sep 17 00:00:00 2001 From: Brandon Thomas Date: Sat, 13 Aug 2022 02:27:21 -0400 Subject: [PATCH 1/3] Benchmarking library and begin implementation --- crates/lib/http_server_common/src/lib.rs | 1 + crates/lib/http_server_common/src/util/mod.rs | 1 + .../lib/http_server_common/src/util/timer.rs | 8 ++++ .../endpoints/users/get_profile.rs | 40 +++++++++++++++---- 4 files changed, 42 insertions(+), 8 deletions(-) create mode 100644 crates/lib/http_server_common/src/util/mod.rs create mode 100644 crates/lib/http_server_common/src/util/timer.rs diff --git a/crates/lib/http_server_common/src/lib.rs b/crates/lib/http_server_common/src/lib.rs index 3867702b0b..bb70593098 100644 --- a/crates/lib/http_server_common/src/lib.rs +++ b/crates/lib/http_server_common/src/lib.rs @@ -15,3 +15,4 @@ pub mod endpoints; pub mod error; pub mod request; pub mod response; +pub mod util; diff --git a/crates/lib/http_server_common/src/util/mod.rs b/crates/lib/http_server_common/src/util/mod.rs new file mode 100644 index 0000000000..44757340c1 --- /dev/null +++ b/crates/lib/http_server_common/src/util/mod.rs @@ -0,0 +1 @@ +pub mod timer; \ No newline at end of file diff --git a/crates/lib/http_server_common/src/util/timer.rs b/crates/lib/http_server_common/src/util/timer.rs new file mode 100644 index 0000000000..78d634ab34 --- /dev/null +++ b/crates/lib/http_server_common/src/util/timer.rs @@ -0,0 +1,8 @@ +use std::future::Future; + +pub async fn time_section(callback: F) -> T + where F: Fn() -> Fut, + Fut: Future, +{ + callback().await +} \ No newline at end of file diff --git a/crates/service/storyteller_web/src/http_server/endpoints/users/get_profile.rs b/crates/service/storyteller_web/src/http_server/endpoints/users/get_profile.rs index b838e2ed10..7340fa6604 100644 --- a/crates/service/storyteller_web/src/http_server/endpoints/users/get_profile.rs +++ b/crates/service/storyteller_web/src/http_server/endpoints/users/get_profile.rs @@ -23,6 +23,8 @@ use sqlx::error::Error::Database; use sqlx::mysql::MySqlDatabaseError; use std::fmt; use std::sync::Arc; +use time::Instant; +use http_server_common::util::timer::time_section; // TODO: This is duplicated in query_user_profile // TODO: This handler has embedded queries. @@ -126,19 +128,31 @@ impl fmt::Display for ProfileError { } } + +struct Timing { + +} + pub async fn get_profile_handler( http_request: HttpRequest, path: Path, server_state: web::Data>) -> Result { - let maybe_user_session = server_state - .session_checker - .maybe_get_user_session(&http_request, &server_state.mysql_pool) - .await - .map_err(|e| { - warn!("Session checker error: {:?}", e); - ProfileError::ServerError - })?; + let time_at_request_start = Instant::now(); + + let maybe_user_session = time_section(|| async { + server_state + .session_checker + .maybe_get_user_session(&http_request, &server_state.mysql_pool) + .await + .map_err(|e| { + warn!("Session checker error: {:?}", e); + ProfileError::ServerError + }) + } + ).await?; + + let time_after_session_check = Instant::now(); let mut is_mod = false; @@ -146,6 +160,8 @@ pub async fn get_profile_handler( is_mod = user_session.can_ban_users; } + let time_before_profile_query = Instant::now(); + // NB: Lookup failure is Err(RowNotFound). // NB: Since this is publicly exposed, we don't query sensitive data. let maybe_profile_record = sqlx::query_as!( @@ -184,6 +200,8 @@ WHERE .fetch_one(&server_state.mysql_pool) .await; // TODO: This will return error if it doesn't exist + let time_after_profile_query = Instant::now(); + let profile_record : RawUserProfileRecord = match maybe_profile_record { Ok(profile_record) => profile_record, Err(err) => { @@ -207,6 +225,8 @@ WHERE return Err(ProfileError::NotFound); } + let time_before_badges_list = Instant::now(); + let badges = list_user_badges(&server_state.mysql_pool, &profile_record.user_token) .await .unwrap_or_else(|err| { @@ -214,6 +234,8 @@ WHERE return Vec::new(); // NB: Fine if this fails. Not sure why it would. }); + let time_after_badges_list = Instant::now(); + let maybe_mod_fields = if is_mod { Some(UserProfileModeratorFields { is_banned, @@ -252,6 +274,8 @@ WHERE user: Some(profile_for_response), }; + let time_at_request_end = Instant::now(); + let body = serde_json::to_string(&response) .map_err(|e| ProfileError::ServerError)?; From 4bd0e09e7dea844b6ec59577967c2d6e54ba6a6d Mon Sep 17 00:00:00 2001 From: Brandon Thomas Date: Tue, 16 Aug 2022 01:18:47 -0400 Subject: [PATCH 2/3] Move user profile query to query lib --- .../users/get_user_profile_by_username.rs | 112 +++++++--- .../lib/http_server_common/src/util/timer.rs | 45 +++- .../endpoints/users/get_profile.rs | 192 ++++++------------ 3 files changed, 182 insertions(+), 167 deletions(-) diff --git a/crates/lib/database_queries/src/queries/users/get_user_profile_by_username.rs b/crates/lib/database_queries/src/queries/users/get_user_profile_by_username.rs index f7c739d4a4..487b687e96 100644 --- a/crates/lib/database_queries/src/queries/users/get_user_profile_by_username.rs +++ b/crates/lib/database_queries/src/queries/users/get_user_profile_by_username.rs @@ -3,14 +3,14 @@ use chrono::{DateTime, Utc}; use container_common::anyhow_result::AnyhowResult; use crate::helpers::boolean_converters::i8_to_bool; use log::{info, warn, log}; +use reusable_types::entity_visibility::EntityVisibility; use sqlx::MySqlPool; use sqlx::error::DatabaseError; use sqlx::error::Error::Database; use sqlx::mysql::MySqlDatabaseError; use std::sync::Arc; -// TODO: This duplicates the get_profile_handler. - +// TODO: Make non-`Serialize` and make the HTTP endpoints do the work #[derive(Serialize)] pub struct UserProfileResult { pub user_token: String, @@ -20,33 +20,66 @@ pub struct UserProfileResult { pub profile_markdown: String, pub profile_rendered_html: String, pub user_role_slug: String, - pub is_banned: bool, pub disable_gravatar: bool, + + // NB: Legacy top-level moderator field + #[deprecated = "use moderator fields instead"] + pub is_banned: bool, + + // Social pub discord_username: Option, pub twitch_username: Option, pub twitter_username: Option, pub patreon_username: Option, pub github_username: Option, + pub cashapp_username: Option, + pub website_url: Option, + + // Preferences; NB: included for get_profile_handler legacy reasons + pub preferred_tts_result_visibility: EntityVisibility, + pub preferred_w2l_result_visibility: EntityVisibility, + pub created_at: DateTime, + + // NB: Moderator fields must be cleared by HTTP handlers for non-mods + #[serde(skip_serializing_if = "Option::is_none")] + pub maybe_moderator_fields: Option, } +// TODO: Make non-`Serialize` and make the HTTP endpoints do the work #[derive(Serialize)] +pub struct UserProfileModeratorFields { + pub is_banned: bool, + pub maybe_mod_comments: Option, + pub maybe_mod_user_token: Option, +} + struct RawUserProfileRecord { - pub user_token: String, - pub username: String, - pub email_gravatar_hash: String, - pub display_name: String, - pub profile_markdown: String, - pub profile_rendered_html: String, - pub user_role_slug: String, - pub is_banned: i8, - pub disable_gravatar: i8, - pub discord_username: Option, - pub twitch_username: Option, - pub twitter_username: Option, - pub patreon_username: Option, - pub github_username: Option, - pub created_at: DateTime, + user_token: String, + username: String, + email_gravatar_hash: String, + display_name: String, + profile_markdown: String, + profile_rendered_html: String, + user_role_slug: String, + disable_gravatar: i8, + discord_username: Option, + twitch_username: Option, + twitter_username: Option, + patreon_username: Option, + github_username: Option, + cashapp_username: Option, + website_url: Option, + created_at: DateTime, + + // Preferences; NB: included for get_profile_handler legacy reasons + preferred_tts_result_visibility: EntityVisibility, + preferred_w2l_result_visibility: EntityVisibility, + + // Mod fields + is_banned: i8, + maybe_mod_comments: Option, + maybe_mod_user_token: Option, } pub async fn get_user_profile_by_username( @@ -64,13 +97,19 @@ SELECT profile_markdown, profile_rendered_html, user_role_slug, - is_banned, disable_gravatar, + preferred_tts_result_visibility as `preferred_tts_result_visibility: reusable_types::entity_visibility::EntityVisibility`, + preferred_w2l_result_visibility as `preferred_w2l_result_visibility: reusable_types::entity_visibility::EntityVisibility`, discord_username, twitch_username, twitter_username, patreon_username, github_username, + cashapp_username, + website_url, + is_banned, + maybe_mod_comments, + maybe_mod_user_token, created_at FROM users WHERE @@ -99,21 +138,30 @@ WHERE }; let profile_for_response = UserProfileResult { - user_token: profile_record.user_token.clone(), - username: profile_record.username.clone(), - display_name: profile_record.display_name.clone(), - email_gravatar_hash: profile_record.email_gravatar_hash.clone(), - profile_markdown: profile_record.profile_markdown.clone(), - profile_rendered_html: profile_record.profile_rendered_html.clone(), - user_role_slug: profile_record.user_role_slug.clone(), + user_token: profile_record.user_token, + username: profile_record.username, + display_name: profile_record.display_name, + email_gravatar_hash: profile_record.email_gravatar_hash, + profile_markdown: profile_record.profile_markdown, + profile_rendered_html: profile_record.profile_rendered_html, + user_role_slug: profile_record.user_role_slug, is_banned: i8_to_bool(profile_record.is_banned), disable_gravatar: i8_to_bool(profile_record.disable_gravatar), - discord_username: profile_record.discord_username.clone(), - twitch_username: profile_record.twitch_username.clone(), - twitter_username: profile_record.twitter_username.clone(), - patreon_username: profile_record.patreon_username.clone(), - github_username: profile_record.github_username.clone(), - created_at: profile_record.created_at.clone(), + discord_username: profile_record.discord_username, + twitch_username: profile_record.twitch_username, + twitter_username: profile_record.twitter_username, + patreon_username: profile_record.patreon_username, + github_username: profile_record.github_username, + cashapp_username: profile_record.cashapp_username, + website_url: profile_record.website_url, + preferred_tts_result_visibility: profile_record.preferred_tts_result_visibility, + preferred_w2l_result_visibility: profile_record.preferred_w2l_result_visibility, + created_at: profile_record.created_at, + maybe_moderator_fields: Some(UserProfileModeratorFields { + is_banned: i8_to_bool(profile_record.is_banned), + maybe_mod_comments: profile_record.maybe_mod_comments, + maybe_mod_user_token: profile_record.maybe_mod_user_token, + }) }; Ok(Some(profile_for_response)) diff --git a/crates/lib/http_server_common/src/util/timer.rs b/crates/lib/http_server_common/src/util/timer.rs index 78d634ab34..c2ffbaf802 100644 --- a/crates/lib/http_server_common/src/util/timer.rs +++ b/crates/lib/http_server_common/src/util/timer.rs @@ -1,8 +1,41 @@ use std::future::Future; +use std::time::{Instant, Duration}; -pub async fn time_section(callback: F) -> T - where F: Fn() -> Fut, - Fut: Future, -{ - callback().await -} \ No newline at end of file +pub struct MultiBenchmarkingTimer { + recorded_sections: Vec, +} + +#[derive(Clone, Serialize)] +pub struct SectionTime { + pub section_name: String, + pub duration: Duration, +} + +impl MultiBenchmarkingTimer { + + pub fn new() -> Self { + Self { + recorded_sections: Vec::new(), + } + } + + pub async fn time_async_section( + &mut self, + section_name: &str, + callback: F + ) -> T + where F: Fn() -> Fut, + Fut: Future, + { + let before = Instant::now(); + let result = callback().await; + let after = Instant::now(); + + self.recorded_sections.push(SectionTime { + section_name: section_name.to_string(), + duration: after.duration_since(before), + }); + + result + } +} diff --git a/crates/service/storyteller_web/src/http_server/endpoints/users/get_profile.rs b/crates/service/storyteller_web/src/http_server/endpoints/users/get_profile.rs index 7340fa6604..2e1032658d 100644 --- a/crates/service/storyteller_web/src/http_server/endpoints/users/get_profile.rs +++ b/crates/service/storyteller_web/src/http_server/endpoints/users/get_profile.rs @@ -10,13 +10,14 @@ use anyhow::anyhow; use chrono::{DateTime, Utc}; use crate::http_server::web_utils::response_error_helpers::to_simple_json_error; use crate::server_state::ServerState; -use database_queries::column_types::record_visibility::RecordVisibility; -use database_queries::helpers::boolean_converters::i8_to_bool; +use database_queries::queries::users::get_user_profile_by_username::{get_user_profile_by_username, UserProfileResult}; use database_queries::queries::users::user_badges::list_user_badges::UserBadgeForList; use database_queries::queries::users::user_badges::list_user_badges::list_user_badges; +use http_server_common::util::timer::MultiBenchmarkingTimer; use log::{info, warn, log}; use md5::{Md5, Digest}; use regex::Regex; +use reusable_types::entity_visibility::EntityVisibility; use sqlx::MySqlPool; use sqlx::error::DatabaseError; use sqlx::error::Error::Database; @@ -24,7 +25,6 @@ use sqlx::mysql::MySqlDatabaseError; use std::fmt; use std::sync::Arc; use time::Instant; -use http_server_common::util::timer::time_section; // TODO: This is duplicated in query_user_profile // TODO: This handler has embedded queries. @@ -39,8 +39,8 @@ pub struct UserProfileRecordForResponse { pub profile_rendered_html: String, pub user_role_slug: String, pub disable_gravatar: bool, - pub preferred_tts_result_visibility: RecordVisibility, - pub preferred_w2l_result_visibility: RecordVisibility, + pub preferred_tts_result_visibility: EntityVisibility, + pub preferred_w2l_result_visibility: EntityVisibility, pub discord_username: Option, pub twitch_username: Option, pub twitter_username: Option, @@ -66,31 +66,6 @@ pub struct ProfileSuccessResponse { pub user: Option, } -#[derive(Serialize)] -pub struct RawUserProfileRecord { - pub user_token: String, - pub username: String, - pub email_gravatar_hash: String, - pub display_name: String, - pub profile_markdown: String, - pub profile_rendered_html: String, - pub user_role_slug: String, - pub disable_gravatar: i8, - pub preferred_tts_result_visibility: RecordVisibility, - pub preferred_w2l_result_visibility: RecordVisibility, - pub discord_username: Option, - pub twitch_username: Option, - pub twitter_username: Option, - pub patreon_username: Option, - pub github_username: Option, - pub cashapp_username: Option, - pub website_url: Option, - pub is_banned: i8, - pub maybe_mod_comments: Option, - pub maybe_mod_user_token: Option, - pub created_at: DateTime, -} - #[derive(Debug)] pub enum ProfileError { ServerError, @@ -138,21 +113,20 @@ pub async fn get_profile_handler( path: Path, server_state: web::Data>) -> Result { - let time_at_request_start = Instant::now(); + let mut benchmark = MultiBenchmarkingTimer::new(); - let maybe_user_session = time_section(|| async { - server_state - .session_checker - .maybe_get_user_session(&http_request, &server_state.mysql_pool) - .await - .map_err(|e| { - warn!("Session checker error: {:?}", e); - ProfileError::ServerError - }) - } - ).await?; - - let time_after_session_check = Instant::now(); + let maybe_user_session = + benchmark.time_async_section("session checker", || async { + server_state + .session_checker + .maybe_get_user_session(&http_request, &server_state.mysql_pool) + .await + .map_err(|e| { + warn!("Session checker error: {:?}", e); + ProfileError::ServerError + }) + } + ).await?; let mut is_mod = false; @@ -160,65 +134,25 @@ pub async fn get_profile_handler( is_mod = user_session.can_ban_users; } - let time_before_profile_query = Instant::now(); + let maybe_user_profile = + get_user_profile_by_username(&path.username, &server_state.mysql_pool).await; - // NB: Lookup failure is Err(RowNotFound). - // NB: Since this is publicly exposed, we don't query sensitive data. - let maybe_profile_record = sqlx::query_as!( - RawUserProfileRecord, - r#" -SELECT - users.token as user_token, - username, - display_name, - email_gravatar_hash, - profile_markdown, - profile_rendered_html, - user_role_slug, - disable_gravatar, - preferred_tts_result_visibility as `preferred_tts_result_visibility: database_queries::column_types::record_visibility::RecordVisibility`, - preferred_w2l_result_visibility as `preferred_w2l_result_visibility: database_queries::column_types::record_visibility::RecordVisibility`, - discord_username, - twitch_username, - twitter_username, - patreon_username, - github_username, - cashapp_username, - website_url, - is_banned, - maybe_mod_comments, - maybe_mod_user_token, - created_at -FROM users -WHERE - users.username = ? - AND users.user_deleted_at IS NULL - AND users.mod_deleted_at IS NULL - "#, - &path.username, - ) - .fetch_one(&server_state.mysql_pool) - .await; // TODO: This will return error if it doesn't exist - - let time_after_profile_query = Instant::now(); - - let profile_record : RawUserProfileRecord = match maybe_profile_record { - Ok(profile_record) => profile_record, + let mut user_profile = match maybe_user_profile { + Ok(Some(user_profile)) => user_profile, + Ok(None) => { + warn!("Invalid user"); + return Err(ProfileError::NotFound); + }, Err(err) => { - match err { - sqlx::Error::RowNotFound => { - warn!("Invalid user"); - return Err(ProfileError::NotFound); - }, - _ => { - warn!("User profile query error: {:?}", err); - return Err(ProfileError::ServerError); - } - } + warn!("User profile query error: {:?}", err); + return Err(ProfileError::ServerError); } }; - let is_banned = i8_to_bool(profile_record.is_banned); + let is_banned = user_profile.maybe_moderator_fields + .as_ref() + .map(|mod_fields| mod_fields.is_banned) + .unwrap_or(false); if is_banned && !is_mod { // Can't see banned users. @@ -227,7 +161,7 @@ WHERE let time_before_badges_list = Instant::now(); - let badges = list_user_badges(&server_state.mysql_pool, &profile_record.user_token) + let badges = list_user_badges(&server_state.mysql_pool, &user_profile.user_token) .await .unwrap_or_else(|err| { warn!("Error querying badges: {:?}", err); @@ -236,39 +170,39 @@ WHERE let time_after_badges_list = Instant::now(); - let maybe_mod_fields = if is_mod { - Some(UserProfileModeratorFields { - is_banned, - maybe_mod_comments: profile_record.maybe_mod_comments.clone(), - maybe_mod_user_token: profile_record.maybe_mod_user_token.clone(), - }) - } else { - None - }; - - let profile_for_response = UserProfileRecordForResponse { - user_token: profile_record.user_token, - username: profile_record.username, - display_name: profile_record.display_name, - email_gravatar_hash: profile_record.email_gravatar_hash, - profile_markdown: profile_record.profile_markdown, - profile_rendered_html: profile_record.profile_rendered_html, - user_role_slug: profile_record.user_role_slug, - disable_gravatar: i8_to_bool(profile_record.disable_gravatar), - preferred_tts_result_visibility: profile_record.preferred_tts_result_visibility, - preferred_w2l_result_visibility: profile_record.preferred_w2l_result_visibility, - discord_username: profile_record.discord_username, - twitch_username: profile_record.twitch_username, - twitter_username: profile_record.twitter_username, - patreon_username: profile_record.patreon_username, - github_username: profile_record.github_username, - cashapp_username: profile_record.cashapp_username, - website_url: profile_record.website_url, - created_at: profile_record.created_at, - maybe_moderator_fields: maybe_mod_fields, + let mut profile_for_response = UserProfileRecordForResponse { + user_token: user_profile.user_token, + username: user_profile.username, + display_name: user_profile.display_name, + email_gravatar_hash: user_profile.email_gravatar_hash, + profile_markdown: user_profile.profile_markdown, + profile_rendered_html: user_profile.profile_rendered_html, + user_role_slug: user_profile.user_role_slug, + disable_gravatar: user_profile.disable_gravatar, + preferred_tts_result_visibility: user_profile.preferred_tts_result_visibility, + preferred_w2l_result_visibility: user_profile.preferred_w2l_result_visibility, + discord_username: user_profile.discord_username, + twitch_username: user_profile.twitch_username, + twitter_username: user_profile.twitter_username, + patreon_username: user_profile.patreon_username, + github_username: user_profile.github_username, + cashapp_username: user_profile.cashapp_username, + website_url: user_profile.website_url, + created_at: user_profile.created_at, + maybe_moderator_fields: user_profile.maybe_moderator_fields.map(|mod_fields| { + UserProfileModeratorFields { + is_banned: mod_fields.is_banned, + maybe_mod_comments: mod_fields.maybe_mod_comments, + maybe_mod_user_token: mod_fields.maybe_mod_user_token, + } + }), badges, }; + if !is_mod { + profile_for_response.maybe_moderator_fields = None; + } + let response = ProfileSuccessResponse { success: true, user: Some(profile_for_response), From 70daacf5595f25ba09886ec9aa4255e5de79e877 Mon Sep 17 00:00:00 2001 From: Brandon Thomas Date: Tue, 16 Aug 2022 02:26:00 -0400 Subject: [PATCH 3/3] Profile endpoint instrumented --- Cargo.lock | 2 + crates/lib/http_server_common/Cargo.toml | 2 + .../lib/http_server_common/src/util/timer.rs | 66 +++++++++++++++++++ .../endpoints/users/get_profile.rs | 53 +++++++++------ 4 files changed, 104 insertions(+), 19 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index bdc3926fe1..38ffd292c4 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1947,6 +1947,8 @@ dependencies = [ "dotenv", "language-tags 0.3.2", "log", + "once_cell", + "regex", "serde", "serde_derive", "serde_json", diff --git a/crates/lib/http_server_common/Cargo.toml b/crates/lib/http_server_common/Cargo.toml index b351f38410..fc005df1d5 100644 --- a/crates/lib/http_server_common/Cargo.toml +++ b/crates/lib/http_server_common/Cargo.toml @@ -23,6 +23,8 @@ base64 = "0.13.0" chrono = { version = "0.4.19", features = ["serde"] } dotenv = "0.15.0" log = "0.4.14" +once_cell = "1.9.0" +regex = "1.5.4" # Web actix-cors = "0.6.0-beta.3" diff --git a/crates/lib/http_server_common/src/util/timer.rs b/crates/lib/http_server_common/src/util/timer.rs index c2ffbaf802..0a75926f0c 100644 --- a/crates/lib/http_server_common/src/util/timer.rs +++ b/crates/lib/http_server_common/src/util/timer.rs @@ -1,7 +1,24 @@ use std::future::Future; +use log::warn; use std::time::{Instant, Duration}; +use once_cell::sync::Lazy; +use regex::Regex; +static SPACES_REGEX : Lazy = Lazy::new(|| { + Regex::new(r"\s+").unwrap() +}); + +static INVALID_HEADER_CHARACTER_REGEX : Lazy = Lazy::new(|| { + Regex::new(r"[^A-Za-z0-9\-]+").unwrap() +}); + +// TODO: Auto inject one of these with each HTTP request and begin with dispatch and end +// with final result delivery. + +/// A simple utility meant to time various segments of an HTTP endpoint so that +/// the timing data can be aggregated and returned. pub struct MultiBenchmarkingTimer { + start_timer: Option, recorded_sections: Vec, } @@ -15,10 +32,59 @@ impl MultiBenchmarkingTimer { pub fn new() -> Self { Self { + start_timer: None, recorded_sections: Vec::new(), } } + pub fn new_started() -> Self { + let mut benchmark = Self::new(); + benchmark.mark_begin(); + benchmark + } + + pub fn iter_section_timings(&self) -> std::slice::Iter<'_, SectionTime> { + self.recorded_sections.iter() + } + + pub fn section_timings_as_headers(&self) -> Vec<(String, String)> { + self.recorded_sections.iter() + .map(|section| { + let header_name = format!("x-timing-{}", section.section_name + .trim() + .to_lowercase()); + let header_name = SPACES_REGEX.replace_all(&header_name, "-").to_string(); + let header_name = INVALID_HEADER_CHARACTER_REGEX.replace_all(&header_name, "").to_string(); + (header_name, format!("{:?}", §ion.duration)) + }) + .collect() + } + + pub fn mark_begin(&mut self) { + if self.start_timer.is_some() { + warn!("Start timer has already been set."); + return; + } + self.start_timer = Some(Instant::now()); + } + + pub fn mark_end(&mut self) { + match self.start_timer { + None => { + warn!("Start timer was never started."); + return; + } + Some(start_time) => { + let end = Instant::now(); + + self.recorded_sections.push(SectionTime { + section_name: "total duration".to_string(), + duration: end.duration_since(start_time), + }); + } + } + } + pub async fn time_async_section( &mut self, section_name: &str, diff --git a/crates/service/storyteller_web/src/http_server/endpoints/users/get_profile.rs b/crates/service/storyteller_web/src/http_server/endpoints/users/get_profile.rs index 2e1032658d..18edb74fab 100644 --- a/crates/service/storyteller_web/src/http_server/endpoints/users/get_profile.rs +++ b/crates/service/storyteller_web/src/http_server/endpoints/users/get_profile.rs @@ -13,8 +13,9 @@ use crate::server_state::ServerState; use database_queries::queries::users::get_user_profile_by_username::{get_user_profile_by_username, UserProfileResult}; use database_queries::queries::users::user_badges::list_user_badges::UserBadgeForList; use database_queries::queries::users::user_badges::list_user_badges::list_user_badges; +use http_server_common::request::get_request_header_optional::get_request_header_optional; use http_server_common::util::timer::MultiBenchmarkingTimer; -use log::{info, warn, log}; +use log::{info, warn, log, error}; use md5::{Md5, Digest}; use regex::Regex; use reusable_types::entity_visibility::EntityVisibility; @@ -24,7 +25,6 @@ use sqlx::error::Error::Database; use sqlx::mysql::MySqlDatabaseError; use std::fmt; use std::sync::Arc; -use time::Instant; // TODO: This is duplicated in query_user_profile // TODO: This handler has embedded queries. @@ -113,7 +113,7 @@ pub async fn get_profile_handler( path: Path, server_state: web::Data>) -> Result { - let mut benchmark = MultiBenchmarkingTimer::new(); + let mut benchmark = MultiBenchmarkingTimer::new_started(); let maybe_user_session = benchmark.time_async_section("session checker", || async { @@ -135,7 +135,9 @@ pub async fn get_profile_handler( } let maybe_user_profile = - get_user_profile_by_username(&path.username, &server_state.mysql_pool).await; + benchmark.time_async_section("profile query", || async { + get_user_profile_by_username(&path.username, &server_state.mysql_pool).await + }).await; let mut user_profile = match maybe_user_profile { Ok(Some(user_profile)) => user_profile, @@ -159,16 +161,16 @@ pub async fn get_profile_handler( return Err(ProfileError::NotFound); } - let time_before_badges_list = Instant::now(); - - let badges = list_user_badges(&server_state.mysql_pool, &user_profile.user_token) - .await - .unwrap_or_else(|err| { - warn!("Error querying badges: {:?}", err); - return Vec::new(); // NB: Fine if this fails. Not sure why it would. - }); - - let time_after_badges_list = Instant::now(); + let badges = + benchmark.time_async_section("badges query", || async { + list_user_badges(&server_state.mysql_pool, &user_profile.user_token) + .await + }) + .await + .unwrap_or_else(|err| { + warn!("Error querying badges: {:?}", err); + return Vec::new(); // NB: Fine if this fails. Not sure why it would. + }); let mut profile_for_response = UserProfileRecordForResponse { user_token: user_profile.user_token, @@ -203,17 +205,30 @@ pub async fn get_profile_handler( profile_for_response.maybe_moderator_fields = None; } + benchmark.mark_end(); + let response = ProfileSuccessResponse { success: true, user: Some(profile_for_response), }; - let time_at_request_end = Instant::now(); - let body = serde_json::to_string(&response) .map_err(|e| ProfileError::ServerError)?; - Ok(HttpResponse::Ok() - .content_type("application/json") - .body(body)) + let mut http_response = HttpResponse::Ok(); + + http_response.content_type("application/json"); + + let has_debug_header = get_request_header_optional(&http_request, "debug-timing") + .is_some(); + + if has_debug_header { + for header in benchmark.section_timings_as_headers() { + http_response.insert_header(header); + } + } + + let http_response = http_response.body(body); + + Ok(http_response) }