跳至主要內容

第2336篇：Java AI应用的日志最佳实践——结构化日志与LLM调用追踪

老张2026/4/30大约 5 分钟

第2336篇：Java AI应用的日志最佳实践——结构化日志与LLM调用追踪

适读人群：负责AI服务运维和排障的Java工程师，希望提升AI应用可观测性的开发者 | 阅读时长：约16分钟 | 核心价值：建立完整的AI应用日志体系，实现LLM调用全链路追踪

生产环境出问题了，日志里只有这么一行：

2026-04-15 14:23:11 ERROR - AI调用失败

然后呢？没有了。不知道是什么请求，不知道Prompt是什么，不知道是超时还是限流还是服务宕机，不知道之前的上下文是什么。

这是我接手一个AI项目时看到的实际日志状态。整个项目3个月里遇到的所有AI故障，都是靠"猜"来定位的。

好的AI应用日志体系，不是打更多日志，而是打对的日志，打能让你在10分钟内定位任何问题的日志。

AI应用日志的特殊需求

传统应用日志关注：异常、慢请求、数据库查询。

AI应用除了上面这些，还需要：

  • 完整的Prompt内容（但要脱敏敏感信息）
  • Token用量（成本追踪）
  • 模型版本（知道是哪个模型的问题）
  • 响应时间分布（LLM延迟比普通接口高很多）
  • Retrieval质量（RAG场景的检索结果）

结构化日志：用JSON而不是文本

AI应用的日志量大，信息复杂，必须用结构化日志才能高效搜索：

<!-- Logback配置：JSON格式输出 -->
<!-- pom.xml -->
<dependency>
    <groupId>net.logstash.logback</groupId>
    <artifactId>logstash-logback-encoder</artifactId>
    <version>7.4</version>
</dependency>
<!-- logback-spring.xml -->
<configuration>
    <appender name="JSON_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>logs/ai-service.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>logs/ai-service.%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder class="net.logstash.logback.encoder.LogstashEncoder">
            <!-- 自定义字段 -->
            <customFields>{"service":"ai-service","env":"${spring.profiles.active}"}</customFields>
            <!-- 包含MDC -->
            <includeMdc>true</includeMdc>
        </encoder>
    </appender>
    
    <!-- 开发环境用可读格式 -->
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>
    
    <root level="INFO">
        <appender-ref ref="JSON_FILE"/>
        <appender-ref ref="CONSOLE"/>
    </root>
</configuration>

LLM调用追踪：核心日志字段

/**
 * LLM调用的追踪日志
 * 包含一次LLM调用的完整信息
 */
@Builder
public record LlmCallTrace(
        String traceId,          // 追踪ID（关联前后日志）
        String sessionId,        // 会话ID
        String userId,           // 用户ID
        String modelName,        // 模型名称（如gpt-4o, deepseek-chat）
        String promptHash,       // Prompt的MD5摘要（不存全文，节省存储）
        int promptLength,        // Prompt字符数
        int promptTokens,        // 实际消耗的Prompt Token数
        int completionTokens,    // 输出Token数
        int totalTokens,         // 总Token数
        long durationMs,         // 调用耗时（毫秒）
        String status,           // SUCCESS / TIMEOUT / RATE_LIMIT / ERROR
        String errorMessage,     // 错误信息（status为ERROR时）
        String ragQuery,         // RAG查询词（RAG场景）
        int ragRetrievedDocs,    // RAG检索文档数
        double ragTopScore       // RAG最高相关性分数
) {}
/**
 * LLM调用追踪的Advisor
 * 透明地记录每次LLM调用的关键信息
 */
@Component
@Slf4j
public class TracingAdvisor implements CallAroundAdvisor, StreamAroundAdvisor {
    
    private static final Logger AI_TRACE_LOG = LoggerFactory.getLogger("AI_TRACE");
    private static final int MAX_PROMPT_LOG_LENGTH = 500;
    
    @Override
    public String getName() { return "TracingAdvisor"; }
    
    @Override
    public int getOrder() { return Ordered.HIGHEST_PRECEDENCE; }  // 在最外层，捕获完整时间
    
    @Override
    public AdvisedResponse aroundCall(AdvisedRequest request, CallAroundAdvisorChain chain) {
        String traceId = MDC.get("traceId");
        long start = System.currentTimeMillis();
        String status = "SUCCESS";
        String errorMsg = null;
        AdvisedResponse response = null;
        
        try {
            response = chain.nextAroundCall(request);
            return response;
        } catch (Exception e) {
            status = classifyError(e);
            errorMsg = e.getMessage();
            throw e;
        } finally {
            long duration = System.currentTimeMillis() - start;
            
            // 构建追踪日志
            Map<String, Object> traceFields = buildTraceFields(
                    traceId, request, response, status, errorMsg, duration);
            
            // 用结构化日志记录
            AI_TRACE_LOG.info("LLM调用追踪", StructuredArguments.entries(traceFields));
            
            // 超过5秒的调用额外打WARNING
            if (duration > 5000) {
                log.warn("LLM慢调用：耗时{}ms，traceId={}", duration, traceId);
            }
        }
    }
    
