feat:添加log日志功能

.gitignore

@@ -15,3 +15,8 @@ benchmarks/gpu/*.json
 
 # OCR outputs
 outputs/
+
+# Generated structured logs (legacy logs directly under logs/ remain tracked)
+logs/single/
+logs/batch/
+logs/pdf/

README.md

@@ -12,6 +12,7 @@ ocr-VL1.6/
 ├── batch_ocr.py            # CPU 批量图片 OCR（系统友好的多进程版本）
 ├── pdf_ocr.py              # CPU PDF OCR（逐页、可恢复）
 ├── pdf_ocr_core.py         # CPU/GPU 共用的 PDF 渲染、恢复和导出逻辑
+├── ocr_logging.py          # CPU/GPU 共用的 UTF-8 结构化日志工具
 ├── pyproject.toml          # CPU 项目依赖
 ├── uv.lock                 # CPU 锁文件
 ├── gpu/                    # 独立 GPU 子项目
@@ -65,6 +66,8 @@ uv run python main.py
 uv run python batch_ocr.py images/
 ```
 
+所有 OCR 入口默认同时输出控制台日志和 UTF-8 日志文件，详见“运行日志”章节。
+
 首次运行会自动从 ModelScope 下载模型文件（约 2GB），后续使用缓存。
 
 ### GPU 子项目
@@ -89,6 +92,108 @@ uv run --project gpu python gpu/main.py --warmup 1 --rounds 3
 
 GPU Benchmark JSON 写入 `benchmarks/gpu/`。详细说明见 [`gpu/README.md`](gpu/README.md)。
 
+## 运行日志
+
+所有主要入口均使用统一日志格式：
+
+```text
+2026-07-16 14:28:02 | INFO     | pid=27644 | PAGE_OCR_COMPLETED page=1 seconds=36.345
+```
+
+默认日志目录：
+
+```text
+logs/
+├── single/    # main.py / gpu/main.py
+├── batch/     # batch_ocr.py
+└── pdf/       # pdf_ocr.py / gpu/pdf_ocr.py
+```
+
+默认文件名包含输入名、设备和时间戳，例如：
+
+```text
+logs/pdf/sample-cpu-20260716-142802.log
+logs/single/手写01-gpu0-20260716-142802.log
+```
+
+可用参数：
+
+```bash
+# 指定日志文件
+uv run python main.py images/手写01.png --log-file logs/custom.log
+uv run python pdf_ocr.py documents/sample.pdf --log-file logs/pdf-sample.log
+uv run python batch_ocr.py images/ --log-file logs/batch-images.log
+
+# 输出详细异常堆栈和调试日志
+uv run python pdf_ocr.py documents/sample.pdf --verbose
+```
+
+日志文件使用 UTF-8 编码。即使 Windows 控制台因 GBK 显示乱码，日志文件中的中文仍可正常查看。
+
+### 单图日志统计
+
+`main.py` 与 `gpu/main.py` 记录：
+
+- 程序启动与输入图片大小
+- Paddle/PaddleOCR 导入耗时
+- CPU 线程数或 GPU/CUDA 初始化耗时
+- 模型初始化耗时
+- 每轮预热耗时
+- 每轮正式推理耗时
+- min/max/mean/median/stdev
+- 图片尺寸、版面框数量、文本块数量
+- OCR 文本块内容（可用 `--no-result` 关闭）
+- 从程序启动到结果输出的总用时
+- GPU 入口额外记录显存统计和 Benchmark JSON 路径
+
+### 批量图片日志统计
+
+`batch_ocr.py` 记录：
+
+- 图片扫描耗时和图片数量
+- Worker 数、每 Worker 线程数和预估内存
+- 每个 Worker 的 PID、错峰等待、框架导入、模型初始化和启动总耗时
+- 每张图片的 Worker PID、推理耗时、尺寸、版面框和文本块数量
+- 任务进度、成功数和失败数
+- Pool 总耗时、串行耗时估计、平均每图耗时和并行加速比
+- 从程序启动到全部结果汇总的总用时
+
+### PDF 日志统计
+
+`pdf_ocr.py` 与 `gpu/pdf_ocr.py` 记录：
+
+- PDF 预检、打开和 manifest 创建耗时
+- 模型初始化耗时
+- 每页渲染耗时
+- 每页 OCR 推理耗时
+- 每页 Markdown/JSON 导出耗时
+- manifest 与合并文件保存耗时
+- 每页总耗时、累计耗时和预计剩余时间（ETA）
+- 每页图片尺寸、版面框数量和文本块数量
+- 完成页、失败页和断点续传前已完成页数
+- 各阶段累计值、平均每页耗时和任务总用时
+- 从程序启动（含模型加载）到退出的程序总用时
+
+PDF 的 `manifest.json` 同时包含 `summary.timing`：
+
+```json
+{
+  "pdf_open_seconds": 0.01,
+  "manifest_prepare_seconds": 0.03,
+  "render_total_seconds": 1.2,
+  "ocr_total_seconds": 324.5,
+  "export_total_seconds": 0.8,
+  "state_save_total_seconds": 0.2,
+  "page_total_seconds": 326.7,
+  "average_ocr_seconds": 162.25,
+  "average_page_seconds": 163.35,
+  "finalize_seconds": 0.1,
+  "task_total_seconds": 327.1
+}
+```
+
+`task_total_seconds` 是 PDF 核心任务总时间，不含入口模型初始化；完整程序总时间记录在日志的 `PROGRAM_COMPLETED` 事件中。
+
 ## PDF OCR
 
 PDF 使用 `pypdfium2` 逐页渲染，再将每一页交给 PaddleOCR-VL。默认采用安全的单进程串行模式，页面完成后立即保存，适合 CPU 长时间任务。CPU 默认预留 2 个逻辑核心给系统，可通过 `--threads` 覆盖。

batch_ocr.py

@@ -1,208 +1,329 @@
-"""
+"""System-friendly multiprocessing batch OCR with structured timing logs."""
-批量 OCR 识别 — 多进程并行加速（系统友好版）
 
-修复要点:
+from __future__ import annotations
-  1. 进程错峰启动（随机延迟），避免同时加载 N 个模型导致内存/CUP 打满
-  2. 降低子进程优先级，保证系统 UI 正常响应
-  3. 预留 1-2 个核心给 OS，避免 CPU 完全饱和
-  4. 用 imap_unordered 逐任务分发，而非一次性灌满
 
-用法:
-    python batch_ocr.py <图片目录> [--workers 4] [--threads 5]
-
-安全建议:
-    - 32GB RAM 建议 --workers <= 4
-    - 16GB RAM 建议 --workers <= 2
-    - 不确定时先用 --workers 1 测试
-"""
-import time
-import os
-import sys
-import random
 import argparse
-from multiprocessing import Pool, cpu_count
+import logging
+import os
+import random
+import sys
+import time
+from logging.handlers import QueueHandler, QueueListener
+from multiprocessing import Manager, Pool, cpu_count
 from pathlib import Path
 
-# ── Worker 初始化（在子进程中执行） ──
+from ocr_logging import default_log_path, setup_run_logger
 
-def _init_worker(threads: int, stagger_max: float):
+PROJECT_ROOT = Path(__file__).resolve().parent
-    """
+_WORKER_LOG_QUEUE = None
-    每个 Worker 启动时：随机延迟 → 设线程数 → 降优先级 → 加载模型。
+_WORKER_INIT_METRICS: dict = {}
 
-    随机延迟是关键：避免 N 个进程同时读磁盘/分配内存，
+
-    将 4×2GB=8GB 的内存峰值分散到 0~15s 的时间窗口中。
+def _worker_logger() -> logging.Logger:
-    """
+    logger = logging.getLogger(f"ocr.batch.worker.{os.getpid()}")
+    if logger.handlers:
+        return logger
+    logger.setLevel(logging.INFO)
+    logger.propagate = False
+    if _WORKER_LOG_QUEUE is not None:
+        logger.addHandler(QueueHandler(_WORKER_LOG_QUEUE))
+    return logger
+
+
+def _init_worker(threads: int, stagger_max: float, log_queue) -> None:
+    """Stagger startup, lower process priority, and load one model per worker."""
+    global _pipeline, _WORKER_LOG_QUEUE, _WORKER_INIT_METRICS
+    _WORKER_LOG_QUEUE = log_queue
+    logger = _worker_logger()
+    worker_started = time.perf_counter()
     delay = random.uniform(0, stagger_max)
+    logger.info("WORKER_START threads=%d stagger_delay_seconds=%.3f", threads, delay)
     time.sleep(delay)
 
-    # 算子级线程数
+    import_started = time.perf_counter()
     from paddle import core
     core.set_num_threads(threads)
+    import_seconds = time.perf_counter() - import_started
 
-    # 降低进程优先级（不影响计算吞吐，但让 OS 调度更公平）
     try:
         import psutil
-        p = psutil.Process()
-        if sys.platform == "win32":
-            p.nice(psutil.BELOW_NORMAL_PRIORITY_CLASS)
-        else:
-            p.nice(10)
-    except ImportError:
-        pass
-    except Exception:
-        pass
 
-    # 加载 pipeline（~2GB，耗时 ~40s）
+        process = psutil.Process()
+        if sys.platform == "win32":
+            process.nice(psutil.BELOW_NORMAL_PRIORITY_CLASS)
+        else:
+            process.nice(10)
+        priority_status = "lowered"
+    except Exception as exc:
+        priority_status = f"unchanged:{type(exc).__name__}"
+
+    model_started = time.perf_counter()
     from paddleocr import PaddleOCRVL
-    global _pipeline
+
-    _pipeline = PaddleOCRVL(pipeline_version="v1.6")
+    _pipeline = PaddleOCRVL(pipeline_version="v1.6", device="cpu")
+    model_seconds = time.perf_counter() - model_started
+    startup_total = time.perf_counter() - worker_started
+    _WORKER_INIT_METRICS = {
+        "pid": os.getpid(),
+        "threads": threads,
+        "stagger_delay_seconds": round(delay, 3),
+        "import_seconds": round(import_seconds, 3),
+        "model_init_seconds": round(model_seconds, 3),
+        "startup_total_seconds": round(startup_total, 3),
+        "priority": priority_status,
+    }
+    logger.info(
+        "WORKER_READY threads=%d import_seconds=%.3f model_init_seconds=%.3f startup_total_seconds=%.3f priority=%s",
+        threads,
+        import_seconds,
+        model_seconds,
+        startup_total,
+        priority_status,
+    )
 
 
 def _ocr_task(image_path: str) -> dict:
-    """单张图片 OCR（使用全局 pipeline）"""
+    global _pipeline, _WORKER_INIT_METRICS
-    global _pipeline
+    logger = _worker_logger()
-    t0 = time.perf_counter()
+    started = time.perf_counter()
-    result = _pipeline.predict(image_path)
+    logger.info("IMAGE_START path=%s", image_path)
-    elapsed = time.perf_counter() - t0
+    try:
-
+        result = _pipeline.predict(image_path)
-    blocks = []
+        elapsed = time.perf_counter() - started
-    for block in result[0]["parsing_res_list"]:
+        first = result[0]
-        if block.content.strip():
+        blocks = [
-            blocks.append({
+            {"label": block.label, "bbox": block.bbox, "content": block.content}
-                "label": block.label,
+            for block in first["parsing_res_list"]
-                "bbox": block.bbox,
+            if block.content.strip()
-                "content": block.content,
+        ]
-            })
+        response = {
-
+            "path": image_path,
-    return {
+            "status": "completed",
-        "path": str(image_path),
+            "elapsed": round(elapsed, 3),
-        "elapsed": round(elapsed, 2),
+            "width": first.get("width"),
-        "blocks": blocks,
+            "height": first.get("height"),
-    }
+            "layout_boxes": len(first["layout_det_res"]["boxes"]),
+            "parsed_blocks": len(first["parsing_res_list"]),
+            "blocks": blocks,
+            "worker_pid": os.getpid(),
+            "worker_init": _WORKER_INIT_METRICS,
+        }
+        logger.info(
+            "IMAGE_COMPLETED path=%s seconds=%.3f width=%s height=%s layout_boxes=%d parsed_blocks=%d non_empty_blocks=%d",
+            image_path,
+            elapsed,
+            response["width"],
+            response["height"],
+            response["layout_boxes"],
+            response["parsed_blocks"],
+            len(blocks),
+        )
+        return response
+    except Exception as exc:
+        elapsed = time.perf_counter() - started
+        logger.exception("IMAGE_FAILED path=%s seconds=%.3f error=%s", image_path, elapsed, exc)
+        return {
+            "path": image_path,
+            "status": "failed",
+            "elapsed": round(elapsed, 3),
+            "error": f"{type(exc).__name__}: {exc}",
+            "blocks": [],
+            "worker_pid": os.getpid(),
+            "worker_init": _WORKER_INIT_METRICS,
+        }
 
 
-# ── 主流程 ──
+def parse_args() -> argparse.Namespace:
-
-def main():
-    total_cores = cpu_count()
-
     parser = argparse.ArgumentParser(
         description="批量 OCR — 多进程并行（系统友好版）",
-        formatter_class=argparse.RawDescriptionHelpFormatter,
+        formatter_class=argparse.ArgumentDefaultsHelpFormatter,
-        epilog="""
-示例:
-  python batch_ocr.py images/                          # 默认 2 进程
-  python batch_ocr.py images/ --workers 4              # 4 进程（需 32GB RAM）
-  python batch_ocr.py images/ --workers 2 --threads 8  # 指定每进程线程数
-        """,
     )
-    parser.add_argument("dir", type=str, help="图片目录")
+    parser.add_argument("dir", type=Path, help="图片目录")
-    parser.add_argument(
+    parser.add_argument("--workers", type=int, default=2, help="并行进程数")
-        "--workers", type=int, default=2,
+    parser.add_argument("--threads", type=int, default=None, help="每进程线程数")
-        help="并行进程数 (默认 2，安全值；最大建议不超过 RAM_GB/2)",
+    parser.add_argument("--stagger", type=float, default=15.0, help="Worker 启动错峰窗口秒数")
-    )
+    parser.add_argument("--log-file", type=Path, default=None, help="日志文件路径")
-    parser.add_argument(
+    parser.add_argument("--verbose", action="store_true", help="输出详细日志")
-        "--threads", type=int, default=None,
+    parser.add_argument("--no-result", action="store_true", help="不记录 OCR 文本块")
-        help=f"每进程线程数 (默认: (总核心-1)/workers，保证 OS 有 1 核可用)",
+    return parser.parse_args()
-    )
+
-    parser.add_argument(
+
-        "--stagger", type=float, default=15.0,
+def main() -> int:
-        help="进程启动错峰窗口秒数 (默认 15s，值越大内存峰值越低)",
+    program_started = time.perf_counter()
-    )
+    args = parse_args()
-    args = parser.parse_args()
+    image_dir = args.dir.expanduser().resolve()
+    log_file = args.log_file or default_log_path(PROJECT_ROOT, "batch", image_dir.name, device="cpu")
+    logger = setup_run_logger("ocr.batch.main", log_file, verbose=args.verbose)
 
-    # ── 扫描图片 ──
-    image_dir = Path(args.dir)
     if not image_dir.is_dir():
-        print(f"[ERROR] 目录不存在: {args.dir}")
+        logger.error("INPUT_DIRECTORY_NOT_FOUND path=%s", image_dir)
-        sys.exit(1)
+        return 1
+    if args.workers < 1 or args.stagger < 0:
+        logger.error("INVALID_ARGUMENT workers=%d stagger=%.3f", args.workers, args.stagger)
+        return 2
 
+    scan_started = time.perf_counter()
     extensions = ("*.png", "*.jpg", "*.jpeg", "*.bmp", "*.tiff", "*.tif", "*.webp")
-    images = []
+    images = sorted(path for extension in extensions for path in image_dir.glob(extension))
-    for ext in extensions:
+    scan_seconds = time.perf_counter() - scan_started
-        images.extend(image_dir.glob(ext))
-    images = sorted(images)
-
     if not images:
-        print(f"[ERROR] 目录中没有图片: {args.dir}")
+        logger.error("NO_IMAGES_FOUND path=%s scan_seconds=%.3f", image_dir, scan_seconds)
-        sys.exit(1)
+        return 1
 
-    # ── 资源规划 ──
+    total_cores = cpu_count()
     workers = min(args.workers, len(images))
-    reserved_for_os = 1  # 至少给 OS 留 1 个逻辑核心
+    threads = args.threads or max(1, (total_cores - 1) // workers)
-    if args.threads:
+    if threads < 1:
-        threads = args.threads
+        logger.error("INVALID_ARGUMENT threads=%d", threads)
-    else:
+        return 2
-        threads = max(1, (total_cores - reserved_for_os) // workers)
-
     total_cpu_used = workers * threads
-    stagger = args.stagger
+    estimated_mem = workers * 2.0 + 2
-
-    # 内存估算
-    model_mem_per_worker = 2.0  # GB, 模型 ~1.8GB + 运行时开销
-    estimated_mem = workers * model_mem_per_worker + 2  # +2GB for OS
 
     try:
         import psutil
-        avail_gb = psutil.virtual_memory().available / (1024**3)
+
-        mem_ok = avail_gb > estimated_mem
+        available_gb = psutil.virtual_memory().available / (1024**3)
     except ImportError:
-        avail_gb = None
+        available_gb = None
-        mem_ok = True  # 无法检测，假定 OK
 
-    # ── 打印配置 ──
+    logger.info(
-    print("=" * 60)
+        "PROGRAM_STARTED directory=%s image_count=%d scan_seconds=%.3f workers=%d threads_per_worker=%d total_cores=%d planned_threads=%d reserved_cores=%d stagger_seconds=%.3f estimated_memory_gb=%.1f available_memory_gb=%s",
-    print(f"  图片数量:       {len(images)}")
+        image_dir,
-    print(f"  并行进程:       {workers}")
+        len(images),
-    print(f"  每进程线程:     {threads}")
+        scan_seconds,
-    print(f"  CPU 占用:       {total_cpu_used} / {total_cores} 核 (保留 {total_cores - total_cpu_used} 给 OS)")
+        workers,
-    print(f"  错峰窗口:       {stagger}s")
+        threads,
-    print(f"  预估内存:       ~{estimated_mem:.0f}GB (可用: {avail_gb:.0f}GB)" if avail_gb else f"  预估内存:       ~{estimated_mem:.0f}GB")
+        total_cores,
-    if not mem_ok:
+        total_cpu_used,
-        print(f"  [WARNING] 可用内存不足！建议降低 --workers 到 {max(1, int((avail_gb - 2) / model_mem_per_worker))}")
+        max(0, total_cores - total_cpu_used),
-    print("=" * 60)
+        args.stagger,
+        estimated_mem,
+        f"{available_gb:.1f}" if available_gb is not None else "unknown",
+    )
 
-    if not mem_ok:
+    if available_gb is not None and available_gb <= estimated_mem:
-        resp = input("内存不足，是否继续？[y/N] ").strip().lower()
+        logger.warning(
-        if resp != "y":
+            "MEMORY_PRESSURE estimated_memory_gb=%.1f available_memory_gb=%.1f recommendation=reduce_workers",
-            print("已取消。")
+            estimated_mem,
-            sys.exit(0)
+            available_gb,
+        )
+        response = input("可用内存可能不足，是否继续？[y/N] ").strip().lower()
+        if response != "y":
+            logger.warning("PROGRAM_CANCELLED_BY_USER")
+            return 0
 
-    # ── 执行 ──
+    pool_started = time.perf_counter()
-    t0 = time.perf_counter()
+    results: list[dict] = []
+    try:
+        with Manager() as manager:
+            log_queue = manager.Queue()
+            listener_handlers = tuple(logger.handlers)
+            listener = QueueListener(log_queue, *listener_handlers, respect_handler_level=True)
+            listener.start()
+            try:
+                with Pool(
+                    processes=workers,
+                    initializer=_init_worker,
+                    initargs=(threads, args.stagger, log_queue),
+                ) as pool:
+                    for completed, result in enumerate(
+                        pool.imap_unordered(_ocr_task, [str(path) for path in images], chunksize=1),
+                        start=1,
+                    ):
+                        results.append(result)
+                        logger.info(
+                            "BATCH_PROGRESS completed=%d total=%d path=%s status=%s image_seconds=%.3f worker_pid=%s",
+                            completed,
+                            len(images),
+                            result["path"],
+                            result["status"],
+                            result["elapsed"],
+                            result.get("worker_pid"),
+                        )
+            finally:
+                listener.stop()
+    except KeyboardInterrupt:
+        logger.warning("PROGRAM_INTERRUPTED elapsed_seconds=%.3f", time.perf_counter() - program_started)
+        return 130
+    except Exception as exc:
+        logger.exception("POOL_FAILED error=%s elapsed_seconds=%.3f", exc, time.perf_counter() - program_started)
+        return 1
 
-    with Pool(
+    pool_seconds = time.perf_counter() - pool_started
-        processes=workers,
+    completed_results = [result for result in results if result["status"] == "completed"]
-        initializer=_init_worker,
+    failed_results = [result for result in results if result["status"] == "failed"]
-        initargs=(threads, stagger),
+    worker_metrics = {
-    ) as pool:
+        result["worker_pid"]: result.get("worker_init", {})
-        # imap_unordered: 逐任务分发，先完成的先返回
+        for result in results
-        # chunk 大 → 吞吐高但内存峰值高；chunk=1 → 最平滑
+        if result.get("worker_pid") is not None
-        image_paths = [str(img) for img in images]
+    }
-        results = list(pool.imap_unordered(_ocr_task, image_paths, chunksize=1))
+    worker_model_init_total = sum(
+        metrics.get("model_init_seconds", 0.0) for metrics in worker_metrics.values()
+    )
+    worker_model_init_average = (
+        worker_model_init_total / len(worker_metrics) if worker_metrics else 0.0
+    )
+    serial_estimate = sum(result["elapsed"] for result in results)
+    average = serial_estimate / len(results) if results else 0.0
+    speedup = serial_estimate / pool_seconds if pool_seconds else 0.0
+    program_total = time.perf_counter() - program_started
 
-    total_elapsed = time.perf_counter() - t0
+    for worker_pid, metrics in sorted(worker_metrics.items()):
+        logger.info(
+            "WORKER_SUMMARY pid=%s threads=%s stagger_delay_seconds=%s import_seconds=%s model_init_seconds=%s startup_total_seconds=%s priority=%s",
+            worker_pid,
+            metrics.get("threads"),
+            metrics.get("stagger_delay_seconds"),
+            metrics.get("import_seconds"),
+            metrics.get("model_init_seconds"),
+            metrics.get("startup_total_seconds"),
+            metrics.get("priority"),
+        )
 
-    # ── 输出 ──
+    for result in sorted(results, key=lambda item: item["path"]):
-    print("\n" + "=" * 60)
+        if result["status"] == "completed":
-    for r in sorted(results, key=lambda x: x["path"]):
+            logger.info(
-        print(f"\n[文件] {r['path']} ({r['elapsed']:.1f}s)")
+                "IMAGE_SUMMARY path=%s seconds=%.3f width=%s height=%s layout_boxes=%d parsed_blocks=%d",
-        for block in r["blocks"]:
+                result["path"],
-            preview = block["content"].replace("\n", "\\n")
+                result["elapsed"],
-            if len(preview) > 80:
+                result["width"],
-                preview = preview[:80] + "..."
+                result["height"],
-            print(f"  [{block['label']}] {preview}")
+                result["layout_boxes"],
+                result["parsed_blocks"],
+            )
+            if not args.no_result:
+                for index, block in enumerate(result["blocks"], start=1):
+                    logger.info(
+                        "OCR_BLOCK path=%s index=%d label=%s bbox=%s content=%s",
+                        result["path"],
+                        index,
+                        block["label"],
+                        block["bbox"],
+                        block["content"].replace("\r", "").replace("\n", "\\n"),
+                    )
+        else:
+            logger.error("IMAGE_SUMMARY path=%s status=failed error=%s", result["path"], result["error"])
 
-    total_per_image = sum(r["elapsed"] for r in results)
+    logger.info(
-    print("\n" + "=" * 60)
+        "BATCH_SUMMARY image_count=%d completed=%d failed=%d scan_seconds=%.3f pool_seconds=%.3f worker_count=%d worker_model_init_total_seconds=%.3f worker_model_init_average_seconds=%.3f serial_estimate_seconds=%.3f average_image_seconds=%.3f speedup=%.3f program_total_seconds=%.3f workers=%d threads_per_worker=%d log=%s",
-    print(f"  总图片:   {len(images)}")
+        len(images),
-    print(f"  总耗时:   {total_elapsed:.1f}s ({total_elapsed/60:.1f}min)")
+        len(completed_results),
-    print(f"  平均每图: {total_elapsed / len(images):.1f}s")
+        len(failed_results),
-    print(f"  串行预计: {total_per_image:.1f}s")
+        scan_seconds,
-    if total_elapsed > 0:
+        pool_seconds,
-        print(f"  加速比:   {total_per_image / total_elapsed:.2f}x")
+        len(worker_metrics),
-    print("=" * 60)
+        worker_model_init_total,
+        worker_model_init_average,
+        serial_estimate,
+        average,
+        speedup,
+        program_total,
+        workers,
+        threads,
+        log_file.resolve(),
+    )
+    return 0 if not failed_results else 3
 
 
 if __name__ == "__main__":
-    main()
+    raise SystemExit(main())

gpu/README.md

@@ -94,8 +94,11 @@ Benchmark 会记录：
 
 ```text
 benchmarks/gpu/gpu-benchmark-YYYYMMDD-HHMMSS.json
+logs/single/<图片名>-gpuN-YYYYMMDD-HHMMSS.log
 ```
 
+日志记录 CUDA 配置、PaddleOCR 导入、模型初始化、每轮预热/推理、显存统计和程序总用时。可用 `--log-file` 指定路径，使用 `--verbose` 输出详细异常。
+
 ## PDF OCR
 
 GPU PDF 入口复用仓库根目录 `pdf_ocr_core.py`，按页渲染、逐页保存并支持断点续传：
@@ -122,6 +125,14 @@ uv run --project gpu python gpu/pdf_ocr.py documents/sample.pdf --keep-rendered
 
 无 CUDA 时脚本会立即退出，不会自动回落到 CPU。当前开发机器没有 NVIDIA GPU，因此此入口尚未完成 GPU 实机验证。
 
+PDF 日志默认写入：
+
+```text
+logs/pdf/<PDF名>-gpuN-YYYYMMDD-HHMMSS.log
+```
+
+日志与 `manifest.json` 会记录每页渲染、OCR、结果导出、状态保存、任务总用时和程序总用时。
+
 ## 当前范围
 
 当前实现单 GPU、单图 Benchmark 和单 GPU PDF 逐页 OCR。暂未实现 GPU 多进程批处理，原因是：

gpu/main.py

@@ -12,6 +12,10 @@ from typing import Any
 
 GPU_DIR = Path(__file__).resolve().parent
 PROJECT_ROOT = GPU_DIR.parent
+if str(PROJECT_ROOT) not in sys.path:
+    sys.path.insert(0, str(PROJECT_ROOT))
+
+from ocr_logging import default_log_path, setup_run_logger
 DEFAULT_IMAGE = PROJECT_ROOT / "images" / "手写01.png"
 DEFAULT_OUTPUT_DIR = PROJECT_ROOT / "benchmarks" / "gpu"
 
@@ -29,6 +33,8 @@ def parse_args() -> argparse.Namespace:
         help="Benchmark JSON 输出目录",
     )
     parser.add_argument("--no-result", action="store_true", help="不在控制台输出 OCR 文本")
+    parser.add_argument("--log-file", type=Path, default=None, help="日志文件路径")
+    parser.add_argument("--verbose", action="store_true", help="输出详细日志")
     return parser.parse_args()
 
 
@@ -133,35 +139,62 @@ def print_ocr_result(result: list[Any]) -> None:
 
 
 def main() -> int:
+    program_started = time.perf_counter()
     args = parse_args()
+    log_file = args.log_file or default_log_path(
+        PROJECT_ROOT,
+        "single",
+        args.image.stem,
+        device=f"gpu{args.device_id}",
+    )
+    logger = setup_run_logger("ocr.single.gpu", log_file, verbose=args.verbose)
+    logger.info(
+        "PROGRAM_STARTED image=%s device_id=%d warmup=%d rounds=%d output_dir=%s",
+        args.image,
+        args.device_id,
+        args.warmup,
+        args.rounds,
+        args.output_dir,
+    )
     try:
         validate_args(args)
+        cuda_started = time.perf_counter()
         paddle, device, device_name = configure_cuda(args.device_id)
+        cuda_setup_seconds = time.perf_counter() - cuda_started
     except (ValueError, RuntimeError) as exc:
-        print(f"[ERROR] {exc}", file=sys.stderr)
+        logger.error("VALIDATION_OR_CUDA_FAILED type=%s error=%s", type(exc).__name__, exc, exc_info=args.verbose)
         return 1
 
+    import_started = time.perf_counter()
     from paddleocr import PaddleOCRVL
+    import_seconds = time.perf_counter() - import_started
+    logger.info(
+        "RUNTIME_READY cuda_setup_seconds=%.3f import_seconds=%.3f device=%s device_name=%s paddle_version=%s image_size_bytes=%d",
+        cuda_setup_seconds,
+        import_seconds,
+        device,
+        device_name,
+        paddle.__version__,
+        args.image.stat().st_size,
+    )
 
-    print("=" * 70)
+    logger.info("MODEL_INITIALIZATION_STARTED pipeline_version=v1.6 device=%s", device)
-    print(f"Device:          {device} ({device_name})")
-    print(f"PaddlePaddle:    {paddle.__version__}")
-    print(f"Input image:     {args.image}")
-    print(f"Warmup/Rounds:   {args.warmup}/{args.rounds}")
-    print("=" * 70)
-
     synchronize(paddle, args.device_id)
     init_started = time.perf_counter()
     pipeline = PaddleOCRVL(pipeline_version="v1.6", device=device)
     synchronize(paddle, args.device_id)
     init_seconds = time.perf_counter() - init_started
-    print(f"Model init:      {init_seconds:.3f}s")
+    logger.info("MODEL_INITIALIZED seconds=%.3f", init_seconds)
 
     result = None
+    warmup_times: list[float] = []
     for index in range(args.warmup):
-        print(f"Warmup {index + 1}/{args.warmup}...", flush=True)
+        started = time.perf_counter()
         result = pipeline.predict(str(args.image))
         synchronize(paddle, args.device_id)
+        elapsed = time.perf_counter() - started
+        warmup_times.append(elapsed)
+        logger.info("WARMUP_COMPLETED round=%d/%d seconds=%.3f", index + 1, args.warmup, elapsed)
 
     inference_times: list[float] = []
     for index in range(args.rounds):
@@ -171,10 +204,10 @@ def main() -> int:
         synchronize(paddle, args.device_id)
         elapsed = time.perf_counter() - started
         inference_times.append(elapsed)
-        print(f"Inference {index + 1}/{args.rounds}: {elapsed:.3f}s", flush=True)
+        logger.info("INFERENCE_COMPLETED round=%d/%d seconds=%.3f", index + 1, args.rounds, elapsed)
 
     if result is None:
-        print("[ERROR] 未产生推理结果。", file=sys.stderr)
+        logger.error("EMPTY_RESULT")
         return 2
 
     summary = result_summary(result)
@@ -191,7 +224,10 @@ def main() -> int:
         "image": summary,
         "warmup_rounds": args.warmup,
         "benchmark_rounds": args.rounds,
+        "cuda_setup_seconds": round(cuda_setup_seconds, 3),
+        "runtime_import_seconds": round(import_seconds, 3),
         "model_init_seconds": round(init_seconds, 3),
+        "warmup_seconds": [round(value, 3) for value in warmup_times],
         "inference_seconds": {
             "all": [round(value, 3) for value in inference_times],
             "min": round(min(inference_times), 3),
@@ -201,6 +237,8 @@ def main() -> int:
             "stdev": round(statistics.pstdev(inference_times), 3),
         },
         "gpu_memory": read_gpu_memory(paddle, args.device_id),
+        "program_total_seconds": round(time.perf_counter() - program_started, 3),
+        "log_file": str(log_file.resolve()),
     }
 
     args.output_dir.mkdir(parents=True, exist_ok=True)
@@ -208,17 +246,44 @@ def main() -> int:
     output_path = args.output_dir / f"gpu-benchmark-{timestamp}.json"
     output_path.write_text(json.dumps(benchmark, ensure_ascii=False, indent=2), encoding="utf-8")
 
-    print("\n[Benchmark]")
+    logger.info(
-    print(f"Image:           {summary['width']} x {summary['height']}")
+        "RESULT_SUMMARY width=%d height=%d layout_boxes=%d parsed_blocks=%d non_empty_blocks=%d gpu_memory=%s",
-    print(f"Layout boxes:    {summary['layout_boxes']}")
+        summary["width"],
-    print(f"Parsed blocks:   {summary['parsed_blocks']}")
+        summary["height"],
-    print(f"Average:         {benchmark['inference_seconds']['mean']:.3f}s")
+        summary["layout_boxes"],
-    print(f"Min/Max:         {benchmark['inference_seconds']['min']:.3f}s / {benchmark['inference_seconds']['max']:.3f}s")
+        summary["parsed_blocks"],
-    print(f"Result JSON:     {output_path}")
+        summary["non_empty_blocks"],
+        benchmark["gpu_memory"],
+    )
+    logger.info(
+        "BENCHMARK_SUMMARY cuda_setup_seconds=%.3f import_seconds=%.3f model_init_seconds=%.3f warmup_total_seconds=%.3f inference_total_seconds=%.3f inference_min_seconds=%.3f inference_max_seconds=%.3f inference_mean_seconds=%.3f inference_median_seconds=%.3f inference_stdev_seconds=%.3f program_total_seconds=%.3f result_json=%s log=%s",
+        cuda_setup_seconds,
+        import_seconds,
+        init_seconds,
+        sum(warmup_times),
+        sum(inference_times),
+        min(inference_times),
+        max(inference_times),
+        statistics.fmean(inference_times),
+        statistics.median(inference_times),
+        statistics.pstdev(inference_times),
+        time.perf_counter() - program_started,
+        output_path,
+        log_file.resolve(),
+    )
 
     if not args.no_result:
-        print_ocr_result(result)
+        for index, block in enumerate(result[0]["parsing_res_list"], start=1):
+            if block.content.strip():
+                logger.info(
+                    "OCR_BLOCK index=%d label=%s bbox=%s content=%s",
+                    index,
+                    block.label,
+                    block.bbox,
+                    block.content.replace("\r", "").replace("\n", "\\n"),
+                )
 
+    logger.info("PROGRAM_COMPLETED")
     return 0
 
 

gpu/pdf_ocr.py

@@ -13,6 +13,7 @@ PROJECT_ROOT = GPU_DIR.parent
 if str(PROJECT_ROOT) not in sys.path:
     sys.path.insert(0, str(PROJECT_ROOT))
 
+from ocr_logging import default_log_path, setup_run_logger
 from pdf_ocr_core import preflight_pdf, process_pdf
 
 DEFAULT_OUTPUT = PROJECT_ROOT / "outputs"
@@ -36,6 +37,8 @@ def parse_args() -> argparse.Namespace:
     parser.add_argument("--max-new-tokens", type=int, default=None, help="限制每个文本块最大生成 token")
     parser.add_argument("--min-pixels", type=int, default=None, help="VLM 最小输入像素参数")
     parser.add_argument("--max-pixels", type=int, default=None, help="VLM 最大输入像素参数")
+    parser.add_argument("--log-file", type=Path, default=None, help="日志文件路径")
+    parser.add_argument("--verbose", action="store_true", help="输出详细日志")
     return parser.parse_args()
 
 
@@ -69,8 +72,29 @@ def configure_cuda(device_id: int):
 
 
 def main() -> int:
+    program_started = time.perf_counter()
     args = parse_args()
+    log_file = args.log_file or default_log_path(
+        PROJECT_ROOT,
+        "pdf",
+        args.pdf.stem,
+        device=f"gpu{args.device_id}",
+    )
+    logger = setup_run_logger("ocr.pdf.gpu", log_file, verbose=args.verbose)
+    logger.info(
+        "PROGRAM_STARTED input=%s output=%s pages=%s dpi=%d device_id=%d resume=%s overwrite=%s keep_rendered=%s fail_fast=%s",
+        args.pdf,
+        args.output,
+        args.pages or "all",
+        args.dpi,
+        args.device_id,
+        args.resume,
+        args.overwrite,
+        args.keep_rendered,
+        args.fail_fast,
+    )
     try:
+        preflight_started = time.perf_counter()
         preflight = preflight_pdf(
             pdf_path=args.pdf,
             output_root=args.output,
@@ -80,24 +104,39 @@ def main() -> int:
             resume=args.resume,
             overwrite=args.overwrite,
         )
+        preflight_seconds = time.perf_counter() - preflight_started
+        cuda_started = time.perf_counter()
         paddle, device, device_name = configure_cuda(args.device_id)
+        cuda_setup_seconds = time.perf_counter() - cuda_started
     except Exception as exc:
-        print(f"[ERROR] {type(exc).__name__}: {exc}", file=sys.stderr)
+        logger.error("PREFLIGHT_OR_CUDA_FAILED type=%s error=%s", type(exc).__name__, exc, exc_info=args.verbose)
         return 1
 
+    import_started = time.perf_counter()
     from paddleocr import PaddleOCRVL
+    import_seconds = time.perf_counter() - import_started
 
-    print(
+    logger.info(
-        f"[PDF] {preflight['page_count']} pages, selected: "
+        "PREFLIGHT_COMPLETED seconds=%.3f page_count=%d selected_pages=%d document_dir=%s",
-        f"{len(preflight['selected_pages'])}, output: {preflight['document_dir']}"
+        preflight_seconds,
+        preflight["page_count"],
+        len(preflight["selected_pages"]),
+        preflight["document_dir"],
     )
-    print(f"[GPU] Device: {device} ({device_name})")
+    logger.info(
-    print("Loading PaddleOCR-VL-1.6...")
+        "RUNTIME_READY cuda_setup_seconds=%.3f import_seconds=%.3f device=%s device_name=%s paddle_version=%s",
+        cuda_setup_seconds,
+        import_seconds,
+        device,
+        device_name,
+        paddle.__version__,
+    )
+    logger.info("MODEL_INITIALIZATION_STARTED pipeline_version=v1.6 device=%s", device)
     init_started = time.perf_counter()
     pipeline = PaddleOCRVL(pipeline_version="v1.6", device=device)
     paddle.device.cuda.synchronize(args.device_id)
     init_seconds = time.perf_counter() - init_started
-    print(f"Model init: {init_seconds:.2f}s")
+    logger.info("MODEL_INITIALIZED seconds=%.3f pipeline_version=v1.6 device=%s", init_seconds, device)
 
     predict_kwargs = {
         key: value
@@ -116,6 +155,10 @@ def main() -> int:
         "paddle_version": paddle.__version__,
         "model_init_seconds": round(init_seconds, 3),
         "pipeline_version": "v1.6",
+        "preflight_seconds": round(preflight_seconds, 3),
+        "cuda_setup_seconds": round(cuda_setup_seconds, 3),
+        "runtime_import_seconds": round(import_seconds, 3),
+        "log_file": str(log_file.resolve()),
     }
 
     try:
@@ -133,19 +176,37 @@ def main() -> int:
             run_metadata=metadata,
             predict_kwargs=predict_kwargs,
             synchronize=lambda: paddle.device.cuda.synchronize(args.device_id),
+            logger=logger,
         )
     except KeyboardInterrupt:
-        print("\n[INTERRUPTED] 已保存当前进度；使用 --resume 继续。", file=sys.stderr)
+        logger.warning(
+            "PROGRAM_INTERRUPTED total_seconds=%.3f resume_hint=--resume",
+            time.perf_counter() - program_started,
+        )
         return 130
     except Exception as exc:
-        print(f"[ERROR] {type(exc).__name__}: {exc}", file=sys.stderr)
+        logger.exception(
+            "PROGRAM_FAILED type=%s error=%s total_seconds=%.3f",
+            type(exc).__name__,
+            exc,
+            time.perf_counter() - program_started,
+        )
         return 1
 
-    print("\n[PDF OCR Summary]")
+    program_total = time.perf_counter() - program_started
-    print(f"Status:    {summary['status']}")
+    timing = summary.get("timing", {})
-    print(f"Completed: {summary['completed_pages']} / {summary['selected_pages']}")
+    logger.info(
-    print(f"Failed:    {summary['failed_pages']}")
+        "PROGRAM_COMPLETED status=%s completed_pages=%d selected_pages=%d failed_pages=%s model_init_seconds=%.3f pdf_task_seconds=%.3f program_total_seconds=%.3f output=%s log=%s",
-    print(f"Output:    {summary['document_dir']}")
+        summary["status"],
+        summary["completed_pages"],
+        summary["selected_pages"],
+        summary["failed_pages"],
+        init_seconds,
+        timing.get("task_total_seconds", 0.0),
+        program_total,
+        summary["document_dir"],
+        log_file.resolve(),
+    )
     return 0 if not summary["failed_pages"] else 3
 
 

main.py

@@ -1,62 +1,140 @@
-import time
+"""CPU single-image OCR benchmark with structured timing logs."""
+
+from __future__ import annotations
+
+import argparse
 import os
-from paddle import core
+import statistics
-from paddleocr import PaddleOCRVL
+import time
+from pathlib import Path
 
-IMAGE_PATH = "images/名片02.jpg"
+from ocr_logging import default_log_path, setup_run_logger
-WARMUP_ROUNDS = 0
-BENCHMARK_ROUNDS = 1
 
-# ── 线程配置 ──
+PROJECT_ROOT = Path(__file__).resolve().parent
-# 可通过环境变量 PADDLE_THREADS 覆盖，否则使用逻辑核心数
+DEFAULT_IMAGE = PROJECT_ROOT / "images" / "名片02.jpg"
-DEFAULT_THREADS = int(os.environ.get("PADDLE_THREADS", os.cpu_count() or 4))
-core.set_num_threads(DEFAULT_THREADS)
-print(f"[Threads] oneDNN compiled, using {DEFAULT_THREADS} threads (CPU cores: {os.cpu_count()})")
 
-# ── 模型初始化计时 ──
-print("=" * 60)
-print("初始化模型...")
-t0 = time.perf_counter()
-pipeline = PaddleOCRVL(pipeline_version="v1.6")
-t_init = time.perf_counter() - t0
-print(f"[OK] 模型初始化耗时: {t_init:.2f}s")
-print("=" * 60)
 
-# ── 推理 Benchmark ──
+def parse_args() -> argparse.Namespace:
-print(f"\n开始 OCR 识别: {IMAGE_PATH}")
+    parser = argparse.ArgumentParser(
-print(f"预热 {WARMUP_ROUNDS} 轮 + 正式测试 {BENCHMARK_ROUNDS} 轮\n")
+        description="PaddleOCR-VL-1.6 CPU 单图 Benchmark",
+        formatter_class=argparse.ArgumentDefaultsHelpFormatter,
+    )
+    parser.add_argument("image", nargs="?", type=Path, default=DEFAULT_IMAGE, help="输入图片")
+    parser.add_argument("--threads", type=int, default=None, help="Paddle CPU 线程数")
+    parser.add_argument("--warmup", type=int, default=0, help="预热轮数")
+    parser.add_argument("--rounds", type=int, default=1, help="正式测试轮数")
+    parser.add_argument("--log-file", type=Path, default=None, help="日志文件路径")
+    parser.add_argument("--verbose", action="store_true", help="输出详细日志")
+    parser.add_argument("--no-result", action="store_true", help="不输出识别文本")
+    return parser.parse_args()
 
-# 预热
-for i in range(WARMUP_ROUNDS):
-    print(f"  预热 {i + 1}/{WARMUP_ROUNDS}...")
-    _ = pipeline.predict(IMAGE_PATH)
 
-# 正式计时
+def main() -> int:
-times = []
+    program_started = time.perf_counter()
-for i in range(BENCHMARK_ROUNDS):
+    args = parse_args()
-    print(f"  推理 {i + 1}/{BENCHMARK_ROUNDS}...", end=" ", flush=True)
+    image_path = args.image.expanduser().resolve()
-    t0 = time.perf_counter()
+    log_file = args.log_file or default_log_path(PROJECT_ROOT, "single", image_path.stem, device="cpu")
-    result = pipeline.predict(IMAGE_PATH)
+    logger = setup_run_logger("ocr.single.cpu", log_file, verbose=args.verbose)
-    elapsed = time.perf_counter() - t0
-    times.append(elapsed)
-    print(f"{elapsed:.2f}s")
 
-print("\n" + "=" * 60)
+    if not image_path.is_file():
-print("[Benchmark]")
+        logger.error("INPUT_NOT_FOUND path=%s", image_path)
-print(f"  图片尺寸: {result[0]['width']} x {result[0]['height']}")
+        return 1
-print(f"  检测文本块: {len(result[0]['layout_det_res']['boxes'])} 个")
+    if args.warmup < 0 or args.rounds < 1:
-print(f"  识别文本块: {len(result[0]['parsing_res_list'])} 个")
+        logger.error("INVALID_ARGUMENT warmup=%d rounds=%d", args.warmup, args.rounds)
-print(f"  推理次数: {BENCHMARK_ROUNDS}")
+        return 2
-print(f"  最快: {min(times):.2f}s")
-print(f"  最慢: {max(times):.2f}s")
-print(f"  平均: {sum(times) / len(times):.2f}s")
-if len(times) > 1:
-    print(f"  标准差: {(sum((t - sum(times) / len(times)) ** 2 for t in times) / len(times)) ** 0.5:.2f}s")
-print("=" * 60)
 
-# ── 输出识别结果 ──
+    total_cores = os.cpu_count() or 4
-print("\n[识别结果]\n")
+    threads = args.threads or int(os.environ.get("PADDLE_THREADS", total_cores))
-for item in result:
+    if threads < 1:
-    for block in item["parsing_res_list"]:
+        logger.error("INVALID_ARGUMENT threads=%d", threads)
-        print(f"  [{block.label}] ({block.bbox})")
+        return 2
-        print(f"  {block.content}\n")
+
+    logger.info(
+        "PROGRAM_STARTED image=%s size_bytes=%d threads=%d total_cores=%d warmup=%d rounds=%d",
+        image_path,
+        image_path.stat().st_size,
+        threads,
+        total_cores,
+        args.warmup,
+        args.rounds,
+    )
+
+    import_started = time.perf_counter()
+    from paddle import core
+    from paddleocr import PaddleOCRVL
+    import_seconds = time.perf_counter() - import_started
+    core.set_num_threads(threads)
+    logger.info("RUNTIME_READY import_seconds=%.3f threads=%d", import_seconds, threads)
+
+    logger.info("MODEL_INITIALIZATION_STARTED pipeline_version=v1.6 device=cpu")
+    init_started = time.perf_counter()
+    pipeline = PaddleOCRVL(pipeline_version="v1.6", device="cpu")
+    init_seconds = time.perf_counter() - init_started
+    logger.info("MODEL_INITIALIZED seconds=%.3f", init_seconds)
+
+    warmup_times: list[float] = []
+    for index in range(args.warmup):
+        started = time.perf_counter()
+        pipeline.predict(str(image_path))
+        elapsed = time.perf_counter() - started
+        warmup_times.append(elapsed)
+        logger.info("WARMUP_COMPLETED round=%d/%d seconds=%.3f", index + 1, args.warmup, elapsed)
+
+    result = None
+    inference_times: list[float] = []
+    for index in range(args.rounds):
+        started = time.perf_counter()
+        result = pipeline.predict(str(image_path))
+        elapsed = time.perf_counter() - started
+        inference_times.append(elapsed)
+        logger.info("INFERENCE_COMPLETED round=%d/%d seconds=%.3f", index + 1, args.rounds, elapsed)
+
+    if not result:
+        logger.error("EMPTY_RESULT")
+        return 3
+
+    first = result[0]
+    layout_boxes = len(first["layout_det_res"]["boxes"])
+    parsed_blocks = len(first["parsing_res_list"])
+    non_empty_blocks = sum(bool(block.content.strip()) for block in first["parsing_res_list"])
+    inference_mean = statistics.fmean(inference_times)
+    inference_stdev = statistics.pstdev(inference_times)
+    program_total = time.perf_counter() - program_started
+
+    logger.info(
+        "RESULT_SUMMARY width=%s height=%s layout_boxes=%d parsed_blocks=%d non_empty_blocks=%d",
+        first.get("width"),
+        first.get("height"),
+        layout_boxes,
+        parsed_blocks,
+        non_empty_blocks,
+    )
+    logger.info(
+        "BENCHMARK_SUMMARY model_init_seconds=%.3f warmup_total_seconds=%.3f inference_total_seconds=%.3f inference_min_seconds=%.3f inference_max_seconds=%.3f inference_mean_seconds=%.3f inference_median_seconds=%.3f inference_stdev_seconds=%.3f program_total_seconds=%.3f",
+        init_seconds,
+        sum(warmup_times),
+        sum(inference_times),
+        min(inference_times),
+        max(inference_times),
+        inference_mean,
+        statistics.median(inference_times),
+        inference_stdev,
+        program_total,
+    )
+
+    if not args.no_result:
+        for index, block in enumerate(first["parsing_res_list"], start=1):
+            logger.info(
+                "OCR_BLOCK index=%d label=%s bbox=%s content=%s",
+                index,
+                block.label,
+                block.bbox,
+                block.content.replace("\r", "").replace("\n", "\\n"),
+            )
+
+    logger.info("PROGRAM_COMPLETED log=%s", log_file.resolve())
+    return 0
+
+
+if __name__ == "__main__":
+    raise SystemExit(main())

ocr_logging.py

@@ -0,0 +1,74 @@
+"""Shared UTF-8 logging helpers for OCR scripts."""
+
+from __future__ import annotations
+
+import logging
+import re
+import sys
+from datetime import datetime
+from pathlib import Path
+
+
+def safe_log_stem(value: str) -> str:
+    cleaned = re.sub(r"[^\w.-]+", "_", value, flags=re.UNICODE).strip("._")
+    return cleaned or "ocr"
+
+
+def default_log_path(
+    project_root: Path,
+    category: str,
+    stem: str,
+    *,
+    device: str | None = None,
+) -> Path:
+    timestamp = datetime.now().strftime("%Y%m%d-%H%M%S")
+    suffix = f"-{safe_log_stem(device)}" if device else ""
+    filename = f"{safe_log_stem(stem)}{suffix}-{timestamp}.log"
+    return project_root / "logs" / safe_log_stem(category) / filename
+
+
+def setup_run_logger(
+    name: str,
+    log_file: Path,
+    *,
+    verbose: bool = False,
+    console: bool = True,
+) -> logging.Logger:
+    """Create an isolated logger that writes UTF-8 text and optional console output."""
+    log_file = log_file.expanduser().resolve()
+    log_file.parent.mkdir(parents=True, exist_ok=True)
+
+    logger = logging.getLogger(name)
+    logger.setLevel(logging.DEBUG if verbose else logging.INFO)
+    logger.propagate = False
+    for handler in logger.handlers[:]:
+        handler.close()
+        logger.removeHandler(handler)
+
+    formatter = logging.Formatter(
+        fmt="%(asctime)s | %(levelname)-8s | pid=%(process)d | %(message)s",
+        datefmt="%Y-%m-%d %H:%M:%S",
+    )
+
+    file_handler = logging.FileHandler(log_file, encoding="utf-8")
+    file_handler.setLevel(logging.DEBUG)
+    file_handler.setFormatter(formatter)
+    logger.addHandler(file_handler)
+
+    if console:
+        console_handler = logging.StreamHandler(sys.stdout)
+        console_handler.setLevel(logging.DEBUG if verbose else logging.INFO)
+        console_handler.setFormatter(formatter)
+        logger.addHandler(console_handler)
+
+    logger.info("LOG_INITIALIZED file=%s", log_file)
+    return logger
+
+
+def close_logger(logger: logging.Logger) -> None:
+    for handler in logger.handlers[:]:
+        try:
+            handler.flush()
+            handler.close()
+        finally:
+            logger.removeHandler(handler)

pdf_ocr.py

@@ -5,10 +5,10 @@ from __future__ import annotations
 import argparse
 import os
 import platform
-import sys
 import time
 from pathlib import Path
 
+from ocr_logging import default_log_path, setup_run_logger
 from pdf_ocr_core import preflight_pdf, process_pdf
 
 PROJECT_ROOT = Path(__file__).resolve().parent
@@ -33,19 +33,41 @@ def parse_args() -> argparse.Namespace:
     parser.add_argument("--max-new-tokens", type=int, default=None, help="限制每个文本块最大生成 token")
     parser.add_argument("--min-pixels", type=int, default=None, help="VLM 最小输入像素参数")
     parser.add_argument("--max-pixels", type=int, default=None, help="VLM 最大输入像素参数")
+    parser.add_argument("--log-file", type=Path, default=None, help="日志文件路径")
+    parser.add_argument("--verbose", action="store_true", help="输出详细日志")
     return parser.parse_args()
 
 
 def main() -> int:
+    program_started = time.perf_counter()
     args = parse_args()
+    log_file = args.log_file or default_log_path(
+        PROJECT_ROOT,
+        "pdf",
+        args.pdf.stem,
+        device="cpu",
+    )
+    logger = setup_run_logger("ocr.pdf.cpu", log_file, verbose=args.verbose)
+    logger.info(
+        "PROGRAM_STARTED input=%s output=%s pages=%s dpi=%d resume=%s overwrite=%s keep_rendered=%s fail_fast=%s",
+        args.pdf,
+        args.output,
+        args.pages or "all",
+        args.dpi,
+        args.resume,
+        args.overwrite,
+        args.keep_rendered,
+        args.fail_fast,
+    )
     total_cores = os.cpu_count() or 4
     safe_default_threads = max(1, total_cores - 2)
     threads = args.threads or int(os.environ.get("PADDLE_THREADS", safe_default_threads))
     if threads < 1:
-        print("[ERROR] --threads 必须大于等于 1", file=sys.stderr)
+        logger.error("INVALID_ARGUMENT threads=%d", threads)
         return 2
 
     try:
+        preflight_started = time.perf_counter()
         preflight = preflight_pdf(
             pdf_path=args.pdf,
             output_root=args.output,
@@ -55,25 +77,37 @@ def main() -> int:
             resume=args.resume,
             overwrite=args.overwrite,
         )
+        preflight_seconds = time.perf_counter() - preflight_started
     except Exception as exc:
-        print(f"[ERROR] {type(exc).__name__}: {exc}", file=sys.stderr)
+        logger.error("PREFLIGHT_FAILED type=%s error=%s", type(exc).__name__, exc, exc_info=args.verbose)
         return 1
 
-    print(
+    logger.info(
-        f"[PDF] {preflight['page_count']} pages, selected: "
+        "PREFLIGHT_COMPLETED seconds=%.3f page_count=%d selected_pages=%d document_dir=%s",
-        f"{len(preflight['selected_pages'])}, output: {preflight['document_dir']}"
+        preflight_seconds,
+        preflight["page_count"],
+        len(preflight["selected_pages"]),
+        preflight["document_dir"],
     )
 
+    import_started = time.perf_counter()
     from paddle import core
     from paddleocr import PaddleOCRVL
+    import_seconds = time.perf_counter() - import_started
 
     core.set_num_threads(threads)
-    print(f"[CPU] Threads: {threads} / {total_cores} (reserved: {max(0, total_cores - threads)})")
+    logger.info(
-    print("Loading PaddleOCR-VL-1.6...")
+        "RUNTIME_READY import_seconds=%.3f threads=%d total_cores=%d reserved_cores=%d",
+        import_seconds,
+        threads,
+        total_cores,
+        max(0, total_cores - threads),
+    )
+    logger.info("MODEL_INITIALIZATION_STARTED pipeline_version=v1.6 device=cpu")
     init_started = time.perf_counter()
     pipeline = PaddleOCRVL(pipeline_version="v1.6", device="cpu")
     init_seconds = time.perf_counter() - init_started
-    print(f"Model init: {init_seconds:.2f}s")
+    logger.info("MODEL_INITIALIZED seconds=%.3f pipeline_version=v1.6 device=cpu", init_seconds)
 
     predict_kwargs = {
         key: value
@@ -91,6 +125,9 @@ def main() -> int:
         "platform": platform.platform(),
         "model_init_seconds": round(init_seconds, 3),
         "pipeline_version": "v1.6",
+        "preflight_seconds": round(preflight_seconds, 3),
+        "runtime_import_seconds": round(import_seconds, 3),
+        "log_file": str(log_file.resolve()),
     }
 
     try:
@@ -107,19 +144,37 @@ def main() -> int:
             fail_fast=args.fail_fast,
             run_metadata=metadata,
             predict_kwargs=predict_kwargs,
+            logger=logger,
         )
     except KeyboardInterrupt:
-        print("\n[INTERRUPTED] 已保存当前进度；使用 --resume 继续。", file=sys.stderr)
+        logger.warning(
+            "PROGRAM_INTERRUPTED total_seconds=%.3f resume_hint=--resume",
+            time.perf_counter() - program_started,
+        )
         return 130
     except Exception as exc:
-        print(f"[ERROR] {type(exc).__name__}: {exc}", file=sys.stderr)
+        logger.exception(
+            "PROGRAM_FAILED type=%s error=%s total_seconds=%.3f",
+            type(exc).__name__,
+            exc,
+            time.perf_counter() - program_started,
+        )
         return 1
 
-    print("\n[PDF OCR Summary]")
+    program_total = time.perf_counter() - program_started
-    print(f"Status:    {summary['status']}")
+    timing = summary.get("timing", {})
-    print(f"Completed: {summary['completed_pages']} / {summary['selected_pages']}")
+    logger.info(
-    print(f"Failed:    {summary['failed_pages']}")
+        "PROGRAM_COMPLETED status=%s completed_pages=%d selected_pages=%d failed_pages=%s model_init_seconds=%.3f pdf_task_seconds=%.3f program_total_seconds=%.3f output=%s log=%s",
-    print(f"Output:    {summary['document_dir']}")
+        summary["status"],
+        summary["completed_pages"],
+        summary["selected_pages"],
+        summary["failed_pages"],
+        init_seconds,
+        timing.get("task_total_seconds", 0.0),
+        program_total,
+        summary["document_dir"],
+        log_file.resolve(),
+    )
     return 0 if not summary["failed_pages"] else 3
 
 

pdf_ocr_core.py

@@ -4,6 +4,7 @@ from __future__ import annotations
 
 import hashlib
 import json
+import logging
 import os
 import re
 import shutil
@@ -82,14 +83,6 @@ def parse_page_spec(spec: str | None, page_count: int) -> list[int]:
     return sorted(selected)
 
 
-def format_duration(seconds: float | None) -> str:
-    if seconds is None:
-        return "unknown"
-    if seconds < 60:
-        return f"{seconds:.1f}s"
-    return f"{seconds / 60:.1f}min"
-
-
 def render_page(document: Any, page_index: int, dpi: int) -> Image.Image:
     page = document.get_page(page_index)
     bitmap = None
@@ -355,8 +348,11 @@ def process_pdf(
     run_metadata: dict[str, Any] | None = None,
     predict_kwargs: dict[str, Any] | None = None,
     synchronize: Callable[[], None] | None = None,
+    logger: logging.Logger | None = None,
 ) -> dict[str, Any]:
     """Render and OCR a PDF one page at a time."""
+    task_started = time.perf_counter()
+    logger = logger or logging.getLogger(__name__)
     pdf_path, output_root = validate_pdf_request(
         pdf_path,
         output_root,
@@ -372,10 +368,22 @@ def process_pdf(
     manifest_path = document_dir / "manifest.json"
     temporary_render_dir = document_dir / ".render-cache"
 
+    pdf_open_started = time.perf_counter()
     document = pdfium.PdfDocument(str(pdf_path), password=password)
+    pdf_open_seconds = time.perf_counter() - pdf_open_started
+    logger.info(
+        "PDF_OPENED path=%s seconds=%.3f dpi=%d resume=%s overwrite=%s keep_rendered=%s",
+        pdf_path,
+        pdf_open_seconds,
+        dpi,
+        resume,
+        overwrite,
+        keep_rendered,
+    )
     try:
         page_count = len(document)
         selected_indexes = parse_page_spec(pages, page_count)
+        manifest_started = time.perf_counter()
         manifest = prepare_manifest(
             pdf_path=pdf_path,
             document_dir=document_dir,
@@ -386,6 +394,14 @@ def process_pdf(
             overwrite=overwrite,
             run_metadata=run_metadata,
         )
+        manifest_prepare_seconds = time.perf_counter() - manifest_started
+        logger.info(
+            "MANIFEST_READY path=%s seconds=%.3f page_count=%d requested_pages=%d",
+            manifest_path,
+            manifest_prepare_seconds,
+            page_count,
+            len(selected_indexes),
+        )
         # Resume uses the union stored in the manifest, so newly added ranges and
         # previously selected pages remain one coherent document task.
         selected_indexes = [page_number - 1 for page_number in manifest["selected_pages"]]
@@ -398,9 +414,14 @@ def process_pdf(
             for index in selected_indexes
             if not _page_is_complete(document_dir, manifest, index + 1)
         ]
-        print(f"PDF: {pdf_path}")
+        logger.info(
-        print(f"Pages: {page_count}, selected: {len(selected_indexes)}, pending: {len(pending_indexes)}")
+            "TASK_PLAN total_pages=%d selected_pages=%d completed_before=%d pending_pages=%d output=%s",
-        print(f"Output: {document_dir}")
+            page_count,
+            len(selected_indexes),
+            completed_before,
+            len(pending_indexes),
+            document_dir,
+        )
 
         run_page_times: list[float] = []
         for position, page_index in enumerate(pending_indexes, start=1):
@@ -408,10 +429,19 @@ def process_pdf(
             page_started = time.perf_counter()
             render_seconds = 0.0
             ocr_seconds = 0.0
+            export_seconds = 0.0
+            state_save_seconds = 0.0
             render_path = temporary_render_dir / f"page-{page_number:04d}.png"
             if keep_rendered:
                 render_path = document_dir / "rendered" / f"page-{page_number:04d}.png"
 
+            logger.info(
+                "PAGE_START page=%d page_index=%d position=%d/%d",
+                page_number,
+                page_index,
+                position,
+                len(pending_indexes),
+            )
             try:
                 render_started = time.perf_counter()
                 image = render_page(document, page_index, dpi)
@@ -420,6 +450,12 @@ def process_pdf(
                 finally:
                     image.close()
                 render_seconds = time.perf_counter() - render_started
+                logger.info(
+                    "PAGE_RENDERED page=%d seconds=%.3f path=%s",
+                    page_number,
+                    render_seconds,
+                    render_path,
+                )
 
                 if synchronize:
                     synchronize()
@@ -428,9 +464,11 @@ def process_pdf(
                 if synchronize:
                     synchronize()
                 ocr_seconds = time.perf_counter() - ocr_started
+                logger.info("PAGE_OCR_COMPLETED page=%d seconds=%.3f", page_number, ocr_seconds)
                 if not result_list:
                     raise RuntimeError("OCR pipeline 未返回结果")
 
+                export_started = time.perf_counter()
                 result = result_list[0]
                 markdown_text = _result_markdown(result, document_dir, page_number)
                 result_json = _result_json(result)
@@ -444,6 +482,7 @@ def process_pdf(
                 markdown_path, json_path = _page_paths(document_dir, page_number)
                 atomic_write_text(markdown_path, markdown_text.rstrip() + "\n")
                 atomic_write_json(json_path, result_json)
+                export_seconds = time.perf_counter() - export_started
 
                 total_seconds = time.perf_counter() - page_started
                 manifest["pages"][str(page_number)] = {
@@ -451,6 +490,7 @@ def process_pdf(
                     "page_number": page_number,
                     "render_seconds": round(render_seconds, 3),
                     "ocr_seconds": round(ocr_seconds, 3),
+                    "export_seconds": round(export_seconds, 3),
                     "total_seconds": round(total_seconds, 3),
                     "width": result.get("width"),
                     "height": result.get("height"),
@@ -460,11 +500,27 @@ def process_pdf(
                     "completed_at": now_iso(),
                 }
                 run_page_times.append(total_seconds)
+                logger.info(
+                    "PAGE_RESULT_SAVED page=%d seconds=%.3f markdown=%s json=%s width=%s height=%s layout_boxes=%d parsed_blocks=%d",
+                    page_number,
+                    export_seconds,
+                    markdown_path,
+                    json_path,
+                    result.get("width"),
+                    result.get("height"),
+                    len(result.get("layout_det_res", {}).get("boxes", [])),
+                    len(result.get("parsing_res_list", [])),
+                )
             except KeyboardInterrupt:
                 manifest["status"] = "interrupted"
                 manifest["updated_at"] = now_iso()
                 atomic_write_json(manifest_path, manifest)
                 rebuild_combined_outputs(document_dir, manifest)
+                logger.warning(
+                    "TASK_INTERRUPTED page=%d elapsed_seconds=%.3f",
+                    page_number,
+                    time.perf_counter() - task_started,
+                )
                 raise
             except Exception as exc:
                 total_seconds = time.perf_counter() - page_started
@@ -473,11 +529,19 @@ def process_pdf(
                     "page_number": page_number,
                     "render_seconds": round(render_seconds, 3),
                     "ocr_seconds": round(ocr_seconds, 3),
+                    "export_seconds": round(export_seconds, 3),
                     "total_seconds": round(total_seconds, 3),
                     "error": f"{type(exc).__name__}: {exc}",
                     "failed_at": now_iso(),
                 }
-                print(f"[FAILED] Page {page_number}: {exc}")
+                logger.exception(
+                    "PAGE_FAILED page=%d render_seconds=%.3f ocr_seconds=%.3f export_seconds=%.3f total_seconds=%.3f",
+                    page_number,
+                    render_seconds,
+                    ocr_seconds,
+                    export_seconds,
+                    total_seconds,
+                )
                 if fail_fast:
                     manifest["status"] = "failed"
                     manifest["updated_at"] = now_iso()
@@ -488,19 +552,33 @@ def process_pdf(
                 if not keep_rendered and render_path.is_file():
                     render_path.unlink()
 
+            state_save_started = time.perf_counter()
             manifest["updated_at"] = now_iso()
             atomic_write_json(manifest_path, manifest)
             rebuild_combined_outputs(document_dir, manifest)
+            state_save_seconds = time.perf_counter() - state_save_started
+            manifest["pages"][str(page_number)]["state_save_seconds"] = round(state_save_seconds, 3)
+            atomic_write_json(manifest_path, manifest)
 
             processed_now = position
             average = sum(run_page_times) / len(run_page_times) if run_page_times else None
             remaining = len(pending_indexes) - processed_now
             eta = average * remaining if average is not None else None
             record = manifest["pages"][str(page_number)]
-            print(
+            elapsed_task = time.perf_counter() - task_started
-                f"[{processed_now}/{len(pending_indexes)}] Page {page_number}: "
+            logger.info(
-                f"{record['status']}, OCR {format_duration(record.get('ocr_seconds'))}, "
+                "PAGE_FINISHED page=%d status=%s render_seconds=%.3f ocr_seconds=%.3f export_seconds=%.3f state_save_seconds=%.3f page_total_seconds=%.3f task_elapsed_seconds=%.3f eta_seconds=%s progress=%d/%d",
-                f"ETA {format_duration(eta)}"
+                page_number,
+                record["status"],
+                record.get("render_seconds", 0.0),
+                record.get("ocr_seconds", 0.0),
+                record.get("export_seconds", 0.0),
+                state_save_seconds,
+                record.get("total_seconds", 0.0),
+                elapsed_task,
+                f"{eta:.3f}" if eta is not None else "unknown",
+                processed_now,
+                len(pending_indexes),
             )
 
         if temporary_render_dir.exists():
@@ -513,16 +591,62 @@ def process_pdf(
             record.get("page_number") for record in selected_records if record.get("status") == "failed"
         ]
         completed_pages = sum(record.get("status") == "completed" for record in selected_records)
+        completed_records = [record for record in selected_records if record.get("status") == "completed"]
+        render_total = sum(record.get("render_seconds", 0.0) for record in completed_records)
+        ocr_total = sum(record.get("ocr_seconds", 0.0) for record in completed_records)
+        export_total = sum(record.get("export_seconds", 0.0) for record in completed_records)
+        state_save_total = sum(record.get("state_save_seconds", 0.0) for record in selected_records)
+        page_total = sum(record.get("total_seconds", 0.0) for record in selected_records)
+        average_ocr = ocr_total / completed_pages if completed_pages else 0.0
+        average_page = page_total / len(selected_records) if selected_records else 0.0
         manifest["status"] = "completed_with_errors" if failed_pages else "completed"
         manifest["summary"] = {
             "selected_pages": len(selected_indexes),
             "completed_pages": completed_pages,
             "completed_before_resume": completed_before,
             "failed_pages": failed_pages,
+            "timing": {
+                "pdf_open_seconds": round(pdf_open_seconds, 3),
+                "manifest_prepare_seconds": round(manifest_prepare_seconds, 3),
+                "render_total_seconds": round(render_total, 3),
+                "ocr_total_seconds": round(ocr_total, 3),
+                "export_total_seconds": round(export_total, 3),
+                "state_save_total_seconds": round(state_save_total, 3),
+                "page_total_seconds": round(page_total, 3),
+                "average_ocr_seconds": round(average_ocr, 3),
+                "average_page_seconds": round(average_page, 3),
+                "finalize_seconds": 0.0,
+                "task_total_seconds": 0.0,
+            },
         }
+        finalize_started = time.perf_counter()
         manifest["updated_at"] = now_iso()
         atomic_write_json(manifest_path, manifest)
         rebuild_combined_outputs(document_dir, manifest)
+        finalize_seconds = time.perf_counter() - finalize_started
+        task_total = time.perf_counter() - task_started
+        manifest["summary"]["timing"]["finalize_seconds"] = round(finalize_seconds, 3)
+        manifest["summary"]["timing"]["task_total_seconds"] = round(task_total, 3)
+        atomic_write_json(manifest_path, manifest)
+        rebuild_combined_outputs(document_dir, manifest)
+        logger.info(
+            "TASK_COMPLETED status=%s selected_pages=%d completed_pages=%d failed_pages=%s pdf_open_seconds=%.3f manifest_prepare_seconds=%.3f render_total_seconds=%.3f ocr_total_seconds=%.3f export_total_seconds=%.3f state_save_total_seconds=%.3f page_total_seconds=%.3f average_ocr_seconds=%.3f average_page_seconds=%.3f finalize_seconds=%.3f task_total_seconds=%.3f",
+            manifest["status"],
+            len(selected_indexes),
+            completed_pages,
+            failed_pages,
+            pdf_open_seconds,
+            manifest_prepare_seconds,
+            render_total,
+            ocr_total,
+            export_total,
+            state_save_total,
+            page_total,
+            average_ocr,
+            average_page,
+            finalize_seconds,
+            task_total,
+        )
 
         return {
             "document_dir": str(document_dir),