diff --git a/app/logger.py b/app/logger.py index bde815822..1aed54e37 100644 --- a/app/logger.py +++ b/app/logger.py @@ -2,9 +2,12 @@ from collections import deque from datetime import datetime import io import logging +import os import sys import threading +import comfy.logging + ANSI_NAMED_COLORS = { 'black': '\033[30m', 'red': '\033[31m', @@ -18,6 +21,7 @@ ANSI_NAMED_COLORS = { ANSI_LEVEL_COLORS = { 'DEBUG': ANSI_NAMED_COLORS['cyan'], + 'DETAIL': ANSI_NAMED_COLORS['blue'], 'INFO': ANSI_NAMED_COLORS['green'], 'WARNING': ANSI_NAMED_COLORS['yellow'], 'ERROR': ANSI_NAMED_COLORS['red'], @@ -85,7 +89,12 @@ def on_flush(callback): if stderr_interceptor is not None: stderr_interceptor.on_flush(callback) -def setup_logger(log_level: str = 'INFO', capacity: int = 300, use_stdout: bool = False): + +def get_log_level(level): + return comfy.logging.DETAIL if level == "DETAIL" else logging.getLevelName(level) + + +def setup_logger(log_level: str = 'INFO', file_outputs=None, capacity: int = 300, use_stdout: bool = False): global logs if logs: return @@ -99,13 +108,18 @@ def setup_logger(log_level: str = 'INFO', capacity: int = 300, use_stdout: bool stderr_interceptor = sys.stderr = LogInterceptor(sys.stderr) # Setup default global logger + if file_outputs is None: + file_outputs = [('DETAIL', 'comfyui_detail.log')] logger = logging.getLogger() - logger.setLevel(log_level) + console_level = get_log_level(log_level) + file_levels = [get_log_level(level) for level, _ in file_outputs] + logger.setLevel(min(console_level, *file_levels)) formatter = ColoredFormatter("%(message)s") stream_handler = logging.StreamHandler() stream_handler.setFormatter(formatter) + stream_handler.setLevel(console_level) if use_stdout: # Only errors and critical to stderr @@ -114,11 +128,24 @@ def setup_logger(log_level: str = 'INFO', capacity: int = 300, use_stdout: bool # Lesser to stdout stdout_handler = logging.StreamHandler(sys.stdout) stdout_handler.setFormatter(formatter) + stdout_handler.setLevel(console_level) stdout_handler.addFilter(lambda record: record.levelno < logging.ERROR) logger.addHandler(stdout_handler) logger.addHandler(stream_handler) + for output_level, output_path in file_outputs: + output_path = os.path.abspath(output_path) + try: + output_handler = logging.FileHandler(output_path, encoding="utf-8") + except OSError as e: + logging.warning("Could not open %s log %s: %s", output_level, output_path, e) + continue + output_handler.setLevel(get_log_level(output_level)) + output_handler.setFormatter(logging.Formatter("[%(asctime)s] [%(levelname)s] %(message)s")) + logger.addHandler(output_handler) + logging.info("%s log: %s", output_level.title(), output_path) + STARTUP_WARNINGS = [] diff --git a/comfy/cli_args.py b/comfy/cli_args.py index 8e03ed032..792148f0a 100644 --- a/comfy/cli_args.py +++ b/comfy/cli_args.py @@ -33,6 +33,31 @@ class EnumAction(argparse.Action): setattr(namespace, self.dest, value) +LOG_LEVELS = ('DEBUG', 'DETAIL', 'INFO', 'WARNING', 'ERROR', 'CRITICAL') + + +class VerboseAction(argparse.Action): + def __call__(self, parser, namespace, values, option_string=None): + if len(values) == 0: + output = ('DEBUG', None) + elif len(values) == 1 and values[0] in LOG_LEVELS: + output = (values[0], None) + elif len(values) == 2 and values[0] in LOG_LEVELS: + output = tuple(values) + else: + parser.error(f"{option_string} expects no values, a console LEVEL, or LEVEL FILE") + setattr(namespace, self.dest, [*getattr(namespace, self.dest, []), output]) + + +def get_console_log_level(outputs): + console_levels = [level for level, path in outputs if path is None] + return min(console_levels, key=LOG_LEVELS.index, default='INFO') + + +def get_file_log_outputs(outputs): + return [(level, path) for level, path in outputs if path is not None] + + parser = argparse.ArgumentParser() parser.add_argument("--listen", type=str, default="127.0.0.1", metavar="IP", nargs="?", const="0.0.0.0,::", help="Specify the IP address to listen on (default: 127.0.0.1). You can give a list of ip addresses by separating them with a comma like: 127.2.2.2,127.3.3.3 If --listen is provided without an argument, it defaults to 0.0.0.0,:: (listens on all ipv4 and ipv6)") @@ -187,7 +212,7 @@ parser.add_argument("--disable-api-nodes", action="store_true", help="Disable lo parser.add_argument("--multi-user", action="store_true", help="Enables per-user storage.") -parser.add_argument("--verbose", default='INFO', const='DEBUG', nargs="?", choices=['DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'], help='Set the logging level') +parser.add_argument("--verbose", action=VerboseAction, nargs='*', default=[], metavar='LEVEL FILE', help='Set console logging with no values or LEVEL, or add a LEVEL FILE log output. May be repeated.') parser.add_argument("--log-stdout", action="store_true", help="Send normal process output to stdout instead of stderr (default).") diff --git a/comfy/logging.py b/comfy/logging.py new file mode 100644 index 000000000..cc785296d --- /dev/null +++ b/comfy/logging.py @@ -0,0 +1,10 @@ +import logging + + +DETAIL = 15 +logging.addLevelName(DETAIL, "DETAIL") + + +def detail(message, *args, **kwargs): + kwargs.setdefault("stacklevel", 2) + logging.log(DETAIL, message, *args, **kwargs) diff --git a/comfy/model_management.py b/comfy/model_management.py index eb768d783..f7351224d 100644 --- a/comfy/model_management.py +++ b/comfy/model_management.py @@ -34,6 +34,7 @@ import comfy.utils import comfy.quant_ops import comfy_aimdo.host_buffer import comfy_aimdo.vram_buffer +from comfy.logging import detail from typing import TYPE_CHECKING if TYPE_CHECKING: @@ -836,6 +837,8 @@ def minimum_inference_memory(): def free_memory(memory_required, device, keep_loaded=[], for_dynamic=False, pins_required=0, ram_required=0): cleanup_models_gc() + if not for_dynamic: + detail("Non dynamic memory free called! memory_required=%s pins_required=%s ram_required=%s", memory_required, pins_required, ram_required) unloaded_model = [] can_unload = [] unloaded_models = [] @@ -974,6 +977,9 @@ def load_models_gpu(models, memory_required=0, force_patch_weights=False, minimu lowvram_model_memory = 0.1 loaded_model.model_load(lowvram_model_memory, force_patch_weights=force_patch_weights) + vram_used = 0 if is_device_cpu(torch_dev) else loaded_model.model_loaded_memory() + ram_used = model.loaded_ram_size() if model.is_dynamic() else loaded_model.model_memory() - vram_used + detail("Model loaded: patcher=%s model=%s ram_mb=%.1f vram_mb=%.1f", model.__class__.__name__, model.model.__class__.__name__, ram_used / (1024 ** 2), vram_used / (1024 ** 2)) current_loaded_models.insert(0, loaded_model) return diff --git a/comfy/model_patcher.py b/comfy/model_patcher.py index 39246b95c..e44322e72 100644 --- a/comfy/model_patcher.py +++ b/comfy/model_patcher.py @@ -22,6 +22,7 @@ import collections import inspect import logging import math +import time import uuid from typing import Callable, Optional @@ -37,6 +38,7 @@ import comfy.patcher_extension import comfy.utils import comfy_aimdo.host_buffer from comfy.comfy_types import UnetWrapperFunction +from comfy.logging import detail from comfy.quant_ops import QuantizedTensor from comfy.patcher_extension import CallbacksMP, PatcherInjection, WrappersMP @@ -1989,10 +1991,25 @@ class ModelPatcherDynamic(ModelPatcher): assert self.load_device != torch.device("cpu") vbar = self._vbar_get() - freed = 0 if vbar is None else vbar.free_memory(memory_to_free) + vbar_freed = 0 if vbar is None else vbar.free_memory(memory_to_free) + freed = vbar_freed + backup_freed = 0 if freed < memory_to_free: - freed += self.restore_loaded_backups() + backup_freed = self.restore_loaded_backups() + freed += backup_freed + + method = "vbar+backups" if vbar_freed and backup_freed else "vbar" if vbar_freed else "backups" if backup_freed else "none" + free_methods = getattr(self, "_free_methods", {}) + free_methods[method] = free_methods.get(method, 0) + 1 + self._free_methods = free_methods + now = time.monotonic() + if now - getattr(self, "_last_free_log_time", 0) >= 5: + requested = "all" if memory_to_free >= 1e30 else f"{memory_to_free / (1024 ** 2):.1f}MB" + prevailing_method = max(free_methods, key=free_methods.get) + detail("AIMDO free: model=%s device=%s prevailing_method=%s methods=%s requested=%s vbar_mb=%.1f backups_mb=%.1f", self.model.__class__.__name__, self.load_device, prevailing_method, free_methods, requested, vbar_freed / (1024 ** 2), backup_freed / (1024 ** 2)) + self._free_methods = {} + self._last_free_log_time = now return freed diff --git a/comfy/samplers.py b/comfy/samplers.py index 25c5a855f..9f571ece9 100755 --- a/comfy/samplers.py +++ b/comfy/samplers.py @@ -20,6 +20,7 @@ import comfy.hooks import comfy.context_windows import comfy.multigpu import comfy.utils +from comfy.logging import detail import scipy.stats import numpy @@ -991,10 +992,15 @@ class KSAMPLER(Sampler): noise = model_wrap.inner_model.model_sampling.noise_scaling(sigmas[0], noise, latent_image, self.max_denoise(model_wrap, sigmas)) - k_callback = None total_steps = len(sigmas) - 1 - if callback is not None: - k_callback = lambda x: callback(x["i"], x["denoised"], x["x"], total_steps) + first_step = True + def k_callback(x): + nonlocal first_step + if first_step: + detail("First sampler step: model=%s sampler=%s step=%s total_steps=%s cfg=%s seed=%s sigma=%s sigma_hat=%s latent_shape=%s denoised_shape=%s", model_wrap.model_patcher.model.__class__.__name__, self.sampler_function.__name__, x["i"], total_steps, model_wrap.cfg, extra_args.get("seed"), x.get("sigma"), x.get("sigma_hat"), tuple(x["x"].shape), tuple(x["denoised"].shape)) + first_step = False + if callback is not None: + callback(x["i"], x["denoised"], x["x"], total_steps) samples = self.sampler_function(model_k, noise, sigmas, extra_args=extra_args, callback=k_callback, disable=disable_pbar, **self.extra_options) samples = model_wrap.inner_model.model_sampling.inverse_noise_scaling(sigmas[-1], samples) @@ -1270,10 +1276,13 @@ class CFGGuider: return latent_image if latent_image.is_nested: + sampler_shapes = [tuple(x.shape) for x in latent_image.unbind()] latent_image, latent_shapes = comfy.utils.pack_latents(latent_image.unbind()) noise, _ = comfy.utils.pack_latents(noise.unbind()) else: latent_shapes = [latent_image.shape] + sampler_shapes = [tuple(latent_image.shape)] + detail("Sampler: model=%s latent_shapes=%s", self.model_patcher.model.__class__.__name__, sampler_shapes) if denoise_mask is not None: if denoise_mask.is_nested: diff --git a/comfy_execution/caching.py b/comfy_execution/caching.py index d60aa1e50..3340e5116 100644 --- a/comfy_execution/caching.py +++ b/comfy_execution/caching.py @@ -524,6 +524,13 @@ class RAMPressureCache(LRUCache): def __init__(self, key_class, enable_providers=False): super().__init__(key_class, 0, enable_providers=enable_providers) self.timestamps = {} + self.active_evictions = False + self.full_evictions = False + + async def set_prompt(self, dynprompt, node_ids, is_changed_cache): + self.active_evictions = False + self.full_evictions = False + await super().set_prompt(dynprompt, node_ids, is_changed_cache) def clean_unused(self): self._clean_subcaches() @@ -588,4 +595,8 @@ class RAMPressureCache(LRUCache): self.timestamps.pop(key, None) self.children.pop(key, None) freed += ram_usage + if freed and free_active: + self.active_evictions = True + if min_entry_size == 0: + self.full_evictions = True return freed diff --git a/execution.py b/execution.py index b17ace65a..7cab4b331 100644 --- a/execution.py +++ b/execution.py @@ -13,12 +13,13 @@ import asyncio import torch -from comfy.cli_args import args +from comfy.cli_args import args, get_console_log_level import comfy.memory_management import comfy.model_management import comfy.model_patcher import comfy.model_prefetch import comfy_aimdo.model_vbar +from comfy.logging import detail from latent_preview import set_preview_method import nodes @@ -544,7 +545,7 @@ async def execute(server, dynprompt, caches, current_item, extra_data, executed, output_data, output_ui, has_subgraph, has_pending_tasks = await get_output_data(prompt_id, unique_id, obj, input_data_all, execution_block_cb=execution_block_cb, pre_execute_cb=pre_execute_cb, v3_data=v3_data) finally: if comfy.memory_management.aimdo_enabled: - if args.verbose == "DEBUG": + if get_console_log_level(args.verbose) == "DEBUG": comfy_aimdo.control.analyze() comfy.model_management.reset_cast_buffers() comfy.model_prefetch.cleanup_prefetch_queues() @@ -835,6 +836,8 @@ class PromptExecutor: if comfy.model_management.DISABLE_SMART_MEMORY: comfy.model_management.unload_all_models() finally: + if self.cache_type == CacheType.RAM_PRESSURE: + detail("RAM cache evictions: prompt=%s active=%s full=%s", prompt_id, self.caches.outputs.active_evictions, self.caches.outputs.full_evictions) comfy.memory_management.set_ram_cache_release_state(None, 0) self.prompt_model_tracker.end() self._notify_prompt_lifecycle("end", prompt_id) diff --git a/main.py b/main.py index 1f16a7f89..c33e75f62 100644 --- a/main.py +++ b/main.py @@ -2,6 +2,7 @@ import comfy.options comfy.options.enable_args_parsing() from comfy.cli_args import args +from comfy.cli_args import get_console_log_level, get_file_log_outputs if args.list_feature_flags: import json @@ -17,7 +18,9 @@ import folder_paths import time from comfy.cli_args import enables_dynamic_vram from app.logger import setup_logger -setup_logger(log_level=args.verbose, use_stdout=args.log_stdout) +console_log_level = get_console_log_level(args.verbose) +file_log_outputs = [('DETAIL', 'comfyui_detail.log'), *get_file_log_outputs(args.verbose)] +setup_logger(log_level=console_log_level, file_outputs=file_log_outputs, use_stdout=args.log_stdout) from app.assets.seeder import asset_seeder from app.assets.services import register_output_files @@ -251,13 +254,18 @@ if args.enable_dynamic_vram or (enables_dynamic_vram() and comfy.model_managemen aimdo_initialized = comfy_aimdo.control.init_devices(d.index for d in comfy.model_management.get_all_torch_devices()) if aimdo_initialized: - if args.verbose == 'DEBUG': + if console_log_level == 'DEBUG': comfy_aimdo.control.set_log_debug() - elif args.verbose == 'CRITICAL': + elif console_log_level == 'DETAIL': + try: + comfy_aimdo.control.set_log_detail() + except AttributeError: + comfy_aimdo.control.set_log_info() + elif console_log_level == 'CRITICAL': comfy_aimdo.control.set_log_critical() - elif args.verbose == 'ERROR': + elif console_log_level == 'ERROR': comfy_aimdo.control.set_log_error() - elif args.verbose == 'WARNING': + elif console_log_level == 'WARNING': comfy_aimdo.control.set_log_warning() else: #INFO comfy_aimdo.control.set_log_info()