diff --git a/CHANGELOG.md b/CHANGELOG.md index 1344f5bb5..fbeb78785 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,6 +3,9 @@ ## Update for 06/03/2023 - new vae decode method to help with larger batch sizes, thanks @bigdog +- profiling of scripts/extensions callbacks +- additional exception handling so bad exception does not crash main app +- additional background removal models ## Update for 06/02/2023 diff --git a/extensions-builtin/a1111-sd-webui-lycoris b/extensions-builtin/a1111-sd-webui-lycoris index dcb9536dc..21e9ea0f5 160000 --- a/extensions-builtin/a1111-sd-webui-lycoris +++ b/extensions-builtin/a1111-sd-webui-lycoris @@ -1 +1 @@ -Subproject commit dcb9536dccba7766c6b66cbf2b27969f4f2fc023 +Subproject commit 21e9ea0f58dfdbee12b08389fd2cd1aa545e058d diff --git a/extensions-builtin/stable-diffusion-webui-rembg b/extensions-builtin/stable-diffusion-webui-rembg index 657ae9f54..3d9eedbbf 160000 --- a/extensions-builtin/stable-diffusion-webui-rembg +++ b/extensions-builtin/stable-diffusion-webui-rembg @@ -1 +1 @@ -Subproject commit 657ae9f5486019a94dbe11d3560b28cccf35a0fd +Subproject commit 3d9eedbbf0d585207f97d5b21e42f32c0042df70 diff --git a/installer.py b/installer.py index 75ecf2958..67245cf0a 100644 --- a/installer.py +++ b/installer.py @@ -50,6 +50,7 @@ args = Dot({ }) git_commit = "unknown" + # setup console and file logging def setup_logging(clean=False): try: @@ -714,7 +715,10 @@ def extensions_preload(force = False): from modules.paths_internal import extensions_builtin_dir, extensions_dir extension_folders = [extensions_builtin_dir] if args.safe else [extensions_builtin_dir, extensions_dir] for ext_dir in extension_folders: + t0 = time.time() preload_extensions(ext_dir, parser) + t1 = time.time() + log.debug(f'Extension preload: {round(t1 - t0, 1)}s {ext_dir}') except: log.error('Error running extension preloading') if args.profile: diff --git a/modules/errors.py b/modules/errors.py index 067cccdb7..8b4f1b6b4 100644 --- a/modules/errors.py +++ b/modules/errors.py @@ -4,8 +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 +from installer import log as installer_log + +log = installer_log console = Console(log_time=True, log_time_format='%H:%M:%S-%f', theme=Theme({ "traceback.border": "black", "traceback.border.syntax_error": "black", diff --git a/modules/lycoris b/modules/lycoris index dfe51b093..57d71913b 160000 --- a/modules/lycoris +++ b/modules/lycoris @@ -1 +1 @@ -Subproject commit dfe51b093cf115b61fa82fccda0a932e5fcdca78 +Subproject commit 57d71913bf47a48dc7dd519b89dd30e09c937b83 diff --git a/modules/processing.py b/modules/processing.py index 8e4ad13d2..2fa263887 100644 --- a/modules/processing.py +++ b/modules/processing.py @@ -924,34 +924,26 @@ class StableDiffusionProcessingTxt2Img(StableDiffusionProcessing): decoded_samples = 2. * decoded_samples - 1. if shared.opts.sd_vae_sliced_encode and len(decoded_samples) > 1: samples = torch.stack([ - self.sd_model.get_first_stage_encoding( - self.sd_model.encode_first_stage(torch.unsqueeze(decoded_sample, 0)) - )[0] + self.sd_model.get_first_stage_encoding(self.sd_model.encode_first_stage(torch.unsqueeze(decoded_sample, 0)))[0] for decoded_sample in decoded_samples ]) else: - samples = self.sd_model.get_first_stage_encoding( - self.sd_model.encode_first_stage(decoded_samples) - ) + samples = self.sd_model.get_first_stage_encoding(self.sd_model.encode_first_stage(decoded_samples)) image_conditioning = self.img2img_image_conditioning(decoded_samples, samples) shared.state.nextjob() img2img_sampler_name = self.sampler_name force_latent_upscaler = shared.opts.data.get('xyz_fallback_sampler') if force_latent_upscaler != 'None' and force_latent_upscaler != 'PLMS': img2img_sampler_name = force_latent_upscaler - elif shared.opts.fallback_sampler != 'PLMS': - img2img_sampler_name = shared.opts.fallback_sampler - else: - img2img_sampler_name = 'UniPC' + if img2img_sampler_name == 'PLMS': + img2img_sampler_name = shared.opts.fallback_sampler if shared.opts.fallback_sampler != 'PLMS' else 'UniPC' self.sampler = sd_samplers.create_sampler(img2img_sampler_name, self.sd_model) samples = samples[:, :, self.truncate_y//2:samples.shape[2]-(self.truncate_y+1)//2, self.truncate_x//2:samples.shape[3]-(self.truncate_x+1)//2] noise = create_random_tensors(samples.shape[1:], seeds=seeds, subseeds=subseeds, subseed_strength=subseed_strength, p=self) - # GC now before running the next img2img to prevent running out of memory x = None - devices.torch_gc() + devices.torch_gc() # GC now before running the next img2img to prevent running out of memory # apply token merging optimizations from tomesd for high-res pass - # check if hr_only so we are not redundantly patching if (cmd_opts.token_merging or opts.token_merging) and (opts.token_merging_hr_only or opts.token_merging_ratio_hr != opts.token_merging_ratio): # case where user wants to use separate merge ratios if not opts.token_merging_hr_only: diff --git a/modules/script_callbacks.py b/modules/script_callbacks.py index 10141281f..4eea6d9fa 100644 --- a/modules/script_callbacks.py +++ b/modules/script_callbacks.py @@ -1,3 +1,4 @@ +import time import inspect from collections import namedtuple from typing import Optional, Dict, Any @@ -114,6 +115,13 @@ callback_map = dict( ) +def timer(t0: float, script, callback: str): + t1 = time.time() + s = round(t1 - t0, 2) + if s > 0.1: + errors.log.debug(f'Script: {s}s {callback} {script}') + + def clear_callbacks(): for callback_list in callback_map.values(): callback_list.clear() @@ -122,7 +130,9 @@ def clear_callbacks(): def app_started_callback(demo: Optional[Blocks], app: FastAPI): for c in callback_map['callbacks_app_started']: try: + t0 = time.time() c.callback(demo, app) + timer(t0, c.script, 'app_started') except Exception as e: report_exception(e, c, 'app_started_callback') @@ -130,7 +140,9 @@ def app_started_callback(demo: Optional[Blocks], app: FastAPI): def app_reload_callback(): for c in callback_map['callbacks_on_reload']: try: + t0 = time.time() c.callback() + timer(t0, c.script, 'on_reload') except Exception as e: report_exception(e, c, 'callbacks_on_reload') @@ -138,27 +150,31 @@ def app_reload_callback(): def model_loaded_callback(sd_model): for c in callback_map['callbacks_model_loaded']: try: + t0 = time.time() c.callback(sd_model) + timer(t0, c.script, 'model_loaded') except Exception as e: report_exception(e, c, 'model_loaded_callback') def ui_tabs_callback(): res = [] - for c in callback_map['callbacks_ui_tabs']: try: + t0 = time.time() res += c.callback() or [] + timer(t0, c.script, 'ui_tabs') except Exception as e: report_exception(e, c, 'ui_tabs_callback') - return res def ui_train_tabs_callback(params: UiTrainTabParams): for c in callback_map['callbacks_ui_train_tabs']: try: + t0 = time.time() c.callback(params) + timer(t0, c.script, 'ui_train_tabs') except Exception as e: report_exception(e, c, 'callbacks_ui_train_tabs') @@ -166,7 +182,9 @@ def ui_train_tabs_callback(params: UiTrainTabParams): def ui_settings_callback(): for c in callback_map['callbacks_ui_settings']: try: + t0 = time.time() c.callback() + timer(t0, c.script, 'ui_settings') except Exception as e: report_exception(e, c, 'ui_settings_callback') @@ -174,7 +192,9 @@ def ui_settings_callback(): def before_image_saved_callback(params: ImageSaveParams): for c in callback_map['callbacks_before_image_saved']: try: + t0 = time.time() c.callback(params) + timer(t0, c.script, 'before_image_saved') except Exception as e: report_exception(e, c, 'before_image_saved_callback') @@ -182,7 +202,9 @@ def before_image_saved_callback(params: ImageSaveParams): def image_saved_callback(params: ImageSaveParams): for c in callback_map['callbacks_image_saved']: try: + t0 = time.time() c.callback(params) + timer(t0, c.script, 'image_saved') except Exception as e: report_exception(e, c, 'image_saved_callback') @@ -190,7 +212,9 @@ def image_saved_callback(params: ImageSaveParams): def cfg_denoiser_callback(params: CFGDenoiserParams): for c in callback_map['callbacks_cfg_denoiser']: try: + t0 = time.time() c.callback(params) + timer(t0, c.script, 'cfg_denoiser') except Exception as e: report_exception(e, c, 'cfg_denoiser_callback') @@ -198,7 +222,9 @@ def cfg_denoiser_callback(params: CFGDenoiserParams): def cfg_denoised_callback(params: CFGDenoisedParams): for c in callback_map['callbacks_cfg_denoised']: try: + t0 = time.time() c.callback(params) + timer(t0, c.script, 'cfg_denoised') except Exception as e: report_exception(e, c, 'cfg_denoised_callback') @@ -206,7 +232,9 @@ def cfg_denoised_callback(params: CFGDenoisedParams): def cfg_after_cfg_callback(params: AfterCFGCallbackParams): for c in callback_map['callbacks_cfg_after_cfg']: try: + t0 = time.time() c.callback(params) + timer(t0, c.script, 'cfg_after_cfg') except Exception as e: report_exception(e, c, 'cfg_after_cfg_callback') @@ -214,7 +242,9 @@ def cfg_after_cfg_callback(params: AfterCFGCallbackParams): def before_component_callback(component, **kwargs): for c in callback_map['callbacks_before_component']: try: + t0 = time.time() c.callback(component, **kwargs) + timer(t0, c.script, 'before_component') except Exception as e: report_exception(e, c, 'before_component_callback') @@ -222,7 +252,9 @@ def before_component_callback(component, **kwargs): def after_component_callback(component, **kwargs): for c in callback_map['callbacks_after_component']: try: + t0 = time.time() c.callback(component, **kwargs) + timer(t0, c.script, 'after_component') except Exception as e: report_exception(e, c, 'after_component_callback') @@ -230,7 +262,9 @@ def after_component_callback(component, **kwargs): def image_grid_callback(params: ImageGridLoopParams): for c in callback_map['callbacks_image_grid']: try: + t0 = time.time() c.callback(params) + timer(t0, c.script, 'image_grid') except Exception as e: report_exception(e, c, 'image_grid') @@ -238,7 +272,9 @@ def image_grid_callback(params: ImageGridLoopParams): def infotext_pasted_callback(infotext: str, params: Dict[str, Any]): for c in callback_map['callbacks_infotext_pasted']: try: + t0 = time.time() c.callback(infotext, params) + timer(t0, c.script, 'infotext_pasted') except Exception as e: report_exception(e, c, 'infotext_pasted') @@ -246,7 +282,9 @@ def infotext_pasted_callback(infotext: str, params: Dict[str, Any]): def script_unloaded_callback(): for c in reversed(callback_map['callbacks_script_unloaded']): try: + t0 = time.time() c.callback() + timer(t0, c.script, 'script_unloaded') except Exception as e: report_exception(e, c, 'script_unloaded') @@ -254,7 +292,9 @@ def script_unloaded_callback(): def before_ui_callback(): for c in reversed(callback_map['callbacks_before_ui']): try: + t0 = time.time() c.callback() + timer(t0, c.script, 'before_ui') except Exception as e: report_exception(e, c, 'before_ui') @@ -262,7 +302,6 @@ def before_ui_callback(): def add_callback(callbacks, fun): stack = [x for x in inspect.stack() if x.filename != __file__] filename = stack[0].filename if len(stack) > 0 else 'unknown file' - callbacks.append(ScriptCallback(filename, fun)) diff --git a/modules/scripts.py b/modules/scripts.py index ef173ed5c..c10021dbf 100644 --- a/modules/scripts.py +++ b/modules/scripts.py @@ -1,6 +1,7 @@ import os import re import sys +import time from collections import namedtuple import gradio as gr from modules import paths, script_callbacks, extensions, script_loading, scripts_postprocessing, errors @@ -8,6 +9,8 @@ from installer import log AlwaysVisible = object() +time_component = {} +time_setup = {} class PostprocessImageArgs: @@ -313,22 +316,28 @@ class ScriptRunner: inputs_alwayson += [script.alwayson for _ in controls] script.args_to = len(inputs) + s = [] with gr.Group(elem_id='scripts_alwayson_img2img' if self.is_img2img else 'scripts_alwayson_txt2img'): for script in self.alwayson_scripts: + t0 = time.time() elem_id = f'script_{"txt2img" if script.is_txt2img else "img2img"}_{script.title().lower().replace(" ", "_")}' with gr.Group(elem_id=elem_id) as group: create_script_ui(script, inputs, inputs_alwayson) script.group = group + time_setup[script.title()] = time_setup.get(script.title(), 0) + (time.time()-t0) dropdown = gr.Dropdown(label="Script", elem_id="script_list", choices=["None"] + self.titles, value="None", type="index") inputs[0] = dropdown + s = [] for script in self.selectable_scripts: with gr.Group(visible=False) as group: + t0 = time.time() create_script_ui(script, inputs, inputs_alwayson) + time_setup[script.title()] = time_setup.get(script.title(), 0) + (time.time()-t0) script.group = group def select_script(script_index): - selected_script = self.selectable_scripts[script_index - 1] if script_index>0 else None + selected_script = self.selectable_scripts[script_index - 1] if script_index > 0 else None return [gr.update(visible=selected_script == s) for s in self.selectable_scripts] def init_field(title): @@ -363,82 +372,105 @@ class ScriptRunner: if script is None: return None parsed = p.per_script_args.get(script.title(), args[script.args_from:script.args_to]) - log.debug(f'Script run: {script.title()}') + t0 = time.time() processed = script.run(p, *parsed) + log.debug(f'Script run: {script.title()}:{round(time.time()-t0, 2)}s') return processed def process(self, p, **kwargs): - log.debug(f'Script process: {[s.title() for s in self.alwayson_scripts]}') + s = [] for script in self.alwayson_scripts: try: - # log.debug(f'Script process start: {script.title()}') + t0 = time.time() args = p.per_script_args.get(script.title(), p.script_args[script.args_from:script.args_to]) script.process(p, *args, **kwargs) - # log.debug(f'Script process end : {script.title()}') + s.append(f'{script.title()}:{round(time.time()-t0, 2)}s') except Exception as e: errors.display(e, f'Running script process: {script.filename}') + log.debug(f'Script process: {s}') def before_process_batch(self, p, **kwargs): - log.debug(f'Script before-process-batch: {[s.title() for s in self.alwayson_scripts]}') + s = [] for script in self.alwayson_scripts: try: + t0 = time.time() args = p.per_script_args.get(script.title(), p.script_args[script.args_from:script.args_to]) script.before_process_batch(p, *args, **kwargs) + s.append(f'{script.title()}:{round(time.time()-t0, 2)}s') except Exception as e: errors.display(e, f'Running script before process batch: {script.filename}') + log.debug(f'Script before-process-batch: {s}') def process_batch(self, p, **kwargs): - log.debug(f'Script process-batch: {[s.title() for s in self.alwayson_scripts]}') + s = [] for script in self.alwayson_scripts: try: + t0 = time.time() args = p.per_script_args.get(script.title(), p.script_args[script.args_from:script.args_to]) script.process_batch(p, *args, **kwargs) + s.append(f'{script.title()}:{round(time.time()-t0, 2)}s') except Exception as e: errors.display(e, f'Running script process batch: {script.filename}') + log.debug(f'Script process-batch: {s}') def postprocess(self, p, processed): - log.debug(f'Script postprocess: {[s.title() for s in self.alwayson_scripts]}') + s = [] for script in self.alwayson_scripts: try: + t0 = time.time() args = p.per_script_args.get(script.title(), p.script_args[script.args_from:script.args_to]) script.postprocess(p, processed, *args) + s.append(f'{script.title()}:{round(time.time()-t0, 2)}s') except Exception as e: errors.display(e, f'Running script postprocess: {script.filename}') + log.debug(f'Script postprocess: {s}') def postprocess_batch(self, p, images, **kwargs): - log.debug(f'Script postprocess-batch: {[s.title() for s in self.alwayson_scripts]}') + s = [] for script in self.alwayson_scripts: try: + t0 = time.time() args = p.per_script_args.get(script.title(), p.script_args[script.args_from:script.args_to]) script.postprocess_batch(p, *args, images=images, **kwargs) + s.append(f'{script.title()}:{round(time.time()-t0, 2)}s') except Exception as e: errors.display(e, f'Running script before postprocess batch: {script.filename}') + log.debug(f'Script postprocess-batch: {s}') def postprocess_image(self, p, pp: PostprocessImageArgs): - log.debug(f'Script postprocess-image: {[s.title() for s in self.alwayson_scripts]}') + s = [] for script in self.alwayson_scripts: try: + t0 = time.time() args = p.per_script_args.get(script.title(), p.script_args[script.args_from:script.args_to]) script.postprocess_image(p, pp, *args) + s.append(f'{script.title()}:{round(time.time()-t0, 2)}s') except Exception as e: errors.display(e, f'Running script postprocess image: {script.filename}') + log.debug(f'Script postprocess-image: {s}') def before_component(self, component, **kwargs): for script in self.scripts: try: + t0 = time.time() script.before_component(component, **kwargs) + time_component[script.title()] = time_component.get(script.title(), 0) + (time.time()-t0) except Exception as e: errors.display(e, f'Running script before component: {script.filename}') def after_component(self, component, **kwargs): for script in self.scripts: try: + t0 = time.time() script.after_component(component, **kwargs) + time_component[script.title()] = time_component.get(script.title(), 0) + (time.time()-t0) except Exception as e: errors.display(e, f'Running script after component: {script.filename}') def reload_sources(self, cache): + s = [] for si, script in list(enumerate(self.scripts)): + t0 = time.time() args_from = script.args_from args_to = script.args_to filename = script.filename @@ -452,6 +484,9 @@ class ScriptRunner: self.scripts[si].filename = filename self.scripts[si].args_from = args_from self.scripts[si].args_to = args_to + s.append(f'{script.title()}:{round(time.time()-t0, 2)}s') + log.debug(f'Script reload-sources: {s}') + scripts_txt2img = ScriptRunner() scripts_img2img = ScriptRunner() diff --git a/webui.py b/webui.py index edb0ba8d7..13d7faa9f 100644 --- a/webui.py +++ b/webui.py @@ -9,6 +9,7 @@ from threading import Thread from modules import timer, errors startup_timer = timer.Timer() +local_url = None import torch # pylint: disable=C0411 try: @@ -221,6 +222,7 @@ def start_ui(): gradio_auth_creds += [x.strip() for x in line.split(',') if x.strip()] import installer + global local_url app, local_url, share_url = shared.demo.launch( share=cmd_opts.share, server_name=server_name, @@ -230,7 +232,7 @@ def start_ui(): ssl_verify=not cmd_opts.tls_selfsign, debug=False, auth=[tuple(cred.split(':')) for cred in gradio_auth_creds] if gradio_auth_creds else None, - inbrowser=cmd_opts.autolaunch, + # inbrowser=cmd_opts.autolaunch, prevent_thread_lock=True, max_threads=64, show_api=True, @@ -260,7 +262,6 @@ def start_ui(): _mounted_app = gradio.mount_gradio_app(app, shared.demo, path=f"/{cmd_opts.subpath}") shared.log.info(f'Redirector mounted: /{cmd_opts.subpath}') - cmd_opts.autolaunch = False startup_timer.record("launch") modules.progress.setup_progress_api(app) @@ -270,12 +271,22 @@ def start_ui(): modules.script_callbacks.app_started_callback(shared.demo, app) startup_timer.record("scripts app_started_callback") + time_setup = [f'{k}:{round(v,3)}s' for (k,v) in modules.scripts.time_setup.items() if v > 0.001] + shared.log.debug(f'Scripts setup: {time_setup}s') + time_component = [f'{k}:{round(v,3)}s' for (k,v) in modules.scripts.time_component.items() if v > 0.001] + shared.log.debug(f'Scripts components: {time_component}s') + def webui(): start_common() start_ui() load_model() log.info(f"Startup time: {startup_timer.summary()}") + if cmd_opts.autolaunch and local_url is not None: + cmd_opts.autolaunch = False + shared.log.info('Launching browser') + import webbrowser + webbrowser.open(local_url, new=2, autoraise=True) return shared.demo.server