diff --git a/py/routes/handlers/model_handlers.py b/py/routes/handlers/model_handlers.py index babf5b63..9d8100c8 100644 --- a/py/routes/handlers/model_handlers.py +++ b/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) diff --git a/py/services/base_model_service.py b/py/services/base_model_service.py index 84db592b..0c35dc19 100644 --- a/py/services/base_model_service.py +++ b/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 diff --git a/py/services/model_cache.py b/py/services/model_cache.py index abd8b68b..466a9803 100644 --- a/py/services/model_cache.py +++ b/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: diff --git a/py/services/model_query.py b/py/services/model_query.py index c5dfc59b..c6287dc0 100644 --- a/py/services/model_query.py +++ b/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