From 2d0b2a4d795ab0d84aa61c1b410894f0cafec5ee Mon Sep 17 00:00:00 2001
From: tibvdm <tibovandemoortele@hotmail.com>
Date: Tue, 27 Aug 2024 14:15:47 +0200
Subject: [PATCH] add timings to track filling the cache

---
 sa-index/src/sa_searcher.rs | 12 ++++++++++--
 1 file changed, 10 insertions(+), 2 deletions(-)

diff --git a/sa-index/src/sa_searcher.rs b/sa-index/src/sa_searcher.rs
index 4b64137..d676359 100644
--- a/sa-index/src/sa_searcher.rs
+++ b/sa-index/src/sa_searcher.rs
@@ -1,4 +1,5 @@
 use std::{cmp::min, ops::Deref};
+use std::time::{SystemTime, SystemTimeError, UNIX_EPOCH};
 use sa_mappings::proteins::{Protein, Proteins};
 
 use crate::{
@@ -152,10 +153,13 @@ impl Searcher {
 
         let print_step_size = searcher.kmer_cache.base.pow(k as u32) / 100;
 
+        eprintln!("Starting cache fill");
+        let start_cache_fill_time = get_time_ms().unwrap();
+
         // Update the bounds for all 3-mers in the KTable
         for i in 0..searcher.kmer_cache.base.pow(k as u32) {
             if i % print_step_size == 0 {
-                eprintln!("Updating kmer cache: {}%", i / print_step_size);
+                eprintln!("Updating kmer cache: {}% ({} seconds since start)", i / print_step_size, (get_time_ms().unwrap() - start_cache_fill_time) / 1000.0);
             }
 
             let kmer = searcher.kmer_cache.index_to_kmer(i);
@@ -170,7 +174,7 @@ impl Searcher {
             }
         }
 
-        eprintln!("Updating kmer cache: 100%");
+        eprintln!("Filled cache in {} seconds", (get_time_ms().unwrap() - start_cache_fill_time) / 1000.0);
 
         searcher
     }
@@ -510,6 +514,10 @@ impl Searcher {
     }
 }
 
+pub fn get_time_ms() -> Result<f64, SystemTimeError> {
+    Ok(SystemTime::now().duration_since(UNIX_EPOCH)?.as_nanos() as f64 * 1e-6)
+}
+
 #[cfg(test)]
 mod tests {
     use sa_mappings::proteins::{Protein, Proteins};