debug ws executed message delay

execution.py

@@ -5,6 +5,7 @@ import logging
 import sys
 import threading
 import time
+import datetime
 import traceback
 from enum import Enum
 from typing import List, Literal, NamedTuple, Optional
@@ -290,6 +291,7 @@ def execute(server, dynprompt, caches, current_item, extra_data, executed, promp
     if caches.outputs.get(unique_id) is not None:
         if server.client_id is not None:
             cached_output = caches.ui.get(unique_id) or {}
+            print(datetime.datetime.now(), "send cached executed", prompt_id, unique_id, display_node_id, cached_output.get("output",None))
             server.send_sync("executed", { "node": unique_id, "display_node": display_node_id, "output": cached_output.get("output",None), "prompt_id": prompt_id }, server.client_id)
         return (ExecutionResult.SUCCESS, None, None)
 
@@ -370,6 +372,7 @@ def execute(server, dynprompt, caches, current_item, extra_data, executed, promp
                 "output": output_ui
             })
             if server.client_id is not None:
+                print(datetime.datetime.now(), "send executed", prompt_id, unique_id, display_node_id)
                 server.send_sync("executed", { "node": unique_id, "display_node": display_node_id, "output": output_ui, "prompt_id": prompt_id }, server.client_id)
         if has_subgraph:
             cached_outputs = []

main.py

@@ -5,6 +5,7 @@ import os
 import importlib.util
 import folder_paths
 import time
+import datetime
 from comfy.cli_args import args
 from app.logger import setup_logger
 import itertools
@@ -185,6 +186,7 @@ def prompt_worker(q, server_instance):
 
             current_time = time.perf_counter()
             execution_time = current_time - execution_start_time
+            print(datetime.datetime.now(), "execution_time", execution_time)
 
             # Log Time in a more readable way after 10 minutes
             if execution_time > 600:

server.py

@@ -2,6 +2,7 @@ import os
 import sys
 import asyncio
 import traceback
+import datetime
 
 import nodes
 import folder_paths
@@ -764,6 +765,8 @@ class PromptServer():
         return prompt_info
 
     async def send(self, event, data, sid=None):
+        if event == "executed":
+            print(datetime.datetime.now(), "server send ", event, data, sid)
         if event == BinaryEventTypes.UNENCODED_PREVIEW_IMAGE:
             await self.send_image(data, sid=sid)
         elif isinstance(data, (bytes, bytearray)):
@@ -825,6 +828,8 @@ class PromptServer():
             await send_socket_catch_exception(self.sockets[sid].send_json, message)
 
     def send_sync(self, event, data, sid=None):
+        if event == "executed":
+            print(datetime.datetime.now(), "send_sync", event, data, sid)
         self.loop.call_soon_threadsafe(
             self.messages.put_nowait, (event, data, sid))
 
@@ -834,6 +839,8 @@ class PromptServer():
     async def publish_loop(self):
         while True:
             msg = await self.messages.get()
+            if msg[0] == "executed":
+                print(datetime.datetime.now(), "publish_loop send ", msg)
             await self.send(*msg)
 
     async def start(self, address, port, verbose=True, call_on_start=None):