perf: add debug msg

Author: ibuler

backend/open_webui/routers/openai.py

@@ -2,6 +2,7 @@
 import hashlib
 import json
 import logging
+import time
 from typing import Optional
 
 import aiohttp
@@ -488,6 +489,7 @@ async def get_filtered_models(models, user):
 )
 async def get_all_models(request: Request, user: UserModel) -> dict[str, list]:
     log.info("get_all_models()")
+    t1 = time.time()
 
     if not request.app.state.config.ENABLE_OPENAI_API:
         return {"data": []}
@@ -548,6 +550,9 @@ def get_merged_models(model_lists):
     models = get_merged_models(map(extract_data, responses))
     log.debug(f"models: {models}")
 
+    t2 = time.time()
+    delta = round(t2 - t1, 2)
+    log.debug(f"OpenAI get_all_models() took {delta}s")
     request.app.state.OPENAI_MODELS = models
     return {"data": list(models.values())}
 
@@ -939,6 +944,7 @@ async def generate_chat_completion(
             trust_env=True, timeout=aiohttp.ClientTimeout(total=AIOHTTP_CLIENT_TIMEOUT)
         )
 
+        t1 = time.time()
         r = await session.request(
             method="POST",
             url=request_url,
@@ -947,6 +953,9 @@ async def generate_chat_completion(
             cookies=cookies,
             ssl=AIOHTTP_CLIENT_SESSION_SSL,
         )
+        t2 = time.time()
+        delta = round(t2 - t1, 2)
+        log.debug(f"OpenAI request session.request() took {delta}s")
 
         # Check if response is SSE
         if "text/event-stream" in r.headers.get("Content-Type", ""):

backend/open_webui/utils/middleware.py

@@ -338,9 +338,16 @@ def get_tools_function_calling_payload(messages, task_model_id, content):
     )
 
     try:
+        t1 = time.time()
         response = await generate_chat_completion(request, form_data=payload, user=user)
+        t2 = time.time()
+        delta = round(t2 - t1, 2)
+        log.debug(f"Chat completion tools handler took {delta}s")
         log.debug(f"{response=}")
         content = await get_content_from_response(response)
+        t3 = time.time()
+        delta = round(t3 - t2, 2)
+        log.debug(f"Get content from response took {delta}s")
         log.debug(f"{content=}")
 
         if not content:
@@ -383,6 +390,7 @@ async def tool_call_handler(tool_call):
                         if k in allowed_params
                     }
 
+                    t4 = time.time()
                     if tool.get("direct", False):
                         tool_result = await event_caller(
                             {
@@ -399,6 +407,9 @@ async def tool_call_handler(tool_call):
                     else:
                         tool_function = tool["callable"]
                         tool_result = await tool_function(**tool_function_params)
+                    t5 = time.time()
+                    delta = round(t5 - t4, 2)
+                    log.info(f"Tool {tool_function_name} took {delta}s")
 
                 except Exception as e:
                     tool_result = str(e)
@@ -437,7 +448,7 @@ async def tool_call_handler(tool_call):
                         )
 
                 print(
-                    f"Tool {tool_function_name} result: {tool_result}",
+                    f"Tool {tool_function_name}",
                     tool_result_files,
                     tool_result_embeds,
                 )

backend/open_webui/utils/models.py

@@ -2,6 +2,7 @@
 import logging
 import asyncio
 import sys
+import copy
 
 from aiocache import cached
 from fastapi import Request
@@ -78,9 +79,25 @@ async def get_all_base_models(request: Request, user: UserModel = None):
 
 
 async def get_all_models(request, refresh: bool = False, user: UserModel = None):
+    t1 = time.time()
+    
+    # Early return if cached final result exists and cache is enabled
     if (
         request.app.state.MODELS
-        and request.app.state.BASE_MODELS
+        and request.app.state.config.ENABLE_BASE_MODELS_CACHE
+        and not refresh
+    ):
+        # Convert cached dict to list format with deep copy and return immediately
+        # This avoids all expensive processing below (lines 107-337)
+        models = [copy.deepcopy(model) for model in request.app.state.MODELS.values()]
+        log.debug(f"get_all_models() returned {len(models)} models from cache")
+        t2 = time.time()
+        log.debug(f"get_all_models() took {t2 - t1} seconds (cached)")
+        return models
+    
+    # Continue with full processing if cache miss or refresh requested
+    if (
+        request.app.state.BASE_MODELS
         and (request.app.state.config.ENABLE_BASE_MODELS_CACHE and not refresh)
     ):
         base_models = request.app.state.BASE_MODELS
@@ -323,6 +340,8 @@ def get_function_module_by_id(function_id):
     log.debug(f"get_all_models() returned {len(models)} models")
 
     request.app.state.MODELS = {model["id"]: model for model in models}
+    t2 = time.time()
+    log.debug(f"get_all_models() took {t2 - t1} seconds")
     return models
 
 

src/lib/components/chat/Chat.svelte

@@ -2307,7 +2307,7 @@
 			_chatId = chat.id;
 			await chatId.set(_chatId);
 
-			window.history.replaceState(history.state, '', `/c/${_chatId}`);
+			window.history.replaceState(history.state, '', `/kael/c/${_chatId}`);
 
 			await tick();
 

vite.config.ts

@@ -29,6 +29,14 @@ export default defineConfig({
 	},
 	server: {
 		port: 5173,
+		watch: {
+			// Exclude backend files from triggering HMR reloads
+			ignored: [
+				'**/backend/**',
+				'**/backend/open_webui/jms/data/**',
+				'**/*.cast'
+			]
+		},
 		proxy: {
 			'^/kael/api/': {
 				target: 'http://localhost:8083',