Merge pull request #5 from storytold/echelon-benchmarking

Echelon benchmarking

Cargo.lock

@@ -1947,6 +1947,8 @@ dependencies = [
  "dotenv",
  "language-tags 0.3.2",
  "log",
+ "once_cell",
+ "regex",
  "serde",
  "serde_derive",
  "serde_json",

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<String>,
   pub twitch_username: Option<String>,
   pub twitter_username: Option<String>,
   pub patreon_username: Option<String>,
   pub github_username: Option<String>,
+  pub cashapp_username: Option<String>,
+  pub website_url: Option<String>,
+
+  // 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<Utc>,
+
+  // NB: Moderator fields must be cleared by HTTP handlers for non-mods
+  #[serde(skip_serializing_if = "Option::is_none")]
+  pub maybe_moderator_fields: Option<UserProfileModeratorFields>,
 }
 
+// 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<String>,
+  pub maybe_mod_user_token: Option<String>,
+}
+
 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<String>,
-  pub twitch_username: Option<String>,
-  pub twitter_username: Option<String>,
-  pub patreon_username: Option<String>,
-  pub github_username: Option<String>,
-  pub created_at: DateTime<Utc>,
+  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<String>,
+  twitch_username: Option<String>,
+  twitter_username: Option<String>,
+  patreon_username: Option<String>,
+  github_username: Option<String>,
+  cashapp_username: Option<String>,
+  website_url: Option<String>,
+  created_at: DateTime<Utc>,
+
+  // 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<String>,
+  maybe_mod_user_token: Option<String>,
 }
 
 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))

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"

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;

crates/lib/http_server_common/src/util/mod.rs

@@ -0,0 +1 @@
+pub mod timer;

crates/lib/http_server_common/src/util/timer.rs

@@ -0,0 +1,107 @@
+use std::future::Future;
+use log::warn;
+use std::time::{Instant, Duration};
+use once_cell::sync::Lazy;
+use regex::Regex;
+
+static SPACES_REGEX : Lazy<Regex> = Lazy::new(|| {
+  Regex::new(r"\s+").unwrap()
+});
+
+static INVALID_HEADER_CHARACTER_REGEX : Lazy<Regex> = 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<Instant>,
+  recorded_sections: Vec<SectionTime>,
+}
+
+#[derive(Clone, Serialize)]
+pub struct SectionTime {
+  pub section_name: String,
+  pub duration: Duration,
+}
+
+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!("{:?}", &section.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<F, Fut, T>(
+    &mut self,
+    section_name: &str,
+    callback: F
+  ) -> T
+    where F: Fn() -> Fut,
+          Fut: Future<Output = T>,
+  {
+    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
+  }
+}

crates/service/storyteller_web/src/http_server/endpoints/users/get_profile.rs

@@ -10,13 +10,15 @@ 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 log::{info, warn, log};
+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, error};
 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;
@@ -37,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<String>,
   pub twitch_username: Option<String>,
   pub twitter_username: Option<String>,
@@ -64,31 +66,6 @@ pub struct ProfileSuccessResponse {
   pub user: Option<UserProfileRecordForResponse>,
 }
 
-#[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<String>,
-  pub twitch_username: Option<String>,
-  pub twitter_username: Option<String>,
-  pub patreon_username: Option<String>,
-  pub github_username: Option<String>,
-  pub cashapp_username: Option<String>,
-  pub website_url: Option<String>,
-  pub is_banned: i8,
-  pub maybe_mod_comments: Option<String>,
-  pub maybe_mod_user_token: Option<String>,
-  pub created_at: DateTime<Utc>,
-}
-
 #[derive(Debug)]
 pub enum ProfileError {
   ServerError,
@@ -126,19 +103,30 @@ impl fmt::Display for ProfileError {
   }
 }
 
+
+struct Timing {
+
+}
+
 pub async fn get_profile_handler(
   http_request: HttpRequest,
   path: Path<GetProfilePathInfo>,
   server_state: web::Data<Arc<ServerState>>) -> Result<HttpResponse, ProfileError>
 {
-  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 mut benchmark = MultiBenchmarkingTimer::new_started();
+
+  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;
 
@@ -146,107 +134,79 @@ pub async fn get_profile_handler(
     is_mod = user_session.can_ban_users;
   }
 
-  // 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 maybe_user_profile =
+      benchmark.time_async_section("profile query", || async {
+        get_user_profile_by_username(&path.username, &server_state.mysql_pool).await
+      }).await;
 
-  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.
     return Err(ProfileError::NotFound);
   }
 
-  let badges = list_user_badges(&server_state.mysql_pool, &profile_record.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 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 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;
+  }
+
+  benchmark.mark_end();
+
   let response = ProfileSuccessResponse {
     success: true,
     user: Some(profile_for_response),
@@ -255,7 +215,20 @@ WHERE
   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)
 }