reorg server startup

CHANGELOG.md

@@ -1,6 +1,6 @@
 # Change Log for SD.Next
 
-## Update for 06/10/2023
+## Update for 06/11/2023
 
 - updated ui labels and hints to improve clarity and provide some extra info  
   this is 1st stage of the process, more to come...  
@@ -11,6 +11,8 @@
   which was preventing some optimizations to take effect  
 - updated **settings** tab functionality, thanks @gegell  
 - **launcher** will now warn if application owned files are modified  
+- add more profiling for scripts/extensions so you can see what takes time  
+  this applies both to initial load as well as execution  
 - experimental `sd_model_dict` setting which allows you to load model dictionary  
   from one model and apply weights from another model specified in `sd_model_checkpoint`  
   results? who am i to judge :)

extensions-builtin/sd-webui-controlnet

@@ -1 +1 @@
-Subproject commit 479bc5c4a97b1c7e0e33d96ecf8c758fdcffa2a1
+Subproject commit 0ddedce554ef5cf490b9196292feced91d882a5e

installer.py

@@ -222,6 +222,8 @@ def clone(url, folder, commithash=None):
 # check python version
 def check_python():
     supported_minors = [9, 10]
+    if args.quick:
+        return True
     if args.experimental:
         supported_minors.append(11)
     log.info(f'Python {platform.python_version()} on {platform.system()}')
@@ -242,6 +244,8 @@ def check_python():
 
 # check torch version
 def check_torch():
+    if args.quick:
+        return True
     if args.profile:
         pr = cProfile.Profile()
         pr.enable()
@@ -345,6 +349,8 @@ def check_torch():
 
 # check modified files
 def check_modified_files():
+    if args.quick:
+        return True
     if args.skip_git:
         return
     try:
@@ -546,7 +552,7 @@ def install_requirements():
 
 # set environment variables controling the behavior of various libraries
 def set_environment():
-    log.info('Setting environment tuning')
+    log.debug('Setting environment tuning')
     os.environ.setdefault('USE_TORCH', '1')
     os.environ.setdefault('TF_CPP_MIN_LOG_LEVEL', '2')
     os.environ.setdefault('ACCELERATE', 'True')
@@ -568,6 +574,8 @@ def set_environment():
 
 
 def check_extensions():
+    if args.quick:
+        return 0
     newest_all = os.path.getmtime('requirements.txt')
     from modules.paths_internal import extensions_builtin_dir, extensions_dir
     extension_folders = [extensions_builtin_dir] if args.safe else [extensions_builtin_dir, extensions_dir]
@@ -601,6 +609,8 @@ def check_version(offline=False, reset=True): # pylint: disable=unused-argument
             sys.exit(1)
     ver = git('log -1 --pretty=format:"%h %ad"')
     log.info(f'Version: {ver}')
+    if args.quick:
+        return True
     if args.version:
         return
     if args.skip_git:
@@ -654,6 +664,8 @@ def update_wiki():
 def check_timestamp():
     if not quick_allowed or not os.path.isfile(log_file):
         return False
+    if args.quick:
+        return True
     if args.skip_git:
         return True
     ok = True
@@ -690,6 +702,7 @@ def add_args(parser):
     group.add_argument('--debug', default = False, action='store_true', help = "Run installer with debug logging, default: %(default)s")
     group.add_argument('--reset', default = False, action='store_true', help = "Reset main repository to latest version, default: %(default)s")
     group.add_argument('--upgrade', default = False, action='store_true', help = "Upgrade main repository to latest version, default: %(default)s")
+    group.add_argument('--quick', default = False, action='store_true', help = "Run with startup sequence only, default: %(default)s")
     group.add_argument("--use-ipex", default = False, action='store_true', help="Use Intel OneAPI XPU backend, default: %(default)s")
     group.add_argument('--use-directml', default = False, action='store_true', help = "Use DirectML if no compatible GPU is detected, default: %(default)s")
     group.add_argument("--use-cuda", default=False, action='store_true', help="Force use nVidia CUDA backend, default: %(default)s")

launch.py

@@ -124,6 +124,7 @@ def start_server(immediate=True, server=None):
     # installer.log.debug(f'Loading module: {module_spec}')
     server = importlib.util.module_from_spec(module_spec)
     installer.log.debug(f'Starting module: {server}')
+    installer.log.info(f"Server arguments: {sys.argv[1:]}")
     module_spec.loader.exec_module(server)
     if args.test:
         installer.log.info("Test only")
@@ -159,7 +160,6 @@ if __name__ == "__main__":
         installer.quick_allowed = False
     if installer.check_timestamp():
         installer.log.info('No changes detected: Quick launch active')
-        installer.check_extensions()
     else:
         installer.install_requirements()
         installer.install_packages()
@@ -176,7 +176,6 @@ if __name__ == "__main__":
     args = installer.parse_args(parser)
     # installer.run_setup()
     # installer.log.debug(f"Args: {vars(args)}")
-    installer.log.info(f"Server arguments: {sys.argv[1:]}")
     logging.disable(logging.NOTSET if args.debug else logging.DEBUG)
 
 

modules/scripts.py

