From fc0b38c9e658a68b8f7ba3113d57ab61a62b4378 Mon Sep 17 00:00:00 2001
From: David Lougheed <david.lougheed@gmail.com>
Date: Mon, 12 Feb 2024 21:28:12 -0500
Subject: [PATCH] chore(call): log allele determining time for slow loci

---
 strkit/call/call_locus.py | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/strkit/call/call_locus.py b/strkit/call/call_locus.py
index 1ea1e10..9b1c852 100644
--- a/strkit/call/call_locus.py
+++ b/strkit/call/call_locus.py
@@ -1153,6 +1153,8 @@ def call_locus(
             have_rare_realigns = True
             break
 
+    allele_start_time = datetime.now()
+
     if params.use_hp:
         top_ps = phase_sets.most_common(1)
         if (haplotagged_reads_count >= min_hp_read_coverage and len(haplotags) == n_alleles and top_ps and
@@ -1261,6 +1263,8 @@ def call_locus(
             debug_str=locus_log_str,
         ) or {}  # Still false-y
 
+    allele_time = (datetime.now() - allele_start_time).total_seconds()
+
     # Extract data from call_data --------------------------------------------------------------------------------------
 
     call = call_data.get("call")
@@ -1358,7 +1362,8 @@ def call_locus(
     if call_time > CALL_WARN_TIME:
         logger_.warning(
             f"{locus_log_str} - locus total call time exceeded {CALL_WARN_TIME}s; {n_reads_in_dict} reads took "
-            f"{call_time}s ({motif_size=}, {motif=}, {call=}, {assign_method=} | {assign_time=}s)")
+            f"{call_time}s ({motif_size=}, {motif=}, {call=}, {assign_method=} | {allele_time=:.4f}s, "
+            f"{assign_time=:.4f}s)")
 
     # Compile the call into a dictionary with all information to return ------------------------------------------------