diff --git a/CHANGELOG.md b/CHANGELOG.md index 4edcf4603..640b1f300 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,6 +1,6 @@ # Change Log for SD.Next -## Update for 2025-01-07 +## Update for 2025-01-08 - [Allegro Video](https://huggingface.co/rhymes-ai/Allegro) - optimizations: full offload and quantization support @@ -25,6 +25,7 @@ - **Refactor**: - refactored progress monitoring, job updates and live preview - improved metadata save and restore + - startup tracing and optimizations - **Schedulers**: - [TDD](https://github.com/RedAIGC/Target-Driven-Distillation) new super-fast scheduler that can generate images in 4-8 steps recommended to use with [TDD LoRA](https://huggingface.co/RED-AIGC/TDD/tree/main) diff --git a/installer.py b/installer.py index f10258e8e..96259da36 100644 --- a/installer.py +++ b/installer.py @@ -8,6 +8,7 @@ import platform import subprocess import cProfile +import importlib # pylint: disable=deprecated-module class Dot(dict): # dot notation access to dictionary attributes @@ -58,6 +59,14 @@ class Dot(dict): # dot notation access to dictionary attributes # 'stable-diffusion-webui-images-browser': '27fe4a7', } + +try: + from modules.timer import init + ts = init.ts +except Exception: + ts = lambda *args, **kwargs: None # pylint: disable=unnecessary-lambda-assignment + + # setup console and file logging def setup_logging(): @@ -84,6 +93,7 @@ def emit(self, record): def get(self): return self.buffer + t_start = time.time() from functools import partial, partialmethod from logging.handlers import RotatingFileHandler from rich.theme import Theme @@ -148,6 +158,7 @@ def get(self): logging.getLogger("ControlNet").handlers = log.handlers logging.getLogger("lycoris").handlers = log.handlers # logging.getLogger("DeepSpeed").handlers = log.handlers + ts('log', t_start) def get_logfile(): @@ -201,11 +212,11 @@ def package_spec(package): # check if package is installed @lru_cache() def installed(package, friendly: str = None, reload = False, quiet = False): + t_start = time.time() ok = True try: if reload: try: - import importlib # pylint: disable=deprecated-module importlib.reload(pkg_resources) except Exception: pass @@ -237,13 +248,15 @@ def installed(package, friendly: str = None, reload = False, quiet = False): else: if not quiet: log.debug(f'Install: package="{p[0]}" install required') + ts('installed', t_start) return ok except Exception as e: log.error(f'Install: package="{pkgs}" {e}') + ts('installed', t_start) return False - def uninstall(package, quiet = False): + t_start = time.time() packages = package if isinstance(package, list) else [package] res = '' for p in packages: @@ -251,11 +264,13 @@ def uninstall(package, quiet = False): if not quiet: log.warning(f'Package: {p} uninstall') res += pip(f"uninstall {p} --yes --quiet", ignore=True, quiet=True, uv=False) + ts('uninstall', t_start) return res @lru_cache() def pip(arg: str, ignore: bool = False, quiet: bool = True, uv = True): + t_start = time.time() originalArg = arg arg = arg.replace('>=', '==') package = arg.replace("install", "").replace("--upgrade", "").replace("--no-deps", "").replace("--force", "").replace(" ", " ").strip() @@ -283,12 +298,14 @@ def pip(arg: str, ignore: bool = False, quiet: bool = True, uv = True): errors.append(f'pip: {package}') log.error(f'Install: {pipCmd}: {arg}') log.debug(f'Install: pip output {txt}') + ts('pip', t_start) return txt # install package using pip if not already installed @lru_cache() def install(package, friendly: str = None, ignore: bool = False, reinstall: bool = False, no_deps: bool = False, quiet: bool = False): + t_start = time.time() res = '' if args.reinstall or args.upgrade: global quick_allowed # pylint: disable=global-statement @@ -297,16 +314,17 @@ def install(package, friendly: str = None, ignore: bool = False, reinstall: bool deps = '' if not no_deps else '--no-deps ' res = pip(f"install{' --upgrade' if not args.uv else ''} {deps}{package}", ignore=ignore, uv=package != "uv" and not package.startswith('git+')) try: - import importlib # pylint: disable=deprecated-module importlib.reload(pkg_resources) except Exception: pass + ts('install', t_start) return res # execute git command @lru_cache() def git(arg: str, folder: str = None, ignore: bool = False, optional: bool = False): + t_start = time.time() if args.skip_git: return '' if optional: @@ -328,6 +346,7 @@ def git(arg: str, folder: str = None, ignore: bool = False, optional: bool = Fal if 'or stash them' in txt: log.error(f'Git local changes detected: check details log="{log_file}"') log.debug(f'Git output: {txt}') + ts('git', t_start) return txt @@ -335,6 +354,7 @@ def git(arg: str, folder: str = None, ignore: bool = False, optional: bool = Fal def branch(folder=None): # if args.experimental: # return None + t_start = time.time() if not os.path.exists(os.path.join(folder or os.curdir, '.git')): return None branches = [] @@ -357,11 +377,13 @@ def branch(folder=None): b = b.split('\n')[0].replace('*', '').strip() log.debug(f'Git submodule: {folder} / {b}') git(f'checkout {b}', folder, ignore=True, optional=True) + ts('branch', t_start) return b # update git repository def update(folder, keep_branch = False, rebase = True): + t_start = time.time() try: git('config rebase.Autostash true') except Exception: @@ -383,11 +405,13 @@ def update(folder, keep_branch = False, rebase = True): if commit is not None: res = git(f'checkout {commit}', folder) debug(f'Install update: folder={folder} branch={b} args={arg} commit={commit} {res}') + ts('update', t_start) return res # clone git repository def clone(url, folder, commithash=None): + t_start = time.time() if os.path.exists(folder): if commithash is None: update(folder) @@ -403,6 +427,7 @@ def clone(url, folder, commithash=None): git(f'clone "{url}" "{folder}"') if commithash is not None: git(f'-C "{folder}" checkout {commithash}') + ts('clone', t_start) def get_platform(): @@ -427,6 +452,7 @@ def get_platform(): # check python version def check_python(supported_minors=[9, 10, 11, 12], reason=None): + t_start = time.time() if args.quick: return log.info(f'Python: version={platform.python_version()} platform={platform.system()} bin="{sys.executable}" venv="{sys.prefix}"') @@ -453,10 +479,12 @@ def check_python(supported_minors=[9, 10, 11, 12], reason=None): else: git_version = git('--version', folder=None, ignore=False) log.debug(f'Git: version={git_version.replace("git version", "").strip()}') + ts('python', t_start) # check diffusers version def check_diffusers(): + t_start = time.time() if args.skip_all or args.skip_git: return sha = '03bcf5aefef13a064c34b605e489c0730052cca8' # diffusers commit hash @@ -472,42 +500,30 @@ def check_diffusers(): pip(f'install --upgrade git+https://github.com/huggingface/diffusers@{sha}', ignore=False, quiet=True, uv=False) global diffusers_commit # pylint: disable=global-statement diffusers_commit = sha + ts('diffusers', t_start) # check onnx version def check_onnx(): + t_start = time.time() if args.skip_all or args.skip_requirements: return if not installed('onnx', quiet=True): install('onnx', 'onnx', ignore=True) if not installed('onnxruntime', quiet=True) and not (installed('onnxruntime-gpu', quiet=True) or installed('onnxruntime-openvino', quiet=True) or installed('onnxruntime-training', quiet=True)): # allow either install('onnxruntime', 'onnxruntime', ignore=True) - - -def check_torchao(): - """ - if args.skip_all or args.skip_requirements: - return - if installed('torchao', quiet=True): - ver = package_version('torchao') - if ver != '0.5.0': - log.debug(f'Uninstall: torchao=={ver}') - pip('uninstall --yes torchao', ignore=True, quiet=True, uv=False) - for m in [m for m in sys.modules if m.startswith('torchao')]: - del sys.modules[m] - """ - return + ts('onnx', t_start) def install_cuda(): + t_start = time.time() log.info('CUDA: nVidia toolkit detected') - if not (args.skip_all or args.skip_requirements): - install('onnxruntime-gpu', 'onnxruntime-gpu', ignore=True, quiet=True) - # return os.environ.get('TORCH_COMMAND', 'torch torchvision --index-url https://download.pytorch.org/whl/cu124') + ts('cuda', t_start) return os.environ.get('TORCH_COMMAND', 'torch==2.5.1+cu124 torchvision==0.20.1+cu124 --index-url https://download.pytorch.org/whl/cu124') def install_rocm_zluda(): + t_start = time.time() if args.skip_all or args.skip_requirements: return None from modules import rocm @@ -628,10 +644,12 @@ def install_rocm_zluda(): else: log.warning(f'ROCm: device={device.name} could not auto-detect HSA version') + ts('amd', t_start) return torch_command def install_ipex(torch_command): + t_start = time.time() check_python(supported_minors=[10,11], reason='IPEX backend requires Python 3.10 or 3.11') args.use_ipex = True # pylint: disable=attribute-defined-outside-init log.info('IPEX: Intel OneAPI toolkit detected') @@ -650,10 +668,12 @@ def install_ipex(torch_command): install(os.environ.get('OPENVINO_PACKAGE', 'openvino==2024.5.0'), 'openvino', ignore=True) install('nncf==2.7.0', ignore=True, no_deps=True) # requires older pandas install(os.environ.get('ONNXRUNTIME_PACKAGE', 'onnxruntime-openvino'), 'onnxruntime-openvino', ignore=True) + ts('ipex', t_start) return torch_command def install_openvino(torch_command): + t_start = time.time() check_python(supported_minors=[9, 10, 11, 12], reason='OpenVINO backend requires Python 3.9, 3.10 or 3.11') log.info('OpenVINO: selected') if sys.platform == 'darwin': @@ -668,10 +688,12 @@ def install_openvino(torch_command): os.environ.setdefault('NEOReadDebugKeys', '1') if os.environ.get("ClDeviceGlobalMemSizeAvailablePercent", None) is None: os.environ.setdefault('ClDeviceGlobalMemSizeAvailablePercent', '100') + ts('openvino', t_start) return torch_command def install_torch_addons(): + t_start = time.time() xformers_package = os.environ.get('XFORMERS_PACKAGE', '--pre xformers') if opts.get('cross_attention_optimization', '') == 'xFormers' or args.use_xformers else 'none' triton_command = os.environ.get('TRITON_COMMAND', 'triton') if sys.platform == 'linux' else None if 'xformers' in xformers_package: @@ -697,10 +719,12 @@ def install_torch_addons(): uninstall('wandb', quiet=True) if triton_command is not None: install(triton_command, 'triton', quiet=True) + ts('addons', t_start) # check torch version def check_torch(): + t_start = time.time() if args.skip_torch: log.info('Torch: skip tests') return @@ -812,10 +836,12 @@ def check_torch(): if args.profile: pr.disable() print_profile(pr, 'Torch') + ts('torch', t_start) # check modified files def check_modified_files(): + t_start = time.time() if args.quick: return if args.skip_git: @@ -832,10 +858,12 @@ def check_modified_files(): log.warning(f'Modified files: {files}') except Exception: pass + ts('files', t_start) # install required packages def install_packages(): + t_start = time.time() if args.profile: pr = cProfile.Profile() pr.enable() @@ -850,6 +878,7 @@ def install_packages(): if args.profile: pr.disable( ) print_profile(pr, 'Packages') + ts('packages', t_start) # run extension installer @@ -873,6 +902,7 @@ def run_extension_installer(folder): except Exception as e: log.error(f'Extension installer exception: {e}') + # get list of all enabled extensions def list_extensions_folder(folder, quiet=False): name = os.path.basename(folder) @@ -888,6 +918,7 @@ def list_extensions_folder(folder, quiet=False): # run installer for each installed and enabled extension and optionally update them def install_extensions(force=False): + t_start = time.time() if args.profile: pr = cProfile.Profile() pr.enable() @@ -936,11 +967,13 @@ def install_extensions(force=False): if args.profile: pr.disable() print_profile(pr, 'Extensions') + ts('extensions', t_start) return '\n'.join(res) # initialize and optionally update submodules def install_submodules(force=True): + t_start = time.time() if args.profile: pr = cProfile.Profile() pr.enable() @@ -968,10 +1001,12 @@ def install_submodules(force=True): if args.profile: pr.disable() print_profile(pr, 'Submodule') + ts('submodules', t_start) return '\n'.join(res) def ensure_base_requirements(): + t_start = time.time() setuptools_version = '69.5.1' def update_setuptools(): @@ -979,7 +1014,6 @@ def update_setuptools(): global pkg_resources, setuptools, distutils # pylint: disable=global-statement # python may ship with incompatible setuptools subprocess.run(f'"{sys.executable}" -m pip install setuptools=={setuptools_version}', shell=True, check=False, env=os.environ, stdout=subprocess.PIPE, stderr=subprocess.PIPE) - import importlib # need to delete all references to modules to be able to reload them otherwise python will use cached version modules = [m for m in sys.modules if m.startswith('setuptools') or m.startswith('pkg_resources') or m.startswith('distutils')] for m in modules: @@ -1004,9 +1038,11 @@ def update_setuptools(): install('rich', 'rich', quiet=True) install('psutil', 'psutil', quiet=True) install('requests', 'requests', quiet=True) + ts('base', t_start) def install_optional(): + t_start = time.time() log.info('Installing optional requirements...') install('basicsr') install('gfpgan') @@ -1027,9 +1063,11 @@ def install_optional(): os.rename(scripts_dir, scripts_dir + '_gguf') except Exception: pass + ts('optional', t_start) def install_requirements(): + t_start = time.time() if args.profile: pr = cProfile.Profile() pr.enable() @@ -1053,6 +1091,7 @@ def install_requirements(): if args.profile: pr.disable() print_profile(pr, 'Requirements') + ts('requirements', t_start) # set environment variables controling the behavior of various libraries @@ -1117,14 +1156,15 @@ def check_extensions(): for f in os.listdir(extension_dir): if '.json' in f or '.csv' in f or '__pycache__' in f: continue - ts = os.path.getmtime(os.path.join(extension_dir, f)) - newest = max(newest, ts) + mtime = os.path.getmtime(os.path.join(extension_dir, f)) + newest = max(newest, mtime) newest_all = max(newest_all, newest) # log.debug(f'Extension version: {time.ctime(newest)} {folder}{os.pathsep}{ext}') return round(newest_all) def get_version(force=False): + t_start = time.time() global version # pylint: disable=global-statement if version is None or force: try: @@ -1159,6 +1199,7 @@ def get_version(force=False): except Exception: os.chdir(cwd) version['ui'] = 'unknown' + ts('version', t_start) return version @@ -1168,6 +1209,7 @@ def same(ver): ui = ver['ui'] if ver is not None and 'ui' in ver else 'unknown' return core == ui or (core == 'master' and ui == 'main') + t_start = time.time() if not same(ver): log.debug(f'Branch mismatch: sdnext={ver["branch"]} ui={ver["ui"]}') cwd = os.getcwd() @@ -1184,6 +1226,7 @@ def same(ver): except Exception as e: log.debug(f'Branch switch: {e}') os.chdir(cwd) + ts('ui', t_start) def check_venv(): @@ -1193,6 +1236,7 @@ def try_relpath(p): except ValueError: return p + t_start = time.time() import site pkg_path = [try_relpath(p) for p in site.getsitepackages() if os.path.exists(p)] log.debug(f'Packages: venv={try_relpath(sys.prefix)} site={pkg_path}') @@ -1212,10 +1256,12 @@ def try_relpath(p): os.unlink(fn) except Exception as e: log.error(f'Packages: site={p} invalid={f} error={e}') + ts('venv', t_start) # check version of the main repo and optionally upgrade it def check_version(offline=False, reset=True): # pylint: disable=unused-argument + t_start = time.time() if args.skip_all: return if not os.path.exists('.git'): @@ -1261,15 +1307,18 @@ def check_version(offline=False, reset=True): # pylint: disable=unused-argument log.info(f'Repository latest available {commits["commit"]["sha"]} {commits["commit"]["commit"]["author"]["date"]}') except Exception as e: log.error(f'Repository failed to check version: {e} {commits}') + ts('latest', t_start) def update_wiki(): + t_start = time.time() if args.upgrade: log.info('Updating Wiki') try: update(os.path.join(os.path.dirname(__file__), "wiki")) except Exception: log.error('Wiki update error') + ts('wiki', t_start) # check if we can run setup in quick mode @@ -1358,6 +1407,7 @@ def parse_args(parser): def extensions_preload(parser): + t_start = time.time() if args.profile: pr = cProfile.Profile() pr.enable() @@ -1379,9 +1429,11 @@ def extensions_preload(parser): if args.profile: pr.disable() print_profile(pr, 'Preload') + ts('preload', t_start) def git_reset(folder='.'): + t_start = time.time() log.warning('Running GIT reset') global quick_allowed # pylint: disable=global-statement quick_allowed = False @@ -1397,9 +1449,11 @@ def git_reset(folder='.'): git('submodule update --init --recursive') git('submodule sync --recursive') log.info('GIT reset complete') + ts('reset', t_start) def read_options(): + t_start = time.time() global opts # pylint: disable=global-statement if os.path.isfile(args.config): with open(args.config, "r", encoding="utf8") as file: @@ -1409,3 +1463,4 @@ def read_options(): opts = json.loads(opts) except Exception as e: log.error(f'Error reading options file: {file} {e}') + ts('options', t_start) diff --git a/launch.py b/launch.py index e00da58c7..07fa93697 100755 --- a/launch.py +++ b/launch.py @@ -24,12 +24,20 @@ skip_install = False # parsed by some extensions +try: + from modules.timer import launch + rec = launch.record +except Exception: + rec = lambda *args, **kwargs: None # pylint: disable=unnecessary-lambda-assignment + + def init_args(): global parser, args # pylint: disable=global-statement import modules.cmd_args parser = modules.cmd_args.parser installer.add_args(parser) args, _ = parser.parse_known_args() + rec('args') def init_paths(): @@ -38,6 +46,7 @@ def init_paths(): modules.paths.register_paths() script_path = modules.paths.script_path extensions_dir = modules.paths.extensions_dir + rec('paths') def get_custom_args(): @@ -60,6 +69,7 @@ def get_custom_args(): ldd = os.environ.get('LD_PRELOAD', None) if ldd is not None: installer.log.debug(f'Linker flags: "{ldd}"') + rec('args') @lru_cache() @@ -71,6 +81,7 @@ def commit_hash(): # compatbility function stored_commit_hash = run(f"{git} rev-parse HEAD").strip() except Exception: stored_commit_hash = "" + rec('commit') return stored_commit_hash @@ -185,6 +196,7 @@ def start_server(immediate=True, server=None): if args.profile: pr.disable() installer.print_profile(pr, 'WebUI') + rec('server') return uvicorn, server @@ -218,7 +230,6 @@ def main(): installer.install("uv", "uv") installer.check_torch() installer.check_onnx() - installer.check_torchao() installer.check_diffusers() installer.check_modified_files() if args.reinstall: diff --git a/modules/script_callbacks.py b/modules/script_callbacks.py index 6c91edf44..a0c85a283 100644 --- a/modules/script_callbacks.py +++ b/modules/script_callbacks.py @@ -141,7 +141,7 @@ def print_timers(): if v > 0.05: long_callbacks.append(f'{k}={v:.2f}') if len(long_callbacks) > 0: - errors.log.debug(f'Script callback init time: {" ".join(long_callbacks)}') + errors.log.debug(f'Script init: {long_callbacks}') def clear_callbacks(): diff --git a/modules/timer.py b/modules/timer.py index 3c7d42f6d..69107e605 100644 --- a/modules/timer.py +++ b/modules/timer.py @@ -25,9 +25,12 @@ def elapsed(self, reset=True): def add(self, name, t): if name not in self.records: - self.records[name] = t - else: - self.records[name] += t + self.records[name] = 0 + self.records[name] += t + + def ts(self, name, t): + elapsed = time.time() - t + self.add(name, elapsed) def record(self, category=None, extra_time=0, reset=True): e = self.elapsed(reset) @@ -41,6 +44,8 @@ def record(self, category=None, extra_time=0, reset=True): def summary(self, min_time=default_min_time, total=True): if self.profile: min_time = -1 + if self.total <= 0: + self.total = sum(self.records.values()) res = f"total={self.total:.2f} " if total else '' additions = [x for x in self.records.items() if x[1] >= min_time] additions = sorted(additions, key=lambda x: x[1], reverse=True) @@ -49,6 +54,9 @@ def summary(self, min_time=default_min_time, total=True): res += " ".join([f"{category}={time_taken:.2f}" for category, time_taken in additions]) return res + def get_total(self): + return sum(self.records.values()) + def dct(self, min_time=default_min_time): if self.profile: res = {k: round(v, 4) for k, v in self.records.items()} @@ -61,3 +69,5 @@ def reset(self): startup = Timer() process = Timer() +launch = Timer() +init = Timer() diff --git a/webui.py b/webui.py index 33769994e..2c70192f1 100644 --- a/webui.py +++ b/webui.py @@ -171,7 +171,7 @@ def sigint_handler(_sig, _frame): def load_model(): if not shared.opts.sd_checkpoint_autoload and shared.cmd_opts.ckpt is None: - log.debug('Model auto load disabled') + log.info('Model auto load disabled') else: shared.state.begin('Load') thread_model = Thread(target=lambda: shared.sd_model) @@ -356,7 +356,15 @@ def webui(restart=False): for m in modules.scripts.postprocessing_scripts_data: debug(f' {m}') modules.script_callbacks.print_timers() - log.info(f"Startup time: {timer.startup.summary()}") + + if cmd_opts.profile: + log.info(f"Launch time: {timer.launch.summary(min_time=0)}") + log.info(f"Installer time: {timer.init.summary(min_time=0)}") + log.info(f"Startup time: {timer.startup.summary(min_time=0)}") + else: + timer.startup.add('launch', timer.launch.get_total()) + timer.startup.add('installer', timer.launch.get_total()) + log.info(f"Startup time: {timer.startup.summary()}") timer.startup.reset() if not restart: