Merge pull request #60 from bob798/claude/performance-investigation-cXVqZ

fix+observability: 修复部署失败 + 日志落盘 + explain 全链路打点

Author: bob798

.dockerignore

@@ -20,7 +20,6 @@ tests/
 docs/
 *.md
 !requirements.txt
-fly.toml
 docker-compose*.yml
 .env*
 !.env.example

.gitignore

@@ -17,6 +17,9 @@ dist/
 static/tts_cache/
 static/audio_cache/
 
+# 应用日志（容器挂载到 /app/logs · 本地 dev 时写到 ./logs/）
+logs/
+
 # OMC runtime state (HUD cache, session state, logs, notepad, project memory)
 .omc/state/
 .omc/logs/

.omc/plans/lightweight-deployment.md

@@ -125,9 +125,9 @@ yt-dlp==<pinned>
 | Step | Action | Detail | Acceptance Criteria |
 |---|---|---|---|
 | 3.1 | Update base to `python:3.12-slim` | Match development environment Python version (3.12). | Dockerfile FROM line updated |
-| 3.2 | Review and update existing `.dockerignore` | `.dockerignore` already exists. Verify it excludes: `fly.toml`, `venv/`, `__pycache__/`, `*.db*`, `.git/`, `tests/`, `docs/`, `.omc/`, `*.md`. Add `fly.toml` if missing. | `docker build` context is <5MB |
+| 3.2 | Review and update existing `.dockerignore` | `.dockerignore` already exists. Verify it excludes: `venv/`, `__pycache__/`, `*.db*`, `.git/`, `tests/`, `docs/`, `.omc/`, `*.md`. | `docker build` context is <5MB |
 | 3.3 | Optimize layer ordering | Copy `requirements.txt` first, `pip install`, then copy app code. (Already done in current Dockerfile — verify preserved.) | Layer cache hits on code-only changes |
-| 3.4 | Remove Fly.io-specific ENV | Remove `ENV SPEAKEASY_DB_PATH=/data/speakeasy.db` from Dockerfile (line 19). Move to docker-compose env. | Dockerfile has no hardcoded paths |
+| 3.4 | Remove legacy hardcoded ENV | Remove `ENV SPEAKEASY_DB_PATH=/data/speakeasy.db` from Dockerfile (line 19). Move to docker-compose env. | Dockerfile has no hardcoded paths |
 | 3.5 | Build and measure | `docker build -t speakeasy:slim .` then `docker images speakeasy:slim` | Image size < 300MB |
 | 3.6 | Smoke test the image | `docker run --rm -p 8000:8000 speakeasy:slim` and `curl http://localhost:8000/` | Returns HTML (index.html) |
 | 3.7 | Fallback if >300MB | If image exceeds 300MB, investigate `yt-dlp` transitive deps (`certifi`, `brotli`, `mutagen`, `pycryptodomex`, `websockets`). Consider `--no-deps` with explicit sub-deps. | Image under target or deviation documented |
@@ -152,7 +152,7 @@ yt-dlp==<pinned>
 | 4.3 | Create `.env.production.example` | Template with all required vars: `DOMAIN`, `MODEL_PROVIDER=volcengine`, `VOLCENGINE_API_KEY`, `GROQ_API_KEY`, `SPEAKEASY_DB_PATH=/data/speakeasy.db`. | File exists, no real secrets committed |
 | 4.4 | Create `.github/workflows/deploy.yml` | Trigger on push to `main`. Steps: checkout → login GHCR → build+push image → SSH to VPS → `docker compose pull && docker compose up -d`. | YAML validates |
 | 4.5 | Update `.gitignore` | Add `.env.production`, verify `speakeasy.db*`, `static/tts_cache/*`, `static/audio_cache/*` are excluded | Sensitive files excluded |
-| 4.6 | Add `fly.toml` legacy comment | Add comment at top: `# LEGACY: Fly.io config, replaced by docker-compose. Remove in future PR.` | Comment added |
+| 4.6 | ~~Add `fly.toml` legacy comment~~ | DONE — `fly.toml` 已彻底移除（仓库不再保留 Fly.io 配置）。 | n/a |
 | 4.7 | Write deployment README section | Setup instructions: clone, copy `.env.production.example`, `docker compose up -d`. Include rollback: `docker compose pull <previous-tag> && docker compose up -d`. | Instructions copy-pasteable on Ubuntu 22.04+ with Docker |
 
 **docker-compose.yml structure:**
