@@ -584,6 +584,61 @@ def recv_json(sock: socket.socket, timeout: float = 30.0) -> dict:
584584 data_buffer .extend (chunk )
585585 return json .loads (data_buffer .decode ("utf-8" ))
586586
587+ # ────────────────────────────────────────────────────────────────────────
588+ # IPC DISPATCH PERFORMANCE LOGGER (active only when OMNIPKG_DEBUG=1)
589+ # One JSONL record per call -> /tmp/omnipkg/perf_<UTC_ts>.jsonl
590+ # ────────────────────────────────────────────────────────────────────────
591+ import datetime as _dt_mod
592+
593+ class DispatchPerfLogger :
594+ """
595+ Singleton perf logger. Activated by OMNIPKG_DEBUG=1.
596+
597+ Usage:
598+ _perf = DispatchPerfLogger.get()
599+ if _perf:
600+ _perf.record('client._send', spec='...', t_connect_ms=0.21, ...)
601+ """
602+
603+ _instance = None
604+ _log_path : str = ""
605+
606+ @classmethod
607+ def get (cls ):
608+ if os .environ .get ("OMNIPKG_DEBUG" ) != "1" :
609+ return None
610+ if cls ._instance is None :
611+ cls ._instance = cls ()
612+ return cls ._instance
613+
614+ def __init__ (self ):
615+ ts = _dt_mod .datetime .utcnow ().strftime ("%Y%m%dT%H%M%SZ" )
616+ log_dir = os .path .join (tempfile .gettempdir (), "omnipkg" )
617+ os .makedirs (log_dir , exist_ok = True )
618+ self ._path = os .path .join (log_dir , f"perf_{ ts } .jsonl" )
619+ DispatchPerfLogger ._log_path = self ._path
620+ self ._lock = threading .Lock ()
621+ header = json .dumps ({
622+ "_note" : "omnipkg IPC dispatch perf log" ,
623+ "_pid" : os .getpid (),
624+ "_started" : ts ,
625+ })
626+ with open (self ._path , "w" , encoding = "utf-8" ) as _f :
627+ _f .write (header + "\n " )
628+
629+ def record (self , site , ** fields ):
630+ """Append one JSONL record. Thread-safe, non-blocking."""
631+ rec = {"ts" : time .time (), "site" : site }
632+ rec .update (fields )
633+ line = json .dumps (rec , default = str ) + "\n "
634+ try :
635+ with self ._lock :
636+ with open (self ._path , "a" , encoding = "utf-8" ) as _f :
637+ _f .write (line )
638+ except Exception :
639+ pass # never crash on debug instrumentation
640+
641+
587642class UniversalGpuIpc :
588643 """
589644 Pure CUDA IPC using ctypes - works WITHOUT PyTorch!
@@ -3162,8 +3217,13 @@ def execute_shm_task(
31623217 safe_print (f" [DAEMON] Sending task { task_id } to worker (package_spec={ self .package_spec } )" , file = sys .stderr )
31633218 safe_print (f" [DAEMON] Command: { json .dumps (command )[:200 ]} ..." , file = sys .stderr )
31643219
3165- self .process .stdin .write (json .dumps (command ) + "\n " )
3220+ _est_t0 = time .perf_counter ()
3221+ _cmd_json = json .dumps (command )
3222+ _est_t_encoded = time .perf_counter ()
3223+
3224+ self .process .stdin .write (_cmd_json + "\n " )
31663225 self .process .stdin .flush ()
3226+ _est_t_flushed = time .perf_counter ()
31673227
31683228 safe_print (f" [DAEMON] Task sent, waiting for response (timeout={ timeout } s)..." , file = sys .stderr )
31693229
@@ -3178,6 +3238,19 @@ def execute_shm_task(
31783238 response_line = self .stdout_queue .get (timeout = timeout )
31793239 except queue .Empty :
31803240 response_line = None
3241+ _est_t_got = time .perf_counter ()
3242+ _est_perf = DispatchPerfLogger .get ()
3243+ if _est_perf :
3244+ _est_perf .record (
3245+ "worker.execute_shm_task" ,
3246+ spec = self .package_spec ,
3247+ task_id = task_id ,
3248+ payload_bytes = len (_cmd_json ),
3249+ t_encode_ms = (_est_t_encoded - _est_t0 ) * 1000 ,
3250+ t_write_flush_ms = (_est_t_flushed - _est_t_encoded ) * 1000 ,
3251+ t_queue_get_ms = (_est_t_got - _est_t_flushed ) * 1000 ,
3252+ total_ms = (_est_t_got - _est_t0 ) * 1000 ,
3253+ )
31813254
31823255 if not response_line :
31833256 safe_print (f" [DAEMON] No response received within { timeout } s" , file = sys .stderr )
@@ -4029,6 +4102,7 @@ def check_daemon_running(socket_path=None, daemon_port=5678):
40294102 def _handle_client (self , conn : socket .socket ):
40304103 """Handle client request with timeout protection."""
40314104 conn .settimeout (30.0 )
4105+ _hc_t0 = time .perf_counter ()
40324106 try :
40334107 # 1. Receive Request
40344108 try :
@@ -4037,6 +4111,7 @@ def _handle_client(self, conn: socket.socket):
40374111 # Client disconnected abruptly (common on Windows during teardown)
40384112 # Just return silently to avoid log noise.
40394113 return
4114+ _hc_t_recvd = time .perf_counter ()
40404115
40414116 self .stats ["total_requests" ] += 1
40424117
@@ -4217,11 +4292,24 @@ def _handle_client(self, conn: socket.socket):
42174292 res = {"success" : False , "error" : f"Unknown type: { req ['type' ]} " }
42184293
42194294 # 3. Send Response
4295+ _hc_t_dispatched = time .perf_counter ()
4296+ _perf = DispatchPerfLogger .get ()
42204297 try :
42214298 send_json (conn , res )
42224299 except (ConnectionResetError , BrokenPipeError ):
42234300 # Client disconnected before we could send response - ignore
42244301 pass
4302+ _hc_t_sent = time .perf_counter ()
4303+ if _perf :
4304+ _perf .record (
4305+ "daemon._handle_client" ,
4306+ req_type = req .get ("type" , "?" ),
4307+ spec = req .get ("spec" , "?" ),
4308+ t_recv_ms = (_hc_t_recvd - _hc_t0 ) * 1000 ,
4309+ t_dispatch_ms = (_hc_t_dispatched - _hc_t_recvd ) * 1000 ,
4310+ t_send_ms = (_hc_t_sent - _hc_t_dispatched ) * 1000 ,
4311+ total_ms = (_hc_t_sent - _hc_t0 ) * 1000 ,
4312+ )
42254313
42264314 except Exception as e :
42274315 # 4. Handle Actual Logic Errors (Log these!)
@@ -5337,7 +5425,9 @@ def _memory_manager(self):
53375425 Workers idle longer than ``max_idle_time`` are reaped.
53385426 """
53395427 while self .running :
5340- time .sleep (60 )
5428+ # 5s poll: fast enough for max_memory_mb to fire within a benchmark
5429+ # window. Was 60s which caused test 13 to appear stuck (never evicted).
5430+ time .sleep (5 )
53415431 now = time .time ()
53425432
53435433 try :
@@ -6566,18 +6656,37 @@ def _send(self, req):
65666656 while attempts < max_attempts :
65676657 attempts += 1
65686658 try :
6659+ _perf = DispatchPerfLogger .get ()
6660+ _t0 = time .perf_counter ()
6661+
65696662 # Get platform-appropriate connection info
65706663 sock_family , address = self ._get_connection_info ()
65716664
65726665 # Create and connect socket
65736666 sock = socket .socket (sock_family , socket .SOCK_STREAM )
65746667 sock .settimeout (self .timeout )
65756668 sock .connect (address )
6669+ _t_connected = time .perf_counter ()
65766670
65776671 # Send request and receive response
65786672 send_json (sock , req , timeout = self .timeout )
6673+ _t_sent = time .perf_counter ()
6674+
65796675 res = recv_json (sock , timeout = self .timeout )
6676+ _t_recvd = time .perf_counter ()
6677+
65806678 sock .close ()
6679+
6680+ if _perf :
6681+ _perf .record (
6682+ "client._send" ,
6683+ req_type = req .get ("type" , "?" ),
6684+ spec = req .get ("spec" , req .get ("type" , "?" )),
6685+ t_connect_ms = (_t_connected - _t0 ) * 1000 ,
6686+ t_send_ms = (_t_sent - _t_connected ) * 1000 ,
6687+ t_recv_ms = (_t_recvd - _t_sent ) * 1000 ,
6688+ total_ms = (_t_recvd - _t0 ) * 1000 ,
6689+ )
65816690 return res
65826691
65836692 except (ConnectionRefusedError , FileNotFoundError ):
0 commit comments