添加日志

ad-engine-commons/src/main/java/com/tzld/piaoquan/ad/engine/commons/score/model/PAIModelV2.java

@@ -211,8 +211,10 @@ public class PAIModelV2 {
             List<Float> result = response.getFloatVals("probs");
 
             long totalTime = System.currentTimeMillis() - totalStart;
-            LOGGER.info("PAIModelV2 score itemSize={} totalTime={}ms buildFeature={}ms predict={}ms",
-                    items.size(), totalTime, buildFeatureTime, predictTime);
+            if (totalTime > 300) {
+                LOGGER.error("PAIModelV2 score slow itemSize={} totalTime={}ms buildFeature={}ms predict={}ms",
+                        items.size(), totalTime, buildFeatureTime, predictTime);
+            }
 
             if (!CollectionUtils.isEmpty(result)) {
                 return result;

ad-engine-service/src/main/java/com/tzld/piaoquan/ad/engine/service/score/scorer/PAIScorerV2.java

@@ -21,6 +21,7 @@ import java.util.concurrent.ExecutionException;
 import java.util.concurrent.ExecutorService;
 import java.util.concurrent.Future;
 import java.util.concurrent.TimeUnit;
+import java.util.concurrent.TimeoutException;
 
 public class PAIScorerV2 extends AbstractScorer {
 
@@ -102,31 +103,45 @@ public class PAIScorerV2 extends AbstractScorer {
         for (List<AdRankItem> batch : batches) {
             futures.add(executor.submit(() -> {
                 long queueWaitTime = System.currentTimeMillis() - submitTime;
+                long batchStartTime = System.currentTimeMillis();
                 try {
                     multipleCtrScore(batch, userFeatureMap, sceneFeatureMap, model);
                 } catch (Exception e) {
                     LOGGER.error("Error during multipleCtrScore batch execution", e);
                 }
-                LOGGER.info("PAIScorerV2 batch done batchSize={} queueWaitTime={}ms",
-                        batch.size(), queueWaitTime);
+                long batchExecuteTime = System.currentTimeMillis() - batchStartTime;
+                if (queueWaitTime > 100) {
+                    LOGGER.error("PAIScorerV2 batch queue wait too long batchSize={} queueWaitTime={}ms executeTime={}ms",
+                            batch.size(), queueWaitTime, batchExecuteTime);
+                }
                 return batch;
             }));
         }
 
         // 合并结果
         List<AdRankItem> merged = new ArrayList<>();
+        int batchIndex = 0;
         for (Future<List<AdRankItem>> future : futures) {
+            long getStartTime = System.currentTimeMillis();
             try {
                 merged.addAll(future.get(400, TimeUnit.MILLISECONDS));
+            } catch (TimeoutException e) {
+                long waitTime = System.currentTimeMillis() - getStartTime;
+                LOGGER.error("PAIScorerV2 batch timeout batchIndex={} waitTime={}ms totalElapsed={}ms",
+                        batchIndex, waitTime, System.currentTimeMillis() - startTime);
             } catch (Exception e) {
-                LOGGER.error("Execution error in batch", e);
+                LOGGER.error("Execution error in batch batchIndex={}", batchIndex, e);
             }
+            batchIndex++;
         }
 
         Collections.sort(merged);
 
-        LOGGER.info("PAIScorerV2 rankByJava done itemSize={} batchCount={} totalTime={}ms",
-                items.size(), batches.size(), System.currentTimeMillis() - startTime);
+        long totalTime = System.currentTimeMillis() - startTime;
+        if (totalTime > 300) {
+            LOGGER.error("PAIScorerV2 rankByJava slow itemSize={} batchCount={} totalTime={}ms",
+                    items.size(), batches.size(), totalTime);
+        }
         return merged;
     }