Add configurable DETAIL logging side channel (#15064)
This commit is contained in:
rattus
GitHub
parent
c01175530e
commit
fbe6d3ca8f
|
|
@ -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 = []
|
||||
|
||||
|
|
|
|||
|
|
@ -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).")
|
||||
|
||||
|
||||
|
|
|
|||
|
|
@ -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)
|
||||
|
|
@ -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
|
||||
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
||||
|
|
|
|||
|
|
@ -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:
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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)
|
||||
|
|
|
|||
18
main.py
18
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()
|
||||
|
|
|
|||
Loading…
Reference in New Issue