debug/logging clean-up

This commit is contained in:
John Pollock 2026-03-04 12:45:09 -06:00
parent 4ae6f77064
commit 8322f39219
4 changed files with 3 additions and 95 deletions

View File

@ -382,10 +382,6 @@ class ComfyNodeExtension(ExtensionBase):
if type(result).__name__ == "NodeOutput": if type(result).__name__ == "NodeOutput":
result = result.args result = result.args
print(
f"{LOG_PREFIX} ISO:child_result_ready node={node_name} type={type(result).__name__}",
flush=True,
)
if self._is_comfy_protocol_return(result): if self._is_comfy_protocol_return(result):
logger.debug( logger.debug(
"%s ISO:child_execute_done ext=%s node=%s protocol_return=1", "%s ISO:child_execute_done ext=%s node=%s protocol_return=1",
@ -393,17 +389,11 @@ class ComfyNodeExtension(ExtensionBase):
getattr(self, "name", "?"), getattr(self, "name", "?"),
node_name, node_name,
) )
print(f"{LOG_PREFIX} ISO:child_wrap_start node={node_name} protocol=1", flush=True)
wrapped = self._wrap_unpicklable_objects(result) wrapped = self._wrap_unpicklable_objects(result)
print(f"{LOG_PREFIX} ISO:child_wrap_done node={node_name} protocol=1", flush=True)
return wrapped return wrapped
if not isinstance(result, tuple): if not isinstance(result, tuple):
result = (result,) result = (result,)
print(
f"{LOG_PREFIX} ISO:child_result_tuple node={node_name} outputs={len(result)}",
flush=True,
)
logger.debug( logger.debug(
"%s ISO:child_execute_done ext=%s node=%s protocol_return=0 outputs=%d", "%s ISO:child_execute_done ext=%s node=%s protocol_return=0 outputs=%d",
LOG_PREFIX, LOG_PREFIX,
@ -411,9 +401,7 @@ class ComfyNodeExtension(ExtensionBase):
node_name, node_name,
len(result), len(result),
) )
print(f"{LOG_PREFIX} ISO:child_wrap_start node={node_name} protocol=0", flush=True)
wrapped = self._wrap_unpicklable_objects(result) wrapped = self._wrap_unpicklable_objects(result)
print(f"{LOG_PREFIX} ISO:child_wrap_done node={node_name} protocol=0", flush=True)
return wrapped return wrapped
async def flush_transport_state(self) -> int: async def flush_transport_state(self) -> int:

View File

@ -245,10 +245,8 @@ class ModelPatcherRegistry(BaseRegistry[Any]):
return False return False
async def get_model_object(self, instance_id: str, name: str) -> Any: async def get_model_object(self, instance_id: str, name: str) -> Any:
print(f"GP_DEBUG: get_model_object START for name={name}", flush=True)
instance = self._get_instance(instance_id) instance = self._get_instance(instance_id)
if name == "model": if name == "model":
print(f"GP_DEBUG: get_model_object END for name={name} (ModelObject)", flush=True)
return f"<ModelObject: {type(instance.model).__name__}>" return f"<ModelObject: {type(instance.model).__name__}>"
result = instance.get_model_object(name) result = instance.get_model_object(name)
if name == "model_sampling": if name == "model_sampling":
@ -264,10 +262,8 @@ class ModelPatcherRegistry(BaseRegistry[Any]):
sampling_id = result._instance_id sampling_id = result._instance_id
else: else:
sampling_id = registry.register(result) sampling_id = registry.register(result)
print(f"GP_DEBUG: get_model_object END for name={name} (model_sampling)", flush=True)
return ModelSamplingProxy(sampling_id, registry) return ModelSamplingProxy(sampling_id, registry)
print(f"GP_DEBUG: get_model_object END for name={name} (fallthrough)", flush=True)
return detach_if_grad(result) return detach_if_grad(result)
async def get_model_options(self, instance_id: str) -> dict: async def get_model_options(self, instance_id: str) -> dict:

View File

