startup tracing

Signed-off-by: Vladimir Mandic <mandic00@live.com>
pull/3696/head
Vladimir Mandic 2025-01-08 09:35:49 -05:00
parent 9763c6bbe8
commit aa1ff725c6
6 changed files with 117 additions and 32 deletions

View File

@ -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)

View File

@ -8,6 +8,7 @@ import logging
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 @@ extensions_commit = {
# '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 setup_logging():
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 setup_logging():
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 ensure_base_requirements():
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 ensure_base_requirements():
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 check_ui(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 check_ui(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 check_venv():
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 check_venv():
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)

View File

@ -24,12 +24,20 @@ python = sys.executable # used by some extensions to run python
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 = "<none>"
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:

View File

@ -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():

View File

@ -25,9 +25,12 @@ class Timer:
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 @@ class Timer:
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 @@ class Timer:
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 @@ class Timer:
startup = Timer()
process = Timer()
launch = Timer()
init = Timer()

View File

@ -171,7 +171,7 @@ def initialize():
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: