remove model load timeouts, add elapsed-time logging

This commit is contained in:
Roland Tannous 2026-03-19 18:08:03 +00:00
commit 799f239ce8
4 changed files with 62 additions and 22 deletions

View file

@ -1010,8 +1010,8 @@ class LlamaCppBackend:
self._is_vision = is_vision
self._model_identifier = model_identifier
# Wait for llama-server to become healthy
if not self._wait_for_health(timeout = 120.0):
# Wait for llama-server to become healthy (no timeout — let it take as long as needed)
if not self._wait_for_health():
self._kill_process()
raise RuntimeError(
"llama-server failed to start. "
@ -1129,39 +1129,49 @@ class LlamaCppBackend:
"""atexit handler to ensure llama-server is terminated."""
self._kill_process()
def _wait_for_health(self, timeout: float = 120.0, interval: float = 0.5) -> bool:
def _wait_for_health(self, interval: float = 0.5) -> bool:
"""
Poll llama-server's /health endpoint until it responds 200.
No timeout waits indefinitely so large models on slow hardware
(e.g. HF Spaces) have time to load. Logs elapsed time every 30s.
Also monitors subprocess for early exit/crash.
"""
deadline = time.monotonic() + timeout
start = time.monotonic()
last_log = start
url = f"http://127.0.0.1:{self._port}/health"
while time.monotonic() < deadline:
while True:
# Check if process crashed
if self._process.poll() is not None:
# Give the drain thread a moment to collect final output
if self._stdout_thread is not None:
self._stdout_thread.join(timeout = 2)
output = "\n".join(self._stdout_lines[-50:])
elapsed = time.monotonic() - start
logger.error(
f"llama-server exited with code {self._process.returncode}. "
f"Output: {output[:2000]}"
f"llama-server exited with code {self._process.returncode} "
f"after {elapsed:.1f}s. Output: {output[:2000]}"
)
return False
try:
resp = httpx.get(url, timeout = 2.0)
if resp.status_code == 200:
elapsed = time.monotonic() - start
logger.info(f"llama-server healthy after {elapsed:.1f}s")
return True
except (httpx.ConnectError, httpx.TimeoutException):
pass
time.sleep(interval)
# Periodic progress logging
now = time.monotonic()
if now - last_log >= 30.0:
elapsed = now - start
logger.info(f"Waiting for llama-server health check... {elapsed:.0f}s elapsed")
last_log = now
logger.error(f"llama-server health check timed out after {timeout}s")
return False
time.sleep(interval)
# ── Message building (OpenAI format) ──────────────────────────

View file

@ -262,28 +262,56 @@ class InferenceOrchestrator:
except (EOFError, OSError, ValueError):
return None
def _wait_response(self, expected_type: str, timeout: float = 120.0) -> dict:
def _wait_response(self, expected_type: str, timeout: Optional[float] = None) -> dict:
"""Block until a response of the expected type arrives.
Also handles 'status' and 'error' events during the wait.
Returns the matching response dict.
Raises RuntimeError on timeout or subprocess crash.
Raises RuntimeError on subprocess crash.
If timeout is None, waits indefinitely (logs progress every 30s).
"""
deadline = time.monotonic() + timeout
start = time.monotonic()
last_log = start
while time.monotonic() < deadline:
remaining = max(0.1, deadline - time.monotonic())
resp = self._read_resp(timeout = min(remaining, 1.0))
while True:
if timeout is not None:
remaining = timeout - (time.monotonic() - start)
if remaining <= 0:
raise RuntimeError(
f"Timeout waiting for '{expected_type}' response after {timeout}s"
)
poll_timeout = min(remaining, 1.0)
else:
poll_timeout = 1.0
resp = self._read_resp(timeout = poll_timeout)
if resp is None:
# Check subprocess health
if not self._ensure_subprocess_alive():
raise RuntimeError("Inference subprocess crashed during wait")
elapsed = time.monotonic() - start
raise RuntimeError(
f"Inference subprocess crashed during wait after {elapsed:.1f}s"
)
# Periodic progress logging
now = time.monotonic()
if now - last_log >= 30.0:
elapsed = now - start
logger.info(
"Waiting for '%s' response... %.0fs elapsed",
expected_type,
elapsed,
)
last_log = now
continue
rtype = resp.get("type", "")
if rtype == expected_type:
elapsed = time.monotonic() - start
logger.info(
"Received '%s' response after %.1fs", expected_type, elapsed
)
return resp
if rtype == "error":
@ -301,10 +329,6 @@ class InferenceOrchestrator:
expected_type,
)
raise RuntimeError(
f"Timeout waiting for '{expected_type}' response after {timeout}s"
)
def _drain_queue(self) -> list:
"""Drain all pending responses."""
events = []
@ -614,7 +638,7 @@ class InferenceOrchestrator:
needed_major,
)
self._spawn_subprocess(sub_config)
resp = self._wait_response("loaded", timeout = 180)
resp = self._wait_response("loaded")
# Update local state from response
if resp.get("success"):

View file

@ -156,6 +156,7 @@ def _handle_load(backend, config: dict, resp_queue: Any) -> None:
except Exception as e:
logger.warning("Could not read adapter_config.json: %s", e)
load_start = time.monotonic()
success = backend.load_model(
config = mc,
max_seq_length = config.get("max_seq_length", 2048),
@ -163,6 +164,8 @@ def _handle_load(backend, config: dict, resp_queue: Any) -> None:
hf_token = hf_token,
trust_remote_code = config.get("trust_remote_code", False),
)
load_elapsed = time.monotonic() - load_start
logger.info("Inference model load took %.1fs (success=%s)", load_elapsed, success)
if success:
# Build model_info for the parent to mirror

View file

@ -415,6 +415,7 @@ def run_training_process(
# ── 4c. Load training model (uses VRAM — dataset already formatted) ──
_send_status(event_queue, "Loading model...")
load_start = time.monotonic()
success = trainer.load_model(
model_name = model_name,
max_seq_length = config["max_seq_length"],
@ -425,6 +426,8 @@ def run_training_process(
is_dataset_audio = config.get("is_dataset_audio", False),
trust_remote_code = config.get("trust_remote_code", False),
)
load_elapsed = time.monotonic() - load_start
logger.info("Training model load took %.1fs (success=%s)", load_elapsed, success)
if not success or trainer.should_stop:
if trainer.should_stop:
event_queue.put(