@ -233,18 +233,8 @@ class ModelSamplingProxy(BaseProxy[ModelSamplingRegistry]):
return self._rpc_caller return self._rpc_caller
def _call(self, method_name: str, *args: Any) -> Any: def _call(self, method_name: str, *args: Any) -> Any:
print(
"ISO:modelsampling_call_enter method=%s instance_id=%s pid=%s"
% (method_name, self._instance_id, os.getpid()),
flush=True,
)
rpc = self._get_rpc() rpc = self._get_rpc()
method = getattr(rpc, method_name) method = getattr(rpc, method_name)
print(
"ISO:modelsampling_call_before_dispatch method=%s instance_id=%s pid=%s"
% (method_name, self._instance_id, os.getpid()),
flush=True,
)
result = method(self._instance_id, *args) result = method(self._instance_id, *args)
timeout_ms = self._rpc_timeout_ms() timeout_ms = self._rpc_timeout_ms()
start_epoch = time.time() start_epoch = time.time()
@ -275,11 +265,6 @@ class ModelSamplingProxy(BaseProxy[ModelSamplingRegistry]):
out = loop.run_until_complete(result) out = loop.run_until_complete(result)
else: else:
out = result out = result
print(
"ISO:modelsampling_call_after_dispatch method=%s instance_id=%s pid=%s"
% (method_name, self._instance_id, os.getpid()),
flush=True,
)
logger.debug( logger.debug(
"ISO:modelsampling_rpc_after_await method=%s instance_id=%s call_id=%s out=%s", "ISO:modelsampling_rpc_after_await method=%s instance_id=%s call_id=%s out=%s",
method_name, method_name,
@ -302,11 +287,6 @@ class ModelSamplingProxy(BaseProxy[ModelSamplingRegistry]):
self._instance_id, self._instance_id,
call_id, call_id,
) )
print(
"ISO:modelsampling_call_return method=%s instance_id=%s pid=%s"
% (method_name, self._instance_id, os.getpid()),
flush=True,
)
return out return out
@staticmethod @staticmethod

View File

