5.8 KiB
后端性能日志排查
此功能不需要安装 py-spy、perf 等工具。后台会为业务 /api/ 请求打印一行简洁耗时（健康检查和 worker 池控制接口除外）；超过 500 ms、返回 5xx 或抛出异常的请求会附带分阶段细节。每 5 秒最多报告一次超过 200 ms 的事件循环卡顿。日志不记录请求体、聊天内容、查询参数、SQL 原文、账号信息或密钥。
查看慢接口阶段耗时
更新并重启后台后，在宿主机执行：
docker logs --since 10m cmzs-deerflow-deerflow-backend-1 2>&1 | grep 'PERF'
慢请求会有一行 PERF http_request 日志，主要字段：
total_ms：完整请求耗时。headers_ms：服务开始返回响应头前的耗时；大通常说明服务端处理或等待较慢。endpoint_ms：接口函数本身的耗时。outside_handler_ms：接口函数以外的耗时，包括鉴权、中间件、依赖解析和响应序列化。stages：接口内部分阶段的耗时，单位为毫秒。event_loop_lag_ms：最近测得的主事件循环延迟。node、worker_access_ms、worker_upstream_headers_ms、worker_fallback：请求是否走子 work、代理耗时，以及是否因容量不足回退主服务。api_inflight_start/route_inflight_start：请求刚进入时正在处理的 API 总数、同一路由请求数；*_end是该请求结束记录时仍在处理的数量。db_pool：慢请求、异常请求和并发达到 8 个时，记录业务数据库连接池已借出数、池大小和溢出连接数。用于判断首屏并发/连续刷新是否挤满 MySQL 连接池。exception_type：只记录异常类型，不记录可能含敏感数据的异常消息。status=499：浏览器刷新、切页或取消请求导致服务端提前结束，不表示接口内部失败。
接口 INFO 日志依赖后台日志级别允许 INFO。若 config.yaml 中设置为 WARNING，请临时调到 INFO；慢请求和 5xx 仍会以 WARNING/ERROR 级别记录。
重点接口的 stages 含义：
auth_options：load_system_settings是系统设置读取；count_admin_users是业务库查询。agents_list：agents_*_query_db和*_db是数据库调用；agent_response_models、agents_filter_and_sort是进程内转换/排序；agents_*_assembly汇总列表组装耗时。llmwiki_knowledge_bases：weknora_knowledge_base_list_wait是等待 WeKnora 列表结果；local_knowledge_base_query_db是本地数据库查询；conversation_deposit_mapping_sync是会话知识库映射同步。llmwiki_agent_knowledge_bases：actor_and_agent_access是用户与智能体权限查询；load_agent_binding_config是读取智能体配置文件；local_knowledge_base_mapping_query是按智能体绑定 ID 读取本地映射；weknora_knowledge_base_list_wait是等待远端列表。
知识库列表接口（/api/llmwiki/knowledge-bases 和智能体绑定列表 /api/llmwiki/agents/{id}/knowledge-bases）会等待 WeKnora 列表请求，进程内缓存有效期为 15 秒。若 PERF http_request 的 stages.weknora_knowledge_base_list_wait 接近 16 秒，同时出现相近耗时的 PERF weknora_knowledge_base_list upstream_ms=...，就能确认主要耗时在 WeKnora 请求。PERF weknora_http_request 会把远端目录请求拆成 auth_ms（获取/刷新 WeKnora 登录凭据）与 network_ms（HTTP 请求等待）；这样能看出慢在登录还是远端 API 网络/处理。若远端耗时很快但接口仍慢，则看其他阶段。智能体绑定接口另记录 actor_and_agent_access（权限与智能体查询）、load_agent_binding_config（配置文件读取）和 local_knowledge_base_mapping_query（本地数据库映射查询）。
ORM 数据库执行时间超过 500 ms 会打印 PERF db_query，包含请求 ID、数据库类型、SQL 操作类型、耗时和 SQL 指纹，不包含 SQL 语句和参数。请求 ID 与 http_request 行相同，可据此判断慢 SQL 属于哪个接口。SQL 错误只记录错误类型。可用 DEERFLOW_SLOW_SQL_LOG_MS 单独调整数据库慢查询阈值。
首屏或反复刷新若引起请求洪峰，可看同一时间 api_inflight_start、route_inflight_start 是否升高，以及 db_pool.checked_out 是否逼近 size + max_overflow。如果接口等待明显但没有慢 SQL，重点看 event_loop_lag_ms 和 outside_handler_ms；这表示等待可能发生在连接获取、文件/磁盘、鉴权中间件或其它同步代码中。
如果 total_ms 很高、接口 stages 都很低，或同时出现 PERF event_loop_stall，问题更可能在接口函数之外的中间件/同步代码，或事件循环被其他任务占用。可以在卡顿发生时抓当下正在执行的 Python 函数。
抓当前 Python 函数堆栈
后台启动时会注册标准库 faulthandler 的 SIGUSR1 处理器。先在宿主机查容器里的 Python 主机 PID，再发信号：
docker top cmzs-deerflow-deerflow-backend-1 -eo pid,ppid,comm,args
sudo kill -USR1 <上一步查到的Python主机PID>
docker logs --since 2m cmzs-deerflow-deerflow-backend-1 2>&1 | less
在 Current thread 段查看最忙线程当时的 Python 文件和函数；其它线程也会一起输出。请在 CPU 正高时连续抓 2 到 3 次，每次间隔几秒：同一个函数反复出现通常是持续热点，不同调用栈则可能是瞬时任务。
若运行环境已有程序占用 SIGUSR1，可在后台容器环境设置 DEERFLOW_ENABLE_STACK_DUMP=0 关闭此处理器。额外详细输出可临时设置 DEERFLOW_PERF_DIAGNOSTICS=1，只会逐次记录 options、agents、知识库列表和智能体绑定知识库接口；HTTP 慢请求阈值可通过 DEERFLOW_SLOW_REQUEST_LOG_MS 调整，默认 500 ms。修改环境变量后需重启后台。