From 54eaf95fc43939582aeb9b7b447b5b4649684783 Mon Sep 17 00:00:00 2001
From: tiennm99 <tiennm99@outlook.com>
Date: Thu, 23 Apr 2026 11:22:06 +0700
Subject: [PATCH] feat: progress logging during model download/parse
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

'Waiting for application startup.' was the last line visible for
several minutes while the lifespan hook silently downloaded 1.2GB and
parsed the text vectors — looks like a hang.

- Print milestones for each load phase (cache hit / download /
  extract / parse / cache-write) with timings.
- During download, print every ~50 MiB with running percent if the
  server sent Content-Length.
- PYTHONUNBUFFERED=1 in Dockerfile so the prints flush to
  'docker compose logs' in real time.

Uses plain print (not logging) because uvicorn's default log config
filters INFO on non-uvicorn loggers, and wrestling with that for six
operator-facing status lines isn't worth the surface area.
---
 Dockerfile     |  3 ++-
 app/vectors.py | 39 +++++++++++++++++++++++++++++++++++++--
 2 files changed, 39 insertions(+), 3 deletions(-)

diff --git a/Dockerfile b/Dockerfile
index 3459e5f..f681eab 100644
--- a/Dockerfile
+++ b/Dockerfile
@@ -16,7 +16,8 @@ COPY app ./app
 # PhoW2V's license forbids public redistribution, so every deployment
 # must point at its own private mirror (typically Nextcloud WebDAV).
 ENV MODEL_PATH=/data/phow2v/word2vec_vi_words_300dims.txt \
-    PORT=8000
+    PORT=8000 \
+    PYTHONUNBUFFERED=1
 
 EXPOSE 8000
 
diff --git a/app/vectors.py b/app/vectors.py
index 782de10..b655add 100644
--- a/app/vectors.py
+++ b/app/vectors.py
@@ -22,6 +22,8 @@ from __future__ import annotations
 
 import os
 import random as _random
+import sys
+import time
 import unicodedata
 import urllib.request
 import zipfile
@@ -32,6 +34,14 @@ from gensim.models import KeyedVectors
 
 _MODEL: Optional[KeyedVectors] = None
 _DOWNLOAD_CHUNK = 1 << 20  # 1 MiB; keeps peak RAM flat for ~1GB downloads.
+_LOG_EVERY_MB = 50  # Print a progress line every ~50 MiB so the operator knows it's alive.
+
+
+def _log(msg: str) -> None:
+    """Uvicorn doesn't surface our logger at INFO by default, and the lifespan
+    runs before any log config the operator might add — print with flush so
+    'docker compose logs' shows progress in real time."""
+    print(f"[phow2sim] {msg}", file=sys.stdout, flush=True)
 
 
 def _download_and_extract(url: str, target_txt: Path) -> None:
@@ -39,13 +49,29 @@ def _download_and_extract(url: str, target_txt: Path) -> None:
     target_txt.parent.mkdir(parents=True, exist_ok=True)
     zip_path = target_txt.with_suffix(".zip")
 
+    _log(f"downloading model zip from {url}")
+    t0 = time.monotonic()
     with urllib.request.urlopen(url) as resp, open(zip_path, "wb") as dst:
+        total = int(resp.headers.get("Content-Length") or 0)
+        total_mb = total / (1 << 20) if total else 0.0
+        downloaded = 0
+        next_log = _LOG_EVERY_MB << 20
         while True:
             chunk = resp.read(_DOWNLOAD_CHUNK)
             if not chunk:
                 break
             dst.write(chunk)
+            downloaded += len(chunk)
+            if downloaded >= next_log:
+                mb = downloaded / (1 << 20)
+                if total_mb:
+                    _log(f"  downloaded {mb:.0f} / {total_mb:.0f} MiB ({downloaded * 100.0 / total:.0f}%)")
+                else:
+                    _log(f"  downloaded {mb:.0f} MiB")
+                next_log += _LOG_EVERY_MB << 20
+    _log(f"download complete in {time.monotonic() - t0:.1f}s ({downloaded / (1 << 20):.0f} MiB)")
 
+    _log(f"extracting .txt from {zip_path.name}")
     with zipfile.ZipFile(zip_path) as zf:
         txt_members = [m for m in zf.namelist() if m.endswith(".txt")]
         if not txt_members:
@@ -58,6 +84,7 @@ def _download_and_extract(url: str, target_txt: Path) -> None:
                     break
                 dst.write(chunk)
     zip_path.unlink(missing_ok=True)
+    _log(f"extracted to {target_txt}")
 
 
 def load_model() -> KeyedVectors:
@@ -71,7 +98,10 @@ def load_model() -> KeyedVectors:
 
     # Prefer the cached binary form for ~5x faster cold start.
     if bin_cache.exists():
+        _log(f"loading cached binary vectors from {bin_cache}")
+        t0 = time.monotonic()
         _MODEL = KeyedVectors.load_word2vec_format(str(bin_cache), binary=True)
+        _log(f"loaded {len(_MODEL)} keys in {time.monotonic() - t0:.1f}s")
         return _MODEL
 
     if not txt_path.exists():
@@ -83,12 +113,17 @@ def load_model() -> KeyedVectors:
             )
         _download_and_extract(url, txt_path)
 
+    _log(f"parsing text-format vectors from {txt_path} (typically ~60s for word-300d)")
+    t0 = time.monotonic()
     _MODEL = KeyedVectors.load_word2vec_format(str(txt_path), binary=False)
+    _log(f"parsed {len(_MODEL)} keys in {time.monotonic() - t0:.1f}s")
+
     # Persist the fast-load cache next to the source .txt.
     try:
+        _log(f"writing binary cache to {bin_cache} for faster future starts")
         _MODEL.save_word2vec_format(str(bin_cache), binary=True)
-    except OSError:
-        pass  # Read-only volume is fine; we'll just pay the txt-parse cost again.
+    except OSError as e:
+        _log(f"warning: could not write binary cache ({e}); will re-parse .txt next time")
     return _MODEL