log cleanup

pull/2440/head
Vladimir Mandic 2023-10-31 12:34:35 -04:00
parent 4392e69431
commit 676ac120f1
24 changed files with 59 additions and 49 deletions

View File

@ -59,7 +59,7 @@ class ExtraNetworkLora(extra_networks.ExtraNetwork):
if network_hashes:
p.extra_generation_params["Lora hashes"] = ", ".join(network_hashes)
if len(names) > 0:
shared.log.info(f'Applying LoRA: {names} patch={t1-t0:.2f}s load={t2-t1:.2f}s')
shared.log.info(f'Applying LoRA: {names} patch={t1-t0:.2f} load={t2-t1:.2f}')
elif self.active:
self.active = False
@ -69,7 +69,7 @@ class ExtraNetworkLora(extra_networks.ExtraNetwork):
if networks.debug:
shared.log.debug("LoRA deactivate")
if self.active and networks.debug:
shared.log.debug(f"LoRA end: load={networks.timer['load']:.2f}s apply={networks.timer['apply']:.2f}s restore={networks.timer['restore']:.2f}s")
shared.log.debug(f"LoRA end: load={networks.timer['load']:.2f} apply={networks.timer['apply']:.2f} restore={networks.timer['restore']:.2f}")
if self.errors:
p.comment("Networks with errors: " + ", ".join(f"{k} ({v})" for k, v in self.errors.items()))
for k, v in self.errors.items():

View File

@ -576,7 +576,6 @@ def install_packages():
install('pi-heif', 'pi_heif', ignore=True)
tensorflow_package = os.environ.get('TENSORFLOW_PACKAGE', 'tensorflow==2.13.0')
install(tensorflow_package, 'tensorflow-rocm' if 'rocm' in tensorflow_package else 'tensorflow', ignore=True)
# install('nvidia-ml-py', 'pynvml', ignore=True)
bitsandbytes_package = os.environ.get('BITSANDBYTES_PACKAGE', None)
if bitsandbytes_package is not None:
install(bitsandbytes_package, 'bitsandbytes', ignore=True)

10
launch.py Normal file → Executable file
View File

@ -1,3 +1,5 @@
#!/usr/bin/env python
import os
import sys
import time
@ -145,7 +147,6 @@ def start_server(immediate=True, server=None):
if collected > 0:
installer.log.debug(f'Memory {get_memory_stats()} Collected {collected}')
module_spec = importlib.util.spec_from_file_location('webui', 'webui.py')
# installer.log.debug(f'Loading module: {module_spec}')
server = importlib.util.module_from_spec(module_spec)
installer.log.debug(f'Starting module: {server}')
get_custom_args()
@ -191,16 +192,17 @@ if __name__ == "__main__":
installer.log.info('Forcing reinstall of all packages')
installer.quick_allowed = False
if args.skip_all:
installer.log.info('Skipping all checks')
installer.log.info('Startup: skip all')
installer.quick_allowed = True
init_paths()
elif installer.check_timestamp():
installer.log.info('No changes detected: quick launch active')
installer.log.info('Startup: quick launch')
installer.install_requirements()
installer.install_packages()
init_paths()
installer.check_extensions()
else:
installer.log.info('Startup: standard')
installer.install_requirements()
installer.install_packages()
installer.install_repositories()
@ -231,7 +233,7 @@ if __name__ == "__main__":
if round(time.time()) % 120 == 0:
state = f'job="{instance.state.job}" {instance.state.job_no}/{instance.state.job_count}' if instance.state.job != '' or instance.state.job_no != 0 or instance.state.job_count != 0 else 'idle'
uptime = round(time.time() - instance.state.server_start)
installer.log.debug(f'Server alive={alive} jobs={instance.state.total_jobs} requests={requests} uptime={uptime}s memory {get_memory_stats()} {state}')
installer.log.debug(f'Server alive={alive} jobs={instance.state.total_jobs} requests={requests} uptime={uptime} memory {get_memory_stats()} {state}')
if not alive:
if uv is not None and uv.wants_restart:
installer.log.info('Server restarting...')

View File