@@ -219,8 +219,9 @@ def load_scripts():
     script_callbacks.clear_callbacks()
     scripts_list = list_scripts("scripts", ".py")
     syspath = sys.path
+    time_load = {}
 
-    def register_scripts_from_module(module):
+    def register_scripts_from_module(module, scriptfile):
         for _key, script_class in module.__dict__.items():
             if type(script_class) != type:
                 continue
@@ -231,17 +232,21 @@ def load_scripts():
                 postprocessing_scripts_data.append(ScriptClassData(script_class, scriptfile.path, scriptfile.basedir, module))
 
     for scriptfile in scripts_list:
+        t0 = time.time()
         try:
             if scriptfile.basedir != paths.script_path:
                 sys.path = [scriptfile.basedir] + sys.path
             current_basedir = scriptfile.basedir
             script_module = script_loading.load_module(scriptfile.path)
-            register_scripts_from_module(script_module)
+            register_scripts_from_module(script_module, scriptfile)
         except Exception as e:
             errors.display(e, f'Loading script: {scriptfile.filename}')
-        finally:
-            sys.path = syspath
-            current_basedir = paths.script_path
+        current_basedir = paths.script_path
+        time_load[scriptfile.basedir] = time_load.get(scriptfile.basedir, 0) + (time.time()-t0)
+    sys.path = syspath
+    current_basedir = paths.script_path
+    time_load = [f'{os.path.basename(k)}:{round(v,3)}s' for (k,v) in time_load.items() if v > 0.05]
+    log.debug(f'Scripts load: {time_load}')
 
 
 def wrap_call(func, filename, funcname, *args, default=None, **kwargs):

modules/sd_models.py

@@ -524,7 +524,7 @@ def load_model(checkpoint_info=None, already_loaded_state_dict=None, timer=None)
             sd_model = instantiate_from_config(sd_config.model)
     except Exception:
         sd_model = instantiate_from_config(sd_config.model)
-    shared.log.info(f"Model created from config: {checkpoint_config}")
+    shared.log.debug(f"Model created from config: {checkpoint_config}")
     sd_model.used_config = checkpoint_config
     timer.record("create")
     load_model_weights(sd_model, checkpoint_info, state_dict, timer)

modules/ui.py

@@ -1498,9 +1498,10 @@ def create_ui():
                 show_progress=info.refresh is not None,
             )
 
-        image_cfg_scale_visibility = (modules.shared.sd_model is not None) and hasattr(modules.shared.sd_model, 'cond_stage_key') and (modules.shared.sd_model.cond_stage_key == "edit") # pix2pix
-        text_settings.change(fn=lambda: gr.update(visible=image_cfg_scale_visibility), inputs=[], outputs=[image_cfg_scale])
-        demo.load(fn=lambda: gr.update(visible=image_cfg_scale_visibility), inputs=[], outputs=[image_cfg_scale])
+        # TODO image_cfg_scale_visibility should be on model change, not on ui create
+        # image_cfg_scale_visibility = (modules.shared.sd_model is not None) and hasattr(modules.shared.sd_model, 'cond_stage_key') and (modules.shared.sd_model.cond_stage_key == "edit") # pix2pix
+        # text_settings.change(fn=lambda: gr.update(visible=image_cfg_scale_visibility), inputs=[], outputs=[image_cfg_scale])
+        # demo.load(fn=lambda: gr.update(visible=image_cfg_scale_visibility), inputs=[], outputs=[image_cfg_scale])
 
         button_set_checkpoint = gr.Button('Change checkpoint', elem_id='change_checkpoint', visible=False)
         button_set_checkpoint.click(

webui.py

@@ -154,11 +154,14 @@ def load_model():
     shared.state.begin()
     shared.state.job = 'load model'
     Thread(target=lambda: shared.sd_model).start()
+    # TODO delay load model
+    """
     if shared.sd_model is None:
         log.warning("No stable diffusion model loaded")
         # exit(1)
     else:
         shared.opts.data["sd_model_checkpoint"] = shared.sd_model.sd_checkpoint_info.title
+    """
     shared.opts.onchange("sd_model_checkpoint", wrap_queued_call(lambda: modules.sd_models.reload_model_weights()), call=False)
     shared.opts.onchange("sd_model_dict", wrap_queued_call(lambda: modules.sd_models.reload_model_weights()), call=False)
     shared.state.end()
@@ -205,7 +208,7 @@ def start_common():
 def start_ui():
     log.debug('Creating UI')
     modules.script_callbacks.before_ui_callback()
-    startup_timer.record("scripts before_ui_callback")
+    startup_timer.record("before-ui")
     shared.demo = modules.ui.create_ui()
     startup_timer.record("ui")
     if cmd_opts.disable_queue:
@@ -281,12 +284,12 @@ def start_ui():
     ui_extra_networks.add_pages_to_demo(app)
 
     modules.script_callbacks.app_started_callback(shared.demo, app)
-    startup_timer.record("scripts app_started_callback")
+    startup_timer.record("app-started")
 
-    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')
+    time_setup = [f'{k}:{round(v,3)}s' 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]
+    shared.log.debug(f'Scripts components: {time_component}')
 
 
 def webui():