perf: Add detailed performance logging to model retrieval, filtering, and sorting operations. see #711

py/routes/handlers/model_handlers.py

@@ -5,6 +5,7 @@ import asyncio
 import json
 import logging
 import os
+import time
 from dataclasses import dataclass
 from typing import Any, Awaitable, Callable, Dict, Iterable, List, Mapping, Optional
 
@@ -160,9 +161,12 @@ class ModelListingHandler:
         self._logger = logger
 
     async def get_models(self, request: web.Request) -> web.Response:
+        start_time = time.perf_counter()
         try:
             params = self._parse_common_params(request)
             result = await self._service.get_paginated_data(**params)
+            
+            format_start = time.perf_counter()
             formatted_result = {
                 "items": [await self._service.format_response(item) for item in result["items"]],
                 "total": result["total"],
@@ -170,6 +174,13 @@ class ModelListingHandler:
                 "page_size": result["page_size"],
                 "total_pages": result["total_pages"],
             }
+            format_duration = time.perf_counter() - format_start
+            
+            duration = time.perf_counter() - start_time
+            self._logger.info(
+                "Request for %s/list took %.3fs (formatting: %.3fs)",
+                self._service.model_type, duration, format_duration
+            )
             return web.json_response(formatted_result)
         except Exception as exc:
             self._logger.error("Error retrieving %ss: %s", self._service.model_type, exc, exc_info=True)

py/services/base_model_service.py

@@ -3,6 +3,7 @@ import asyncio
 from typing import Any, Dict, List, Optional, Type, TYPE_CHECKING
 import logging
 import os
+import time
 
 from ..utils.constants import VALID_LORA_TYPES
 from ..utils.models import BaseModelMetadata
@@ -79,10 +80,16 @@ class BaseModelService(ABC):
         **kwargs,
     ) -> Dict:
         """Get paginated and filtered model data"""
+        overall_start = time.perf_counter()
 
         sort_params = self.cache_repository.parse_sort(sort_by)
+        
+        t0 = time.perf_counter()
         sorted_data = await self.cache_repository.fetch_sorted(sort_params)
+        fetch_duration = time.perf_counter() - t0
+        initial_count = len(sorted_data)
 
+        t1 = time.perf_counter()
         if hash_filters:
             filtered_data = await self._apply_hash_filters(sorted_data, hash_filters)
         else:
@@ -112,17 +119,25 @@ class BaseModelService(ABC):
             
             if allow_selling_generated_content is not None:
                 filtered_data = await self._apply_allow_selling_filter(filtered_data, allow_selling_generated_content)
+        filter_duration = time.perf_counter() - t1
+        post_filter_count = len(filtered_data)
 
         annotated_for_filter: Optional[List[Dict]] = None
+        t2 = time.perf_counter()
         if update_available_only:
             annotated_for_filter = await self._annotate_update_flags(filtered_data)
             filtered_data = [
                 item for item in annotated_for_filter
                 if item.get('update_available')
             ]
+        update_filter_duration = time.perf_counter() - t2
+        final_count = len(filtered_data)
 
+        t3 = time.perf_counter()
         paginated = self._paginate(filtered_data, page, page_size)
+        pagination_duration = time.perf_counter() - t3
 
+        t4 = time.perf_counter()
         if update_available_only:
             # Items already include update flags thanks to the pre-filter annotation.
             paginated['items'] = list(paginated['items'])
@@ -130,6 +145,16 @@ class BaseModelService(ABC):
             paginated['items'] = await self._annotate_update_flags(
                 paginated['items'],
             )
+        annotate_duration = time.perf_counter() - t4
+        
+        overall_duration = time.perf_counter() - overall_start
+        logger.info(
+            "%s.get_paginated_data took %.3fs (fetch: %.3fs, filter: %.3fs, update_filter: %.3fs, pagination: %.3fs, annotate: %.3fs). "
+            "Counts: initial=%d, post_filter=%d, final=%d",
+            self.__class__.__name__, overall_duration, fetch_duration, filter_duration, 
+            update_filter_duration, pagination_duration, annotate_duration,
+            initial_count, post_filter_count, final_count
+        )
         return paginated
 
     