@ -208,18 +208,14 @@ def calc_cond_batch(model: BaseModel, conds: list[list[dict]], x_in: torch.Tenso
return handler.execute(_calc_cond_batch_outer, model, conds, x_in, timestep, model_options) return handler.execute(_calc_cond_batch_outer, model, conds, x_in, timestep, model_options)
def _calc_cond_batch_outer(model: BaseModel, conds: list[list[dict]], x_in: torch.Tensor, timestep, model_options): def _calc_cond_batch_outer(model: BaseModel, conds: list[list[dict]], x_in: torch.Tensor, timestep, model_options):
print("CC_DEBUG2: enter _calc_cond_batch_outer", flush=True)
executor = comfy.patcher_extension.WrapperExecutor.new_executor( executor = comfy.patcher_extension.WrapperExecutor.new_executor(
_calc_cond_batch, _calc_cond_batch,
comfy.patcher_extension.get_all_wrappers(comfy.patcher_extension.WrappersMP.CALC_COND_BATCH, model_options, is_model_options=True) comfy.patcher_extension.get_all_wrappers(comfy.patcher_extension.WrappersMP.CALC_COND_BATCH, model_options, is_model_options=True)
) )
print("CC_DEBUG2: before _calc_cond_batch executor.execute", flush=True)
result = executor.execute(model, conds, x_in, timestep, model_options) result = executor.execute(model, conds, x_in, timestep, model_options)
print("CC_DEBUG2: after _calc_cond_batch executor.execute", flush=True)
return result return result
def _calc_cond_batch(model: BaseModel, conds: list[list[dict]], x_in: torch.Tensor, timestep, model_options): def _calc_cond_batch(model: BaseModel, conds: list[list[dict]], x_in: torch.Tensor, timestep, model_options):
print("CC_DEBUG2: enter _calc_cond_batch", flush=True)
isolation_active = args.use_process_isolation or os.environ.get("PYISOLATE_ISOLATION_ACTIVE") == "1" isolation_active = args.use_process_isolation or os.environ.get("PYISOLATE_ISOLATION_ACTIVE") == "1"
out_conds = [] out_conds = []
out_counts = [] out_counts = []
@ -252,9 +248,7 @@ def _calc_cond_batch(model: BaseModel, conds: list[list[dict]], x_in: torch.Tens
if has_default_conds: if has_default_conds:
finalize_default_conds(model, hooked_to_run, default_conds, x_in, timestep, model_options) finalize_default_conds(model, hooked_to_run, default_conds, x_in, timestep, model_options)
print("CC_DEBUG: before prepare_state", flush=True)
model.current_patcher.prepare_state(timestep) model.current_patcher.prepare_state(timestep)
print("CC_DEBUG: after prepare_state", flush=True)
# run every hooked_to_run separately # run every hooked_to_run separately
for hooks, to_run in hooked_to_run.items(): for hooks, to_run in hooked_to_run.items():
@ -269,9 +263,7 @@ def _calc_cond_batch(model: BaseModel, conds: list[list[dict]], x_in: torch.Tens
to_batch_temp.reverse() to_batch_temp.reverse()
to_batch = to_batch_temp[:1] to_batch = to_batch_temp[:1]
print("CC_DEBUG: before get_free_memory", flush=True)
free_memory = model.current_patcher.get_free_memory(x_in.device) free_memory = model.current_patcher.get_free_memory(x_in.device)
print("CC_DEBUG: after get_free_memory", flush=True)
for i in range(1, len(to_batch_temp) + 1): for i in range(1, len(to_batch_temp) + 1):
batch_amount = to_batch_temp[:len(to_batch_temp)//i] batch_amount = to_batch_temp[:len(to_batch_temp)//i]
input_shape = [len(batch_amount) * first_shape[0]] + list(first_shape)[1:] input_shape = [len(batch_amount) * first_shape[0]] + list(first_shape)[1:]
@ -281,9 +273,7 @@ def _calc_cond_batch(model: BaseModel, conds: list[list[dict]], x_in: torch.Tens
for k, v in to_run[tt][0].conditioning.items(): for k, v in to_run[tt][0].conditioning.items():
cond_shapes[k].append(v.size()) cond_shapes[k].append(v.size())
print("CC_DEBUG: before memory_required", flush=True)
memory_required = model.memory_required(input_shape, cond_shapes=cond_shapes) memory_required = model.memory_required(input_shape, cond_shapes=cond_shapes)
print("CC_DEBUG: after memory_required", flush=True)
if memory_required * 1.5 < free_memory: if memory_required * 1.5 < free_memory:
to_batch = batch_amount to_batch = batch_amount
break break
@ -321,9 +311,7 @@ def _calc_cond_batch(model: BaseModel, conds: list[list[dict]], x_in: torch.Tens
else: else:
timestep_ = torch.cat([timestep] * batch_chunks) timestep_ = torch.cat([timestep] * batch_chunks)
print("CC_DEBUG: before apply_hooks", flush=True)
transformer_options = model.current_patcher.apply_hooks(hooks=hooks) transformer_options = model.current_patcher.apply_hooks(hooks=hooks)
print("CC_DEBUG: after apply_hooks", flush=True)
if 'transformer_options' in model_options: if 'transformer_options' in model_options:
transformer_options = comfy.patcher_extension.merge_nested_dicts(transformer_options, transformer_options = comfy.patcher_extension.merge_nested_dicts(transformer_options,
model_options['transformer_options'], model_options['transformer_options'],
@ -345,13 +333,9 @@ def _calc_cond_batch(model: BaseModel, conds: list[list[dict]], x_in: torch.Tens
c['control'] = control.get_control(input_x, timestep_, c, len(cond_or_uncond), transformer_options) c['control'] = control.get_control(input_x, timestep_, c, len(cond_or_uncond), transformer_options)
if 'model_function_wrapper' in model_options: if 'model_function_wrapper' in model_options:
print("CC_DEBUG: before apply_model", flush=True)
output = model_options['model_function_wrapper'](model.apply_model, {"input": input_x, "timestep": timestep_, "c": c, "cond_or_uncond": cond_or_uncond}).chunk(batch_chunks) output = model_options['model_function_wrapper'](model.apply_model, {"input": input_x, "timestep": timestep_, "c": c, "cond_or_uncond": cond_or_uncond}).chunk(batch_chunks)
print("CC_DEBUG: after apply_model", flush=True)
else: else:
print("CC_DEBUG: before apply_model", flush=True)
output = model.apply_model(input_x, timestep_, **c).chunk(batch_chunks) output = model.apply_model(input_x, timestep_, **c).chunk(batch_chunks)
print("CC_DEBUG: after apply_model", flush=True)
for o in range(batch_chunks): for o in range(batch_chunks):
cond_index = cond_or_uncond[o] cond_index = cond_or_uncond[o]
@ -786,7 +770,6 @@ class KSAMPLER(Sampler):
self.inpaint_options = inpaint_options self.inpaint_options = inpaint_options
def sample(self, model_wrap, sigmas, extra_args, callback, noise, latent_image=None, denoise_mask=None, disable_pbar=False): def sample(self, model_wrap, sigmas, extra_args, callback, noise, latent_image=None, denoise_mask=None, disable_pbar=False):
print("CC_DEBUG3: enter KSAMPLER.sample", flush=True)
extra_args["denoise_mask"] = denoise_mask extra_args["denoise_mask"] = denoise_mask
model_k = KSamplerX0Inpaint(model_wrap, sigmas) model_k = KSamplerX0Inpaint(model_wrap, sigmas)
model_k.latent_image = latent_image model_k.latent_image = latent_image
@ -796,46 +779,19 @@ class KSAMPLER(Sampler):
else: else:
model_k.noise = noise model_k.noise = noise
print("CC_DEBUG3: before max_denoise", flush=True)
max_denoise = self.max_denoise(model_wrap, sigmas) max_denoise = self.max_denoise(model_wrap, sigmas)
print("CC_DEBUG3: after max_denoise", flush=True)
print("CC_DEBUG3: before model_sampling_attr", flush=True)
model_sampling = model_wrap.inner_model.model_sampling model_sampling = model_wrap.inner_model.model_sampling
print( noise = model_sampling.noise_scaling(
"CC_DEBUG3: after model_sampling_attr type=%s id=%s instance_id=%s" sigmas[0], noise, latent_image, max_denoise
% (
type(model_sampling).__name__,
id(model_sampling),
getattr(model_sampling, "_instance_id", "n/a"),
),
flush=True,
) )
print("CC_DEBUG3: before noise_scaling_call", flush=True)
try:
noise_scaled = model_sampling.noise_scaling(
sigmas[0], noise, latent_image, max_denoise
)
print("CC_DEBUG3: after noise_scaling_call", flush=True)
except Exception as e:
print(
"CC_DEBUG3: noise_scaling_exception type=%s msg=%s"
% (type(e).__name__, str(e)),
flush=True,
)
raise
noise = noise_scaled
print("CC_DEBUG3: after noise_assignment", flush=True)
k_callback = None k_callback = None
total_steps = len(sigmas) - 1 total_steps = len(sigmas) - 1
if callback is not None: if callback is not None:
k_callback = lambda x: callback(x["i"], x["denoised"], x["x"], total_steps) k_callback = lambda x: callback(x["i"], x["denoised"], x["x"], total_steps)
print("CC_DEBUG3: before sampler_function", flush=True)
samples = self.sampler_function(model_k, noise, sigmas, extra_args=extra_args, callback=k_callback, disable=disable_pbar, **self.extra_options) samples = self.sampler_function(model_k, noise, sigmas, extra_args=extra_args, callback=k_callback, disable=disable_pbar, **self.extra_options)
print("CC_DEBUG3: after sampler_function", flush=True)
samples = model_wrap.inner_model.model_sampling.inverse_noise_scaling(sigmas[-1], samples) samples = model_wrap.inner_model.model_sampling.inverse_noise_scaling(sigmas[-1], samples)
print("CC_DEBUG3: after inverse_noise_scaling", flush=True)
return samples return samples
@ -875,16 +831,10 @@ def process_conds(model, noise, conds, device, latent_image=None, denoise_mask=N
for k in conds: for k in conds:
calculate_start_end_timesteps(model, conds[k]) calculate_start_end_timesteps(model, conds[k])
print('GP_DEBUG: before hasattr extra_conds', flush=True)
print('GP_DEBUG: before hasattr extra_conds', flush=True)
if hasattr(model, 'extra_conds'): if hasattr(model, 'extra_conds'):
print('GP_DEBUG: has extra_conds!', flush=True)
print('GP_DEBUG: has extra_conds!', flush=True)
for k in conds: for k in conds:
conds[k] = encode_model_conds(model.extra_conds, conds[k], noise, device, k, latent_image=latent_image, denoise_mask=denoise_mask, seed=seed, latent_shapes=latent_shapes) conds[k] = encode_model_conds(model.extra_conds, conds[k], noise, device, k, latent_image=latent_image, denoise_mask=denoise_mask, seed=seed, latent_shapes=latent_shapes)
print('GP_DEBUG: before area make sure loop', flush=True)
print('GP_DEBUG: before area make sure loop', flush=True)
#make sure each cond area has an opposite one with the same area #make sure each cond area has an opposite one with the same area
for k in conds: for k in conds:
for c in conds[k]: for c in conds[k]:
@ -898,11 +848,8 @@ def process_conds(model, noise, conds, device, latent_image=None, denoise_mask=N
for hook in c['hooks'].hooks: for hook in c['hooks'].hooks:
hook.initialize_timesteps(model) hook.initialize_timesteps(model)
print('GP_DEBUG: before pre_run_control loop', flush=True)
for k in conds: for k in conds:
print('GP_DEBUG: calling pre_run_control for key:', k, flush=True)
pre_run_control(model, conds[k]) pre_run_control(model, conds[k])
print('GP_DEBUG: after pre_run_control loop', flush=True)
if "positive" in conds: if "positive" in conds:
positive = conds["positive"] positive = conds["positive"]
@ -1064,8 +1011,6 @@ class CFGGuider:
self.conds = process_conds(self.inner_model, noise, self.conds, device, latent_image, denoise_mask, seed, latent_shapes=latent_shapes) self.conds = process_conds(self.inner_model, noise, self.conds, device, latent_image, denoise_mask, seed, latent_shapes=latent_shapes)
print("GP_DEBUG: process_conds finished", flush=True)
print("GP_DEBUG: process_conds finished", flush=True)
extra_model_options = comfy.model_patcher.create_model_options_clone(self.model_options) extra_model_options = comfy.model_patcher.create_model_options_clone(self.model_options)
extra_model_options.setdefault("transformer_options", {})["sample_sigmas"] = sigmas extra_model_options.setdefault("transformer_options", {})["sample_sigmas"] = sigmas
extra_args = {"model_options": extra_model_options, "seed": seed} extra_args = {"model_options": extra_model_options, "seed": seed}
@ -1075,7 +1020,6 @@ class CFGGuider:
sampler, sampler,
comfy.patcher_extension.get_all_wrappers(comfy.patcher_extension.WrappersMP.SAMPLER_SAMPLE, extra_args["model_options"], is_model_options=True) comfy.patcher_extension.get_all_wrappers(comfy.patcher_extension.WrappersMP.SAMPLER_SAMPLE, extra_args["model_options"], is_model_options=True)
) )
print("GP_DEBUG: before executor.execute", flush=True)
samples = executor.execute(self, sigmas, extra_args, callback, noise, latent_image, denoise_mask, disable_pbar) samples = executor.execute(self, sigmas, extra_args, callback, noise, latent_image, denoise_mask, disable_pbar)
return self.inner_model.process_latent_out(samples.to(torch.float32)) return self.inner_model.process_latent_out(samples.to(torch.float32))