add trace logging

CHANGELOG.md

@@ -1,6 +1,6 @@
 # Change Log for SD.Next
 
-## Update for 2023-12-19
+## Update for 2023-12-20
 
 *Note*: based on `diffusers==0.25.0.dev0`
 
@@ -38,7 +38,7 @@
       <https://github.com/vladmandic/automatic/blob/dev/scripts/example.py>  
   - **Schedulers**  
     - add timesteps range, changing it will make scheduler to be over-complete or under-complete  
-    - add rescale betas with zero SNR option (applicable to Euler and DDIM, allows for higher dynamic range)  
+    - add rescale betas with zero SNR option (applicable to Euler, Euler a and DDIM, allows for higher dynamic range)  
 - **General**  
   - **Process** create videos from batch or folder processing  
       supports *GIF*, *PNG* and *MP4* with full interpolation, scene change detection, etc.  
@@ -73,6 +73,12 @@
   - **HDR controls**  
     - batch-aware for enhancement of multiple images or video frames  
     - available in image tab  
+  - **Logging**
+    - additional *TRACE* logging enabled via specific env variables  
+      see <https://github.com/vladmandic/automatic/wiki/Debug> for details  
+    - improved profiling  
+      use with `--debug --profile`  
+    - log output file sizes  
   - **Other**  
     - **API** several minor but breaking changes to API behavior to better align response fields, thanks @Trojaner
     - **Inpaint** add option `apply_overlay` to control if inpaint result should be applied as overlay or as-is  
@@ -86,7 +92,6 @@
     - add hdr settings to metadata  
     - improve handling of long filenames and filenames during batch processing  
     - do not set preview samples when using via api  
-    - log output file sizes  
     - avoid unnecessary resizes in img2img and inpaint  
     - updated `cli/simple-txt2img.py` and `cli/simple-img2img.py` scripts  
     - save `params.txt` regardless of image save status  

installer.py

@@ -67,6 +67,7 @@ def setup_logging():
         def get(self):
             return self.buffer
 
+    from functools import partial, partialmethod
     from logging.handlers import RotatingFileHandler
     from rich.theme import Theme
     from rich.logging import RichHandler
@@ -78,6 +79,11 @@ def setup_logging():
         global log_file # pylint: disable=global-statement
         log_file = args.log
 