@@ -258,7 +258,7 @@ networks:
   - Build on VPS: rejected — requires build tooling on VPS; GHCR approach means VPS only needs Docker
 - **Why chosen:** Caddy eliminates TLS ops entirely. GitHub Actions + GHCR is free and avoids build tooling on VPS. Slim base avoids musl wheel compilation failures.
 - **Consequences:** Caddy adds ~40MB to the stack (acceptable). GitHub Actions creates vendor dependency (mitigated: workflow is portable to any CI with SSH). GHCR requires VPS to have network access to ghcr.io.
-- **Follow-ups:** Evaluate `fly.toml` full removal in a future PR. Consider SQLite backup strategy for production.
+- **Follow-ups:** ~~Evaluate `fly.toml` full removal in a future PR.~~ DONE. Consider SQLite backup strategy for production.
 
 ---
 

.omc/specs/deep-interview-lightweight-deployment.md

@@ -69,7 +69,7 @@
 - **STT**: Groq Whisper-large-v3
 - **TTS**: Edge-TTS (primary) + OpenAI TTS (fallback)
 - **VAD**: Silero VAD (PyTorch) — **TO BE REMOVED**
-- **Deployment**: Fly.io (fly.toml) — **TO BE REPLACED**
+- **Deployment**: VPS + docker-compose + Caddy（原 Fly.io 已迁出，`fly.toml` 已移除）
 
 ### 需要修改的文件
 - `app/services/vad_service.py` — 删除

Dockerfile

@@ -35,8 +35,8 @@ ENV APP_VERSION="${APP_VERSION}"
 # 用 Stage 1 构建好的 dist 覆盖 frontend/dist
 COPY --from=frontend-build /build/dist ./frontend/dist
 
-# 数据目录（挂载 volume 也行 · 这里兜底）
-RUN mkdir -p static/tts_cache static/audio_cache
+# 数据 / 日志目录（挂载 volume 也行 · 这里兜底，确保未挂卷的镜像也能直接跑）
+RUN mkdir -p static/tts_cache static/audio_cache /app/logs /app/data
 
 EXPOSE 8000
 

app/logger.py

@@ -1,12 +1,30 @@
 import logging
 import os
+import pathlib
 from contextvars import ContextVar
+from logging.handlers import RotatingFileHandler
+from typing import Optional
 
 # 通过 contextvars 在异步环境中安全传递 request_id
 request_id_var: ContextVar[str] = ContextVar("request_id", default="-")
 
 LOG_LEVEL: str = os.getenv("LOG_LEVEL", "INFO").upper()
 
+# 文件日志配置（VPS 部署后线上需要持久日志）
+# - LOG_TO_FILE  : 是否写文件，"0"/"false" 关闭（默认开）
+# - LOG_DIR      : 日志目录，默认 "logs"（docker-compose 里挂载到 /app/logs）
+# - LOG_FILE     : 文件名，默认 "app.log"
+# - LOG_FILE_MAX_BYTES   : 单文件上限，默认 10 MB
+# - LOG_FILE_BACKUP_COUNT: 保留轮转份数，默认 5
+LOG_TO_FILE: bool = os.getenv("LOG_TO_FILE", "1").lower() not in {"0", "false", "no"}
+LOG_DIR: str = os.getenv("LOG_DIR", "logs")
+LOG_FILE: str = os.getenv("LOG_FILE", "app.log")
+LOG_FILE_MAX_BYTES: int = int(os.getenv("LOG_FILE_MAX_BYTES", str(10 * 1024 * 1024)))
+LOG_FILE_BACKUP_COUNT: int = int(os.getenv("LOG_FILE_BACKUP_COUNT", "5"))
+
+_FMT = "%(asctime)s | %(levelname)-5s | %(name)s | [%(request_id)s] %(message)s"
+_DATEFMT = "%Y-%m-%d %H:%M:%S"
+
 
 class _RequestIdFormatter(logging.Formatter):
     """在每条日志里自动注入当前请求的 request_id"""
@@ -16,16 +34,49 @@ def format(self, record: logging.LogRecord) -> str:
         return super().format(record)
 
 
