[BE] Track time spent in DB to many operations

backend/src/controller/person/mod.rs

@@ -1,3 +1,5 @@
+use std::time::Instant;
+
 use log::{error, info};
 use reqwest::Client;
 use rocket::http::Status;
@@ -58,6 +60,8 @@ pub async fn get_by_dni(dni: i32) -> (Status, Json<JsonResult<Person>>) {
      */
     let reniec_api_key = std::env::var("RENIEC_API").expect("RENIEC_API env var is not set!");
     let client = Client::new();
+
+    let start = Instant::now();
     let reqwest_result = client
         .get(format!("https://api.apis.net.pe/v1/dni?numero={}", &dni))
         .bearer_auth(reniec_api_key)
@@ -65,6 +69,10 @@ pub async fn get_by_dni(dni: i32) -> (Status, Json<JsonResult<Person>>) {
         .header("charset", "utf-8")
         .send()
         .await;
+    log::info!(
+        "Search in RENIEC took: {:?} ms",
+        start.elapsed().as_millis()
+    );
 
     let reniec_person = match reqwest_result {
         Ok(data) => {
@@ -103,6 +111,9 @@ pub async fn get_by_dni(dni: i32) -> (Status, Json<JsonResult<Person>>) {
             }
         };
 
+        // TODO: Insert & get last inserted id in one query
+
+        let start = Instant::now();
         let query_1 = sqlx::query!(
             "INSERT INTO person (person_dni, person_names, person_paternal_surname, person_maternal_surname) VALUES (?, ?, ?, ?)",
             dni,
@@ -112,10 +123,19 @@ pub async fn get_by_dni(dni: i32) -> (Status, Json<JsonResult<Person>>) {
         )
         .execute(&mut *tx)
         .await;
+        log::info!(
+            "DB (insert person) took: {:?} ms",
+            start.elapsed().as_millis()
+        );
 
+        let start = Instant::now();
         let query_2 = sqlx::query!("SELECT LAST_INSERT_ID() AS person_id")
             .fetch_one(&mut *tx)
             .await;
+        log::info!(
+            "DB (fetch last inserted person) took: {:?} ms",
+            start.elapsed().as_millis()
+        );
 
         match tx.commit().await {
             Ok(_) => (),

backend/src/main.rs

@@ -30,8 +30,7 @@ pub async fn db() -> Result<MySqlConnection, String> {
 
     let start = Instant::now();
     let conn = sqlx::MySqlConnection::connect(db_url.as_str()).await;
-    let duration = start.elapsed();
-    log::info!("DB connection took: {:?} ms", duration.as_millis());
+    log::info!("DB connection took: {:?} ms", start.elapsed().as_millis());
 
     match conn {
         Ok(connection) => Ok(connection),

backend/src/model/person.rs

@@ -1,3 +1,5 @@
+use std::time::Instant;
+
 use log::error;
 use serde::{Deserialize, Serialize};
 
@@ -39,9 +41,11 @@ impl Person {
             Err(reason) => return Err(DBError::Str(reason)),
         };
 
+        let start = Instant::now();
         let result = sqlx::query_as!(Person, "SELECT * FROM person WHERE person_dni = ?", dni)
             .fetch_one(&mut db)
             .await;
+        log::info!("DB query (person by dni) took: {:?} ms", start.elapsed().as_millis());
 
         match result {
             Ok(v) => Ok(v),

backend/src/model/register.rs

@@ -339,6 +339,7 @@ impl Register {
     pub async fn get_by_dni(dni: String) -> Result<Vec<Register>, String> {
         let mut db = db().await?;
 
+        let start = Instant::now();
         let res = sqlx::query!(
             "SELECT * FROM register 
                 WHERE register_person_id = (SELECT person_id FROM person WHERE person_dni = ?)",
@@ -346,6 +347,10 @@ impl Register {
         )
         .fetch_all(&mut db)
         .await;
+        log::info!(
+            "DB (get register by id) took: {:?} ms",
+            start.elapsed().as_millis()
+        );
 
         let res = match res {
             Ok(res) => res,