Update app.py

app.py

@@ -12,9 +12,6 @@ import logging
 import re
 import json
 from datetime import datetime
-
-current_time = datetime.now()
-
 from typing import Annotated, Sequence, TypedDict, List, Optional, Any, Type
 from pydantic import BaseModel, Field
 
@@ -38,16 +35,19 @@ load_dotenv(".env")
 HF_TOKEN = os.getenv("HF_TOKEN") or os.getenv("HUGGINGFACEHUB_API_TOKEN")
 print("Environment variables loaded.")
 
+# --- Setup main logger first ---
+logging.basicConfig(level=logging.INFO)
+logger = logging.getLogger(__name__)
+
 # --- Environment and Logging Setup ---
-# Create a custom logger for metrics
 def setup_metrics_logger():
     """Setup a simple file logger for human-readable metrics"""
-    logger = logging.getLogger('metrics')
-    logger.setLevel(logging.INFO)
+    metrics_logger = logging.getLogger('metrics')
+    metrics_logger.setLevel(logging.INFO)
     
     # Avoid duplicate handlers
-    if logger.handlers:
-        return logger
+    if metrics_logger.handlers:
+        return metrics_logger
     
     # Create file handler
     log_file = 'performance_metrics.log'
@@ -57,17 +57,18 @@ def setup_metrics_logger():
     formatter = logging.Formatter('%(message)s')
     handler.setFormatter(formatter)
     
-    logger.addHandler(handler)
-    return logger
+    metrics_logger.addHandler(handler)
+    return metrics_logger
 
 # Initialize the logger
 metrics_logger = setup_metrics_logger()
 
 def log_metric(message):
     """Log a human-readable metric message with automatic timestamp"""
+    current_time = datetime.now()
     timestamped_message = f"{message} | Logged: {current_time:%Y-%m-%d %H:%M:%S}"
     metrics_logger.info(timestamped_message)
-    logger.info(timestamped_message)  # Also log to console using info.logger
+    logger.info(timestamped_message)
 
 # Support both token names for flexibility
 hf_token = HF_TOKEN
@@ -112,6 +113,8 @@ def Create_Graph_Tool(graph_config: str) -> str:
     Include educational_context to explain why the visualization helps learning.
     """
     start_create_graph_tool_time = time.perf_counter()
+    current_time = datetime.now()
+    
     try:
         # Validate it's proper JSON
         config = json.loads(graph_config)
@@ -125,9 +128,15 @@ def Create_Graph_Tool(graph_config: str) -> str:
         # Add educational context if provided
         if educational_context:
             context_html = f'<div style="margin: 10px 0; padding: 10px; background: #f8f9fa; border-left: 4px solid #007bff; font-style: italic;">💡 {educational_context}</div>'
-            return context_html + graph_html
+            result = context_html + graph_html
+        else:
+            result = graph_html
+        
+        end_create_graph_tool_time = time.perf_counter()
+        graph_create_graph_tool_time = end_create_graph_tool_time - start_create_graph_tool_time
+        log_metric(f"Graph tool creation time: {graph_create_graph_tool_time:0.4f} seconds. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
         
-        return graph_html
+        return result
         
     except json.JSONDecodeError as e:
         logger.error(f"Invalid JSON provided to graph tool: {e}")
@@ -135,13 +144,8 @@ def Create_Graph_Tool(graph_config: str) -> str:
     except Exception as e:
         logger.error(f"Error in graph generation: {e}")
         return f'<p style="color:red;">Error creating graph: {str(e)}</p>'
-    end_create_graph_tool_time = time.perf_counter()
-    graph_create_graph_tool_time = end_create_graph_tool_time - start_create_graph_tool_time
-
-    log_metric(f"Graph tool creation time: {graph_create_graph_tool_time:0.4f} seconds. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
 
 # --- Tool Decision Engine (Updated for LangGraph) ---
-start_graph_decision_time = time.perf_counter()
 class Tool_Decision_Engine:
     """Uses LLM to intelligently decide when visualization tools would be beneficial"""
     
@@ -168,6 +172,9 @@ Decision:"""
 
     def should_use_visualization(self, query: str) -> bool:
         """Enhanced decision logic with explicit exclusions"""
