ADD: 监控打印时长

recommend-server-service/src/main/java/com/tzld/piaoquan/recommend/server/framework/recaller/BaseRecaller.java

@@ -2,6 +2,7 @@ package com.tzld.piaoquan.recommend.server.framework.recaller;
 
 
 import com.alibaba.fastjson.JSONObject;
+import com.google.common.base.Stopwatch;
 import com.google.common.collect.FluentIterable;
 import com.google.common.collect.Lists;
 import com.google.common.collect.Maps;
@@ -192,9 +193,12 @@ public class BaseRecaller<Video> {
         LOGGER.info("traceId: [{}], recall candidateQueueMap: [{}]", requestData.getRequestId(),
                 JSONObject.toJSONString(candidateQueueMap));
 
+        Stopwatch stopwatch = Stopwatch.createStarted();
+        stopwatch.start();
         List<RankItem> result = convertToRankItem(candidateQueueMap, requestData, user);
-        LOGGER.info("traceId: [{}], recall result: [{}]", requestData.getRequestId(),
-                JSONObject.toJSONString(result));
+
+        LOGGER.info("traceId: [{}], cost = {}, convertToRankItem result: [{}]", requestData.getRequestId(),
+                stopwatch.elapsed().toMillis(), JSONObject.toJSONString(result));
         return result;
     }
 

recommend-server-service/src/main/java/com/tzld/piaoquan/recommend/server/implement/TopRecommendPipeline.java

@@ -3,6 +3,7 @@ package com.tzld.piaoquan.recommend.server.implement;
 
 import com.alibaba.fastjson.JSONObject;
 import com.ctrip.framework.apollo.spring.annotation.ApolloJsonValue;
+import com.google.common.base.Stopwatch;
 import com.google.common.reflect.TypeToken;
 import com.tzld.piaoquan.recommend.server.common.base.RankItem;
 import com.tzld.piaoquan.recommend.server.framework.candidiate.Candidate;
@@ -59,16 +60,21 @@ public class TopRecommendPipeline {
                              final int requestIndex,
                              final User userInfo, Boolean logPrint) {
         // Step 1: Attention extraction
+        Stopwatch stopwatch = Stopwatch.createStarted();
+        stopwatch.start();
         List<RankItem> rankItems = feedByRec(requestData, requestIndex, userInfo, logPrint);
         if (rankItems == null || rankItems.isEmpty()) {
             return new ArrayList<>();
         }
         if (logPrint) {
-            log.info("traceId = {}, rankItems = {}", requestData.getRequestId(), JSONUtils.toJson(rankItems));
+            log.info("traceId = {}, cost = {}, feeds rankItems = {}", requestData.getRequestId(),
+                    stopwatch.elapsed().toMillis(), JSONUtils.toJson(rankItems));
         }
+        stopwatch.reset().start();
         List<Video> videos = rankItem2Video(rankItems);
         if (logPrint) {
-            log.info("traceId = {}, videos = {}", requestData.getRequestId(), JSONUtils.toJson(videos));
+            log.info("traceId = {}, cost = {}, videos = {}", requestData.getRequestId(),
+                    stopwatch.elapsed().toMillis(), JSONUtils.toJson(videos));
         }
         return videos;
     }
