a “slow request” logging, log when a request exceeds the budgeted prompt and gets compacted

app.py

@@ -179,6 +179,11 @@ def _compact_messages(messages: list[dict], max_tokens: int) -> list[dict]:
     return compacted
 
 
+def _estimate_messages_tokens(messages: list[dict]) -> int:
+    """Estimate total tokens for a list of messages."""
+    return sum(_estimate_tokens(str(m.get("content", ""))) for m in messages)
+
+
 @dataclass
 class CachedModel:
     """Represents a cached model with its process and connection info."""
@@ -953,6 +958,7 @@ async def chat_completions(request: ChatCompletionRequest, raw_request: Request)
     - Request metrics tracking
     """
     request_id = getattr(raw_request.state, "request_id", "-")
+    slow_task: Optional[asyncio.Task] = None
     try:
         request_start = time.time()
 
@@ -965,7 +971,30 @@ async def chat_completions(request: ChatCompletionRequest, raw_request: Request)
             raise HTTPException(status_code=500, detail="Current model not loaded")
 
         # Forward to llama-server using aiohttp
+        prompt_budget = CONTEXT_SIZE - request.max_tokens - PROMPT_MARGIN_TOKENS
+        original_tokens = _estimate_messages_tokens(request.messages)
+        if prompt_budget > 0 and original_tokens > prompt_budget:
+            logger.warning(
+                f"request_id={request_id} prompt_compaction "
+                f"original_tokens≈{original_tokens} budget≈{prompt_budget}"
+            )
+
         compacted_messages = _compact_messages(request.messages, request.max_tokens)
+
+        compacted_tokens = _estimate_messages_tokens(compacted_messages)
+        if compacted_tokens < original_tokens:
+            logger.info(
+                f"request_id={request_id} prompt_compacted "
+                f"tokens≈{original_tokens}->{compacted_tokens}"
+            )
+
+        async def _slow_request_logger():
+            await asyncio.sleep(30)
+            elapsed = time.time() - request_start
+            logger.warning(f"request_id={request_id} slow_request {elapsed:.1f}s")
+
+        slow_task = asyncio.create_task(_slow_request_logger())
+
         payload = {
             "messages": compacted_messages,
             "max_tokens": request.max_tokens,
@@ -1000,6 +1029,9 @@ async def chat_completions(request: ChatCompletionRequest, raw_request: Request)
     except Exception:
         logger.exception(f"request_id={request_id} chat_completions error")
         raise
+    finally:
+        if slow_task and not slow_task.done():
+            slow_task.cancel()
 
 
 async def search_web_async(query: str, max_results: int = 5) -> list[dict]:
@@ -1074,6 +1106,7 @@ async def web_chat_completions(request: WebChatRequest, raw_request: Request):
     - Parallel execution where possible
     """
     request_id = getattr(raw_request.state, "request_id", "-")
+    slow_task: Optional[asyncio.Task] = None
     try:
         # Get the last user message as search query
         user_messages = [msg for msg in request.messages if msg.get("role") == "user"]
@@ -1109,8 +1142,29 @@ Always cite sources when using information from the search results."""
             raise HTTPException(status_code=500, detail="HTTP session not initialized")
 
         # Compact messages to fit within context
+        prompt_budget = CONTEXT_SIZE - request.max_tokens - PROMPT_MARGIN_TOKENS
+        original_tokens = _estimate_messages_tokens(augmented_messages)
+        if prompt_budget > 0 and original_tokens > prompt_budget:
+            logger.warning(
+                f"request_id={request_id} prompt_compaction "
+                f"original_tokens≈{original_tokens} budget≈{prompt_budget}"
+            )
+
         augmented_messages = _compact_messages(augmented_messages, request.max_tokens)
 
+        compacted_tokens = _estimate_messages_tokens(augmented_messages)
+        if compacted_tokens < original_tokens:
+            logger.info(
+                f"request_id={request_id} prompt_compacted "
+                f"tokens≈{original_tokens}->{compacted_tokens}"
+            )
+
+        async def _slow_request_logger():
+            await asyncio.sleep(30)
+            logger.warning(f"request_id={request_id} slow_request 30.0s")
+
+        slow_task = asyncio.create_task(_slow_request_logger())
+
         # Get current model from cache
         cached_model = model_cache.get(current_model)
         if not cached_model:
@@ -1146,6 +1200,9 @@ Always cite sources when using information from the search results."""
     except Exception as e:
         logger.exception(f"request_id={request_id} web_chat_completions error")
         raise HTTPException(status_code=500, detail=f"Error: {str(e)}")
+    finally:
+        if slow_task and not slow_task.done():
+            slow_task.cancel()
 
 
 @app.get(