+    logging.TRACE = 25
+    logging.addLevelName(logging.TRACE, 'TRACE')
+    logging.Logger.trace = partialmethod(logging.Logger.log, logging.TRACE)
+    logging.trace = partial(logging.log, logging.TRACE)
+
     level = logging.DEBUG if args.debug else logging.INFO
     log.setLevel(logging.DEBUG) # log to file is always at level debug for facility `sd`
     console = Console(log_time=True, log_time_format='%H:%M:%S-%f', theme=Theme({

modules/errors.py

@@ -4,9 +4,10 @@ from rich.console import Console
 from rich.theme import Theme
 from rich.pretty import install as pretty_install
 from rich.traceback import install as traceback_install
-from installer import log as installer_log
+from installer import log as installer_log, setup_logging
 
 
+setup_logging()
 log = installer_log
 console = Console(log_time=True, log_time_format='%H:%M:%S-%f', theme=Theme({
     "traceback.border": "black",

modules/generation_parameters_copypaste.py

@@ -16,7 +16,7 @@ re_hypernet_hash = re.compile("\(([0-9a-f]+)\)$") # pylint: disable=anomalous-ba
 type_of_gr_update = type(gr.update())
 paste_fields = {}
 registered_param_bindings = []
-debug = shared.log.info if os.environ.get('SD_PASTE_DEBUG', None) is not None else lambda *args, **kwargs: None
+debug = shared.log.trace if os.environ.get('SD_PASTE_DEBUG', None) is not None else lambda *args, **kwargs: None
 
 
 class ParamBinding:

modules/images.py

@@ -19,7 +19,7 @@ from PIL import Image, ImageFont, ImageDraw, PngImagePlugin, ExifTags
 from modules import sd_samplers, shared, script_callbacks, errors, paths
 
 
-debug = errors.log.info if os.environ.get('SD_PATH_DEBUG', None) is not None else lambda *args, **kwargs: None
+debug = errors.log.trace if os.environ.get('SD_PATH_DEBUG', None) is not None else lambda *args, **kwargs: None
 try:
     from pi_heif import register_heif_opener
     register_heif_opener()

modules/img2img.py

@@ -9,7 +9,7 @@ from modules.ui import plaintext_to_html
 from modules.memstats import memory_stats
 
 
-debug = shared.log.debug if os.environ.get('SD_PROCESS_DEBUG', None) is not None else lambda *args, **kwargs: None
+debug = shared.log.trace if os.environ.get('SD_PROCESS_DEBUG', None) is not None else lambda *args, **kwargs: None
 
 
 def process_batch(p, input_files, input_dir, output_dir, inpaint_mask_dir, args):

modules/paths.py

@@ -32,7 +32,7 @@ sd_configs_path = os.path.join(script_path, "configs")
 sd_default_config = os.path.join(sd_configs_path, "v1-inference.yaml")
 sd_model_file = cli.ckpt or os.path.join(script_path, 'model.ckpt') # not used
 default_sd_model_file = sd_model_file # not used
-debug = log.info if os.environ.get('SD_PATH_DEBUG', None) is not None else lambda *args, **kwargs: None
+debug = log.trace if os.environ.get('SD_PATH_DEBUG', None) is not None else lambda *args, **kwargs: None
 paths = {}
 
 if os.environ.get('SD_PATH_DEBUG', None) is not None:

modules/processing.py

@@ -44,7 +44,7 @@ from modules.sd_hijack_hypertile import context_hypertile_vae, context_hypertile
 
 opt_C = 4
 opt_f = 8
-debug = shared.log.debug if os.environ.get('SD_PROCESS_DEBUG', None) is not None else lambda *args, **kwargs: None
+debug = shared.log.trace if os.environ.get('SD_PROCESS_DEBUG', None) is not None else lambda *args, **kwargs: None
 
 
 def setup_color_correction(image):

modules/processing_correction.py

@@ -8,7 +8,7 @@ import torch
 from modules import shared
 
 
-debug = shared.log.info if os.environ.get('SD_HDR_DEBUG', None) is not None else lambda *args, **kwargs: None
+debug = shared.log.trace if os.environ.get('SD_HDR_DEBUG', None) is not None else lambda *args, **kwargs: None
 
 
 def soft_clamp_tensor(tensor, threshold=0.8, boundary=4):

modules/prompt_parser.py

@@ -70,7 +70,7 @@ re_attention_v1 = re.compile(r"""
 
 
 debug_output = os.environ.get('SD_PROMPT_DEBUG', None)
-debug = log.info if debug_output is not None else lambda *args, **kwargs: None
+debug = log.trace if debug_output is not None else lambda *args, **kwargs: None
 
 
 def get_learned_conditioning_prompt_schedules(prompts, steps):

modules/prompt_parser_diffusers.py

@@ -6,7 +6,7 @@ from compel import ReturnedEmbeddingsType
 from compel.embeddings_provider import BaseTextualInversionManager, EmbeddingsProvider
 from modules import shared, prompt_parser, devices
 
-debug = shared.log.info if os.environ.get('SD_PROMPT_DEBUG', None) is not None else lambda *args, **kwargs: None
+debug = shared.log.trace if os.environ.get('SD_PROMPT_DEBUG', None) is not None else lambda *args, **kwargs: None
 
 CLIP_SKIP_MAPPING = {
     None: ReturnedEmbeddingsType.LAST_HIDDEN_STATES_NORMALIZED,
@@ -58,7 +58,7 @@ class DiffusersTextualInversionManager(BaseTextualInversionManager):
         return self.pipe.tokenizer.encode(prompt, add_special_tokens=False)
 
 
-def get_prompt_schedule(p, prompt, steps):
+def get_prompt_schedule(p, prompt, steps): # pylint: disable=unused-argument
     t0 = time.time()
     temp = []
     schedule = prompt_parser.get_learned_conditioning_prompt_schedules([prompt], steps)[0]
@@ -72,7 +72,7 @@ def get_prompt_schedule(p, prompt, steps):
     return temp, len(schedule) > 1
 
 
-def encode_prompts(pipe, p, prompts: list, negative_prompts: list, steps: int, step: int = 1, clip_skip: typing.Optional[int] = None):
+def encode_prompts(pipe, p, prompts: list, negative_prompts: list, steps: int, step: int = 1, clip_skip: typing.Optional[int] = None): # pylint: disable=unused-argument
     if 'StableDiffusion' not in pipe.__class__.__name__ and 'DemoFusion':
         shared.log.warning(f"Prompt parser not supported: {pipe.__class__.__name__}")
         return None, None, None, None

modules/sd_samplers.py

@@ -1,7 +1,9 @@
+import os
 from modules import sd_samplers_compvis, sd_samplers_kdiffusion, sd_samplers_diffusers, shared
 from modules.sd_samplers_common import samples_to_image_grid, sample_to_image # pylint: disable=unused-import
 
 
+debug = shared.log.trace if os.environ.get('SD_SAMPLER_DEBUG', None) is not None else lambda *args, **kwargs: None
 all_samplers = []
 all_samplers = []
 all_samplers_map = {}
@@ -9,6 +11,7 @@ samplers = all_samplers
 samplers_for_img2img = all_samplers
 samplers_map = {}
 
+
 def list_samplers(backend_name = shared.backend):
     global all_samplers # pylint: disable=global-statement
     global all_samplers_map # pylint: disable=global-statement

modules/sd_samplers_diffusers.py

@@ -1,6 +1,11 @@
+import os
+import inspect
 from modules import shared
 from modules import sd_samplers_common
 
+
+debug = shared.log.trace if os.environ.get('SD_SAMPLER_DEBUG', None) is not None else lambda *args, **kwargs: None
+
 try:
     from diffusers import (
         DDIMScheduler,
@@ -33,7 +38,7 @@ config = {
     'DPM++ 1S': { 'solver_order': 2, 'thresholding': False, 'sample_max_value': 1.0, 'algorithm_type': "dpmsolver++", 'solver_type': "midpoint", 'lower_order_final': True, 'use_karras_sigmas': False },
     'DPM++ 2M': { 'thresholding': False, 'sample_max_value': 1.0, 'algorithm_type': "dpmsolver++", 'solver_type': "midpoint", 'lower_order_final': True, 'use_karras_sigmas': False },
     'DPM SDE': { 'use_karras_sigmas': False },
-    'Euler a': { },
+    'Euler a': { 'rescale_betas_zero_snr': False },
     'Euler': { 'interpolation_type': "linear", 'use_karras_sigmas': False, 'rescale_betas_zero_snr': False },
     'Heun': { 'use_karras_sigmas': False },
     'KDPM2': { 'steps_offset': 0 },
@@ -116,5 +121,13 @@ class DiffusionSampler:
             self.config['algorithm_type'] = shared.opts.schedulers_dpm_solver
         if name == 'DEIS':
             self.config['algorithm_type'] = 'deis'
+        # validate all config params
+        signature = inspect.signature(constructor, follow_wrapped=True)
+        possible = signature.parameters.keys()
+        debug(f'Sampler: sampler="{name}" config={self.config} signature={possible}')
+        for key in self.config.copy().keys():
+            if key not in possible:
+                shared.log.warning(f'Sampler: sampler="{name}" config={self.config} invalid={key}')
+                del self.config[key]
         self.sampler = constructor(**self.config)
         self.sampler.name = name

modules/txt2img.py

@@ -5,7 +5,7 @@ from modules.generation_parameters_copypaste import create_override_settings_dic
 from modules.ui import plaintext_to_html
 
 
-debug = shared.log.debug if os.environ.get('SD_PROCESS_DEBUG', None) is not None else lambda *args, **kwargs: None
+debug = shared.log.trace if os.environ.get('SD_PROCESS_DEBUG', None) is not None else lambda *args, **kwargs: None
 
 
 def txt2img(id_task,

modules/ui.py

@@ -421,6 +421,7 @@ def create_sampler_and_steps_selection(choices, tabname):
         opts.data['schedulers_use_karras'] = 'karras' in sampler_options
         opts.data['schedulers_use_thresholding'] = 'dynamic thresholding' in sampler_options
         opts.data['schedulers_use_loworder'] = 'low order' in sampler_options
+        opts.data['schedulers_rescale_betas'] = 'rescale beta' in sampler_options
         opts.save(modules.shared.config_filename, silent=True)
 
     with FormRow(elem_classes=['flex-break']):
@@ -440,11 +441,12 @@ def create_sampler_and_steps_selection(choices, tabname):
         sampler_algo.change(fn=set_sampler_original_options, inputs=[sampler_options, sampler_algo], outputs=[])
     else:
         with FormRow(elem_classes=['flex-break']):
-            choices = ['karras', 'dynamic thresholding', 'low order']
+            choices = ['karras', 'dynamic threshold', 'low order', 'rescale beta']
             values = []
             values += ['karras'] if opts.data.get('schedulers_use_karras', True) else []
-            values += ['dynamic thresholding'] if opts.data.get('schedulers_use_thresholding', False) else []
+            values += ['dynamic threshold'] if opts.data.get('schedulers_use_thresholding', False) else []
             values += ['low order'] if opts.data.get('schedulers_use_loworder', True) else []
+            values += ['rescale beta'] if opts.data.get('schedulers_rescale_betas', False) else []
             sampler_options = gr.CheckboxGroup(label='Sampler options', choices=choices, value=values, type='value')
         sampler_options.change(fn=set_sampler_diffuser_options, inputs=[sampler_options], outputs=[])
     return steps, sampler_index

modules/ui_extra_networks.py

@@ -24,7 +24,7 @@ allowed_dirs = []
 dir_cache = {} # key=path, value=(mtime, listdir(path))
 refresh_time = 0
 extra_pages = shared.extra_networks
-debug = shared.log.info if os.environ.get('SD_EN_DEBUG', None) is not None else lambda *args, **kwargs: None
+debug = shared.log.trace if os.environ.get('SD_EN_DEBUG', None) is not None else lambda *args, **kwargs: None
 card_full = '''
     <div class='card' onclick={card_click} title='{name}' data-tab='{tabname}' data-page='{page}' data-name='{name}' data-filename='{filename}' data-tags='{tags}' data-mtime='{mtime}' data-size='{size}' data-search='{search}'>
         <div class='overlay'>

modules/ui_tempdir.py

@@ -8,7 +8,7 @@ from modules import shared, errors, paths
 
 
 Savedfile = namedtuple("Savedfile", ["name"])
-debug = errors.log.info if os.environ.get('SD_PATH_DEBUG', None) is not None else lambda *args, **kwargs: None
+debug = errors.log.trace if os.environ.get('SD_PATH_DEBUG', None) is not None else lambda *args, **kwargs: None
 
 
 def register_tmp_file(gradio, filename):

webui.py

@@ -316,7 +316,7 @@ def webui(restart=False):
         for k, v in modules.script_callbacks.callback_map.items():
             shared.log.debug(f'Registered callbacks: {k}={len(v)} {[c.script for c in v]}')
     log.info(f"Startup time: {timer.startup.summary()}")
-    debug = log.info if os.environ.get('SD_SCRIPT_DEBUG', None) is not None else lambda *args, **kwargs: None
+    debug = log.trace if os.environ.get('SD_SCRIPT_DEBUG', None) is not None else lambda *args, **kwargs: None
     debug('Loaded scripts:')
     for m in modules.scripts.scripts_data:
         debug(f'  {m}')