日志打印优化

backend-java/src/main/java/com/pharmacopoeia/controller/ChatController.java

@@ -7,6 +7,8 @@ import com.pharmacopoeia.dto.ImageChatRequest;
 import com.pharmacopoeia.dto.MultimodalChatRequest;
 import com.pharmacopoeia.service.*;
 import jakarta.servlet.http.HttpServletRequest;
+import lombok.extern.slf4j.Slf4j;
+import org.jetbrains.annotations.NotNull;
 import org.springframework.http.MediaType;
 import org.springframework.http.ResponseEntity;
 import org.springframework.http.codec.ServerSentEvent;
@@ -23,6 +25,7 @@ import java.util.stream.Collectors;
 
 @RestController
 @RequestMapping("/api/v1/chat")
+@Slf4j
 public class ChatController {
 
     // 复用 PromptService.SECTION_DISPLAY 统一权威映射，避免两处重复定义导致不一致
@@ -141,22 +144,26 @@ public class ChatController {
         // 检查全局缓存
         Map<String, Object> cached = qaCache.get(normalized);
         if (cached != null) {
-            return streamCached(cached, cid, query, normalized, userKey);
+            return streamCached(cached, cid, query, userKey);
         }
 
         // 未命中缓存：尝试抢占处理权，避免并发重复调 LLM
         if (!qaCache.tryMarkPending(normalized)) {
             Map<String, Object> waited = qaCache.waitForCache(normalized);
             if (waited != null) {
-                return streamCached(waited, cid, query, normalized, userKey);
+                return streamCached(waited, cid, query, userKey);
             }
         }
 
         final String intent = retrieverService.classifyIntent(query);
+        final long t0 = System.currentTimeMillis();
+        log.info("[chatStream] intent={}, query={}", intent, query.substring(0, Math.min(50, query.length())));
 
         return retrieverService.searchReactive(query, intent, 20)
                 .map(docs -> rerankerService.rerank(docs, query, 5))
                 .flatMapMany(docs -> {
+                    long t2 = System.currentTimeMillis();
+                    log.info("[chatStream] search+rerank done, docs={}, elapsed={}ms", docs.size(), t2 - t0);
                     Sinks.Many<ServerSentEvent<String>> sink = Sinks.many().unicast().onBackpressureBuffer();
 
                     sink.tryEmitNext(ServerSentEvent.<String>builder().event("intent").data(intent).build());
@@ -165,6 +172,9 @@ public class ChatController {
 
                     final List<Map<String, String>> messages = promptService.buildPrompt(query, docs, intent);
                     StringBuilder fullAnswer = new StringBuilder();
+                    final long t3 = System.currentTimeMillis();
+                    log.info("[chatStream] prompt built, elapsed={}ms, chars={}",
+                            t3 - t0, messages.stream().mapToInt(m -> m.get("content").length()).sum());
 
                     llmService.chatStream(messages)
                             .doOnNext(token -> {
@@ -183,6 +193,8 @@ public class ChatController {
                                 } catch (Exception ignored) {}
 
                                 String finalAnswer = cleanAnswer(fullAnswer.toString());
+                                long t4 = System.currentTimeMillis();
+                                log.info("[chatStream] chatStream done, llmElapsed={}ms, total={}ms", t4 - t3, t4 - t0);
                                 persistenceService.saveMessage(userKey, cid, "user", query, intent, null);
                                 persistenceService.saveMessage(userKey, cid, "assistant", finalAnswer, intent, sources);
 
@@ -192,6 +204,8 @@ public class ChatController {
                                 sink.tryEmitComplete();
                             })
                             .doOnError(e -> {
+                                long t4 = System.currentTimeMillis();
+                                log.error("[chatStream] LLM error, totalElapsed={}ms, error={}", t4 - t0, e.getMessage());
                                 // 异常时清除 PENDING 标记，避免后续同问题请求被锁死
                                 qaCache.removePending(normalized);
                                 sink.tryEmitError(e);
@@ -204,8 +218,8 @@ public class ChatController {
 
     /** 将缓存命中结果以流式 SSE 形式返回 */
     private Flux<ServerSentEvent<String>> streamCached(Map<String, Object> cached, String cid,
-                                                        String query, String normalized,
-                                                        String userKey) {
+                                                        String query,
+                                                       String userKey) {
         String answer = (String) cached.get("answer");
         String intent = (String) cached.getOrDefault("intent", "");
         @SuppressWarnings("unchecked")
@@ -260,10 +274,9 @@ public class ChatController {
         // Step 3: 构建 Prompt（含图片分析上下文）+ 联网搜索
         List<Map<String, String>> messages = promptService.buildPrompt(query, docs, intent);
         String imageContext = "\n\n【图片分析结果】\n" + ocrText + "\n";
-        messages.get(0).put("content", messages.get(0).get("content") + imageContext);
+        messages.getFirst().put("content", messages.getFirst().get("content") + imageContext);
 
-        String llmAnswer = cleanAnswer(llmService.chat(messages, true));
-        String answer = llmAnswer;
+        String answer = cleanAnswer(llmService.chat(messages, true));
 
         List<Map<String, Object>> sources = buildSources(docs);
         persistenceService.saveMessage(userKey, cid, "user",
@@ -323,7 +336,7 @@ public class ChatController {
                                 // Step 3: 构建 Prompt + 联网搜索流式生成
                                 final List<Map<String, String>> messages = promptService.buildPrompt(query, docs, intent);
                                 String imageContext = "\n\n【图片分析结果】\n" + ocrText + "\n";
-                                messages.get(0).put("content", messages.get(0).get("content") + imageContext);
+                                messages.getFirst().put("content", messages.getFirst().get("content") + imageContext);
 
                                 StringBuilder fullAnswer = new StringBuilder();
                                 llmService.chatStream(messages, true)
@@ -402,13 +415,12 @@ public class ChatController {
         // Step 4: 构建 Prompt + 联网搜索
         List<Map<String, String>> messages = promptService.buildPrompt(query, docs, intent);
         if (!ocrText.isEmpty()) {
-            messages.get(0).put("content",
-                    messages.get(0).get("content") + "\n\n【" + mediaLabel + "分析结果】\n" + ocrText + "\n");
+            messages.getFirst().put("content",
+                    messages.getFirst().get("content") + "\n\n【" + mediaLabel + "分析结果】\n" + ocrText + "\n");
         }
 
         boolean enableSearch = !ocrText.isEmpty() || props.isEnableWebSearch();
-        String llmAnswer = cleanAnswer(llmService.chat(messages, enableSearch));
-        String answer = llmAnswer;
+        String answer = cleanAnswer(llmService.chat(messages, enableSearch));
 
         List<Map<String, Object>> sources = buildSources(docs);
         String userMsg = !request.getMessage().isBlank() ? request.getMessage()
@@ -586,8 +598,8 @@ public class ChatController {
 
                     final List<Map<String, String>> messages = promptService.buildPrompt(query, docs, intent);
                     if (!ocrText.isEmpty()) {
-                        messages.get(0).put("content",
-                                messages.get(0).get("content") + "\n\n【" + mediaLabel + "分析结果】\n" + ocrText + "\n");
+                        messages.getFirst().put("content",
+                                messages.getFirst().get("content") + "\n\n【" + mediaLabel + "分析结果】\n" + ocrText + "\n");
                     }
 
                     // 发送回答 section header
@@ -720,22 +732,12 @@ public class ChatController {
                     }
 
                     // 构建完整来源引用
-                    StringBuilder sourceBuilder = new StringBuilder();
-                    if (!sourceVersion.isEmpty()) {
-                        sourceBuilder.append(sourceVersion);
-                    }
-                    if (!sourceVolume.isEmpty()) {
-                        if (!sourceBuilder.isEmpty()) {
-                            sourceBuilder.append(" ");
-                        }
-                        sourceBuilder.append(sourceVolume);
-                    }
-                    String fullSource = sourceBuilder.toString();
+                    String fullSource = getFullSource(sourceVersion, sourceVolume);
 
                     content = content.replaceAll("\\s*来源：.*$", "");
                     content = content.replaceAll("[\\r\\n]+", " ").trim();
                     String excerpt = content.length() > 500 ? content.substring(0, 500) + "…" : content;
-                    return Map.<String, Object>of(
+                    return Map.of(
                             "drug_id", d.getOrDefault("drug_id", ""),
                             "name", drugName,
                             "section", sectionDisplay,
@@ -758,6 +760,21 @@ public class ChatController {
                 .collect(Collectors.toList());
     }
 
+    @NotNull
+    private static String getFullSource(String sourceVersion, String sourceVolume) {
+        StringBuilder sourceBuilder = new StringBuilder();
+        if (!sourceVersion.isEmpty()) {
+            sourceBuilder.append(sourceVersion);
+        }
+        if (!sourceVolume.isEmpty()) {
+            if (!sourceBuilder.isEmpty()) {
+                sourceBuilder.append(" ");
+            }
+            sourceBuilder.append(sourceVolume);
+        }
+        return sourceBuilder.toString();
+    }
+
     private String extractDrugName(String content) {
         if (content == null) {
             return "";

backend-java/src/main/java/com/pharmacopoeia/service/LLMService.java

@@ -9,6 +9,7 @@ import org.slf4j.LoggerFactory;
 import org.springframework.http.MediaType;
 import org.springframework.stereotype.Service;
 import org.springframework.web.reactive.function.client.WebClient;
+import org.springframework.web.util.UriBuilder;
 import reactor.core.publisher.Flux;
 import reactor.core.publisher.Mono;
 
@@ -62,6 +63,7 @@ public class LLMService {
 
     public Flux<String> chatStream(List<Map<String, String>> messages, boolean enableSearch) {
         checkRateLimit();
+        long t0 = System.currentTimeMillis();
         Map<String, Object> body = new java.util.HashMap<>(Map.of(
                 "model", props.getModel(),
                 "messages", messages,
@@ -72,14 +74,30 @@ public class LLMService {
         if (enableSearch) {
             body.put("enable_search", true);
         }
+        log.info("[chatStream] POST /chat/completions, model={}, msgs={}, bodyBuilt={}ms",
+                props.getModel(), messages.size(), System.currentTimeMillis() - t0);
+
+        final long t1 = System.currentTimeMillis();
         return chatClient.post()
                 .uri("/chat/completions")
                 .contentType(MediaType.APPLICATION_JSON)
                 .bodyValue(body)
                 .retrieve()
                 .bodyToFlux(String.class)
+                .doFirst(() -> {
+                    long elapsed = System.currentTimeMillis() - t1;
+                    log.info("[chatStream] 百炼已响应, latency={}ms (从POST到收到第一个字节)", elapsed);
+                })
                 .filter(data -> !"[DONE]".equals(data.trim()))
-                .map(this::extractDeltaContent);
+                .map(this::extractDeltaContent)
+                .doOnComplete(() -> {
+                    long total = System.currentTimeMillis() - t0;
+                    log.info("[chatStream] 流结束, total={}ms", total);
+                })
+                .doOnError(e -> {
+                    long total = System.currentTimeMillis() - t0;
+                    log.error("[chatStream] 流出错, total={}ms, error={}", total, e.getMessage());
+                });
     }
 
     public String chat(List<Map<String, String>> messages) {
@@ -88,6 +106,7 @@ public class LLMService {
 
     public String chat(List<Map<String, String>> messages, boolean enableSearch) {
         checkRateLimit();
+        long t0 = System.currentTimeMillis();
         Map<String, Object> body = new java.util.HashMap<>(Map.of(
                 "model", props.getModel(),
                 "messages", messages,
@@ -97,6 +116,7 @@ public class LLMService {
         if (enableSearch) {
             body.put("enable_search", true);
         }
+        long t1 = System.currentTimeMillis();
         String response = chatClient.post()
                 .uri("/chat/completions")
                 .contentType(MediaType.APPLICATION_JSON)
@@ -104,6 +124,9 @@ public class LLMService {
                 .retrieve()
                 .bodyToMono(String.class)
                 .block();
+        long t2 = System.currentTimeMillis();
+        log.info("[chat] POST /chat/completions completed, latency={}ms, bodyBuilt={}ms, total={}ms",
+                t2 - t1, t1 - t0, t2 - t0);
 
         try {
             JsonNode node = mapper.readTree(response);
@@ -149,7 +172,7 @@ public class LLMService {
         body.put("parameters", Map.of("max_tokens", 2048));
 
         String response = visionClient.post()
-                .uri(props.getMultimodalUrl(), uri -> uri.build())
+                .uri(props.getMultimodalUrl(), UriBuilder::build)
                 .contentType(MediaType.APPLICATION_JSON)
                 .bodyValue(body)
                 .retrieve()
@@ -161,7 +184,7 @@ public class LLMService {
             // 原生 API 响应：output.choices[0].message.content[0].text
             JsonNode content = node.get("output").get("choices").get(0)
                     .get("message").get("content");
-            if (content.isArray() && content.size() > 0) {
+            if (content.isArray() && !content.isEmpty()) {
                 return content.get(0).get("text").asText();
             }
             return content.asText();
@@ -193,7 +216,7 @@ public class LLMService {
         body.put("parameters", Map.of("max_tokens", 2048, "stream", true, "incremental_output", true));
 
         return visionClient.post()
-                .uri(props.getMultimodalUrl(), uri -> uri.build())
+                .uri(props.getMultimodalUrl(), UriBuilder::build)
                 .contentType(MediaType.APPLICATION_JSON)
                 .bodyValue(body)
                 .retrieve()
@@ -231,7 +254,7 @@ public class LLMService {
         body.put("parameters", Map.of("max_tokens", 2048));
 
         String response = visionClient.post()
-                .uri(props.getMultimodalUrl(), uri -> uri.build())
+                .uri(props.getMultimodalUrl(), UriBuilder::build)
                 .contentType(MediaType.APPLICATION_JSON)
                 .bodyValue(body)
                 .retrieve()
@@ -242,7 +265,7 @@ public class LLMService {
             JsonNode node = mapper.readTree(response);
             JsonNode content = node.get("output").get("choices").get(0)
                     .get("message").get("content");
-            if (content.isArray() && content.size() > 0) {
+            if (content.isArray() && !content.isEmpty()) {
                 return content.get(0).get("text").asText();
             }
             return content.asText();
@@ -271,7 +294,7 @@ public class LLMService {
         body.put("parameters", Map.of("max_tokens", 2048, "stream", true, "incremental_output", true));
 
         return visionClient.post()
-                .uri(props.getMultimodalUrl(), uri -> uri.build())
+                .uri(props.getMultimodalUrl(), UriBuilder::build)
                 .contentType(MediaType.APPLICATION_JSON)
                 .bodyValue(body)
                 .retrieve()
@@ -307,18 +330,16 @@ public class LLMService {
         if (result.isEmpty()) {
             return List.of();
         }
-        return result.get(0);
-    }
-
-    public List<List<Float>> embed(List<String> texts) {
-        return embedBatch(texts);
+        return result.getFirst();
     }
 
     private List<List<Float>> embedBatch(List<String> texts) {
         checkRateLimit();
+        long t0 = System.currentTimeMillis();
         int maxRetries = 3;
         for (int attempt = 1; attempt <= maxRetries; attempt++) {
             try {
+                long t1 = System.currentTimeMillis();
                 String response = embedClient.post()
                         .uri(props.getEmbeddingUrl())
                         .contentType(MediaType.APPLICATION_JSON)
@@ -330,10 +351,12 @@ public class LLMService {
                         .retrieve()
                         .bodyToMono(String.class)
                         .block();
+                long t2 = System.currentTimeMillis();
+                log.info("[embed] POST embedding latency={}ms, texts={}", t2 - t1, texts.size());
 
                 JsonNode node = mapper.readTree(response);
                 var embeddings = node.get("output").get("embeddings");
-                return Flux.fromIterable(embeddings)
+                var result = Flux.fromIterable(embeddings)
                         .map(e -> Flux.fromIterable(e.get("embedding"))
                                 .map(JsonNode::asDouble)
                                 .map(Double::floatValue)
@@ -341,9 +364,11 @@ public class LLMService {
                                 .block())
                         .collectList()
                         .block();
+                log.info("[embed] total={}ms (含解析), attempt={}", System.currentTimeMillis() - t0, attempt);
+                return result;
             } catch (Exception e) {
                 if (attempt < maxRetries) {
-                    log.warn("Embedding API 失败，第 {} 次重试...", attempt);
+                    log.warn("Embedding API失败，第 {} 次重试...", attempt);
                     try { Thread.sleep(attempt * 1000L); } catch (InterruptedException ignored) {}
                 } else {
                     log.error("Embedding API 重试 {} 次后仍失败，降级返回空", maxRetries, e);
@@ -360,7 +385,7 @@ public class LLMService {
 
     public Mono<List<Float>> embedReactive(String text) {
         return embedReactiveBatch(List.of(text))
-                .map(result -> result.isEmpty() ? List.<Float>of() : result.get(0));
+                .map(result -> result.isEmpty() ? List.of() : result.getFirst());
     }
 
     private Mono<List<List<Float>>> embedReactiveBatch(List<String> texts) {
@@ -417,7 +442,7 @@ public class LLMService {
             }
             JsonNode node = mapper.readTree(json);
             var choices = node.get("choices");
-            if (choices != null && choices.size() > 0) {
+            if (choices != null && !choices.isEmpty()) {
                 var delta = choices.get(0).get("delta");
                 if (delta != null) {
                     var content = delta.get("content");
@@ -442,9 +467,9 @@ public class LLMService {
             JsonNode output = node.get("output");
             if (output != null) {
                 var choices = output.get("choices");
-                if (choices != null && choices.size() > 0) {
+                if (choices != null && !choices.isEmpty()) {
                     var msgContent = choices.get(0).get("message").get("content");
-                    if (msgContent != null && msgContent.isArray() && msgContent.size() > 0) {
+                    if (msgContent != null && msgContent.isArray() && !msgContent.isEmpty()) {
                         var text = msgContent.get(0).get("text");
                         return text != null ? text.asText() : "";
                     }