@ -224,7 +224,7 @@ class Hypernetwork:
self.filename = filename if os.path.exists(filename) else os.path.join(shared.opts.hypernetwork_dir, filename)
if self.name is None:
self.name = os.path.splitext(os.path.basename(self.filename))[0]
with progress.open(self.filename, 'rb', description=f'Loading hypernetwork: [cyan]{self.filename}', auto_refresh=True, console=shared.console) as f:
with progress.open(self.filename, 'rb', description=f'Load hypernetwork: [cyan]{self.filename}', auto_refresh=True, console=shared.console) as f:
state_dict = torch.load(f, map_location='cpu')
self.layer_structure = state_dict.get('layer_structure', [1, 2, 1])
self.optional_info = state_dict.get('optional_info', None)
@ -256,7 +256,7 @@ class Hypernetwork:
if self.optimizer_state_dict:
self.optimizer_name = optimizer_saved_dict.get('optimizer_name', 'AdamW')
if shared.opts.print_hypernet_extra:
print("Loaded existing optimizer from checkpoint")
print("Load existing optimizer from checkpoint")
print(f"Optimizer name is {self.optimizer_name}")
else:
self.optimizer_name = "AdamW"

View File

@ -17,7 +17,7 @@ import torch # pylint: disable=C0411
# torch.set_num_threads(1)
try:
import intel_extension_for_pytorch as ipex # pylint: disable=import-error, unused-import
errors.log.debug(f'Loaded IPEX=={ipex.__version__}')
errors.log.debug(f'Load IPEX=={ipex.__version__}')
except Exception:
pass
urllib3.disable_warnings(urllib3.exceptions.InsecureRequestWarning)
@ -40,4 +40,4 @@ errors.install([gradio])
import diffusers # pylint: disable=W0611,C0411
timer.startup.record("diffusers")
errors.log.debug(f'Loaded packages: torch={getattr(torch, "__long_version__", torch.__version__)} diffusers={diffusers.__version__} gradio={gradio.__version__}')
errors.log.debug(f'Load packages: torch={getattr(torch, "__long_version__", torch.__version__)} diffusers={diffusers.__version__} gradio={gradio.__version__}')

View File

@ -288,7 +288,7 @@ def load_diffusers_models(model_path: str, command_path: str = None):
shared.log.error(f"Error analyzing diffusers model: {place}/{folder} {e}")
except Exception as e:
shared.log.error(f"Error listing diffusers: {place} {e}")
shared.log.debug(f'Scanning diffusers cache: {model_path} {command_path} items={len(output)} time={time.time()-t0:.2f}s')
shared.log.debug(f'Scanning diffusers cache: {model_path} {command_path} items={len(output)} time={time.time()-t0:.2f}')
return output
@ -574,4 +574,4 @@ def load_upscalers():
datas += scaler.scalers
names.append(name[8:])
shared.sd_upscalers = sorted(datas, key=lambda x: x.name.lower() if not isinstance(x.scaler, (UpscalerNone, UpscalerLanczos, UpscalerNearest)) else "") # Special case for UpscalerNone keeps it at the beginning of the list.
shared.log.debug(f"Loaded upscalers: total={len(shared.sd_upscalers)} downloaded={len([x for x in shared.sd_upscalers if x.data_path is not None and os.path.isfile(x.data_path)])} user={len([x for x in shared.sd_upscalers if x.custom])} {names}")
shared.log.debug(f"Load upscalers: total={len(shared.sd_upscalers)} downloaded={len([x for x in shared.sd_upscalers if x.data_path is not None and os.path.isfile(x.data_path)])} user={len([x for x in shared.sd_upscalers if x.custom])} {names}")

View File

