57 lines
5.8 KiB
Markdown
57 lines
5.8 KiB
Markdown
# 后端性能日志排查
|
||
|
||
此功能不需要安装 `py-spy`、`perf` 等工具。后台会为业务 `/api/` 请求打印一行简洁耗时（健康检查和 worker 池控制接口除外）；超过 500 ms、返回 5xx 或抛出异常的请求会附带分阶段细节。每 5 秒最多报告一次超过 200 ms 的事件循环卡顿。日志不记录请求体、聊天内容、查询参数、SQL 原文、账号信息或密钥。
|
||
|
||
## 查看慢接口阶段耗时
|
||
|
||
更新并重启后台后，在宿主机执行：
|
||
|
||
```bash
|
||
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，再发信号：
|
||
|
||
```bash
|
||
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。修改环境变量后需重启后台。
|