+_formatter = _RequestIdFormatter(_FMT, datefmt=_DATEFMT)
+_file_handler: Optional[logging.Handler] = None
+_file_handler_attempted = False
+
+
+def _build_file_handler() -> Optional[logging.Handler]:
+    """惰性初始化共享的文件 handler；目录创建失败时降级为 None 不阻断启动"""
+    global _file_handler, _file_handler_attempted
+    if _file_handler_attempted:
+        return _file_handler
+    _file_handler_attempted = True
+    if not LOG_TO_FILE:
+        return None
+    try:
+        log_dir = pathlib.Path(LOG_DIR)
+        log_dir.mkdir(parents=True, exist_ok=True)
+        handler = RotatingFileHandler(
+            log_dir / LOG_FILE,
+            maxBytes=LOG_FILE_MAX_BYTES,
+            backupCount=LOG_FILE_BACKUP_COUNT,
+            encoding="utf-8",
+        )
+        handler.setFormatter(_formatter)
+        _file_handler = handler
+    except OSError as e:
+        # 容器/VPS 上偶发目录不可写时不要让应用起不来，记一行到 stderr 后降级到仅 stdout
+        logging.getLogger(__name__).warning(
+            "无法创建日志文件 %s/%s（%s）；仅输出到 stdout", LOG_DIR, LOG_FILE, e
+        )
+        _file_handler = None
+    return _file_handler
+
+
 def get_logger(name: str) -> logging.Logger:
     """返回已配置好格式和级别的 logger，避免重复添加 handler"""
     logger = logging.getLogger(name)
     if not logger.handlers:
-        handler = logging.StreamHandler()
-        fmt = "%(asctime)s | %(levelname)-5s | %(name)s | [%(request_id)s] %(message)s"
-        handler.setFormatter(
-            _RequestIdFormatter(fmt, datefmt="%Y-%m-%d %H:%M:%S")
-        )
-        logger.addHandler(handler)
+        stream_handler = logging.StreamHandler()
+        stream_handler.setFormatter(_formatter)
+        logger.addHandler(stream_handler)
+        file_handler = _build_file_handler()
+        if file_handler is not None:
+            logger.addHandler(file_handler)
     logger.setLevel(LOG_LEVEL)
     logger.propagate = False
     return logger

app/services/explain_service.py

@@ -77,14 +77,16 @@ def _normalize_level(level: Optional[str]) -> str:
 
 
 def _get_user_level(user_id: str) -> str:
+    t0 = time.time()
     with OrmSession(engine) as s:
         row = s.query(UserProfile).filter_by(user_id=user_id).first()
-        if row and row.cefr_level:
-            return _normalize_level(row.cefr_level)
-    return ""
+        level = _normalize_level(row.cefr_level) if row and row.cefr_level else ""
+    logger.debug("user_level 查询 user=%s level=%r 耗时=%.3fs", user_id[:8], level, time.time() - t0)
+    return level
 
 
 def _cache_get(text: str, kind: str, cefr_level: str) -> Optional[Dict]:
+    t0 = time.time()
     h = _hash_text(text)
     with OrmSession(engine) as s:
         row = (
@@ -96,13 +98,24 @@ def _cache_get(text: str, kind: str, cefr_level: str) -> Optional[Dict]:
             row.hit_count = (row.hit_count or 0) + 1
             s.commit()
             try:
-                return json.loads(row.explanation)
+                data = json.loads(row.explanation)
+                logger.info(
+                    "cache_get HIT kind=%s level=%s hit_count=%d 耗时=%.3fs",
+                    kind, cefr_level, row.hit_count, time.time() - t0,
+                )
+                return data
             except json.JSONDecodeError:
+                logger.warning(
+                    "cache_get 命中但 JSON 解析失败 kind=%s level=%s 耗时=%.3fs",
+                    kind, cefr_level, time.time() - t0,
+                )
                 return None
+    logger.info("cache_get MISS kind=%s level=%s 耗时=%.3fs", kind, cefr_level, time.time() - t0)
     return None
 
 
 def _cache_set(text: str, kind: str, cefr_level: str, explanation: Dict, overwrite: bool = False) -> None:
+    t0 = time.time()
     h = _hash_text(text)
     with OrmSession(engine) as s:
         existing = (
@@ -116,6 +129,9 @@ def _cache_set(text: str, kind: str, cefr_level: str, explanation: Dict, overwri
                 existing.source_text = text
                 existing.hit_count = 1   # 重生成清零计数
                 s.commit()
+                logger.debug("cache_set OVERWRITE kind=%s level=%s 耗时=%.3fs", kind, cefr_level, time.time() - t0)
+            else:
+                logger.debug("cache_set SKIP（已存在）kind=%s level=%s 耗时=%.3fs", kind, cefr_level, time.time() - t0)
             return
         s.add(
             ExplanationCache(
@@ -128,8 +144,10 @@ def _cache_set(text: str, kind: str, cefr_level: str, explanation: Dict, overwri
         )
         try:
             s.commit()
+            logger.debug("cache_set INSERT kind=%s level=%s 耗时=%.3fs", kind, cefr_level, time.time() - t0)
         except IntegrityError:
             s.rollback()
+            logger.warning("cache_set IntegrityError kind=%s level=%s 耗时=%.3fs", kind, cefr_level, time.time() - t0)
 
 
 def _strip_code_fences(raw: str) -> str:
@@ -190,6 +208,7 @@ async def explain_text(
     :param context: word 模式下提供所在句子，sentence 模式下忽略
     :param force: True 时跳过缓存，重新生成并覆盖；带 3s debounce
     """
+    t_start = time.time()
     if not text or not text.strip():
         raise ValueError("解读内容不能为空")
     text = text.strip()
@@ -198,6 +217,12 @@ async def explain_text(
     if kind not in VALID_KINDS:
         raise ValueError(f"无效的解读类型: {kind}，可选值: sentence / word")
 
+    preview = text if len(text) <= 30 else text[:30] + "…"
+    logger.info(
+        "explain_text 入口 kind=%s text_len=%d preview=%r user=%s force=%s",
+        kind, len(text), preview, user_id[:8] if user_id else "-", force,
+    )
+
     cefr_level = _get_user_level(user_id)
     cache_level = cefr_level or _DEFAULT_LEVEL
 
@@ -207,30 +232,58 @@ async def explain_text(
     else:
         cached = _cache_get(text, kind, cache_level)
         if cached is not None:
+            logger.info(
+                "explain_text 完成 kind=%s 来源=cache 总耗时=%.3fs",
+                kind, time.time() - t_start,
+            )
             return {"explanation": cached, "cefr_level": cache_level, "cached": True}
 
     prompt_level = cefr_level or _DEFAULT_LEVEL
+    t_prompt = time.time()
     if kind == "sentence":
+        liaison = liaison_prompt_block()
         system_prompt = EXPLAIN_SENTENCE_PROMPT.format(
             cefr_level=prompt_level,
-            liaison_kb=liaison_prompt_block(),
+            liaison_kb=liaison,
+        )
+        logger.debug(
+            "prompt 拼装 kind=sentence system_len=%d liaison_len=%d 耗时=%.3fs",
+            len(system_prompt), len(liaison), time.time() - t_prompt,
         )
     else:
         system_prompt = EXPLAIN_WORD_PROMPT.format(
             cefr_level=prompt_level,
             text=text.replace('"', '\\"'),
             context=(context or "").replace('"', '\\"'),
         )
+        logger.debug(
+            "prompt 拼装 kind=word system_len=%d context_len=%d 耗时=%.3fs",
+            len(system_prompt), len(context or ""), time.time() - t_prompt,
+        )
 
     messages = [
         {"role": "system", "content": system_prompt},
         {"role": "user", "content": text},
     ]
     client = get_client()
+    t_llm = time.time()
     raw = await client.complete(messages, max_tokens=2000, scene="explain")
+    llm_elapsed = time.time() - t_llm
+    logger.info(
+        "explain_text LLM 完成 kind=%s output_len=%d 耗时=%.2fs",
+        kind, len(raw or ""), llm_elapsed,
+    )
+
+    t_parse = time.time()
     explanation = _parse_explanation(raw)
+    logger.debug("explain_text JSON 解析 耗时=%.3fs fields=%d", time.time() - t_parse, len(explanation))
 
     _cache_set(text, kind, cache_level, explanation, overwrite=force)
+    total = time.time() - t_start
+    logger.info(
+        "explain_text 完成 kind=%s 来源=llm 总耗时=%.2fs (LLM 占比=%.0f%%)",
+        kind, total, (llm_elapsed / total * 100) if total > 0 else 0,
+    )
     return {"explanation": explanation, "cefr_level": cache_level, "cached": False, "regenerated": force}
 
 
@@ -266,12 +319,19 @@ async def stream_sentence_explanation(
       - 结束后额外 yield 一个 {"_done": True} 事件
     :param force: True 时跳过缓存重新生成（带 3s debounce）
     """
+    t_start = time.time()
     if not text or not text.strip():
         raise ValueError("解读内容不能为空")
     text = text.strip()
     if len(text) > MAX_TEXT_LEN:
         raise ValueError(f"解读内容不能超过 {MAX_TEXT_LEN} 字符")
 
+    preview = text if len(text) <= 30 else text[:30] + "…"
+    logger.info(
+        "stream_sentence 入口 text_len=%d preview=%r user=%s force=%s",
+        len(text), preview, user_id[:8] if user_id else "-", force,
+    )
+
     cefr_level = _get_user_level(user_id)
     cache_level = cefr_level or _DEFAULT_LEVEL
 
@@ -282,23 +342,31 @@ async def stream_sentence_explanation(
     else:
         cached = _cache_get(text, "sentence", cache_level)
         if cached is not None:
+            logger.info("stream_sentence 来源=cache 总耗时=%.3fs", time.time() - t_start)
             yield json.dumps({"_cached": True, "cefr_level": cache_level, "explanation": cached}, ensure_ascii=False)
             return
 
     prompt_level = cefr_level or _DEFAULT_LEVEL
+    t_prompt = time.time()
+    liaison = liaison_prompt_block()
     system_prompt = (
         EXPLAIN_SENTENCE_PROMPT.format(
             cefr_level=prompt_level,
-            liaison_kb=liaison_prompt_block(),
+            liaison_kb=liaison,
         )
         + _STREAM_FORMAT_HINT
     )
+    logger.debug(
+        "stream prompt 拼装 system_len=%d liaison_len=%d 耗时=%.3fs",
+        len(system_prompt), len(liaison), time.time() - t_prompt,
+    )
     messages = [
         {"role": "system", "content": system_prompt},
         {"role": "user", "content": text},
     ]
 
     client = get_client()
+    t_llm = time.time()
     buffer = ""
     collected: Dict[str, object] = {}
     async for chunk in client.chat_stream_messages(messages, scene="explain"):
@@ -332,6 +400,12 @@ async def stream_sentence_explanation(
         except json.JSONDecodeError:
             pass
 
+    llm_elapsed = time.time() - t_llm
     if collected:
         _cache_set(text, "sentence", cache_level, collected, overwrite=force)
+    total = time.time() - t_start
+    logger.info(
+        "stream_sentence 完成 来源=llm fields=%d LLM=%.2fs 总耗时=%.2fs",
+        len(collected), llm_elapsed, total,
+    )
     yield json.dumps({"_done": True, "cefr_level": cache_level, "regenerated": force}, ensure_ascii=False)

docker-compose.yml

@@ -11,9 +11,11 @@ services:
       # SQLite 落到挂载卷 · 容器重启/镜像更新数据不丢
       DATABASE_URL: sqlite+aiosqlite:////app/data/speakeasy.db
       SPEAKEASY_DB_PATH: /app/data/speakeasy.db
+      # 日志落到 /app/logs（挂 named volume，宿主机可 `docker compose exec` 查看或挂主机目录持久化）
+      LOG_DIR: /app/logs
     volumes:
       - /etc/localtime:/etc/localtime:ro
-      - logs:/javarun/logs
+      - logs:/app/logs
       - data:/app/data
     ports:
       - "8600:8000"

docs/decisions/v02a-tech-decisions.md

@@ -58,7 +58,7 @@ Speakeasy 的部署路径更可能是：
 | 阶段 | 部署方式 | 是否需要 Nginx |
 |------|----------|----------------|
 | 本地开发 | `uvicorn main:app --reload` | ❌ |
-| 早期上线 | Railway / Render / Fly.io | ❌（平台内置 HTTPS + 反代） |
+| 早期上线 | VPS + docker-compose + Caddy（当前方案） | ❌（Caddy 自动 HTTPS + 反代） |
 | 规模化 | 容器化 → 云平台 LB | ❌（云 LB 原生支持 SSE） |
 | 特殊场景 | 自管服务器 | ✅ 届时配置 |