+        start_graph_decision_time = time.perf_counter()
+        current_time = datetime.now()
+        
         try:
             # Explicit exclusions for common non-visual queries
             exclusion_patterns = [
@@ -183,6 +190,9 @@ Decision:"""
             # Check exclusions first
             for pattern in exclusion_patterns:
                 if re.search(pattern, query_lower):
+                    end_graph_decision_time = time.perf_counter()
+                    graph_decision_time = end_graph_decision_time - start_graph_decision_time
+                    log_metric(f"Tool decision time (excluded): {graph_decision_time:0.4f} seconds. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
                     return False
             
             # Create decision prompt
@@ -198,19 +208,21 @@ Decision:"""
             logger.info(f"Tool decision for '{query[:50]}...': {decision_text}")
             
             # More strict parsing
-            if "YES" in decision_text and "NO" not in decision_text:
-                return True
-            return False
+            result = "YES" in decision_text and "NO" not in decision_text
+            
+            end_graph_decision_time = time.perf_counter()
+            graph_decision_time = end_graph_decision_time - start_graph_decision_time
+            log_metric(f"Tool decision time: {graph_decision_time:0.4f} seconds. Decision: {result}. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
+            
+            return result
             
         except Exception as e:
             logger.error(f"Error in tool decision making: {e}")
-            # Default to no tools if decision fails
+            end_graph_decision_time = time.perf_counter()
+            graph_decision_time = end_graph_decision_time - start_graph_decision_time
+            log_metric(f"Tool decision time (error): {graph_decision_time:0.4f} seconds. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
             return False
 
-end_graph_decision_time = time.perf_counter()
-graph_decision_time = end_graph_decision_time - start_graph_decision_time
-
-log_metric(f"Tool decision time: {graph_decision_time:0.4f} seconds. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
 # --- System Prompt ---
 SYSTEM_PROMPT = """You are Mimir, an expert multi-concept tutor designed to facilitate genuine learning and understanding. Your primary mission is to guide students through the learning process rather than providing direct answers to academic work.
 ## Core Educational Principles
@@ -266,6 +278,7 @@ class Qwen25SmallLLM(Runnable):
         super().__init__()
         logger.info(f"Loading model: {model_path} (use_4bit={use_4bit})")
         start_Loading_Model_time = time.perf_counter()
+        current_time = datetime.now()
 
         try:
             # Load tokenizer
@@ -321,6 +334,9 @@ class Qwen25SmallLLM(Runnable):
 
     def invoke(self, input: Input, config=None) -> Output:
         """Main invoke method for Runnable compatibility"""
+        start_invoke_time = time.perf_counter()
+        current_time = datetime.now()
+        
         # Handle both string and dict inputs for flexibility
         if isinstance(input, dict):
             prompt = input.get('input', str(input))
@@ -351,10 +367,19 @@ class Qwen25SmallLLM(Runnable):
                 )
 
             new_tokens = [out[len(inp):] for inp, out in zip(inputs.input_ids, outputs)]
-            return self.tokenizer.batch_decode(new_tokens, skip_special_tokens=True)[0].strip()
+            result = self.tokenizer.batch_decode(new_tokens, skip_special_tokens=True)[0].strip()
+            
+            end_invoke_time = time.perf_counter()
+            invoke_time = end_invoke_time - start_invoke_time
+            log_metric(f"LLM Invoke time: {invoke_time:0.4f} seconds. Input length: {len(prompt)} chars. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
+            
+            return result
 
         except Exception as e:
             logger.error(f"Generation error: {e}")
+            end_invoke_time = time.perf_counter()
+            invoke_time = end_invoke_time - start_invoke_time
+            log_metric(f"LLM Invoke time (error): {invoke_time:0.4f} seconds. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
             return f"[Error generating response: {str(e)}]"
 
     @property
@@ -371,6 +396,7 @@ class Educational_Agent:
     
     def __init__(self):
         start_init_and_langgraph_time = time.perf_counter()
+        current_time = datetime.now()
         
         self.llm = Qwen25SmallLLM(model_path="Qwen/Qwen2.5-1.5B-Instruct", use_4bit=True)
         self.tool_decision_engine = Tool_Decision_Engine(self.llm)
@@ -407,6 +433,7 @@ class Educational_Agent:
         def call_model(state: EducationalAgentState) -> dict:
             """Call the model with tool decision logic"""
             start_call_model_time = time.perf_counter()
+            current_time = datetime.now()
             
             messages = state["messages"]
             
@@ -503,6 +530,7 @@ Otherwise, provide a regular educational response.
         def handle_tools(state: EducationalAgentState) -> dict:
             """Handle tool execution"""
             start_handle_tools_time = time.perf_counter()
+            current_time = datetime.now()
             
             try:
                 messages = state["messages"]
@@ -573,7 +601,9 @@ Otherwise, provide a regular educational response.
     
     def chat(self, message: str, thread_id: str = "default") -> str:
         """Main chat interface"""
-        start_chat_time = time.perf_counter()    
+        start_chat_time = time.perf_counter()
+        current_time = datetime.now()
+        
         try:
             config = {"configurable": {"thread_id": thread_id}}
             
@@ -650,11 +680,6 @@ window.MathJax = {
 </script>
 '''
 
-end_init_and_langgraph_time = time.perf_counter()
-init_and_langgraph_time = end_init_and_langgraph_time - start_init_and_langgraph_time
-
-log_metric(f"Init and LangGraph workflow setup time: {init_and_langgraph_time:0.4f} seconds. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
-
 # --- HTML Head Content ---
 html_head_content = '''
 <meta charset="utf-8">
@@ -680,28 +705,36 @@ window.addEventListener('DOMContentLoaded', function () {
 '''
 
 # --- Core Logic Functions ---
-start_smart_truncate_time = time.perf_counter()
 def smart_truncate(text, max_length=3000):
     """Truncates text intelligently to the last full sentence or word."""
+    start_smart_truncate_time = time.perf_counter()
+    current_time = datetime.now()
+    
     if len(text) <= max_length:
+        end_smart_truncate_time = time.perf_counter()
+        smart_truncate_time = end_smart_truncate_time - start_smart_truncate_time
+        log_metric(f"Smart Truncate time: {smart_truncate_time:0.4f} seconds. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
         return text
     
     # Try to split by sentence
     sentences = re.split(r'(?<=[.!?])\s+', text[:max_length])
     if len(sentences) > 1:
-        return ' '.join(sentences[:-1]) + "... [Response truncated - ask for continuation]"
-    # Otherwise, split by word
-    words = text[:max_length].split()
-    return ' '.join(words[:-1]) + "... [Response truncated]"
+        result = ' '.join(sentences[:-1]) + "... [Response truncated - ask for continuation]"
+    else:
+        # Otherwise, split by word
+        words = text[:max_length].split()
+        result = ' '.join(words[:-1]) + "... [Response truncated]"
     
-end_smart_truncate_time = time.perf_counter()
-smart_truncate_time = end_smart_truncate_time - start_smart_truncate_time
-
-log_metric(f"Smart Truncate time: {smart_truncate_time:0.4f} seconds. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
+    end_smart_truncate_time = time.perf_counter()
+    smart_truncate_time = end_smart_truncate_time - start_smart_truncate_time
+    log_metric(f"Smart Truncate time: {smart_truncate_time:0.4f} seconds. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
+    
+    return result
 
-start_generate_response_with_agent_time = time.perf_counter()
 def generate_response_with_agent(message, max_retries=3):
     """Generate response using LangGraph agent."""
+    start_generate_response_with_agent_time = time.perf_counter()
+    current_time = datetime.now()
     
     for attempt in range(max_retries):
         try:
@@ -711,7 +744,13 @@ def generate_response_with_agent(message, max_retries=3):
             # Use the agent's chat method
             response = current_agent.chat(message)
             
-            return smart_truncate(response)
+            result = smart_truncate(response)
+            
+            end_generate_response_with_agent_time = time.perf_counter()
+            generate_response_with_agent_time = end_generate_response_with_agent_time - start_generate_response_with_agent_time
+            log_metric(f"Generate response with agent time: {generate_response_with_agent_time:0.4f} seconds. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
+            
+            return result
             
         except Exception as e:
             logger.error(f"Agent error (attempt {attempt + 1}): {e}")
@@ -719,61 +758,32 @@ def generate_response_with_agent(message, max_retries=3):
                 time.sleep(2)
                 continue
             else:
+                end_generate_response_with_agent_time = time.perf_counter()
+                generate_response_with_agent_time = end_generate_response_with_agent_time - start_generate_response_with_agent_time
+                log_metric(f"Generate response with agent time (error): {generate_response_with_agent_time:0.4f} seconds. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
                 return f"I apologize, but I encountered an error while processing your message: {str(e)}"
-end_generate_response_with_agent_time = time.perf_counter()
-generate_response_with_agent_time = end_generate_response_with_agent_time - start_generate_response_with_agent_time
-
-log_metric(f"Smart Truncate time: {generate_response_with_agent_time:0.4f} seconds. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
-
-start_chat_response_time = time.perf_counter()
 
 def chat_response(message, history=None):
     """Process chat message and return response."""
+    start_chat_response_time = time.perf_counter()
+    current_time = datetime.now()
+    
     try:
-        # Track metrics with timing context
-        start_time = time.time()
-        timing_context = {
-            'start_time': start_time,
-            'chunk_count': 0,
-            'provider_latency': 0.0
-        }
-        
-        try:
-            # Log start of interaction
-            metrics_tracker.log_interaction(
-                query=message,
-                response="", 
-                timing_context=timing_context,
-                error_occurred=False
-            )
-            logger.info("Metrics interaction logged successfully")
-        except Exception as metrics_error:
-            logger.error(f"Error in metrics_tracker.log_interaction: {metrics_error}")
-        
         # Generate response with LangGraph agent
         response = generate_response_with_agent(message)
         
-        # Log final metrics
-        try:
-            metrics_tracker.log_interaction(
-                query=message,
-                response=response,
-                timing_context=timing_context,
-                error_occurred=False
-            )
-        except Exception as metrics_error:
-            logger.error(f"Error in final metrics logging: {metrics_error}")
+        end_chat_response_time = time.perf_counter()
+        chat_response_time = end_chat_response_time - start_chat_response_time
+        log_metric(f"Chat response time: {chat_response_time:0.4f} seconds. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
         
         return response
         
     except Exception as e:
         logger.error(f"Error in chat_response: {e}")
+        end_chat_response_time = time.perf_counter()
+        chat_response_time = end_chat_response_time - start_chat_response_time
+        log_metric(f"Chat response time (error): {chat_response_time:0.4f} seconds. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
         return f"I apologize, but I encountered an error while processing your message: {str(e)}"
-        
-end_chat_response_time = time.perf_counter()
-chat_response_time = end_chat_response_time - start_chat_response_time
-
-log_metric(f"Smart Truncate time: {chat_response_time:0.4f} seconds. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
 
 def respond_and_update(message, history):
     """Main function to handle user submission."""
@@ -792,13 +802,13 @@ def respond_and_update(message, history):
 
 def clear_chat():
     """Clear the chat history."""
-    # Note: LangGraph handles conversation history automatically through thread_id
-    # We could clear by using a new thread_id, but for now we'll keep it simple
     return [], ""
 
-start_agent_warmup_time = time.perf_counter()
 def warmup_agent():
     """Warm up the agent with a test query to preload everything."""
+    start_agent_warmup_time = time.perf_counter()
+    current_time = datetime.now()
+    
     logger.info("Warming up LangGraph agent with test query...")
     try:
         current_agent = get_agent()
@@ -807,18 +817,21 @@ def warmup_agent():
         test_response = current_agent.chat("Hello, this is a warmup test.")
         logger.info(f"LangGraph agent warmup completed successfully! Test response length: {len(test_response)} chars")
         
+        end_agent_warmup_time = time.perf_counter()
+        agent_warmup_time = end_agent_warmup_time - start_agent_warmup_time
+        log_metric(f"Agent warmup time: {agent_warmup_time:0.4f} seconds. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
+        
     except Exception as e:
         logger.error(f"LangGraph agent warmup failed: {e}")
-        
-end_agent_warmup_time = time.perf_counter()
-agent_warmup_time = end_agent_warmup_time - start_agent_warmup_time
-
-log_metric(f"Smart Truncate time: {agent_warmup_time:0.4f} seconds. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
+        end_agent_warmup_time = time.perf_counter()
+        agent_warmup_time = end_agent_warmup_time - start_agent_warmup_time
+        log_metric(f"Agent warmup time (error): {agent_warmup_time:0.4f} seconds. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
 
 # --- UI: Interface Creation ---
-start_create_interface_time = time.perf_counter()
 def create_interface():
     """Creates and configures the complete Gradio interface."""
+    start_create_interface_time = time.perf_counter()
+    current_time = datetime.now()
     
     # Read CSS file
     custom_css = ""
@@ -881,13 +894,12 @@ def create_interface():
             
             # Apply CSS at the very end
             gr.HTML(f'<style>{custom_css}</style>')
-        
-        return demo
-
-end_create_interface_time = time.perf_counter()
-create_interface_time = end_create_interfacep_time - start_create_interface_time
-
-log_metric(f"Smart Truncate time: {create_interface_time:0.4f} seconds. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
+    
+    end_create_interface_time = time.perf_counter()
+    create_interface_time = end_create_interface_time - start_create_interface_time
+    log_metric(f"Create interface time: {create_interface_time:0.4f} seconds. Timestamp: {current_time:%Y-%m-%d %H:%M:%S}")
+    
+    return demo
 
 # --- Main Execution ---
 if __name__ == "__main__":