Improve model query performance tracing

Cargo.lock

@@ -1630,6 +1630,7 @@ dependencies = [
  "sqlx 0.3.5 (registry+https://github.com/rust-lang/crates.io-index)",
  "tokio 0.2.22 (registry+https://github.com/rust-lang/crates.io-index)",
  "tracing 0.1.17 (registry+https://github.com/rust-lang/crates.io-index)",
+ "tracing-futures 0.2.4 (registry+https://github.com/rust-lang/crates.io-index)",
  "tracing-subscriber 0.2.9 (registry+https://github.com/rust-lang/crates.io-index)",
  "url 2.1.1 (registry+https://github.com/rust-lang/crates.io-index)",
  "uuid 0.8.1 (registry+https://github.com/rust-lang/crates.io-index)",

Cargo.toml

@@ -27,3 +27,4 @@ url = "2.1"
 async-trait = "0.1"
 tracing = "0.1"
 tracing-subscriber = "0.2"
+tracing-futures = "0.2"

README.md

@@ -29,6 +29,12 @@
 
 # Todo
 
+* Add HTTP header authentication for endpoints that modify an owner's data.
+* Add DELETE endpoints for existing resources.
+* Add endpoints for the other models.
+* Add caching. Not sure how to do this exactly. Could use Redis, Varnish, Nginx, 
+  or a lib resident in the rust web server process. I'll probably need to do 
+  invalidations as transactions are made, or interiors are updated.
 * Make self-contained docker container that can run the app without any setup.
 * Add rate-limiting per IP address. The `tower` crate has a service that might 
   be useful for this.

src/models/interior_ref_list.rs

@@ -4,7 +4,7 @@ use chrono::prelude::*;
 use serde::{Deserialize, Serialize};
 use sqlx::postgres::PgPool;
 use sqlx::types::Json;
-use tracing::debug;
+use tracing::instrument;
 
 use super::ListParams;
 use super::Model;
@@ -46,24 +46,22 @@ impl Model for InteriorRefList {
         self.id
     }
 
+    #[instrument(level = "debug", skip(db))]
     async fn get(db: &PgPool, id: i32) -> Result<Self> {
-        let timer = std::time::Instant::now();
+        Ok(
-        let result =
             sqlx::query_as_unchecked!(Self, "SELECT * FROM interior_ref_lists WHERE id = $1", id)
                 .fetch_one(db)
-                .await?;
+                .await?,
-        let elapsed = timer.elapsed();
+        )
-        debug!("SELECT * FROM interior_ref_lists ... {:.3?}", elapsed);
-        Ok(result)
     }
 
+    #[instrument(level = "debug", skip(db))]
     async fn save(self, db: &PgPool) -> Result<Self> {
-        let timer = std::time::Instant::now();
         // TODO:
         // * Decide if I'll need to make the same changes to merchandise and transactions
         //      - answer depends on how many rows of each I expect to insert in one go
         // * should probably omit ref_list from response
-        let result = sqlx::query_as_unchecked!(
+        Ok(sqlx::query_as_unchecked!(
             Self,
             "INSERT INTO interior_ref_lists
             (shop_id, ref_list, created_at, updated_at)
@@ -73,14 +71,11 @@ impl Model for InteriorRefList {
             self.ref_list,
         )
         .fetch_one(db)
-        .await?;
+        .await?)
-        let elapsed = timer.elapsed();
-        debug!("INSERT INTO interior_ref_lists ... {:.3?}", elapsed);
-        Ok(result)
     }
 
+    #[instrument(level = "debug", skip(db))]
     async fn list(db: &PgPool, list_params: ListParams) -> Result<Vec<Self>> {
-        let timer = std::time::Instant::now();
         let result = if let Some(order_by) = list_params.get_order_by() {
             sqlx::query_as_unchecked!(
                 Self,
@@ -106,8 +101,6 @@ impl Model for InteriorRefList {
             .fetch_all(db)
             .await?
         };
-        let elapsed = timer.elapsed();
-        debug!("SELECT * FROM interior_ref_lists ... {:.3?}", elapsed);
         Ok(result)
     }
 }

src/models/owner.rs

@@ -4,7 +4,7 @@ use chrono::prelude::*;
 use ipnetwork::IpNetwork;
 use serde::{Deserialize, Serialize};
 use sqlx::postgres::PgPool;
-use tracing::debug;
+use tracing::instrument;
 use uuid::Uuid;
 
 use super::ListParams;
@@ -31,19 +31,18 @@ impl Model for Owner {
         self.id
     }
 
+    #[instrument(level = "debug", skip(db))]
     async fn get(db: &PgPool, id: i32) -> Result<Self> {
-        let timer = std::time::Instant::now();
+        Ok(
-        let result = sqlx::query_as!(Self, "SELECT * FROM owners WHERE id = $1", id)
+            sqlx::query_as!(Self, "SELECT * FROM owners WHERE id = $1", id)
                 .fetch_one(db)
-            .await?;
+                .await?,
-        let elapsed = timer.elapsed();
+        )
-        debug!("SELECT * FROM owners ... {:.3?}", elapsed);
-        Ok(result)
     }
 
+    #[instrument(level = "debug", skip(db))]
     async fn save(self, db: &PgPool) -> Result<Self> {
-        let timer = std::time::Instant::now();
+        Ok(sqlx::query_as!(
-        let result = sqlx::query_as!(
             Self,
             "INSERT INTO owners
                 (name, api_key, ip_address, mod_version, created_at, updated_at)
@@ -55,14 +54,11 @@ impl Model for Owner {
             self.mod_version,
         )
         .fetch_one(db)
-        .await?;
+        .await?)
-        let elapsed = timer.elapsed();
-        debug!("INSERT INTO owners ... {:.3?}", elapsed);
-        Ok(result)
     }
 
+    #[instrument(level = "debug", skip(db))]
     async fn list(db: &PgPool, list_params: ListParams) -> Result<Vec<Self>> {
-        let timer = std::time::Instant::now();
         let result = if let Some(order_by) = list_params.get_order_by() {
             sqlx::query_as!(
                 Self,
@@ -88,8 +84,6 @@ impl Model for Owner {
             .fetch_all(db)
             .await?
         };
-        let elapsed = timer.elapsed();
-        debug!("SELECT * FROM owners ... {:.3?}", elapsed);
         Ok(result)
     }
 }

src/models/shop.rs

@@ -3,7 +3,7 @@ use async_trait::async_trait;
 use chrono::prelude::*;
 use serde::{Deserialize, Serialize};
 use sqlx::postgres::PgPool;
-use tracing::debug;
+use tracing::instrument;
 
 use super::ListParams;
 use super::Model;
@@ -32,19 +32,18 @@ impl Model for Shop {
         self.id
     }
 
+    #[instrument(level = "debug", skip(db))]
     async fn get(db: &PgPool, id: i32) -> Result<Self> {
-        let timer = std::time::Instant::now();
+        Ok(
-        let result = sqlx::query_as!(Self, "SELECT * FROM shops WHERE id = $1", id)
+            sqlx::query_as!(Self, "SELECT * FROM shops WHERE id = $1", id)
                 .fetch_one(db)
-            .await?;
+                .await?,
-        let elapsed = timer.elapsed();
+        )
-        debug!("SELECT * FROM shops ... {:.3?}", elapsed);
-        Ok(result)
     }
 
+    #[instrument(level = "debug", skip(db))]
     async fn save(self, db: &PgPool) -> Result<Self> {
-        let timer = std::time::Instant::now();
+        Ok(sqlx::query_as!(
-        let result = sqlx::query_as!(
             Self,
             "INSERT INTO shops
             (name, owner_id, description, is_not_sell_buy, sell_buy_list_id, vendor_id,
@@ -60,14 +59,11 @@ impl Model for Shop {
             self.vendor_gold,
         )
         .fetch_one(db)
-        .await?;
+        .await?)
-        let elapsed = timer.elapsed();
-        debug!("INSERT INTO shops ... {:.3?}", elapsed);
-        Ok(result)
     }
 
+    #[instrument(level = "debug", skip(db))]
     async fn list(db: &PgPool, list_params: ListParams) -> Result<Vec<Self>> {
-        let timer = std::time::Instant::now();
         let result = if let Some(order_by) = list_params.get_order_by() {
             sqlx::query_as!(
                 Self,
@@ -93,8 +89,6 @@ impl Model for Shop {
             .fetch_all(db)
             .await?
         };
-        let elapsed = timer.elapsed();
-        debug!("SELECT * FROM shops ... {:.3?}", elapsed);
         Ok(result)
     }
 }