@ -40,6 +40,7 @@ if os.environ.get('SD_PATH_DEBUG', None) is not None:
def register_paths():
log.debug('Register paths')
sys.path.insert(0, script_path)
sd_path = os.path.join(script_path, 'repositories')
path_dirs = [
@ -66,9 +67,9 @@ def create_path(folder):
return
try:
os.makedirs(folder, exist_ok=True)
log.info(f'Create folder={folder}')
log.info(f'Create: folder="{folder}"')
except Exception as e:
log.error(f'Create Failed folder={folder} {e}')
log.error(f'Create failed: folder="{folder}" {e}')
def create_paths(opts):
@ -83,7 +84,7 @@ def create_paths(opts):
fix = os.path.abspath(fix)
fix = fix if os.path.isabs(fix) else os.path.relpath(fix, script_path)
opts.data[folder] = fix
debug(f'Paths: folder={folder} original="{tgt}" target="{fix}"')
debug(f'Paths: folder="{folder}" original="{tgt}" target="{fix}"')
return opts.data[folder]
create_path(data_path)

View File

@ -939,7 +939,7 @@ def process_images_inner(p: StableDiffusionProcessing) -> Processed:
devices.torch_gc()
t1 = time.time()
shared.log.info(f'Processed: images={len(output_images)} time={t1 - t0:.2f}s its={(p.steps * len(output_images)) / (t1 - t0):.2f} memory={modules.memstats.memory_stats()}')
shared.log.info(f'Processed: images={len(output_images)} time={t1 - t0:.2f} its={(p.steps * len(output_images)) / (t1 - t0):.2f} memory={modules.memstats.memory_stats()}')
p.color_corrections = None
index_of_first_image = 0

View File

@ -93,7 +93,7 @@ def process_diffusers(p: StableDiffusionProcessing, seeds, prompts, negative_pro
if shared.opts.diffusers_move_unet and not getattr(model, 'has_accelerate', False):
model.unet.to(unet_device)
t1 = time.time()
shared.log.debug(f'VAE decode: name={sd_vae.loaded_vae_file if sd_vae.loaded_vae_file is not None else "baked"} dtype={model.vae.dtype} upcast={upcast} images={latents.shape[0]} latents={latents.shape} time={round(t1-t0, 3)}s')
shared.log.debug(f'VAE decode: name={sd_vae.loaded_vae_file if sd_vae.loaded_vae_file is not None else "baked"} dtype={model.vae.dtype} upcast={upcast} images={latents.shape[0]} latents={latents.shape} time={round(t1-t0, 3)}')
return decoded
def full_vae_encode(image, model):

View File

@ -118,7 +118,7 @@ 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}')
errors.log.debug(f'Script: {s} {callback} {script}')
def clear_callbacks():

View File

@ -269,7 +269,7 @@ def load_scripts():
script_module = script_loading.load_module(scriptfile.path)
register_scripts_from_module(script_module, scriptfile)
except Exception as e:
errors.display(e, f'Loading script: {scriptfile.filename}')
errors.display(e, f'Load script: {scriptfile.filename}')
finally:
current_basedir = paths.script_path
t.record(os.path.basename(scriptfile.basedir))
@ -307,8 +307,8 @@ class ScriptSummary:
total = sum(self.time.values())
if total == 0:
return
scripts = [f'{k}:{v}s' for k, v in self.time.items() if v > 0]
log.debug(f'Script: op={self.op} total={total}s scripts={scripts}')
scripts = [f'{k}:{v}' for k, v in self.time.items() if v > 0]
log.debug(f'Script: op={self.op} total={total} scripts={scripts}')
class ScriptRunner:

View File

@ -178,7 +178,7 @@ def list_models():
shared.opts.data['sd_model_checkpoint'] = checkpoint_info.title
elif shared.cmd_opts.ckpt != shared.default_sd_model_file and shared.cmd_opts.ckpt is not None:
shared.log.warning(f"Checkpoint not found: {shared.cmd_opts.ckpt}")
shared.log.info(f'Available models: path="{shared.opts.ckpt_dir}" items={len(checkpoints_list)} time={time.time()-t0:.2f}s')
shared.log.info(f'Available models: path="{shared.opts.ckpt_dir}" items={len(checkpoints_list)} time={time.time()-t0:.2f}')
checkpoints_list = dict(sorted(checkpoints_list.items(), key=lambda cp: cp[1].filename))
if len(checkpoints_list) == 0:
@ -314,10 +314,10 @@ def get_state_dict_from_checkpoint(pl_sd):
def write_metadata():
global sd_metadata_pending # pylint: disable=global-statement
if sd_metadata_pending == 0:
shared.log.debug(f"Model metadata: {sd_metadata_file} no changes")
shared.log.debug(f'Model metadata: file="{sd_metadata_file}" no changes')
return
shared.writefile(sd_metadata, sd_metadata_file)
shared.log.info(f"Model metadata saved: {sd_metadata_file} items={sd_metadata_pending} time={sd_metadata_timer:.2f}s")
shared.log.info(f'Model metadata saved: file="{sd_metadata_file}" items={sd_metadata_pending} time={sd_metadata_timer:.2f}')
sd_metadata_pending = 0
@ -424,7 +424,7 @@ def read_state_dict(checkpoint_file, map_location=None): # pylint: disable=unuse
sd = get_state_dict_from_checkpoint(pl_sd)
del pl_sd
except Exception as e:
errors.display(e, f'loading model: {checkpoint_file}')
errors.display(e, f'Load model: {checkpoint_file}')
sd = None
return sd
@ -826,7 +826,7 @@ def load_diffuser(checkpoint_info=None, already_loaded_state_dict=None, timer=No
ckpt_basename = os.path.basename(shared.cmd_opts.ckpt)
model_name = modelloader.find_diffuser(ckpt_basename)
if model_name is not None:
shared.log.info(f'Loading model {op}: {model_name}')
shared.log.info(f'Load model {op}: {model_name}')
model_file = modelloader.download_diffusers_model(hub_id=model_name)
try:
shared.log.debug(f'Model load {op} config: {diffusers_load_config}')
@ -986,7 +986,7 @@ def load_diffuser(checkpoint_info=None, already_loaded_state_dict=None, timer=No
timer.record("load")
devices.torch_gc(force=True)
script_callbacks.model_loaded_callback(sd_model)
shared.log.info(f"Loaded {op}: time={timer.summary()} native={get_native(sd_model)} {memory_stats()}")
shared.log.info(f"Load {op}: time={timer.summary()} native={get_native(sd_model)} {memory_stats()}")
class DiffusersTaskType(Enum):
@ -1227,7 +1227,7 @@ def reload_model_weights(sd_model=None, info=None, reuse_dict=False, op='model')
timer.record("device")
shared.state.end()
shared.state = orig_state
shared.log.info(f"Loaded: {op} time={timer.summary()}")
shared.log.info(f"Load: {op} time={timer.summary()}")
return sd_model

View File

@ -43,7 +43,7 @@ def nn_approximation(sample): # Approximate NN
sd_vae_approx_model.load_state_dict(approx_weights)
sd_vae_approx_model.eval()
sd_vae_approx_model.to(devices.device, devices.dtype)
shared.log.debug(f'Loaded VAE decode approximate: model="{model_path}"')
shared.log.debug(f'Load VAE decode approximate: model="{model_path}"')
try:
in_sample = sample.to(devices.device, devices.dtype).unsqueeze(0)
x_sample = sd_vae_approx_model(in_sample)

View File

@ -158,17 +158,25 @@ def list_samplers():
def temp_disable_extensions():
disable_safe = ['sd-webui-controlnet', 'multidiffusion-upscaler-for-automatic1111', 'a1111-sd-webui-lycoris', 'sd-webui-agent-scheduler', 'clip-interrogator-ext', 'stable-diffusion-webui-rembg', 'sd-extension-chainner', 'stable-diffusion-webui-images-browser']
disable_diffusers = ['sd-webui-controlnet', 'multidiffusion-upscaler-for-automatic1111', 'a1111-sd-webui-lycoris']
disable_original = []
disabled = []
if cmd_opts.safe:
for ext in ['sd-webui-controlnet', 'multidiffusion-upscaler-for-automatic1111', 'a1111-sd-webui-lycoris', 'sd-webui-agent-scheduler', 'clip-interrogator-ext', 'stable-diffusion-webui-rembg', 'sd-extension-chainner', 'stable-diffusion-webui-images-browser']:
for ext in disable_safe:
if ext not in opts.disabled_extensions:
disabled.append(ext)
log.info(f'Safe mode disabling extensions: {disabled}')
if backend == Backend.DIFFUSERS:
for ext in ['sd-webui-controlnet', 'multidiffusion-upscaler-for-automatic1111', 'a1111-sd-webui-lycoris']:
for ext in disable_diffusers:
if ext not in opts.disabled_extensions:
disabled.append(ext)
log.info(f'Diffusers disabling uncompatible extensions: {disabled}')
log.info(f'Disabling uncompatible extensions: backend={backend} {disabled}')
if backend == Backend.ORIGINAL:
for ext in disable_original:
if ext not in opts.disabled_extensions:
disabled.append(ext)
log.info(f'Disabling uncompatible extensions: backend={backend} {disabled}')
cmd_opts.controlnet_loglevel = 'WARNING'
return disabled
@ -184,7 +192,7 @@ def readfile(filename, silent=False):
if type(data) is str:
data = json.loads(data)
if not silent:
log.debug(f'Reading: {filename} len={len(data)}')
log.debug(f'Read: file="{filename}" len={len(data)}')
except Exception as e:
if not silent:
log.error(f'Reading failed: {filename} {e}')
@ -213,7 +221,7 @@ def writefile(data, filename, mode='w', silent=False):
else:
raise ValueError('not a valid object')
if not silent:
log.debug(f'Saving: {filename} len={len(output)}')
log.debug(f'Save: file="{filename}" len={len(output)}')
with open(filename, mode, encoding="utf8") as file:
file.write(output)
except Exception as e:

View File

@ -85,7 +85,7 @@ class State:
log.debug(f'Access state.end: {sys._getframe().f_back.f_code.co_name}') # pylint: disable=protected-access
self.time_start = time.time()
if self.debug_output:
log.debug(f'State end: {self.job} time={time.time() - self.time_start:.2f}s')
log.debug(f'State end: {self.job} time={time.time() - self.time_start:.2f}')
self.job = ""
self.job_count = 0
self.job_no = 0

View File

@ -128,7 +128,7 @@ class StyleDatabase:
if self.built_in:
self.load_style(os.path.join('html', 'art-styles.json'), 'built-in')
log.debug(f'Loaded styles: folder={self.path} items={len(self.styles.keys())}')
log.debug(f'Load styles: folder="{self.path}" items={len(self.styles.keys())}')
def find_style(self, name):
found = [style for style in self.styles.values() if style.name == name]
@ -184,7 +184,7 @@ class StyleDatabase:
self.styles[row["name"]] = Style(row["name"], row["prompt"] if "prompt" in row else row["text"], row.get("negative_prompt", ""))
except Exception:
log.error(f'Styles error: file={legacy_file} row={row}')
log.debug(f'Loaded legacy styles: file={legacy_file} items={len(self.styles.keys())}')
log.debug(f'Load legacy styles: file={legacy_file} items={len(self.styles.keys())}')
"""
def save_csv(self, path: str) -> None:

View File

@ -33,7 +33,7 @@ def model(model_class = 'sd', model_type = 'decoder'):
vae = taesd_models[f'{model_class}-{model_type}']
vae.eval()
vae.to(devices.device, devices.dtype_vae)
log.info(f"Loaded VAE-TAESD: model={model_path}")
log.info(f"Load VAE-TAESD: model={model_path}")
else:
raise FileNotFoundError(f'TAESD model not found: {model_path}')
if vae is None:

View File

@ -308,7 +308,7 @@ class EmbeddingDatabase:
if self.previously_displayed_embeddings != displayed_embeddings:
self.previously_displayed_embeddings = displayed_embeddings
t1 = time.time()
shared.log.info(f"Loaded embeddings: loaded={len(self.word_embeddings)} skipped={len(self.skipped_embeddings)} time={t1-t0:.2f}s")
shared.log.info(f"Load embeddings: loaded={len(self.word_embeddings)} skipped={len(self.skipped_embeddings)} time={t1-t0:.2f}")
def find_embedding_at_position(self, tokens, offset):
@ -497,7 +497,7 @@ def train_embedding(id_task, embedding_name, learn_rate, batch_size, gradient_st
optimizer_state_dict = optimizer_saved_dict.get('optimizer_state_dict', None)
if optimizer_state_dict is not None:
optimizer.load_state_dict(optimizer_state_dict)
shared.log.info("Loaded existing optimizer from checkpoint")
shared.log.info("Load existing optimizer from checkpoint")
else:
shared.log.info("No saved optimizer exists in checkpoint")

View File

@ -64,7 +64,7 @@ def reload_gradio_theme(theme_name=None):
'font_mono':['IBM Plex Mono', 'ui-monospace', 'Consolas', 'monospace']
}
is_builtin = theme_name in list_builtin_themes()
modules.shared.log.info(f'Loading UI theme: name={theme_name} style={modules.shared.opts.theme_style} base={"style.css" if is_builtin else "base.css"}')
modules.shared.log.info(f'Load UI theme: name="{theme_name}" style={modules.shared.opts.theme_style} base={"style.css" if is_builtin else "base.css"}')
if is_builtin:
gradio_theme = gr.themes.Base(**default_font_params)
elif theme_name.startswith("gradio/"):

View File

@ -22,11 +22,11 @@ class Timer:
self.total += e + extra_time
def summary(self, min_time=0.05):
res = f"{self.total:.2f}s"
res = f"{self.total:.2f}"
additions = [x for x in self.records.items() if x[1] >= min_time]
if not additions:
return res
res += " { " + " ".join([f"{category}={time_taken:.2f}s" for category, time_taken in additions]) + " }"
res += " { " + " ".join([f"{category}={time_taken:.2f}" for category, time_taken in additions]) + " }"
return res
def reset(self):

View File

@ -254,7 +254,7 @@ class ExtraNetworksPage:
self.html = f"<div id='{tabname}_{self_name_id}_subdirs' class='extra-network-subdirs'>{subdirs_html}</div><div id='{tabname}_{self_name_id}_cards' class='extra-network-cards'>{self.html}</div>"
else:
return ''
shared.log.debug(f"Extra networks: page='{self.name}' items={len(self.items)} subdirs={len(subdirs)} tab={tabname} dirs={self.allowed_directories_for_previews()} time={self.list_time}s")
shared.log.debug(f"Extra networks: page='{self.name}' items={len(self.items)} subdirs={len(subdirs)} tab={tabname} dirs={self.allowed_directories_for_previews()} time={self.list_time}")
if len(self.missing_thumbs) > 0:
threading.Thread(target=self.create_thumb).start()
return self.html

View File

@ -40,7 +40,7 @@ class Upscaler:
self.mod_scale = None
self.model_download_path = None
if self.user_path is not None and len(self.user_path) > 0 and not os.path.exists(self.user_path):
modules.shared.log.info(f'Upscaler create: folder={self.user_path}')
modules.shared.log.info(f'Upscaler create: folder="{self.user_path}"')
if self.model_path is None and self.name:
self.model_path = os.path.join(modules.shared.models_path, self.name)
if self.model_path and create_dirs:

0
webui.ps1 Normal file → Executable file
View File

View File

@ -105,7 +105,7 @@ def initialize():
gfpgan.setup_model(opts.gfpgan_models_path)
timer.startup.record("face-restore")
log.debug('Loading extensions')
log.debug('Load extensions')
t_timer, t_total = modules.scripts.load_scripts()
timer.startup.record("extensions")
timer.startup.records["extensions"] = t_total # scripts can reset the time
@ -294,9 +294,9 @@ def start_ui():
modules.script_callbacks.app_started_callback(shared.demo, app)
timer.startup.record("app-started")
time_setup = [f'{k}:{round(v,3)}s' for (k,v) in modules.scripts.time_setup.items() if v > 0.005]
time_setup = [f'{k}:{round(v,3)}' for (k,v) in modules.scripts.time_setup.items() if v > 0.005]
shared.log.debug(f'Scripts setup: {time_setup}')
time_component = [f'{k}:{round(v,3)}s' for (k,v) in modules.scripts.time_component.items() if v > 0.005]
time_component = [f'{k}:{round(v,3)}' for (k,v) in modules.scripts.time_component.items() if v > 0.005]
if len(time_component) > 0:
shared.log.debug(f'Scripts components: {time_component}')