diff --git a/.gitignore b/.gitignore index d09d3ce..1b28b4f 100644 --- a/.gitignore +++ b/.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/ diff --git a/README.md b/README.md index a6faa41..6e513d9 100644 --- a/README.md +++ b/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` 覆盖。 diff --git a/batch_ocr.py b/batch_ocr.py index 85f03d4..4f337f3 100644 --- a/batch_ocr.py +++ b/batch_ocr.py @@ -1,208 +1,329 @@ -""" -批量 OCR 识别 — 多进程并行加速（系统友好版） +"""System-friendly multiprocessing batch OCR with structured timing logs.""" -修复要点: - 1. 进程错峰启动（随机延迟），避免同时加载 N 个模型导致内存/CUP 打满 - 2. 降低子进程优先级，保证系统 UI 正常响应 - 3. 预留 1-2 个核心给 OS，避免 CPU 完全饱和 - 4. 用 imap_unordered 逐任务分发，而非一次性灌满 +from __future__ import annotations -用法: - 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): - """ - 每个 Worker 启动时：随机延迟 → 设线程数 → 降优先级 → 加载模型。 +PROJECT_ROOT = Path(__file__).resolve().parent +_WORKER_LOG_QUEUE = None +_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 - t0 = time.perf_counter() - result = _pipeline.predict(image_path) - elapsed = time.perf_counter() - t0 - - blocks = [] - for block in result[0]["parsing_res_list"]: - if block.content.strip(): - blocks.append({ - "label": block.label, - "bbox": block.bbox, - "content": block.content, - }) - - return { - "path": str(image_path), - "elapsed": round(elapsed, 2), - "blocks": blocks, - } + global _pipeline, _WORKER_INIT_METRICS + logger = _worker_logger() + started = time.perf_counter() + logger.info("IMAGE_START path=%s", image_path) + try: + result = _pipeline.predict(image_path) + elapsed = time.perf_counter() - started + first = result[0] + blocks = [ + {"label": block.label, "bbox": block.bbox, "content": block.content} + for block in first["parsing_res_list"] + if block.content.strip() + ] + response = { + "path": image_path, + "status": "completed", + "elapsed": round(elapsed, 3), + "width": first.get("width"), + "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 main(): - total_cores = cpu_count() - +def parse_args() -> argparse.Namespace: parser = argparse.ArgumentParser( description="批量 OCR — 多进程并行（系统友好版）", - formatter_class=argparse.RawDescriptionHelpFormatter, - 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 # 指定每进程线程数 - """, + formatter_class=argparse.ArgumentDefaultsHelpFormatter, ) - parser.add_argument("dir", type=str, help="图片目录") - parser.add_argument( - "--workers", type=int, default=2, - help="并行进程数 (默认 2，安全值；最大建议不超过 RAM_GB/2)", - ) - parser.add_argument( - "--threads", type=int, default=None, - help=f"每进程线程数 (默认: (总核心-1)/workers，保证 OS 有 1 核可用)", - ) - parser.add_argument( - "--stagger", type=float, default=15.0, - help="进程启动错峰窗口秒数 (默认 15s，值越大内存峰值越低)", - ) - args = parser.parse_args() + parser.add_argument("dir", type=Path, help="图片目录") + parser.add_argument("--workers", type=int, default=2, help="并行进程数") + parser.add_argument("--threads", type=int, default=None, help="每进程线程数") + parser.add_argument("--stagger", type=float, default=15.0, help="Worker 启动错峰窗口秒数") + 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="不记录 OCR 文本块") + return parser.parse_args() + + +def main() -> int: + program_started = time.perf_counter() + args = 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}") - sys.exit(1) + logger.error("INPUT_DIRECTORY_NOT_FOUND path=%s", image_dir) + 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 = [] - for ext in extensions: - images.extend(image_dir.glob(ext)) - images = sorted(images) - + images = sorted(path for extension in extensions for path in image_dir.glob(extension)) + scan_seconds = time.perf_counter() - scan_started if not images: - print(f"[ERROR] 目录中没有图片: {args.dir}") - sys.exit(1) + logger.error("NO_IMAGES_FOUND path=%s scan_seconds=%.3f", image_dir, scan_seconds) + return 1 - # ── 资源规划 ── + total_cores = cpu_count() workers = min(args.workers, len(images)) - reserved_for_os = 1 # 至少给 OS 留 1 个逻辑核心 - if args.threads: - threads = args.threads - else: - threads = max(1, (total_cores - reserved_for_os) // workers) - + threads = args.threads or max(1, (total_cores - 1) // workers) + if threads < 1: + logger.error("INVALID_ARGUMENT threads=%d", threads) + return 2 total_cpu_used = workers * threads - stagger = args.stagger - - # 内存估算 - model_mem_per_worker = 2.0 # GB, 模型 ~1.8GB + 运行时开销 - estimated_mem = workers * model_mem_per_worker + 2 # +2GB for OS + estimated_mem = workers * 2.0 + 2 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 - mem_ok = True # 无法检测，假定 OK + available_gb = None - # ── 打印配置 ── - print("=" * 60) - print(f" 图片数量: {len(images)}") - print(f" 并行进程: {workers}") - print(f" 每进程线程: {threads}") - print(f" CPU 占用: {total_cpu_used} / {total_cores} 核 (保留 {total_cores - total_cpu_used} 给 OS)") - print(f" 错峰窗口: {stagger}s") - print(f" 预估内存: ~{estimated_mem:.0f}GB (可用: {avail_gb:.0f}GB)" if avail_gb else f" 预估内存: ~{estimated_mem:.0f}GB") - if not mem_ok: - print(f" [WARNING] 可用内存不足！建议降低 --workers 到 {max(1, int((avail_gb - 2) / model_mem_per_worker))}") - print("=" * 60) + logger.info( + "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", + image_dir, + len(images), + scan_seconds, + workers, + threads, + total_cores, + total_cpu_used, + max(0, total_cores - total_cpu_used), + args.stagger, + estimated_mem, + f"{available_gb:.1f}" if available_gb is not None else "unknown", + ) - if not mem_ok: - resp = input("内存不足，是否继续？[y/N] ").strip().lower() - if resp != "y": - print("已取消。") - sys.exit(0) + if available_gb is not None and available_gb <= estimated_mem: + logger.warning( + "MEMORY_PRESSURE estimated_memory_gb=%.1f available_memory_gb=%.1f recommendation=reduce_workers", + estimated_mem, + available_gb, + ) + response = input("可用内存可能不足，是否继续？[y/N] ").strip().lower() + if response != "y": + logger.warning("PROGRAM_CANCELLED_BY_USER") + return 0 - # ── 执行 ── - t0 = time.perf_counter() + pool_started = 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( - processes=workers, - initializer=_init_worker, - initargs=(threads, stagger), - ) as pool: - # imap_unordered: 逐任务分发，先完成的先返回 - # chunk 大 → 吞吐高但内存峰值高；chunk=1 → 最平滑 - image_paths = [str(img) for img in images] - results = list(pool.imap_unordered(_ocr_task, image_paths, chunksize=1)) + pool_seconds = time.perf_counter() - pool_started + completed_results = [result for result in results if result["status"] == "completed"] + failed_results = [result for result in results if result["status"] == "failed"] + worker_metrics = { + result["worker_pid"]: result.get("worker_init", {}) + for result in results + if result.get("worker_pid") is not None + } + 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"), + ) - # ── 输出 ── - print("\n" + "=" * 60) - for r in sorted(results, key=lambda x: x["path"]): - print(f"\n[文件] {r['path']} ({r['elapsed']:.1f}s)") - for block in r["blocks"]: - preview = block["content"].replace("\n", "\\n") - if len(preview) > 80: - preview = preview[:80] + "..." - print(f" [{block['label']}] {preview}") + for result in sorted(results, key=lambda item: item["path"]): + if result["status"] == "completed": + logger.info( + "IMAGE_SUMMARY path=%s seconds=%.3f width=%s height=%s layout_boxes=%d parsed_blocks=%d", + result["path"], + result["elapsed"], + result["width"], + result["height"], + 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) - print("\n" + "=" * 60) - print(f" 总图片: {len(images)}") - print(f" 总耗时: {total_elapsed:.1f}s ({total_elapsed/60:.1f}min)") - print(f" 平均每图: {total_elapsed / len(images):.1f}s") - print(f" 串行预计: {total_per_image:.1f}s") - if total_elapsed > 0: - print(f" 加速比: {total_per_image / total_elapsed:.2f}x") - print("=" * 60) + logger.info( + "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", + len(images), + len(completed_results), + len(failed_results), + scan_seconds, + pool_seconds, + len(worker_metrics), + 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() \ No newline at end of file + raise SystemExit(main()) diff --git a/documents/化肥买卖合同　GF—2000—0102.pdf b/documents/化肥买卖合同　GF—2000—0102.pdf new file mode 100644 index 0000000..ac1a14b Binary files /dev/null and b/documents/化肥买卖合同　GF—2000—0102.pdf differ diff --git a/documents/民用爆破器材买卖合同　GF—2001—0107.pdf b/documents/民用爆破器材买卖合同　GF—2001—0107.pdf new file mode 100644 index 0000000..9c73055 Binary files /dev/null and b/documents/民用爆破器材买卖合同　GF—2001—0107.pdf differ diff --git a/gpu/README.md b/gpu/README.md index b60a154..95fd811 100644 --- a/gpu/README.md +++ b/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/-gpuN-YYYYMMDD-HHMMSS.log +``` + +日志与 `manifest.json` 会记录每页渲染、OCR、结果导出、状态保存、任务总用时和程序总用时。 + ## 当前范围 当前实现单 GPU、单图 Benchmark 和单 GPU PDF 逐页 OCR。暂未实现 GPU 多进程批处理，原因是： diff --git a/gpu/main.py b/gpu/main.py index 728c4c0..9fbec3f 100644 --- a/gpu/main.py +++ b/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) - 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) - + logger.info("MODEL_INITIALIZATION_STARTED pipeline_version=v1.6 device=%s", device) 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]") - print(f"Image: {summary['width']} x {summary['height']}") - print(f"Layout boxes: {summary['layout_boxes']}") - print(f"Parsed blocks: {summary['parsed_blocks']}") - print(f"Average: {benchmark['inference_seconds']['mean']:.3f}s") - print(f"Min/Max: {benchmark['inference_seconds']['min']:.3f}s / {benchmark['inference_seconds']['max']:.3f}s") - print(f"Result JSON: {output_path}") + logger.info( + "RESULT_SUMMARY width=%d height=%d layout_boxes=%d parsed_blocks=%d non_empty_blocks=%d gpu_memory=%s", + summary["width"], + summary["height"], + summary["layout_boxes"], + summary["parsed_blocks"], + 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 diff --git a/gpu/pdf_ocr.py b/gpu/pdf_ocr.py index a5a04ae..3340faf 100644 --- a/gpu/pdf_ocr.py +++ b/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( - f"[PDF] {preflight['page_count']} pages, selected: " - f"{len(preflight['selected_pages'])}, output: {preflight['document_dir']}" + logger.info( + "PREFLIGHT_COMPLETED seconds=%.3f page_count=%d selected_pages=%d document_dir=%s", + preflight_seconds, + preflight["page_count"], + len(preflight["selected_pages"]), + preflight["document_dir"], ) - print(f"[GPU] Device: {device} ({device_name})") - print("Loading PaddleOCR-VL-1.6...") + logger.info( + "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]") - print(f"Status: {summary['status']}") - print(f"Completed: {summary['completed_pages']} / {summary['selected_pages']}") - print(f"Failed: {summary['failed_pages']}") - print(f"Output: {summary['document_dir']}") + program_total = time.perf_counter() - program_started + timing = summary.get("timing", {}) + logger.info( + "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", + 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 diff --git a/main.py b/main.py index eaf21ca..a8f0a8c 100644 --- a/main.py +++ b/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 -from paddleocr import PaddleOCRVL +import statistics +import time +from pathlib import Path -IMAGE_PATH = "images/名片02.jpg" -WARMUP_ROUNDS = 0 -BENCHMARK_ROUNDS = 1 +from ocr_logging import default_log_path, setup_run_logger -# ── 线程配置 ── -# 可通过环境变量 PADDLE_THREADS 覆盖，否则使用逻辑核心数 -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()})") +PROJECT_ROOT = Path(__file__).resolve().parent +DEFAULT_IMAGE = PROJECT_ROOT / "images" / "名片02.jpg" -# ── 模型初始化计时 ── -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 ── -print(f"\n开始 OCR 识别: {IMAGE_PATH}") -print(f"预热 {WARMUP_ROUNDS} 轮 + 正式测试 {BENCHMARK_ROUNDS} 轮\n") +def parse_args() -> argparse.Namespace: + parser = argparse.ArgumentParser( + 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) -# 正式计时 -times = [] -for i in range(BENCHMARK_ROUNDS): - print(f" 推理 {i + 1}/{BENCHMARK_ROUNDS}...", end=" ", flush=True) - t0 = time.perf_counter() - result = pipeline.predict(IMAGE_PATH) - elapsed = time.perf_counter() - t0 - times.append(elapsed) - print(f"{elapsed:.2f}s") +def main() -> int: + program_started = time.perf_counter() + args = parse_args() + image_path = args.image.expanduser().resolve() + log_file = args.log_file or default_log_path(PROJECT_ROOT, "single", image_path.stem, device="cpu") + logger = setup_run_logger("ocr.single.cpu", log_file, verbose=args.verbose) -print("\n" + "=" * 60) -print("[Benchmark]") -print(f" 图片尺寸: {result[0]['width']} x {result[0]['height']}") -print(f" 检测文本块: {len(result[0]['layout_det_res']['boxes'])} 个") -print(f" 识别文本块: {len(result[0]['parsing_res_list'])} 个") -print(f" 推理次数: {BENCHMARK_ROUNDS}") -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) + if not image_path.is_file(): + logger.error("INPUT_NOT_FOUND path=%s", image_path) + return 1 + if args.warmup < 0 or args.rounds < 1: + logger.error("INVALID_ARGUMENT warmup=%d rounds=%d", args.warmup, args.rounds) + return 2 -# ── 输出识别结果 ── -print("\n[识别结果]\n") -for item in result: - for block in item["parsing_res_list"]: - print(f" [{block.label}] ({block.bbox})") - print(f" {block.content}\n") \ No newline at end of file + total_cores = os.cpu_count() or 4 + threads = args.threads or int(os.environ.get("PADDLE_THREADS", total_cores)) + if threads < 1: + logger.error("INVALID_ARGUMENT threads=%d", threads) + return 2 + + 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()) diff --git a/ocr_logging.py b/ocr_logging.py new file mode 100644 index 0000000..0e353cc --- /dev/null +++ b/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) diff --git a/pdf_ocr.py b/pdf_ocr.py index 8fa9b83..b5df4d5 100644 --- a/pdf_ocr.py +++ b/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( - f"[PDF] {preflight['page_count']} pages, selected: " - f"{len(preflight['selected_pages'])}, output: {preflight['document_dir']}" + logger.info( + "PREFLIGHT_COMPLETED seconds=%.3f page_count=%d selected_pages=%d document_dir=%s", + 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)})") - print("Loading PaddleOCR-VL-1.6...") + logger.info( + "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]") - print(f"Status: {summary['status']}") - print(f"Completed: {summary['completed_pages']} / {summary['selected_pages']}") - print(f"Failed: {summary['failed_pages']}") - print(f"Output: {summary['document_dir']}") + program_total = time.perf_counter() - program_started + timing = summary.get("timing", {}) + logger.info( + "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", + 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 diff --git a/pdf_ocr_core.py b/pdf_ocr_core.py index 9ca39a4..f924c52 100644 --- a/pdf_ocr_core.py +++ b/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}") - print(f"Pages: {page_count}, selected: {len(selected_indexes)}, pending: {len(pending_indexes)}") - print(f"Output: {document_dir}") + logger.info( + "TASK_PLAN total_pages=%d selected_pages=%d completed_before=%d pending_pages=%d output=%s", + 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( - f"[{processed_now}/{len(pending_indexes)}] Page {page_number}: " - f"{record['status']}, OCR {format_duration(record.get('ocr_seconds'))}, " - f"ETA {format_duration(eta)}" + elapsed_task = time.perf_counter() - task_started + logger.info( + "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", + 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),