添加日志

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

@@ -126,9 +126,15 @@ public class PAIModelV2 {
     public List<Float> score(final List<AdRankItem> items,
                              final Map<String, String> userFeatureMap,
                              final Map<String, String> sceneFeatureMap) {
+        long totalStart = System.currentTimeMillis();
+        long buildFeatureTime = 0;
+        long predictTime = 0;
+
         try {
             TFRequest request = new TFRequest();
 
+            // 阶段1：构建用户/场景特征
+            long stageStart = System.currentTimeMillis();
             for (String feature : sparseUserStrFeatures) {
                 String v = userFeatureMap.getOrDefault(feature, "");
                 request.addFeed(feature, TFDataType.DT_STRING, new long[]{1}, new String[]{v});
@@ -144,11 +150,12 @@ public class PAIModelV2 {
                 request.addFeed(feature, TFDataType.DT_INT64, new long[]{1}, new long[]{v});
             }
 
-
             for (String feature : userFeatures) {
                 double v = NumberUtils.toDouble(userFeatureMap.getOrDefault(feature, "0.0"), 0.0);
                 request.addFeed(feature.toLowerCase(), TFDataType.DT_DOUBLE, new long[]{1}, new double[]{v});
             }
+
+            // 阶段2：构建 item 特征
             Map<String, double[]> doubleFeed = new HashMap<>();
             Map<String, long[]> longFeed = new HashMap<>();
             Map<String, String[]> strFeed = new HashMap<>();
@@ -187,22 +194,33 @@ public class PAIModelV2 {
             for (Map.Entry<String, double[]> entry : doubleFeed.entrySet()) {
                 request.addFeed(entry.getKey(), TFDataType.DT_DOUBLE, new long[]{items.size()}, entry.getValue());
             }
-
             for (Map.Entry<String, long[]> entry : longFeed.entrySet()) {
                 request.addFeed(entry.getKey(), TFDataType.DT_INT64, new long[]{items.size()}, entry.getValue());
             }
-
             for (Map.Entry<String, String[]> entry : strFeed.entrySet()) {
                 request.addFeed(entry.getKey(), TFDataType.DT_STRING, new long[]{items.size()}, entry.getValue());
             }
             request.addFetch("probs");
+            buildFeatureTime = System.currentTimeMillis() - stageStart;
+
+            // 阶段3：PAI-EAS 远程调用
+            stageStart = System.currentTimeMillis();
             TFResponse response = client.predict(request);
+            predictTime = System.currentTimeMillis() - stageStart;
+
             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 (!CollectionUtils.isEmpty(result)) {
                 return result;
             }
         } catch (Exception e) {
-            LOGGER.error("PAIModel score error", e);
+            long totalTime = System.currentTimeMillis() - totalStart;
+            LOGGER.error("PAIModelV2 score error itemSize={} totalTime={}ms buildFeature={}ms predict={}ms",
+                    items.size(), totalTime, buildFeatureTime, predictTime, e);
         }
         return new ArrayList<>(Collections.nCopies(items.size(), 0.0f));
     }

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

@@ -97,13 +97,18 @@ public class PAIScorerV2 extends AbstractScorer {
         ExecutorService executor = ThreadPoolFactory.score();
         List<Future<List<AdRankItem>>> futures = new ArrayList<>();
 
+        // 记录提交时间，用于计算 SCORE 线程池排队等待耗时
+        long submitTime = System.currentTimeMillis();
         for (List<AdRankItem> batch : batches) {
             futures.add(executor.submit(() -> {
+                long queueWaitTime = System.currentTimeMillis() - submitTime;
                 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);
                 return batch;
             }));
         }
@@ -120,7 +125,8 @@ public class PAIScorerV2 extends AbstractScorer {
 
         Collections.sort(merged);
 
-        LOGGER.debug("ctr ranker java execute time: [{}ms]", System.currentTimeMillis() - startTime);
+        LOGGER.info("PAIScorerV2 rankByJava done itemSize={} batchCount={} totalTime={}ms",
+                items.size(), batches.size(), System.currentTimeMillis() - startTime);
         return merged;
     }