    private Map<String, Object> buildTraceFields(
            String traceId, AdvisedRequest request, AdvisedResponse response,
            String status, String errorMsg, long duration) {
        
        Map<String, Object> fields = new LinkedHashMap<>();
        fields.put("trace_id", traceId);
        fields.put("duration_ms", duration);
        fields.put("status", status);
        
        // Prompt信息（不存完整内容，只存摘要）
        String userText = request.userText();
        fields.put("prompt_hash", DigestUtils.md5Hex(userText));
        fields.put("prompt_length", userText.length());
        
        // 打印Prompt的前N个字符（便于调试，但要脱敏）
        String promptPreview = sanitizePrompt(userText);
        fields.put("prompt_preview", promptPreview);
        
        // Token用量（从响应中提取）
        if (response != null && response.response() != null) {
            Usage usage = response.response().getMetadata().getUsage();
            if (usage != null) {
                fields.put("prompt_tokens", usage.getPromptTokens());
                fields.put("completion_tokens", usage.getGenerationTokens());
                fields.put("total_tokens", usage.getTotalTokens());
            }
        }
        
        if (errorMsg != null) {
            fields.put("error", errorMsg);
        }
        
        return fields;
    }
    
    private String classifyError(Exception e) {
        String message = e.getMessage();
        if (message != null) {
            if (message.contains("429") || message.contains("Rate limit")) return "RATE_LIMIT";
            if (message.contains("timeout") || message.contains("Timeout")) return "TIMEOUT";
            if (message.contains("503") || message.contains("Service Unavailable")) return "SERVICE_UNAVAILABLE";
        }
        return "ERROR";
    }
    
    private String sanitizePrompt(String prompt) {
        if (prompt == null) return "";
        // 脱敏处理：移除可能的手机号、邮箱等敏感信息
        String sanitized = prompt
                .replaceAll("1[3-9]\\d{9}", "[手机号]")
                .replaceAll("[a-zA-Z0-9._%+-]+@[a-zA-Z0-9.-]+\\.[a-zA-Z]{2,}", "[邮箱]")
                .replaceAll("\\d{18}", "[身份证]");
        
        // 只保留前MAX_PROMPT_LOG_LENGTH个字符
        return sanitized.length() > MAX_PROMPT_LOG_LENGTH 
                ? sanitized.substring(0, MAX_PROMPT_LOG_LENGTH) + "..."
                : sanitized;
    }
    
    @Override
    public Flux<AdvisedResponse> aroundStream(AdvisedRequest request, StreamAroundAdvisorChain chain) {
        long start = System.currentTimeMillis();
        AtomicInteger tokenCount = new AtomicInteger(0);
        
        return chain.nextAroundStream(request)
                .doOnNext(r -> {
                    // 统计流式输出的token数（粗略估计）
                    if (r.response() != null && r.response().getResult() != null) {
                        String content = r.response().getResult().getOutput().getContent();
                        if (content != null) {
                            tokenCount.addAndGet(content.length() / 4);  // 粗略估算
                        }
                    }
                })
                .doOnComplete(() -> {
                    long duration = System.currentTimeMillis() - start;
                    AI_TRACE_LOG.info("LLM流式调用完成",
                            StructuredArguments.keyValue("duration_ms", duration),
                            StructuredArguments.keyValue("estimated_tokens", tokenCount.get()),
                            StructuredArguments.keyValue("trace_id", MDC.get("traceId")));
                });
    }
}

MDC：传播追踪上下文

用MDC把traceId贯穿整个请求链路：

@Component
public class TraceContextFilter extends OncePerRequestFilter {
    
    @Override
    protected void doFilterInternal(HttpServletRequest request,
                                     HttpServletResponse response,
                                     FilterChain chain) throws ServletException, IOException {
        // 从请求头获取traceId，或者生成新的
        String traceId = Optional.ofNullable(request.getHeader("X-Trace-Id"))
                .orElse(UUID.randomUUID().toString().replace("-", "").substring(0, 16));
        
        String userId = Optional.ofNullable(request.getHeader("X-User-Id"))
                .orElse("anonymous");
        
        // 设置MDC（所有后续日志都会包含这些字段）
        MDC.put("traceId", traceId);
        MDC.put("userId", userId);
        MDC.put("requestPath", request.getRequestURI());
        
        // 把traceId写回响应头，方便前端关联
        response.setHeader("X-Trace-Id", traceId);
        
        try {
            chain.doFilter(request, response);
        } finally {
            MDC.clear();  // 请求结束后清理
        }
    }
}

日志分析：快速定位问题

有了结构化日志，用ELK或简单的命令行就能快速分析：

# 找到最近1小时所有RATE_LIMIT错误
cat logs/ai-service.log | jq 'select(.status == "RATE_LIMIT") | select(.@timestamp > "2026-04-15T14:00:00")' | head -20

# 计算平均Token消耗
cat logs/ai-service.log | jq '.total_tokens' | grep -v null | awk '{sum+=$1; count++} END {print "平均Token:", sum/count}'

# 找到最慢的10次调用
cat logs/ai-service.log | jq -s 'sort_by(-.duration_ms) | .[0:10] | .[] | {traceId, duration_ms, prompt_preview}'

# 按用户统计调用量（找异常用户）
cat logs/ai-service.log | jq -r '.userId' | sort | uniq -c | sort -rn | head -20

好的日志体系不是一次配置好就完事，而是要随着系统的问题不断完善。每次生产故障之后，问自己：这次排查用了多久？下次遇到类似问题，日志能让排查时间缩短一半吗？

编辑此页
最近更新:
贡献者: xiaozhangge