(improvement)(chat) add traceId and time cost for show (#272)

chat/api/src/main/java/com/tencent/supersonic/chat/api/pojo/response/ParseResp.java

@@ -22,6 +22,7 @@ public class ParseResp {
     private List<SemanticParseInfo> selectedParses;
     private List<SemanticParseInfo> candidateParses;
     private List<SolvedQueryRecallResp> similarSolvedQuery;
+    private ParseTimeCostDO parseTimeCost;
 
     public enum ParseState {
         COMPLETED,

chat/api/src/main/java/com/tencent/supersonic/chat/api/pojo/response/ParseTimeCostDO.java

@@ -0,0 +1,9 @@
+package com.tencent.supersonic.chat.api.pojo.response;
+
+import lombok.Data;
+
+@Data
+public class ParseTimeCostDO {
+    private Long parseTime;
+    private Long sqlTime;
+}

chat/api/src/main/java/com/tencent/supersonic/chat/api/pojo/response/QueryRecallResp.java

@@ -0,0 +1,11 @@
+package com.tencent.supersonic.chat.api.pojo.response;
+
+import lombok.Data;
+
+import java.util.List;
+
+@Data
+public class QueryRecallResp {
+    private List<SolvedQueryRecallResp> solvedQueryRecallRespList;
+    private Long queryTimeCost;
+}

chat/api/src/main/java/com/tencent/supersonic/chat/api/pojo/response/QueryResult.java

@@ -21,4 +21,5 @@ public class QueryResult {
     private SemanticParseInfo chatContext;
     private Object response;
     private List<Map<String, Object>> queryResults;
+    private Long queryTimeCost;
 }

chat/core/src/main/java/com/tencent/supersonic/chat/parser/llm/s2ql/LLMS2QLParser.java

@@ -172,7 +172,7 @@ public class LLMS2QLParser implements SemanticParser {
     }
 
     private List<QueryFilter> getDimensionFilter(Map<String, SchemaElement> fieldNameToElement,
-            List<FilterExpression> filterExpressions) {
+                                                 List<FilterExpression> filterExpressions) {
         List<QueryFilter> result = Lists.newArrayList();
         for (FilterExpression expression : filterExpressions) {
             QueryFilter dimensionFilter = new QueryFilter();
@@ -229,7 +229,7 @@ public class LLMS2QLParser implements SemanticParser {
     }
 
     private boolean containOperators(FilterExpression expression, FilterOperatorEnum firstOperator,
-            FilterOperatorEnum... operatorEnums) {
+                                     FilterOperatorEnum... operatorEnums) {
         return (Arrays.asList(operatorEnums).contains(firstOperator) && Objects.nonNull(expression.getFieldValue()));
     }
 
@@ -257,7 +257,7 @@ public class LLMS2QLParser implements SemanticParser {
     }
 
     private SemanticParseInfo getParseInfo(QueryContext queryCtx, Long modelId, CommonAgentTool commonAgentTool,
-            ParseResult parseResult) {
+                                           ParseResult parseResult) {
         PluginSemanticQuery semanticQuery = QueryManager.createPluginQuery(S2QLQuery.QUERY_MODE);
         SemanticParseInfo parseInfo = semanticQuery.getParseInfo();
         parseInfo.getElementMatches().addAll(queryCtx.getMapInfo().getMatchedElements(modelId));
@@ -414,7 +414,7 @@ public class LLMS2QLParser implements SemanticParser {
 
 
     protected List<String> getFieldNameList(QueryContext queryCtx, Long modelId, SemanticSchema semanticSchema,
-            LLMParserConfig llmParserConfig) {
+                                            LLMParserConfig llmParserConfig) {
 
         Set<String> results = getTopNFieldNames(modelId, semanticSchema, llmParserConfig);
 
@@ -450,7 +450,7 @@ public class LLMS2QLParser implements SemanticParser {
     }
 
     private Set<String> getTopNFieldNames(Long modelId, SemanticSchema semanticSchema,
-            LLMParserConfig llmParserConfig) {
+                                          LLMParserConfig llmParserConfig) {
         Set<String> results = semanticSchema.getDimensions(modelId).stream()
                 .sorted(Comparator.comparing(SchemaElement::getUseCnt).reversed())
                 .limit(llmParserConfig.getDimensionTopN())

chat/core/src/main/java/com/tencent/supersonic/chat/responder/parse/ExplainSqlParseResponder.java

@@ -5,6 +5,7 @@ import com.tencent.supersonic.chat.api.pojo.QueryContext;
 import com.tencent.supersonic.chat.api.pojo.SemanticParseInfo;
 import com.tencent.supersonic.chat.api.pojo.request.QueryReq;
 import com.tencent.supersonic.chat.api.pojo.response.ParseResp;
+import com.tencent.supersonic.chat.api.pojo.response.ParseTimeCostDO;
 import com.tencent.supersonic.chat.persistence.dataobject.ChatParseDO;
 import com.tencent.supersonic.chat.query.QueryManager;
 import com.tencent.supersonic.common.util.JsonUtil;
@@ -22,8 +23,11 @@ public class ExplainSqlParseResponder implements ParseResponder {
     public void fillResponse(ParseResp parseResp, QueryContext queryContext,
                              List<ChatParseDO> chatParseDOS) {
         QueryReq queryReq = queryContext.getRequest();
+        Long startTime = System.currentTimeMillis();
         addExplainSql(queryReq, parseResp.getSelectedParses());
         addExplainSql(queryReq, parseResp.getCandidateParses());
+        parseResp.setParseTimeCost(new ParseTimeCostDO());
+        parseResp.getParseTimeCost().setSqlTime(System.currentTimeMillis() - startTime);
         if (!CollectionUtils.isEmpty(chatParseDOS)) {
             Map<Integer, ChatParseDO> chatParseDOMap = chatParseDOS.stream()
                     .collect(Collectors.toMap(ChatParseDO::getParseId,

chat/core/src/main/java/com/tencent/supersonic/chat/rest/ChatController.java

@@ -3,6 +3,7 @@ package com.tencent.supersonic.chat.rest;
 
 import com.github.pagehelper.PageInfo;
 import com.tencent.supersonic.auth.api.authentication.utils.UserHolder;
+import com.tencent.supersonic.chat.api.pojo.response.QueryRecallResp;
 import com.tencent.supersonic.chat.api.pojo.response.ShowCaseResp;
 import com.tencent.supersonic.chat.api.pojo.response.SolvedQueryRecallResp;
 import com.tencent.supersonic.chat.persistence.dataobject.ChatDO;
@@ -89,7 +90,12 @@ public class ChatController {
     @RequestMapping("/getSolvedQuery")
     public List<SolvedQueryRecallResp> getSolvedQuery(@RequestParam(value = "queryText") String queryText,
                                                       @RequestParam(value = "agentId") Integer agentId) {
-        return chatService.getSolvedQuery(queryText, agentId);
+        QueryRecallResp queryRecallResp = new QueryRecallResp();
+        Long startTime = System.currentTimeMillis();
+        List<SolvedQueryRecallResp> solvedQueryRecallRespList = chatService.getSolvedQuery(queryText, agentId);
+        queryRecallResp.setSolvedQueryRecallRespList(solvedQueryRecallRespList);
+        queryRecallResp.setQueryTimeCost(System.currentTimeMillis() - startTime);
+        return solvedQueryRecallRespList;
     }
 
 }

chat/core/src/main/java/com/tencent/supersonic/chat/service/impl/QueryServiceImpl.java

@@ -112,6 +112,7 @@ public class QueryServiceImpl implements QueryService {
 
     @Override
     public ParseResp performParsing(QueryReq queryReq) {
+        Long parseTime = System.currentTimeMillis();
         QueryContext queryCtx = new QueryContext(queryReq);
         // in order to support multi-turn conversation, chat context is needed
         ChatContext chatCtx = chatService.getOrCreateContext(queryReq.getChatId());
@@ -169,6 +170,8 @@ public class QueryServiceImpl implements QueryService {
                     queryReq.getUser().getName(), queryReq.getChatId().longValue());
         }
         chatService.updateChatParse(chatParseDOS);
+        parseResult.getParseTimeCost().setParseTime(
+                System.currentTimeMillis() - parseTime - parseResult.getParseTimeCost().getSqlTime());
         return parseResult;
     }
 
@@ -204,6 +207,7 @@ public class QueryServiceImpl implements QueryService {
 
     @Override
     public QueryResult performExecution(ExecuteQueryReq queryReq) throws Exception {
+        Long executeTime = System.currentTimeMillis();
         ChatParseDO chatParseDO = chatService.getParseInfo(queryReq.getQueryId(),
                 queryReq.getParseId());
         ChatQueryDO chatQueryDO = chatService.getLastQuery(queryReq.getChatId());
@@ -224,6 +228,7 @@ public class QueryServiceImpl implements QueryService {
         if (queryResult != null) {
             timeCostDOList.add(StatisticsDO.builder().cost((int) (System.currentTimeMillis() - startTime))
                     .interfaceName(semanticQuery.getClass().getSimpleName()).type(CostType.QUERY.getType()).build());
+            queryResult.setQueryTimeCost(timeCostDOList.get(0).getCost().longValue());
             saveInfo(timeCostDOList, queryReq.getQueryText(), queryReq.getQueryId(),
                     queryReq.getUser().getName(), queryReq.getChatId().longValue());
             queryResult.setChatContext(parseInfo);
@@ -242,7 +247,7 @@ public class QueryServiceImpl implements QueryService {
         } else {
             chatService.deleteChatQuery(queryReq.getQueryId());
         }
-
+        queryResult.setQueryTimeCost(System.currentTimeMillis() - executeTime);
         return queryResult;
     }
 
@@ -349,20 +354,14 @@ public class QueryServiceImpl implements QueryService {
                     parseInfo.getDimensionFilters(), addWhereConditions, removeWhereFieldNames);
             updateDateInfo(queryData, parseInfo, filedNameToValueMap,
                     whereExpressionList, addWhereConditions, removeWhereFieldNames);
-            log.info("filedNameToValueMap:{}", filedNameToValueMap);
-            log.info("removeWhereFieldNames:{}", removeWhereFieldNames);
             correctorSql = SqlParserReplaceHelper.replaceValue(correctorSql, filedNameToValueMap);
             correctorSql = SqlParserRemoveHelper.removeWhereCondition(correctorSql, removeWhereFieldNames);
 
             updateFilters(havingFiledNameToValueMap, havingExpressionList, queryData.getDimensionFilters(),
                     parseInfo.getDimensionFilters(), addHavingConditions, removeHavingFieldNames);
-            log.info("havingFiledNameToValueMap:{}", havingFiledNameToValueMap);
-            log.info("removeHavingFieldNames:{}", removeHavingFieldNames);
             correctorSql = SqlParserReplaceHelper.replaceHavingValue(correctorSql, havingFiledNameToValueMap);
             correctorSql = SqlParserRemoveHelper.removeHavingCondition(correctorSql, removeHavingFieldNames);
 
-            log.info("addWhereConditions:{}", addWhereConditions);
-            log.info("addHavingConditions:{}", addHavingConditions);
             correctorSql = SqlParserAddHelper.addWhere(correctorSql, addWhereConditions);
             correctorSql = SqlParserAddHelper.addHaving(correctorSql, addHavingConditions);
 

common/pom.xml

@@ -133,6 +133,10 @@
             <artifactId>jsqlparser</artifactId>
             <version>${jsqlparser.version}</version>
         </dependency>
+        <dependency>
+            <groupId>org.springframework.boot</groupId>
+            <artifactId>spring-boot-starter-web</artifactId>
+        </dependency>
 
     </dependencies>
 

common/src/main/java/com/tencent/supersonic/common/interceptor/LogInterceptor.java

@@ -0,0 +1,41 @@
+package com.tencent.supersonic.common.interceptor;
+
+import com.tencent.supersonic.common.util.TraceIdUtil;
+import lombok.extern.slf4j.Slf4j;
+import org.apache.commons.lang3.StringUtils;
+import org.springframework.stereotype.Component;
+import org.springframework.web.servlet.HandlerInterceptor;
+import org.springframework.web.servlet.ModelAndView;
+
+import javax.servlet.http.HttpServletRequest;
+import javax.servlet.http.HttpServletResponse;
+
+@Component
+@Slf4j
+public class LogInterceptor implements HandlerInterceptor {
+    @Override
+    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
+        //use previous traceId
+        String traceId = request.getHeader(TraceIdUtil.TRACE_ID);
+        if (StringUtils.isBlank(traceId)) {
+            TraceIdUtil.setTraceId(TraceIdUtil.generateTraceId());
+        } else {
+            TraceIdUtil.setTraceId(traceId);
+        }
+        return true;
+    }
+
+    @Override
+    public void postHandle(HttpServletRequest request, HttpServletResponse response,
+                           Object handler, ModelAndView modelAndView)
+            throws Exception {
+
+    }
+
+    @Override
+    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex)
+            throws Exception {
+        //remove after Completing
+        TraceIdUtil.remove();
+    }
+}

common/src/main/java/com/tencent/supersonic/common/pojo/ResultData.java

@@ -1,6 +1,8 @@
 package com.tencent.supersonic.common.pojo;
 
+import com.tencent.supersonic.common.util.TraceIdUtil;
 import lombok.Data;
+import org.slf4j.MDC;
 
 /***
  * result data
@@ -11,6 +13,7 @@ public class ResultData<T> {
     private String msg;
     private T data;
     private long timestamp;
+    private String traceId;
 
     public ResultData() {
         this.timestamp = System.currentTimeMillis();
@@ -21,6 +24,7 @@ public class ResultData<T> {
         resultData.setCode(ReturnCode.SUCCESS.getCode());
         resultData.setMsg(ReturnCode.SUCCESS.getMessage());
         resultData.setData(data);
+        resultData.setTraceId(MDC.get(TraceIdUtil.TRACE_ID));
         return resultData;
     }
 
@@ -28,7 +32,8 @@ public class ResultData<T> {
         ResultData<T> resultData = new ResultData<>();
         resultData.setCode(code);
         resultData.setMsg(message);
+        resultData.setTraceId(MDC.get(TraceIdUtil.TRACE_ID));
         return resultData;
     }
 
-}
+}

common/src/main/java/com/tencent/supersonic/common/pojo/ThreadPoolExecutorMdcWrapper.java

@@ -0,0 +1,30 @@
+package com.tencent.supersonic.common.pojo;
+
+import com.tencent.supersonic.common.util.ThreadMdcUtil;
+import org.slf4j.MDC;
+import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor;
+
+import java.util.concurrent.Callable;
+import java.util.concurrent.Future;
+
+public class ThreadPoolExecutorMdcWrapper extends ThreadPoolTaskExecutor {
+    private static final long serialVersionUID = 3940722618853093830L;
+
+    @Override
+    public void execute(Runnable task) {
+        super.execute(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
+    }
+
+    @Override
+    public <T> Future<T> submit(Callable<T> task) {
+        return super
+                .submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
+    }
+
+    @Override
+    public Future<?> submit(Runnable task) {
+        return super
+                .submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
+    }
+}
+

common/src/main/java/com/tencent/supersonic/common/util/ThreadMdcUtil.java

@@ -0,0 +1,49 @@
+package com.tencent.supersonic.common.util;
+
+import org.slf4j.MDC;
+
+import java.util.Map;
+import java.util.concurrent.Callable;
+
+public class ThreadMdcUtil {
+    public static void setTraceIdIfAbsent() {
+        if (MDC.get(TraceIdUtil.TRACE_ID) == null) {
+            MDC.put(TraceIdUtil.TRACE_ID, TraceIdUtil.generateTraceId());
+        }
+    }
+
+    public static <T> Callable<T> wrap(final Callable<T> callable, final Map<String, String> context) {
+        return () -> {
+            if (context == null) {
+                MDC.clear();
+            } else {
+                MDC.setContextMap(context);
+            }
+            setTraceIdIfAbsent();
+            try {
+                return callable.call();
+            } finally {
+                MDC.clear();
+            }
+        };
+    }
+
+    public static Runnable wrap(final Runnable runnable, final Map<String, String> context) {
+        return () -> {
+            if (context == null) {
+                MDC.clear();
+            } else {
+                MDC.setContextMap(context);
+            }
+            //设置traceId
+            setTraceIdIfAbsent();
+            try {
+                runnable.run();
+            } finally {
+                MDC.clear();
+            }
+        };
+    }
+}
+
+

common/src/main/java/com/tencent/supersonic/common/util/TraceIdUtil.java

@@ -0,0 +1,34 @@
+package com.tencent.supersonic.common.util;
+
+import org.slf4j.MDC;
+
+import java.util.UUID;
+
+public class TraceIdUtil {
+    public static final String TRACE_ID = "traceId";
+
+    public static final String PREFIX = "supersonic";
+
+    public static String getTraceId() {
+        String traceId = (String) MDC.get(TRACE_ID);
+        return traceId == null ? "" : traceId;
+    }
+
+    public static void setTraceId(String traceId) {
+        MDC.put(TRACE_ID, traceId);
+    }
+
+    public static void remove() {
+        MDC.remove(TRACE_ID);
+
+    }
+
+    public static void clear() {
+        MDC.clear();
+    }
+
+    public static String generateTraceId() {
+        String uuid = UUID.randomUUID().toString().replace("-", "");
+        return PREFIX + "_" + uuid;
+    }
+}

common/src/main/java/com/tencent/supersonic/common/util/WebMvcConfig.java

@@ -0,0 +1,16 @@
+package com.tencent.supersonic.common.util;
+
+import com.tencent.supersonic.common.interceptor.LogInterceptor;
+import org.springframework.context.annotation.Configuration;
+import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
+import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;
+
+@Configuration
+public class WebMvcConfig implements WebMvcConfigurer {
+
+    @Override
+    public void addInterceptors(InterceptorRegistry registry) {
+        registry.addInterceptor(new LogInterceptor()).addPathPatterns("/**");
+    }
+}
+

launchers/standalone/src/main/resources/logback-spring.xml

@@ -29,7 +29,7 @@
         <!--日志输出编码格式化-->
         <encoder>
             <charset>UTF-8</charset>
-            <pattern>%d [%thread] %-5level [%X{TRACE_ID}] %logger{36} %line - %msg%n</pattern>
+            <pattern>%d [%thread] %-5level [%X{traceId}] %logger{36} %line - %msg%n</pattern>
         </encoder>
     </appender>
 
@@ -55,7 +55,7 @@
         <!--日志输出编码格式化-->
         <encoder>
             <charset>UTF-8</charset>
-            <pattern>%d [%thread] %-5level [%X{TRACE_ID}] %logger{36} %line - %msg%n</pattern>
+            <pattern>%d [%thread] %-5level [%X{traceId}] %logger{36} %line - %msg%n</pattern>
         </encoder>
     </appender>
 
@@ -83,11 +83,11 @@
         <!--日志输出编码格式化-->
         <encoder>
             <charset>UTF-8</charset>
-            <pattern>%d [%thread] %-5level [%X{TRACE_ID}] %logger{36} %line - %msg%n</pattern>
+            <pattern>%d [%thread] %-5level [%X{traceId}] %logger{36} %line - %msg%n</pattern>
         </encoder>
     </appender>
 
     <logger name="com.tencent.supersonic" level="INFO" additivity="true">
         <appender-ref ref="serviceLog"/>
     </logger>
-</configuration>
+</configuration>

semantic/query/src/main/java/com/tencent/supersonic/semantic/query/utils/S2QLDataAspect.java

@@ -75,12 +75,11 @@ public class S2QLDataAspect {
 
         //1. determine whether admin of the model
         if (authCommonService.doModelAdmin(user, modelId)) {
+            log.info("determine whether admin of the model!");
             return joinPoint.proceed();
         }
-
         // 2. determine whether the subject field is visible
         authCommonService.doModelVisible(user, modelId);
-
         // 3. fetch data permission meta information
         Set<String> res4Privilege = queryStructUtils.getResNameEnExceptInternalCol(queryS2QLReq, user);
         log.info("modelId:{}, res4Privilege:{}", modelId, res4Privilege);