[Log] Add trace log and add loggingInstrumentor tool

[qwes5s5]

FastDeploy 日志与追踪改进方案

一、需求背景

在 RL Profiler 能力建设 过程中，需要支持用户在分析单条数据时能够下钻到具体服务，进一步分析各模块的耗时情况。

目前推理阶段缺乏细粒度的时间打点数据，无法支撑对推理内部阶段的耗时分布查询。因此，需要对 FastDeploy 推理阶段 进行细化划分，并增加日志打点。

此外，现有日志系统存在以下问题：

1. 日志仅包含时间、进程、消息等预定义信息，缺乏上下文链路信息，无法快速定位所属的 Trace 与 Span。

2. 系统可观测性不足，故障排查效率低。

3. 当前日志格式固定，仅支持 msg 参数，缺乏扩展能力。

为了解决无法快速定位的问题，引入 OpenTelemetry LoggingInstrumentor 工具，将 日志（Logs） 与 追踪（Traces） 关联起来，从而提升系统的可观测性与调试能力。

---

二、改动点

1. 新增 Trace Logger

• 新建 trace_logger，并提供获取函数 get_trace_logger。

• 后续所有 FastDeploy 各阶段耗时打点 均通过此 logger 进行。

• 日志输出至独立文件 trace_logger.log。

2. 新增自定义 Formatter

• 创建新的格式化器 CustomColoredFormatter，与 RL Profiler 格式兼容。

• 支持日志扩展字段 extra={"attributes": {...}}。

• 目前在打印时会添加以下关键信息：

  • request_id

  • user_id

  • event

  • stage

• 有助于后续日志聚合与性能分析。

打点示例

trace_logger.info(
    "preprocess end",
    extra={
        "attributes": {
            "request_id": f"{request_id}",
            "user_id": f"{getattr(request, 'user', '')}",
            "event": "POSTPROCESSING_END",
            "stage": "POSTPROCESSING",
        }
    },
)

打印示例（未开启 Trace）

[2025-10-30 06:33:47,246] [INFO    ] (engine_client.py:add_requests:175)
[thread=140634757722560] [thread_name=MainThread] [timestamp=1761806027246]
[request_id=chatcmpl-114514-29ff96da-3825-41a1-acd8-601890942bef]
[user_id=114514] [event=PREPROCESSING_START] [stage=PREPROCESSING]
preprocess is started

---

3. 引入 LoggingInstrumentor

• 接入 OpenTelemetry LoggingInstrumentor。

• 当系统开启 Trace 时，会自动在日志中注入：

  • otel_trace_id

  • otel_span_id

• 修改 Formatter 逻辑，在日志中体现 Trace 相关字段。

打印示例（开启 Trace）

trace_logger：

[2025-10-30 07:47:28,661] [INFO    ] (engine_client.py:add_requests:175)
[otel_trace_id=cea88436e433abb227589130de85a620]
[otel_span_id=f0e8826f89e7f716]
[thread=139858837144000] [thread_name=MainThread] [timestamp=1761810448661]
[request_id=chatcmpl-b6d68f14-4477-4d9d-a6de-bacc60ea782a]
[event=PREPROCESSING_START] [stage=PREPROCESSING]
preprocess is started

api_server_logger：

INFO 2025-10-30 07:47:28,710 21681 serving_chat.py[line:307]
[otel_trace_id=cea88436e433abb227589130de85a620]
[otel_span_id=f0e8826f89e7f716]
Chat Streaming response send_idx 0:
{"id":"chatcmpl-b6d68f14-4477-4d9d-a6de-bacc60ea782a", ...}

---

4. FastDeploy 阶段划分与打点

在 FastDeploy 各主要阶段插入日志打点，以支持耗时分析与追踪。

阶段划分图

打点事件与阶段对应表

事件描述	event 名称	stage 名称
请求前处理开始	PREPROCESSING_START	PREPROCESSING
请求前处理结束	PREPROCESSING_END	PREPROCESSING
请求调度开始	REQUEST_SCHEDULE_START	SCHEDULE
请求排队开始	REQUEST_QUEUE_START	SCHEDULE
请求排队结束	REQUEST_QUEUE_END	SCHEDULE
资源分配开始	RESOURCE_ALLOCATE_START	SCHEDULE
资源分配结束	RESOURCE_ALLOCATE_END	SCHEDULE
请求调度结束	REQUEST_SCHEDULE_END	SCHEDULE
开始推理	INFERENCE_START	PREFILL
首 Token 生成	FIRST_TOKEN_GENERATED	PREFILL
Decode 开始	DECODE_START	DECODE
推理完成	INFERENCE_END	DECODE
后处理开始	POSTPROCESSING_START	POSTPROCESSING
后处理结束	POSTPROCESSING_END	POSTPROCESSING

[paddle-bot]

Thanks for your contribution!