@@ -109,32 +115,34 @@ public class TopRecommendPipeline {
                                     final User userInfo, Boolean logPrint) {
         int recallNum = 150;
 
-        // Step 1: Attention extraction
-//        long timestamp = System.currentTimeMillis();
-//        UserAttentionExtractorPipeline attentionExtractorPipeline = UserAttentionExtractorUtils.getAtttentionPipeline(UserAttentionExtractorUtils.BASE_CONF);
-//        attentionExtractorPipeline.extractAttention(requestData, userInfo);
+        Stopwatch stopwatch = Stopwatch.createStarted();
 
         // Step 2: create top queue
+        stopwatch.start();
         StrategyQueue topQueue = MergeUtils.createTopQueue(MERGE_CONF, "top-queue");
         if (logPrint) {
-            log.info("traceId = {}, topQueue = {}", requestData.getRequestId(), JSONUtils.toJson(topQueue));
+            log.info("traceId = {}, cost = {}, topQueue = {}", requestData.getRequestId(),
+                    stopwatch.elapsed().toMillis(), JSONUtils.toJson(topQueue));
         }
 
         // Step 3: Candidate
+        stopwatch.reset().start();
         Map<String, Candidate> candidates = new HashMap<String, Candidate>();
         topQueue.candidate(candidates, recallNum, userInfo, requestData, 0, 0);
         if (logPrint) {
-            log.info("traceId = {}, candidates = {}", requestData.getRequestId(), JSONUtils.toJson(candidates));
+            log.info("traceId = {}, cost = {}, candidates = {}", requestData.getRequestId(),
+                    stopwatch.elapsed().toMillis(), JSONUtils.toJson(candidates));
         }
 
 
         // Step 4: Recalling & Basic Scoring
+        stopwatch.reset().start();
         RedisBackedQueue queueProvider = new RedisBackedQueue(client, 1000L);
-
         BaseRecaller recaller = new BaseRecaller(queueProvider);
         List<RankItem> items = recaller.recalling(requestData, userInfo, requestIndex, new ArrayList<>(candidates.values()));
         if (logPrint) {
-            log.info("traceId = {}, items = {}", requestData.getRequestId(), JSONUtils.toJson(items));
+            log.info("traceId = {}, cost = {}, items = {}", requestData.getRequestId(),
+                    stopwatch.elapsed().toMillis(), JSONUtils.toJson(items));
         }
 
 
@@ -146,6 +154,7 @@ public class TopRecommendPipeline {
             return new ArrayList<>();
         }
 
+        stopwatch.reset().start();
         // Step 5: Merger
         MergeUtils.distributeItemsToMultiQueues(topQueue, items);
         topQueue.merge(recallNum * 3, userInfo, requestData, requestIndex, 0);
@@ -158,15 +167,18 @@ public class TopRecommendPipeline {
         duplicate(mergeItems);
 
         if (logPrint) {
-            log.info("traceId = {}, mergeItems = {}", requestData.getRequestId(), JSONUtils.toJson(mergeItems));
+            log.info("traceId = {}, cost = {}, mergeItems = {}", requestData.getRequestId(),
+                    stopwatch.elapsed().toMillis(), JSONUtils.toJson(mergeItems));
         }
 //        MergeUtils.diversityRerank(mergeItems, SimilarityUtils.getIsSameUserTagOrCategoryFunc(), recallNum, 6, 2);
 
         // Step 6: Global Rank & subList
         // TODO 前置和后置处理逻辑 hardcode，后续优化
+        stopwatch.reset().start();
         List<RankItem> rovRecallRankNewScore = rankByScore(mergeItems, requestData);
         if (logPrint) {
-            log.info("traceId = {}, rovRecallRankNewScore = {}", requestData.getRequestId(), JSONUtils.toJson(rovRecallRankNewScore));
+            log.info("traceId = {}, cost = {}, rovRecallRankNewScore = {}", requestData.getRequestId(),
+                    stopwatch.elapsed().toMillis(), JSONUtils.toJson(rovRecallRankNewScore));
         }
 
         return rovRecallRankNewScore;

recommend-server-service/src/main/java/com/tzld/piaoquan/recommend/server/service/VideoRecommendService.java

@@ -1,6 +1,7 @@
 package com.tzld.piaoquan.recommend.server.service;
 
 import com.alibaba.fastjson.JSONObject;
+import com.google.common.base.Stopwatch;
 import com.google.common.base.Strings;
 import com.tzld.piaoquan.recommend.server.framework.common.User;
 import com.tzld.piaoquan.recommend.server.gen.common.Result;
@@ -59,34 +60,39 @@ public class VideoRecommendService {
     }
 
     private RecommendResponse recommendNew(RecommendRequest request, RecommendParam recommendParam, int recommendType) {
+        Stopwatch stopwatch = Stopwatch.createStarted();
         User user = getUser(request);
         List<Video> topRecommendVideoList = new ArrayList<>();
         List<Video> flowPoolRecommendVideoList = new ArrayList<>();
         try {
+            stopwatch.start();
             topRecommendVideoList = topRecommendPipeline.feeds(request, 0, user, newLogPrint);
             if (newLogPrint) {
-                log.info("traceId = {}, topRecommendVideoList [{}]", request.getRequestId(),
-                        JSONObject.toJSONString(topRecommendVideoList));
+                log.info("traceId = {}, cost = {}, topRecommendVideoList [{}]", request.getRequestId(),
+                        stopwatch.elapsed().toMillis(), JSONObject.toJSONString(topRecommendVideoList));
             }
 
         } catch (Exception e) {
             log.error("traceId = {}, topRecommendVideoList error", request.getRequestId(), e);
         }
         try {
+            stopwatch.reset().start();
             flowPoolRecommendVideoList = flowPoolRecommendPipeline.feedByRec(request, recommendType, newLogPrint);
             if (newLogPrint) {
-                log.info("traceId = {}, flowPoolRecommendVideoList [{}]", request.getRequestId(),
-                        JSONObject.toJSONString(flowPoolRecommendVideoList));
+                log.info("traceId = {}, cost = {}, flowPoolRecommendVideoList [{}]", request.getRequestId(),
+                        stopwatch.elapsed().toMillis(), JSONObject.toJSONString(flowPoolRecommendVideoList));
             }
         } catch (Exception e) {
             log.error("traceId = {}, flowPoolRecommendVideoList error", request.getRequestId(), e);
         }
-        RankParam rankParam = recommendService.convertToRankParam(recommendParam, null);
 
+        stopwatch.reset().start();
+        RankParam rankParam = recommendService.convertToRankParam(recommendParam, null);
         RankResult rankResult = rankStrategy4RegionMergeModelV2.mergeAndSort(rankParam, topRecommendVideoList,
                 flowPoolRecommendVideoList);
         if (newLogPrint) {
-            log.info("traceId = {}, rankResult [{}]", request.getRequestId(), JSONObject.toJSONString(rankResult));
+            log.info("traceId = {}, cost = {}, final rankResult [{}]", request.getRequestId(),
+                    stopwatch.elapsed().toMillis(), JSONObject.toJSONString(rankResult));
         }
 
         // 只返回size条数据