debug context now as tag, performance stats

JerboaBurrow · Feb 15, 2024 · 9a3a70c · 9a3a70c
1 parent 73dd537
commit 9a3a70c
Show file tree

Hide file tree

Showing 3 changed files with 54 additions and 13 deletions.
diff --git a/src/config.rs b/src/config.rs
@@ -12,7 +12,7 @@ pub struct StatsConfig
     pub save_period_seconds: u64,
     pub path: String,
     pub hit_cooloff_seconds: u64,
-    pub clear_period_second: u64,
+    pub clear_period_seconds: u64,
     pub ipinfo_token: Option<String>
 }
 
@@ -54,8 +54,7 @@ pub struct Config
     notification_endpoint: Webhook,
     cert_path: String,
     key_path: String,
-    throttle: ThrottleConfig,
-    debug: bool
+    throttle: ThrottleConfig
 }
 
 impl Config 
@@ -100,11 +99,6 @@ impl Config
         self.throttle.clone()
     }
 
-    pub fn get_debug(&self) -> bool
-    {
-        self.debug
-    }
-
 }
 
 #[derive(Clone)]

diff --git a/src/lib.rs b/src/lib.rs
@@ -21,12 +21,23 @@ pub fn debug(msg: String, context: Option<String>)
 {
     if DEBUG == false { return }
 
-    match context
+    let mut message = String::new();
+
+    let tag = match context
+    {
+        Some(s) => format!("[{s}] "),
+        None => format!("[DEBUG] ")
+    };
+
+    for line in msg.split("\n")
     {
-        Some(s) => println!("[DEBUG] {msg} in context {s}"),
-        None => println!("[DEBUG] {msg}")
+        message.push_str(&tag);
+        message.push_str(line);
+        message.push_str("\n");
     }
-
+
+    print!("{message}");
+
 }
 
 pub fn program_version() -> Version 

diff --git a/src/web/stats.rs b/src/web/stats.rs
@@ -67,8 +67,12 @@ pub async fn log_stats<B>
 {
 
     {
+        let start_time = Instant::now();
+
         let mut stats = state.lock().await;
 
+        let compute_start_time = Instant::now();
+
         let stats_config = read_stats_config().unwrap();
 
         let sip = addr.ip().to_string();
@@ -92,7 +96,20 @@ pub async fn log_stats<B>
                         let delta = (chrono::offset::Utc::now()-t.to_utc()).num_seconds();
                         if delta < (stats_config.hit_cooloff_seconds as i64)
                         {
+                            let total_time = start_time.elapsed().as_secs_f64();
+                            let compute_time = compute_start_time.elapsed().as_secs_f64();
+
+                            crate::debug(format!
+                            (
+                                "\nTotal stats time:         {} s (Passthrough)\nCompute stats time:       {} s (Passthrough)", 
+                                total_time,
+                                compute_time
+                            ), Some("PERFORMANCE".to_string()));
+
+                            let serve_start = Instant::now();
                             let response = next.run(request).await;
+                            crate::debug(format!("Serve time:               {} s", serve_start.elapsed().as_secs_f64()), Some("PERFORMANCE".to_string()));
+
                             return Ok(response)
                         }
                     },
@@ -115,6 +132,10 @@ pub async fn log_stats<B>
 
         stats.hits.insert(addr.ip(), hit);
 
+        let compute_time = compute_start_time.elapsed().as_secs_f64();
+
+        let write_start_time = Instant::now();
+
         if stats.last_save.elapsed() >= std::time::Duration::from_secs(stats_config.save_period_seconds)
         {
             let file_name = stats_config.path.to_string()+"-"+&chrono::offset::Utc::now().to_rfc3339();
@@ -124,16 +145,31 @@ pub async fn log_stats<B>
                 Err(e) => {crate::debug(format!("Error saving stats {}", e), None)}
             }
 
-            if stats.last_save.elapsed() >= std::time::Duration::from_secs(stats_config.clear_period_second)
+            if stats.last_save.elapsed() >= std::time::Duration::from_secs(stats_config.clear_period_seconds)
             {
                 stats.hits.clear()
             }
 
             stats.last_save = Instant::now();
         }
+
+        let write_time = write_start_time.elapsed().as_secs_f64();
+        let total_time = start_time.elapsed().as_secs_f64();
+
+        crate::debug(format!
+        (
+            "\nTotal stats time:         {} s\nCompute stats time:       {} s\nWrite stats time:         {} s", 
+            total_time,
+            compute_time,
+            write_time
+        ), Some("PERFORMANCE".to_string()));
+
     }
 
+    let serve_start = Instant::now();
     let response = next.run(request).await;
+    crate::debug(format!("Serve time:               {} s", serve_start.elapsed().as_secs_f64()), Some("PERFORMANCE".to_string()));
+
     Ok(response)
 
 }