py/services/model_cache.py

@@ -1,4 +1,8 @@
 import asyncio
+import time
+import logging
+
+logger = logging.getLogger(__name__)
 from typing import Any, Dict, List, Optional, Tuple
 from dataclasses import dataclass, field
 from operator import itemgetter
@@ -212,40 +216,53 @@ class ModelCache:
 
     def _sort_data(self, data: List[Dict], sort_key: str, order: str) -> List[Dict]:
         """Sort data by sort_key and order"""
+        start_time = time.perf_counter()
         reverse = (order == 'desc')
         if sort_key == 'name':
             # Natural sort by configured display name, case-insensitive
-            return natsorted(
+            result = natsorted(
                 data,
                 key=lambda x: self._get_display_name(x).lower(),
                 reverse=reverse
             )
         elif sort_key == 'date':
             # Sort by modified timestamp
-            return sorted(
+            result = sorted(
                 data,
                 key=itemgetter('modified'),
                 reverse=reverse
             )
         elif sort_key == 'size':
             # Sort by file size
-            return sorted(
+            result = sorted(
                 data,
                 key=itemgetter('size'),
                 reverse=reverse
             )
         else:
             # Fallback: no sort
-            return list(data)
+            result = list(data)
+        
+        duration = time.perf_counter() - start_time
+        if duration > 0.05:
+            logger.info("ModelCache._sort_data(%s, %s) for %d items took %.3fs", sort_key, order, len(data), duration)
+        return result
 
     async def get_sorted_data(self, sort_key: str = 'name', order: str = 'asc') -> List[Dict]:
         """Get sorted data by sort_key and order, using cache if possible"""
         async with self._lock:
             if (sort_key, order) == self._last_sort:
                 return self._last_sorted_data
+            
+            start_time = time.perf_counter()
             sorted_data = self._sort_data(self.raw_data, sort_key, order)
             self._last_sort = (sort_key, order)
             self._last_sorted_data = sorted_data
+            
+            duration = time.perf_counter() - start_time
+            if duration > 0.1:
+                logger.debug("ModelCache.get_sorted_data(%s, %s) took %.3fs", sort_key, order, duration)
+            
             return sorted_data
 
     async def update_name_display_mode(self, display_mode: str) -> None:

py/services/model_query.py

@@ -5,6 +5,10 @@ from typing import Any, Dict, Iterable, List, Mapping, Optional, Sequence, Tuple
 
 from ..utils.constants import NSFW_LEVELS
 from ..utils.utils import fuzzy_match as default_fuzzy_match
+import time
+import logging
+
+logger = logging.getLogger(__name__)
 
 
 DEFAULT_CIVITAI_MODEL_TYPE = "LORA"
@@ -115,22 +119,33 @@ class ModelFilterSet:
 
     def apply(self, data: Iterable[Dict[str, Any]], criteria: FilterCriteria) -> List[Dict[str, Any]]:
         """Return items that satisfy the provided criteria."""
+        overall_start = time.perf_counter()
         items = list(data)
+        initial_count = len(items)
 
         if self._settings.get("show_only_sfw", False):
+            t0 = time.perf_counter()
             threshold = self._nsfw_levels.get("R", 0)
             items = [
                 item for item in items
                 if not item.get("preview_nsfw_level") or item.get("preview_nsfw_level") < threshold
             ]
+            sfw_duration = time.perf_counter() - t0
+        else:
+            sfw_duration = 0
 
+        favorites_duration = 0
         if criteria.favorites_only:
+            t0 = time.perf_counter()
             items = [item for item in items if item.get("favorite", False)]
+            favorites_duration = time.perf_counter() - t0
 
+        folder_duration = 0
         folder = criteria.folder
         options = criteria.search_options or {}
         recursive = bool(options.get("recursive", True))
         if folder is not None:
+            t0 = time.perf_counter()
             if recursive:
                 if folder:
                     folder_with_sep = f"{folder}/"
@@ -140,61 +155,82 @@ class ModelFilterSet:
                     ]
             else:
                 items = [item for item in items if item.get("folder") == folder]
+            folder_duration = time.perf_counter() - t0
 
+        base_models_duration = 0
         base_models = criteria.base_models or []
         if base_models:
+            t0 = time.perf_counter()
             base_model_set = set(base_models)
             items = [item for item in items if item.get("base_model") in base_model_set]
+            base_models_duration = time.perf_counter() - t0
 
+        tags_duration = 0
         tag_filters = criteria.tags or {}
-        include_tags = set()
-        exclude_tags = set()
-        if isinstance(tag_filters, dict):
-            for tag, state in tag_filters.items():
-                if not tag:
-                    continue
-                if state == "exclude":
-                    exclude_tags.add(tag)
-                else:
-                    include_tags.add(tag)
-        else:
-            include_tags = {tag for tag in tag_filters if tag}
+        if tag_filters:
+            t0 = time.perf_counter()
+            include_tags = set()
+            exclude_tags = set()
+            if isinstance(tag_filters, dict):
+                for tag, state in tag_filters.items():
+                    if not tag:
+                        continue
+                    if state == "exclude":
+                        exclude_tags.add(tag)
+                    else:
+                        include_tags.add(tag)
+            else:
+                include_tags = {tag for tag in tag_filters if tag}
 
-        if include_tags:
-            def matches_include(item_tags):
-                if not item_tags and "__no_tags__" in include_tags:
-                    return True
-                return any(tag in include_tags for tag in (item_tags or []))
+            if include_tags:
+                def matches_include(item_tags):
+                    if not item_tags and "__no_tags__" in include_tags:
+                        return True
+                    return any(tag in include_tags for tag in (item_tags or []))
 
-            items = [
-                item for item in items
-                if matches_include(item.get("tags"))
-            ]
+                items = [
+                    item for item in items
+                    if matches_include(item.get("tags"))
+                ]
 
-        if exclude_tags:
-            def matches_exclude(item_tags):
-                if not item_tags and "__no_tags__" in exclude_tags:
-                    return True
-                return any(tag in exclude_tags for tag in (item_tags or []))
+            if exclude_tags:
+                def matches_exclude(item_tags):
+                    if not item_tags and "__no_tags__" in exclude_tags:
+                        return True
+                    return any(tag in exclude_tags for tag in (item_tags or []))
 
-            items = [
-                item for item in items
-                if not matches_exclude(item.get("tags"))
-            ]
+                items = [
+                    item for item in items
+                    if not matches_exclude(item.get("tags"))
+                ]
+            tags_duration = time.perf_counter() - t0
 
+        model_types_duration = 0
         model_types = criteria.model_types or []
-        normalized_model_types = {
-            model_type for model_type in (
-                normalize_civitai_model_type(value) for value in model_types
-            )
-            if model_type
-        }
-        if normalized_model_types:
-            items = [
-                item for item in items
-                if normalize_civitai_model_type(resolve_civitai_model_type(item)) in normalized_model_types
-            ]
+        if model_types:
+            t0 = time.perf_counter()
+            normalized_model_types = {
+                model_type for model_type in (
+                    normalize_civitai_model_type(value) for value in model_types
+                )
+                if model_type
+            }
+            if normalized_model_types:
+                items = [
+                    item for item in items
+                    if normalize_civitai_model_type(resolve_civitai_model_type(item)) in normalized_model_types
+                ]
+            model_types_duration = time.perf_counter() - t0
 
+        duration = time.perf_counter() - overall_start
+        if duration > 0.1: # Only log if it's potentially slow
+            logger.info(
+                "ModelFilterSet.apply took %.3fs (sfw: %.3fs, fav: %.3fs, folder: %.3fs, base: %.3fs, tags: %.3fs, types: %.3fs). "
+                "Count: %d -> %d",
+                duration, sfw_duration, favorites_duration, folder_duration, 
+                base_models_duration, tags_duration, model_types_duration,
+                initial_count, len(items)
+            )
         return items